On Wed, 12 Aug 2020 at 10:24, Daniel-Constantin Mierla <miconda@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@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@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@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@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@192.168.50.139:5060','sip:+987654321@192.168.50.139','as5a6d564e','sip:+1234567890@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@192.168.50.139:5060','sip:192.168.82.230:5060',NULL,'<sip:192.168.82.250:5060;lr>',0,NULL,'sip:+1234567890@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@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@192.168.50.139:5060','29176259973485-74271626511770@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@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@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@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@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@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@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@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@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@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@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@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@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 List
sr-users@lists.kamailio.org
https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users
-- 
Daniel-Constantin Mierla -- www.asipto.com
www.twitter.com/miconda -- www.linkedin.com/in/miconda
Funding: https://www.paypal.me/dcmierla
-- 
Daniel-Constantin Mierla -- www.asipto.com
www.twitter.com/miconda -- www.linkedin.com/in/miconda
Funding: https://www.paypal.me/dcmierla
-- 
Daniel-Constantin Mierla -- www.asipto.com
www.twitter.com/miconda -- www.linkedin.com/in/miconda
Funding: https://www.paypal.me/dcmierla
_______________________________________________
Kamailio (SER) - Users Mailing List
sr-users@lists.kamailio.org
https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users
_______________________________________________
Kamailio (SER) - Users Mailing List
sr-users@lists.kamailio.org
https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users
_______________________________________________
Kamailio (SER) - Users Mailing List
sr-users@lists.kamailio.org
https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users
_______________________________________________
Kamailio (SER) - Users Mailing List
sr-users@lists.kamailio.org
https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users
-- 
Daniel-Constantin Mierla -- www.asipto.com
www.twitter.com/miconda -- www.linkedin.com/in/miconda
Funding: https://www.paypal.me/dcmierla
-- 
Daniel-Constantin Mierla -- www.asipto.com
www.twitter.com/miconda -- www.linkedin.com/in/miconda
Funding: https://www.paypal.me/dcmierla