7 Jun
2019
7 Jun
'19
3:43 p.m.
[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