[tracker] Task opened: ACK not in transaction when t_relay or t_check

Discussion:

[tracker] Task opened: ACK not in transaction when t_relay or t_check_trans

sip-router

2012-05-10 15:05:24 UTC

THIS IS AN AUTOMATED MESSAGE, DO NOT REPLY.

A new Flyspray task has been opened. Details are below.

User who did this - Pawel Sternal (Sternik)

Attached to Project - sip-router
Summary - ACK not in transaction when t_relay or t_check_trans
Task Type - Bug Report
Category - Core
Status - Unconfirmed
Assigned To -
Operating System - Linux
Severity - Low
Priority - Normal
Reported Version - Development
Due in Version - Undecided
Due Date - Undecided
Details - Hi. We have noticed in currently installed kamailio 3.2.2 have problem with ACK. In kamailio 1.5.2 there are no problem with it. When kamailio received and forward 200ok, ACK on that response is not in transaction. ACK after that is forwarding statelessly - header Record-Route is added to the package.

I'm looking at the diff between src of t_lookup.c with this "problem", and only I'm found that in 3.2.2, this ACK is in "2 - full match to a proxied transaction" when function "ack_matching" is call.

Below two output of this same connection, after trying t_relay(). Also when I'm trying to "t_check_trans". ACK is not matched to 200ok.
This is kamailio 1.5.2 log output
{code}
May 10 13:35:54 kamailio /usr/sbin/kamailio[5715]: DBG:tm:t_newtran: transaction on entrance=0xffffffff
May 10 13:35:54 kamailio /usr/sbin/kamailio[5715]: DBG:core:parse_headers: flags=ffffffffffffffff
May 10 13:35:54 kamailio /usr/sbin/kamailio[5715]: DBG:core:parse_headers: flags=78
May 10 13:35:54 kamailio /usr/sbin/kamailio[5715]: DBG:tm:t_lookup_request: start searching: hash=63132, isACK=1
May 10 13:35:54 kamailio /usr/sbin/kamailio[5715]: DBG:core:parse_headers: flags=38
May 10 13:35:54 kamailio /usr/sbin/kamailio[5715]: DBG:tm:t_lookup_request: RFC3261 ACK matched
May 10 13:35:54 kamailio /usr/sbin/kamailio[5715]: DBG:tm:t_lookup_request: REF_UNSAFE: after is 1
May 10 13:35:54 kamailio /usr/sbin/kamailio[5715]: DBG:tm:t_lookup_request: e2e proxy ACK found
May 10 13:35:54 kamailio /usr/sbin/kamailio[5715]: DBG:tm:t_newtran: building branch for end2end ACK
May 10 13:35:54 kamailio /usr/sbin/kamailio[5715]: DBG:tm:t_relay_to: forwarding ACK
May 10 13:35:54 kamailio /usr/sbin/kamailio[5715]: DBG:core:mk_proxy: doing DNS lookup...
May 10 13:35:54 kamailio /usr/sbin/kamailio[5715]: DBG:core:forward_request: sending: ACK sip:***@IP_ADDR:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP IP_ADDR;branch=z9hG4bKc96f.0501e9d4.2 Via: SIP/2.0/UDP IP_ADDR:5061;received=127.0.0.1;branch=z9hG4bK363e1c74;rport=5061 From: "NUM" <sip:***@IP>;tag=as3f095bcb To: <sip:***@IP_ADDR>;tag=chfs37pbjs4ecadm.i Contact: <sip:***@IP:5061> Call-ID: ***@IP CSeq: 102 ACK User-Agent: Server Max-Forwards: 70 Remote-Party-ID: "NUM" <sip:***@IP>;privacy=off;screen=no Content-Length: 0 .
May 10 13:35:54 kamailio /usr/sbin/kamailio[5715]: DBG:core:forward_request: orig. len=597, new_len=631, proto=1
May 10 13:35:54 kamailio /usr/sbin/kamailio[5715]: DBG:tm:t_unref_cell: UNREF_UNSAFE: after is 0
May 10 13:35:54 kamailio /usr/sbin/kamailio[5715]: DBG:core:destroy_avp_list: destroying list 0xb3381970
May 10 13:35:54 kamailio /usr/sbin/kamailio[5715]: DBG:core:receive_msg: cleaning up
{code}

