200 OK & ACK & topoh issues

[sigxcpu76]

Description

A certain inbound provider does not return ACK R-URI as an exact copy of contact. A parameter is appended to it, like below:

200 OK Contact:

Contact: <sip:35.197.205.XXX:5060;line=sr-N6IAzJd4WxFLWxVlz.jwWB0yM.y7MlV7zGZlMlvuMx3A>

ACK R-URI:

ACK sip:35.197.205.XXX:5060;line=sr-N6IAzJd4WxFLWxVlz.jwWB0yM.y7MlV7zGZlMlvuMx3A;user=phone SIP/2.0

As you can see, the user=phone is appended along with line= put by topoh.

Troubleshooting

Reproduction

I am not sure how this can be reproductible. I've put the URI with and without user=phone part in a small C app that calls kamailio's parse_params function and both resolved to one and two params, as expected, so the problem must come from parse_uri.
See the debug logs below that show the difference between a "good" ACK and a "bad" ACK. topoh doesn't get its line= param, so it doesn't perform the Contact header rewrite. The ACK does not match a dialog/transaction and it is forwarded to itself (from internal IP to external IP, this being a kamailio behind NAT, but that's not the problem).

Debugging Data

Log Messages

This is the "good" call, with ACK R-URI identical to Contact header. See the "+decoded" line:

13(40) DEBUG: topoh [topoh_mod.c:249]: th_prepare_msg(): no second via in this message
13(40) DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=as496aacd0
13(40) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29
13(40) DEBUG: topoh [th_msg.c:1165]: th_route_direction(): ftag match
13(40) DEBUG: topoh [th_msg.c:763]: th_unmask_ruri(): +decoded: 34: [sip:+441274957XXX@10.32.2.133:5060]
13(40) DEBUG: topoh [topoh_mod.c:358]: th_msg_received(): adding cookie: dc
13(40) DEBUG: topoh [th_msg.c:997]: th_add_hdr_cookie(): added cookie header [TH: dch

This is the "bad" call, with ACK R-URI having a user=phone param appended to original Contact contents:

10(37) DEBUG: topoh [topoh_mod.c:249]: th_prepare_msg(): no second via in this message
10(37) DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=3735986184-753647
10(37) DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29
10(37) DEBUG: topoh [th_msg.c:1165]: th_route_direction(): ftag match
10(37) DEBUG: <core> [core/parser/parse_param.c:580]: parse_params2(): empty uri params, skipping
10(37) DEBUG: topoh [topoh_mod.c:358]: th_msg_received(): adding cookie: dc
10(37) DEBUG: topoh [th_msg.c:997]: th_add_hdr_cookie(): added cookie header [TH: dch

SIP Traffic

U 2018/05/21 10:22:53.206320 35.197.205.XXX:5060 -> 88.215.58.YYY:5060
SIP/2.0 200 OK.
Via: SIP/2.0/UDP 88.215.58.YYY:5060;rport=5060;branch=z9hG4bK469d20c71c138e366475cd537dc0c68b.
Record-Route: <sip:35.197.205.XXX;lr;ftag=3735908572-610467;vsf=AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA7dXNlcj1waG9uZQ--;vst=AAAAAAAAAAAAAAAAAAAAAAAACQgAAQMbFhsLHTE1OjUwNjA7dXNlcj1waG9uZQ--;did=f17.b7f>.
From: <sip:+16098378XXX@88.215.58.YYY;user=phone>;tag=3735908572-610467.
To: <sip:+441242395XXX@88.215.58.YYY:5060;user=phone>;tag=as3147fc45.
Call-ID: 5577511-3735908572-610459@MSX163.XXX.com.
CSeq: 1 INVITE.
Server: Asterisk PBX 1.8.28-cert5.
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH, MESSAGE.
Supported: replaces.
Contact: <sip:35.197.205.XXX:5060;line=sr-N6IAzJd4WxFLWxVlz.jwWB0yM.y7MlV7zGZlMlvuMx3A>.
Content-Type: application/sdp.
Content-Length: 259.
.
v=0.
o=root 1611167628 1611167628 IN IP4 35.197.206.251.
s=Asterisk PBX 1.8.28-cert5.
c=IN IP4 35.197.206.251.
t=0 0.
m=audio 10948 RTP/AVP 8 101.
a=rtpmap:8 PCMA/8000.
a=rtpmap:101 telephone-event/8000.
a=fmtp:101 0-16.
a=ptime:20.
a=sendrecv.
a=rtcp:10949.


U 2018/05/21 10:22:53.206827 88.215.58.YYY:5060 -> 35.197.205.XXX:5060
ACK sip:35.197.205.XXX:5060;line=sr-N6IAzJd4WxFLWxVlz.jwWB0yM.y7MlV7zGZlMlvuMx3A;user=phone SIP/2.0.
Max-Forwards: 68.
Route: <sip:35.197.205.XXX;lr;ftag=3735908572-610467;vsf=AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA7dXNlcj1waG9uZQ--;vst=AAAAAAAAAAAAAAAAAAAAAAAACQgAAQMbFhsLHTE1OjUwNjA7dXNlcj1waG9uZQ--;did=f17.b7f>.
To: <sip:+441242395XXX@88.215.58.YYY:5060;user=phone>;tag=as3147fc45.
From: <sip:+16098378XXX@88.215.58.YYY;user=phone>;tag=3735908572-610467.
Call-ID: 5577511-3735908572-610459@MSX163.XXX.com.
CSeq: 1 ACK.
Allow: PUBLISH,MESSAGE,UPDATE,SUBSCRIBE,REFER,INFO,NOTIFY,OPTIONS,BYE,INVITE,ACK,CANCEL.
Via: SIP/2.0/UDP 88.215.58.YYY:5060;branch=z9hG4bK6c862e8111736dc6d7d22479393d1f2d.
Contact: <sip:+16098378YYY@88.215.58.YYY:5060>.
Content-Length: 0.

Possible Solutions

Changed the provider to avoid downtime, but the empty uri params, skipping error from parse_params2 is strange, considering that we do not have a single param but 2.

Additional Information

• Kamailio Version - output of kamailio -v

version: kamailio 5.0.4 (x86_64/linux)
flags: STATS: Off, USE_TCP, USE_TLS, USE_SCTP, TLS_HOOKS, DISABLE_NAGLE, USE_MCAST, DNS_IP_HACK, SHM_MEM, SHM_MMAP, PKG_MALLOC, Q_MALLOC, F_MALLOC, TLSF_MALLOC, DBG_SR_MEMORY, USE_FUTEX, FAST_LOCK-ADAPTIVE_WAIT, USE_DNS_CACHE, USE_DNS_FAILOVER, USE_NAPTR, USE_DST_BLACKLIST, HAVE_RESOLV_RES
ADAPTIVE_WAIT_LOOPS=1024, MAX_RECV_BUFFER_SIZE 262144, MAX_LISTEN 16, MAX_URI_SIZE 1024, BUF_SIZE 65535, DEFAULT PKG_SIZE 8MB
poll method support: poll, epoll_lt, epoll_et, sigio_rt, select.
id: unknown
compiled with gcc 5.4.0

• Operating System:

Linux gke-lon-1-sbc-in-082a7447-9rll 4.13.0-1011-gcp #15-Ubuntu SMP Mon Feb 12 16:29:04 UTC 2018 x86_64 x86_64 x86_64 GNU/Linux

[miconda]

Can you try with the patch from commit 5a0086f and then grab again the debug messages printed for the bad handling ACK? I want to see if the r-uri is the same as in the ngrep trace, not altered somehow before.

[sigxcpu76]

Thank you.

This is one of the problems we have. We are running in GKE with a container built using .deb packages, this being the reason we've "tested" with a small C app.
Rebuilding the image from sources instead of .deb will take a while and we don't have that provider anymore.

Is there a way to quickly test parse_uri using an external app that feeds various URI strings? Local, no SIP & network involved.

If not, we may need to build a custom SIP message sender and feed just the ACK to kamailio with one and two parameters, to check topoh & parser messages. If we reproduce, then we can test with the patch you have provided to get more insight.

[miconda]

Probably you can setup quickly a testbed to reproduce. For example, you can make a test unit using docker container and out recent testing framework:

• https://github.com/kamailio/kamailio-tests

Then you can use sipsak or the internal misc/tools/protoshoot to send the packet.

[miconda]

Any update with new data on this one?

[sigxcpu76]

Hi, still didn't have time to check how to reproduce this.
Meanwhile, I've tried to move to mangler (to rewrite Contact) which upset other providers and finally wrote a simple base64 encoder for Contact header that fits the job (looks "normal" and does not have private IPs in it).
This seems to make all providers happy until now.

[miconda]

Should be fixed by the commit reference above (to be backported).

The addition of user=phone turns the uri type in tel mapped over sip and params were stored in different field.