[OpenSIPS-Users] Error in log caused by DIALOG module

Thu Feb 26 15:15:02 CET 2009

Hi all.
Investigating more deeply about the errors generated by dialog module, I saw that the problem is the writing in the dialog table of the database, immediately after receiving the ACK.

Feb 26 13:02:39 opensips-lab /usr/local/sbin/opensips[4839]: New request - M=ACK RURI=sip:1001 at 10.10.45.102:5062 F=sip:1000 at mysip.com T=sip:1001 at mysip.com IP=10.10.45.102 ID=617BBA30-1DD2-11B2-B403-C498EB25A704 at 10.10.45.102
Feb 26 13:02:39 opensips-lab /usr/local/sbin/opensips[4839]: CRITICAL:dialog:log_next_state_dlg: bogus event 6 in state 2 for dlg 0xb5c24900 [1224:615410713] with clid '617BBA30-1DD2-11B2-B403-C498EB25A704 at 10.10.45.102' and tags '30014539721873472581' ''
Feb 26 13:02:39 opensips-lab /usr/local/sbin/opensips[4839]: Request leaving server, D-URI=<null> - M=ACK RURI=sip:1001 at 10.10.45.102:5062 F=sip:1000 at mysip.com T=sip:1001 at mysip.com IP=10.10.45.102 ID=617BBA30-1DD2-11B2-B403-C498EB25A704 at 10.10.45.102
Feb 26 13:02:39 opensips-lab /usr/local/sbin/opensips[4839]: ACC: request acknowledged: timestamp=1235649759;method=ACK;from_tag=30014539721873472581;to_tag=712966524;call_id=617BBA30-1DD2-11B2-B403-C498EB25A704 at 10.10.45.102;code=200;reason=OK;caller_id=sip:1000 at mysip.com;callee_id=sip:1001 at mysip.com;destination=10.10.45.102
Feb 26 13:02:39 opensips-lab /usr/local/sbin/opensips[4841]: ERROR:db_mysql:db_mysql_submit_query: driver error on query: Column 'from_uri' cannot be null
Feb 26 13:02:39 opensips-lab /usr/local/sbin/opensips[4841]: ERROR:core:db_do_insert: error while submitting query
Feb 26 13:02:39 opensips-lab /usr/local/sbin/opensips[4841]: ERROR:dialog:update_dialog_dbinfo: could not add another dialog to db

Indeed changing the parameter db_mode from 1 to 0 the error disappears.
I have version 1.5 (rev. 5190) of opensips. Lately something has changed in the module dialog?
Any suggestion?

Thanks.

-----Messaggio originale-----
Da: mmarzuola at interfree.it
Inviato il: 26 Feb 2009 - 11:15
A: users at lists.opensips.org

Hi all.
Checking the log I noticed that the dialog module generates some errors, but the dialogs are being completed when the BYE comes.
In my opensips.cfg I set :

modparam("dialog","dlg_flag", 4)
modparam("dialog", "db_url", "mysql://opensips:opensipsrw@localhost/opensips")
modparam("dialog", "db_mode", 1)

and these are the routes:

# Request route 'main'
route {

xlog("L_INFO", "New request - M=$rm RURI=$ru F=$fu T=$tu IP=$si ID=$ci\n");
if(msg:len > 2048) {
xlog("L_INFO", "Message too big - M=$rm RURI=$ru F=$fu T=$tu IP=$si ID=$ci\n");
sl_send_reply("513", "Message Too Big");
exit;
}
if (!mf_process_maxfwd_header("10")) {
xlog("L_INFO", "Too many hops - M=$rm RURI=$ru F=$fu T=$tu IP=$si ID=$ci\n");
sl_send_reply("483", "Too Many Hops");
exit;
}

if(!is_method("REGISTER")) {
record_route();
}

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;
}

if(is_method("BYE")) {
setflag(1); # do accounting ...
setflag(3); # ... even if the transaction fails
}
route(2);
}

if(is_method("REGISTER")) {
route(1);
}

setflag(1); # do accounting ...
setflag(3); # ... even if the transaction fails

if(is_method("INVITE")) {
route(3);
}

if(is_method("CANCEL") || is_method("ACK")) {
route(7);
}

