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; } }
On Wednesday 11 June 2008, kionez wrote:
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
On Wednesday 11 June 2008, Henning Westerholt wrote:
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
#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.