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

[George Diamantopoulos]

A clarification:

The two exchanges-examples I included in the original message are not from
the same peer. The issue is reproducible every time with the problematic
peer (first example). I only included another exchange from a different
peer (so it should read peer2 where I censored IP addressed) for comparison
and to prove a point.

On 23 August 2017 at 17:13, George Diamantopoulos <georgediam at gmail.com>
wrote:

> 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/f1430977/attachment.html>