[SR-Users] Error with ACK from SIPML5

[Andrew Pogrebennyk]

Sorry for reviving this old thread. I think I've come across the same
issue as Jayesh and it is triggered by the Route
inserted by sipml5 into in-dialog requests like ACK - Route:
<sip:172.18.101.48:5060;lr;sipml5-outbound;transport=udp>

Jayesh had two Route headers that belong to this kamailio instance and I
also have two of them:
Route:
<sip:172.18.101.48;transport=ws;r2=on;lr=on;ftag=RtycJXR6JIUFzAezAbRX;nat=yes;ngcplb=yes;socket=ws:172.18.101.48:5060>
Route:
<sip:127.0.0.1;r2=on;lr=on;ftag=RtycJXR6JIUFzAezAbRX;nat=yes;ngcplb=yes;socket=ws:172.18.101.48:5060>

Although RFC3261 doesn't seem to forbit that explicitly, but when sipml5
adds a pre-existing Route to *in-dialog* request, it creates a set where
not all URIs are unique. What happens in kamailio is that when
loose_route encounters the topmost Route from sipml5 client, it does not
remove other routes before sending the request, e.g. I see no further
processing after "Next URI is a loose router". I can share the kamailio
debug log, but the most important part is:

> Feb 14 23:26:54 spce lb[3773]: DEBUG: websocket [ws_frame.c:589]: ws_frame_receive(): Rx SIP message:
> ACK sip:ngcp-lb at 172.18.101.48:5060;ngcpct=7369703a3132372e302e302e313a35303830 SIP/2.0
> Via: SIP/2.0/WS df7jal23ls0d.invalid;branch=z9hG4bKPLN9elJsPlfeyLsMqN2J;rport
> From: "4252143385"<sip:4252143385 at 172.18.101.48>;tag=RtycJXR6JIUFzAezAbRX
> To: <sip:2067077495 at 172.18.101.48>;tag=1F9894DE-52FE982E000437E0-321A4700
> Contact: "4252143385"<sip:4252143385 at df7jal23ls0d.invalid;rtcweb-breaker=yes;click2call=no;transport=ws>;+g.oma.sip-im;+sip.ice;language="en,fr"
> Call-ID: 1bff80ac-1e47-ab0f-3ea4-6a7b8637030b
> CSeq: 43084 ACK
> Content-Length: 0
> Route: <sip:172.18.101.48:5060;lr;sipml5-outbound;transport=udp>
> Max-Forwards: 70
> Proxy-Authorization: …
> Route: <sip:172.18.101.48;transport=ws;r2=on;lr=on;ftag=RtycJXR6JIUFzAezAbRX;nat=yes;ngcplb=yes;socket=ws:172.18.101.48:5060>
> Route: <sip:127.0.0.1;r2=on;lr=on;ftag=RtycJXR6JIUFzAezAbRX;nat=yes;ngcplb=yes;socket=ws:172.18.101.48:5060>
> Route: <sip:127.0.0.1:5062;lr=on;ftag=RtycJXR6JIUFzAezAbRX;did=117.fcb;mpd=ii;ice_caller=replace;savp_caller=force_srtp;avpf_caller=force_avpf;ice_callee=strip;savp_callee=force_rtp;avpf_callee=force_avp;rtpprx=yes;vsf=ampNeU9nS3R6XXJyQ2QgJVJTaiZjfFJ4S35Wf0E->
> User-Agent: IM-client/OMA1.0 sipML5-v1.2014.01.27
> Organization: Doubango Telecom
> [...]
> Feb 14 23:26:54 spce lb[3773]: DEBUG: rr [loose.c:778]: after_loose(): Topmost route URI: 'sip:172.18.101.48:5060;lr;sipml5-outbound;transport=udp' is me
> Feb 14 23:26:54 spce lb[3773]: DEBUG: rr [loose.c:862]: after_loose(): URI to be processed: 'sip:172.18.101.48;transport=ws;r2=on;lr=on;ftag=RtycJXR6JIUFzAezAbRX;nat=yes;ngcplb=yes;socket=ws:172.18.101.48:5060'
> Feb 14 23:26:54 spce lb[3773]: DEBUG: rr [loose.c:871]: after_loose(): Next URI is a loose router
> Feb 14 23:26:54 spce lb[3773]: DEBUG: rr [rr_cb.c:97]: run_rr_callbacks(): callback id 0 entered with <lr;sipml5-outbound;transport=udp>
> Feb 14 23:26:54 spce lb[3773]: DEBUG: siputils [checks.c:106]: has_totag(): totag found
> Feb 14 23:26:54 spce lb[3773]: DEBUG: rr [loose.c:974]: check_route_param(): params are <;lr;sipml5-outbound;transport=udp>
> Feb 14 23:26:54 spce lb[3773]: INFO: <script>: Reset loose-routing, du='sip:172.18.101.48;transport=ws;r2=on;lr=on;ftag=RtycJXR6JIUFzAezAbRX;nat=yes;ngcplb=yes;socket=ws:172.18.101.48:5060' - R=sip:127.0.0.1:5080 ID=1bff80ac-1e47-ab0f-3ea4-6a7b8637030b

