topos: missing Record-Route on 200 OK leaving the server (downstream)

[linuxmaniac]

Description

Seems that topos is not adding Record-Route headers in this scenario.

Troubleshooting

Reproduction

Log Messages

I've added some more debug to topos: https://paste.debian.net/1152674/
Full kamailio-lb.log

This is the part when processing of the 200 OK coming from PSTN(fake)

Jun 18 13:48:35 sp1 lb[14702]: DEBUG: topos [tps_msg.c:868]: tps_response_received(): handling incoming response
Jun 18 13:48:35 sp1 lb[14702]: DEBUG: topos [tps_msg.c:376]: tps_pack_message(): compacted headers - x_via1: [SIP/2.0/UDP 127.0.0.1:5064;branch=z9hG4bKcf3d.49d855e2b5f83b9dff62c8a6b0cf23f8.0](80) - x_via2: [](0) - x_vbranch1: [z9hG4bKcf3d.49d855e2b5f83b9dff62c8a6b0cf23f8.0](46)
Jun 18 13:48:35 sp1 lb[14702]: DEBUG: topos [tps_msg.c:485]: tps_pack_message(): compacted headers - a_rr: [](0) - b_rr: [](0) - s_rr: [](0)
Jun 18 13:48:35 sp1 lb[14702]: DEBUG: topos [tps_msg.c:490]: tps_pack_message(): compacted headers - as_contact: [](0) - bs_contact: [](0)
Jun 18 13:48:35 sp1 lb[14702]: DEBUG: topos [tps_storage.c:126]: tps_storage_lock_get(): tps lock get: 220
Jun 18 13:48:35 sp1 lb[14702]: DEBUG: topos [tps_msg.c:889]: tps_response_received(): loaded dialog a_uuid [atpsh-5eeb547f-3970-3]
Jun 18 13:48:35 sp1 lb[14702]: DEBUG: topos [tps_storage.c:391]: tps_storage_link_msg(): downstream: yes - acontact: [] - bcontact: [sip:127.0.2.1:50603;transport=UDP]
Jun 18 13:48:35 sp1 lb[14702]: DEBUG: topos [tps_storage.c:138]: tps_storage_lock_release(): tps lock release: 220
Jun 18 13:48:35 sp1 lb[14702]: DEBUG: topos [tps_msg.c:182]: tps_add_headers(): adding to headers(0) - [Via: SIP/2.0/UDP 127.0.0.1:5080;received=127.0.0.1;branch=z9hG4bKh2oO8aY.;rport=5080#015#012]
Jun 18 13:48:35 sp1 lb[14702]: DEBUG: topos [tps_msg.c:910]: tps_response_received(): x_rr[] y_rr[] s_rr[<sip:127.0.0.1:5064;r2=on;lr=on;ftag=5A412B38-5EEB5492000D683F-C3258700;ngcplb=yes;socket=udp:127.0.0.1:5064>,<sip:127.0.0.1;r2=on;lr=on;ftag=5A412B38-5EEB5492000D683F-C3258700;ngcplb=yes;socket=udp:127.0.0.1:5064>]
Jun 18 13:48:35 sp1 lb[14702]: DEBUG: topos [tps_msg.c:182]: tps_add_headers(): adding to headers(0) - [Record-Route: <sip:127.0.0.1:5064;r2=on;lr=on;ftag=5A412B38-5EEB5492000D683F-C3258700;ngcplb=yes;socket=udp:127.0.0.1:5064>,<sip:127.0.0.1;r2=on;lr=on;ftag=5A412B38-5EEB5492000D683F-C3258700;ngcplb=yes;socket=udp:127.0.0.1:5064>#015#012]
Jun 18 13:48:35 sp1 lb[14702]: DEBUG: topos [tps_msg.c:182]: tps_add_headers(): adding to headers(0) - [P-SR-XBranch: z9hG4bKcf3d.49d855e2b5f83b9dff62c8a6b0cf23f8.0#015#012]
Jun 18 13:48:35 sp1 lb[14702]: NOTICE: REPLY_FROM_OUTBOUND <script>: Reply from Outbound - S=200 - OK M=INVITE IP=«udp»:«127.0.2.1»:«50603» ID=«NGCP%invite_peerout_outbound_socket%///1-15281@127.126.0.1_b2b-1» UA='<null>' DESTIP=«127.0.0.1»:«5064»
Jun 18 13:48:35 sp1 lb[14702]: NOTICE: REPLY_FROM_OUTBOUND <script>: NATed reply detected - ID=«NGCP%invite_peerout_outbound_socket%///1-15281@127.126.0.1_b2b-1» UA='<null>'
Jun 18 13:48:35 sp1 lb[14702]: NOTICE: REPLY_FROM_OUTBOUND <script>: Sending reply from outbound, fs='«udp:127.0.0.1:5060»' du='«127.0.0.1»:«5080»' - ID=«NGCP%invite_peerout_outbound_socket%///1-15281@127.126.0.1_b2b-1» UA='<null>'
Jun 18 13:48:35 sp1 lb[14702]: DEBUG: <null> topos [topos_mod.c:514]: tps_execute_event_route(): executing event_route[topos:topos:msg-sending] (2)
Jun 18 13:48:35 sp1 lb[14702]: DEBUG: <null> topos [tps_msg.c:1038]: tps_response_sent(): handling outgoing response
Jun 18 13:48:35 sp1 lb[14702]: DEBUG: <null> topos [tps_msg.c:376]: tps_pack_message(): compacted headers - x_via1: [SIP/2.0/UDP 127.0.0.1:5080;received=127.0.0.1;branch=z9hG4bKh2oO8aY.;rport=5080](79) - x_via2: [](0) - x_vbranch1: [z9hG4bKh2oO8aY.](15)
Jun 18 13:48:35 sp1 lb[14702]: DEBUG: <null> topos [tps_msg.c:485]: tps_pack_message(): compacted headers - a_rr: [](0) - b_rr: [<sip:127.0.0.1:5064;r2=on;lr=on;ftag=5A412B38-5EEB5492000D683F-C3258700;ngcplb=yes;socket=udp:127.0.0.1:5064>,<sip:127.0.0.1;r2=on;lr=on;ftag=5A412B38-5EEB5492000D683F-C3258700;ngcplb=yes;socket=udp:127.0.0.1:5064>](214) - s_rr: [](0)
Jun 18 13:48:35 sp1 lb[14702]: DEBUG: <null> topos [tps_msg.c:490]: tps_pack_message(): compacted headers - as_contact: [](0) - bs_contact: [](0)
Jun 18 13:48:35 sp1 lb[14702]: DEBUG: <null> topos [tps_storage.c:126]: tps_storage_lock_get(): tps lock get: 220
Jun 18 13:48:35 sp1 lb[14702]: DEBUG: <null> topos [tps_msg.c:1068]: tps_response_sent(): loaded branch a_uuid [atpsh-5eeb547f-3970-3]
Jun 18 13:48:35 sp1 lb[14702]: DEBUG: <null> topos [tps_storage.c:138]: tps_storage_lock_release(): tps lock release: 220
Jun 18 13:48:35 sp1 lb[14702]: DEBUG: <null> topos [tps_msg.c:182]: tps_add_headers(): adding to headers(0) - [Contact: <sip:atpsh-5eeb547f-3970-3@127.0.0.1>#015#012]
Jun 18 13:48:35 sp1 lb[14702]: DEBUG: <null> topos [tps_msg.c:1101]: tps_response_sent(): x_rr[] y_rr[] s_rr[<sip:127.0.0.1:5064;r2=on;lr=on;ftag=5A412B38-5EEB5492000D683F-C3258700;ngcplb=yes;socket=udp:127.0.0.1:5064>,<sip:127.0.0.1;r2=on;lr=on;ftag=5A412B38-5EEB5492000D683F-C3258700;ngcplb=yes;socket=udp:127.0.0.1:5064>]
Jun 18 13:48:35 sp1 lb[14702]: DEBUG: <null> topos [tps_storage.c:391]: tps_storage_link_msg(): downstream: yes - acontact: [] - bcontact: [sip:127.0.2.1:50603;transport=UDP]
Jun 18 13:48:35 sp1 lb[14702]: DEBUG: <null> topos [topos_mod.c:454]: tps_msg_sent(): new outbound buffer generated

topos [tps_msg.c:910]: tps_response_received(): x_rr[] y_rr[] s_rr[<sip:127.0.0.1:5064;r2=on;lr=on;ftag=5A412B38-5EEB5492000D683F-C3258700;ngcplb=yes;socket=udp:127.0.0.1:5064>,<sip:127.0.0.1;r2=on;lr=on;ftag=5A412B38-5EEB5492000D683F-C3258700;ngcplb=yes;socket=udp:127.0.0.1:5064>]

proper Record-Route value is on s_rr

but here uses x_rr that is empty in this case

SIP Traffic

pcap files for the same scenario with and without topos

no_topos.zip
topos.zip

Additional Information

• Kamailio Version - output of kamailio -v

This is Sipwise version based on 5.3.4, no patches on topos apart of the debug one.

[linuxmaniac]

Uhm, maybe I'm missing something here. Sorry for the noise.