I created a special branch in case someone wants to propose more debuggability modifications
https://github.com/kamailio/kamailio/pull/2483 On Wed, Sep 23, 2020 at 10:33 AM Julien Chavanton <[email protected]> wrote: > I will start isolating to problem with this patch > > > > On Wed, Sep 23, 2020 at 9:17 AM Julien Chavanton <[email protected]> > wrote: > >> 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
