[sr-dev] [kamailio/kamailio] msrp: kamailio cannot create new TCP connection (#2215)

8 Feb 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@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

-- 
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

2024

2023

2022

2021

2020

2019

2018

2017

2016

2015

2014

2013

2012

2011

2010

2009

2008

[sr-dev] [kamailio/kamailio] msrp: kamailio cannot create new TCP connection (#2215)