[SR-Users] Re-use TCP connections on different transactions
Daniel-Constantin Mierla
miconda at gmail.com
Fri Nov 22 10:02:20 CET 2019
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
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/20191122/b38c3d7e/attachment.html>
More information about the sr-users
mailing list