Description

Kamailio cannot create new TCP connection when.

  1. used msrp module;
  2. 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

/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

/ # 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 e9a19d5

—
You are receiving this because you are subscribed to this thread.
Reply to this email directly, view it on GitHub, or unsubscribe.