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:[email protected]:5062 F=sip:[email protected] T=sip:[email protected] IP=10.10.45.102 [email protected] 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 '[email protected]' 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:[email protected]:5062 F=sip:[email protected] T=sip:[email protected] IP=10.10.45.102 [email protected] 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;[email protected];code=200;reason=OK;caller_id=sip:[email protected];callee_id=sip:[email protected];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: [email protected] Inviato il: 26 Feb 2009 - 11:15 A: [email protected] 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:opensip...@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:[email protected]} 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:[email protected]} Feb 26 11:05:26 opensips-lab /usr/local/sbin/opensips[3608]: DBG:core:get_hdr_field: [37]; uri=[sip:[email protected]] 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:[email protected]:5061 F=sip:[email protected] 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:[email protected]: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:[email protected]: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:[email protected]: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:[email protected]: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 [email protected] 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 ---------------------------------------------------------------------------- _______________________________________________ Users mailing list [email protected] http://lists.opensips.org/cgi-bin/mailman/listinfo/users
