[sr-dev] [kamailio/kamailio] msrp: kamailio cannot create new TCP connection (#2215)
sergey-safarov
notifications at github.com
Sat Feb 8 19:30:21 CET 2020
### 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 at 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 at example.com>
To: <sip:+12134237682 at 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 at example.com>
To: <sip:+12134237682 at 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 at 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
--
You are receiving this because you are subscribed to this thread.
Reply to this email directly or view it on GitHub:
https://github.com/kamailio/kamailio/issues/2215
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.kamailio.org/pipermail/sr-dev/attachments/20200208/30734a8d/attachment-0001.html>
More information about the sr-dev
mailing list