[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