22 Jun
2009
22 Jun
'09
4:38 a.m.
while testing new version of lcr module, i got this kind of tm errors:
Jun 22 11:27:36 localhost /usr/sbin/sip-router[16330]: ERROR: tm [t_reply.c:1066]: ERROR:
t_should_relay_response: status rewrite by UAS: stored: 408, received: 403
Jun 22 11:27:36 localhost /usr/sbin/sip-router[16329]: ERROR: tm [t_reply.c:1066]: ERROR:
t_should_relay_response: status rewrite by UAS: stored: 408, received: 403
Jun 22 11:27:37 localhost /usr/sbin/sip-router[16331]: ERROR: tm [t_reply.c:1066]: ERROR:
t_should_relay_response: status rewrite by UAS: stored: 408, received: 403
Jun 22 11:27:39 localhost /usr/sbin/sip-router[16331]: ERROR: tm [t_reply.c:1066]: ERROR:
t_should_relay_response: status rewrite by UAS: stored: 408, received: 403
they came when i first called t_relay 4 times. first call was in route
block and the rest in failure route block. there was no reply to any of
these four calls and each time fr_timer hit. on fifth call, gw
responded with 403.
i don't get these kind of errors in k. what do they mean and how to get
rid of them?
-- juha
22 Jun
22 Jun
7:22 a.m.
On Jun 22, 2009 at 11:38, Juha Heinanen <jh(a)tutpro.com> wrote:
while testing new version of lcr module, i got this
kind of tm errors:
Jun 22 11:27:36 localhost /usr/sbin/sip-router[16330]: ERROR: tm [t_reply.c:1066]: ERROR:
t_should_relay_response: status rewrite by UAS: stored: 408, received: 403
Jun 22 11:27:36 localhost /usr/sbin/sip-router[16329]: ERROR: tm [t_reply.c:1066]: ERROR:
t_should_relay_response: status rewrite by UAS: stored: 408, received: 403
Jun 22 11:27:37 localhost /usr/sbin/sip-router[16331]: ERROR: tm [t_reply.c:1066]: ERROR:
t_should_relay_response: status rewrite by UAS: stored: 408, received: 403
Jun 22 11:27:39 localhost /usr/sbin/sip-router[16331]: ERROR: tm [t_reply.c:1066]: ERROR:
t_should_relay_response: status rewrite by UAS: stored: 408, received: 403
they came when i first called t_relay 4 times. first call was in route
block and the rest in failure route block. there was no reply to any of
these four calls and each time fr_timer hit. on fifth call, gw
responded with 403.
i don't get these kind of errors in k. what do they mean and how to get
rid of them?
They mean that after a final reply was received or "faked"
(automatically generated locally) on a branch, a new different reply for
the same branch was received.
In all this cases the new reply is discarded. The error messages is
printed for everything except the following 2 cases: initial final reply
on branch was 487 or the final reply was 408 followed by a 487 (these
are very common and happen in normal operation).
In your case the final reply is 408 (timeout) and the new received one
is 403.
What might have happened is either the gw sent the 403 after the
fr_inv_timer did hit for the branch corresponding to your fifth call or
the gw sent the 403 for one of the previous branches, but it's hard to say
without more info.
You do not get this messages in k, because there the error message is
enclosed by #ifdef EXTRA_DEBUG.
Andrei
9:12 a.m.
Andrei Pelinescu-Onciul writes:
In your case the final reply is 408 (timeout) and the
new received one
is 403.
What might have happened is either the gw sent the 403 after the
fr_inv_timer did hit for the branch corresponding to your fifth call or
the gw sent the 403 for one of the previous branches, but it's hard to say
without more info.
andrei,
i set fr_timer_avp to 3000 (3 sec) before calling t_relay. i have
modparam("tm", "fr_inv_timer", 75000)
i have defined fr_inv_timer_avp, but it has not been given a value
during processing of this request. could the explanation be this:
k:
1.3.11. fr_timer_avp (string)
If you set the AVP to an empty string, the whole mechanism for
variable timeout will be disabled, falling back to the static
value.
sr:
1.3.29. fr_inv_timer_avp (string)
The value of fr_inv_timer timer can be overriden on per-transaction
basis. The administrator can provide a value to be used for a
particular transaction in an AVP. This parameter contains the name of
the AVP that will be checked. If the AVP exists then its value will be
used for the fr_inv_timer timer, effectively overriding the value
configured in fr_inv_timer parameter for the current transaction.
what does sr do if fr_inv_timer_avp exists, but is not set before
t_relay is called?
below is what comes to syslog.
-- juha
Jun 22 16:02:54 localhost /usr/sbin/sip-router[31499]: INFO: Routing initial INVITE to
<sip:0407058050@192.98.101.24:5060> and <<null>>
Jun 22 16:02:59 localhost /usr/sbin/sip-router[31514]: INFO: Routing next INVITE to
<sip:0407058050@192.98.101.21:5060>
Jun 22 16:03:04 localhost /usr/sbin/sip-router[31514]: INFO: Routing next INVITE to
<sip:0407058050@192.98.101.23:5060>
Jun 22 16:03:09 localhost /usr/sbin/sip-router[31514]: INFO: Routing next INVITE to
<sip:0407058050@192.98.101.22:5060>
Jun 22 16:03:14 localhost /usr/sbin/sip-router[31514]: INFO: Routing next INVITE to
<sip:0407058050@192.98.100.10:5060>
Jun 22 16:03:15 localhost /usr/sbin/sip-router[31499]: ERROR: tm [t_reply.c:1066]: ERROR:
t_should_relay_response: status rewrite by UAS: stored: 408, received: 403
Jun 22 16:03:15 localhost /usr/sbin/sip-router[31498]: ERROR: tm [t_reply.c:1066]: ERROR:
t_should_relay_response: status rewrite by UAS: stored: 408, received: 403
Jun 22 16:03:15 localhost /usr/sbin/sip-router[31500]: ERROR: tm [t_reply.c:1066]: ERROR:
t_should_relay_response: status rewrite by UAS: stored: 408, received: 403
Jun 22 16:03:18 localhost /usr/sbin/sip-router[31498]: ERROR: tm [t_reply.c:1066]: ERROR:
t_should_relay_response: status rewrite by UAS: stored: 408, received: 403
Jun 22 16:03:19 localhost /usr/sbin/sip-router[31514]: WARNING: No more gateways for
INVITE <sip:0407058050@192.98.101.24:5060>
9:53 a.m.
On Jun 22, 2009 at 16:12, Juha Heinanen <jh(a)tutpro.com> wrote:
Andrei Pelinescu-Onciul writes:
^^^^^^ the avp timers are in seconds, so you should
set them it to 3. All the other timeouts are in ms (I'll add a note to
the docs).
In your case the final reply is 408 (timeout) and
the new received one
is 403.
What might have happened is either the gw sent the 403 after the
fr_inv_timer did hit for the branch corresponding to your fifth call or
the gw sent the 403 for one of the previous branches, but it's hard to say
without more info.
andrei,
i set fr_timer_avp to 3000 (3 sec) before calling t_relay. i have
modparam("tm", "fr_inv_timer", 75000)
i have defined fr_inv_timer_avp, but it has not been given a value
during processing of this request. could the explanation be this:
k:
1.3.11. fr_timer_avp (string)
If you set the AVP to an empty string, the whole mechanism for
variable timeout will be disabled, falling back to the static
value.
sr:
1.3.29. fr_inv_timer_avp (string)
The value of fr_inv_timer timer can be overriden on per-transaction
basis. The administrator can provide a value to be used for a
particular transaction in an AVP. This parameter contains the name of
the AVP that will be checked. If the AVP exists then its value will be
used for the fr_inv_timer timer, effectively overriding the value
configured in fr_inv_timer parameter for the current transaction.
Yes, this is it.
what does sr do if fr_inv_timer_avp exists, but is not set before
t_relay is called?
An avp always has a value if it exists. If its value is the empty string
or 0 => the avp integer value will be 0 => in this case the timer will
be set to 0.
I'll add a check for 0 in sr too (so that it will be compatible with the
k way).
Note that in ser the modern way to use avps for timers is via t_set_fr()
& friends (you can set everything from fr timers to retransmission and
lifetime, you can later reset to default via t_reset_fr() and you can
use it only when needed).
Andrei
11:03 a.m.
Andrei Pelinescu-Onciul writes:
i did so, but it didn't affect the error messages. while doing it i
noticed that fr_timer is not very accurate. i call next_gw() when
previous call times out and syslog reports 5 second intervals:
Jun 22 17:56:46 localhost /usr/sbin/sip-router[5881]: INFO: Routing initial INVITE to
<sip:0407058050@192.98.101.21:5060> and <<null>>
Jun 22 17:56:51 localhost /usr/sbin/sip-router[5909]: INFO: Routing next INVITE to
<sip:0407058050@192.98.101.24:5060>
Jun 22 17:56:56 localhost /usr/sbin/sip-router[5909]: INFO: Routing next INVITE to
<sip:0407058050@192.98.101.23:5060>
Jun 22 17:57:01 localhost /usr/sbin/sip-router[5909]: INFO: Routing next INVITE to
<sip:0407058050@192.98.101.22:5060>
Jun 22 17:57:06 localhost /usr/sbin/sip-router[5909]: INFO: Routing next INVITE to
<sip:0407058050@192.98.100.10:5060>
i set
fr_timer_avp to 3000 (3 sec) before calling t_relay. i have
^^^^^^ the avp timers are in seconds, so you should
set them it to 3. All the other timeouts are in ms (I'll add a note to
the docs). An avp always has a value if it exists. If its value
is the empty string
or 0 => the avp integer value will be 0 => in this case the timer will
be set to 0.
i added xlog statement before first next_gw() call and it reports that
fr_inv_timer_avp has value null:
Jun 22 17:56:46 localhost /usr/sbin/sip-router[5881]: INFO: fr_inv_timer_avp <null>
I'll add a check for 0 in sr too (so that it will
be compatible with the
k way).
that would be nice so that script writer can leave the avp unset if
there is no need to change the default set by the module parameter
variable.
Note that in ser the modern way to use avps for timers
is via t_set_fr()
& friends (you can set everything from fr timers to retransmission and
lifetime, you can later reset to default via t_reset_fr() and you can
use it only when needed).
thanks for the pointer. i'll take a look at those.
-- juha
12:44 p.m.
i updated my tm module from git and replaced tm timer avps with t_set_fr
calls. before i start calling next_gw()/t_relay(), i do
t_set_fr(75000, 3000)
accuracy of fr_timeout became good, but i'm still getting the error
messages:
Jun 22 19:38:53 localhost /usr/sbin/sip-router[11411]: INFO: Routing initial INVITE to
<sip:0407058050@192.98.101.21:5060> and <<null>>
Jun 22 19:38:56 localhost /usr/sbin/sip-router[11437]: INFO: Routing next INVITE to
<sip:0407058050@192.98.101.24:5060>
Jun 22 19:38:59 localhost /usr/sbin/sip-router[11437]: INFO: Routing next INVITE to
<sip:0407058050@192.98.101.23:5060>
Jun 22 19:39:02 localhost /usr/sbin/sip-router[11437]: INFO: Routing next INVITE to
<sip:0407058050@192.98.101.22:5060>
Jun 22 19:39:05 localhost /usr/sbin/sip-router[11437]: INFO: Routing next INVITE to
<sip:0407058050@192.98.100.10:5060>
Jun 22 19:39:07 localhost /usr/sbin/sip-router[11412]: ERROR: tm [t_reply.c:1066]: ERROR:
t_should_relay_response: status rewrite by UAS: stored: 408, received: 403
Jun 22 19:39:07 localhost /usr/sbin/sip-router[11411]: ERROR: tm [t_reply.c:1066]: ERROR:
t_should_relay_response: status rewrite by UAS: stored: 408, received: 403
Jun 22 19:39:07 localhost /usr/sbin/sip-router[11410]: ERROR: tm [t_reply.c:1066]: ERROR:
t_should_relay_response: status rewrite by UAS: stored: 408, received: 403
like before, in this test the first four t_relays resulted in fr_timeout
(gw didn't respond) and the last returned 403 (forbidden).
what is the next step, i.e., how to get rid of the error messages? i
don't see that i would be doing anything wrong here in my cfg file.
-- juha
1:07 p.m.
On Jun 22, 2009 at 19:44, Juha Heinanen <jh(a)tutpro.com> wrote:
i updated my tm module from git and replaced tm timer
avps with t_set_fr
calls. before i start calling next_gw()/t_relay(), i do
t_set_fr(75000, 3000)
accuracy of fr_timeout became good, but i'm still getting the error
messages:
It's strange that the accuracy became good, because the timeout is set
in a similar way when fr_timer_avp is used (so it should be always good,
always at max. 125 ms drift with default TIMER_TICKS_HZ).
Jun 22 19:38:53 localhost /usr/sbin/sip-router[11411]: INFO: Routing initial INVITE to
<sip:0407058050@192.98.101.21:5060> and <<null>>
Jun 22 19:38:56 localhost /usr/sbin/sip-router[11437]: INFO: Routing next INVITE to
<sip:0407058050@192.98.101.24:5060>
Jun 22 19:38:59 localhost /usr/sbin/sip-router[11437]: INFO: Routing next INVITE to
<sip:0407058050@192.98.101.23:5060>
Jun 22 19:39:02 localhost /usr/sbin/sip-router[11437]: INFO: Routing next INVITE to
<sip:0407058050@192.98.101.22:5060>
Jun 22 19:39:05 localhost /usr/sbin/sip-router[11437]: INFO: Routing next INVITE to
<sip:0407058050@192.98.100.10:5060>
Jun 22 19:39:07 localhost /usr/sbin/sip-router[11412]: ERROR: tm [t_reply.c:1066]: ERROR:
t_should_relay_response: status rewrite by UAS: stored: 408, received: 403
Jun 22 19:39:07 localhost /usr/sbin/sip-router[11411]: ERROR: tm [t_reply.c:1066]: ERROR:
t_should_relay_response: status rewrite by UAS: stored: 408, received: 403
Jun 22 19:39:07 localhost /usr/sbin/sip-router[11410]: ERROR: tm [t_reply.c:1066]: ERROR:
t_should_relay_response: status rewrite by UAS: stored: 408, received: 403
like before, in this test the first four t_relays resulted in fr_timeout
(gw didn't respond) and the last returned 403 (forbidden).
what is the next step, i.e., how to get rid of the error messages? i
don't see that i would be doing anything wrong here in my cfg file.
We could log it at a lower level or add a config option for skipping the
log message, but first we should see if it doesn't point to some other
more serious error. I still don't understand why you get them.
Are you sure that the gateway does not respond later with 403 for the
initial branches (after more then 14s)?
Do you add a new branch in all the cases?
Could you send me a packet dump along with the log (preferably at a
high debug level) and a short example on how you are doing this gateway
failover from the failure route?
It's most likely a too verbose message for your setup, but I'd like to
be sure of that and that it does not hide a more important problem.
Andrei
12:55 p.m.
On 22-06 15:53, Andrei Pelinescu-Onciul wrote:
On Jun 22, 2009 at 16:12, Juha Heinanen
<jh(a)tutpro.com> wrote:
Shouldn't we change the unit of AVP timers to ms too, just to be consistent?
I've bumped into this inconsistency many times in the past and it was always a
great source of confusion for me.
Jan.
Andrei Pelinescu-Onciul writes:
^^^^^^ the avp timers are in seconds, so you should
set them it to 3. All the other timeouts are in ms (I'll add a note to
the docs). In your case the final reply is 408 (timeout) and
the new received one
is 403.
What might have happened is either the gw sent the 403 after the
fr_inv_timer did hit for the branch corresponding to your fifth call or
the gw sent the 403 for one of the previous branches, but it's hard to say
without more info.
andrei,
i set fr_timer_avp to 3000 (3 sec) before calling t_relay. i have
1:12 p.m.
On Jun 22, 2009 at 18:55, Jan Janak <jan(a)iptel.org> wrote:
On 22-06 15:53, Andrei Pelinescu-Onciul wrote:
Since I think new scripts should use t_set_fr() I don't have any
preference for fr_timer_avp unit.
However if we change it, both ser and kamailio users that have it set in
seconds somewhere in some DB, will have problems. We could change its
name to fr_timer_avp_ms (so at least users will get an error) or leave
it the way it is (at least is documented now, and while inconsistent, it
will have the minimum migration impact).
Andrei
On Jun 22, 2009 at 16:12, Juha Heinanen
<jh(a)tutpro.com> wrote:
Shouldn't we change the unit of AVP timers to ms too, just to be consistent?
I've bumped into this inconsistency many times in the past and it was always a
great source of confusion for me. Andrei Pelinescu-Onciul writes:
^^^^^^ the avp timers are in seconds, so you should
set them it to 3. All the other timeouts are in ms (I'll add a note to
the docs). In your case the final reply is 408 (timeout) and
the new received one
is 403.
What might have happened is either the gw sent the 403 after the
fr_inv_timer did hit for the branch corresponding to your fifth call or
the gw sent the 403 for one of the previous branches, but it's hard to say
without more info.
andrei,
i set fr_timer_avp to 3000 (3 sec) before calling t_relay. i have
1:20 p.m.
Jan Janak writes:
Shouldn't we change the unit of AVP timers to ms
too, just to be consistent?
I've bumped into this inconsistency many times in the past and it was
always a great source of confusion for me.
i agree with that proposal. perhaps we could remove of the tm timer
avps altogether. that way it would be easier for k user to recognize
that changes are needed.
-- juha
5639
days inactive
5639
days old
9 comments
3 participants
participants (3)
-
Andrei Pelinescu-Onciul -
Jan Janak -
jh＠tutpro.com