This is kamailio 3.2.2 log output
{code}
May 10 12:23:43 kamailio /usr/sbin/kamailio[23198]: DEBUG: tm [t_lookup.c:1379]: DEBUG: t_newtran: msg id=35377 , global msg id=35376 , T on entrance=0xffffffff
May 10 12:23:43 kamailio /usr/sbin/kamailio[23198]: DEBUG: tm [t_lookup.c:527]: t_lookup_request: start searching: hash=4487, isACK=1
May 10 12:23:43 kamailio /usr/sbin/kamailio[23198]: DEBUG: tm [t_lookup.c:485]: DEBUG: RFC3261 transaction matching failed
May 10 12:23:43 kamailio /usr/sbin/kamailio[23198]: DEBUG: tm [t_lookup.c:709]: DEBUG: t_lookup_request: no transaction found
May 10 12:23:43 kamailio /usr/sbin/kamailio[23198]: DEBUG: tm [t_funcs.c:315]: SER: forwarding ACK statelessly
May 10 12:23:43 kamailio /usr/sbin/kamailio[23198]: DEBUG: <core> [msg_translator.c:204]: check_via_address(127.0.0.1, IP, 0)
May 10 12:23:43 kamailio /usr/sbin/kamailio[23198]: DEBUG: <core> [forward.c:601]: Sending: ACK sip:***@IP:5060;transport=udp SIP/2.0 Record-Route: <sip:IP:5060;ftag=as50b3af68;lr> Via: SIP/2.0/UDP IP;branch=z9hG4bKcydzigwkX Via: SIP/2.0/UDP IP:5061;received=127.0.0.1;branch=z9hG4bK587eb61e;rport=5061 From: "NUM" <sip:***@IP>;tag=as50b3af68 To: <sip:***@IP>;tag=ovqdnmak77x4xa54.i Contact: <sip:***@IP:5061> Call-ID: ***@IP CSeq: 102 ACK User-Agent: Server Max-Forwards: 70 Remote-Party-ID: "NUM" <sip:***@IP>;privacy=off;screen=no Content-Length: 0 .
May 10 12:23:43 kamailio /usr/sbin/kamailio[23198]: DEBUG: <core> [forward.c:603]: orig. len=597, new_len=685, proto=1
May 10 12:23:43 kamailio /usr/sbin/kamailio[23198]: DEBUG: <core> [usr_avp.c:644]: DEBUG:destroy_avp_list: destroying list 0xb2f15ca8
May 10 12:23:43 kamailio /usr/sbin/kamailio[23198]: DEBUG: <core> [usr_avp.c:644]: DEBUG:destroy_avp_list: destroying list (nil)
May 10 12:23:43 kamailio /usr/sbin/kamailio[23198]: DEBUG: <core> [usr_avp.c:644]: DEBUG:destroy_avp_list: destroying list (nil)
May 10 12:23:43 kamailio /usr/sbin/kamailio[23198]: DEBUG: <core> [usr_avp.c:644]: DEBUG:destroy_avp_list: destroying list (nil)
May 10 12:23:43 kamailio /usr/sbin/kamailio[23198]: DEBUG: <core> [usr_avp.c:644]: DEBUG:destroy_avp_list: destroying list (nil)
May 10 12:23:43 kamailio /usr/sbin/kamailio[23198]: DEBUG: <core> [usr_avp.c:644]: DEBUG:destroy_avp_list: destroying list (nil)
May 10 12:23:43 kamailio /usr/sbin/kamailio[23198]: DEBUG: <core> [xavp.c:365]: destroying xavp list (nil)
May 10 12:23:43 kamailio /usr/sbin/kamailio[23198]: DEBUG: <core> [receive.c:291]: receive_msg: cleaning up
{code}

Maybe this not a bug, but why in kamailio 1.5.2 it work? :-)

