Hi, I am also troubleshooting unexpected no-ack disconnection. recently I added a modification to catch them before they would take place in the logs
commit 2f1338a67579c8fef58deec911d417851ff55cda (tag: v5.3.3.fr.4) Author: Julien Chavanton <[email protected]> Date: Fri Jul 24 14:51:02 2020 -0700 dialog: log no-ack timer disconnection diff --git a/src/modules/dialog/dlg_hash.c b/src/modules/dialog/dlg_hash.c index 4e0e28b788..273b43b286 100644 --- a/src/modules/dialog/dlg_hash.c +++ b/src/modules/dialog/dlg_hash.c @@ -243,6 +243,10 @@ int dlg_clean_run(ticks_t ti) unlink_unsafe_dlg(&d_table->entries[i], tdlg); destroy_dlg(tdlg); } + if(tdlg->state==DLG_STATE_CONFIRMED_NA && tdlg->start_ts>0 && tdlg->start_ts<tm-60) { + LM_NOTICE("dialog disconnection no-ACK call-id[%.*s][%u]<[%u - 60]\n", + tdlg->callid.len, tdlg->callid.s, tdlg->start_ts, tm); + } if(tdlg->state==DLG_STATE_CONFIRMED_NA && tdlg->start_ts>0 && tdlg->start_ts<tm-dlg_noack_timeout) { if(update_dlg_timer(&tdlg->tl, 10)<0) { I found many and they do not seem to be missing anything, the to/from/call-id and route header are there and when I replay some they work just fine. I am now adding more debugging lines in dlg_onroute to isolate the check/condition that is not updating the dialog on reception of an ACK I am also having a look at your logs to see if this seems to be the same problem On Mon, Aug 17, 2020 at 11:43 PM Ilie Soltanici <[email protected]> wrote: > Hello, > > Back to this issue again, I just got another DEBUG log file which seems to > have more information, could you please take a look? > Thank you. > > On Wed, 12 Aug 2020 at 15:18, Ilie Soltanici <[email protected]> wrote: > >> Hello, >> >> Setting the dlg_manage() function just before any other functions/vars >> didn't help either. I will try to get another debug log, maybe I will be >> able to get more information from there. >> Thanks >> >> On Wed, 12 Aug 2020 at 11:26, Ilie Soltanici <[email protected]> >> wrote: >> >>> Hello, >>> >>> OK, so I've added it as a first function in the request_route. >>> I will keep you updated. >>> Thanks >>> >>> On Wed, 12 Aug 2020 at 11:20, Daniel-Constantin Mierla < >>> [email protected]> wrote: >>> >>>> Hello, >>>> >>>> try with dlg_manage() before any of the dialog functions/vars -- I >>>> noticed a condition for skipping double processing, which could be a result >>>> of such case (I haven't dug further in the code yet). >>>> >>>> Cheers, >>>> Daniel >>>> On 12.08.20 12:06, Ilie Soltanici wrote: >>>> >>>> Hello, >>>> >>>> Yes, ACK have the To-tag: >>>> >>>> *To: <sip:[email protected] >>>> <sip%3A%[email protected]>>;tag=05e27170-ffe5-4e90-b785-9a2fffa0194d* >>>> >>>> Yes, I'm using dlg_va() function before calling dlg_manage() function. >>>> Could that be the reason? What is strange is that this is happening >>>> randomly (20-30 calls per day) with some of the calls only, and cannot be >>>> replicated. >>>> Thanks >>>> >>>> On Wed, 12 Aug 2020 at 10:54, Daniel-Constantin Mierla < >>>> [email protected]> wrote: >>>> >>>>> Do you have the pcap with the traffic of this call? Does the ACK has >>>>> the To-tag? Do you access dialog in any other way before calling >>>>> dlg_manage() (e.g., by $dlg_var() or other function from dialog module)? >>>>> >>>>> Cheers, >>>>> Daniel >>>>> On 12.08.20 11:48, Ilie Soltanici wrote: >>>>> >>>>> Unfortunately that's everything I can see for this call, maybe the >>>>> systemd daemon didn't log all the messages. It's strange as I have all >>>>> ratelimit's disabled. >>>>> I will try get another call log, hope that I would be able to get more >>>>> information there. >>>>> >>>>> Thanks >>>>> >>>>> On Wed, 12 Aug 2020 at 10:24, Daniel-Constantin Mierla < >>>>> [email protected]> wrote: >>>>> >>>>>> Hello, >>>>>> >>>>>> are these all debug messages printed for ACK processing? >>>>>> >>>>>> There should be a log message like: >>>>>> >>>>>> ... changed from state X to state Y ... >>>>>> >>>>>> Cheers, >>>>>> Daniel >>>>>> On 12.08.20 10:56, Ilie Soltanici wrote: >>>>>> >>>>>> Hello, >>>>>> >>>>>> After a couple of days trying to run kamailio in debug mode 3 finally >>>>>> I was able to catch one call with this issue. Please see below the Debug >>>>>> Log for the ACK: >>>>>> >>>>>> Aug 12 08:37:38 kamailio.localhost kamailio[28296]: DEBUG: {INVITE >>>>>> (2) | Seq=103 | Source IP=192.168.89.110 (udp) | Call ID= >>>>>> [email protected]:5060} <core> >>>>>> [db_query.c:72]: db_do_submit_query(): submitted query: insert into >>>>>> `dialog_vars` (`hash_entry`,`hash_id`,`dialog_key`,`dialog_value` ) >>>>>> values >>>>>> (273,1534,'start_time','1597217857.509'), result 0 >>>>>> Aug 12 08:37:38 kamailio.localhost kamailio[28296]: DEBUG: {INVITE >>>>>> (2) | Seq=103 | Source IP=192.168.89.110 (udp) | Call ID= >>>>>> [email protected]:5060} dialog >>>>>> [dlg_db_handler.c:834]: update_dialog_dbinfo_unsafe(): updated 13 vars >>>>>> for >>>>>> dlg [273:1534] >>>>>> Aug 12 08:37:38 kamailio.localhost kamailio[28296]: DEBUG: {INVITE >>>>>> (2) | Seq=103 | Source IP=192.168.89.110 (udp) | Call ID= >>>>>> [email protected]:5060} db_cluster >>>>>> [dbcl_api.c:483]: db_cluster_use_table(): use table (dialog) - cluster >>>>>> [kamailio] >>>>>> Aug 12 08:37:38 kamailio.localhost kamailio[28296]: DEBUG: {INVITE >>>>>> (2) | Seq=103 | Source IP=192.168.89.110 (udp) | Call ID= >>>>>> [email protected]:5060} <core> >>>>>> [db_query.c:72]: db_do_submit_query(): submitted query: insert into >>>>>> `dialog` >>>>>> (`hash_entry`,`hash_id`,`callid`,`from_uri`,`from_tag`,`to_uri`,`to_tag`,`caller_sock`,`callee_sock`,`start_time`,`state`,`timeout`,`caller_cseq`,`callee_cseq`,`caller_contact`,`callee_contact`,`caller_route_set`,`callee_route_set`,`sflags`,`toroute_name`,`req_uri`,`xdata`,`iflags` >>>>>> ) values (273,1534,' >>>>>> [email protected]:5060',' >>>>>> sip:[email protected]','as5a6d564e',' >>>>>> sip:[email protected] >>>>>> ','05e27170-ffe5-4e90-b785-9a2fffa0194d','udp:192.168.50.12:5060 >>>>>> ','udp:192.168.180.16:5060',1597217858,3,1538026468,'103','0',' >>>>>> sip:[email protected]:5060','sip:192.168.82.230:5060',NULL,' >>>>>> <sip:192.168.82.250:5060;lr>',0,NULL,'sip:[email protected]',NULL,0), >>>>>> result 0 >>>>>> Aug 12 08:37:38 kamailio.localhost kamailio[28296]: DEBUG: {INVITE >>>>>> (2) | Seq=103 | Source IP=192.168.89.110 (udp) | Call ID= >>>>>> [email protected]:5060} dialog >>>>>> [dlg_timer.c:110]: insert_dialog_timer_unsafe(): inserting 0x7f769a594418 >>>>>> for 59202190 >>>>>> Aug 12 08:37:38 kamailio.localhost kamailio[28296]: DEBUG: {INVITE >>>>>> (2) | Seq=103 | Source IP=192.168.89.110 (udp) | Call ID= >>>>>> [email protected]:5060} dialog >>>>>> [dlg_hash.c:1045]: dlg_ref_helper(): ref op on 0x7f769a5943b8 with 1 from >>>>>> dlg_handlers.c:557 >>>>>> Aug 12 08:37:38 kamailio.localhost kamailio[28296]: DEBUG: {INVITE >>>>>> (2) | Seq=103 | Source IP=192.168.89.110 (udp) | Call ID= >>>>>> [email protected]:5060} dialog >>>>>> [dlg_hash.c:1049]: dlg_ref_helper(): ref dlg 0x7f769a5943b8 with 1 -> 3 >>>>>> Aug 12 08:37:38 kamailio.localhost kamailio[28296]: DEBUG: {INVITE >>>>>> (2) | Seq=103 | Source IP=192.168.89.110 (udp) | Call ID= >>>>>> [email protected]:5060} dialog >>>>>> [dlg_hash.c:1065]: dlg_unref_helper(): unref op on 0x7f769a5943b8 with 1 >>>>>> from dlg_hash.c:1083 >>>>>> Aug 12 08:37:38 kamailio.localhost kamailio[28296]: DEBUG: {INVITE >>>>>> (2) | Seq=103 | Source IP=192.168.89.110 (udp) | Call ID= >>>>>> [email protected]:5060} <core> >>>>>> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <103> >>>>>> <INVITE> >>>>>> Aug 12 08:37:38 kamailio.localhost kamailio[28307]: DEBUG: {ACK (1) | >>>>>> Seq=103 | Source IP=192.168.50.139 (udp) | Call ID= >>>>>> [email protected]:5060} sl >>>>>> [sl_funcs.c:421]: sl_filter_ACK(): too late to be a local ACK! >>>>>> Aug 12 08:37:38 kamailio.localhost kamailio[28307]: DEBUG: {ACK (1) | >>>>>> Seq=103 | Source IP=192.168.50.139 (udp) | Call ID= >>>>>> [email protected]:5060} dialog >>>>>> [dlg_var.c:276]: print_lists(): ua=AGENT (flags 1) >>>>>> Aug 12 08:37:38 kamailio.localhost kamailio[28307]: DEBUG: {ACK (1) | >>>>>> Seq=103 | Source IP=192.168.50.139 (udp) | Call ID= >>>>>> [email protected]:5060} dialog >>>>>> [dlg_var.c:276]: print_lists(): ua=AGENT (flags 1) >>>>>> Aug 12 08:37:38 kamailio.localhost kamailio[28307]: DEBUG: {ACK (1) | >>>>>> Seq=103 | Source IP=192.168.50.139 (udp) | Call ID= >>>>>> [email protected]:5060} dialog >>>>>> [dlg_var.c:276]: print_lists(): dest_ip=192.168.89.110 (flags 1) >>>>>> Aug 12 08:37:38 kamailio.localhost kamailio[28307]: DEBUG: {ACK (1) | >>>>>> Seq=103 | Source IP=192.168.50.139 (udp) | Call ID= >>>>>> [email protected]:5060} dialog >>>>>> [dlg_var.c:276]: print_lists(): dest_ip=192.168.89.110 (flags 1) >>>>>> Aug 12 08:37:38 kamailio.localhost kamailio[28307]: DEBUG: {ACK (1) | >>>>>> Seq=103 | Source IP=192.168.50.139 (udp) | Call ID= >>>>>> [email protected]:5060} rr >>>>>> [loose.c:90]: is_preloaded(): is_preloaded: No >>>>>> Aug 12 08:37:38 kamailio.localhost kamailio[28307]: DEBUG: {ACK (1) | >>>>>> Seq=103 | Source IP=192.168.50.139 (udp) | Call ID= >>>>>> [email protected]:5060} dialog >>>>>> [dlg_hash.c:1065]: dlg_unref_helper(): unref op on 0x7f769a5c8b48 with 1 >>>>>> from dlg_hash.c:1083 >>>>>> Aug 12 08:37:38 kamailio.localhost kamailio[28307]: DEBUG: {ACK (1) | >>>>>> Seq=103 | Source IP=192.168.50.139 (udp) | Call ID= >>>>>> [email protected]:5060} dialog >>>>>> [dlg_var.c:276]: print_lists(): log=1 (flags 3) >>>>>> Aug 12 08:37:38 kamailio.localhost kamailio[28307]: DEBUG: {ACK (1) | >>>>>> Seq=103 | Source IP=192.168.50.139 (udp) | Call ID= >>>>>> [email protected]:5060} dialog >>>>>> [dlg_var.c:276]: print_lists(): called_number=0123456789 (flags 1) >>>>>> Aug 12 08:37:38 kamailio.localhost kamailio[28307]: DEBUG: {ACK (1) | >>>>>> Seq=103 | Source IP=192.168.50.139 (udp) | Call ID= >>>>>> [email protected]:5060} tm >>>>>> [t_lookup.c:1330]: t_newtran(): msg (0x7f76bf204b68) id=5441/28307 global >>>>>> id=5440/28307 T start=(nil) >>>>>> Aug 12 08:37:38 kamailio.localhost kamailio[28307]: DEBUG: {ACK (1) | >>>>>> Seq=103 | Source IP=192.168.50.139 (udp) | Call ID= >>>>>> [email protected]:5060} <core> >>>>>> [db_query.c:72]: db_do_submit_query(): submitted query: insert into `acc` >>>>>> (`method`,`from_tag`,`to_tag`,`callid`,`sip_code`,`sip_reason`,`time`,`time_attr`,`time_exten`,`src_user`,`src_domain`,`src_ip`,`dst_ouser`,`dst_user`,`dst_domain`,`cseq` >>>>>> ) values ('ACK','as5a6d564e','05e27170-ffe5-4e90-b785-9a2fffa0194d',' >>>>>> [email protected]:5060','200','OK','2020-08-12 >>>>>> 08:37:38',1597217858,642167,'+987654321','192.168.50.139','192.168.50.139','+0123456789','','192.168.82.230','103'), >>>>>> result 0 >>>>>> Aug 12 08:37:38 kamailio.localhost kamailio[28307]: DEBUG: {ACK (1) | >>>>>> Seq=103 | Source IP=192.168.50.139 (udp) | Call ID= >>>>>> [email protected]:5060} acc >>>>>> [acc_extra.h:64]: free_strar_mem(): Freeing memory, type is 2, >>>>>> message_index 9, index i 0 >>>>>> Aug 12 08:37:38 kamailio.localhost kamailio[28307]: DEBUG: {ACK (1) | >>>>>> Seq=103 | Source IP=192.168.50.139 (udp) | Call ID= >>>>>> [email protected]:5060} acc >>>>>> [acc_extra.h:64]: free_strar_mem(): Freeing memory, type is 2, >>>>>> message_index 9, index i 1 >>>>>> Aug 12 08:37:38 kamailio.localhost kamailio[28307]: DEBUG: {ACK (1) | >>>>>> Seq=103 | Source IP=192.168.50.139 (udp) | Call ID= >>>>>> [email protected]:5060} acc >>>>>> [acc_extra.h:64]: free_strar_mem(): Freeing memory, type is 2, >>>>>> message_index 9, index i 2 >>>>>> Aug 12 08:37:38 kamailio.localhost kamailio[28307]: DEBUG: {ACK (1) | >>>>>> Seq=103 | Source IP=192.168.50.139 (udp) | Call ID= >>>>>> [email protected]:5060} <core> >>>>>> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: >>>>>> tag=05e27170-ffe5-4e90-b785-9a2fffa0194d >>>>>> Aug 12 08:37:42 kamailio.localhost kamailio[28324]: DEBUG: dialog >>>>>> [dlg_hash.c:361]: destroy_dlg(): removed timer for dlg 0x7f769a5c8b48 >>>>>> [273:1533] with clid ' >>>>>> [email protected]:5060' and tags >>>>>> 'as5a6d564e' '' >>>>>> Aug 12 08:37:42 kamailio.localhost kamailio[28324]: DEBUG: dialog >>>>>> [dlg_db_handler.c:710]: remove_dialog_from_db(): trying to remove dialog >>>>>> [ >>>>>> [email protected]:5060], update_flag >>>>>> is 640 >>>>>> Aug 12 08:37:42 kamailio.localhost kamailio[28324]: DEBUG: dialog >>>>>> [dlg_db_handler.c:736]: remove_dialog_from_db(): callid was >>>>>> [email protected]:5060 >>>>>> Aug 12 08:40:08 kamailio.localhost kamailio[28323]: WARNING: dialog >>>>>> [dlg_handlers.c:1652]: dlg_ontimeout(): dlg timeout - callid: ' >>>>>> [email protected]:5060' tags: >>>>>> 'as5a6d564e' '05e27170-ffe5-4e90-b785-9a2fffa0194d' ostate: 3 >>>>>> Aug 12 08:40:08 kamailio.localhost kamailio[28323]: DEBUG: <core> >>>>>> [db_query.c:72]: db_do_submit_query(): submitted query: insert into >>>>>> `acc_cdrs` >>>>>> (`start_time`,`end_time`,`duration`,`account_id`,`aleg_uuid`,`bleg_uuid`,`caller_number`,`called_number`,`sip_code`,`sip_reason`,`sip_user_agent`,`kamailio_server`,`billsec`,`src_ip`,`dest_ip`,`direction` >>>>>> ) values ('2020-08-12 08:37:37','2020-08-12 08:37:37',0.000000 ,'101',' >>>>>> [email protected]:5060',' >>>>>> [email protected]','987654321','0123456789',NULL,NULL,'AGENT','SRV',NULL,'192.168.50.139','192.168.89.110','OUTBOUND'), >>>>>> result 0 >>>>>> Aug 12 08:40:08 kamailio.localhost kamailio[28323]: DEBUG: dialog >>>>>> [dlg_hash.c:361]: destroy_dlg(): removed timer for dlg 0x7f769a5943b8 >>>>>> [273:1534] with clid ' >>>>>> [email protected]:5060' and tags >>>>>> 'as5a6d564e' '05e27170-ffe5-4e90-b785-9a2fffa0194d' >>>>>> Aug 12 08:40:08 kamailio.localhost kamailio[28323]: DEBUG: dialog >>>>>> [dlg_db_handler.c:710]: remove_dialog_from_db(): trying to remove dialog >>>>>> [ >>>>>> [email protected]:5060], update_flag >>>>>> is 1542 >>>>>> Aug 12 08:40:08 kamailio.localhost kamailio[28323]: DEBUG: dialog >>>>>> [dlg_db_handler.c:736]: remove_dialog_from_db(): callid was >>>>>> [email protected]:5060 >>>>>> >>>>>> >>>>>> What I noticed strange here, is that SL module reporting: >>>>>> >>>>>> * sl_filter_ACK(): too late to be a local ACK! * >>>>>> >>>>>> I'm not sure that this is the core of the problem, but maybe you can >>>>>> spot something here. >>>>>> >>>>>> This is sl_module configuration, in case if you'll need it: >>>>>> # ---- sl params ---- >>>>>> modparam("sl", "default_code", 505) >>>>>> modparam("sl", "default_reason", "Server Error") >>>>>> >>>>>> Thanks. >>>>>> >>>>>> On Thu, 30 Jul 2020 at 07:22, Daniel-Constantin Mierla < >>>>>> [email protected]> wrote: >>>>>> >>>>>>> Hello, >>>>>>> >>>>>>> run with debug=3 in kamailio.cfg and send here all the log messages >>>>>>> printed by kamailio when processing the ACK. >>>>>>> >>>>>>> Cheers, >>>>>>> Daniel >>>>>>> On 29.07.20 18:48, Ilie Soltanici wrote: >>>>>>> >>>>>>> Hello, >>>>>>> >>>>>>> I changed the configuration file to call dlg_manage() for all >>>>>>> methods: >>>>>>> >>>>>>> if (loose_route()) { >>>>>>> dlg_manage(); >>>>>>> >>>>>>> if (is_method("BYE")) { >>>>>>> setflag(FLAG_ACC); >>>>>>> setflag(FLAG_ACCMISSED); >>>>>>> $dlg_var(billsec) = $DLG_lifetime; >>>>>>> } >>>>>>> >>>>>>> route(RELAY); >>>>>>> exit; >>>>>>> }; >>>>>>> >>>>>>> but, unfortunately this is not helping either. I'm not sure that >>>>>>> there is a buggy UA messing RR because this is happening with 4 >>>>>>> Providers >>>>>>> randomly. >>>>>>> What else I noticed is that this is happening mostly with ISP's >>>>>>> using authorization, with other ISPs using IP as whitelisted source I >>>>>>> didn't notice anything like that. >>>>>>> Could this be related somehow? >>>>>>> Thanks. >>>>>>> >>>>>>> >>>>>>> On Wed, 29 Jul 2020 at 17:19, Sergiu Pojoga <[email protected]> >>>>>>> wrote: >>>>>>> >>>>>>>> Correct me if I'm wrong, but not all within-dialogs are 'calls', >>>>>>>> for e.g. NOTIFY with a preset Route after SUBSCRIBE, wondering how >>>>>>>> dlg_manage() would treat those, would it count them as 'calls'? >>>>>>>> >>>>>>>> Not to mention that docs mention "dlg_manage() - this makes sense >>>>>>>> only for initial requests) >>>>>>>> >>>>>>>> On Wed, Jul 29, 2020 at 10:55 AM M S <[email protected]> wrote: >>>>>>>> >>>>>>>>> Please put dlg_manage immediately after loose_route condition, >>>>>>>>> e.g. >>>>>>>>> >>>>>>>>> if (loose_route) { >>>>>>>>> dlg_manage(); >>>>>>>>> ... >>>>>>>>> } >>>>>>>>> >>>>>>>>> There is no harm in calling it for every SIP method (not just BYE >>>>>>>>> or ACK) within dialog. It will help for re-invites (call hold / unhold >>>>>>>>> events) etc. from same buggy UAs as well. >>>>>>>>> >>>>>>>>> Thank you. >>>>>>>>> >>>>>>>>> >>>>>>>>> On Wed, Jul 29, 2020 at 3:21 PM Ilie Soltanici < >>>>>>>>> [email protected]> wrote: >>>>>>>>> >>>>>>>>>> Hello, >>>>>>>>>> >>>>>>>>>> I've tried what you recommended, but without success so far. >>>>>>>>>> >>>>>>>>>> This is the configuration block: >>>>>>>>>> >>>>>>>>>> if (!has_totag()) return; >>>>>>>>>> >>>>>>>>>> if (is_method("ACK")) { >>>>>>>>>> dlg_manage(); >>>>>>>>>> } >>>>>>>>>> >>>>>>>>>> if (loose_route()) { >>>>>>>>>> if (is_method("BYE")) { >>>>>>>>>> dlg_manage(); >>>>>>>>>> setflag(FLAG_ACC); >>>>>>>>>> setflag(FLAG_ACCMISSED); >>>>>>>>>> $dlg_var(billsec) = $DLG_lifetime; >>>>>>>>>> } >>>>>>>>>> route(RELAY); >>>>>>>>>> exit; >>>>>>>>>> }; >>>>>>>>>> >>>>>>>>>> if (is_method("ACK") ) { >>>>>>>>>> if ( t_check_trans() ) { >>>>>>>>>> route(RELAY); >>>>>>>>>> exit; >>>>>>>>>> } else { >>>>>>>>>> sl_send_reply("606", "Not Acceptable"); >>>>>>>>>> exit; >>>>>>>>>> } >>>>>>>>>> } >>>>>>>>>> >>>>>>>>>> Here is the sip trace: >>>>>>>>>> https://pastebin.com/Aen2GCjm >>>>>>>>>> >>>>>>>>>> And that's the error I'm getting in the Kamailio log file: >>>>>>>>>> >>>>>>>>>> WARNING: dialog [dlg_handlers.c:1652]: dlg_ontimeout(): dlg >>>>>>>>>> timeout - callid: ' >>>>>>>>>> [email protected]:5060' tags: >>>>>>>>>> 'as52c10007' 'Uv7HS0jX65ctF' ostate: 3 >>>>>>>>>> >>>>>>>>>> Any other ideas? >>>>>>>>>> >>>>>>>>>> On Tue, 28 Jul 2020 at 15:44, Daniel-Constantin Mierla < >>>>>>>>>> [email protected]> wrote: >>>>>>>>>> >>>>>>>>>>> Hello, >>>>>>>>>>> >>>>>>>>>>> I see the in-dialog ACK in the trace, try with dlg_manage() >>>>>>>>>>> explicitly used for it. >>>>>>>>>>> >>>>>>>>>>> The warning messages are not when processing the ack, but on >>>>>>>>>>> dialog timeout, if you do not get some other errors like 90-120 >>>>>>>>>>> seconds >>>>>>>>>>> before, when the ack was routed, then it was no processing error >>>>>>>>>>> for it. >>>>>>>>>>> >>>>>>>>>>> Cheers, >>>>>>>>>>> Daniel >>>>>>>>>>> On 28.07.20 12:31, Ilie Soltanici wrote: >>>>>>>>>>> >>>>>>>>>>> Hello, >>>>>>>>>>> >>>>>>>>>>> In the Kamailio logs I can see only those errors: >>>>>>>>>>> >>>>>>>>>>> WARNING: dialog [dlg_handlers.c:1652]: dlg_ontimeout(): dlg >>>>>>>>>>> timeout - callid: '45b0130e14a692b95134696d2fc5f2a9' tags: >>>>>>>>>>> 'as31fb1118' >>>>>>>>>>> '12UDcK9S8630r' ostate: 3 >>>>>>>>>>> WARNING: acc [acc_cdr.c:230]: db_write_cdr(): fallback to >>>>>>>>>>> dlg_only search because of message doesn't exist >>>>>>>>>>> >>>>>>>>>>> Here you can see the full sip trace: >>>>>>>>>>> https://pastebin.com/Q4eqcGJj >>>>>>>>>>> >>>>>>>>>>> The First Invite it's from the Asterisk server (192.168.0.140), >>>>>>>>>>> and the second one - it's from Kamailio (192.168.1.16), >>>>>>>>>>> 192.168.2.0/24 - it's an ISP. What 's strange for me here is >>>>>>>>>>> that Kamailio it's still adding rr_param to the RR Header even if >>>>>>>>>>> it's >>>>>>>>>>> disabled in the module configuration, why would that be? >>>>>>>>>>> >>>>>>>>>>> This is the module configuration: >>>>>>>>>>> modparam("dialog", "enable_stats", 1) >>>>>>>>>>> modparam("dialog", "rr_param", "did") >>>>>>>>>>> modparam("dialog", "dlg_match_mode", 2) >>>>>>>>>>> modparam("dialog", "default_timeout", 10800) >>>>>>>>>>> modparam("dialog", "early_timeout", 180) >>>>>>>>>>> modparam("dialog", "noack_timeout", 90) >>>>>>>>>>> modparam("dialog", "track_cseq_updates", 1) >>>>>>>>>>> modparam("dialog", "dlg_extra_hdrs", "Hint: Inactivity Timeout >>>>>>>>>>> \r\n") >>>>>>>>>>> modparam("dialog", "detect_spirals", 1) >>>>>>>>>>> modparam("dialog", "db_mode", 1) >>>>>>>>>>> >>>>>>>>>>> I will try to run dlg_manage for ACK within the dialog and see >>>>>>>>>>> if it works. >>>>>>>>>>> Thank you. >>>>>>>>>>> >>>>>>>>>>> >>>>>>>>>>> On Tue, 28 Jul 2020 at 09:26, Daniel-Constantin Mierla < >>>>>>>>>>> [email protected]> wrote: >>>>>>>>>>> >>>>>>>>>>>> Hello, >>>>>>>>>>>> >>>>>>>>>>>> that confirms my guessing -- the ack was not handled in the >>>>>>>>>>>> dialog context, the state 3 is defined inside dlg_hash.h by: >>>>>>>>>>>> >>>>>>>>>>>> #define DLG_STATE_CONFIRMED_NA 3 /*!< confirmed dialog without >>>>>>>>>>>> a ACK yet */ >>>>>>>>>>>> >>>>>>>>>>>> Do you see any error messages in the logs when handling the ACK >>>>>>>>>>>> in the config? Did you grab the pcap with sip traffic for such a >>>>>>>>>>>> call? >>>>>>>>>>>> >>>>>>>>>>>> Try also to explicitly execute dlg_manage() for ACK within >>>>>>>>>>>> dialog. >>>>>>>>>>>> >>>>>>>>>>>> Cheers, >>>>>>>>>>>> Daniel >>>>>>>>>>>> On 28.07.20 10:05, Ilie Soltanici wrote: >>>>>>>>>>>> >>>>>>>>>>>> Hello, >>>>>>>>>>>> >>>>>>>>>>>> I re-compiled Kamailio from the Master branch and I'm getting >>>>>>>>>>>> the old state: 3 >>>>>>>>>>>> >>>>>>>>>>>> *dlg_ontimeout(): dlg timeout - callid: >>>>>>>>>>>> '225ce4fc79d78c0f5477d02d02f3feea' tags: 'as3f0a58cf' >>>>>>>>>>>> 'a9eb002d-c544-47f7-84ec-1c4e690cd0b4' ostate: 3* >>>>>>>>>>>> >>>>>>>>>>>> [ilie.soltanici@dev ~]$ /usr/local/sbin/kamailio -V >>>>>>>>>>>> version: kamailio 5.3.5 (x86_64/linux) ff2f8c >>>>>>>>>>>> >>>>>>>>>>>> Thanks >>>>>>>>>>>> >>>>>>>>>>>> On Mon, 27 Jul 2020 at 08:56, Daniel-Constantin Mierla < >>>>>>>>>>>> [email protected]> wrote: >>>>>>>>>>>> >>>>>>>>>>>>> Hello, >>>>>>>>>>>>> >>>>>>>>>>>>> this sounds like the ACK is not matched for dialog processing >>>>>>>>>>>>> and the early_timeout is firing. I just pushed a commit to dialog >>>>>>>>>>>>> module to >>>>>>>>>>>>> print the old state when the timeout callback function is >>>>>>>>>>>>> executed, maybe >>>>>>>>>>>>> you can test with it -- it is in branch 5.3: >>>>>>>>>>>>> >>>>>>>>>>>>> - >>>>>>>>>>>>> https://github.com/kamailio/kamailio/commit/ff2f8c4e63b4fefa7dc5b10835505c3c4ae84388 >>>>>>>>>>>>> >>>>>>>>>>>>> Otherwise, maybe call dlg_manage() for ACK, although the >>>>>>>>>>>>> loose_route() callback should be executed and ACK handled for >>>>>>>>>>>>> dialog >>>>>>>>>>>>> processing. >>>>>>>>>>>>> >>>>>>>>>>>>> Cheers, >>>>>>>>>>>>> Daniel >>>>>>>>>>>>> On 24.07.20 12:46, Ilie Soltanici wrote: >>>>>>>>>>>>> >>>>>>>>>>>>> Hello, >>>>>>>>>>>>> >>>>>>>>>>>>> I'm trying to get CDR working in Kamailio by using the acc and >>>>>>>>>>>>> dialog modules. Everything seemed to be working fine - until i >>>>>>>>>>>>> noticed that >>>>>>>>>>>>> for some of the calls the call duration is 0, even if that call >>>>>>>>>>>>> has been >>>>>>>>>>>>> successfully established and duration was for about a few >>>>>>>>>>>>> minutes. In the >>>>>>>>>>>>> Kamailio logs I'm getting such errors: >>>>>>>>>>>>> >>>>>>>>>>>>> WARNING: dialog [dlg_handlers.c:1649]: dlg_ontimeout(): >>>>>>>>>>>>> timeout for dlg with CallID '304bad142b50bb3a7a117816439ea3d5' >>>>>>>>>>>>> and tags >>>>>>>>>>>>> 'as3adde5c7' '7d28152f-e0e3-4bcf-9d5c-21c3723b95c5' >>>>>>>>>>>>> WARNING: acc [acc_cdr.c:230]: db_write_cdr(): fallback to >>>>>>>>>>>>> dlg_only search because of message doesn't exist. >>>>>>>>>>>>> >>>>>>>>>>>>> This error I'm getting at about 2 min after the ACK message >>>>>>>>>>>>> for 200 OK. I'm not sure that this is related to the dialog >>>>>>>>>>>>> timeout, but >>>>>>>>>>>>> below you can see the related configuration for the dialog module: >>>>>>>>>>>>> >>>>>>>>>>>>> modparam("dialog", "default_timeout", 10800) # 3 hours >>>>>>>>>>>>> modparam("dialog", "early_timeout", 180) >>>>>>>>>>>>> modparam("dialog", "noack_timeout", 90) >>>>>>>>>>>>> >>>>>>>>>>>>> Unfortunately, I'm not able to reproduce this issue, as that's >>>>>>>>>>>>> happening randomly and just a few times per day. On the SIP Level >>>>>>>>>>>>> i didn't >>>>>>>>>>>>> notice any strange issues. >>>>>>>>>>>>> >>>>>>>>>>>>> Any ideas why is that happening? >>>>>>>>>>>>> Thank you. >>>>>>>>>>>>> >>>>>>>>>>>>> _______________________________________________ >>>>>>>>>>>>> Kamailio (SER) - Users Mailing >>>>>>>>>>>>> [email protected]https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users >>>>>>>>>>>>> >>>>>>>>>>>>> -- >>>>>>>>>>>>> Daniel-Constantin Mierla -- www.asipto.comwww.twitter.com/miconda >>>>>>>>>>>>> -- www.linkedin.com/in/miconda >>>>>>>>>>>>> Funding: https://www.paypal.me/dcmierla >>>>>>>>>>>>> >>>>>>>>>>>>> -- >>>>>>>>>>>> Daniel-Constantin Mierla -- www.asipto.comwww.twitter.com/miconda >>>>>>>>>>>> -- www.linkedin.com/in/miconda >>>>>>>>>>>> Funding: https://www.paypal.me/dcmierla >>>>>>>>>>>> >>>>>>>>>>>> -- >>>>>>>>>>> Daniel-Constantin Mierla -- www.asipto.comwww.twitter.com/miconda >>>>>>>>>>> -- www.linkedin.com/in/miconda >>>>>>>>>>> Funding: https://www.paypal.me/dcmierla >>>>>>>>>>> >>>>>>>>>>> _______________________________________________ >>>>>>>>>> Kamailio (SER) - Users Mailing List >>>>>>>>>> [email protected] >>>>>>>>>> https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users >>>>>>>>>> >>>>>>>>> _______________________________________________ >>>>>>>>> Kamailio (SER) - Users Mailing List >>>>>>>>> [email protected] >>>>>>>>> https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users >>>>>>>>> >>>>>>>> _______________________________________________ >>>>>>>> Kamailio (SER) - Users Mailing List >>>>>>>> [email protected] >>>>>>>> https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users >>>>>>>> >>>>>>> >>>>>>> _______________________________________________ >>>>>>> Kamailio (SER) - Users Mailing >>>>>>> [email protected]https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users >>>>>>> >>>>>>> -- >>>>>>> Daniel-Constantin Mierla -- www.asipto.comwww.twitter.com/miconda -- >>>>>>> www.linkedin.com/in/miconda >>>>>>> Funding: https://www.paypal.me/dcmierla >>>>>>> >>>>>>> -- >>>>>> Daniel-Constantin Mierla -- www.asipto.comwww.twitter.com/miconda -- >>>>>> www.linkedin.com/in/miconda >>>>>> Funding: https://www.paypal.me/dcmierla >>>>>> >>>>>> -- >>>>> Daniel-Constantin Mierla -- www.asipto.comwww.twitter.com/miconda -- >>>>> www.linkedin.com/in/miconda >>>>> Funding: https://www.paypal.me/dcmierla >>>>> >>>>> -- >>>> Daniel-Constantin Mierla -- www.asipto.comwww.twitter.com/miconda -- >>>> www.linkedin.com/in/miconda >>>> Funding: https://www.paypal.me/dcmierla >>>> >>>> _______________________________________________ > Kamailio (SER) - Users Mailing List > [email protected] > https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users >
_______________________________________________ Kamailio (SER) - Users Mailing List [email protected] https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users
