[SR-Users] Re-use TCP connections on different transactions
Joel Serrano
joel at textplus.com
Thu Nov 21 19:44:41 CET 2019
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> 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>
> 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 (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 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> 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> 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>
>>>> 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> 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:1111 -> 2.2.2.2:443 (EXT) 3.3.3.3:3333 (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:4444 (INT) ->
>>>>>> 7.7.7.7:5060 (Kamailio)
>>>>>>
>>>>>> Transaction 3: BYE
>>>>>>
>>>>>> Kam 7.7.7.7:5060 -> 3.3.3.3:3333 (INT) 2.2.2.2:443 (EXT) ->
>>>>>> 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
>>>>>> (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 would be the equivalent
>>>>>> of 3.3.3.3:3333 and 104.175.176.242:28157 would be 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
>>>>>> https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users
>>>>>>
>>>>> _______________________________________________
>>>>> Kamailio (SER) - Users Mailing List
>>>>> sr-users at lists.kamailio.org
>>>>> https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users
>>>>>
>>>>
>> _______________________________________________
>> Kamailio (SER) - Users Mailing Listsr-users at lists.kamailio.orghttps://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users
>>
>> --
>> Daniel-Constantin Mierla -- www.asipto.comwww.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/20191121/fa1afab4/attachment.html>
More information about the sr-users
mailing list