More information can be found at the following URL:
http://sip-router.org/tracker/index.php?do=details&task_id=229

You are receiving this message because you have requested it from the Flyspray bugtracking system. If you did not expect this message or don't want to receive mails in future, you can change your notification settings at the URL shown above.

sip-router

2012-05-15 20:15:55 UTC

Permalink

THIS IS AN AUTOMATED MESSAGE, DO NOT REPLY.

The following task has a new comment added:

FS#229 - ACK not in transaction when t_relay or t_check_trans
User who did this - Daniel-Constantin Mierla (miconda)

----------
Can you attach here the sip trace with the INVITE, 200OK reply and the ACK?
----------

More information can be found at the following URL:
http://sip-router.org/tracker/index.php?do=details&task_id=229#comment640

You are receiving this message because you have requested it from the Flyspray bugtracking system. If you did not expect this message or don't want to receive mails in future, you can change your notification settings at the URL shown above.

sip-router

2012-05-16 09:27:25 UTC

Permalink

THIS IS AN AUTOMATED MESSAGE, DO NOT REPLY.

The following task has a new comment added:

FS#229 - ACK not in transaction when t_relay or t_check_trans
User who did this - Pawel Sternal (Sternik)

----------
I made a simple call A --> SER --> B (sip trace included). Debug:

May 16 10:21:41 kamailio /usr/sbin/kamailio[24846]: DEBUG: tm [t_lookup.c:1379]: DEBUG: t_newtran: msg id=38585 , global msg id=38584 , T on entrance=0xffffffff
May 16 10:21:41 kamailio /usr/sbin/kamailio[24846]: DEBUG: tm [t_lookup.c:527]: t_lookup_request: start searching: hash=13472, isACK=1
May 16 10:21:41 kamailio /usr/sbin/kamailio[24846]: DEBUG: tm [t_lookup.c:485]: DEBUG: RFC3261 transaction matching failed
May 16 10:21:41 kamailio /usr/sbin/kamailio[24846]: DEBUG: tm [t_lookup.c:709]: DEBUG: t_lookup_request: no transaction found
May 16 10:21:41 kamailio /usr/sbin/kamailio[24846]: DEBUG: tm [t_funcs.c:315]: SER: forwarding ACK statelessly

I'll try add some DBG logs to t_lookup.c, to determine where in the code matching failed.
----------

One or more files have been attached.

More information can be found at the following URL:
http://sip-router.org/tracker/index.php?do=details&task_id=229#comment643

You are receiving this message because you have requested it from the Flyspray bugtracking system. If you did not expect this message or don't want to receive mails in future, you can change your notification settings at the URL shown above.

sip-router

2012-05-16 12:45:10 UTC

Permalink

THIS IS AN AUTOMATED MESSAGE, DO NOT REPLY.

The following task has a new comment added:

FS#229 - ACK not in transaction when t_relay or t_check_trans
User who did this - Pawel Sternal (Sternik)

----------
Ok. We found that ACK not enter in this statement:

