### Description
Kamailio cannot create new `TCP` connection when.
1. used `msrp` module; 1. stated with option `-x tlsf`;
Kamailio send `SYN` packet, receive `SYN/ACK` and then Kamailio send `RST` packet. And you will get in log ``` 4(36) DEBUG: <core> [core/ip_addr.c:223]: print_ip(): tcpconn_new: new tcp connection: YYY.YYY.120.101 4(36) DEBUG: <core> [core/tcp_main.c:1174]: tcpconn_new(): on port 2855, type 2 4(36) DEBUG: <core> [core/tcp_main.c:1493]: tcpconn_add(): hashes: 3592:0:0, 3 4(36) DEBUG: <core> [core/tcp_main.c:2885]: tcpconn_1st_send(): pending write on new connection 0x7fab86821eb8 (-1/669 bytes written) (err: 11 - Resource temporarily unavailable) 4(36) ERROR: <core> [core/tcp_main.c:616]: _wbufq_add(): (669 bytes): write queue full or timeout (0, total -2038706176, last write 131535619 s ago) 4(36) ERROR: <core> [core/tcp_main.c:2904]: tcpconn_1st_send(): YYY.YYY.120.101:2855: EAGAIN and write queue full or failed for 0x7fab86821eb8 4(36) DEBUG: <core> [core/tcp_main.c:3171]: tcpconn_chld_put(): destroying connection 0x7fab86821eb8 (3, -1) flags 0060 4(36) ERROR: msrp [msrp_netio.c:180]: msrp_relay(): forwarding frame failed ```
### Troubleshooting
#### Reproduction
To reproduce issue need start kamailio with this config.
``` #!KAMAILIO
debug=2 memdbg=5 memlog=5
children=4
log_stderror=yes auto_aliases=no
tcp_accept_no_cl=yes tcp_connection_lifetime=1810
listen=tcp:eth0:2855
loadmodule "sl.so" loadmodule "msrp.so" loadmodule "pv.so" loadmodule "htable.so" loadmodule "xlog.so"
modparam("htable", "htable", "msrp=>size=8;")
request_route { sl_send_reply("403", "No SIP Here"); exit; }
reply_route { drop; }
event_route[msrp:frame-in] { xdbg("============#[[$msrp(method)]]===========\n"); xdbg("============*[[$si:$sp]]\n"); xdbg("============ crthop: [$msrp(crthop)]\n"); xdbg("============ prevhop: [$msrp(prevhop)]\n"); xdbg("============ nexthop: [$msrp(nexthop)]\n"); xdbg("============ firsthop: [$msrp(firsthop)]\n"); xdbg("============ lasthop: [$msrp(lasthop)]\n"); xdbg("============ prevhops: [$msrp(prevhops)]\n"); xdbg("============ nexthops: [$msrp(nexthops)]\n"); xdbg("============ srcaddr: [$msrp(srcaddr)]\n"); xdbg("============ srcsock: [$msrp(srcsock)]\n"); xdbg("============ sessid: [$msrp(sessid)]\n");
msrp_reply_flags("1");
if (msrp_is_reply()) { msrp_relay(); } else if ($msrp(method)=="SEND" || $msrp(method)=="REPORT") { if ($msrp(nexthops)>1) { if ($msrp(method)!="REPORT") { msrp_reply("200", "OK"); } msrp_relay(); exit; }
if($msrp(method)!="REPORT") { msrp_reply("200", "OK"); } msrp_relay(); } else { msrp_reply("501", "Request-method-not-understood"); } } ``` And send MSRP message via Kamailio.
You will get this output ``` 8(40) DEBUG: <core> [core/ip_addr.c:223]: print_ip(): tcpconn_new: new tcp connection: 91.224.133.8 8(40) DEBUG: <core> [core/tcp_main.c:1174]: tcpconn_new(): on port 51380, type 2 8(40) DEBUG: <core> [core/tcp_main.c:1493]: tcpconn_add(): hashes: 1780:844:2173, 1 8(40) DEBUG: <core> [core/io_wait.h:376]: io_watch_add(): DBG: io_watch_add(0x5647a5dbd800, 16, 2, 0x7fab8681db58), fd_no=12 8(40) DEBUG: <core> [core/io_wait.h:598]: io_watch_del(): DBG: io_watch_del (0x5647a5dbd800, 16, -1, 0x0) fd_no=13 called 8(40) DEBUG: <core> [core/tcp_main.c:4454]: handle_tcpconn_ev(): sending to child, events 1 8(40) DEBUG: <core> [core/tcp_main.c:4124]: send2child(): selected tcp worker idx:0 proc:4 pid:36 for activity on [tcp:XXX.XXX.120.100:2855], 0x7fab8681db58 4(36) DEBUG: <core> [core/tcp_read.c:1759]: handle_io(): received n=8 con=0x7fab8681db58, fd=4 4(36) DEBUG: <core> [core/tcp_read.c:1087]: msrp_process_msg(): MSRP Message: [[>>> MSRP 5279ea9b658f5933 SEND To-Path: msrp://XXX.XXX.120.100:2855/s.8167.4.1897294566;tcp msrp://YYY.YYY.120.101:2855/628b709ee0444396b567545d28cc5bc5;tcp From-Path: msrp://192.168.122.2:2855/4bc8884925ca0aeb314d;tcp Message-ID: 33f0c5fe84311abf Byte-Range: 1-0/0 -------5279ea9b658f5933$ <<<]] 4(36) DEBUG: msrp [msrp_parser.c:165]: msrp_parse_fline(): MSRP FLine: [1] [MSRP] [5279ea9b658f5933] [SEND] [1] [] 4(36) DEBUG: msrp [msrp_parser.c:325]: msrp_parse_headers(): MSRP Header: (0x7fab8a9490f0) [To-Path] [2] [msrp://XXX.XXX.120.100:2855/s.8167.4.1897294566;tcp msrp://YYY.YYY.120.101:2855/628b709ee0444396b567545d28cc5bc5;tcp] 4(36) DEBUG: msrp [msrp_parser.c:325]: msrp_parse_headers(): MSRP Header: (0x7fab8a949170) [From-Path] [1] [msrp://192.168.122.2:2855/4bc8884925ca0aeb314d;tcp] 4(36) DEBUG: msrp [msrp_parser.c:325]: msrp_parse_headers(): MSRP Header: (0x7fab8a9491f0) [Message-ID] [4] [33f0c5fe84311abf] 4(36) DEBUG: msrp [msrp_parser.c:325]: msrp_parse_headers(): MSRP Header: (0x7fab8a95d258) [Byte-Range] [5] [1-0/0] 4(36) DEBUG: <core> [core/parser/msg_parser.c:610]: parse_msg(): SIP Request: 4(36) DEBUG: <core> [core/parser/msg_parser.c:611]: parse_msg(): method: <MSRP> 4(36) DEBUG: <core> [core/parser/msg_parser.c:613]: parse_msg(): uri: sip:a@127.0.0.1 4(36) DEBUG: <core> [core/parser/msg_parser.c:615]: parse_msg(): version: <SIP/2.0> 4(36) DEBUG: <core> [core/parser/parse_via.c:1300]: parse_via_param(): Found param type 232, <branch> = <z9hG4bKa>; state=16 4(36) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5 4(36) DEBUG: <core> [core/parser/msg_parser.c:498]: parse_headers(): Via found, flags=2 4(36) DEBUG: <core> [core/parser/msg_parser.c:500]: parse_headers(): this is the first via 4(36) DEBUG: msrp [msrp_mod.c:538]: msrp_frame_received(): executing event_route[msrp:frame-in] (1) 4(36) DEBUG: <script>: xlog_helper(): ============#[[SEND]]=========== 4(36) DEBUG: <script>: xlog_helper(): ============*[[91.224.133.8:51380]] 4(36) DEBUG: <script>: xlog_helper(): ============ crthop: [msrp://XXX.XXX.120.100:2855/s.8167.4.1897294566;tcp] 4(36) DEBUG: <script>: xlog_helper(): ============ prevhop: [msrp://192.168.122.2:2855/4bc8884925ca0aeb314d;tcp] 4(36) DEBUG: <script>: xlog_helper(): ============ nexthop: [msrp://YYY.YYY.120.101:2855/628b709ee0444396b567545d28cc5bc5;tcp] 4(36) DEBUG: <script>: xlog_helper(): ============ firsthop: [msrp://192.168.122.2:2855/4bc8884925ca0aeb314d;tcp] 4(36) DEBUG: <script>: xlog_helper(): ============ lasthop: [msrp://YYY.YYY.120.101:2855/628b709ee0444396b567545d28cc5bc5;tcp] 4(36) DEBUG: <script>: xlog_helper(): ============ prevhops: [1] 4(36) DEBUG: <script>: xlog_helper(): ============ nexthops: [1] 4(36) DEBUG: <script>: xlog_helper(): ============ srcaddr: [msrp://91.224.133.8:51380] 4(36) DEBUG: <script>: xlog_helper(): ============ srcsock: [tcp:XXX.XXX.120.100:2855] 4(36) DEBUG: msrp [msrp_parser.c:565]: msrp_parse_uri(): MSRP URI: [msrp] [] [XXX.XXX.120.100] [2855] [s.8167.4.1897294566] [tcp] [] 4(36) DEBUG: <script>: xlog_helper(): ============ sessid: [s.8167.4.1897294566] 4(36) DEBUG: <core> [core/tcp_main.c:1589]: _tcpconn_find(): found connection by id: 1 4(36) DEBUG: <core> [core/tcp_main.c:2470]: tcpconn_send_put(): send from reader (36 (4)), reusing fd 4(36) DEBUG: <core> [core/tcp_main.c:2705]: tcpconn_do_send(): sending... 4(36) DEBUG: <core> [core/tcp_main.c:2738]: tcpconn_do_send(): after real write: c= 0x7fab8681db58 n=232 fd=4 4(36) DEBUG: <core> [core/tcp_main.c:2739]: tcpconn_do_send(): buf= MSRP 5279ea9b658f5933 200 OK To-Path: msrp://192.168.122.2:2855/4bc8884925ca0aeb314d;tcp From-Path: msrp://XXX.XXX.120.100:2855/s.8167.4.1897294566;tcp Message-ID: 33f0c5fe84311abf -------5279ea9b658f5933$
4(36) DEBUG: msrp [msrp_parser.c:565]: msrp_parse_uri(): MSRP URI: [msrp] [] [YYY.YYY.120.101] [2855] [628b709ee0444396b567545d28cc5bc5] [tcp] [] 4(36) DEBUG: <core> [core/tcp_main.c:1992]: tcp_send(): no open tcp connection found, opening new one 4(36) DEBUG: <core> [core/ip_addr.c:223]: print_ip(): tcpconn_new: new tcp connection: YYY.YYY.120.101 4(36) DEBUG: <core> [core/tcp_main.c:1174]: tcpconn_new(): on port 2855, type 2 4(36) DEBUG: <core> [core/tcp_main.c:1493]: tcpconn_add(): hashes: 3592:0:0, 2 4(36) DEBUG: <core> [core/tcp_main.c:2885]: tcpconn_1st_send(): pending write on new connection 0x7fab86821eb8 (-1/313 bytes written) (err: 11 - Resource temporarily unavailable) 4(36) ERROR: <core> [core/tcp_main.c:616]: _wbufq_add(): (313 bytes): write queue full or timeout (0, total -2038706176, last write 131535619 s ago) 4(36) ERROR: <core> [core/tcp_main.c:2904]: tcpconn_1st_send(): YYY.YYY.120.101:2855: EAGAIN and write queue full or failed for 0x7fab86821eb8 4(36) DEBUG: <core> [core/tcp_main.c:3171]: tcpconn_chld_put(): destroying connection 0x7fab86821eb8 (2, -1) flags 0060 4(36) ERROR: msrp [msrp_netio.c:180]: msrp_relay(): forwarding frame failed 4(36) DEBUG: <core> [core/io_wait.h:376]: io_watch_add(): DBG: io_watch_add(0x5647a5e01ba0, 4, 2, 0x7fab8681db58), fd_no=1 4(36) DEBUG: <core> [core/tcp_read.c:1087]: msrp_process_msg(): MSRP Message: [[>>> MSRP 7a06bb2f2057775 SEND To-Path: msrp://XXX.XXX.120.100:2855/s.8167.4.1897294566;tcp msrp://YYY.YYY.120.101:2855/628b709ee0444396b567545d28cc5bc5;tcp From-Path: msrp://192.168.122.2:2855/4bc8884925ca0aeb314d;tcp Message-ID: c019ad9285cb154e Byte-Range: 1-282/282 Success-Report: no Failure-Report: no Content-Type: message/cpim
From: dell sip:+12134567788@example.com To: sip:+12134237682@example.com DateTime: 2020-02-08T18:08:29.321289+03:00
MIME-Version: 1.0 Content-Type: text/plain
?OTRv3? I would like to start an Off-the-Record private conversation, but you do not seem to support that. -------7a06bb2f2057775$ <<<]] 4(36) DEBUG: msrp [msrp_parser.c:165]: msrp_parse_fline(): MSRP FLine: [1] [MSRP] [7a06bb2f2057775] [SEND] [1] [] 4(36) DEBUG: msrp [msrp_parser.c:325]: msrp_parse_headers(): MSRP Header: (0x7fab8a9490f0) [To-Path] [2] [msrp://XXX.XXX.120.100:2855/s.8167.4.1897294566;tcp msrp://YYY.YYY.120.101:2855/628b709ee0444396b567545d28cc5bc5;tcp] 4(36) DEBUG: msrp [msrp_parser.c:325]: msrp_parse_headers(): MSRP Header: (0x7fab8a949170) [From-Path] [1] [msrp://192.168.122.2:2855/4bc8884925ca0aeb314d;tcp] 4(36) DEBUG: msrp [msrp_parser.c:325]: msrp_parse_headers(): MSRP Header: (0x7fab8a9491f0) [Message-ID] [4] [c019ad9285cb154e] 4(36) DEBUG: msrp [msrp_parser.c:325]: msrp_parse_headers(): MSRP Header: (0x7fab8a95d258) [Byte-Range] [5] [1-282/282] 4(36) DEBUG: msrp [msrp_parser.c:325]: msrp_parse_headers(): MSRP Header: (0x7fab8a95d2d8) [Success-Report] [7] [no] 4(36) DEBUG: msrp [msrp_parser.c:325]: msrp_parse_headers(): MSRP Header: (0x7fab8a95d358) [Failure-Report] [0] [no] 4(36) DEBUG: msrp [msrp_parser.c:325]: msrp_parse_headers(): MSRP Header: (0x7fab8a95d3d8) [Content-Type] [8] [message/cpim] 4(36) DEBUG: msrp [msrp_parser.c:355]: msrp_parse_headers(): MSRP Body: [284] [[ From: dell sip:+12134567788@example.com To: sip:+12134237682@example.com DateTime: 2020-02-08T18:08:29.321289+03:00
MIME-Version: 1.0 Content-Type: text/plain
?OTRv3? I would like to start an Off-the-Record private conversation, but you do not seem to support that.
]] 4(36) DEBUG: <core> [core/parser/msg_parser.c:610]: parse_msg(): SIP Request: 4(36) DEBUG: <core> [core/parser/msg_parser.c:611]: parse_msg(): method: <MSRP> 4(36) DEBUG: <core> [core/parser/msg_parser.c:613]: parse_msg(): uri: sip:a@127.0.0.1 4(36) DEBUG: <core> [core/parser/msg_parser.c:615]: parse_msg(): version: <SIP/2.0> 4(36) DEBUG: <core> [core/parser/parse_via.c:1300]: parse_via_param(): Found param type 232, <branch> = <z9hG4bKa>; state=16 4(36) DEBUG: <core> [core/parser/parse_via.c:2639]: parse_via(): end of header reached, state=5 4(36) DEBUG: <core> [core/parser/msg_parser.c:498]: parse_headers(): Via found, flags=2 4(36) DEBUG: <core> [core/parser/msg_parser.c:500]: parse_headers(): this is the first via 4(36) DEBUG: msrp [msrp_mod.c:538]: msrp_frame_received(): executing event_route[msrp:frame-in] (1) 4(36) DEBUG: <script>: xlog_helper(): ============#[[SEND]]=========== 4(36) DEBUG: <script>: xlog_helper(): ============*[[91.224.133.8:51380]] 4(36) DEBUG: <script>: xlog_helper(): ============ crthop: [msrp://XXX.XXX.120.100:2855/s.8167.4.1897294566;tcp] 4(36) DEBUG: <script>: xlog_helper(): ============ prevhop: [msrp://192.168.122.2:2855/4bc8884925ca0aeb314d;tcp] 4(36) DEBUG: <script>: xlog_helper(): ============ nexthop: [msrp://YYY.YYY.120.101:2855/628b709ee0444396b567545d28cc5bc5;tcp] 4(36) DEBUG: <script>: xlog_helper(): ============ firsthop: [msrp://192.168.122.2:2855/4bc8884925ca0aeb314d;tcp] 4(36) DEBUG: <script>: xlog_helper(): ============ lasthop: [msrp://YYY.YYY.120.101:2855/628b709ee0444396b567545d28cc5bc5;tcp] 4(36) DEBUG: <script>: xlog_helper(): ============ prevhops: [1] 4(36) DEBUG: <script>: xlog_helper(): ============ nexthops: [1] 4(36) DEBUG: <script>: xlog_helper(): ============ srcaddr: [msrp://91.224.133.8:51380] 4(36) DEBUG: <script>: xlog_helper(): ============ srcsock: [tcp:XXX.XXX.120.100:2855] 4(36) DEBUG: msrp [msrp_parser.c:565]: msrp_parse_uri(): MSRP URI: [msrp] [] [XXX.XXX.120.100] [2855] [s.8167.4.1897294566] [tcp] [] 4(36) DEBUG: <script>: xlog_helper(): ============ sessid: [s.8167.4.1897294566] 4(36) DEBUG: <core> [core/tcp_main.c:1589]: _tcpconn_find(): found connection by id: 1 4(36) DEBUG: <core> [core/tcp_main.c:2470]: tcpconn_send_put(): send from reader (36 (4)), reusing fd 4(36) DEBUG: <core> [core/tcp_main.c:2705]: tcpconn_do_send(): sending... 4(36) DEBUG: <core> [core/tcp_main.c:2738]: tcpconn_do_send(): after real write: c= 0x7fab8681db58 n=230 fd=4 4(36) DEBUG: <core> [core/tcp_main.c:2739]: tcpconn_do_send(): buf= MSRP 7a06bb2f2057775 200 OK To-Path: msrp://192.168.122.2:2855/4bc8884925ca0aeb314d;tcp From-Path: msrp://XXX.XXX.120.100:2855/s.8167.4.1897294566;tcp Message-ID: c019ad9285cb154e -------7a06bb2f2057775$
4(36) DEBUG: msrp [msrp_parser.c:565]: msrp_parse_uri(): MSRP URI: [msrp] [] [YYY.YYY.120.101] [2855] [628b709ee0444396b567545d28cc5bc5] [tcp] [] 4(36) DEBUG: <core> [core/tcp_main.c:1992]: tcp_send(): no open tcp connection found, opening new one 4(36) DEBUG: <core> [core/ip_addr.c:223]: print_ip(): tcpconn_new: new tcp connection: YYY.YYY.120.101 4(36) DEBUG: <core> [core/tcp_main.c:1174]: tcpconn_new(): on port 2855, type 2 4(36) DEBUG: <core> [core/tcp_main.c:1493]: tcpconn_add(): hashes: 3592:0:0, 3 4(36) DEBUG: <core> [core/tcp_main.c:2885]: tcpconn_1st_send(): pending write on new connection 0x7fab86821eb8 (-1/669 bytes written) (err: 11 - Resource temporarily unavailable) 4(36) ERROR: <core> [core/tcp_main.c:616]: _wbufq_add(): (669 bytes): write queue full or timeout (0, total -2038706176, last write 131535619 s ago) 4(36) ERROR: <core> [core/tcp_main.c:2904]: tcpconn_1st_send(): YYY.YYY.120.101:2855: EAGAIN and write queue full or failed for 0x7fab86821eb8 4(36) DEBUG: <core> [core/tcp_main.c:3171]: tcpconn_chld_put(): destroying connection 0x7fab86821eb8 (3, -1) flags 0060 4(36) ERROR: msrp [msrp_netio.c:180]: msrp_relay(): forwarding frame failed ```
### Additional Information
* **Kamailio Version** - output of `kamailio -v`
``` /etc/kamailio # kamailio -v version: kamailio 5.4.0-dev3 (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_BLACKLIST, 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 on 19:57:02 Feb 6 2020 with gcc 9.2.0 ```
* **Operating System**: ``` / # cat /etc/os-release NAME="Alpine Linux" ID=alpine VERSION_ID=3.12_alpha20200122 PRETTY_NAME="Alpine Linux edge" HOME_URL="https://alpinelinux.org/" BUG_REPORT_URL="https://bugs.alpinelinux.org/" ``` Kamailio packaged into docker container `kamailio/kamailio-ci:master-alpine.debug`. Commit e9a19d5b4ebff9e06a061efdc5f2b91d4e1bf1b2