<html>
<head>
<meta http-equiv="Content-Type" content="text/html; charset=UTF-8">
</head>
<body>
<p>Hello,</p>
<p>I pushed a patch to master to print a debug message when the
socket is set on double rr. Can you retest and send again all the
debug messages for a misrouted BYE? If the sockets is set
correctly, then will have to look at the tcp conection lookup.</p>
<p>Cheers,<br>
Daniel<br>
</p>
<div class="moz-cite-prefix">On 22.11.19 19:25, Joel Serrano wrote:<br>
</div>
<blockquote type="cite"
cite="mid:CAMtXxQmHmEjYPPcWojDcqyFaE-AACEtoLBmhfL9vArSDfZXXww@mail.gmail.com">
<meta http-equiv="content-type" content="text/html; charset=UTF-8">
<div dir="ltr">Hi Daniel,
<div><br>
</div>
<div>I have advertise as:</div>
<div><br>
</div>
<div>listen=tcp:<a href="http://10.116.15.237:443"
moz-do-not-send="true">10.116.15.237:443</a> advertise <a
href="http://sbc01.stg.gii.me:443" moz-do-not-send="true">sbc01.stg.gii.me:443</a><br>
</div>
<div><br>
</div>
<div>(normally it would be tls, I switched to tcp so I could get
unencrypted traffic in tcpdump for you)</div>
<div><br>
</div>
<div>Record-route is done as:</div>
<div><br>
</div>
<div> # Dispatch requests<br>
if (is_method("INVITE")) {<br>
$avp(caller_conid) = $conid;<br>
record_route();<br>
route(DISPATCH);<br>
exit;<br>
}<br>
</div>
<div><br>
</div>
<div>(route DISPATCH basically does dispatcher lookup and
t_relay)</div>
<div><br>
</div>
<div>And this is the log for the BYE that doesn't work:</div>
<div><br>
</div>
<div>"message":" DEBUG: <core> [core\/udp_server.c:498]:
udp_rcv_loop(): received on udp socket: (106\/100\/907) [[BYE
<a class="moz-txt-link-freetext" href="sip:linphone@104.175.176.242:43750;alias=130.211.3.12~53883~2;transport=tcp">sip:linphone@104.175.176.242:43750;alias=130.211.3.12~53883~2;transport=tcp</a>
SIP\/2.0 0D 0A Via: SIP\/2.]]"}<br>
"message":" DEBUG: <core>
[core\/parser\/msg_parser.c:610]: parse_msg(): SIP Request:"}<br>
"message":" DEBUG: <core>
[core\/parser\/msg_parser.c:612]: parse_msg(): method:
<BYE>"}<br>
"message":" DEBUG: <core>
[core\/parser\/msg_parser.c:614]: parse_msg(): uri:
<a class="moz-txt-link-rfc2396E" href="sip:linphone@104.175.176.242:43750;alias=130.211.3.12~53883~2;transport=tcp"><sip:linphone@104.175.176.242:43750;alias=130.211.3.12~53883~2;transport=tcp></a>"}<br>
"message":" DEBUG: <core>
[core\/parser\/msg_parser.c:616]: parse_msg(): version:
<SIP\/2.0>"}<br>
"message":" DEBUG: <core>
[core\/parser\/parse_via.c:1303]: parse_via_param(): Found
param type 232, <branch> =
<z9hG4bK4eda.30b29b519ea0cbd688ceb8071e271f7d.0>;
state=16"}<br>
"message":" DEBUG: <core>
[core\/parser\/parse_via.c:2639]: parse_via(): end of header
reached, state=5"}<br>
"message":" DEBUG: <core>
[core\/parser\/msg_parser.c:498]: parse_headers(): Via found,
flags=2"}<br>
"message":" DEBUG: <core>
[core\/parser\/msg_parser.c:500]: parse_headers(): this is the
first via"}<br>
"message":" DEBUG: <core>
[core\/parser\/parse_via.c:1303]: parse_via_param(): Found
param type 234, <received> = <35.226.32.33>;
state=6"}<br>
"message":" DEBUG: <core>
[core\/parser\/parse_via.c:1303]: parse_via_param(): Found
param type 235, <rport> = <6061>; state=6"}<br>
"message":" DEBUG: <core>
[core\/parser\/parse_via.c:1303]: parse_via_param(): Found
param type 232, <branch> = <z9hG4bKy0gFgvHcajHtm>;
state=16"}<br>
"message":" DEBUG: <core>
[core\/parser\/parse_via.c:2639]: parse_via(): end of header
reached, state=5"}<br>
"message":" DEBUG: <core>
[core\/parser\/msg_parser.c:498]: parse_headers(): Via found,
flags=78"}<br>
"message":" DEBUG: <core>
[core\/parser\/msg_parser.c:511]: parse_headers(): this is the
second via"}<br>
"message":" DEBUG: <core>
[core\/parser\/parse_addr_spec.c:185]: parse_to_param(): add
param: tag=DU0ehPULu"}<br>
"message":" DEBUG: <core>
[core\/parser\/parse_addr_spec.c:864]: parse_addr_spec(): end
of header reached, state=29"}<br>
"message":" DEBUG: <core>
[core\/parser\/msg_parser.c:171]: get_hdr_field(): <To>
[82]; uri=[<a
href="mailto:sip%3A8bd2a0aba14541789bb7269800646458@app.nextplus.me"
moz-do-not-send="true">sip:8bd2a0aba14541789bb7269800646458@app.nextplus.me</a>]"}<br>
"message":" DEBUG: <core>
[core\/parser\/msg_parser.c:174]: get_hdr_field(): to body
[\"Joel Test\" <<a
href="mailto:sip%3A8bd2a0aba14541789bb7269800646458@app.nextplus.me"
moz-do-not-send="true">sip:8bd2a0aba14541789bb7269800646458@app.nextplus.me</a>>],
to tag [DU0ehPULu]"}<br>
"message":" DEBUG: <core>
[core\/parser\/msg_parser.c:152]: get_hdr_field(): cseq
<CSeq>: <12626897> <BYE>"}<br>
"message":" DEBUG: <core> [core\/receive.c:320]:
receive_msg(): --- received sip message - request - call-id:
[nsWZzKWRld] - cseq: [12626897 BYE]"}<br>
"message":" DEBUG: <core>
[core\/parser\/msg_parser.c:185]: get_hdr_field():
content_length=0"}<br>
"message":" DEBUG: <core>
[core\/parser\/msg_parser.c:89]: get_hdr_field(): found end of
header"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/receive.c:380]: receive_msg(): preparing to run routing
scripts..."}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/socket_info.c:628]: grep_sock_info(): checking if
host==us: 12==13 && [198.1.54.228] ==
[10.116.15.237]"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/socket_info.c:646]: grep_sock_info(): checking
advertise if host==us: 12==12 && [198.1.54.228] ==
[34.70.182.24]"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/socket_info.c:628]: grep_sock_info(): checking if
host==us: 12==13 && [198.1.54.228] ==
[10.116.15.237]"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/socket_info.c:628]: grep_sock_info(): checking if
host==us: 12==13 && [198.1.54.228] ==
[10.116.15.237]"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/socket_info.c:646]: grep_sock_info(): checking
advertise if host==us: 12==16 && [198.1.54.228] == [<a
href="http://sbc01.stg.gii.me" moz-do-not-send="true">sbc01.stg.gii.me</a>]"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/socket_info.c:628]: grep_sock_info(): checking if
host==us: 12==13 && [198.1.54.228] ==
[10.116.15.237]"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/forward.c:413]: check_self(): host != me"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} maxfwd
[mf_funcs.c:74]: is_maxfwd_present(): value = 69 "}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} sanity
[sanity.c:247]: check_ruri_sip_version():
check_ruri_sip_version entered"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} sanity
[sanity.c:270]: check_ruri_sip_version():
check_ruri_sip_version passed"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} sanity
[sanity.c:277]: check_ruri_scheme(): check_ruri_scheme
entered"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} sanity
[sanity.c:297]: check_ruri_scheme(): check_ruri_scheme
passed"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} sanity
[sanity.c:305]: check_required_headers():
check_required_headers entered"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} sanity
[sanity.c:313]: check_required_headers():
check_required_headers passed"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} sanity
[sanity.c:479]: check_cseq_method(): check_cseq_method
entered"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} sanity
[sanity.c:512]: check_cseq_method(): check_cseq_method
passed"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} sanity
[sanity.c:521]: check_cseq_value(): check_cseq_value entered"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} sanity
[sanity.c:549]: check_cseq_value(): check_cseq_value passed"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} sanity
[sanity.c:558]: check_cl(): check_cl entered"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} sanity
[sanity.c:583]: check_cl(): check_cl passed"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} sanity
[sanity.c:595]: check_expires_value(): check_expires_value
entered"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} sanity
[sanity.c:632]: check_expires_value(): no expires header
found"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} sanity
[sanity.c:732]: check_parse_uris(): check_parse_uris entered"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} sanity
[sanity.c:736]: check_parse_uris(): parsing ruri"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} sanity
[sanity.c:750]: check_parse_uris(): looking up From header"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} sanity
[sanity.c:764]: check_parse_uris(): parsing From header"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/parser\/parse_addr_spec.c:185]: parse_to_param(): add
param: tag=QZQSQQegvc5Zr"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/parser\/parse_addr_spec.c:864]: parse_addr_spec(): end
of header reached, state=29"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} sanity
[sanity.c:790]: check_parse_uris(): parsing From URI"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} sanity
[sanity.c:808]: check_parse_uris(): looking up To header"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} sanity
[sanity.c:830]: check_parse_uris(): check_parse_uris():
parsing To URI"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} sanity
[sanity.c:875]: check_parse_uris(): check_parse_uris passed"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} sanity
[sanity_mod.c:254]: w_sanity_check(): sanity checks result:
1"}<br>
"message":" NOTICE: {1 12626897 BYE nsWZzKWRld}
<script>: JOEL TEST New request - M=BYE UAC-IP=<a
href="http://198.1.54.228:5060" moz-do-not-send="true">198.1.54.228:5060</a>
LB-IP=<null>:<null> CONID=<null>
TCP-CONID=<null> UA='FS textPlus Voice' ID=nsWZzKWRld"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/msg_translator.c:161]: check_via_address():
(198.1.54.228, 198.1.54.228, 0)"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} siputils
[checks.c:123]: has_totag(): totag found"}<br>
"message":" NOTICE: {1 12626897 BYE nsWZzKWRld}
<script>: In-dialog request from COPS - M=BYE
R=<a class="moz-txt-link-freetext" href="sip:linphone@104.175.176.242:43750;alias=130.211.3.12~53883~2;transport=tcp">sip:linphone@104.175.176.242:43750;alias=130.211.3.12~53883~2;transport=tcp</a>
ID=nsWZzKWRld"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} rr
[loose.c:90]: is_preloaded(): is_preloaded: No"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/socket_info.c:628]: grep_sock_info(): checking if
host==us: 15==13 && [104.175.176.242] ==
[10.116.15.237]"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/socket_info.c:635]: grep_sock_info(): checking if port
5070 (advertise 5070) matches port 43750"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/socket_info.c:628]: grep_sock_info(): checking if
host==us: 15==13 && [104.175.176.242] ==
[10.116.15.237]"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/socket_info.c:635]: grep_sock_info(): checking if port
5080 (advertise 0) matches port 43750"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/socket_info.c:628]: grep_sock_info(): checking if
host==us: 15==13 && [104.175.176.242] ==
[10.116.15.237]"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/socket_info.c:635]: grep_sock_info(): checking if port
443 (advertise 443) matches port 43750"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/socket_info.c:628]: grep_sock_info(): checking if
host==us: 15==13 && [104.175.176.242] ==
[10.116.15.237]"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/socket_info.c:635]: grep_sock_info(): checking if port
80 (advertise 0) matches port 43750"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/forward.c:413]: check_self(): host != me"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/socket_info.c:628]: grep_sock_info(): checking if
host==us: 12==13 && [34.70.182.24] ==
[10.116.15.237]"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/socket_info.c:635]: grep_sock_info(): checking if port
5070 (advertise 5070) matches port 5070"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/socket_info.c:646]: grep_sock_info(): checking
advertise if host==us: 12==12 && [34.70.182.24] ==
[34.70.182.24]"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} rr
[loose.c:811]: after_loose(): Topmost route URI:
'<a class="moz-txt-link-freetext" href="sip:34.70.182.24:5070;r2=on;lr=on;ftag=DU0ehPULu;did=bfc.e45;nat=yes">sip:34.70.182.24:5070;r2=on;lr=on;ftag=DU0ehPULu;did=bfc.e45;nat=yes</a>'
is me"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/socket_info.c:628]: grep_sock_info(): checking if
host==us: 16==13 && [<a href="http://sbc01.stg.gii.me"
moz-do-not-send="true">sbc01.stg.gii.me</a>] ==
[10.116.15.237]"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/socket_info.c:635]: grep_sock_info(): checking if port
443 (advertise 443) matches port 443"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/socket_info.c:646]: grep_sock_info(): checking
advertise if host==us: 16==16 && [<a
href="http://sbc01.stg.gii.me" moz-do-not-send="true">sbc01.stg.gii.me</a>]
== [<a href="http://sbc01.stg.gii.me" moz-do-not-send="true">sbc01.stg.gii.me</a>]"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/parser\/msg_parser.c:89]: get_hdr_field(): found end of
header"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} rr
[loose.c:181]: find_next_route(): No next Route HF found"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} rr
[loose.c:875]: after_loose(): no next URI found"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} rr
[rr_cb.c:94]: run_rr_callbacks(): callback id 0 entered with
<r2=on;lr=on;ftag=DU0ehPULu;did=bfc.e45;nat=yes>"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} dialog
[dlg_handlers.c:1306]: dlg_onroute(): route param is 'bfc.e45'
(len=7)"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} dialog
[dlg_hash.c:784]: dlg_lookup(): ref dlg 0x7f56979d4660 with 1
-> 3"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} dialog
[dlg_hash.c:786]: dlg_lookup(): dialog id=1358 found on entry
3323"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} dialog
[dlg_profile.c:536]: set_current_dialog(): setting current
dialog [3323:1358]"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} dialog
[dlg_hash.c:1228]: next_state_dlg(): dialog 0x7f56979d4660
changed from state 4 to state 5, due event 7 (ref 3)"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} dialog
[dlg_hash.c:1009]: dlg_ref_helper(): ref op on 0x7f56979d4660
with 1 from dlg_handlers.c:1430"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} dialog
[dlg_hash.c:1013]: dlg_ref_helper(): ref dlg 0x7f56979d4660
with 1 -> 4"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} dialog
[dlg_handlers.c:1441]: dlg_onroute(): BYE successfully
processed"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} dialog
[dlg_hash.c:1029]: dlg_unref_helper(): unref op on
0x7f56979d4660 with 2 from dlg_handlers.c:1465"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} dialog
[dlg_hash.c:1033]: dlg_unref_helper(): unref dlg
0x7f56979d4660 with 2 -> 2"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} dialog
[dlg_hash.c:1029]: dlg_unref_helper(): unref op on
0x7f56979d4660 with 1 from dlg_hash.c:1047"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} dialog
[dlg_hash.c:1033]: dlg_unref_helper(): unref dlg
0x7f56979d4660 with 1 -> 1"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} nathelper
[nathelper.c:1144]: handle_ruri_alias(): setting dst_uri to
<a class="moz-txt-link-rfc2396E" href="sip:130.211.3.12:53883;transport=tcp"><sip:130.211.3.12:53883;transport=tcp></a>"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} nathelper
[nathelper.c:1166]: handle_ruri_alias(): rewriting r-uri to
<a class="moz-txt-link-rfc2396E" href="sip:linphone@104.175.176.242:43750;transport=tcp"><sip:linphone@104.175.176.242:43750;transport=tcp></a>"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} tm
[t_lookup.c:1328]: t_newtran(): msg (0x7f569f9211e0)
id=394\/10865 global id=393\/10865 T
start=0xffffffffffffffff"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} tm
[t_lookup.c:497]: t_lookup_request(): start searching:
hash=44516, isACK=0"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} tm
[t_lookup.c:455]: matching_3261(): RFC3261 transaction
matching failed - via branch
[z9hG4bK4eda.30b29b519ea0cbd688ceb8071e271f7d.0]"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} tm
[t_lookup.c:675]: t_lookup_request(): no transaction found"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} tm
[t_hooks.c:336]: run_reqin_callbacks_internal():
trans=0x7f56979d6558, callback type 1, id 0 entered"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/crypto\/md5utils.c:67]: MD5StringArray(): MD5
calculated: 7fe00a28920a3325330971908f8c5b0e"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} siputils
[checks.c:123]: has_totag(): totag found"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} rr
[loose.c:1095]: check_route_param(): route params checking
against [;r2=on;lr=on;ftag=DU0ehPULu;did=bfc.e45;nat=yes]
(orig: [r2=on;lr=on;ftag=DU0ehPULu;did=bfc.e45;nat=yes])"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} rr
[loose.c:1101]: check_route_param(): params are
<;r2=on;lr=on;ftag=DU0ehPULu;did=bfc.e45;nat=yes>"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} siputils
[checks.c:123]: has_totag(): totag found"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/msg_translator.c:161]: check_via_address():
(198.1.54.228, 198.1.54.228, 0)"}<br>
"message":" ERROR: {1 12626897 BYE nsWZzKWRld} tm
[..\/..\/core\/forward.h:261]: msg_send_buffer(): tcp_send
failed"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} tm
[t_fwd.c:1537]: t_send_branch(): send to <a
href="http://130.211.3.12:53883" moz-do-not-send="true">130.211.3.12:53883</a>
(2) failed"}<br>
"message":" WARNING: {1 12626897 BYE nsWZzKWRld} tm
[t_fwd.c:1557]: t_send_branch(): sending request on branch 0
failed"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} tm
[t_funcs.c:336]: t_relay_to(): t_forward_nonack returned error
-1 (-477)"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} tm
[t_funcs.c:354]: t_relay_to(): -477 error reply generation
delayed "}<br>
"message":" ERROR: {1 12626897 BYE nsWZzKWRld} <script>:
Could not forward request - M=BYE
R=<a class="moz-txt-link-freetext" href="sip:linphone@104.175.176.242:43750;transport=tcp">sip:linphone@104.175.176.242:43750;transport=tcp</a>
ID=nsWZzKWRld"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/msg_translator.c:161]: check_via_address():
(198.1.54.228, 198.1.54.228, 0)"}<br>
"message":" ERROR: {1 12626897 BYE nsWZzKWRld} sl
[sl_funcs.c:392]: sl_reply_error(): stateless error reply
used: I'm terribly sorry, server error occurred (1\/SL)"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/receive.c:438]: receive_msg(): request-route executed
in: 1051 usec"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} dialog
[dlg_hash.c:784]: dlg_lookup(): ref dlg 0x7f56979d4660 with 1
-> 2"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} dialog
[dlg_hash.c:786]: dlg_lookup(): dialog id=1358 found on entry
3323"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} dialog
[dlg_hash.c:1029]: dlg_unref_helper(): unref op on
0x7f56979d4660 with 1 from dlg_hash.c:1047"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} dialog
[dlg_hash.c:1033]: dlg_unref_helper(): unref dlg
0x7f56979d4660 with 1 -> 1"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} tm
[t_lookup.c:1493]: t_unref(): delayed error reply
generation(-477)"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/msg_translator.c:161]: check_via_address():
(198.1.54.228, 198.1.54.228, 0)"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} tm
[t_reply.c:1667]: cleanup_uac_timers(): RETR\/FR timers
reset"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} tm
[t_hooks.c:252]: run_trans_callbacks_internal(): DBG:
trans=0x7f56979d6558, callback type 512, id 0 entered"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} dialog
[dlg_hash.c:784]: dlg_lookup(): ref dlg 0x7f56979d4660 with 1
-> 2"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} dialog
[dlg_hash.c:786]: dlg_lookup(): dialog id=1358 found on entry
3323"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} dialog
[dlg_hash.c:1029]: dlg_unref_helper(): unref op on
0x7f56979d4660 with 1 from dlg_hash.c:1047"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} dialog
[dlg_hash.c:1033]: dlg_unref_helper(): unref dlg
0x7f56979d4660 with 1 -> 1"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} tm
[t_reply.c:610]: _reply_light(): reply sent out.
buf=0x7f569f91ed70: SIP\/2.0 477 Unfortun...,
shmem=0x7f56979d1520: SIP\/2.0 477 Unfortun"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} tm
[t_reply.c:621]: _reply_light(): finished"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/usr_avp.c:636]: destroy_avp_list(): destroying list
(nil)"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/usr_avp.c:636]: destroy_avp_list(): destroying list
(nil)"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/usr_avp.c:636]: destroy_avp_list(): destroying list
(nil)"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/usr_avp.c:636]: destroy_avp_list(): destroying list
(nil)"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/usr_avp.c:636]: destroy_avp_list(): destroying list
(nil)"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/usr_avp.c:636]: destroy_avp_list(): destroying list
(nil)"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/xavp.c:517]: xavp_destroy_list(): destroying xavp list
(nil)"}<br>
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/receive.c:529]: receive_msg(): cleaning up"}<br>
"message":" DEBUG: <core> [core\/io_wait.h:599]:
io_watch_del(): DBG: io_watch_del (0x562f315c32a0, 6, -1,
0x10) fd_no=3 called"}<br>
"message":" DEBUG: <core> [core\/tcp_read.c:1680]:
release_tcpconn(): releasing con 0x7f56979e0ad8, state 1,
fd=6, id=6 ([104.175.176.242]:43750 ->
[104.175.176.242]:443)"}<br>
"message":" DEBUG: <core> [core\/tcp_read.c:1684]:
release_tcpconn(): extra_data (nil)"}<br>
"message":" DEBUG: <core> [core\/io_wait.h:599]:
io_watch_del(): DBG: io_watch_del (0x562f315c32a0, 9, -1,
0x10) fd_no=2 called"}<br>
"message":" DEBUG: <core> [core\/tcp_read.c:1680]:
release_tcpconn(): releasing con 0x7f56979f0e78, state 1,
fd=9, id=7 ([104.175.176.242]:44043 ->
[104.175.176.242]:443)"}<br>
"message":" DEBUG: <core> [core\/tcp_read.c:1684]:
release_tcpconn(): extra_data (nil)"}<br>
"message":" DEBUG: <core> [core\/tcp_main.c:3625]:
handle_tcp_child(): reader response= 7f56979e0ad8, 1 from 0 "}<br>
"message":" DEBUG: <core> [core\/io_wait.h:377]:
io_watch_add(): DBG: io_watch_add(0x562f31567820, 24, 2,
0x7f56979e0ad8), fd_no=15"}<br>
"message":" DEBUG: <core> [core\/tcp_main.c:3752]:
handle_tcp_child(): CONN_RELEASE 0x7f56979e0ad8 refcnt= 1"}<br>
"message":" DEBUG: <core> [core\/tcp_main.c:3625]:
handle_tcp_child(): reader response= 7f56979f0e78, 1 from 0 "}<br>
"message":" DEBUG: <core> [core\/io_wait.h:377]:
io_watch_add(): DBG: io_watch_add(0x562f31567820, 26, 2,
0x7f56979f0e78), fd_no=16"}<br>
"message":" DEBUG: <core> [core\/tcp_main.c:3752]:
handle_tcp_child(): CONN_RELEASE 0x7f56979f0e78 refcnt= 1"}<br>
</div>
<div><br>
</div>
<div>Not sure what I can be doing wrong!</div>
<div><br>
</div>
<div>IP information to help you understand the packet capture:</div>
<div><br>
</div>
<div>UAC: 104.175.176.242</div>
<div>LB (UAC side): <a href="http://35.186.235.62:443"
moz-do-not-send="true">35.186.235.62:443</a> or <a
href="http://sbc01stg.gii.me:443" moz-do-not-send="true">sbc01stg.gii.me:443</a></div>
<div>LB (Kam side can be many, for this example it's <a
href="http://130.211.3.12:53883" moz-do-not-send="true">130.211.3.12:53883</a>)</div>
<div>PSTN GW: 198.1.54.228</div>
<div><br>
</div>
<div>Thanks for your help on this.</div>
<div><br>
</div>
<div>Best, </div>
<div>Joel.</div>
</div>
<br>
<div class="gmail_quote">
<div dir="ltr" class="gmail_attr">On Fri, Nov 22, 2019 at 1:02
AM Daniel-Constantin Mierla <<a
href="mailto:miconda@gmail.com" moz-do-not-send="true">miconda@gmail.com</a>>
wrote:<br>
</div>
<blockquote class="gmail_quote" style="margin:0px 0px 0px
0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex">
<div>
<p>Hello,</p>
<p>how do you set the record-route? Do you have advertised
address for the socket receiving TCP/HAproxy loadbalancer
connections?</p>
<p>Can you give all the debug messages when processing the
BYE that doesn't go through?</p>
<p>Cheers,<br>
Daniel<br>
</p>
<div>On 21.11.19 19:44, Joel Serrano wrote:<br>
</div>
<blockquote type="cite">
<div dir="ltr">Hi Daniel,
<div><br>
</div>
<div>I sent you (privately) 2 pcaps. Please let me know
if you need anything else.</div>
<div><br>
</div>
<div>My current TCP params are:</div>
<div><br>
</div>
<div>disable_tcp=no<br>
tcp_children=1<br>
tcp_max_connections=12288<br>
tcp_rd_buf_size=65536<br>
tcp_conn_wq_max=131072<br>
tcp_keepalive=yes<br>
tcp_crlf_ping=yes<br>
tcp_keepcnt=3<br>
tcp_keepidle=30<br>
tcp_keepintvl=30<br>
tcp_connection_lifetime=3610<br>
tcp_accept_no_cl=yes<br>
tcp_accept_haproxy=yes<br>
tcp_no_connect=yes<br>
</div>
<div><br>
</div>
<div>Thanks, </div>
<div>Joel.</div>
</div>
<br>
<div class="gmail_quote">
<div dir="ltr" class="gmail_attr">On Thu, Nov 21, 2019
at 7:50 AM Joel Serrano <<a
href="mailto:joel@textplus.com" target="_blank"
moz-do-not-send="true">joel@textplus.com</a>>
wrote:<br>
</div>
<blockquote class="gmail_quote" style="margin:0px 0px
0px 0.8ex;border-left:1px solid
rgb(204,204,204);padding-left:1ex">
<div>
<div dir="auto">I don’t, but I’ll repeat the test
with tcpdump active! I’ll report back shortly</div>
</div>
<div><br>
<div class="gmail_quote">
<div dir="ltr" class="gmail_attr">On Thu, Nov 21,
2019 at 03:50 Daniel-Constantin Mierla <<a
href="mailto:miconda@gmail.com"
target="_blank" moz-do-not-send="true">miconda@gmail.com</a>>
wrote:<br>
</div>
<blockquote class="gmail_quote" style="margin:0px
0px 0px 0.8ex;border-left:1px solid
rgb(204,204,204);padding-left:1ex">
<div>
<p>Hello,</p>
<p>do you have the pcap with the sip traffic
for this case?</p>
<p>Cheers,<br>
Daniel<br>
</p>
</div>
<div>
<div>On 20.11.19 19:45, Joel Serrano wrote:<br>
</div>
<blockquote type="cite">
<div dir="ltr">Hello,
<div><br>
</div>
<div>I added to the config file:</div>
<div><br>
</div>
<div>tcp_no_connect=yes<br>
</div>
<div><br>
</div>
<div>And with that param, the same test
results in a different behavior, but
still not working:</div>
<div><br>
</div>
<div>"message":" DEBUG: {1 12583750 BYE
RVXZVMHKop} <core>
[core\/msg_translator.c:161]:
check_via_address(): (198.1.54.228,
198.1.54.228, 0)"}<br>
<font color="#ff0000">"message":" ERROR:
{1 12583750 BYE RVXZVMHKop} tm
[..\/..\/core\/forward.h:292]:
msg_send_buffer(): tcp_send failed"}<br>
"message":" DEBUG: {1 12583750 BYE
RVXZVMHKop} tm [t_fwd.c:1537]:
t_send_branch(): send to <a
href="http://35.191.9.20:56470"
target="_blank"
moz-do-not-send="true">35.191.9.20:56470</a>
(3) failed"}</font><br>
"message":" WARNING: {1 12583750 BYE
RVXZVMHKop} tm [t_fwd.c:1557]:
t_send_branch(): sending request on
branch 0 failed"}<br>
"message":" DEBUG: {1 12583750 BYE
RVXZVMHKop} tm [t_funcs.c:336]:
t_relay_to(): t_forward_nonack returned
error -1 (-477)"}<br>
"message":" DEBUG: {1 12583750 BYE
RVXZVMHKop} tm [t_funcs.c:354]:
t_relay_to(): -477 error reply
generation delayed "}<br>
</div>
<div><br>
</div>
<div>Although, netstats says the
connection is active:</div>
<div><br>
</div>
<div>root@sbc-gslb-test-1:~# netstat
-putan | grep 56470<br>
tcp 0 0 <a
href="http://10.116.15.237:443"
target="_blank" moz-do-not-send="true">10.116.15.237:443</a>
<a
href="http://35.191.9.20:56470"
target="_blank" moz-do-not-send="true">35.191.9.20:56470</a>
ESTABLISHED 3920/kamailio<br>
root@sbc-gslb-test-1:~#<br>
</div>
<div><br>
</div>
<div><br>
</div>
<div>Anyone?</div>
</div>
<br>
<div class="gmail_quote">
<div dir="ltr" class="gmail_attr">On Wed,
Nov 20, 2019 at 9:26 AM Joel Serrano
<<a href="mailto:joel@textplus.com"
target="_blank" moz-do-not-send="true">joel@textplus.com</a>>
wrote:<br>
</div>
<blockquote class="gmail_quote"
style="margin:0px 0px 0px
0.8ex;border-left:1px solid
rgb(204,204,204);padding-left:1ex">
<div dir="ltr">Bumping this thread up!
<div><br>
</div>
<div>I did some more tests trying to
narrow down the problem and this is
what I found...:</div>
<div><br>
</div>
<div>On the INVITE, I add the TCP
connection information I want to
save (for later reuse). Snippets:</div>
<div><br>
</div>
<div>...(found this in
the misc/examples/pkg/sip-router-oob.cfg,
but I haven't noticed any changes to
the headers or anything)...</div>
<div><br>
</div>
<div> # Force response to received
connection<br>
force_rport();<br>
if (proto==TCP || proto == TLS)
{<br>
force_tcp_alias();<br>
xlog("L_NOTICE",
"force_tcp_alias() done");<br>
}<br>
</div>
<div>...</div>
<div><br>
</div>
<div>...(I also have this)...</div>
<div><br>
</div>
<div> if (is_first_hop()) {<br>
xlog("L_NOTICE", "Adding LB
info to contact - M=$rm ID=$ci\n");<br>
add_contact_alias("$tcp(c_si)",
"$tcp(c_sp)", "tls");<br>
}<br>
</div>
<div>...</div>
<div><br>
</div>
<div>Which effectively makes the
contact look like:</div>
<div><br>
</div>
<div><a moz-do-not-send="true"><sip:linphone@104.175.176.242:50312;alias=35.191.9.21~50705~3;transport=tls></a><br>
</div>
<div><br>
</div>
<div>..180..</div>
<div>..200 OK..</div>
<div>..ACK..</div>
<div><br>
</div>
<div>Then, callee ends the call (so
the BYE comes from callee to
caller), when I run
handle_ruri_alias() I see in the
logs that the everything is handled
correctly:</div>
<div><br>
</div>
<div>"message":" DEBUG: {1 12543376
BYE QQy-qagkcB} nathelper
[nathelper.c:1144]:
handle_ruri_alias(): setting dst_uri
to <a moz-do-not-send="true"><sip:35.191.9.21:50705;transport=tls></a>"}<br>
"message":" DEBUG: {1 12543376 BYE
QQy-qagkcB} nathelper
[nathelper.c:1166]:
handle_ruri_alias(): rewriting r-uri
to <a moz-do-not-send="true"><sip:linphone@104.175.176.242:50312;transport=tls></a>"}</div>
<div><br>
</div>
<div>But then, Kamalio won't reuse the
existing TCP connection and tries to
create a new one:</div>
<div><br>
"message":" DEBUG: {1 12543376 BYE
QQy-qagkcB} tm [t_lookup.c:1328]:
t_newtran(): msg (0x7f85883b14c8)
id=27\/1974 global id=25\/1974 T
start=0xffffffffffffffff"}<br>
"message":" DEBUG: {1 12543376 BYE
QQy-qagkcB} tm [t_lookup.c:497]:
t_lookup_request(): start searching:
hash=63128, isACK=0"}<br>
"message":" DEBUG: {1 12543376 BYE
QQy-qagkcB} tm [t_lookup.c:455]:
matching_3261(): RFC3261 transaction
matching failed - via branch
[z9hG4bK896f.dc04734743b0f0997f39c4fff07c0fbb.0]"}<br>
"message":" DEBUG: {1 12543376 BYE
QQy-qagkcB} tm [t_lookup.c:675]:
t_lookup_request(): no transaction
found"}<br>
"message":" DEBUG: {1 12543376 BYE
QQy-qagkcB} tm [t_hooks.c:336]:
run_reqin_callbacks_internal():
trans=0x7f8583b17208, callback type
1, id 0 entered"}<br>
"message":" DEBUG: {1 12543376 BYE
QQy-qagkcB} <core>
[core\/crypto\/md5utils.c:67]:
MD5StringArray(): MD5 calculated:
71c229aff3c0b4f6e9e77c4990b74e5e"}<br>
"message":" DEBUG: {1 12543376 BYE
QQy-qagkcB} siputils [checks.c:123]:
has_totag(): totag found"}<br>
"message":" DEBUG: {1 12543376 BYE
QQy-qagkcB} rr [loose.c:1095]:
check_route_param(): route params
checking against
[;r2=on;lr=on;ftag=tAsjXhyIX;did=7d1.e6a2;nat=yes]
(orig:
[r2=on;lr=on;ftag=tAsjXhyIX;did=7d1.e6a2;nat=yes])"}<br>
"message":" DEBUG: {1 12543376 BYE
QQy-qagkcB} rr [loose.c:1101]:
check_route_param(): params are
<;r2=on;lr=on;ftag=tAsjXhyIX;did=7d1.e6a2;nat=yes>"}<br>
"message":" DEBUG: {1 12543376 BYE
QQy-qagkcB} siputils [checks.c:123]:
has_totag(): totag found"}<br>
"message":" DEBUG: {1 12543376 BYE
QQy-qagkcB} <core>
[core\/msg_translator.c:161]:
check_via_address(): (198.1.54.228,
198.1.54.228, 0)"}<br>
<font color="#ff0000">"message":"
DEBUG: {1 12543376 BYE QQy-qagkcB}
<core>
[core\/tcp_main.c:2060]:
tcp_send(): no open tcp connection
found, opening new one"}<br>
"message":" DEBUG: {1 12543376 BYE
QQy-qagkcB} <core>
[core\/ip_addr.c:229]: print_ip():
tcpconn_new: new tcp connection:
35.191.9.21"}<br>
"message":" DEBUG: {1 12543376 BYE
QQy-qagkcB} <core>
[core\/tcp_main.c:1242]:
tcpconn_new(): on port 50705, type
3"}</font><br>
"message":" DEBUG: {1 12543376 BYE
QQy-qagkcB} <core>
[core\/tcp_main.c:1561]:
tcpconn_add(): hashes: 337:3545:0,
3"}<br>
</div>
<div><br>
</div>
<div>Am I still missing anything?</div>
<div><br>
</div>
<div>Is this a bug and I should open a
GH issue?</div>
<div><br>
</div>
<div>Any suggestions/comments/ideas
are very welcome!</div>
<div><br>
</div>
<div>Thanks, </div>
<div>Joel.</div>
<div><br>
</div>
</div>
<br>
<div class="gmail_quote">
<div dir="ltr" class="gmail_attr">On
Fri, Nov 1, 2019 at 11:46 AM Joel
Serrano <<a
href="mailto:joel@textplus.com"
target="_blank"
moz-do-not-send="true">joel@textplus.com</a>>
wrote:<br>
</div>
<blockquote class="gmail_quote"
style="margin:0px 0px 0px
0.8ex;border-left:1px solid
rgb(204,204,204);padding-left:1ex">
<div dir="ltr">Hi Yuriy,
<div><br>
</div>
<div>Thanks for your suggestion,
I've tried
tcp_accept_aliases=yes in config
and I added force_tcp_alias() in
the request route, but I haven't
seen any changes.</div>
<div><br>
</div>
<div>All the VIA headers look
exactly the same, and I still
get this in the logs:</div>
<div><br>
</div>
<div>"message":" DEBUG: {1
11762916 BYE d2T9-YOxYk}
<core>
[core\/tcp_main.c:2060]:
tcp_send(): no open tcp
connection found, opening new
one"}<br>
</div>
<div><br>
</div>
<div><br>
</div>
<div>The docs say: </div>
<div><br>
</div>
<div>"f<span
style="color:rgb(51,51,51);font-family:Arial,sans-serif;font-size:14px">orce_tcp_alias(port)</span></div>
<p style="margin:0px 0px
1.4em;padding:0px;color:rgb(51,51,51);font-family:Arial,sans-serif;font-size:14px">adds
a tcp port alias for the current
connection (if tcp). Useful if
you want to send all the trafic
to port_alias through the same
connection this request came
from [it could help for firewall
or nat traversal]. With no
parameters adds the port from
the message via as the alias.
When the “aliased” connection is
closed (e.g. it's idle for too
much time), all the port aliases
are removed."</p>
<p style="margin:0px 0px
1.4em;padding:0px;color:rgb(51,51,51);font-family:Arial,sans-serif;font-size:14px">I
tried also using
force_tcp_alias(5353) as an
example, just to see if I find
"5353" added to any headers, but
no luck, it wasn't added
anywhere..</p>
<p style="margin:0px 0px
1.4em;padding:0px;color:rgb(51,51,51);font-family:Arial,sans-serif;font-size:14px"><br>
</p>
<p style="margin:0px 0px
1.4em;padding:0px;color:rgb(51,51,51);font-family:Arial,sans-serif;font-size:14px">Any
other suggestions? Am I missing
something?</p>
<p style="margin:0px 0px
1.4em;padding:0px;color:rgb(51,51,51);font-family:Arial,sans-serif;font-size:14px"><br>
</p>
<p style="margin:0px 0px
1.4em;padding:0px;color:rgb(51,51,51);font-family:Arial,sans-serif;font-size:14px">Thanks, </p>
<p style="margin:0px 0px
1.4em;padding:0px;color:rgb(51,51,51);font-family:Arial,sans-serif;font-size:14px">Joel.</p>
</div>
<br>
<div class="gmail_quote">
<div dir="ltr" class="gmail_attr">On
Thu, Oct 31, 2019 at 10:53 PM
Yuriy Gorlichenko <<a
href="mailto:ovoshlook@gmail.com"
target="_blank"
moz-do-not-send="true">ovoshlook@gmail.com</a>>
wrote:<br>
</div>
<blockquote class="gmail_quote"
style="margin:0px 0px 0px
0.8ex;border-left:1px solid
rgb(204,204,204);padding-left:1ex">
<div dir="auto">You have to use
<div dir="auto">tcp_accept_aliases=yes</div>
<div dir="auto">But this is
not enough as this param
will be triggered by
function</div>
<div dir="auto">force_tcp_alias()
you need to use in the route
for request ( for example
record_route or subroutes) </div>
<div dir="auto">It will add
param
paramname=<portnum> (I
Don't remember specific
name) </div>
<div dir="auto">to Via header
that will be used for all
dialog requests belongs one
being affected</div>
<div dir="auto"><br>
</div>
</div>
<br>
<div class="gmail_quote">
<div dir="ltr"
class="gmail_attr">On Fri, 1
Nov 2019, 00:52 Joel
Serrano, <<a
href="mailto:joel@textplus.com"
rel="noreferrer"
target="_blank"
moz-do-not-send="true">joel@textplus.com</a>>
wrote:<br>
</div>
<blockquote
class="gmail_quote"
style="margin:0px 0px 0px
0.8ex;border-left:1px solid
rgb(204,204,204);padding-left:1ex">
<div dir="ltr">Hello, <br>
<div><br>
</div>
<div>I'm setting up a
Kamailio instance behind
a TCP load balancer
(with proxy protocol and
NAT routing: meaning Kam
stays in the flow all
the time).</div>
<div><br>
</div>
<div>I've managed to get
working almost
everything we need for
our service, except for
one thing, and that is
for Kam to use existing
connections for
subsequent transactions:</div>
<div><br>
</div>
<div>Following this
example:</div>
<div><br>
</div>
<div>
<div><br>
</div>
<div>
<div><img
src="https://mail.google.com/mail/?ui=2&ik=4cb8059f98&attid=0.1&th=16e257fd109e4e49&view=fimg&rm=16e257fd109e4e49&sz=w1600-h1000&attbid=ANGjdJ-91VHFzKV4hniupoRVBXwam-q5S4OzAdN4gy3xbdsMj4mq4jMHzqZAiNWCoW81L4r2mg7JSPiju8xWuIJzzKXfQ4TM-pAK-XcezfHICxM9RjHRbirzKBr1mdM&disp=emb&realattid=ii_k2fbh1u00&zw"
alt="image.png"
moz-do-not-send="true"
width="542"
height="270"></div>
</div>
</div>
<div><br>
</div>
<div><br>
</div>
<div>EXT & INT
represent the external
and internal interface
of a LB between the UAC
and Kamailio, using TLS
on both legs and proxy
protocol.</div>
<div><br>
</div>
<div>Transaction 1:
INVITE, 100, 180, 183,
200 OK</div>
<div><br>
</div>
<div>UAC <a
href="http://1.1.1.1:1111"
rel="noreferrer
noreferrer"
target="_blank"
moz-do-not-send="true">1.1.1.1:1111</a>
-> <a
href="http://2.2.2.2:443"
rel="noreferrer
noreferrer"
target="_blank"
moz-do-not-send="true">2.2.2.2:443</a>
(EXT) <a
href="http://3.3.3.3:3333"
rel="noreferrer
noreferrer"
target="_blank"
moz-do-not-send="true">3.3.3.3:3333</a>
(INT) -> <a
href="http://7.7.7.7:5060"
rel="noreferrer
noreferrer"
target="_blank"
moz-do-not-send="true">7.7.7.7:5060</a>
(Kamailio) </div>
<div><br>
</div>
<div>Transaction 2: ACK</div>
<div><br>
</div>
<div>
<div>UAC <a
href="http://1.1.1.1:1112"
rel="noreferrer
noreferrer"
target="_blank"
moz-do-not-send="true">1.1.1.1:1112</a>
-> <a
href="http://2.2.2.2:443"
rel="noreferrer
noreferrer"
target="_blank"
moz-do-not-send="true">2.2.2.2:443</a>
(EXT) <a
href="http://4.4.4.4:4444"
rel="noreferrer
noreferrer"
target="_blank"
moz-do-not-send="true">4.4.4.4:4444</a>
(INT) -> <a
href="http://7.7.7.7:5060"
rel="noreferrer
noreferrer"
target="_blank"
moz-do-not-send="true">7.7.7.7:5060</a>
(Kamailio) </div>
</div>
<div><br>
</div>
<div>Transaction 3: BYE</div>
<div><br>
</div>
<div>Kam <a
href="http://7.7.7.7:5060"
rel="noreferrer
noreferrer"
target="_blank"
moz-do-not-send="true">7.7.7.7:5060</a>
-> <a
href="http://3.3.3.3:3333"
rel="noreferrer
noreferrer"
target="_blank"
moz-do-not-send="true">3.3.3.3:3333</a>
(INT) <a
href="http://2.2.2.2:443"
rel="noreferrer
noreferrer"
target="_blank"
moz-do-not-send="true">2.2.2.2:443</a>
(EXT) -> <a
href="http://1.1.1.1:1111"
rel="noreferrer
noreferrer"
target="_blank"
moz-do-not-send="true">1.1.1.1:1111</a>
UAC</div>
<div><br>
</div>
<div>
<div><br>
</div>
</div>
<div><br>
</div>
<div>My problem is with
Transaction 3. In this
case the BYE is
originated by the
callee, and Kam has to
send it to the caller.
As the TCP load balancer
is between Kam and the
UAC, Kam has to send it
to the LB so then the LB
can forward it back to
the UAC. This works well
for msgs that belong to
the same transaction
(INVITE, 100, 180, 183,
200 OK) but it fails
when they don't belong
to the same transaction.</div>
<div><br>
</div>
<div>Thanks to the newly
added $tcp(c_si) and
$tcp(c_sp) pseudovars, I
can save the internal
IP:Port of the LB, so I
can send stuff later to
it, my problem is that
Kam doesn't seem to
allow this?</div>
<div><br>
</div>
<div>On the original
INVITE, I use the
following to save where
I have to reach the UAC:</div>
<div><br>
</div>
<div>add_contact_alias("$tcp(c_si)",
"$tcp(c_sp)", "tls");<br>
</div>
<div><br>
</div>
<div>Then,
handle_ruri_alias() will
take care of setting $du
to the correct (internal
LB) IP:Port so I can
reach the UAC, this
works.</div>
<div><br>
</div>
<div>My problem is that
Kamailio doesn't
identify that there is a
valid existing TLS
connection still up
(from the INVITE), and
tries to create a new
one (and this obviously
doesn't gives all sorts
of problems).</div>
<div><br>
</div>
<div>So when I run
handle_ruri_alias(), and
$du is set to <a
href="http://3.3.3.3:3333"
rel="noreferrer
noreferrer"
target="_blank"
moz-do-not-send="true">3.3.3.3:3333</a>
(from the example
above), instead of using
the existing connection,
Kamailio tries to create
a new one.</div>
<div><br>
</div>
<div>I have a log
statement right before
with the result of
tcp_conid_state(1) (the
connid is 1 for this
connection) and the $rc
is 1 (Connection is OK),
but when I tell Kamailio
it has to use it I get
this in the logs:</div>
<div><br>
</div>
<div>DEBUG: {1 11726467
BYE gqR1qqNK8B}
<core>
[core\/tcp_main.c:2060]:
tcp_send(): no open tcp
connection found,
opening new one"}<br>
</div>
<div><br>
</div>
<div>And then the problems
begin...</div>
<div><br>
</div>
<div><br>
</div>
<div>I have tried playing
around with:</div>
<div><br>
</div>
<div>tcp_reuse_port<br>
</div>
<div>tcp_connection_match</div>
<div><br>
</div>
<div>But no luck..!</div>
<div><br>
</div>
<div>I also thought it
could be a problem of
the connection being
created on one worker,
and a different worker
handling BYE
transaction, so tested
with children=1 and
tcp_children=1, but
still same problem.</div>
<div><br>
</div>
<div>A more detailed log:</div>
<div><br>
</div>
<div>In blue my log
statement checking for
the status of conid "1",
in red Kam not being
able to find it,
although it exists (as
validated
by tcp_conid_state(),
and even in netstat I
can see the connection
established). In this
log, <a
href="http://35.191.0.66:60271"
rel="noreferrer
noreferrer"
target="_blank"
moz-do-not-send="true">35.191.0.66:60271</a>
would be the equivalent
of <a
href="http://3.3.3.3:3333"
rel="noreferrer
noreferrer"
target="_blank"
moz-do-not-send="true">3.3.3.3:3333</a>
and <a
href="http://104.175.176.242:28157"
rel="noreferrer
noreferrer"
target="_blank"
moz-do-not-send="true">104.175.176.242:28157</a>
would be <a
href="http://1.1.1.1:1111"
rel="noreferrer
noreferrer"
target="_blank"
moz-do-not-send="true">1.1.1.1:1111</a>
from the example above.</div>
<div><br>
</div>
<div>...<br>
<font color="#0000ff">"message":"
DEBUG: {1 11727734 BYE
5-LX4GdI9X}
<core>
[core\/tcp_main.c:1657]:
_tcpconn_find(): found
connection by id: 1"}<br>
"message":" NOTICE: {1
11727734 BYE
5-LX4GdI9X}
<script>: JOEL
TEST New request -
M=BYE TCP STATUS:1
ID=5-LX4GdI9X"}</font><br>
...<br>
"message":" DEBUG: {1
11727734 BYE 5-LX4GdI9X}
nathelper
[nathelper.c:1144]:
handle_ruri_alias():
setting dst_uri to <a
moz-do-not-send="true"><sip:35.191.0.66:60271;transport=tls></a>"}<br>
"message":" DEBUG: {1
11727734 BYE 5-LX4GdI9X}
nathelper
[nathelper.c:1166]:
handle_ruri_alias():
rewriting r-uri to <a
moz-do-not-send="true"><sip:linphone@104.175.176.242:28157;transport=tls></a>"}<br>
"message":" DEBUG: {1
11727734 BYE 5-LX4GdI9X}
tm [t_lookup.c:1328]:
t_newtran(): msg
(0x7f3c884259d0)
id=534\/18664 global
id=532\/18664 T
start=0xffffffffffffffff"}<br>
"message":" DEBUG: {1
11727734 BYE 5-LX4GdI9X}
tm [t_lookup.c:497]:
t_lookup_request():
start searching:
hash=63496, isACK=0"}<br>
"message":" DEBUG: {1
11727734 BYE 5-LX4GdI9X}
tm [t_lookup.c:455]:
matching_3261(): RFC3261
transaction matching
failed - via branch
[z9hG4bK808f.eee2444f92a02cb33e1b7a21f20bc6bb.0]"}<br>
"message":" DEBUG: {1
11727734 BYE 5-LX4GdI9X}
tm [t_lookup.c:675]:
t_lookup_request(): no
transaction found"}<br>
"message":" DEBUG: {1
11727734 BYE 5-LX4GdI9X}
tm [t_hooks.c:336]:
run_reqin_callbacks_internal():
trans=0x7f3c83b8c598,
callback type 1, id 0
entered"}<br>
"message":" DEBUG: {1
11727734 BYE 5-LX4GdI9X}
<core>
[core\/crypto\/md5utils.c:67]:
MD5StringArray(): MD5
calculated:
3071029feb05962b26b53a9664a14210"}<br>
"message":" DEBUG: {1
11727734 BYE 5-LX4GdI9X}
siputils [checks.c:123]:
has_totag(): totag
found"}<br>
"message":" DEBUG: {1
11727734 BYE 5-LX4GdI9X}
rr [loose.c:1095]:
check_route_param():
route params checking
against
[;r2=on;lr=on;ftag=Eb~TbdfTA;did=cab.01e2;nat=yes]
(orig:
[r2=on;lr=on;ftag=Eb~TbdfTA;did=cab.01e2;nat=yes])"}<br>
"message":" DEBUG: {1
11727734 BYE 5-LX4GdI9X}
rr [loose.c:1101]:
check_route_param():
params are
<;r2=on;lr=on;ftag=Eb~TbdfTA;did=cab.01e2;nat=yes>"}<br>
"message":" DEBUG: {1
11727734 BYE 5-LX4GdI9X}
siputils [checks.c:123]:
has_totag(): totag
found"}<br>
"message":" DEBUG: {1
11727734 BYE 5-LX4GdI9X}
<core>
[core\/msg_translator.c:161]:
check_via_address():
(198.1.54.228,
198.1.54.228, 0)"}<br>
<font color="#ff0000">"message":"
DEBUG: {1 11727734 BYE
5-LX4GdI9X}
<core>
[core\/tcp_main.c:2060]:
tcp_send(): no open
tcp connection found,
opening new one"}<br>
</font>"message":"
DEBUG: {1 11727734 BYE
5-LX4GdI9X} <core>
[core\/ip_addr.c:229]:
print_ip(): tcpconn_new:
new tcp connection:
35.191.0.66"}<br>
"message":" DEBUG: {1
11727734 BYE 5-LX4GdI9X}
<core>
[core\/tcp_main.c:1242]:
tcpconn_new(): on port
60271, type 3"}<br>
"message":" DEBUG: {1
11727734 BYE 5-LX4GdI9X}
<core>
[core\/tcp_main.c:1561]:
tcpconn_add(): hashes:
1446:2350:0, 5"}<br>
"message":" DEBUG: {1
11727734 BYE 5-LX4GdI9X}
tls [tls_server.c:199]:
tls_complete_init():
completing tls
connection
initialization"}<br>
...<br>
</div>
<div><br>
</div>
<div><br>
</div>
<div>So time to seek help
from the community, any
suggestions/ideas/comments? Sorry if all this sounds confusing, I've
tried my best to put in
text the whole scenario
in and "understandable"
way... </div>
<div><br>
</div>
<div>Is this even doable?</div>
<div><br>
</div>
<div>Thanks, </div>
<div>Joel.</div>
<div><br>
</div>
<div><br>
</div>
<div><br>
</div>
<div><br>
</div>
<div><br>
</div>
<div><br>
</div>
<div><br>
</div>
</div>
_______________________________________________<br>
Kamailio (SER) - Users
Mailing List<br>
<a
href="mailto:sr-users@lists.kamailio.org"
rel="noreferrer
noreferrer"
target="_blank"
moz-do-not-send="true">sr-users@lists.kamailio.org</a><br>
<a
href="https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users"
rel="noreferrer noreferrer
noreferrer"
target="_blank"
moz-do-not-send="true">https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users</a><br>
</blockquote>
</div>
_______________________________________________<br>
Kamailio (SER) - Users Mailing
List<br>
<a
href="mailto:sr-users@lists.kamailio.org"
target="_blank"
moz-do-not-send="true">sr-users@lists.kamailio.org</a><br>
<a
href="https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users"
rel="noreferrer"
target="_blank"
moz-do-not-send="true">https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users</a><br>
</blockquote>
</div>
</blockquote>
</div>
</blockquote>
</div>
<br>
<fieldset></fieldset>
<pre>_______________________________________________
Kamailio (SER) - Users Mailing List
<a href="mailto:sr-users@lists.kamailio.org" target="_blank" moz-do-not-send="true">sr-users@lists.kamailio.org</a>
<a href="https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users" target="_blank" moz-do-not-send="true">https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users</a>
</pre>
</blockquote>
<pre cols="72">--
Daniel-Constantin Mierla -- <a href="http://www.asipto.com" target="_blank" moz-do-not-send="true">www.asipto.com</a>
<a href="http://www.twitter.com/miconda" target="_blank" moz-do-not-send="true">www.twitter.com/miconda</a> -- <a href="http://www.linkedin.com/in/miconda" target="_blank" moz-do-not-send="true">www.linkedin.com/in/miconda</a>
Kamailio World Conference - April 27-29, 2020, in Berlin -- <a href="http://www.kamailioworld.com" target="_blank" moz-do-not-send="true">www.kamailioworld.com</a></pre>
</div>
</blockquote>
</div>
</div>
</blockquote>
</div>
</blockquote>
<pre cols="72">--
Daniel-Constantin Mierla -- <a href="http://www.asipto.com" target="_blank" moz-do-not-send="true">www.asipto.com</a>
<a href="http://www.twitter.com/miconda" target="_blank" moz-do-not-send="true">www.twitter.com/miconda</a> -- <a href="http://www.linkedin.com/in/miconda" target="_blank" moz-do-not-send="true">www.linkedin.com/in/miconda</a>
Kamailio World Conference - April 27-29, 2020, in Berlin -- <a href="http://www.kamailioworld.com" target="_blank" moz-do-not-send="true">www.kamailioworld.com</a></pre>
</div>
</blockquote>
</div>
</blockquote>
<pre class="moz-signature" cols="72">--
Daniel-Constantin Mierla -- <a class="moz-txt-link-abbreviated" href="http://www.asipto.com">www.asipto.com</a>
<a class="moz-txt-link-abbreviated" href="http://www.twitter.com/miconda">www.twitter.com/miconda</a> -- <a class="moz-txt-link-abbreviated" href="http://www.linkedin.com/in/miconda">www.linkedin.com/in/miconda</a>
Kamailio World Conference - April 27-29, 2020, in Berlin -- <a class="moz-txt-link-abbreviated" href="http://www.kamailioworld.com">www.kamailioworld.com</a></pre>
</body>
</html>