[SR-Users] Re-use TCP connections on different transactions
Daniel-Constantin Mierla
miconda at gmail.com
Thu Nov 21 12:50:41 CET 2019
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
> https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users
--
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/20191121/7862b457/attachment.html>
More information about the sr-users
mailing list