[sr-dev] [tracker] Task opened: our Record-Route is doubled on subsequent branches

Mon Sep 8 16:51:25 CEST 2014

THIS IS AN AUTOMATED MESSAGE, DO NOT REPLY.

A new Flyspray task has been opened.  Details are below. 

User who did this - Andrew Pogrebennyk (marduk) 

Attached to Project - sip-router
Summary - our Record-Route is doubled on subsequent branches
Task Type - Bug Report
Category - Module
Status - Unconfirmed
Assigned To - 
Operating System - All
Severity - Low
Priority - Normal
Reported Version - Development
Due in Version - Undecided
Due Date - Undecided
Details - I think I need some help understanding how the record_route() works.
I have two kamailio instances running here, one on 127.0.0.1:5060 and another one which is the proxy on 127.0.0.1:5062, UAS on 127.0.0.1:5080.

The proxy receives the INVITE which already has the RR of the lb instance on :5060 and sends it to the UAS, this is fine:

Sep  8 16:32:04 sp1 proxy[16687]: DEBUG: <core> [parser/parse_rr.c:380]: print_rr_body(): current rr is <sip:127.0.0.1;lr=on;ftag=17519SIPpTag001;ngcplb=yes;socket=udp:127.0.0.1:5060>
Sep  8 16:32:04 sp1 proxy[16687]: DEBUG: <core> [parser/parse_rr.c:405]: print_rr_body(): skipping 0 route records
Sep  8 16:32:04 sp1 proxy[16687]: DEBUG: <core> [parser/parse_rr.c:443]: print_rr_body(): out rr [<sip:127.0.0.1;lr=on;ftag=17519SIPpTag001;ngcplb=yes;socket=udp:127.0.0.1:5060>]
Sep  8 16:32:04 sp1 proxy[16687]: DEBUG: <core> [parser/parse_rr.c:444]: print_rr_body(): we have 1 records
...
####
U 2014/09/08 16:32:04.179882 127.0.0.1:5062 -> 127.0.0.1:5080
INVITE sip:testuser1003 at 127.1.0.1:50604 SIP/2.0.
Record-Route: <sip:127.0.0.1:5062;lr=on;ftag=17519SIPpTag001;did=5ad.f301;mpd=ii;ice_caller=strip;ice_callee=strip;aset=50;rtpprx=yes;vsf=NHBnWA4TKgQiEwV5cQgZDg1NRXslXhM9PTE->.
Record-Route: <sip:127.0.0.1;lr=on;ftag=17519SIPpTag001;ngcplb=yes;socket=udp:127.0.0.1:5060>.
Via: SIP/2.0/UDP 127.0.0.1:5062;branch=z9hG4bK9dda.7e4b118bbf12c6fc683081d44c680ec9.0.
Route: <sip:lb at 127.0.0.1;lr;socket=sip:127.0.0.1:5060>.
Via: SIP/2.0/UDP 127.0.0.1;branch=z9hG4bK9dda.c7a81cd777225e671c9471d1394c1865.0.
Via: SIP/2.0/UDP 127.126.0.1:50602;rport=50602;branch=z9hG4bK-17519-1-5.
From: <sip:4311002 at spce.test>;tag=17519SIPpTag001.
To: <sip:testuser1003 at spce.test>.
Call-ID: 1-17519 at 127.126.0.1.
CSeq: 2 INVITE.
Contact: sip:testuser1002 at 127.126.0.1:50602.
Max-Forwards:  9.
Content-Type: application/sdp.
Content-Length:   176.
P-Caller-UUID: 074e2a60-4910-4123-88d4-31e2fb88323a.
P-Callee-UUID: 9d655469-e443-48a0-beb3-3e6ddd774e22.
P-Asserted-Identity: <sip:4311002 at spce.test>.
P-Called-Party-ID: <sip:testuser1003 at spce.test>.
P-App-Param: ;aleg_sst_enable=no;sst_enable=no.
P-App-Name: sbc.
P-NGCP-Caller-Info: <sip:testuser1002 at spce.test>;ip=127.126.0.1;port=50602.
P-NGCP-Callee-Info: <sip:testuser1003 at spce.test>;ip=127.0.0.1;port=5060.
P-D-Uri: sip:lb at 127.0.0.1;lr;socket=sip:127.0.0.1:5060.
.
v=0.
o=user1 53655765 2353687637 IN IP4 192.168.51.16.
s=-.
c=IN IP4 192.168.51.16.
t=0 0.
m=audio 30230 RTP/AVP 8.
a=rtpmap:8 PCMA/8000.
a=ptime:50.
a=sendrecv.
a=rtcp:30231.

The UAS responds with a 404:

#
U 2014/09/08 16:32:04.183998 127.0.0.1:5080 -> 127.0.0.1:5062
SIP/2.0 404 Not Found.
Record-Route: <sip:127.0.0.1:5062;lr=on;ftag=17519SIPpTag001;did=5ad.f301;mpd=ii;ice_caller=strip;ice_callee=strip;aset=50;rtpprx=yes;vsf=NHBnWA4TKgQiEwV5cQgZDg1NRXslXhM9PTE->.
Record-Route: <sip:127.0.0.1;lr=on;ftag=17519SIPpTag001;ngcplb=yes;socket=udp:127.0.0.1:5060>.
Via: SIP/2.0/UDP 127.0.0.1:5062;branch=z9hG4bK9dda.7e4b118bbf12c6fc683081d44c680ec9.0;received=127.0.0.1.
Via: SIP/2.0/UDP 127.0.0.1;branch=z9hG4bK9dda.c7a81cd777225e671c9471d1394c1865.0.
Via: SIP/2.0/UDP 127.126.0.1:50602;rport=50602;branch=z9hG4bK-17519-1-5.
From: <sip:4311002 at spce.test>;tag=17519SIPpTag001.
To: <sip:testuser1003 at spce.test>;tag=3B4CEA2F-540DBDE40002BFF2-AB22A700.
Call-ID: 1-17519 at 127.126.0.1.
CSeq: 2 INVITE.
Content-Length: 0.