if (unlikely(has_tran_tmcbs(p_cell, TMCB_E2EACK_IN|TMCB_E2EACK_RETR_IN) || (p_cell->relayed_reply_branch==-2))) {

In my scenario "p_cell->relayed_reply_branch" is equal to 0. But I think is not the problem. Maybe is something wrong in this ACK packet whene function "has_tran_tmcbs(p_cell, TMCB_E2EACK_IN|TMCB_E2EACK_RETR_IN)" was called... don't know.
----------

More information can be found at the following URL:
http://sip-router.org/tracker/index.php?do=details&task_id=229#comment644

You are receiving this message because you have requested it from the Flyspray bugtracking system. If you did not expect this message or don't want to receive mails in future, you can change your notification settings at the URL shown above.

sip-router

2012-05-17 11:42:59 UTC

Permalink

THIS IS AN AUTOMATED MESSAGE, DO NOT REPLY.

The following task has a new comment added:

FS#229 - ACK not in transaction when t_relay or t_check_trans
User who did this - Daniel-Constantin Mierla (miconda)

----------
The ACK seems ok, can you get any debug info from the device not accepting the ACK?

ACK comes to kamailio and it is routed to callee, based on source IP and port of 200ok, because the callee is behind nat.

The code you are referring to I guess is the one related to matching ACK to an existing INVITE transaction, used for accounting purposes. But the ACK itself for a 200OK is a separate transaction, being a request within dialog and has to be routed base on Route header.

In the initial description of this item you say that Record-Route is added to ACK, I could not spot that in the trace you attached. Even it would be, that is a matter of config, transaction management/matching has nothing to do with Record-Route headers.

If you want to get ACK matched to INVITE transaction, set acc module to record the ACK events and try again to see if there is any difference.

Can you post the trace taken when using 1.5.x? I would like to see if there is any difference.
----------

More information can be found at the following URL:
http://sip-router.org/tracker/index.php?do=details&task_id=229#comment646

You are receiving this message because you have requested it from the Flyspray bugtracking system. If you did not expect this message or don't want to receive mails in future, you can change your notification settings at the URL shown above.

sip-router

2012-05-17 12:56:05 UTC

Permalink

THIS IS AN AUTOMATED MESSAGE, DO NOT REPLY.

The following task has a new comment added:

FS#229 - ACK not in transaction when t_relay or t_check_trans
User who did this - Pawel Sternal (Sternik)

----------
Yes, when I set ack_report to 1, ACK is correctly matched. My fault is not to check in documentation.

About "Record-Route", again my fault, because I run "record_route()" if(!$tt). When we migrate kamailio 1.5 to 3.x we notice that !$tt must be change to $tt==$null. And this time I forgot about it, with another migration, and dump on not matched ACK. Again - my fault.

I tried to check another scenario A-> SER -> ASTERISK | ASTERISK -> SER -> PSTN simulation. We don't use here acc. In kamailio 1.5.2 (test_1.5.cap) I have in:

1 ACK:
May 17 14:48:20 gx00 /usr/sbin/kamailio[32283]: DBG:tm:t_newtran: transaction on entrance=0xffffffff
May 17 14:48:20 gx00 /usr/sbin/kamailio[32282]: DBG:core:parse_headers: flags=80
May 17 14:48:20 gx00 /usr/sbin/kamailio[32283]: DBG:core:parse_headers: flags=ffffffffffffffff
May 17 14:48:20 gx00 /usr/sbin/kamailio[32283]: DBG:core:parse_headers: flags=78
May 17 14:48:20 gx00 /usr/sbin/kamailio[32283]: DBG:tm:t_lookup_request: start searching: hash=5186, isACK=1
May 17 14:48:20 gx00 /usr/sbin/kamailio[32282]: DBG:core:print_rr_body: current rr is <sip:10.0.6.20:5060;ftag=4c30f07ddedec1e3o3;lr>
May 17 14:48:20 gx00 /usr/sbin/kamailio[32282]: DBG:core:print_rr_body: current rr is <sip:10.0.6.40;lr>
May 17 14:48:20 gx00 /usr/sbin/kamailio[32283]: DBG:core:parse_headers: flags=38
May 17 14:48:20 gx00 /usr/sbin/kamailio[32282]: DBG:core:print_rr_body: skipping 2 route records
May 17 14:48:20 gx00 /usr/sbin/kamailio[32283]: DBG:tm:t_lookup_request: RFC3261 ACK matched
May 17 14:48:20 gx00 /usr/sbin/kamailio[32282]: DBG:core:print_rr_body: out rr []
May 17 14:48:20 gx00 /usr/sbin/kamailio[32283]: DBG:tm:t_lookup_request: REF_UNSAFE: after is 1
May 17 14:48:20 gx00 /usr/sbin/kamailio[32282]: DBG:core:print_rr_body: we have 2 records
May 17 14:48:20 gx00 /usr/sbin/kamailio[32283]: DBG:tm:t_lookup_request: e2e proxy ACK found
May 17 14:48:20 gx00 /usr/sbin/kamailio[32282]: DBG:dialog:populate_leg_info: route_set , contact sip:NodesProdIn1-***@public.gmane.org:5062, cseq 102 and bind_addr udp:10.0.6.20:5060
May 17 14:48:20 gx00 /usr/sbin/kamailio[32283]: DBG:tm:t_newtran: building branch for end2end ACK
May 17 14:48:20 gx00 /usr/sbin/kamailio[32283]: DBG:tm:t_relay_to: forwarding ACK

2 ACK:
May 17 14:48:20 gx00 /usr/sbin/kamailio[32283]: DBG:tm:t_lookup_request: start searching: hash=5186, isACK=1
May 17 14:48:20 gx00 /usr/sbin/kamailio[32282]: DBG:core:print_rr_body: current rr is <sip:10.0.6.20:5060;ftag=4c30f07ddedec1e3o3;lr>
May 17 14:48:20 gx00 /usr/sbin/kamailio[32282]: DBG:core:print_rr_body: current rr is <sip:10.0.6.40;lr>
May 17 14:48:20 gx00 /usr/sbin/kamailio[32283]: DBG:core:parse_headers: flags=38
May 17 14:48:20 gx00 /usr/sbin/kamailio[32282]: DBG:core:print_rr_body: skipping 2 route records
May 17 14:48:20 gx00 /usr/sbin/kamailio[32283]: DBG:tm:t_lookup_request: RFC3261 ACK matched
May 17 14:48:20 gx00 /usr/sbin/kamailio[32282]: DBG:core:print_rr_body: out rr []
May 17 14:48:20 gx00 /usr/sbin/kamailio[32283]: DBG:tm:t_lookup_request: REF_UNSAFE: after is 1
May 17 14:48:20 gx00 /usr/sbin/kamailio[32282]: DBG:core:print_rr_body: we have 2 records
May 17 14:48:20 gx00 /usr/sbin/kamailio[32283]: DBG:tm:t_lookup_request: e2e proxy ACK found
May 17 14:48:20 gx00 /usr/sbin/kamailio[32282]: DBG:dialog:populate_leg_info: route_set , contact sip:NodesProdIn1-***@public.gmane.org:5062, cseq 102 and bind_addr udp:10.0.6.20:5060
May 17 14:48:20 gx00 /usr/sbin/kamailio[32283]: DBG:tm:t_newtran: building branch for end2end ACK
May 17 14:48:20 gx00 /usr/sbin/kamailio[32283]: DBG:tm:t_relay_to: forwarding ACK

This same scenario in kamailio 3.2.2 (test_3.2.cap):

1 ACK:
May 17 13:54:26 gx00 /usr/sbin/kamailio[13546]: DEBUG: tm [t_lookup.c:1379]: DEBUG: t_newtran: msg id=16134 , global msg id=16133 , T on entrance=0xffffffff
May 17 13:54:26 gx00 /usr/sbin/kamailio[13546]: DEBUG: tm [t_lookup.c:527]: t_lookup_request: start searching: hash=37195, isACK=1
May 17 13:54:26 gx00 /usr/sbin/kamailio[13546]: DEBUG: tm [t_lookup.c:485]: DEBUG: RFC3261 transaction matching failed
May 17 13:54:26 gx00 /usr/sbin/kamailio[13546]: DEBUG: tm [t_lookup.c:709]: DEBUG: t_lookup_request: no transaction found
May 17 13:54:26 gx00 /usr/sbin/kamailio[13546]: DEBUG: tm [t_funcs.c:315]: SER: forwarding ACK statelessly

2 ACK:
May 17 13:54:26 gx00 /usr/sbin/kamailio[13546]: DEBUG: tm [t_lookup.c:1379]: DEBUG: t_newtran: msg id=16134 , global msg id=16133 , T on entrance=0xffffffff
May 17 13:54:26 gx00 /usr/sbin/kamailio[13546]: DEBUG: tm [t_lookup.c:527]: t_lookup_request: start searching: hash=37195, isACK=1
May 17 13:54:26 gx00 /usr/sbin/kamailio[13546]: DEBUG: tm [t_lookup.c:485]: DEBUG: RFC3261 transaction matching failed
May 17 13:54:26 gx00 /usr/sbin/kamailio[13546]: DEBUG: tm [t_lookup.c:709]: DEBUG: t_lookup_request: no transaction found
May 17 13:54:26 gx00 /usr/sbin/kamailio[13546]: DEBUG: tm [t_funcs.c:315]: SER: forwarding ACK statelessly

:-)
----------

