[SR-Users] Kamailio fails to process ACK to 487 from Cisco-SIPGateway/IOS-12.x?

[George Diamantopoulos]

Hello all,

I'm having a weird issue with Kamailio failing to properly process an ACK
received to a 487 it sent, resulting in retransmissions of the 487. I
assume it's because it can't match the ACK to the transaction, but I could
be wrong.

I'm using a modified version of the default configuration, so ACKs should
be handled correctly. I haven't editted the WITHINDLG route in any way that
would affect this (or at least I think).

In addition, ACKs to 487 from other UAs are processed correctly, and these
transactions are handled by the same routes in kamailio configuration as
the problematic one, so I'm inclined to believe it's UA-specific?

Here's an example transaction of the failed kind (results in kamailio
retransmitting the 487):

myself:5060 -> peer:5060
-------------------------
SIP/2.0 487 Request Terminated
Via: SIP/2.0/UDP peer:5060
From: <sip:user at peer>;tag=116B5368-24D8
To: <sip:tel at myself>;tag=as655f6372
Call-ID: 84DC69F2-873811E7-8A639B5A-3D9194E8 at peer
CSeq: 101 INVITE
Server: modCOM v2 SIP Server
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO,
PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0

peer:49590 -> myself:5060
-------------------------
ACK sip:tel at myself:5060 SIP/2.0
Via: SIP/2.0/UDP  peer:5060
From: <sip:user at peer>;tag=116B5368-24D8
To: <sip:tel at myself>;tag=as655f6372
Date: Wed, 23 Aug 2017 12:50:47 GMT
Call-ID: 84DC69F2-873811E7-8A639B5A-3D9194E8 at peer
Max-Forwards: 10
Content-Length: 0
CSeq: 101 ACK

And here's another similar transaction which is successful (no
retransmissions):

myself:5060 -> peer:5060
------------------------
SIP/2.0 487 Request Terminated
Via: SIP/2.0/UDP peer:5060;branch=z9hG4bKjbmvq4009gthskk0a6s1.1
From: <sip:user at anonymous.invalid;user=phone>;tag=599D7495-9ACE9E3-0A324A05
To: <sip:tel at anonymous.invalid:5060;user=phone>;tag=as65375e5d
Call-ID: 599D7495-007A5832 at fath3pcu238
CSeq: 1 INVITE
Server: modCOM v2 SIP Server
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO,
PUBLISH, MESSAGE
Supported: replaces, timer
Content-Length: 0


peer:5060 -> myself:5060
------------------------
ACK sip:tel at myself:5060;user=phone SIP/2.0
Via: SIP/2.0/UDP peer:5060;branch=z9hG4bKjbmvq4009gthskk0a6s1.1
From: <sip:user at anonymous.invalid;user=phone>;tag=599D7495-9ACE9E3-0A324A05
To: <sip:tel at anonymous.invalid:5060;user=phone>;tag=as65375e5d

Call-ID: 599D7495-007A5832 at fath3pcu238
Max-Forwards: 69
Content-Length: 0
CSeq: 1 ACK

I can't pinpoint anything wrong with the first exchange, other than the
fact that for some reason, the "less than" (<) sign in the from and to URIs
is escaped as &lt in homer's GUI (which also breaks CSS rendering in
Firefox, I had to clear this code out). However, these escaping characters
are not visible with sngrep when capturing traffic normally, and neither
when doing a select in homer's database directly, so I guess it's a
rendering bug in homer-ui and can be ignored (unless someone has reason to
believe otherwise).

Now the relevant portion of the debug log is:

Aug 23 16:47:12 modcom-sbc-1 kamailio[9750]: {1 101 ACK
64AA4E6C-874011E7-9A729B5A-3D9194E8 at peer}  7(9760) exec: ***
cfgtrace:request_route=[WITHINDLG] c=[/etc/kamailio/kamailio.cfg] l=223
a=24 n=t_check_trans
Aug 23 16:47:12 modcom-sbc-1 kamailio[9750]: {1 101 ACK
64AA4E6C-874011E7-9A729B5A-3D9194E8 at peer}  7(9760) DEBUG: tm
[t_lookup.c:1001]: t_check_msg(): msg id=104 global id=103 T start=(nil)
Aug 23 16:47:12 modcom-sbc-1 kamailio[9750]: {1 101 ACK
64AA4E6C-874011E7-9A729B5A-3D9194E8 at peer}  7(9760) DEBUG: tm
[t_lookup.c:459]: t_lookup_request(): start searching: hash=54992, isACK=1
Aug 23 16:47:12 modcom-sbc-1 kamailio[9750]: {1 101 ACK
64AA4E6C-874011E7-9A729B5A-3D9194E8 at peer}  7(9760) DEBUG: tm
[t_lookup.c:494]: t_lookup_request(): proceeding to pre-RFC3261 transaction
matching
Aug 23 16:47:12 modcom-sbc-1 kamailio[9750]: {1 101 ACK
64AA4E6C-874011E7-9A729B5A-3D9194E8 at peer}  7(9760) DEBUG: tm
[t_lookup.c:641]: t_lookup_request(): no transaction found
Aug 23 16:47:12 modcom-sbc-1 kamailio[9750]: {1 101 ACK
64AA4E6C-874011E7-9A729B5A-3D9194E8 at peer}  7(9760) DEBUG: tm
[t_lookup.c:1070]: t_check_msg(): msg id=104 global id=104 T end=(nil)
Aug 23 16:47:12 modcom-sbc-1 kamailio[9750]: {1 101 ACK
64AA4E6C-874011E7-9A729B5A-3D9194E8 at peer}  7(9760) exec: ***
cfgtrace:request_route=[WITHINDLG] c=[/etc/kamailio/kamailio.cfg] l=231 a=2
n=exit

It explicitly states that no transaction is found, after initiating
pre-RFC3261 (why?) transaction matching. However, even pre-3261 matching
should work, as the from and to headers as well as call-id in request and
repy are the same.

Any input would be greatly appreciated, thanks!
George
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.kamailio.org/pipermail/sr-users/attachments/20170823/5438656b/attachment.html>