route(8);
}

# Request route 'base-route-register'
route[1] {
sl_send_reply("100", "Trying");
if (!www_authorize("", "subscriber")) {
xlog("L_INFO", "Register authentication failed - M=$rm RURI=$ru F=$fu T=$tu IP=$si ID=$ci\n");
www_challenge("", "0");
exit;
}
if (!check_to()) {
xlog("L_INFO", "Spoofed To-URI detected - M=$rm RURI=$ru F=$fu T=$tu IP=$si ID=$ci\n");
sl_send_reply("403","Forbidden auth ID");
exit;
}
if(!save("location")) {
xlog("L_ERR", "Saving contact failed - M=$rm RURI=$ru F=$fu T=$tu IP=$si ID=$ci\n");
sl_reply_error();
exit;
}

xlog("L_INFO", "Registration successful - M=$rm RURI=$ru F=$fu T=$tu IP=$si ID=$ci\n");
exit;
}

# Request route 'base-outbound'
route[2] {
t_on_reply("1");

t_on_failure("1");

xlog("L_INFO", "Request leaving server, D-URI='$du' - M=$rm RURI=$ru F=$fu T=$tu IP=$si ID=$ci\n");
if(!t_relay()) {
sl_reply_error();
}
exit;
}

# Request route 'base-route-invite'
route[3] {
if (!proxy_authorize("", "subscriber")) {
xlog("L_INFO", "Proxy authentication failed - M=$rm RURI=$ru F=$fu T=$tu IP=$si ID=$ci\n");
proxy_challenge("", "0");
exit;
}
if (!check_from()) {
xlog("L_INFO", "Spoofed From-URI detected - M=$rm RURI=$ru F=$fu T=$tu IP=$si ID=$ci\n");
sl_send_reply("403","Forbidden auth ID");
exit;
}
consume_credentials();

create_dialog();
set_dlg_flag("4");

route(4);
}

# Request route 'invite-find-callee'
route[4] {

if(!is_domain_local("$rd")) {
setflag(20);

route(6);
}

if(does_uri_exist()) {
xlog("L_INFO", "Callee is local - M=$rm RURI=$ru F=$fu T=$tu IP=$si ID=$ci\n");
route(5);
}
else {
xlog("L_INFO", "Callee is not local - M=$rm RURI=$ru F=$fu T=$tu IP=$si ID=$ci\n");
route(6);
}
exit;
}

# Request route 'invite-to-internal'
route[5] {
if (!lookup("location")) {
switch ($retcode) {
case -1:
case -3:
xlog("L_INFO", "Local user offline - M=$rm RURI=$ru F=$fu T=$tu IP=$si ID=$ci\n");
t_newtran();
t_reply("404", "Not Found");
exit;
case -2:
sl_send_reply("405", "Method Not Allowed");
exit;
}
}
else {
xlog("L_INFO", "Local user online - M=$rm RURI=$ru F=$fu T=$tu IP=$si ID=$ci\n");
route(2);
}
exit;

}

# Request route 'invite-to-external'
route[6] {
if(isflagset(20)) {
xlog("L_INFO", "Call to foreign domain - M=$rm RURI=$ru F=$fu T=$tu IP=$si ID=$ci\n");
route(2);
exit;
}

xlog("L_INFO", "Call to unknown user - M=$rm RURI=$ru F=$fu T=$tu IP=$si ID=$ci\n");
sl_send_reply("404", "User Not Found");
exit;
}