after which we set an alternative destination and call append_branch():

Sep  8 16:32:04 sp1 proxy[16683]: NOTICE: <script>: Fallback from E164 number to user - R=sip:testuser1003 at spce.test ID=1-17519 at 127.126.0.1

after that the proxy on :5062 sends the new INVITE to the UAS.
This new INVITE has two record-routes belonging to the proxy:

###
U 2014/09/08 16:32:04.271489 127.0.0.1:5062 -> 127.0.0.1:5080
INVITE sip:testuser1003 at 127.1.0.1:50604 SIP/2.0.
Record-Route: <sip:127.0.0.1:5062;lr=on;ftag=17519SIPpTag001;did=5ad.f301;mpd=ii;ice_caller=strip;ice_callee=strip;aset=50;rtpprx=yes;vsf=NHBnWA4TKgQiEwV5cQgZDg1NRXslXhM9PTE->.
Record-Route: <sip:127.0.0.1:5062;lr=on;ftag=17519SIPpTag001>.
Record-Route: <sip:127.0.0.1;lr=on;ftag=17519SIPpTag001;ngcplb=yes;socket=udp:127.0.0.1:5060>.
Via: SIP/2.0/UDP 127.0.0.1:5062;branch=z9hG4bK9dda.7e4b118bbf12c6fc683081d44c680ec9.1.
Route: <sip:lb at 127.0.0.1;lr;socket=sip:127.0.0.1:5060>.
Via: SIP/2.0/UDP 127.0.0.1;branch=z9hG4bK9dda.c7a81cd777225e671c9471d1394c1865.0.
Via: SIP/2.0/UDP 127.126.0.1:50602;rport=50602;branch=z9hG4bK-17519-1-5.
From: <sip:4311002 at spce.test>;tag=17519SIPpTag001.
To: <sip:testuser1003 at spce.test>.
Call-ID: 1-17519 at 127.126.0.1.
CSeq: 2 INVITE.
Contact: sip:testuser1002 at 127.126.0.1:50602.
Max-Forwards:  9.
Content-Type: application/sdp.
Content-Length:   176.
P-Caller-UUID: 074e2a60-4910-4123-88d4-31e2fb88323a.
P-Callee-UUID: 9d655469-e443-48a0-beb3-3e6ddd774e22.
P-Asserted-Identity: <sip:4311002 at spce.test>.
P-Called-Party-ID: <sip:testuser1003 at spce.test>.
P-App-Param: ;aleg_sst_enable=no;sst_enable=no.
P-App-Name: sbc.
P-NGCP-Caller-Info: <sip:testuser1002 at spce.test>;ip=127.126.0.1;port=50602.
P-NGCP-Callee-Info: <sip:testuser1003 at spce.test>;ip=127.0.0.1;port=5060.
P-D-Uri: sip:lb at 127.0.0.1;lr;socket=sip:127.0.0.1:5060.
.
v=0.
o=user1 53655765 2353687637 IN IP4 192.168.51.16.
s=-.
c=IN IP4 192.168.51.16.
t=0 0.
m=audio 30230 RTP/AVP 8.
a=rtpmap:8 PCMA/8000.
a=ptime:50.
a=sendrecv.
a=rtcp:30231.

...
Sep  8 16:32:04 sp1 proxy[16684]: DEBUG: <core> [parser/parse_rr.c:380]: print_rr_body(): current rr is <sip:127.0.0.1:5062;lr=on;ftag=17519SIPpTag001;did=5ad.f301;mpd=ii;ice_caller=strip;ice_callee=strip;aset=50;rtpprx=yes;vsf=NHBnWA4TKgQiEwV5cQgZDg1NRXslXhM9PTE->
Sep  8 16:32:04 sp1 proxy[16684]: DEBUG: <core> [parser/parse_rr.c:380]: print_rr_body(): current rr is <sip:127.0.0.1:5062;lr=on;ftag=17519SIPpTag001>
Sep  8 16:32:04 sp1 proxy[16684]: DEBUG: <core> [parser/parse_rr.c:380]: print_rr_body(): current rr is <sip:127.0.0.1;lr=on;ftag=17519SIPpTag001;ngcplb=yes;socket=udp:127.0.0.1:5060>
Sep  8 16:32:04 sp1 proxy[16684]: DEBUG: <core> [parser/parse_rr.c:405]: print_rr_body(): skipping 3 route records
Sep  8 16:32:04 sp1 proxy[16684]: DEBUG: <core> [parser/parse_rr.c:443]: print_rr_body(): out rr []
Sep  8 16:32:04 sp1 proxy[16684]: DEBUG: <core> [parser/parse_rr.c:444]: print_rr_body(): we have 3 records

I know that this happens only if I call record_route after t_newtran(), if I create the transaction first it's all fine. But there are reasons why I prefer to do it the way it is. Questions:
1) Is this an incorrect usage or rr module? To me it seems like more a bug in kamailio, because if RR is kept on private memory it should be discarded after failure route, but if the RR persists it should not be added 2nd time.
2) Is there an easy way to check if the RR header has been already added?

More information can be found at the following URL:
http://sip-router.org/tracker/index.php?do=details&task_id=466

You are receiving this message because you have requested it from the Flyspray bugtracking system.  If you did not expect this message or don't want to receive mails in future, you can change your notification settings at the URL shown above.