Re: [SR-Users] Re-use TCP connections on different transactions

2019-11-22 Thread Joel Serrano
Hi Daniel,

I have advertise as:

listen=tcp:10.116.15.237:443 advertise 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\/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\/parser\/msg_parser.c:610]: parse_msg():
SIP Request:"}
"message":" DEBUG:  [core\/parser\/msg_parser.c:612]: parse_msg():
 method:  "}
"message":" DEBUG:  [core\/parser\/msg_parser.c:614]: parse_msg():
 uri: "}
"message":" DEBUG:  [core\/parser\/msg_parser.c:616]: parse_msg():
 version: "}
"message":" DEBUG:  [core\/parser\/parse_via.c:1303]:
parse_via_param(): Found param type 232,  =
; state=16"}
"message":" DEBUG:  [core\/parser\/parse_via.c:2639]: parse_via():
end of header reached, state=5"}
"message":" DEBUG:  [core\/parser\/msg_parser.c:498]:
parse_headers(): Via found, flags=2"}
"message":" DEBUG:  [core\/parser\/msg_parser.c:500]:
parse_headers(): this is the first via"}
"message":" DEBUG:  [core\/parser\/parse_via.c:1303]:
parse_via_param(): Found param type 234,  = <35.226.32.33>;
state=6"}
"message":" DEBUG:  [core\/parser\/parse_via.c:1303]:
parse_via_param(): Found param type 235,  = <6061>; state=6"}
"message":" DEBUG:  [core\/parser\/parse_via.c:1303]:
parse_via_param(): Found param type 232,  = ;
state=16"}
"message":" DEBUG:  [core\/parser\/parse_via.c:2639]: parse_via():
end of header reached, state=5"}
"message":" DEBUG:  [core\/parser\/msg_parser.c:498]:
parse_headers(): Via found, flags=78"}
"message":" DEBUG:  [core\/parser\/msg_parser.c:511]:
parse_headers(): this is the second via"}
"message":" DEBUG:  [core\/parser\/parse_addr_spec.c:185]:
parse_to_param(): add param: tag=DU0ehPULu"}
"message":" DEBUG:  [core\/parser\/parse_addr_spec.c:864]:
parse_addr_spec(): end of header reached, state=29"}
"message":" DEBUG:  [core\/parser\/msg_parser.c:171]:
get_hdr_field():  [82]; uri=[
sip:8bd2a0aba14541789bb7269800646...@app.nextplus.me]"}
"message":" DEBUG:  [core\/parser\/msg_parser.c:174]:
get_hdr_field(): to body [\"Joel Test\" <
sip:8bd2a0aba14541789bb7269800646...@app.nextplus.me>], to tag [DU0ehPULu]"}
"message":" DEBUG:  [core\/parser\/msg_parser.c:152]:
get_hdr_field(): cseq : <12626897> "}
"message":" DEBUG:  [core\/receive.c:320]: receive_msg(): ---
received sip message - request - call-id: [nsWZzKWRld] - cseq: [12626897
BYE]"}
"message":" DEBUG:  [core\/parser\/msg_parser.c:185]:
get_hdr_field(): content_length=0"}
"message":" DEBUG:  [core\/parser\/msg_parser.c:89]: get_hdr_field():
found end of header"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} 
[core\/receive.c:380]: receive_msg(): preparing to run routing scripts..."}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} 
[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\/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\/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\/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\/socket_info.c:646]: grep_sock_info(): checking advertise if
host==us: 12==16 && [198.1.54.228] == [sbc01.stg.gii.me]"}
"message":" DEBUG: {1 12626897 BYE nsWZzKWRld} 
[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\/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 

Re: [SR-Users] Re-use TCP connections on different transactions

2019-11-22 Thread Daniel-Constantin Mierla
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  > 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
> mailto:mico...@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\/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
>>  (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
>>        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
>> mailto:j...@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:
>>
>> 
>> 
>>
>> ..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 "}
>> "message":" DEBUG: {1 12543376 BYE QQy-qagkcB} nathelper
>> [nathelper.c:1166]: handle_ruri_alias(): rewriting r-uri
>> to "}
>>
>> 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=0x"}
>> "message":" DEBUG: {1 12543376 BYE 

Re: [SR-Users] Re-use TCP connections on different transactions

2019-11-21 Thread Joel Serrano
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  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 
> 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\/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 (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
>> tcp0  0 10.116.15.237:443   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  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:
>>>
>>>
>>> 
>>>
>>> ..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
>>> "}
>>> "message":" DEBUG: {1 12543376 BYE QQy-qagkcB} nathelper
>>> [nathelper.c:1166]: handle_ruri_alias(): rewriting r-uri to
>>> "}
>>>
>>> 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=0x"}
>>> "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\/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 

Re: [SR-Users] Re-use TCP connections on different transactions

2019-11-21 Thread Joel Serrano
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 
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\/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 (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
> tcp0  0 10.116.15.237:443   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  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:
>>
>>
>> 
>>
>> ..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
>> "}
>> "message":" DEBUG: {1 12543376 BYE QQy-qagkcB} nathelper
>> [nathelper.c:1166]: handle_ruri_alias(): rewriting r-uri to
>> "}
>>
>> 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=0x"}
>> "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\/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\/msg_translator.c:161]: check_via_address(): (198.1.54.228,
>> 198.1.54.228, 0)"}
>> "message":" DEBUG: {1 12543376 BYE QQy-qagkcB} 
>> [core\/tcp_main.c:2060]: tcp_send(): no open tcp connection found, opening
>> new one"}
>> "message":" DEBUG: {1 12543376 BYE QQy-qagkcB} 
>> [core\/ip_addr.c:229]: print_ip(): tcpconn_new: new tcp connection:
>> 35.191.9.21"}
>> "message":" DEBUG: {1 12543376 BYE QQy-qagkcB} 
>> [core\/tcp_main.c:1242]: 

Re: [SR-Users] Re-use TCP connections on different transactions

2019-11-21 Thread Daniel-Constantin Mierla
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\/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 
> (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       
> 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  > 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:
>
> 
> 
>
> ..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
> "}
> "message":" DEBUG: {1 12543376 BYE QQy-qagkcB} nathelper
> [nathelper.c:1166]: handle_ruri_alias(): rewriting r-uri to
> "}
>
> 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=0x"}
> "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\/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\/msg_translator.c:161]: check_via_address(): (198.1.54.228,
> 198.1.54.228, 0)"}
> "message":" DEBUG: {1 12543376 BYE QQy-qagkcB} 
> [core\/tcp_main.c:2060]: tcp_send(): no open tcp connection found,
> opening new one"}
> "message":" DEBUG: {1 12543376 BYE QQy-qagkcB} 
> 

Re: [SR-Users] Re-use TCP connections on different transactions

2019-11-20 Thread Joel Serrano
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\/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 (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
tcp0  0 10.116.15.237:443   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  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:
>
>  ;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
> "}
> "message":" DEBUG: {1 12543376 BYE QQy-qagkcB} nathelper
> [nathelper.c:1166]: handle_ruri_alias(): rewriting r-uri to
> "}
>
> 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=0x"}
> "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\/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\/msg_translator.c:161]: check_via_address(): (198.1.54.228,
> 198.1.54.228, 0)"}
> "message":" DEBUG: {1 12543376 BYE QQy-qagkcB} 
> [core\/tcp_main.c:2060]: tcp_send(): no open tcp connection found, opening
> new one"}
> "message":" DEBUG: {1 12543376 BYE QQy-qagkcB} 
> [core\/ip_addr.c:229]: print_ip(): tcpconn_new: new tcp connection:
> 35.191.9.21"}
> "message":" DEBUG: {1 12543376 BYE QQy-qagkcB} 
> [core\/tcp_main.c:1242]: tcpconn_new(): on port 50705, type 3"}
> "message":" DEBUG: {1 12543376 BYE QQy-qagkcB} 
> [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  wrote:
>
>> Hi Yuriy,
>>
>> Thanks for 

Re: [SR-Users] Re-use TCP connections on different transactions

2019-11-20 Thread Joel Serrano
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:



..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
"}
"message":" DEBUG: {1 12543376 BYE QQy-qagkcB} nathelper
[nathelper.c:1166]: handle_ruri_alias(): rewriting r-uri to
"}

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=0x"}
"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\/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\/msg_translator.c:161]: check_via_address(): (198.1.54.228,
198.1.54.228, 0)"}
"message":" DEBUG: {1 12543376 BYE QQy-qagkcB} 
[core\/tcp_main.c:2060]: tcp_send(): no open tcp connection found, opening
new one"}
"message":" DEBUG: {1 12543376 BYE QQy-qagkcB} 
[core\/ip_addr.c:229]: print_ip(): tcpconn_new: new tcp connection:
35.191.9.21"}
"message":" DEBUG: {1 12543376 BYE QQy-qagkcB} 
[core\/tcp_main.c:1242]: tcpconn_new(): on port 50705, type 3"}
"message":" DEBUG: {1 12543376 BYE QQy-qagkcB} 
[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  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\/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 
> 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= (I Don't remember 

Re: [SR-Users] Re-use TCP connections on different transactions

2019-11-01 Thread Joel Serrano
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\/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 
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= (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,  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: 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: -> 2.2.2.2:443 (EXT) 3.3.3.3: (INT) -> 7.7.7.7:5060
>> (Kamailio)
>>
>> Transaction 2: ACK
>>
>> UAC 1.1.1.1:1112 -> 2.2.2.2:443 (EXT) 4.4.4.4: (INT) -> 7.7.7.7:5060
>> (Kamailio)
>>
>> Transaction 3: BYE
>>
>> Kam 7.7.7.7:5060 -> 3.3.3.3: (INT) 2.2.2.2:443 (EXT) -> 1.1.1.1:
>> 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: (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\/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 would be the equivalent of
>> 3.3.3.3: and 104.175.176.242:28157 would be 1.1.1.1: from the
>> example above.
>>
>> ...
>> "message":" DEBUG: {1 11727734 BYE 5-LX4GdI9X} 
>> [core\/tcp_main.c:1657]: _tcpconn_find(): found 

Re: [SR-Users] Re-use TCP connections on different transactions

2019-10-31 Thread Yuriy Gorlichenko
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= (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,  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: 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: -> 2.2.2.2:443 (EXT) 3.3.3.3: (INT) -> 7.7.7.7:5060
> (Kamailio)
>
> Transaction 2: ACK
>
> UAC 1.1.1.1:1112 -> 2.2.2.2:443 (EXT) 4.4.4.4: (INT) -> 7.7.7.7:5060
> (Kamailio)
>
> Transaction 3: BYE
>
> Kam 7.7.7.7:5060 -> 3.3.3.3: (INT) 2.2.2.2:443 (EXT) -> 1.1.1.1:
> 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: (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\/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 would be the equivalent of
> 3.3.3.3: and 104.175.176.242:28157 would be 1.1.1.1: from the
> example above.
>
> ...
> "message":" DEBUG: {1 11727734 BYE 5-LX4GdI9X} 
> [core\/tcp_main.c:1657]: _tcpconn_find(): found connection by id: 1"}
> "message":" NOTICE: {1 11727734 BYE 5-LX4GdI9X}