26 Nov
2019
26 Nov
'19
1:30 p.m.
Hello,
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.
Cheers,
Daniel
On 22.11.19 19:25, Joel Serrano wrote:
Hi Daniel,
I have advertise as:
listen=tcp:10.116.15.237:443 <http://10.116.15.237:443> advertise
sbc01.stg.gii.me:443 <http://sbc01.stg.gii.me:443>
(normally it would be tls, I switched to tcp so I could get
unencrypted traffic in tcpdump for you)
Record-route is done as:
# Dispatch requests
if (is_method("INVITE")) {
$avp(caller_conid) = $conid;
record_route();
route(DISPATCH);
exit;
}
(route DISPATCH basically does dispatcher lookup and t_relay)
And this is the log for the BYE that doesn't work:
"message":" DEBUG: <core> [core\/udp_server.c:498]: udp_rcv_loop():
received on udp socket: (106\/100\/907) [[BYE
sip:linphone@104.175.176.242:43750;alias=130.211.3.12~53883~2;transport=tcp
SIP\/2.0 0D 0A Via: SIP\/2.]]"}
"message":" DEBUG: <core> [core\/parser\/msg_parser.c:610]:
parse_msg(): SIP Request:"}
"message":" DEBUG: <core> [core\/parser\/msg_parser.c:612]:
parse_msg(): method: <BYE>"}
"message":" DEBUG: <core> [core\/parser\/msg_parser.c:614]:
parse_msg(): uri:
<sip:linphone@104.175.176.242:43750;alias=130.211.3.12~53883~2;transport=tcp>"}
"message":" DEBUG: <core> [core\/parser\/msg_parser.c:616]:
parse_msg(): version: <SIP\/2.0>"}
"message":" DEBUG: <core> [core\/parser\/parse_via.c:1303]:
parse_via_param(): Found param type 232, <branch> =
<z9hG4bK4eda.30b29b519ea0cbd688ceb8071e271f7d.0>; state=16"}
"message":" DEBUG: <core> [core\/parser\/parse_via.c:2639]:
parse_via(): end of header reached, state=5"}
"message":" DEBUG: <core> [core\/parser\/msg_parser.c:498]:
parse_headers(): Via found, flags=2"}
"message":" DEBUG: <core> [core\/parser\/msg_parser.c:500]:
parse_headers(): this is the first via"}
"message":" DEBUG: <core> [core\/parser\/parse_via.c:1303]:
parse_via_param(): Found param type 234, <received> = <35.226.32.33>;
state=6"}
"message":" DEBUG: <core> [core\/parser\/parse_via.c:1303]:
parse_via_param(): Found param type 235, <rport> = <6061>; state=6"}
"message":" DEBUG: <core> [core\/parser\/parse_via.c:1303]:
parse_via_param(): Found param type 232, <branch> =
<z9hG4bKy0gFgvHcajHtm>; state=16"}
"message":" DEBUG: <core> [core\/parser\/parse_via.c:2639]:
parse_via(): end of header reached, state=5"}
"message":" DEBUG: <core> [core\/parser\/msg_parser.c:498]:
parse_headers(): Via found, flags=78"}
"message":" DEBUG: <core> [core\/parser\/msg_parser.c:511]:
parse_headers(): this is the second via"}
"message":" DEBUG: <core> [core\/parser\/parse_addr_spec.c:185]:
parse_to_param(): add param: tag=DU0ehPULu"}
"message":" DEBUG: <core> [core\/parser\/parse_addr_spec.c:864]:
parse_addr_spec(): end of header reached, state=29"}
"message":" DEBUG: <core> [core\/parser\/msg_parser.c:171]:
get_hdr_field(): <To> [82];
uri=[sip:8bd2a0aba14541789bb7269800646458@app.nextplus.me
<mailto:sip%3A8bd2a0aba14541789bb7269800646458@app.nextplus.me>]"}
"message":" DEBUG: <core> [core\/parser\/msg_parser.c:174]:
get_hdr_field(): to body [\"Joel Test\"
<sip:8bd2a0aba14541789bb7269800646458@app.nextplus.me
<mailto:sip%3A8bd2a0aba14541789bb7269800646458@app.nextplus.me>>], to
tag [DU0ehPULu]"}
"message":" DEBUG: <core> [core\/parser\/msg_parser.c:152]:
get_hdr_field(): cseq <CSeq>: <12626897> <BYE>"}
"message":" DEBUG: <core> [core\/receive.c:320]: receive_msg(): ---
received sip message - request - call-id: [nsWZzKWRld] - cseq:
[12626897 BYE]"}
"message":" DEBUG: <core> [core\/parser\/msg_parser.c:185]:
get_hdr_field(): content_length=0"}
"message":" DEBUG: <core> [core\/parser\/msg_parser.c:89]:
get_hdr_field(): found end of header"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/receive.c:380]: receive_msg(): preparing to run routing
scripts..."}
"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]"}
"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]"}
"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]"}
"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]"}
"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] == [sbc01.stg.gii.me
<http://sbc01.stg.gii.me>]"}
"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]"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/forward.c:413]: check_self(): host != me"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} maxfwd [mf_funcs.c:74]:
is_maxfwd_present(): value = 69 "}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} sanity [sanity.c:247]:
check_ruri_sip_version(): check_ruri_sip_version entered"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} sanity [sanity.c:270]:
check_ruri_sip_version(): check_ruri_sip_version passed"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} sanity [sanity.c:277]:
check_ruri_scheme(): check_ruri_scheme entered"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} sanity [sanity.c:297]:
check_ruri_scheme(): check_ruri_scheme passed"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} sanity [sanity.c:305]:
check_required_headers(): check_required_headers entered"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} sanity [sanity.c:313]:
check_required_headers(): check_required_headers passed"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} sanity [sanity.c:479]:
check_cseq_method(): check_cseq_method entered"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} sanity [sanity.c:512]:
check_cseq_method(): check_cseq_method passed"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} sanity [sanity.c:521]:
check_cseq_value(): check_cseq_value entered"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} sanity [sanity.c:549]:
check_cseq_value(): check_cseq_value passed"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} sanity [sanity.c:558]:
check_cl(): check_cl entered"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} sanity [sanity.c:583]:
check_cl(): check_cl passed"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} sanity [sanity.c:595]:
check_expires_value(): check_expires_value entered"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} sanity [sanity.c:632]:
check_expires_value(): no expires header found"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} sanity [sanity.c:732]:
check_parse_uris(): check_parse_uris entered"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} sanity [sanity.c:736]:
check_parse_uris(): parsing ruri"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} sanity [sanity.c:750]:
check_parse_uris(): looking up From header"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} sanity [sanity.c:764]:
check_parse_uris(): parsing From header"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/parser\/parse_addr_spec.c:185]: parse_to_param(): add param:
tag=QZQSQQegvc5Zr"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/parser\/parse_addr_spec.c:864]: parse_addr_spec(): end of
header reached, state=29"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} sanity [sanity.c:790]:
check_parse_uris(): parsing From URI"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} sanity [sanity.c:808]:
check_parse_uris(): looking up To header"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} sanity [sanity.c:830]:
check_parse_uris(): check_parse_uris(): parsing To URI"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} sanity [sanity.c:875]:
check_parse_uris(): check_parse_uris passed"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} sanity
[sanity_mod.c:254]: w_sanity_check(): sanity checks result: 1"}
"message":" NOTICE: {1 12626897 BYE nsWZzKWRld} <script>: JOEL TEST
New request - M=BYE UAC-IP=198.1.54.228:5060
<http://198.1.54.228:5060> LB-IP=<null>:<null> CONID=<null>
TCP-CONID=<null> UA='FS textPlus Voice' ID=nsWZzKWRld"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/msg_translator.c:161]: check_via_address(): (198.1.54.228,
198.1.54.228, 0)"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} siputils
[checks.c:123]: has_totag(): totag found"}
"message":" NOTICE: {1 12626897 BYE nsWZzKWRld} <script>: In-dialog
request from COPS - M=BYE
R=sip:linphone@104.175.176.242:43750;alias=130.211.3.12~53883~2;transport=tcp
ID=nsWZzKWRld"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} rr [loose.c:90]:
is_preloaded(): is_preloaded: No"}
"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]"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/socket_info.c:635]: grep_sock_info(): checking if port 5070
(advertise 5070) matches port 43750"}
"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]"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/socket_info.c:635]: grep_sock_info(): checking if port 5080
(advertise 0) matches port 43750"}
"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]"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/socket_info.c:635]: grep_sock_info(): checking if port 443
(advertise 443) matches port 43750"}
"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]"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/socket_info.c:635]: grep_sock_info(): checking if port 80
(advertise 0) matches port 43750"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/forward.c:413]: check_self(): host != me"}
"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]"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/socket_info.c:635]: grep_sock_info(): checking if port 5070
(advertise 5070) matches port 5070"}
"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]"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} rr [loose.c:811]:
after_loose(): Topmost route URI:
'sip:34.70.182.24:5070;r2=on;lr=on;ftag=DU0ehPULu;did=bfc.e45;nat=yes'
is me"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/socket_info.c:628]: grep_sock_info(): checking if host==us:
16==13 && [sbc01.stg.gii.me <http://sbc01.stg.gii.me>] ==
[10.116.15.237]"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/socket_info.c:635]: grep_sock_info(): checking if port 443
(advertise 443) matches port 443"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/socket_info.c:646]: grep_sock_info(): checking advertise if
host==us: 16==16 && [sbc01.stg.gii.me <http://sbc01.stg.gii.me>] ==
[sbc01.stg.gii.me <http://sbc01.stg.gii.me>]"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/parser\/msg_parser.c:89]: get_hdr_field(): found end of header"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} rr [loose.c:181]:
find_next_route(): No next Route HF found"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} rr [loose.c:875]:
after_loose(): no next URI found"}
"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>"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} dialog
[dlg_handlers.c:1306]: dlg_onroute(): route param is 'bfc.e45' (len=7)"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} dialog
[dlg_hash.c:784]: dlg_lookup(): ref dlg 0x7f56979d4660 with 1 -> 3"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} dialog
[dlg_hash.c:786]: dlg_lookup(): dialog id=1358 found on entry 3323"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} dialog
[dlg_profile.c:536]: set_current_dialog(): setting current dialog
[3323:1358]"}
"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)"}
"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"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} dialog
[dlg_hash.c:1013]: dlg_ref_helper(): ref dlg 0x7f56979d4660 with 1 -> 4"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} dialog
[dlg_handlers.c:1441]: dlg_onroute(): BYE successfully processed"}
"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"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} dialog
[dlg_hash.c:1033]: dlg_unref_helper(): unref dlg 0x7f56979d4660 with 2
-> 2"}
"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"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} dialog
[dlg_hash.c:1033]: dlg_unref_helper(): unref dlg 0x7f56979d4660 with 1
-> 1"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} nathelper
[nathelper.c:1144]: handle_ruri_alias(): setting dst_uri to
<sip:130.211.3.12:53883;transport=tcp>"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} nathelper
[nathelper.c:1166]: handle_ruri_alias(): rewriting r-uri to
<sip:linphone@104.175.176.242:43750;transport=tcp>"}
"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"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} tm [t_lookup.c:497]:
t_lookup_request(): start searching: hash=44516, isACK=0"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} tm [t_lookup.c:455]:
matching_3261(): RFC3261 transaction matching failed - via branch
[z9hG4bK4eda.30b29b519ea0cbd688ceb8071e271f7d.0]"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} tm [t_lookup.c:675]:
t_lookup_request(): no transaction found"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} tm [t_hooks.c:336]:
run_reqin_callbacks_internal(): trans=0x7f56979d6558, callback type 1,
id 0 entered"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/crypto\/md5utils.c:67]: MD5StringArray(): MD5 calculated:
7fe00a28920a3325330971908f8c5b0e"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} siputils
[checks.c:123]: has_totag(): totag found"}
"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])"}
"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>"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} siputils
[checks.c:123]: has_totag(): totag found"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/msg_translator.c:161]: check_via_address(): (198.1.54.228,
198.1.54.228, 0)"}
"message":" ERROR: {1 12626897 BYE nsWZzKWRld} tm
[..\/..\/core\/forward.h:261]: msg_send_buffer(): tcp_send failed"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} tm [t_fwd.c:1537]:
t_send_branch(): send to 130.211.3.12:53883
<http://130.211.3.12:53883> (2) failed"}
"message":" WARNING: {1 12626897 BYE nsWZzKWRld} tm [t_fwd.c:1557]:
t_send_branch(): sending request on branch 0 failed"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} tm [t_funcs.c:336]:
t_relay_to(): t_forward_nonack returned error -1 (-477)"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} tm [t_funcs.c:354]:
t_relay_to(): -477 error reply generation delayed "}
"message":" ERROR: {1 12626897 BYE nsWZzKWRld} <script>: Could not
forward request - M=BYE
R=sip:linphone@104.175.176.242:43750;transport=tcp ID=nsWZzKWRld"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/msg_translator.c:161]: check_via_address(): (198.1.54.228,
198.1.54.228, 0)"}
"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)"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/receive.c:438]: receive_msg(): request-route executed in: 1051
usec"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} dialog
[dlg_hash.c:784]: dlg_lookup(): ref dlg 0x7f56979d4660 with 1 -> 2"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} dialog
[dlg_hash.c:786]: dlg_lookup(): dialog id=1358 found on entry 3323"}
"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"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} dialog
[dlg_hash.c:1033]: dlg_unref_helper(): unref dlg 0x7f56979d4660 with 1
-> 1"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} tm [t_lookup.c:1493]:
t_unref(): delayed error reply generation(-477)"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/msg_translator.c:161]: check_via_address(): (198.1.54.228,
198.1.54.228, 0)"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} tm [t_reply.c:1667]:
cleanup_uac_timers(): RETR\/FR timers reset"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} tm [t_hooks.c:252]:
run_trans_callbacks_internal(): DBG: trans=0x7f56979d6558, callback
type 512, id 0 entered"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} dialog
[dlg_hash.c:784]: dlg_lookup(): ref dlg 0x7f56979d4660 with 1 -> 2"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} dialog
[dlg_hash.c:786]: dlg_lookup(): dialog id=1358 found on entry 3323"}
"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"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} dialog
[dlg_hash.c:1033]: dlg_unref_helper(): unref dlg 0x7f56979d4660 with 1
-> 1"}
"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"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} tm [t_reply.c:621]:
_reply_light(): finished"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/usr_avp.c:636]: destroy_avp_list(): destroying list (nil)"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/xavp.c:517]: xavp_destroy_list(): destroying xavp list (nil)"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} <core>
[core\/receive.c:529]: receive_msg(): cleaning up"}
"message":" DEBUG: <core> [core\/io_wait.h:599]: io_watch_del():
DBG:
io_watch_del (0x562f315c32a0, 6, -1, 0x10) fd_no=3 called"}
"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)"}
"message":" DEBUG: <core> [core\/tcp_read.c:1684]:
release_tcpconn():
extra_data (nil)"}
"message":" DEBUG: <core> [core\/io_wait.h:599]: io_watch_del():
DBG:
io_watch_del (0x562f315c32a0, 9, -1, 0x10) fd_no=2 called"}
"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)"}
"message":" DEBUG: <core> [core\/tcp_read.c:1684]:
release_tcpconn():
extra_data (nil)"}
"message":" DEBUG: <core> [core\/tcp_main.c:3625]:
handle_tcp_child():
reader response= 7f56979e0ad8, 1 from 0 "}
"message":" DEBUG: <core> [core\/io_wait.h:377]: io_watch_add():
DBG:
io_watch_add(0x562f31567820, 24, 2, 0x7f56979e0ad8), fd_no=15"}
"message":" DEBUG: <core> [core\/tcp_main.c:3752]:
handle_tcp_child():
CONN_RELEASE 0x7f56979e0ad8 refcnt= 1"}
"message":" DEBUG: <core> [core\/tcp_main.c:3625]:
handle_tcp_child():
reader response= 7f56979f0e78, 1 from 0 "}
"message":" DEBUG: <core> [core\/io_wait.h:377]: io_watch_add():
DBG:
io_watch_add(0x562f31567820, 26, 2, 0x7f56979f0e78), fd_no=16"}
"message":" DEBUG: <core> [core\/tcp_main.c:3752]:
handle_tcp_child():
CONN_RELEASE 0x7f56979f0e78 refcnt= 1"}
Not sure what I can be doing wrong!
IP information to help you understand the packet capture:
UAC: 104.175.176.242
LB (UAC side): 35.186.235.62:443 <http://35.186.235.62:443> or
sbc01stg.gii.me:443 <http://sbc01stg.gii.me:443>
LB (Kam side can be many, for this example it's 130.211.3.12:53883
<http://130.211.3.12:53883>)
PSTN GW: 198.1.54.228
Thanks for your help on this.
Best,
Joel.
On Fri, Nov 22, 2019 at 1:02 AM Daniel-Constantin Mierla
<miconda(a)gmail.com <mailto:miconda@gmail.com>> wrote:
Hello,
how do you set the record-route? Do you have advertised address
for the socket receiving TCP/HAproxy loadbalancer connections?
Can you give all the debug messages when processing the BYE that
doesn't go through?
Cheers,
Daniel
On 21.11.19 19:44, Joel Serrano wrote:
--
Daniel-Constantin Mierla -- www.asipto.com
www.twitter.com/miconda -- www.linkedin.com/in/miconda
Kamailio World Conference - April 27-29, 2020, in Berlin -- www.kamailioworld.com
Hi Daniel,
I sent you (privately) 2 pcaps. Please let me know if you need
anything else.
My current TCP params are:
disable_tcp=no
tcp_children=1
tcp_max_connections=12288
tcp_rd_buf_size=65536
tcp_conn_wq_max=131072
tcp_keepalive=yes
tcp_crlf_ping=yes
tcp_keepcnt=3
tcp_keepidle=30
tcp_keepintvl=30
tcp_connection_lifetime=3610
tcp_accept_no_cl=yes
tcp_accept_haproxy=yes
tcp_no_connect=yes
Thanks,
Joel.
On Thu, Nov 21, 2019 at 7:50 AM Joel Serrano <joel(a)textplus.com
<mailto:joel@textplus.com>> wrote:
I don’t, but I’ll repeat the test with tcpdump active! I’ll
report back shortly
On Thu, Nov 21, 2019 at 03:50 Daniel-Constantin Mierla
<miconda(a)gmail.com <mailto:miconda@gmail.com>> wrote:
Hello,
do you have the pcap with the sip traffic for this case?
Cheers,
Daniel
On 20.11.19 19:45, Joel Serrano wrote:
--
Daniel-Constantin Mierla -- www.asipto.com <http://www.asipto.com>
www.twitter.com/miconda <http://www.twitter.com/miconda> --
www.linkedin.com/in/miconda <http://www.linkedin.com/in/miconda>
Kamailio World Conference - April 27-29, 2020, in Berlin -- www.kamailioworld.com
<http://www.kamailioworld.com>
Hello,
I added to the config file:
tcp_no_connect=yes
And with that param, the same test results in a
different behavior, but still not working:
"message":" DEBUG: {1 12583750 BYE RVXZVMHKop} <core>
[core\/msg_translator.c:161]: check_via_address():
(198.1.54.228, 198.1.54.228, 0)"}
"message":" ERROR: {1 12583750 BYE RVXZVMHKop} tm
[..\/..\/core\/forward.h:292]: msg_send_buffer():
tcp_send failed"}
"message":" DEBUG: {1 12583750 BYE RVXZVMHKop} tm
[t_fwd.c:1537]: t_send_branch(): send to
35.191.9.20:56470 <http://35.191.9.20:56470> (3) failed"}
"message":" WARNING: {1 12583750 BYE RVXZVMHKop} tm
[t_fwd.c:1557]: t_send_branch(): sending request on
branch 0 failed"}
"message":" DEBUG: {1 12583750 BYE RVXZVMHKop} tm
[t_funcs.c:336]: t_relay_to(): t_forward_nonack returned
error -1 (-477)"}
"message":" DEBUG: {1 12583750 BYE RVXZVMHKop} tm
[t_funcs.c:354]: t_relay_to(): -477 error reply
generation delayed "}
Although, netstats says the connection is active:
root@sbc-gslb-test-1:~# netstat -putan | grep 56470
tcp 0 0 10.116.15.237:443
<http://10.116.15.237:443> 35.191.9.20:56470
<http://35.191.9.20:56470> ESTABLISHED 3920/kamailio
root@sbc-gslb-test-1:~#
Anyone?
On Wed, Nov 20, 2019 at 9:26 AM Joel Serrano
<joel(a)textplus.com <mailto:joel@textplus.com>> wrote:
Bumping this thread up!
I did some more tests trying to narrow down the
problem and this is what I found...:
On the INVITE, I add the TCP connection information
I want to save (for later reuse). Snippets:
...(found this in
the misc/examples/pkg/sip-router-oob.cfg, but I
haven't noticed any changes to the headers or
anything)...
# Force response to received connection
force_rport();
if (proto==TCP || proto == TLS) {
force_tcp_alias();
xlog("L_NOTICE", "force_tcp_alias() done");
}
...
...(I also have this)...
if (is_first_hop()) {
xlog("L_NOTICE", "Adding LB info to contact
- M=$rm ID=$ci\n");
add_contact_alias("$tcp(c_si)",
"$tcp(c_sp)", "tls");
}
...
Which effectively makes the contact look like:
<sip:linphone@104.175.176.242:50312;alias=35.191.9.21~50705~3;transport=tls>
..180..
..200 OK..
..ACK..
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:
"message":" DEBUG: {1 12543376 BYE QQy-qagkcB}
nathelper [nathelper.c:1144]: handle_ruri_alias():
setting dst_uri to
<sip:35.191.9.21:50705;transport=tls>"}
"message":" DEBUG: {1 12543376 BYE QQy-qagkcB}
nathelper [nathelper.c:1166]: handle_ruri_alias():
rewriting r-uri to
<sip:linphone@104.175.176.242:50312;transport=tls>"}
But then, Kamalio won't reuse the existing TCP
connection and tries to create a new one:
"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"}
"message":" DEBUG: {1 12543376 BYE QQy-qagkcB} tm
[t_lookup.c:497]: t_lookup_request(): start
searching: hash=63128, isACK=0"}
"message":" DEBUG: {1 12543376 BYE QQy-qagkcB} tm
[t_lookup.c:455]: matching_3261(): RFC3261
transaction matching failed - via branch
[z9hG4bK896f.dc04734743b0f0997f39c4fff07c0fbb.0]"}
"message":" DEBUG: {1 12543376 BYE QQy-qagkcB} tm
[t_lookup.c:675]: t_lookup_request(): no transaction
found"}
"message":" DEBUG: {1 12543376 BYE QQy-qagkcB} tm
[t_hooks.c:336]: run_reqin_callbacks_internal():
trans=0x7f8583b17208, callback type 1, id 0 entered"}
"message":" DEBUG: {1 12543376 BYE QQy-qagkcB}
<core> [core\/crypto\/md5utils.c:67]:
MD5StringArray(): MD5 calculated:
71c229aff3c0b4f6e9e77c4990b74e5e"}
"message":" DEBUG: {1 12543376 BYE QQy-qagkcB}
siputils [checks.c:123]: has_totag(): totag found"}
"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])"}
"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>"}
"message":" DEBUG: {1 12543376 BYE QQy-qagkcB}
siputils [checks.c:123]: has_totag(): totag found"}
"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)"}
"message":" DEBUG: {1 12543376 BYE QQy-qagkcB}
<core> [core\/tcp_main.c:2060]: tcp_send(): no open
tcp connection found, opening new one"}
"message":" DEBUG: {1 12543376 BYE QQy-qagkcB}
<core> [core\/ip_addr.c:229]: print_ip():
tcpconn_new: new tcp connection: 35.191.9.21"}
"message":" DEBUG: {1 12543376 BYE QQy-qagkcB}
<core> [core\/tcp_main.c:1242]: tcpconn_new(): on
port 50705, type 3"}
"message":" DEBUG: {1 12543376 BYE QQy-qagkcB}
<core> [core\/tcp_main.c:1561]: tcpconn_add():
hashes: 337:3545:0, 3"}
Am I still missing anything?
Is this a bug and I should open a GH issue?
Any suggestions/comments/ideas are very welcome!
Thanks,
Joel.
On Fri, Nov 1, 2019 at 11:46 AM Joel Serrano
<joel(a)textplus.com <mailto:joel@textplus.com>> wrote:
Hi Yuriy,
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.
All the VIA headers look exactly the same, and I
still get this in the logs:
"message":" DEBUG: {1 11762916 BYE d2T9-YOxYk}
<core> [core\/tcp_main.c:2060]: tcp_send(): no
open tcp connection found, opening new one"}
The docs say:
"force_tcp_alias(port)
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."
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..
Any other suggestions? Am I missing something?
Thanks,
Joel.
On Thu, Oct 31, 2019 at 10:53 PM Yuriy
Gorlichenko <ovoshlook(a)gmail.com
<mailto:ovoshlook@gmail.com>> wrote:
You have to use
tcp_accept_aliases=yes
But this is not enough as this param will be
triggered by function
force_tcp_alias() you need to use in the
route for request ( for example record_route
or subroutes)
It will add param paramname=<portnum> (I
Don't remember specific name)
to Via header that will be used for all
dialog requests belongs one being affected
On Fri, 1 Nov 2019, 00:52 Joel Serrano,
<joel(a)textplus.com
<mailto:joel@textplus.com>> wrote:
Hello,
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).
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:
Following this example:
image.png
EXT & INT represent the external and
internal interface of a LB between the
UAC and Kamailio, using TLS on both legs
and proxy protocol.
Transaction 1: INVITE, 100, 180, 183, 200 OK
UAC 1.1.1.1:1111 <http://1.1.1.1:1111>
-> 2.2.2.2:443 <http://2.2.2.2:443>
(EXT) 3.3.3.3:3333 <http://3.3.3.3:3333>
(INT) -> 7.7.7.7:5060
<http://7.7.7.7:5060> (Kamailio)
Transaction 2: ACK
UAC 1.1.1.1:1112 <http://1.1.1.1:1112>
-> 2.2.2.2:443 <http://2.2.2.2:443>
(EXT) 4.4.4.4:4444 <http://4.4.4.4:4444>
(INT) -> 7.7.7.7:5060
<http://7.7.7.7:5060> (Kamailio)
Transaction 3: BYE
Kam 7.7.7.7:5060 <http://7.7.7.7:5060>
-> 3.3.3.3:3333 <http://3.3.3.3:3333>
(INT) 2.2.2.2:443 <http://2.2.2.2:443>
(EXT) -> 1.1.1.1:1111
<http://1.1.1.1:1111> UAC
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.
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?
On the original INVITE, I use the
following to save where I have to reach
the UAC:
add_contact_alias("$tcp(c_si)",
"$tcp(c_sp)", "tls");
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.
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).
So when I run handle_ruri_alias(), and
$du is set to 3.3.3.3:3333
<http://3.3.3.3:3333> (from the example
above), instead of using the existing
connection, Kamailio tries to create a
new one.
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:
DEBUG: {1 11726467 BYE gqR1qqNK8B}
<core> [core\/tcp_main.c:2060]:
tcp_send(): no open tcp connection
found, opening new one"}
And then the problems begin...
I have tried playing around with:
tcp_reuse_port
tcp_connection_match
But no luck..!
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.
A more detailed log:
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,
35.191.0.66:60271
<http://35.191.0.66:60271> would be the
equivalent of 3.3.3.3:3333
<http://3.3.3.3:3333>
and 104.175.176.242:28157
<http://104.175.176.242:28157> would be
1.1.1.1:1111 <http://1.1.1.1:1111> from
the example above.
...
"message":" DEBUG: {1 11727734 BYE
5-LX4GdI9X} <core>
[core\/tcp_main.c:1657]:
_tcpconn_find(): found connection by id: 1"}
"message":" NOTICE: {1 11727734 BYE
5-LX4GdI9X} <script>: JOEL TEST New
request - M=BYE TCP STATUS:1 ID=5-LX4GdI9X"}
...
"message":" DEBUG: {1 11727734 BYE
5-LX4GdI9X} nathelper
[nathelper.c:1144]: handle_ruri_alias():
setting dst_uri to
<sip:35.191.0.66:60271;transport=tls>"}
"message":" DEBUG: {1 11727734 BYE
5-LX4GdI9X} nathelper
[nathelper.c:1166]: handle_ruri_alias():
rewriting r-uri to
<sip:linphone@104.175.176.242:28157;transport=tls>"}
"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"}
"message":" DEBUG: {1 11727734 BYE
5-LX4GdI9X} tm [t_lookup.c:497]:
t_lookup_request(): start searching:
hash=63496, isACK=0"}
"message":" DEBUG: {1 11727734 BYE
5-LX4GdI9X} tm [t_lookup.c:455]:
matching_3261(): RFC3261 transaction
matching failed - via branch
[z9hG4bK808f.eee2444f92a02cb33e1b7a21f20bc6bb.0]"}
"message":" DEBUG: {1 11727734 BYE
5-LX4GdI9X} tm [t_lookup.c:675]:
t_lookup_request(): no transaction found"}
"message":" DEBUG: {1 11727734 BYE
5-LX4GdI9X} tm [t_hooks.c:336]:
run_reqin_callbacks_internal():
trans=0x7f3c83b8c598, callback type 1,
id 0 entered"}
"message":" DEBUG: {1 11727734 BYE
5-LX4GdI9X} <core>
[core\/crypto\/md5utils.c:67]:
MD5StringArray(): MD5 calculated:
3071029feb05962b26b53a9664a14210"}
"message":" DEBUG: {1 11727734 BYE
5-LX4GdI9X} siputils [checks.c:123]:
has_totag(): totag found"}
"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])"}
"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>"}
"message":" DEBUG: {1 11727734 BYE
5-LX4GdI9X} siputils [checks.c:123]:
has_totag(): totag found"}
"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)"}
"message":" DEBUG: {1 11727734 BYE
5-LX4GdI9X} <core>
[core\/tcp_main.c:2060]: tcp_send(): no
open tcp connection found, opening new one"}
"message":" DEBUG: {1 11727734 BYE
5-LX4GdI9X} <core>
[core\/ip_addr.c:229]: print_ip():
tcpconn_new: new tcp connection:
35.191.0.66"}
"message":" DEBUG: {1 11727734 BYE
5-LX4GdI9X} <core>
[core\/tcp_main.c:1242]: tcpconn_new():
on port 60271, type 3"}
"message":" DEBUG: {1 11727734 BYE
5-LX4GdI9X} <core>
[core\/tcp_main.c:1561]: tcpconn_add():
hashes: 1446:2350:0, 5"}
"message":" DEBUG: {1 11727734 BYE
5-LX4GdI9X} tls [tls_server.c:199]:
tls_complete_init(): completing tls
connection initialization"}
...
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...
Is this even doable?
Thanks,
Joel.
_______________________________________________
Kamailio (SER) - Users Mailing List
sr-users(a)lists.kamailio.org
<mailto:sr-users@lists.kamailio.org>
https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users
_______________________________________________
Kamailio (SER) - Users Mailing List
sr-users(a)lists.kamailio.org
<mailto:sr-users@lists.kamailio.org>
https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users
_______________________________________________
Kamailio (SER) - Users Mailing List
sr-users(a)lists.kamailio.org <mailto:sr-users@lists.kamailio.org>
https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users
--
Daniel-Constantin Mierla -- www.asipto.com <http://www.asipto.com>
www.twitter.com/miconda <http://www.twitter.com/miconda> --
www.linkedin.com/in/miconda <http://www.linkedin.com/in/miconda>
Kamailio World Conference - April 27-29, 2020, in Berlin --
www.kamailioworld.com <http://www.kamailioworld.com>