[SR-Users] Re-use TCP connections on different transactions
Daniel-Constantin Mierla
miconda at gmail.com
Tue Nov 26 11:30:18 CET 2019
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 at 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 at 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 at app.nextplus.me
> <mailto:sip%3A8bd2a0aba14541789bb7269800646458 at app.nextplus.me>]"}
> "message":" DEBUG: <core> [core\/parser\/msg_parser.c:174]:
> get_hdr_field(): to body [\"Joel Test\"
> <sip:8bd2a0aba14541789bb7269800646458 at app.nextplus.me
> <mailto:sip%3A8bd2a0aba14541789bb7269800646458 at 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 at 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 at 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 at 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 at gmail.com <mailto:miconda at 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:
>> 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 at textplus.com
>> <mailto:joel at 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 at gmail.com <mailto:miconda at 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:
>>> 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 at 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 at sbc-gslb-test-1:~#
>>>
>>>
>>> Anyone?
>>>
>>> On Wed, Nov 20, 2019 at 9:26 AM Joel Serrano
>>> <joel at textplus.com <mailto:joel at 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 at 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 at 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 at textplus.com <mailto:joel at 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 at gmail.com
>>> <mailto:ovoshlook at 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 at textplus.com
>>> <mailto:joel at 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 at 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 at lists.kamailio.org
>>> <mailto:sr-users at lists.kamailio.org>
>>> https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users
>>>
>>> _______________________________________________
>>> Kamailio (SER) - Users Mailing List
>>> sr-users at lists.kamailio.org
>>> <mailto:sr-users at lists.kamailio.org>
>>> https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users
>>>
>>>
>>> _______________________________________________
>>> Kamailio (SER) - Users Mailing List
>>> sr-users at lists.kamailio.org <mailto:sr-users at 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>
>>
> --
> 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>
>
--
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
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.kamailio.org/pipermail/sr-users/attachments/20191126/36407571/attachment.html>
More information about the sr-users
mailing list