[SR-Users] Dialog - timeout for dlg with CallID
Julien Chavanton
jchavanton at gmail.com
Wed Sep 23 19:33:01 CEST 2020
I will start isolating to problem with this patch
On Wed, Sep 23, 2020 at 9:17 AM Julien Chavanton <jchavanton at gmail.com>
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 <jchavanton at gmail.com>
> 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 <iliusha.md at gmail.com>
> 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 <iliusha.md at gmail.com>
>> 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 <iliusha.md at gmail.com>
>>> 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 <
>>>> miconda at gmail.com> 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:+1234567890 at 192.168.89.110
>>>>> <sip%3A%2B1234567890 at 192.168.89.110>>;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 <
>>>>> miconda at gmail.com> 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 <
>>>>>> miconda at gmail.com> 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=
>>>>>>> 5d905a9857b4136c42fc52242077ef58 at 192.168.50.139: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=
>>>>>>> 5d905a9857b4136c42fc52242077ef58 at 192.168.50.139: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=
>>>>>>> 5d905a9857b4136c42fc52242077ef58 at 192.168.50.139: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=
>>>>>>> 5d905a9857b4136c42fc52242077ef58 at 192.168.50.139: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,'
>>>>>>> 5d905a9857b4136c42fc52242077ef58 at 192.168.50.139:5060','
>>>>>>> sip:+987654321 at 192.168.50.139','as5a6d564e','
>>>>>>> sip:+1234567890 at 192.168.89.110
>>>>>>> ','05e27170-ffe5-4e90-b785-9a2fffa0194d','udp:192.168.50.12:5060
>>>>>>> ','udp:192.168.180.16:5060',1597217858,3,1538026468,'103','0','
>>>>>>> sip:+987654321 at 192.168.50.139:5060','sip:192.168.82.230:5060',NULL,'
>>>>>>> <sip:192.168.82.250:5060;lr>',0,NULL,'sip:+1234567890 at 192.168.89.110',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=
>>>>>>> 5d905a9857b4136c42fc52242077ef58 at 192.168.50.139: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=
>>>>>>> 5d905a9857b4136c42fc52242077ef58 at 192.168.50.139: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=
>>>>>>> 5d905a9857b4136c42fc52242077ef58 at 192.168.50.139: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=
>>>>>>> 5d905a9857b4136c42fc52242077ef58 at 192.168.50.139: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=
>>>>>>> 5d905a9857b4136c42fc52242077ef58 at 192.168.50.139: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=
>>>>>>> 5d905a9857b4136c42fc52242077ef58 at 192.168.50.139: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=
>>>>>>> 5d905a9857b4136c42fc52242077ef58 at 192.168.50.139: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=
>>>>>>> 5d905a9857b4136c42fc52242077ef58 at 192.168.50.139: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=
>>>>>>> 5d905a9857b4136c42fc52242077ef58 at 192.168.50.139: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=
>>>>>>> 5d905a9857b4136c42fc52242077ef58 at 192.168.50.139: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=
>>>>>>> 5d905a9857b4136c42fc52242077ef58 at 192.168.50.139: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=
>>>>>>> 5d905a9857b4136c42fc52242077ef58 at 192.168.50.139: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=
>>>>>>> 5d905a9857b4136c42fc52242077ef58 at 192.168.50.139: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=
>>>>>>> 5d905a9857b4136c42fc52242077ef58 at 192.168.50.139: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=
>>>>>>> 5d905a9857b4136c42fc52242077ef58 at 192.168.50.139: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=
>>>>>>> 5d905a9857b4136c42fc52242077ef58 at 192.168.50.139: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','
>>>>>>> 5d905a9857b4136c42fc52242077ef58 at 192.168.50.139: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=
>>>>>>> 5d905a9857b4136c42fc52242077ef58 at 192.168.50.139: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=
>>>>>>> 5d905a9857b4136c42fc52242077ef58 at 192.168.50.139: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=
>>>>>>> 5d905a9857b4136c42fc52242077ef58 at 192.168.50.139: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=
>>>>>>> 5d905a9857b4136c42fc52242077ef58 at 192.168.50.139: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 '
>>>>>>> 5d905a9857b4136c42fc52242077ef58 at 192.168.50.139: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 [
>>>>>>> 5d905a9857b4136c42fc52242077ef58 at 192.168.50.139: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
>>>>>>> 5d905a9857b4136c42fc52242077ef58 at 192.168.50.139:5060
>>>>>>> Aug 12 08:40:08 kamailio.localhost kamailio[28323]: WARNING: dialog
>>>>>>> [dlg_handlers.c:1652]: dlg_ontimeout(): dlg timeout - callid: '
>>>>>>> 5d905a9857b4136c42fc52242077ef58 at 192.168.50.139: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','
>>>>>>> 5d905a9857b4136c42fc52242077ef58 at 192.168.50.139:5060','
>>>>>>> 29176259973485-74271626511770 at 192.168.1.228','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 '
>>>>>>> 5d905a9857b4136c42fc52242077ef58 at 192.168.50.139: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 [
>>>>>>> 5d905a9857b4136c42fc52242077ef58 at 192.168.50.139: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
>>>>>>> 5d905a9857b4136c42fc52242077ef58 at 192.168.50.139: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 <
>>>>>>> miconda at gmail.com> 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 <pojogas at gmail.com>
>>>>>>>> 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 <shaheryarkh at gmail.com>
>>>>>>>>> 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 <
>>>>>>>>>> iliusha.md at gmail.com> 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: '
>>>>>>>>>>> 0555141d7d3hsag78sgce830391f9348 at 10.1.50.240:5060' tags:
>>>>>>>>>>> 'as52c10007' 'Uv7HS0jX65ctF' ostate: 3
>>>>>>>>>>>
>>>>>>>>>>> Any other ideas?
>>>>>>>>>>>
>>>>>>>>>>> On Tue, 28 Jul 2020 at 15:44, Daniel-Constantin Mierla <
>>>>>>>>>>> miconda at gmail.com> 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 <
>>>>>>>>>>>> miconda at gmail.com> 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 at 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 <
>>>>>>>>>>>>> miconda at gmail.com> 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 Listsr-users at lists.kamailio.orghttps://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
>>>>>>>>>>> sr-users at lists.kamailio.org
>>>>>>>>>>> https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users
>>>>>>>>>>>
>>>>>>>>>> _______________________________________________
>>>>>>>>>> Kamailio (SER) - Users Mailing List
>>>>>>>>>> sr-users at lists.kamailio.org
>>>>>>>>>> https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users
>>>>>>>>>>
>>>>>>>>> _______________________________________________
>>>>>>>>> Kamailio (SER) - Users Mailing List
>>>>>>>>> sr-users at lists.kamailio.org
>>>>>>>>> https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users
>>>>>>>>>
>>>>>>>>
>>>>>>>> _______________________________________________
>>>>>>>> Kamailio (SER) - Users Mailing Listsr-users at lists.kamailio.orghttps://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
>> sr-users at lists.kamailio.org
>> https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users
>>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.kamailio.org/pipermail/sr-users/attachments/20200923/c0c24ba0/attachment.htm>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: no-ack.diff
Type: text/x-patch
Size: 4112 bytes
Desc: not available
URL: <http://lists.kamailio.org/pipermail/sr-users/attachments/20200923/c0c24ba0/attachment.bin>
More information about the sr-users
mailing list