11 Jun
2008
11 Jun
'08
10:58 a.m.
Hi all, i'm trying to debug a strange behaviour of dialog mode.
If I use "record_route" in my script, to force any message to toward the
server, dialog module stops to check "timeout_avp", if I comment it out,
when timeout_avp is reached, the dialog module notify me in sylog (as
shown in log.txt)
It seems that dialog module has some problems to work if i use
record_route()...
I try to use version 1.3.1 and 1.3.2, but i see the same behaviour.
So, where i'm wrong? ;)
Here's relevant part of config, and in openser.txt there's my routing
script
----
loadmodule "rr.so"
modparam("rr", "enable_full_lr", 1)
modparam("rr", "append_fromtag", 1)
modparam("rr", "enable_double_rr", 1)
modparam("rr", "add_username", 0)
loadmodule "dialog.so"
modparam("dialog", "enable_stats", 1)
modparam("dialog", "dlg_flag", 4)
modparam("dialog", "timeout_avp", "$avp(s:dlgtimeout)")
modparam("dialog", "dlg_extra_hdrs", "Hint: credit
expired\r\n")
modparam("dialog", "dlg_match_mode", 1)
modparam("dialog", "db_url",
"mysql://dbuser:dbpass@localhost/openser")
modparam("dialog", "db_mode", 1)
----
thanx in advance
k.
# With record_route()
Jun 11 09:36:07 New request - M=INVITE RURI=sip:alice@192.168.27.74
F=sip:bob@192.168.27.74 T=sip:alice@192.168.27.74 IP=192.168.27.82 ID=2112176925
Jun 11 09:36:07 BRANCH - S=<null>
R=sip:alice@192.168.1.201:5060;line=2c542c23af8e7c7 D=<null> F=sip:bob@192.168.27.74
T=sip:alice@192.168.27.74 IP=192.168.27.82 ID=2112176925
Jun 11 09:36:07 Reply - S=101 R=<null> D=Dialog Establishement
F=sip:bob@192.168.27.74 T=sip:alice@192.168.27.74 IP=192.168.27.201 ID=2112176925
Jun 11 09:36:07 Reply - S=100 R=<null> D=Trying F=sip:bob@192.168.27.74
T=sip:alice@192.168.27.74 IP=192.168.27.201 ID=2112176925
Jun 11 09:36:07 Reply - S=180 R=<null> D=Ringing F=sip:bob@192.168.27.74
T=sip:alice@192.168.27.74 IP=192.168.27.201 ID=2112176925
Jun 11 09:36:09 Reply - S=200 R=<null> D=OK F=sip:bob@192.168.27.74
T=sip:alice@192.168.27.74 IP=192.168.27.201 ID=2112176925
Jun 11 09:36:09 New request - M=ACK RURI=sip:alice@192.168.1.201:5060
F=sip:bob@192.168.27.74 T=sip:alice@192.168.27.74 IP=192.168.27.82 ID=2112176925
Jun 11 09:36:26 New request - M=BYE RURI=sip:alice@192.168.1.201:5060
F=sip:bob@192.168.27.74 T=sip:alice@192.168.27.74 IP=192.168.27.82 ID=2112176925
Jun 11 09:36:26 Reply - S=200 R=<null> D=OK F=sip:bob@192.168.27.74
T=sip:alice@192.168.27.74 IP=192.168.27.201 ID=2112176925
# Without record_route()
Jun 11 09:36:49 New request - M=INVITE RURI=sip:alice@192.168.27.74
F=sip:bob@192.168.27.74 T=sip:alice@192.168.27.74 IP=192.168.27.82 ID=1675712119
Jun 11 09:36:49 BRANCH - S=<null>
R=sip:alice@192.168.1.201:5060;line=2c542c23af8e7c7 D=<null> F=sip:bob@192.168.27.74
T=sip:alice@192.168.27.74 IP=192.168.27.82 ID=1675712119
Jun 11 09:36:49 Reply - S=100 R=<null> D=Trying F=sip:bob@192.168.27.74
T=sip:alice@192.168.27.74 IP=192.168.27.201 ID=1675712119
Jun 11 09:36:49 Reply - S=101 R=<null> D=Dialog Establishement
F=sip:bob@192.168.27.74 T=sip:alice@192.168.27.74 IP=192.168.27.201 ID=1675712119
Jun 11 09:36:49 Reply - S=180 R=<null> D=Ringing F=sip:bob@192.168.27.74
T=sip:alice@192.168.27.74 IP=192.168.27.201 ID=1675712119
Jun 11 09:36:51 Reply - S=200 R=<null> D=OK F=sip:bob@192.168.27.74
T=sip:alice@192.168.27.74 IP=192.168.27.201 ID=1675712119
Jun 11 09:36:56 WARNING:dialog:dlg_ontimeout: timeout for dlg with CallID
'1675712119' and tags '53233056' '453709088'
####### Routing Logic ########
route[0]
{
xlog("L_INFO", "New request - M=$rm RURI=$ru F=$fu T=$tu IP=$si
ID=$ci\n");
if(loose_route())
{
if(!has_totag())
{
xlog("L_INFO", "Initial loose-routing rejected - M=$rm RURI=$ru
F=$fu T=$tu IP=$si ID=$ci\n");
sl_send_reply("403", "Initial Loose-Routing Rejected");
exit;
}
t_on_reply("1");
t_on_failure("1");
}
if(!is_method("REGISTER"))
{
#record_route();
}
if(is_method("CANCEL") || is_method("ACK"))
{
t_on_reply("1");
if(t_check_trans()) {
if(!t_relay()) {
sl_reply_error();
}
}
else {
xlog("L_INFO", "Dropping mis-routed request - M=$rm RURI=$ru F=$fu T=$tu
IP=$si ID=$ci\n");
}
exit;
}
t_check_trans();
if(is_method("REGISTER"))
{
sl_send_reply("100", "Trying");
if(!save("location"))
{
xlog("L_ERR", "Register FAIL - M=$rm RURI=$ru F=$fu T=$tu IP=$si
ID=$ci\n");
sl_reply_error();
exit;
}
xlog("L_INFO", "Register OK - M=$rm RURI=$ru F=$fu T=$tu IP=$si
ID=$ci\n");
exit;
}
if(is_method("INVITE"))
{
$avp(s:dlgtimeout)=5;
$avp(s:ringtimeout)=10;
setflag(4);
sl_send_reply("100", "Trying");
}
if(is_method("BYE"))
{
route(1);
}
if (!lookup("location")) {
switch ($retcode) {
case -1:
case -3:
t_newtran();
t_reply("404", "Not Found");
exit;
case -2:
sl_send_reply("405", "Method Not Allowed");
exit;
}
}
route(1);
}
route[1] {
if (is_method("INVITE")) {
t_on_branch("1");
t_on_reply("1");
t_on_failure("1");
}
if (!t_relay()) {
sl_reply_error();
};
exit;
}
branch_route[1] {
xlog("L_INFO", "BRANCH - S=$rs R=$ru D=$rr F=$fu T=$tu IP=$si
ID=$ci\n");
}
onreply_route[1]
{
xlog("L_INFO", "Reply - S=$rs R=$ru D=$rr F=$fu T=$tu IP=$si
ID=$ci\n");
}
failure_route[1] {
if (t_was_cancelled()) {
exit;
}
}
11 Jun
11 Jun
3:22 p.m.
On Wednesday 11 June 2008, kionez wrote:
If I use "record_route" in my script, to
force any message to toward the
server, dialog module stops to check "timeout_avp", if I comment it out,
when timeout_avp is reached, the dialog module notify me in sylog (as
shown in log.txt)
It seems that dialog module has some problems to work if i use
record_route()...
[..]
Hi,
if you don't use record routing the module can't track all the messages from
the dialog, so the internal dialog state will be different. But i can confirm
the problem with the timeout_avp value, i've did some tests with your
configuration.
Cheers,
Henning
3:41 p.m.
On Wednesday 11 June 2008, Henning Westerholt wrote:
if you don't use record routing the module
can't track all the messages
from the dialog, so the internal dialog state will be different. But i can
confirm the problem with the timeout_avp value, i've did some tests with
your configuration.
It seems that in this case the AVP value is not valid, and the default timeout
is used. Some logs (from trunk):
Jun 11 14:37:52 ca ../openser[23446]: DBG:dialog:dlg_onroute: route param
is '494.7573c3' (len=10)
Jun 11 14:37:52 ca ../openser[23446]: DBG:dialog:lookup_dlg: ref dlg
0xb5c61e50 with 1 -> 3
Jun 11 14:37:52 ca ../openser[23446]: DBG:dialog:lookup_dlg: dialog id=3946327
found on entry 1172
Jun 11 14:37:52 ca ../openser[23446]: DBG:core:parse_headers: flags=48
Jun 11 14:37:52 ca ../openser[23446]: DBG:dialog:next_state_dlg: dialog
0xb5c61e50 changed from state 3 to state 4, due event 6
Jun 11 14:37:52 ca ../openser[23446]: DBG:dialog:dlg_onroute: sequential
request successfully processed
Jun 11 14:37:52 ca ../openser[23446]: INFO:dialog:get_dlg_timeout: invalid AVP
value, use default timeout
Jun 11 14:37:52 ca ../openser[23446]: DBG:dialog:insert_dlg_timer_unsafe:
inserting 0xb5c61e78 for 43211
Jun 11 14:37:52 ca ../openser[23446]: DBG:dialog:dlg_update_cseq: cseq is 20
Jun 11 14:37:52 ca ../openser[23446]: DBG:uri:has_totag: totag found
Henning
12 Jun
12 Jun
10:45 a.m.
#include <Henning Westerholt.h> // created 11/06/2008 14:41
[cut]
It seems that in this case the AVP value is not valid,
and the
default timeout
is used. Some logs (from trunk):
[cut]
Jun 11 14:37:52 ca ../openser[23446]:
INFO:dialog:get_dlg_timeout:
invalid AVP
value, use default timeout
I try to set my debug level to 9, but i can't reproduce this behaviour,
i never seen "invalid AVP value".. what version are you using?
k.
6009
days inactive
6010
days old
3 comments
2 participants
participants (2)
-
Henning Westerholt -
kionez