[5.2] 200 Ok on Re-invite faces "transaction not found - (branch -1)" when topos module is used ### Description My setup is UAC --> Kamailio SBC --> External PBX When external PBX sends 407 Proxy Autehtication required , the kamailio SBC sends another invite with auth header ( uac module ) and updated cseq ( from dialog modules track_cseq_updates ). To this the external PBX replies with 200 OK . However Kamailio SBC drops this 200 ok with "**t_reply_matching(): failure to match a transaction**" and "**reply_received(): transaction not found - (branch -1)"**. I am using Lua engine but problem is reproducible even with plain config file based routing configuration ### Troubleshooting #### Reproduction Reproducible everytime with uac module working with uac and topos module from v5.1 and above. #### Debugging Data Sample parameters declaration I am using is like ``` modparam("dialog", "dlg_flag", 4) modparam("dialog", "track_cseq_updates", 1) modparam("uac","auth_username_avp","$avp(auser)") modparam("uac","auth_password_avp","$avp(apass)") modparam("uac","auth_realm_avp","$avp(arealm)") modparam("topos", "storage", "redis") modparam("topos", "sanity_checks", 1) modparam("topos_redis", "serverid", "sbc") ``` #### Log Messages Pasting some snippets from Kamailio in deug mode 3 ( mangled the ips and values of some private identities) ``` <To> [31]; uri=[sip:1234567890@<kamailio_pvt_ip_addr>] to body [<sip:1234567890@<kamailio_pvt_ip_addr>>] cseq <CSeq>: <1> <INVITE> content_length=286 found end of header add param: tag=e0090423 SIP Request: method: <INVITE> uri: <sip:1234567890@<kamailio_pvt_ip_addr>> version: <SIP/2.0> <branch> = <z9hG4bK-d8754z-e7184457335bac6a-1---d8754z->; state=6 <rport> = <n/a>; state=17 parse_via(): end of header reached, state=5 parse_headers(): Via found, flags=2 parse_headers(): this is the first via parse_addr_spec(): end of header reached, state=10 get_hdr_field(): <To> [31]; uri=[sip:1234567890@<kamailio_pvt_ip_addr>] get_hdr_field(): to body [<sip:1234567890@<kamailio_pvt_ip_addr>>] get_hdr_field(): cseq <CSeq>: <1> <INVITE> --- received sip message - request - call-id: [OWY3ZTQ3NGM3NTg0N2U3YmE2MTBiOTIxMTRkOGZmNjM] - cseq: [1 INVITE] Jun 3 07:23:05 inbound1 kamailio[3901]: DEBUG: app_lua [app_lua_api.c:666]: app_lua_run_ex(): executing Lua function: [[ksr_request_route]] get_hdr_field(): content_length=286 get_hdr_field(): found end of header add param: tag=e0090423 end of header reached, state=29 internal_get_dlg(): no dialog callid='OWY3ZTQ3NGM3NTg0N2U3YmE2MTBiOTIxMTRkOGZmNjM' found dlg_search(): dialog with callid='OWY3ZTQ3NGM3NTg0N2U3YmE2MTBiOTIxMTRkOGZmNjM' not found build_new_dlg(): new dialog on hash 3407 populate_leg_info(): leg(0) route_set [], contact [sip:8887779996@<uac_pvt_ip_addr>:10376], cseq [1] and bind_addr [udp:<kamilio_pvt_ip_addr>:5060] dialog [dlg_hash.c:894]: link_dlg(): linking dialog [3407:2543] dialog [dlg_hash.c:903]: link_dlg(): ref dlg 0x7f898dd3f4d8 with 1 -> 1 dialog [dlg_cb.c:228]: run_create_callbacks(): dialog=0x7f898dd3f4d8 rr [record.c:918]: add_rr_param(): rr_param_buf=<;did=f4d.fe9> dialog [dlg_profile.c:536]: set_current_dialog(): setting current dialog [3407:2543] dialog [dlg_hash.c:705]: dlg_lookup(): ref dlg 0x7f898dd3f4d8 with 1 -> 2 dialog [dlg_hash.c:707]: dlg_lookup(): dialog id=2543 found on entry 3407 dialog [dlg_handlers.c:1834]: dlg_manage(): dialog created before transaction has_totag(): no totag matching_3261(): RFC3261 transaction matching failed - via branch [z9hG4bK-d8754z-e7184457335bac6a-1---d8754z-] tm [t_lookup.c:682]: t_lookup_request(): no transaction found SIP Request: method: <INVITE> uri: <sip:1231231230@<pbx_pub_ip_addr>:5080;pstn_inbound=true;ignore_userinfo=true> version: <SIP/2.0> Found param type 232, <branch> = <z9hG4bK68dc.5ad386873790061ba2a8f1d254ec3300.0>; state=16 end of header reached, state=5 Via found, flags=2 this is the first via Found param type 234, <received> = <<uac_pub_ip_addr>>; state=6 Found param type 232, <branch> = <z9hG4bK-d8754z-e7184457335bac6a-1---d8754z->; state=6 Found param type 235, <rport> = <18214>; state=16 end of header reached, state=5 Via found, flags=4 this is the second via end of header reached, state=10 <To> [74]; uri=[sip:1231231230@<pbx_pub_ip_addr>:5080;pstn_inbound=true;ignore_userinfo=true] to body [<sip:1231231230@<pbx_pub_ip_addr>:5080;pstn_inbound=true;ignore_userinfo=true>] cseq <CSeq>: <1> <INVITE> content_length=286 found end of header add param: tag=e0090423 end of header reached, state=29 handling outgoing request (0, 0) compacted headers - x_via1: [SIP/2.0/UDP <kamailio_pvt_ip_addr>:5060;branch=z9hG4bK68dc.5ad386873790061ba2a8f1d254ec3300.0](82) - x_via2: [SIP/2.0/UDP <uac_pvt_ip_addr>:10376;received=<uac_pub_ip_addr>;branch=z9hG4bK-d8754z-e7184457335bac6a-1---d8754z-;rport=18214](118) - x_vbranch1: [z9hG4bK68dc.5ad386873790061ba2a8f1d254ec3300.0](46) received on udp socket: (106/100/741) [[SIP/2.0 407 Proxy Authentication Required 0D 0A Via: SIP/2.0/UDP <kamailio_pvt_ip_addr>:5060;branch=z9hG4bK68dc.5ad3]] Jun 3 07:23:05 inbound1 kamailio[3902]: DEBUG: dialog [dlg_cseq.c:116]: dlg_cseq_prepare_new_msg(): prepare new msg for cseq update operations Jun 3 07:23:05 inbound1 kamailio[3902]: DEBUG: <core> [core/parser/msg_parser.c:614]: parse_msg(): SIP Reply (status): Jun 3 07:23:05 inbound1 kamailio[3902]: DEBUG: <core> [core/parser/msg_parser.c:616]: parse_msg(): version: <SIP/2.0> Jun 3 07:23:05 inbound1 kamailio[3902]: DEBUG: <core> [core/parser/msg_parser.c:618]: parse_msg(): status: <407> Jun 3 07:23:05 inbound1 kamailio[3902]: DEBUG: <core> [core/parser/msg_parser.c:620]: parse_msg(): reason: <Proxy Authentication Required> Jun 3 07:23:05 inbound1 kamailio[3902]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK68dc.5ad386873790061ba2a8f1d254ec3300.0>; state=16 Jun 3 07:23:05 inbound1 kamailio[3902]: DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5 Jun 3 07:23:05 inbound1 kamailio[3902]: DEBUG: <core> [core/parser/msg_parser.c:492]: parse_headers(): Via found, flags=2 Jun 3 07:23:05 inbound1 kamailio[3902]: DEBUG: <core> [core/parser/msg_parser.c:494]: parse_headers(): this is the first via Jun 3 07:23:05 inbound1 kamailio[3902]: DEBUG: dialog [dlg_cseq.c:59]: dlg_cseq_prepare_msg(): prepare msg for cseq update operations Jun 3 07:23:05 inbound1 kamailio[3902]: DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=ZZ2ry8U898rSH Jun 3 07:23:05 inbound1 kamailio[3902]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29 <To> [92]; uri=[sip:1231231230@<pbx_pub_ip_addr>:5080;pstn_inbound=true;ignore_userinfo=true] to body [<sip:1231231230@<pbx_pub_ip_addr>:5080;pstn_inbound=true;ignore_userinfo=true>] cseq <CSeq>: <1> <INVITE> content_length=0 found end of header Jun 3 07:23:05 inbound1 kamailio[3902]: DEBUG: dialog [dlg_cseq.c:87]: dlg_cseq_prepare_msg(): no second via in this message Jun 3 07:23:05 inbound1 kamailio[3902]: DEBUG: <core> [core/parser/msg_parser.c:614]: parse_msg(): SIP Reply (status): version: <SIP/2.0> status: <407> reason: <Proxy Authentication Required> Found param type 232, <branch> = <z9hG4bK68dc.5ad386873790061ba2a8f1d254ec3300.0>; state=16 Jun 3 07:23:05 inbound1 kamailio[3902]: DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5 Jun 3 07:23:05 inbound1 kamailio[3902]: DEBUG: <core> [core/parser/msg_parser.c:492]: parse_headers(): Via found, flags=2 Jun 3 07:23:05 inbound1 kamailio[3902]: DEBUG: <core> [core/parser/msg_parser.c:494]: parse_headers(): this is the first via Jun 3 07:23:05 inbound1 kamailio[3902]: DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=ZZ2ry8U898rSH Jun 3 07:23:05 inbound1 kamailio[3902]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29 <To> [92]; uri=[sip:1231231230@<pbx_pub_ip_addr>:5080;pstn_inbound=true;ignore_userinfo=true] to body [<sip:1231231230@<pbx_pub_ip_addr>:5080;pstn_inbound=true;ignore_userinfo=true>] cseq <CSeq>: <1> <INVITE> content_length=0 found end of header add param: tag=e0090423 end of header reached, state=29 handling incoming response branchi 0 From: <sip:8887779996@<kamailio_pvt_ip_addr>>;tag=e0090423 To: <sip:1231231230@<pbx_pub_ip_addr>:5080;pstn_inbound=true;ignore_userinfo=true>;tag=ZZ2ry8U898rSH Call-ID: OWY3ZTQ3NGM3NTg0N2U3YmE2MTBiOTIxMTRkOGZmNjM CSeq: 1 INVITE User-Agent: FreeSWITCH-mod_sofia/1.9.0-742-8f1b7e0~64bit Accept: application/sdpAllow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, path, replaces Allow-Events: talk, hold, conference, refer Proxy-Authenticate: Digest realm="<pbx_pub_ip_addr>", nonce="df67c993-df56-4246-9e79-10fdf0c79cbb", algorithm=MD5, qop="auth" Content-Length: 0 Via: SIP/2.0/UDP <uac_pvt_ip_addr>:10376;received=<uac_pub_ip_addr>;branch=z9hG4bK-d8754z-e7184457335bac6a-1---d8754z-;rport=18214 Record-Route: <sip:<kamailio_pvt_ip_addr>;lr;ftag=e0090423;did=f4d.fe9;nat=yes> P-SR-XBranch: z9hG4bK68dc.5ad386873790061ba2a8f1d254ec3300.0 , branchl 1 , branch_id 0 ... parse_msg(): SIP Request: Jun 3 07:23:05 inbound1 kamailio[3902]: DEBUG: <core> [core/parser/msg_parser.c:606]: parse_msg(): method: <ACK> Jun 3 07:23:05 inbound1 kamailio[3902]: DEBUG: <core> [core/parser/msg_parser.c:608]: parse_msg(): uri: <sip:1231231230@<pbx_pub_ip_addr>:5080;pstn_inbound=true;ignore_userinfo=true> Jun 3 07:23:05 inbound1 kamailio[3902]: DEBUG: <core> [core/parser/msg_parser.c:610]: parse_msg(): version: <SIP/2.0> Jun 3 07:23:05 inbound1 kamailio[3902]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK68dc.5ad386873790061ba2a8f1d254ec3300.0>; state=16 Jun 3 07:23:05 inbound1 kamailio[3902]: DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5 Jun 3 07:23:05 inbound1 kamailio[3902]: DEBUG: <core> [core/parser/msg_parser.c:492]: parse_headers(): Via found, flags=2 Jun 3 07:23:05 inbound1 kamailio[3902]: DEBUG: <core> [core/parser/msg_parser.c:494]: parse_headers(): this is the first via Jun 3 07:23:05 inbound1 kamailio[3902]: DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=ZZ2ry8U898rSH Jun 3 07:23:05 inbound1 kamailio[3902]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29 Jun 3 07:23:05 inbound1 kamailio[3902]: DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To> [92]; uri=[sip:1231231230@<pbx_pub_ip_addr>:5080;pstn_inbound=true;ignore_userinfo=true] Jun 3 07:23:05 inbound1 kamailio[3902]: DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body [<sip:1231231230@<pbx_pub_ip_addr>:5080;pstn_inbound=true;ignore_userinfo=true>] Jun 3 07:23:05 inbound1 kamailio[3902]: DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <1> <ACK> Jun 3 07:23:05 inbound1 kamailio[3902]: DEBUG: <core> [core/parser/msg_parser.c:183]: get_hdr_field(): content_length=0 Jun 3 07:23:05 inbound1 kamailio[3902]: DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header Jun 3 07:23:05 inbound1 kamailio[3902]: DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=e0090423 Jun 3 07:23:05 inbound1 kamailio[3902]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29 Jun 3 07:23:05 inbound1 kamailio[3902]: DEBUG: topos [tps_msg.c:934]: tps_request_sent(): handling outgoing request (1, 1) Jun 3 07:23:05 inbound1 kamailio[3902]: DEBUG: topos [tps_msg.c:380]: tps_pack_message(): compacted headers - x_via1: [SIP/2.0/UDP <kamailio_pvt_ip_addr>:5060;branch=z9hG4bK68dc.5ad386873790061ba2a8f1d254ec3300.0](82) - x_via2: [](0) - x_vbranch1: [z9hG4bK68dc.5ad386873790061ba2a8f1d254ec3300.0](46) DEBUG: app_lua [app_lua_sr.c:1649]: sr_kemi_lua_exec_func_ex(): param[1] for: log is str: OWY3ZTQ3NGM3NTg0N2U3YmE2MTBiOTIxMTRkOGZmNjM|udp:<uac_pub_ip_addr>:18214|INVITE|failure route: incoming reply received - 407#012 Jun 3 07:23:05 inbound1 kamailio[3902]: ERROR: <core> [core/kemi.c:144]: sr_kemi_core_log(): OWY3ZTQ3NGM3NTg0N2U3YmE2MTBiOTIxMTRkOGZmNjM|udp:<uac_pub_ip_addr>:18214|INVITE|failure route: incoming reply received - 407 OWY3ZTQ3NGM3NTg0N2U3YmE2MTBiOTIxMTRkOGZmNjM|udp:<uac_pub_ip_addr>:18214|INVITE|Auth Request, send authorization to sip:1231231230@<pbx_pub_ip_addr>:5080;pstn_inbound=true;ignore_userinfo=true;timeout=60;username=<username>;password=<pass>;carrierid=55 OWY3ZTQ3NGM3NTg0N2U3YmE2MTBiOTIxMTRkOGZmNjM|udp:<uac_pub_ip_addr>:18214|INVITE| ksr_auth gateway : sip:1231231230@<pbx_pub_ip_addr>:5080;pstn_inbound=true;ignore_userinfo=true;timeout=60;username=<username>;password=<pass>;carrierid=55 OWY3ZTQ3NGM3NTg0N2U3YmE2MTBiOTIxMTRkOGZmNjM|udp:<uac_pub_ip_addr>:18214|INVITE| ksr_auth creds : <username><pass><pbx_pub_ip_addr> hdr is <Proxy-Authorization: Digest username="<username>", realm="<pbx_pub_ip_addr>", nonce="df67c993-df56-4246-9e79-10fdf0c79cbb", uri="sip:1231231230@<pbx_pub_ip_addr>:5080;pstn_inbound=true;ignore_userinfo=true", qop=auth, nc=00000001, cnonce="2931066055", response="65cbbb1afd6b54bcd5f594a336b53b89", algorithm=MD5> OWY3ZTQ3NGM3NTg0N2U3YmE2MTBiOTIxMTRkOGZmNjM|udp:<uac_pub_ip_addr>:18214|INVITE| uac auth headers formed OWY3ZTQ3NGM3NTg0N2U3YmE2MTBiOTIxMTRkOGZmNjM|udp:<uac_pub_ip_addr>:18214|INVITE| relay auth req OWY3ZTQ3NGM3NTg0N2U3YmE2MTBiOTIxMTRkOGZmNjM|udp:<uac_pub_ip_addr>:18214|INVITE| ksr_route_realy OWY3ZTQ3NGM3NTg0N2U3YmE2MTBiOTIxMTRkOGZmNjM|udp:<uac_pub_ip_addr>:18214|INVITE|relaying the message with Request-Uri - sip:1231231230@<pbx_pub_ip_addr>:5080;pstn_inbound=true;ignore_userinfo=true Destination-Uri - ... OWY3ZTQ3NGM3NTg0N2U3YmE2MTBiOTIxMTRkOGZmNjM|udp:<uac_pub_ip_addr>:18214|INVITE| req_mtd INVITE1 OWY3ZTQ3NGM3NTg0N2U3YmE2MTBiOTIxMTRkOGZmNjM|udp:<uac_pub_ip_addr>:18214|INVITE| not is dialog request , goto set carrier info OWY3ZTQ3NGM3NTg0N2U3YmE2MTBiOTIxMTRkOGZmNjM|udp:<uac_pub_ip_addr>:18214|INVITE| target not set for branch route setting OWY3ZTQ3NGM3NTg0N2U3YmE2MTBiOTIxMTRkOGZmNjM|udp:<uac_pub_ip_addr>:18214|INVITE|target not set for failure , setting OWY3ZTQ3NGM3NTg0N2U3YmE2MTBiOTIxMTRkOGZmNjM|udp:<uac_pub_ip_addr>:18214|INVITE| core.is_trans_target_set onreply_routetrue OWY3ZTQ3NGM3NTg0N2U3YmE2MTBiOTIxMTRkOGZmNjM|udp:<uac_pub_ip_addr>:18214|INVITE| ew branch [1] to sip:1231231230@<pbx_pub_ip_addr>:5080;pstn_inbound=true;ignore_userinfo=true has_totag(): no totag parse_msg(): SIP Request: method: <INVITE> uri: <sip:1231231230@<pbx_pub_ip_addr>:5080;pstn_inbound=true;ignore_userinfo=true> version: <SIP/2.0> Found param type 232, <branch> = <z9hG4bK68dc.5ad386873790061ba2a8f1d254ec3300.1>; state=16 end of header reached, state=5 Via found, flags=2 this is the first via Found param type 234, <received> = <<uac_pub_ip_addr>>; state=6 Found param type 232, <branch> = <z9hG4bK-d8754z-e7184457335bac6a-1---d8754z->; state=6 Found param type 235, <rport> = <18214>; state=16 end of header reached, state=5 Via found, flags=4 this is the second via end of header reached, state=10 Jun 3 07:23:05 inbound1 kamailio[3902]: DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To> [74]; uri=[sip:1231231230@<pbx_pub_ip_addr>:5080;pstn_inbound=true;ignore_userinfo=true] Jun 3 07:23:05 inbound1 kamailio[3902]: DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body [<sip:1231231230@<pbx_pub_ip_addr>:5080;pstn_inbound=true;ignore_userinfo=true>] Jun 3 07:23:05 inbound1 kamailio[3902]: DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <1> <INVITE> Jun 3 07:23:05 inbound1 kamailio[3902]: DEBUG: <core> [core/parser/msg_parser.c:183]: get_hdr_field(): content_length=286 Jun 3 07:23:05 inbound1 kamailio[3902]: DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header Jun 3 07:23:05 inbound1 kamailio[3902]: DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=e0090423 Jun 3 07:23:05 inbound1 kamailio[3902]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29 Jun 3 07:23:05 inbound1 kamailio[3902]: DEBUG: topos [tps_msg.c:934]: tps_request_sent(): handling outgoing request (0, 0) Jun 3 07:23:05 inbound1 kamailio[3902]: DEBUG: topos [tps_msg.c:380]: tps_pack_message(): compacted headers - x_via1: [SIP/2.0/UDP <kamailio_pvt_ip_addr>:5060;branch=z9hG4bK68dc.5ad386873790061ba2a8f1d254ec3300.1](82) - x_via2: [SIP/2.0/UDP <uac_pvt_ip_addr>:10376;received=<uac_pub_ip_addr>;branch=z9hG4bK-d8754z-e7184457335bac6a-1---d8754z-;rport=18214](118) - x_vbranch1: [z9hG4bK68dc.5ad386873790061ba2a8f1d254ec3300.1](46) received on udp socket: (106/100/389) [[SIP/2.0 100 Trying 0D 0A Via: SIP/2.0/UDP <kamailio_pvt_ip_addr>:5060;branch=z9hG4bK68dc.5ad386873790061ba2a8f1d254e]] Jun 3 07:23:05 inbound1 kamailio[3898]: DEBUG: dialog [dlg_cseq.c:116]: dlg_cseq_prepare_new_msg(): prepare new msg for cseq update operations Jun 3 07:23:05 inbound1 kamailio[3898]: DEBUG: <core> [core/parser/msg_parser.c:614]: parse_msg(): SIP Reply (status): Jun 3 07:23:05 inbound1 kamailio[3898]: DEBUG: <core> [core/parser/msg_parser.c:616]: parse_msg(): version: <SIP/2.0> Jun 3 07:23:05 inbound1 kamailio[3898]: DEBUG: <core> [core/parser/msg_parser.c:618]: parse_msg(): status: <100> Jun 3 07:23:05 inbound1 kamailio[3898]: DEBUG: <core> [core/parser/msg_parser.c:620]: parse_msg(): reason: <Trying> Jun 3 07:23:05 inbound1 kamailio[3898]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK68dc.5ad386873790061ba2a8f1d254ec3300.1.cs1>; state=16 Jun 3 07:23:05 inbound1 kamailio[3898]: DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5 Jun 3 07:23:05 inbound1 kamailio[3898]: DEBUG: <core> [core/parser/msg_parser.c:492]: parse_headers(): Via found, flags=2 Jun 3 07:23:05 inbound1 kamailio[3898]: DEBUG: <core> [core/parser/msg_parser.c:494]: parse_headers(): this is the first via Jun 3 07:23:05 inbound1 kamailio[3898]: DEBUG: dialog [dlg_cseq.c:59]: dlg_cseq_prepare_msg(): prepare msg for cseq update operations Jun 3 07:23:05 inbound1 kamailio[3898]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=10 Jun 3 07:23:05 inbound1 kamailio[3898]: DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To> [74]; uri=[sip:1231231230@<pbx_pub_ip_addr>:5080;pstn_inbound=true;ignore_userinfo=true] Jun 3 07:23:05 inbound1 kamailio[3898]: DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body [<sip:1231231230@<pbx_pub_ip_addr>:5080;pstn_inbound=true;ignore_userinfo=true>] Jun 3 07:23:05 inbound1 kamailio[3898]: DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <2> <INVITE> Jun 3 07:23:05 inbound1 kamailio[3898]: DEBUG: <core> [core/parser/msg_parser.c:183]: get_hdr_field(): content_length=0 Jun 3 07:23:05 inbound1 kamailio[3898]: DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header Jun 3 07:23:05 inbound1 kamailio[3898]: DEBUG: dialog [dlg_cseq.c:87]: dlg_cseq_prepare_msg(): no second via in this message receive_msg(): --- received sip message - reply - call-id: [OWY3ZTQ3NGM3NTg0N2U3YmE2MTBiOTIxMTRkOGZmNjM] - cseq: [2 INVITE] t_reply_matching(): branchi 1.cs1 From: <sip:8887779996@<kamailio_pvt_ip_addr>>;tag=e0090423 To: <sip:1231231230@<pbx_pub_ip_addr>:5080;pstn_inbound=true;ignore_userinfo=true> Call-ID: OWY3ZTQ3NGM3NTg0N2U3YmE2MTBiOTIxMTRkOGZmNjM CSeq: 2 INVITE User-Agent: FreeSWITCH-mod_sofia/1.9.0-742-8f1b7e0~64bitContent-Length: 0 , branchl 5 , branch_id 16 **t_reply_matching(): failure to match a transaction** udp_rcv_loop(): received on udp socket: (106/100/1032) [[SIP/2.0 200 OK 0D 0A Via: SIP/2.0/UDP <kamailio_pvt_ip_addr>:5060;branch=z9hG4bK68dc.5ad386873790061ba2a8f1d254ec330]] Jun 3 07:23:05 inbound1 kamailio[3903]: DEBUG: dialog [dlg_cseq.c:116]: dlg_cseq_prepare_new_msg(): prepare new msg for cseq update operations Jun 3 07:23:05 inbound1 kamailio[3903]: DEBUG: <core> [core/parser/msg_parser.c:614]: parse_msg(): SIP Reply (status): Jun 3 07:23:05 inbound1 kamailio[3903]: DEBUG: <core> [core/parser/msg_parser.c:616]: parse_msg(): version: <SIP/2.0> Jun 3 07:23:05 inbound1 kamailio[3903]: DEBUG: <core> [core/parser/msg_parser.c:618]: parse_msg(): status: <200> Jun 3 07:23:05 inbound1 kamailio[3903]: DEBUG: <core> [core/parser/msg_parser.c:620]: parse_msg(): reason: <OK> Jun 3 07:23:05 inbound1 kamailio[3903]: DEBUG: <core> [core/parser/parse_via.c:1303]: parse_via_param(): Found param type 232, <branch> = <z9hG4bK68dc.5ad386873790061ba2a8f1d254ec3300.1.cs1>; state=16 Jun 3 07:23:05 inbound1 kamailio[3903]: DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5 Jun 3 07:23:05 inbound1 kamailio[3903]: DEBUG: <core> [core/parser/msg_parser.c:492]: parse_headers(): Via found, flags=2 Jun 3 07:23:05 inbound1 kamailio[3903]: DEBUG: <core> [core/parser/msg_parser.c:494]: parse_headers(): this is the first via Jun 3 07:23:05 inbound1 kamailio[3903]: DEBUG: dialog [dlg_cseq.c:59]: dlg_cseq_prepare_msg(): prepare msg for cseq update operations Jun 3 07:23:05 inbound1 kamailio[3903]: DEBUG: <core> [core/parser/parse_addr_spec.c:185]: parse_to_param(): add param: tag=08UH03cc7HFcD Jun 3 07:23:05 inbound1 kamailio[3903]: DEBUG: <core> [core/parser/parse_addr_spec.c:864]: parse_addr_spec(): end of header reached, state=29 Jun 3 07:23:05 inbound1 kamailio[3903]: DEBUG: <core> [core/parser/msg_parser.c:171]: get_hdr_field(): <To> [92]; uri=[sip:1231231230@<pbx_pub_ip_addr>:5080;pstn_inbound=true;ignore_userinfo=true] Jun 3 07:23:05 inbound1 kamailio[3903]: DEBUG: <core> [core/parser/msg_parser.c:172]: get_hdr_field(): to body [<sip:1231231230@<pbx_pub_ip_addr>:5080;pstn_inbound=true;ignore_userinfo=true>] Jun 3 07:23:05 inbound1 kamailio[3903]: DEBUG: <core> [core/parser/msg_parser.c:152]: get_hdr_field(): cseq <CSeq>: <2> <INVITE> Jun 3 07:23:05 inbound1 kamailio[3903]: DEBUG: <core> [core/parser/msg_parser.c:183]: get_hdr_field(): content_length=218 Jun 3 07:23:05 inbound1 kamailio[3903]: DEBUG: <core> [core/parser/msg_parser.c:89]: get_hdr_field(): found end of header Jun 3 07:23:05 inbound1 kamailio[3903]: DEBUG: dialog [dlg_cseq.c:87]: dlg_cseq_prepare_msg(): no second via in this message receive_msg(): --- received sip message - reply - call-id: [OWY3ZTQ3NGM3NTg0N2U3YmE2MTBiOTIxMTRkOGZmNjM] - cseq: [2 INVITE] t_reply_matching(): branchi 1.cs1From: <sip:8887779996@<kamailio_pvt_ip_addr>>;tag=e0090423To: <sip:1231231230@<pbx_pub_ip_addr>:5080;pstn_inbound=true;ignore_userinfo=true>;tag=08UH03cc7HFcDCall-ID: OWY3ZTQ3NGM3NTg0N2U3YmE2MTBiOTIxMTRkOGZmNjMCSeq: 2 INVITEContact: <sip:1231231230@<pbx_pub_ip_addr>:5080;transport=udp>User-Agent: FreeSWITCH-mod_sofia/1.9.0-742-8f1b7e0~64bitAccept: application/sdpAllow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFYSupported: timer, path, replacesAllow-Events: talk, hold, conference, referContent-Type: application/sdpContent-Disposition: sessionContent-Length: 218Remote-Party-ID: "1231231230" <sip:1231231230@<pbx_pub_ip_addr>>;party=calling;privacy=off;screen=nov=0o=FreeSWITCH 1559530170 1559530171 IN IP4 <pbx_pub_ip_addr>s=FreeSWITCHc=IN IP4 <pbx_pub_ip_addr>t=0 0m=audio 16432 RTP/AVP 0 101a=rtpmap:0 PCMU/8000a=rtpmap:101 telephone-event/8000a=fmtp:101 0-16a=ptime:20 , branchl 5 , branch_id 16 **t_reply_matching(): failure to match a transaction** ``` #### SIP Traffic Not sure if the callflow will appear disfigured below. Primarily what it depicts is that 200 ok from External PBX is dropped by Kamailio and hence kamailio tries to resen the auth based invote multiple times till request timeout occurs ``` |Time | UAC | Kamailio SBC | External PBX | |6.649019 | INVITE SDP (g711U te | |SIP INVITE From: <sip:8887779996@<uac_address> To:<sip:18077881601@<uac_address> Call-ID:OWY3ZTQ3NGM3NTg0N2U3YmE2MTBiOTIxMTRkOGZmNjM CSeq:1 | | ------------------> | | |6.649538 | 100 trying -- your c | |SIP Status 100 trying -- your call is important to us | | <------------------ | | |6.650087 | | INVITE SDP (g711U te |SIP INVITE From: <sip:8887779996@<uac_address> To:<sip:18077881601@<uac_address> CSeq:1 | | | ------------------> | |6.651861 | | 407 Proxy Authentica |SIP Status 407 Proxy Authentication Required | | | <------------------ | |6.652194 | | ACK | |SIP ACK From: <sip:8887779996@<uac_address> To:<sip:18077881601@<uac_address> CSeq:1 | | | ------------------> | |6.653097 | | INVITE SDP (g711U te |SIP INVITE From: <sip:8887779996@<uac_address> To:<sip:18077881601@<uac_address> CSeq:2 | | | ------------------> | |6.673088 | | 100 Trying| |SIP Status 100 Trying | | | <------------------ | |6.676293 | | 200 OK SDP (g711U te |SIP Status 200 OK | | | <------------------ | |7.109339 | | INVITE SDP (g711U te |SIP INVITE From: <sip:8887779996@<uac_address> To:<sip:18077881601@<uac_address> CSeq:2 | | | ------------------> | |7.110230 | | 200 OK SDP (g711U te |SIP Status 200 OK | | | <------------------ | |7.176010 | | 200 OK SDP (g711U te |SIP Status 200 OK | | | <------------------ | |8.109281 | | INVITE SDP (g711U te |SIP INVITE From: <sip:8887779996@<uac_address> To:<sip:18077881601@<uac_address> CSeq:2 | | | ------------------> | |8.110154 | | 200 OK SDP (g711U te |SIP Status 200 OK | | | <------------------ | |8.176005 | | 200 OK SDP (g711U te |SIP Status 200 OK | | | <------------------ | ``` ### Possible Solutions By monitoring redis, I can see that compacting headers by topos and tps storage C file on redis is only happening for the branch id of the first invite , such as ``` "HMSET" "b:x:z9hG4bK68dc.5ad386873790061ba2a8f1d254ec3300.0" "rectime" "1559887868" "a_callid" "OWY3ZTQ3NGM3NTg0N2U3YmE2MTBiOTIxMTRkOGZmNjM" "a_uuid" "atpsh-5cf9fea7-123a-1" "b_uuid" "btpsh-5cf9fea7-123a-1" "direction" "0" "x_via" "SIP/2.0/TCP <uac_pvt_address>:9364;received=<uac_pub_address>;branch=z9hG4bK-d8754z-e7184457335bac6a-1---d8754z-;rport=29567" "x_vbranch" "z9hG4bK68dc.5ad386873790061ba2a8f1d254ec3300.0" "s_rr" "<sip:<kamailio_pub_address>:5060;r2=on;lr;ftag=e0090423;did=508.39e1;nat=yes>,<sip:<kamailio_pub_address>;transport=tcp;r2=on;lr;ftag=e0090423;did=f4d.fe9;nat=yes>" "x_tag" "45a56f2c" "s_method" "INVITE" "s_cseq" "1" "a_contact" "sip:6666666666@<uac_pvt_address>:9364;transport=tcp;alias=<uac_pub_address>~29567~2" "as_contact" "<sip:atpsh-5cf9fea7-123a-1@<kamailio_pub_address>;transport=tcp>" "bs_contact" "<sip:btpsh-5cf9fea7-123a-1@<kamailio_pub_address>:5060>" "a_tag" "45a56f2c" ``` But when the 200 ok for re-invite comes back after authentication, the topos module tries to extract the records for new branch cseq such as "HGETALL" "b:x:5ad386873790061ba2a8f1d254ec3300.1.cs1" which is obviously not set and hence not fetched resulting in transaction not matched error and 200 ok being dropped. If topos storage can HMSET for newer branch id as they are created, I presumme it should fix things up and matching transactions will be ok ### Additional Information * **Kamailio Version** - output of `kamailio -v` ``` version: kamailio 5.1.8 (x86_64/linux) 5534c0 flags: STATS: Off, USE_TCP, USE_TLS, USE_SCTP, TLS_HOOKS, USE_RAW_SOCKS, 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_URI_SIZE 1024, BUF_SIZE 65535, DEFAULT PKG_SIZE 8MB poll method support: poll, epoll_lt, epoll_et, sigio_rt, select. id: 5534c0 compiled on 09:32:39 Jun 7 2019 with gcc 4.8.4 ``` * **Operating System**: ``` My OS is Distributor ID: Ubuntu Description: Ubuntu 14.04.5 LTS Release: 14.04 Codename: trusty ``` -- You are receiving this because you are subscribed to this thread. Reply to this email directly or view it on GitHub: https://github.com/kamailio/kamailio/issues/1975