# Request route 'base-route-local'
route[7] {
t_on_reply("1");
if(t_check_trans()) {
xlog("L_INFO", "Request leaving server - M=$rm RURI=$ru F=$fu T=$tu IP=$si ID=$ci\n");
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;
}

# Request route 'base-route-generic'
route[8] {
xlog("L_INFO", "Method not supported - M=$rm RURI=$ru F=$fu T=$tu IP=$si ID=$ci\n");
sl_send_reply("501", "Method Not Supported Here");
exit;
}

# Request route 'base-filter-failover'
route[9] {
if(!t_check_status("408|500|503")) {
xlog("L_INFO", "No failover routing needed for this response code - M=$rm RURI=$ru F=$fu T=$tu IP=$si ID=$ci\n");
exit;
}
}

# Reply route 'base-standard-reply'
onreply_route[1] {
xlog("L_INFO", "Reply - S=$rs D=$rr F=$fu T=$tu IP=$si ID=$ci\n");
exit;
}

# Failure route 'base-standard-failure'
failure_route[1] {
if (t_was_cancelled()) {
route(9);
}
}

Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: DBG:core:parse_msg:  method:
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: DBG:core:parse_msg:  uri:
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: DBG:core:parse_msg:  version:
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: DBG:core:parse_headers: flags=2
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: DBG:core:parse_via_param: found param type 235,  = ; state=6
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: DBG:core:parse_via_param: found param type 232,  =
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: DBG:core:parse_via: end of header reached, state=5
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: DBG:core:parse_headers: via found, flags=2
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: DBG:core:parse_headers: this is the first via
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: DBG:core:receive_msg: After parse_msg...
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: DBG:core:receive_msg: preparing to run routing scripts...
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: DBG:sl:sl_filter_ACK: to late to be a local ACK!
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: DBG:core:parse_headers: flags=10
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: DBG:core:get_hdr_field: content_length=0
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: DBG:core:get_hdr_field: cseq : <2>
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: DBG:core:parse_to_param: tag=2989716276221805576
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: DBG:core:parse_to: end of header reached, state=29
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: DBG:core:parse_to: display={"Sjphone laptop_User"}, ruri={sip:1000 at mysip.com}
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: DBG:core:parse_headers: flags=8
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: DBG:core:parse_to_param: tag=1562350172
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: DBG:core:parse_to: end of header reached, state=29
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: DBG:core:parse_to: display={}, ruri={sip:1001 at mysip.com}
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: DBG:core:get_hdr_field:  [37]; uri=[sip:1001 at mysip.com]
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: DBG:core:get_hdr_field: to body []
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: New request - M=ACK RURI=sip:1001 at 10.10.45.102:5061 F=sip:1000 at mysip.com T=sip:$
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: DBG:maxfwd:is_maxfwd_present: value = 70
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: DBG:core:parse_headers: flags=200
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: DBG:rr:is_preloaded: is_preloaded: No
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: DBG:core:grep_sock_info: checking if host==us: 12==12 &&  [10.10.45.102] == [10$
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: DBG:core:grep_sock_info: checking if port 5060 matches port 5061
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: DBG:core:check_self: host != me
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: DBG:core:grep_sock_info: checking if host==us: 12==12 &&  [10.10.45.158] == [10$
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: DBG:core:grep_sock_info: checking if port 5060 matches port 5060
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: DBG:rr:after_loose: Topmost route URI: 'sip:10.10.45.158;lr=on;ftag=29897162762$
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: DBG:core:parse_headers: flags=200
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: DBG:core:get_hdr_field: found end of header
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: DBG:rr:find_next_route: No next Route HF found
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: DBG:rr:after_loose: No next URI found
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: DBG:rr:run_rr_callbacks: callback id 0 entered with
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: DBG:dialog:dlg_onroute: route param is '459.4612f0c' (len=11)
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: DBG:dialog:lookup_dlg: ref dlg 0xb5bf8ae0 with 1 -> 3
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: DBG:dialog:lookup_dlg: dialog id=202318180 found on entry 2388
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: DBG:core:parse_headers: flags=48
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: CRITICAL:dialog:log_next_state_dlg: bogus event 6 in state 2 for dlg 0xb5bf8ae0$
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: DBG:dialog:next_state_dlg: dialog 0xb5bf8ae0 changed from state 2 to state 2, d$
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: DBG:uri:has_totag: totag found
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: DBG:core:pv_get_dsturi: no destination URI
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: Request leaving server, D-URI=" - M=ACK RURI=sip:1001 at 10.10.45.102:5061 $
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: DBG:tm:t_newtran: transaction on entrance=0xffffffff
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: DBG:core:parse_headers: flags=ffffffffffffffff
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: DBG:core:parse_headers: flags=78
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: DBG:tm:t_lookup_request: start searching: hash=41562, isACK=1
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: DBG:core:parse_headers: flags=38
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: DBG:tm:t_lookup_request: REF_UNSAFE: after is 2
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: DBG:tm:t_lookup_request: e2e proxy ACK found
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: DBG:tm:t_newtran: building branch for end2end ACK
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: DBG:core:parse_headers: flags=8
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: DBG:tm:unmatched_totag: totag for e2e ACK found: 0
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: DBG:tm:run_trans_callbacks: trans=0xb5bf8c50, callback type 4, id 1 entered
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: DBG:core:parse_headers: flags=78
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: ACC: request acknowledged: timestamp=1235642726;method=ACK;from_tag=29897162762$
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: DBG:tm:t_relay_to: forwarding ACK
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: DBG:core:mk_proxy: doing DNS lookup...
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: DBG:core:forward_request: sending: ACK sip:1001 at 10.10.45.102:5061 SIP/2.0^M Rec$
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: DBG:core:forward_request: orig. len=480, new_len=559, proto=1
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: DBG:dialog:unref_dlg: unref dlg 0xb5bf8ae0 with 1 -> 2
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: DBG:tm:t_unref_cell: UNREF_UNSAFE: after is 1
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: DBG:core:destroy_avp_list: destroying list (nil)
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: DBG:core:receive_msg: cleaning up
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3610]: DBG:tm:run_trans_callbacks: trans=0xb5bf8c50, callback type 128, id 0 entered
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3610]: DBG:dialog:next_state_dlg: dialog 0xb5bf8ae0 changed from state 2 to state 3, d$
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3610]: DBG:dialog:dlg_onreply: dialog 0xb5bf8ae0 confirmed
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3610]: DBG:core:print_rr_body: current rr is
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3610]: DBG:core:print_rr_body: skipping 1 route records
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3610]: DBG:core:print_rr_body: out rr []
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3610]: DBG:core:print_rr_body: we have 1 records
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3610]: DBG:dialog:populate_leg_info: route_set , contact sip:1001 at 10.10.45.102:5061, c$
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3610]: DBG:dialog:update_dialog_dbinfo: sock_info is udp:10.10.45.158:5060
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3610]: ERROR:db_mysql:db_mysql_submit_query: driver error on query: Column 'callid' ca$
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3610]: ERROR:core:db_do_insert: error while submitting query
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3610]: ERROR:dialog:update_dialog_dbinfo: could not add another dialog to db
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3610]: DBG:dialog:insert_dlg_timer_unsafe: inserting 0xb5bf8b0c for 43204
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3610]: DBG:dialog:ref_dlg: ref dlg 0xb5bf8ae0 with 1 -> 3
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3610]: DBG:dialog:populate_leg_info: route_set , contact sip:1001 at 10.10.45.102:5061, c$
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3610]: DBG:dialog:update_dialog_dbinfo: sock_info is udp:10.10.45.158:5060
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3610]: ERROR:db_mysql:db_mysql_submit_query: driver error on query: Column 'callid' ca$
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3610]: ERROR:core:db_do_insert: error while submitting query
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3610]: ERROR:dialog:update_dialog_dbinfo: could not add another dialog to db
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3610]: DBG:dialog:insert_dlg_timer_unsafe: inserting 0xb5bf8b0c for 43204
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3610]: DBG:dialog:ref_dlg: ref dlg 0xb5bf8ae0 with 1 -> 3
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3610]: DBG:tm:cleanup_uac_timers: RETR/FR timers reset
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3610]: DBG:tm:t_unref: UNREF_UNSAFE: after is 0
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3610]: DBG:core:destroy_avp_list: destroying list (nil)
Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3610]: DBG:core:receive_msg: cleaning up

what these errors mean?

Thanks in advance

Matteo Marzuola

----------------------------------------------------------------------------
Vuoi essere presente online?
Vuoi dare voce alla tua attivita`?
Acquista un dominio su domini.interfree.it.
A partire da 18,59 euro
----------------------------------------------------------------------------

_______________________________________________
Users mailing list
Users at lists.opensips.org
http://lists.opensips.org/cgi-bin/mailman/listinfo/users

----------------------------------------------------------------------------
Vuoi essere presente online? 
Vuoi dare voce alla tua attivita`? 
Acquista un dominio su domini.interfree.it.
A partire da 18,59 euro
----------------------------------------------------------------------------