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

[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:

<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
>>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.kamailio.org/pipermail/sr-users/attachments/20191120/95069df3/attachment.html>