One or more files have been attached.

More information can be found at the following URL:
http://sip-router.org/tracker/index.php?do=details&task_id=229#comment647

You are receiving this message because you have requested it from the Flyspray bugtracking system. If you did not expect this message or don't want to receive mails in future, you can change your notification settings at the URL shown above.

sip-router

2012-05-31 13:18:43 UTC

Permalink

THIS IS AN AUTOMATED MESSAGE, DO NOT REPLY.

The following task has a new comment added:

FS#229 - ACK not in transaction when t_relay or t_check_trans
User who did this - Daniel-Constantin Mierla (miconda)

----------
I checked the trace for 3.2 and all is fine with routing ACK. You have a b2bua, the ack from caller goes to proxy and then to b2bua (no retransmissions), also the ack from b2bua goes to callee via proxy without problems. The call is ended by Linksys/SPA941-5.1.8 after approx. 2 seconds from the ACK, meaning either was a user interaction or some codecs issue.

if there would have been an issue with the ack, the 200OK would have been retransmitted for about 30sec.

Have you spotted anything wrong in your case, what is not working for your case that you believe there is a problem?
----------

More information can be found at the following URL:
http://sip-router.org/tracker/index.php?do=details&task_id=229#comment655

You are receiving this message because you have requested it from the Flyspray bugtracking system. If you did not expect this message or don't want to receive mails in future, you can change your notification settings at the URL shown above.

