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@172.18.101.48:5060;ngcpct=7369703a3132372e302e302e313a35303830 SIP/2.0 Via: SIP/2.0/WS df7jal23ls0d.invalid;branch=z9hG4bKPLN9elJsPlfeyLsMqN2J;rport From: "4252143385"sip:4252143385@172.18.101.48;tag=RtycJXR6JIUFzAezAbRX To: sip:2067077495@172.18.101.48;tag=1F9894DE-52FE982E000437E0-321A4700 Contact: "4252143385"sip:4252143385@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 *