<p>[5.2] 200 Ok on Re-invite faces "transaction not found - (branch -1)" when topos module is used</p>
<h3>Description</h3>
<p>My setup is UAC --> Kamailio SBC --> External PBX<br>
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 "<strong>t_reply_matching(): failure to match a transaction</strong>" and "<strong>reply_received(): transaction not found - (branch -1)"</strong>.</p>
<p>I am using Lua engine but problem is reproducible even with plain config file based routing configuration</p>
<h3>Troubleshooting</h3>
<h4>Reproduction</h4>
<p>Reproducible everytime with uac module working with uac and topos module from v5.1 and above.</p>
<h4>Debugging Data</h4>
<p>Sample parameters declaration I am using is like</p>
<pre><code>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")
</code></pre>
<h4>Log Messages</h4>
<p>Pasting some snippets from Kamailio in deug mode 3 ( mangled the ips and values of some private identities)</p>
<pre><code><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**
</code></pre>
<h4>SIP Traffic</h4>
<p>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</p>
<pre><code>|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
| | | <------------------ |
</code></pre>
<h3>Possible Solutions</h3>
<p>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</p>
<pre><code>"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"
</code></pre>
<p>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<br>
"HGETALL" "b<g-emoji class="g-emoji" alias="x" fallback-src="https://github.githubassets.com/images/icons/emoji/unicode/274c.png">❌</g-emoji>5ad386873790061ba2a8f1d254ec3300.1.cs1"<br>
which is obviously not set and hence not fetched resulting in transaction not matched error and 200 ok being dropped.</p>
<p>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</p>
<h3>Additional Information</h3>
<ul>
<li><strong>Kamailio Version</strong> - output of <code>kamailio -v</code></li>
</ul>
<pre><code>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
</code></pre>
<ul>
<li><strong>Operating System</strong>:</li>
</ul>
<pre><code>My OS is
Distributor ID: Ubuntu
Description: Ubuntu 14.04.5 LTS
Release: 14.04
Codename: trusty
</code></pre>
<p style="font-size:small;-webkit-text-size-adjust:none;color:#666;">—<br />You are receiving this because you are subscribed to this thread.<br />Reply to this email directly, <a href="https://github.com/kamailio/kamailio/issues/1975?email_source=notifications&email_token=ABO7UZMIDVBM4OCHMEQALHDPZI3U7A5CNFSM4HVVORRKYY3PNVWWK3TUL52HS4DFUVEXG43VMWVGG33NNVSW45C7NFSM4GYHDJZQ">view it on GitHub</a>, or <a href="https://github.com/notifications/unsubscribe-auth/ABO7UZOR534J2OWSGYLB4HDPZI3U7ANCNFSM4HVVORRA">mute the thread</a>.<img src="https://github.com/notifications/beacon/ABO7UZNE5PXFWNOECE7SWALPZI3U7A5CNFSM4HVVORRKYY3PNVWWK3TUL52HS4DFUVEXG43VMWVGG33NNVSW45C7NFSM4GYHDJZQ.gif" height="1" width="1" alt="" /></p>
<script type="application/ld+json">[
{
"@context": "http://schema.org",
"@type": "EmailMessage",
"potentialAction": {
"@type": "ViewAction",
"target": "https://github.com/kamailio/kamailio/issues/1975?email_source=notifications\u0026email_token=ABO7UZMIDVBM4OCHMEQALHDPZI3U7A5CNFSM4HVVORRKYY3PNVWWK3TUL52HS4DFUVEXG43VMWVGG33NNVSW45C7NFSM4GYHDJZQ",
"url": "https://github.com/kamailio/kamailio/issues/1975?email_source=notifications\u0026email_token=ABO7UZMIDVBM4OCHMEQALHDPZI3U7A5CNFSM4HVVORRKYY3PNVWWK3TUL52HS4DFUVEXG43VMWVGG33NNVSW45C7NFSM4GYHDJZQ",
"name": "View Issue"
},
"description": "View this Issue on GitHub",
"publisher": {
"@type": "Organization",
"name": "GitHub",
"url": "https://github.com"
}
}
]</script>