### 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
Hi Sergey, did not looked that much into it - but one question: does it only happens with the TLSF memory manager, and not with the default?
yes, Henning, only with TLSF On default manager connection created properly.
@sergey-safarov - that error code and error message (11 - Resource temporarily unavailable)) typically happens when the target accepts the connection but it doesn't read data, so the sender app is filling the socket buffer.
From the logs, the connection is created and added to the internal hash, so that is not the problem, but transmitting the data seems to be the issue. What is the receiving party? A sip phone with msrp support, or some generic tool?
On the other hand, it is strange that you get it when using tlsf memory manager ...
Daniel, received is FreeSwitch. As wrote above Kamailio do not send any data. Kamailio just send two packets. 1) `SYN` and receive `SYN/ACK` packet; 2) `RST` packet.
Also I start kamailio without `-x tlsf` arg with same config to same FreeSwitch, then Kamailio able send MSP message to FreeSwitch.
The errno and errno string are printed because send() on tcp socket failed, but that is after the connection was established.
Anyhow, the error might have been because of a shared pointer not being initialized, that resulted in closing the connection. I pushed a commit to master branch, can you give it a try and see how it goes this time?
Closed #2215.
I have tested 994a8dfc070d84b5dad28fa873d8759280c910f2 commit Now `TCP` connection opens properly.