I see several people came to this mailing list with this issue, but I'm
unsure about the outcome. Is this acceptable for an UAC to add a route
to in-dialog ACK, which was not in the route set received from the UAS
or proxy? Does it intend that the request should spiral? Did anyone take
it to the sipml5.org guys? Is loose_route() behavior 100% valid?

Thanks in advance.
Andrew

P.S. the log file from Jayesh is quoted below:

On 24/06/13 17:11, Daniel-Constantin Mierla wrote:
> Can you get the ngrep on the server from the initial invite to the ack.
> It seems that record route is not properly mirrored, so one client might
> mess the route path.
> 
> Cheers,
> Daniel
> 
> On 6/23/13 8:58 PM, Jayesh Nambiar wrote:
>> I did do debug=3 and saw the logs but couldn't figure out much. Here
>> is the log for the appropriate ACK received on websocket port. I've
>> highlighted a few lines I felt might be problematic:
>> [...]
>> Jun 23 18:45:46 v9 /usr/local/ghanti-ko/sbin/kamailio[22879]: DEBUG: rr
>> [loose.c:778]: after_loose(): Topmost route URI:
>> 'sip:126.128.68.9:5060;lr;sipml5-outbound;transport=udp' is me
>> Jun 23 18:45:46 v9 /usr/local/ghanti-ko/sbin/kamailio[22879]: DEBUG: rr
>> [loose.c:862]: after_loose(): URI to be processed:
>> 'sip:126.128.68.9:8080;transport=ws;r2=on;lr=on;ftag=7EKISKAakFG2QZ2JvpDO;nat=yes'
>> Jun 23 18:45:46 v9 /usr/local/ghanti-ko/sbin/kamailio[22879]: DEBUG: rr
>> [loose.c:871]: after_loose(): Next URI is a loose router
>> Jun 23 18:45:46 v9 /usr/local/ghanti-ko/sbin/kamailio[22879]: DEBUG:
>> siputils [checks.c:106]: has_totag(): totag found
>> Jun 23 18:45:46 v9 /usr/local/ghanti-ko/sbin/kamailio[22879]: DEBUG: rr
>> [loose.c:974]: check_route_param(): params are
>> <;lr;sipml5-outbound;transport=udp>
>> Jun 23 18:45:46 v9 /usr/local/ghanti-ko/sbin/kamailio[22879]: INFO:
>> <script>: Inside Natmanage ACK
>> Jun 23 18:45:46 v9 /usr/local/ghanti-ko/sbin/kamailio[22879]: DEBUG:
>> siputils [checks.c:106]: has_totag(): totag found
>> Jun 23 18:45:46 v9 /usr/local/ghanti-ko/sbin/kamailio[22879]: DEBUG: tm
>> [t_lookup.c:1395]: t_newtran(): DEBUG: t_newtran: msg id=8 , global msg
>> id=7 , T on entrance=(nil)
>> Jun 23 18:45:46 v9 /usr/local/ghanti-ko/sbin/kamailio[22879]: DEBUG: tm
>> [t_lookup.c:534]: t_lookup_request(): t_lookup_request: start searching:
>> hash=60000, isACK=1
>> un 23 18:45:46 v9 /usr/local/ghanti-ko/sbin/kamailio[22879]: DEBUG: tm
>> [t_lookup.c:492]: matching_3261(): *DEBUG: RFC3261 transaction matching
>> failed*
>> Jun 23 18:45:46 v9 /usr/local/ghanti-ko/sbin/kamailio[22879]: DEBUG: tm
>> [t_lookup.c:716]: t_lookup_request(): *DEBUG: t_lookup_request: no
>> transaction found*
>> Jun 23 18:45:46 v9 /usr/local/ghanti-ko/sbin/kamailio[22879]: DEBUG: tm
>> [t_funcs.c:311]: t_relay_to(): SER: forwarding ACK  statelessly
>> *Jun 23 18:45:46 v9 /usr/local/ghanti-ko/sbin/kamailio[22879]: WARNING:
>> <core> [msg_translator.c:2499]: via_builder(): TCP/TLS connection (id:
>> 0) for WebSocket could not be found*
>> *Jun 23 18:45:46 v9 /usr/local/ghanti-ko/sbin/kamailio[22879]: ERROR:
>> <core> [msg_translator.c:1725]: build_req_buf_from_sip_req(): could not
>> create Via header*
>> *Jun 23 18:45:46 v9 /usr/local/ghanti-ko/sbin/kamailio[22879]: ERROR:
>> <core> [forward.c:607]: forward_request(): ERROR: forward_request:
>> building failed*
>> *Jun 23 18:45:46 v9 /usr/local/ghanti-ko/sbin/kamailio[22879]: ERROR: sl
>> [sl_funcs.c:371]: sl_reply_error(): ERROR: sl_reply_error used: I'm
>> terribly sorry, server error occurred *