sip-router

2012-06-18 05:37:24 UTC

Permalink

THIS IS AN AUTOMATED MESSAGE, DO NOT REPLY.

The following task has a new comment added:

FS#229 - ACK not in transaction when t_relay or t_check_trans
User who did this - Vlad (Vlad1983)

----------
Hi.
After a T.38 reINVITE misses the verification t_check_trans in section WITHINDLG standard configuration file.
----------

One or more files have been attached.

More information can be found at the following URL:
http://sip-router.org/tracker/index.php?do=details&task_id=229#comment692

You are receiving this message because you have requested it from the Flyspray bugtracking system. If you did not expect this message or don't want to receive mails in future, you can change your notification settings at the URL shown above.

sip-router

2013-07-11 17:10:05 UTC

Permalink

THIS IS AN AUTOMATED MESSAGE, DO NOT REPLY.

The following task has a new comment added:

FS#229 - ACK not in transaction when t_relay or t_check_trans
User who did this - Daniel-Constantin Mierla (miconda)

----------
The problem is that the ACK for re-INVITE does not come with a Route header. Try to use record_route() even for INVITEs that have To-tag (within dialog routing block) -- this shouldn't be needed based on rfc, but maybe some UAs don't follow that.
----------

More information can be found at the following URL:
https://sip-router.org/tracker/index.php?do=details&task_id=229#comment993

You are receiving this message because you have requested it from the Flyspray bugtracking system. If you did not expect this message or don't want to receive mails in future, you can change your notification settings at the URL shown above.

sip-router

2013-07-11 17:10:14 UTC

Permalink

THIS IS AN AUTOMATED MESSAGE, DO NOT REPLY.

The following task is now closed:

FS#229 - ACK not in transaction when t_relay or t_check_trans
User who did this - Daniel-Constantin Mierla (miconda)

Reason for closing: Not a bug
More information can be found at the following URL:
https://sip-router.org/tracker/index.php?do=details&task_id=229

You are receiving this message because you have requested it from the Flyspray bugtracking system. If you did not expect this message or don't want to receive mails in future, you can change your notification settings at the URL shown above.