### Description
Having clients connected via TCP doing only passive connections in the kamailio server it seems the tcp_send_timeout is not used on messages going out to the clients. While tcp_keepalive is doing well as long as there was not sent any packet to the client tcp_send_timout does nothing. The underlying Linux tries to send the SIP message for ages (15 minutes in my case).
Do I have a wrong understanding of tcp_send_timeout?
I tried with tcp_async yes and no with same results.
### Troubleshooting
These are my tcp settings:
``` # def = 10 Time in seconds after a TCP connection will be closed if it is not available for writing in this interval (and Kamailio wants to send something on it). # Lower this value for faster detection of broken TCP connections. tcp_send_timeout=3
tcp_connect_timeout=10 # def = 10 tcp_connection_lifetime=3605 tcp_rd_buf_size=32768 tcp_max_connections=2048 tcp_connection_match=1 # match also local port
tcp_keepalive=yes # Enables keepalive for tcp (sets SO_KEEPALIVE socket option) tcp_keepcnt=3 # Number of keepalives sent before dropping the connection (TCP_KEEPCNT socket option). Linux only. tcp_keepidle=30 # Time before starting to send keepalives, if the connection is idle (TCP_KEEPIDLE socket option). Linux only. tcp_keepintvl=10 # Time interval between keepalive probes, when the previous probe failed (TCP_KEEPINTVL socket option). Linux only.
tcp_async=yes # alias tcp_buf_write, default=yes tcp_crlf_ping=no ```
I also tried to set the tcp_send_timeout to much too high value 333666 to trigger this line of code in tcp_options.c:
``` WARN("%s: timeout too big (%u), the maximum value is %u\n", name, *to, max_val); ```
But even in -d -d -d debugging that line never hits.
I do **not** make any connections outbound (senseless on NAT). Instead I'd like to reject this:
``` if ($dP =~ "tcp") { set_forward_no_connect(); xlog("L_INFO", ">> checking tcp connection to $dd:$dp"); if(tcp_get_conid("$dd:$dp", "$var(conid)")) { xlog("L_INFO", ">> connection id to $dd:$dp is: $var(conid)"); } else { xlog("L_ERR", ">> connection to $dd:$dp is no longer connected. Client must reregister!"); sl_send_reply("480", "TCP not connected"); exit; } } ```
But the connection ID is still there for a long time. And there are no keepalives done since the outgoing packets are in the queue.
#### Reproduction
1. Register a client with TCP. 2. Pull the plug. 3. Make a call to it. 4. Run a `'watch 'netstat -tapen | grep <client_ip>'`: The connected client never vanishes. 5. Run a `tcpdump -i ethX tcp port <kamailio_server_port>`: the system tries to send the packet for a long time
#### Log Messages
There is not much to see in the log, even in debug level.
`/usr/sbin/kamailio -P /var/run/kamailio/kamailio.sbc.pid -f /etc/kamailio.sbc/kamailio.cfg -m 48 -M 24 -u kamailio -g kamailio -d -d -d`
At that moment the switchport was already shutdown:
``` May 9 10:48:19 p01t-1 kamailio.sbc[150273]: INFO: sbc:<script>: Network sending:
>>>>>>>>>>>>>>>>>>>>>>>>
INVITE sip:22@ws2.domain.tld;user=phone SIP/2.0 Record-Route: sip:192.168.48.131:5065;r2=on;lr;ftag=97p54nlxgb;x-rtpp=1 Record-Route: sip:10.101.65.131:5082;r2=on;lr;ftag=97p54nlxgb;x-rtpp=1 Via: SIP/2.0/UDP 192.168.48.131:5065;branch=z9hG4bKe01f.07e0d03fb0af18dcdb76154be67bea1d.0 Via: SIP/2.0/UDP 192.168.41.57:48310;received=10.101.65.130;branch=z9hG4bK-nzdt1be9c4xn;rport=48310 From: "01/301102-21" sip:15553010221@ws2.domain.tld;tag=97p54nlxgb To: sip:22@ws2.domain.tld;user=phone Call-ID: 3136383336323230393839333336-jg7spjsktbm2 CSeq: 2 INVITE Max-Forwards: 69 User-Agent: snomD765/10.1.49.11 Contact: sip:15553010221@192.168.48.131:5065;ntv3=2;alias=10.101.65.130~48310~1;fs=udp:10.101.65.131:5082;uri=sip:15553010221%40192.168.41.57:48310%3bline%3dbq029ivo;line=bq029ivo;reg-id=1 Accept: application/sdp Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO, UPDATE Allow-Events: talk, hold, refer, call-info Supported: timer, 100rel, replaces, from-change Session-Expires: 3600 Min-SE: 90 Proxy-Authorization: Digest username="45487cfdffef4777",realm="ws2.domain.tld",nonce="d84c8d657ba6e3081547bbb6e0c1817c",uri="sip:22@ws2.domain.tld;user=phone",qop=auth,nc=00000001,cnonce="6be15ae9",response="9455eafa4f6b2b78e971a87cb2716132",opaque="485307819b9fa9a1f7e2ca58ae77f795",algorithm=MD5 Content-Type: application/sdp Content-Length: 258 P-Charging-Vector: icid-value=31363833363232;icid-generated-at=c5sbcp01t X-User: sip:45487cfdffef4777@ws2.domain.tld X-Location: dev.DefaultGroup;reg=192.168.48.68:5060;sig=192.168.48.74:5060;bt=0 X-Realm: p01t
v=0 o=root 711904586 711904586 IN IP4 10.101.65.133 s=call c=IN IP4 10.101.65.133 t=0 0 m=audio 10490 RTP/AVP 9 8 101 a=rtpmap:9 G722/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=sendrecv a=rtcp:10491 a=ptime:20
>>>>>>>>>>>>>>>>>>>>>>>>
May 9 10:48:19 p01t-1 kamailio.sbc[150273]: DEBUG: sbc:tm [t_funcs.c:373]: t_relay_to(): new transaction forwarded May 9 10:48:19 p01t-1 kamailio.sbc[150273]: DEBUG: sbc:<core> [core/receive.c:528]: receive_msg(): request-route executed in: 45584 usec May 9 10:48:19 p01t-1 kamailio.sbc[150273]: DEBUG: sbc:<core> [core/usr_avp.c:637]: destroy_avp_list(): destroying list (nil) May 9 10:48:19 p01t-1 kamailio.sbc[150273]: DEBUG: sbc:<core> [core/usr_avp.c:637]: destroy_avp_list(): destroying list (nil) May 9 10:48:19 p01t-1 kamailio.sbc[150273]: DEBUG: sbc:<core> [core/usr_avp.c:637]: destroy_avp_list(): destroying list (nil) May 9 10:48:19 p01t-1 kamailio.sbc[150273]: DEBUG: sbc:<core> [core/usr_avp.c:637]: destroy_avp_list(): destroying list (nil) May 9 10:48:19 p01t-1 kamailio.sbc[150273]: DEBUG: sbc:<core> [core/usr_avp.c:637]: destroy_avp_list(): destroying list (nil) May 9 10:48:19 p01t-1 kamailio.sbc[150273]: DEBUG: sbc:<core> [core/usr_avp.c:637]: destroy_avp_list(): destroying list (nil) May 9 10:48:19 p01t-1 kamailio.sbc[150273]: DEBUG: sbc:<core> [core/xavp.c:541]: xavp_destroy_list(): destroying xavp list (nil) May 9 10:48:19 p01t-1 kamailio.sbc[150273]: DEBUG: sbc:<core> [core/xavp.c:541]: xavp_destroy_list(): destroying xavp list (nil) May 9 10:48:19 p01t-1 kamailio.sbc[150273]: DEBUG: sbc:<core> [core/xavp.c:541]: xavp_destroy_list(): destroying xavp list (nil) May 9 10:48:19 p01t-1 kamailio.sbc[150273]: DEBUG: sbc:<core> [core/receive.c:628]: receive_msg(): cleaning up May 9 10:48:19 p01t-1 kamailio.sbc[150273]: DEBUG: sbc:<core> [core/parser/sdp/sdp.c:863]: free_sdp(): _sdp = 0x7fa8d478c728 May 9 10:48:19 p01t-1 kamailio.sbc[150273]: DEBUG: sbc:<core> [core/parser/sdp/sdp.c:865]: free_sdp(): sdp = 0x7fa8d44ef100 May 9 10:48:19 p01t-1 kamailio.sbc[150273]: DEBUG: sbc:<core> [core/parser/sdp/sdp.c:867]: free_sdp(): session = 0x7fa8d44ee018
...
May 9 10:48:19 p01t-1 kamailio.sbc[150271]: DEBUG: sbc:<core> [core/tcp_main.c:1664]: _tcpconn_find(): found connection by peer address (id: 1) May 9 10:48:19 p01t-1 kamailio.sbc[150271]: DEBUG: sbc:<core> [core/tcp_main.c:2541]: tcpconn_send_put(): found fd in cache (11, 0x7fa8d0965140, 1) May 9 10:48:19 p01t-1 kamailio.sbc[150271]: DEBUG: sbc:<core> [core/tcp_main.c:2763]: tcpconn_do_send(): sending... May 9 10:48:19 p01t-1 kamailio.sbc[150271]: DEBUG: sbc:<core> [core/tcp_main.c:2796]: tcpconn_do_send(): after real write: c= 0x7fa8d0965140 n=1261 fd=11 May 9 10:48:19 p01t-1 kamailio.sbc[150271]: DEBUG: sbc:<core> [core/tcp_main.c:2797]: tcpconn_do_send(): buf= INVITE sip:22@192.168.41.157:39342;line=5z2d2k8i;ob SIP/2.0
...
```
Finally the Application Server in front cancels the call.
But look at this:
``` root@p01t-1:~# tcpdump -nn -i eth1 tcp port 5082 tcpdump: verbose output suppressed, use -v[v]... for full protocol decode listening on eth1, link-type EN10MB (Ethernet), snapshot length 262144 bytes 10:47:31.915062 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [.], ack 3024626659, win 501, options [nop,nop,TS val 924881395 ecr 4525523], length 0 10:47:31.916129 IP 10.101.65.130.39342 > 10.101.65.131.5082: Flags [.], ack 1, win 4836, options [nop,nop,TS val 4528662 ecr 924819977], length 0
10:48:02.635024 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [.], ack 1, win 501, options [nop,nop,TS val 924912115 ecr 4528662], length 0 10:48:02.636100 IP 10.101.65.130.39342 > 10.101.65.131.5082: Flags [.], ack 1, win 4836, options [nop,nop,TS val 4531734 ecr 924819977], length 0
----- switch port port shutdown ------
----- make the call:
10:48:19.690401 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 924929170 ecr 4531734], length 1261 10:48:19.899036 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 924929379 ecr 4531734], length 1261 10:48:20.331011 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 924929811 ecr 4531734], length 1261 10:48:21.194994 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 924930675 ecr 4531734], length 1261 10:48:22.891001 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 924932371 ecr 4531734], length 1261 10:48:26.446978 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 924935927 ecr 4531734], length 1261 10:48:33.355070 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 924942835 ecr 4531734], length 1261 10:48:40.011057 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 924949491 ecr 4531734], length 1261 10:48:46.667041 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 924956147 ecr 4531734], length 1261 10:48:53.323039 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 924962803 ecr 4531734], length 1261 10:48:59.979042 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 924969459 ecr 4531734], length 1261 10:49:06.635029 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 924976115 ecr 4531734], length 1261 10:49:13.291079 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 924982771 ecr 4531734], length 1261 10:49:19.947045 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 924989427 ecr 4531734], length 1261 10:49:26.603048 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 924996083 ecr 4531734], length 1261 10:49:33.259016 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925002739 ecr 4531734], length 1261 10:49:39.915052 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925009395 ecr 4531734], length 1261 10:49:46.571046 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925016051 ecr 4531734], length 1261 10:49:53.227015 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925022707 ecr 4531734], length 1261 10:49:59.883017 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925029363 ecr 4531734], length 1261 10:50:06.539037 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925036019 ecr 4531734], length 1261 10:50:13.195051 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925042675 ecr 4531734], length 1261 10:50:19.850986 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925049331 ecr 4531734], length 1261 10:50:26.507018 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925055987 ecr 4531734], length 1261 10:50:33.163011 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925062643 ecr 4531734], length 1261 10:50:39.819015 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925069299 ecr 4531734], length 1261 10:50:46.475056 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925075955 ecr 4531734], length 1261 10:50:53.135023 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925082615 ecr 4531734], length 1261 10:51:00.043094 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925089523 ecr 4531734], length 1261 10:51:06.699024 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925096179 ecr 4531734], length 1261 10:51:13.355049 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925102835 ecr 4531734], length 1261 10:51:20.011080 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925109491 ecr 4531734], length 1261 10:51:26.667023 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925116147 ecr 4531734], length 1261 10:51:33.323042 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925122803 ecr 4531734], length 1261 10:51:39.979029 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925129459 ecr 4531734], length 1261 10:51:46.635040 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925136115 ecr 4531734], length 1261 10:51:53.291007 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925142771 ecr 4531734], length 1261 10:51:59.947009 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925149427 ecr 4531734], length 1261 10:52:06.603019 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925156083 ecr 4531734], length 1261 10:52:13.259033 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925162739 ecr 4531734], length 1261 10:52:19.915011 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925169395 ecr 4531734], length 1261 10:52:26.571014 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925176051 ecr 4531734], length 1261 10:52:33.227032 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925182707 ecr 4531734], length 1261 10:52:39.883041 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925189363 ecr 4531734], length 1261 10:52:46.539013 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925196019 ecr 4531734], length 1261 10:52:53.199018 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925202679 ecr 4531734], length 1261 10:53:00.107035 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925209587 ecr 4531734], length 1261 10:53:06.763039 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925216243 ecr 4531734], length 1261 10:53:13.419041 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925222899 ecr 4531734], length 1261 10:53:20.075014 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925229555 ecr 4531734], length 1261 10:53:26.731046 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925236211 ecr 4531734], length 1261 10:53:33.387027 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925242867 ecr 4531734], length 1261 10:53:40.043077 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925249523 ecr 4531734], length 1261 10:53:46.699076 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925256179 ecr 4531734], length 1261 10:53:53.355055 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925262835 ecr 4531734], length 1261 10:54:00.011019 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925269491 ecr 4531734], length 1261 10:54:06.667071 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925276147 ecr 4531734], length 1261 10:54:13.323026 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925282803 ecr 4531734], length 1261 10:54:19.979077 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925289459 ecr 4531734], length 1261 10:54:26.635284 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925296115 ecr 4531734], length 1261 10:54:33.291019 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925302771 ecr 4531734], length 1261 10:54:39.946998 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925309427 ecr 4531734], length 1261 10:54:46.603049 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925316083 ecr 4531734], length 1261 10:54:53.259008 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925322739 ecr 4531734], length 1261 10:54:59.915019 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925329395 ecr 4531734], length 1261 10:55:06.571100 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925336051 ecr 4531734], length 1261 10:55:13.227056 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925342707 ecr 4531734], length 1261 10:55:19.883016 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925349363 ecr 4531734], length 1261 10:55:26.539021 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925356019 ecr 4531734], length 1261 10:55:33.195043 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925362675 ecr 4531734], length 1261 10:55:39.850991 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925369331 ecr 4531734], length 1261 10:55:46.507013 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925375987 ecr 4531734], length 1261 10:55:53.163060 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925382643 ecr 4531734], length 1261 10:55:59.819014 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925389299 ecr 4531734], length 1261 10:56:06.475045 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925395955 ecr 4531734], length 1261 10:56:13.131065 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925402611 ecr 4531734], length 1261 10:56:19.787052 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925409267 ecr 4531734], length 1261 10:56:26.443048 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925415923 ecr 4531734], length 1261 10:56:33.099016 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925422579 ecr 4531734], length 1261 10:56:39.755032 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925429235 ecr 4531734], length 1261 10:56:46.411005 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925435891 ecr 4531734], length 1261 10:56:53.067116 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925442547 ecr 4531734], length 1261 10:56:59.723032 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925449203 ecr 4531734], length 1261 10:57:06.379062 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925455859 ecr 4531734], length 1261 10:57:13.035003 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925462515 ecr 4531734], length 1261 10:57:19.691077 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925469171 ecr 4531734], length 1261 10:57:26.347050 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925475827 ecr 4531734], length 1261 10:57:33.003004 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925482483 ecr 4531734], length 1261 10:57:39.659029 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925489139 ecr 4531734], length 1261 10:57:46.314989 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925495795 ecr 4531734], length 1261 10:57:52.971040 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925502451 ecr 4531734], length 1261 10:57:59.631026 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925509111 ecr 4531734], length 1261 10:58:06.539039 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925516019 ecr 4531734], length 1261 10:58:13.195056 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925522675 ecr 4531734], length 1261 10:58:19.851012 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925529331 ecr 4531734], length 1261 10:58:26.507049 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925535987 ecr 4531734], length 1261 10:58:33.163017 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925542643 ecr 4531734], length 1261 10:58:39.819091 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925549299 ecr 4531734], length 1261 10:58:46.475017 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925555955 ecr 4531734], length 1261 10:58:53.131046 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925562611 ecr 4531734], length 1261 10:58:59.786990 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925569267 ecr 4531734], length 1261 10:59:06.443029 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925575923 ecr 4531734], length 1261 10:59:13.099009 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925582579 ecr 4531734], length 1261 10:59:19.754984 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925589235 ecr 4531734], length 1261 10:59:26.411053 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925595891 ecr 4531734], length 1261 10:59:33.067041 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925602547 ecr 4531734], length 1261 10:59:39.723053 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925609203 ecr 4531734], length 1261 10:59:46.379016 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925615859 ecr 4531734], length 1261 10:59:53.035054 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925622515 ecr 4531734], length 1261 10:59:59.691058 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925629171 ecr 4531734], length 1261 11:00:06.347021 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925635827 ecr 4531734], length 1261 11:00:13.003052 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925642483 ecr 4531734], length 1261 11:00:19.659043 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925649139 ecr 4531734], length 1261 11:00:26.315011 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925655795 ecr 4531734], length 1261 11:00:32.971015 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925662451 ecr 4531734], length 1261 11:00:39.627039 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925669107 ecr 4531734], length 1261 11:00:46.283052 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925675763 ecr 4531734], length 1261 11:00:52.939024 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925682419 ecr 4531734], length 1261 11:00:59.595048 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925689075 ecr 4531734], length 1261 11:01:06.251017 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925695731 ecr 4531734], length 1261 11:01:12.907013 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925702387 ecr 4531734], length 1261 11:01:19.563042 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925709043 ecr 4531734], length 1261 11:01:26.219027 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925715699 ecr 4531734], length 1261 11:01:32.875010 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925722355 ecr 4531734], length 1261 11:01:39.531004 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925729011 ecr 4531734], length 1261 11:01:46.187040 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925735667 ecr 4531734], length 1261 11:01:52.843002 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925742323 ecr 4531734], length 1261 11:01:59.499048 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925748979 ecr 4531734], length 1261 11:02:06.155027 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925755635 ecr 4531734], length 1261 11:02:12.811044 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925762291 ecr 4531734], length 1261 11:02:19.467018 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925768947 ecr 4531734], length 1261 11:02:26.123041 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925775603 ecr 4531734], length 1261 11:02:32.779046 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925782259 ecr 4531734], length 1261 11:02:39.435015 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925788915 ecr 4531734], length 1261 11:02:46.091034 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925795571 ecr 4531734], length 1261 11:02:52.747128 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925802227 ecr 4531734], length 1261 11:02:59.403096 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925808883 ecr 4531734], length 1261 11:03:06.059012 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925815539 ecr 4531734], length 1261 11:03:12.715029 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925822195 ecr 4531734], length 1261 11:03:19.370993 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925828851 ecr 4531734], length 1261 11:03:26.027010 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925835507 ecr 4531734], length 1261 11:03:32.683029 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925842163 ecr 4531734], length 1261 11:03:39.339046 IP 10.101.65.131.5082 > 10.101.65.130.39342: Flags [P.], seq 1:1262, ack 1, win 501, options [nop,nop,TS val 925848819 ecr 4531734], length 1261
```
### Possible Solutions
I have no idea why tcp_send_timeout is not set on the connected socket during spawning the listener for this client.
### Additional Information
``` root@p01t-1:~# kamailio -V version: kamailio 5.6.4 (x86_64/linux) flags: USE_TCP, USE_TLS, USE_SCTP, TLS_HOOKS, USE_RAW_SOCKS, DISABLE_NAGLE, USE_MCAST, DNS_IP_HACK, SHM_MMAP, PKG_MALLOC, Q_MALLOC, F_MALLOC, TLSF_MALLOC, DBG_SR_MEMORY, USE_FUTEX, FAST_LOCK-ADAPTIVE_WAIT, USE_DNS_CACHE, USE_DNS_FAILOVER, USE_NAPTR, USE_DST_BLOCKLIST, HAVE_RESOLV_RES, TLS_PTHREAD_MUTEX_SHARED ADAPTIVE_WAIT_LOOPS 1024, MAX_RECV_BUFFER_SIZE 262144, MAX_URI_SIZE 1024, BUF_SIZE 65535, DEFAULT PKG_SIZE 8MB poll method support: poll, epoll_lt, epoll_et, sigio_rt, select. id: unknown compiled with gcc 10.2.1 ```
* **Operating System**:
``` root@p01t-1:~# cat /etc/debian_version 11.7
Linux p01t-1.neotel.at 5.10.0-22-amd64 #1 SMP Debian 5.10.178-3 (2023-04-22) x86_64 GNU/Linux ``` [debug.log](https://github.com/kamailio/kamailio/files/11429302/debug.log)
I made working patch on the current master branch:
```diff --- a/src/core/tcp_main.c +++ b/src/core/tcp_main.c @@ -4324,10 +4324,25 @@ static inline int handle_new_connect(struct socket_info *si) struct tcp_connection *tcpconn; socklen_t su_len; int new_sock; + int optval;
/* got a connection on r */ su_len = sizeof(su); new_sock = accept(si->socket, &(su.s), &su_len); + + if ((optval = TICKS_TO_S(cfg_get(tcp, tcp_cfg, send_timeout)))) { + optval *= 1000; + if(setsockopt(new_sock, IPPROTO_TCP, TCP_USER_TIMEOUT, &optval, + sizeof(optval)) + < 0) { + LM_WARN("failed to set TCP_USER_TIMEOUT: %s\n", + strerror(errno)); + } else { + LM_INFO("Set new connection TCP_USER_TIMEOUT=%d ms\n", optval); + } + } + + if(unlikely(new_sock == -1)) { if((errno == EAGAIN) || (errno == EWOULDBLOCK)) return 0; ```
Now the retransmits do what is configured and time out after 3s.
``` Jul 27 18:14:15 p01t-1 kamailio.sbc[1182787]: INFO: <core> [core/tcp_main.c:4373]: handle_new_connect(): Set new connection TCP_USER_TIMEOUT=3000 ms ... Jul 27 18:14:49 p01t-1 kamailio.sbc[1182775]: INFO: sbc:<script>: >>> Sending Request: INVITE sip:22@192.168.41.157:51151;line=q9yhaejq;ob (10.84.65.131:5082 -> 10.84.65.130:51151: sip:193.84.65.130:51151;transport=tcp) Jul 27 18:14:52 p01t-1 kamailio.sbc[1182785]: NOTICE: <core> [core/tcp_read.c:267]: tcp_read_data(): error reading: Connection timed out (110) ```
Readings:
https://stackoverflow.com/questions/5907527/application-control-of-tcp-retra... https://man7.org/linux/man-pages/man7/tcp.7.html
Although said "This option, like many others, will be inherited by the socket returned by [accept(2)](https://man7.org/linux/man-pages/man2/accept.2.html), if it was set on the listening socket." => NO, it is not inherited (I tried it after init_sock_keepalive(sock_info->socket); line in tcp_main.c). So it seems it must be done on the spawned socket in handle_new_connect().
Needs more testing and must be done more pretty.
Erratum: It **is** inherited - I had oberwritten the TCP_USER_TIMEOUT in handle_new_connect() with a missing TICKS_TO_S() - so it was a too high value (ticks instead of seconds).
Tried again in tcp_init() on the listening socket:
```diff --- a/src/core/tcp_main.c +++ b/src/core/tcp_main.c @@ -3172,6 +3172,22 @@ int tcp_init(struct socket_info *sock_info) } #endif init_sock_keepalive(sock_info->socket); + + + if ((optval = TICKS_TO_S(cfg_get(tcp, tcp_cfg, send_timeout)))) { + optval *= 1000; + if(setsockopt(sock_info->socket, IPPROTO_TCP, TCP_USER_TIMEOUT, &optval, + sizeof(optval)) + < 0) { + LM_WARN("failed to set TCP_USER_TIMEOUT: %s\n", + strerror(errno)); + } else { + LM_INFO("Set TCP_USER_TIMEOUT=%d ms\n", optval); + } + } + + + if(bind(sock_info->socket, &addr->s, sockaddru_len(*addr)) == -1) { LM_ERR("bind(%x, %p, %d) on %s:%d : %s\n", sock_info->socket, &addr->s, (unsigned)sockaddru_len(*addr), sock_info->address_str.s, ```
=> working, too.
What is your opinion? Should it be in tcp_init() or in handle_new_connect()?
This issue is stale because it has been open 6 weeks with no activity. Remove stale label or comment or this will be closed in 2 weeks.
What is missing and why it doesnt go into upstream? Why it was not added to 5.7.2?
@schoberw your pull request got merged already some time ago. Is there something missing in this issue? Otherwise it should be closed.
Closed #3443 as completed.
The patch is a really small change. So it should be easy to add. I would aprreciate to find it in the stable branch to avoic private builds all the time.
I understand, that my task is done so far.
-
github-actions[bot] -
Henning Westerholt
-
schoberw