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 <[email protected]> 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 <[email protected]> > 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@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 <[email protected]> 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:[email protected]: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:[email protected]: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 <[email protected]> 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 <[email protected]> >>>> 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, <[email protected]> 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:[email protected]: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 >>>>>> [email protected] >>>>>> https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users >>>>>> >>>>> _______________________________________________ >>>>> Kamailio (SER) - Users Mailing List >>>>> [email protected] >>>>> https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users >>>>> >>>> >> _______________________________________________ >> Kamailio (SER) - Users Mailing >> [email protected]https://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 >> >>
_______________________________________________ Kamailio (SER) - Users Mailing List [email protected] https://lists.kamailio.org/cgi-bin/mailman/listinfo/sr-users
