Random crashes on tcp_main.c:handle_tcp_child() on FreeBSD

[drTr0jan]

Description

We've random crashes (approx one occurrence per day) on handle_tcp_child().

Troubleshooting

Reproduction

The crash appears sometimes on closing TLS session (it doesn't have to be gracefully) initiated by remote edge or other conditions.

Debugging Data

(lldb) target create "/usr/local/sbin/kamailio" --core "/var/coredump/986/kamailio.51059.core"
Core file '/var/coredump/986/kamailio.51059.core' (x86_64) was loaded.
(lldb) bt
* thread #1, name = 'kamailio', stop reason = signal SIGSEGV
  * frame #0: 0x0000000800a13cd4 libc.so.7`__je_large_dalloc(tsdn=0x0000000800d1a090, extent=0x0000000000000000) at jemalloc_large.c:346
    frame #1: 0x0000000800a3acb7 libc.so.7`__free [inlined] rtree_leaf_elm_lookup(tsdn=0x0000000800d1a090, rtree=<unavailable>, rtree_ctx=<unavailable>, key=<unavailable>, dependent=true, init_missing=false) at rtree.h:337:6
    frame #2: 0x0000000800a3acb2 libc.so.7`__free [inlined] rtree_read(tsdn=0x0000000800d1a090, rtree=<unavailable>, rtree_ctx=<unavailable>, key=<unavailable>, dependent=true) at rtree.h:406
    frame #3: 0x0000000800a3acb2 libc.so.7`__free [inlined] rtree_extent_read(tsdn=0x0000000800d1a090, rtree=<unavailable>, rtree_ctx=<unavailable>, key=<unavailable>, dependent=true) at rtree.h:418
    frame #4: 0x0000000800a3acb2 libc.so.7`__free [inlined] iealloc(tsdn=0x0000000800d1a090, ptr=0x00000008235782f0) at jemalloc_internal_inlines_b.h:82
    frame #5: 0x0000000800a3acb2 libc.so.7`__free [inlined] arena_dalloc(tsdn=0x0000000800d1a090, ptr=0x00000008235782f0, tcache=0x0000000800cf4c80, alloc_ctx=<unavailable>, slow_path=false) at arena_inlines_b.h:236
    frame #6: 0x0000000800a3ac91 libc.so.7`__free [inlined] idalloctm(tsdn=0x0000000800d1a090, ptr=0x00000008235782f0, tcache=0x0000000800cf4c80, alloc_ctx=<unavailable>, is_internal=false, slow_path=false) at jemalloc_internal_inlines_c.h:118
    frame #7: 0x0000000800a3ac91 libc.so.7`__free [inlined] ifree(tsd=<unavailable>, ptr=0x00000008235782f0, tcache=0x0000000800cf4c80, slow_path=false) at jemalloc_jemalloc.c:2226
    frame #8: 0x0000000800a3ac91 libc.so.7`__free(ptr=<unavailable>) at jemalloc_jemalloc.c:2382
    frame #9: 0x0000000800d9ed0b libthr.so.3`_thr_rwlock_destroy(rwlock=<unavailable>) at thr_rwlock.c:136:3
    frame #10: 0x00000008027feba3 libcrypto.so.111`CRYPTO_THREAD_lock_free(lock=0x0000000802e87e20) at threads_pthread.c:107:5
    frame #11: 0x00000008027ec676 libcrypto.so.111`BIO_free(a=0x0000000802e88920) at bio_lib.c:136:5
    frame #12: 0x00000008027ed572 libcrypto.so.111`BIO_free_all(bio=0x0000000000000000) at bio_lib.c:691:9
    frame #13: 0x0000000802540d0b libssl.so.111`SSL_free(s=0x0000000802e799a8) at ssl_lib.c:1160:5
    frame #14: 0x0000000802482fdd tls.so`tls_h_tcpconn_clean_f(c=0x0000000802e93270) at tls_server.c:655:3
    frame #15: 0x0000000000618bd8 kamailio`_tcpconn_free(c=0x0000000802e93270) at tcp_main.c:1528:58
    frame #16: 0x0000000000659534 kamailio`tcpconn_put_destroy(tcpconn=0x0000000802e93270) at tcp_main.c:3269:3
    frame #17: 0x0000000000668966 kamailio`handle_tcp_child(tcp_c=0x00000008014dcf68, fd_i=-1) at tcp_main.c:3706:5
    frame #18: 0x000000000065b7e9 kamailio`handle_io(fm=0x00000008014e6110, ev=1, idx=-1) at tcp_main.c:4523:8
    frame #19: 0x0000000000644502 kamailio`io_wait_loop_kqueue(h=0x00000000008dbf50, t=5, repeat=0) at io_wait.h:1187:9
    frame #20: 0x000000000063cb62 kamailio`tcp_main_loop at tcp_main.c:4824:5
    frame #21: 0x00000000002e973a kamailio`main_loop at main.c:1779:5
    frame #22: 0x00000000002f7650 kamailio`main(argc=7, argv=0x00007fffffffec68) at main.c:2856:6
    frame #23: 0x00000000002d1af0 kamailio`_start(ap=<unavailable>, cleanup=<unavailable>) at crt1.c:76:7

All backtraces are differ from other on frames downed handle_tcp_child() (frame #17 on the backtrace).

Log Messages

17:40:34.305319 51059 - - DEBUG: <core> [core/io_wait.h:600]: io_watch_del(): DBG: io_watch_del (0x8dbf50, 55, -1, 0x0) fd_no=46 called
17:40:34.305363 51059 - - DEBUG: <core> [core/tcp_main.c:4457]: handle_tcpconn_ev(): sending to child, events 11
17:40:34.305382 51059 - - DEBUG: <core> [core/tcp_main.c:4130]: send2child(): selected tcp worker idx:5 proc:30 pid:51056 for activity on [tls:91.217.xx.yy:5070], 0x802e93270
17:40:34.305430 51059 - - DEBUG: <core> [core/io_wait.h:600]: io_watch_del(): DBG: io_watch_del (0x8dbf50, 56, -1, 0x0) fd_no=45 called
17:40:34.305446 51059 - - DEBUG: <core> [core/tcp_main.c:4457]: handle_tcpconn_ev(): sending to child, events 11
17:40:34.305461 51059 - - DEBUG: <core> [core/tcp_main.c:4130]: send2child(): selected tcp worker idx:6 proc:31 pid:51057 for activity on [tls:91.217.xx.yy:5070], 0x802ea7430
17:40:34.305678 51059 - - DEBUG: <core> [core/tcp_main.c:3560]: handle_tcp_child(): reader response= 802e93270, -1 from 5 
17:40:34.305700 51059 - - DEBUG: tls [tls_server.c:683]: tls_h_tcpconn_close_f(): Closing SSL connection 0x802e9b3a8
17:40:35.024013 51026 - - ALERT: <core> [main.c:777]: handle_sigs(): child process 51059 exited by a signal 11

Additional Information

• Kamailio Version - output of kamailio -v

kamailio 5.4.3 (x86_64/freebsd) e19ae3
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, FAST_LOCK-ADAPTIVE_WAIT, USE_DNS_CACHE, USE_DNS_FAILOVER, USE_NAPTR, USE_DST_BLACKLIST, HAVE_RESOLV_RES
ADAPTIVE_WAIT_LOOPS 1024, MAX_RECV_BUFFER_SIZE 262144, MAX_URI_SIZE 1024, BUF_SIZE 65535, DEFAULT PKG_SIZE 8MB
poll method support: poll, select, kqueue.
id: e19ae3 
compiled on 14:45:07 Feb 11 2021 with cc FreeBSD clang version 10.0.1 (git@github.com:llvm/llvm-project.git llvmorg-10.0.1-0-gef32c611aa2)

• Operating System:

FreeBSD 12.2-STABLE r369029
OpenSSL 1.1.1i-freebsd  8 Dec 2020

[miconda]

This could be specific to FreeBSD and libssl. Is it openssl lib or libressl?

If it is openssl lib, maybe you can try to see if you can reproduce on Debian 10. I do not have any *BSD, not really familiar with FreeBSD, so I can't help much with this kind of environment, but maybe other devs want to jump in and try to help if they use *BSDes.

[drTr0jan]

@miconda, we use openssl. We can try to rebuild the kamailio with libressl support.

I've investigated the problem much more and found out the crash has appeared on handle_tcp_child() instead tls_h_tcpconn_clean_f().

Example:

Core file '/var/coredump/986/kamailio.4087.core' (x86_64) was loaded.
(lldb) bt all
* thread #1, name = 'kamailio', stop reason = signal SIGSEGV
  * frame #0: 0x00000008009fa56d libc.so.7`__je_tcache_bin_flush_small [inlined] extent_arena_get(extent=0x0000000000000000) at extent_inlines.h:39:43
    frame #1: 0x00000008009fa56d libc.so.7`__je_tcache_bin_flush_small(tsd=<unavailable>, tcache=<unavailable>, tbin=0x0000000800d1a2a8, binind=<unavailable>, rem=33) at jemalloc_tcache.c:123
    frame #2: 0x00000008009fa17c libc.so.7`__je_tcache_event_hard(tsd=<unavailable>, tcache=0x0000000800d1a250) at jemalloc_tcache.c:54:4
    frame #3: 0x0000000800a37934 libc.so.7`__malloc [inlined] arena_malloc(tsdn=0x0000000800d1a090, arena=0x0000000000000000, size=<unavailable>, ind=<unavailable>, zero=false, tcache=<unavailable>, slow_path=false) at arena_inlines_b.h:0
    frame #4: 0x0000000800a378a7 libc.so.7`__malloc [inlined] iallocztm(tsdn=0x0000000800d1a090, size=<unavailable>, ind=<unavailable>, zero=false, tcache=<unavailable>, is_internal=false, arena=0x0000000000000000, slow_path=false) at jemalloc_internal_inlines_c.h:53
    frame #5: 0x0000000800a378a7 libc.so.7`__malloc [inlined] imalloc_no_sample(sopts=<unavailable>, dopts=<unavailable>, tsd=<unavailable>, size=<unavailable>, usize=<unavailable>, ind=<unavailable>) at jemalloc_jemalloc.c:1713
    frame #6: 0x0000000800a378a7 libc.so.7`__malloc [inlined] imalloc_body(sopts=<unavailable>, dopts=<unavailable>, tsd=<unavailable>) at jemalloc_jemalloc.c:1909
    frame #7: 0x0000000800a378a7 libc.so.7`__malloc [inlined] imalloc(sopts=<unavailable>, dopts=<unavailable>) at jemalloc_jemalloc.c:2009
    frame #8: 0x0000000800a3768b libc.so.7`__malloc(size=<unavailable>) at jemalloc_jemalloc.c:2042
    frame #9: 0x0000000800acaf34 libc.so.7`__smakebuf(fp=0x0000000800d06010) at makebuf.c:73:11
    frame #10: 0x0000000800acae39 libc.so.7`__swsetup(fp=0x0000000800d06010) at wsetup.c:82:3
    frame #11: 0x0000000800a67b53 libc.so.7`__vfprintf(fp=0x0000000800d06010, locale=0x0000000800ade698, fmt0="", ap=0x00007fffffff8cf0) at vfprintf.c:462:6
    frame #12: 0x0000000800a678c5 libc.so.7`vfprintf_l(fp=0x0000000800d06010, locale=0x0000000800ade698, fmt0="", ap=0x00007fffffff8cf0) at vfprintf.c:285:9
    frame #13: 0x0000000800a6f113 libc.so.7`fprintf(fp=<unavailable>, fmt=<unavailable>) at fprintf.c:57:8
    frame #14: 0x0000000800aa8f01 libc.so.7`vsyslog [inlined] vsyslog1(pri=135, fmt="", ap=0x00007fffffff9c50) at syslog.c:173:8
    frame #15: 0x0000000800aa8e4c libc.so.7`vsyslog(pri=<unavailable>, fmt="", ap=0x00007fffffff9c50) at syslog.c:363
    frame #16: 0x0000000800aa8dcd libc.so.7`syslog(pri=<unavailable>, fmt=<unavailable>) at syslog.c:129:2
    frame #17: 0x00000000006655dc kamailio`handle_tcp_child(tcp_c=0x00000008014dcf08, fd_i=-1) at tcp_main.c:3559:2
    frame #18: 0x000000000065b7e9 kamailio`handle_io(fm=0x00000008014e6080, ev=1, idx=-1) at tcp_main.c:4523:8
    frame #19: 0x0000000000644502 kamailio`io_wait_loop_kqueue(h=0x00000000008dbf50, t=5, repeat=0) at io_wait.h:1187:9
    frame #20: 0x000000000063cb62 kamailio`tcp_main_loop at tcp_main.c:4824:5
    frame #21: 0x00000000002e973a kamailio`main_loop at main.c:1779:5
    frame #22: 0x00000000002f7650 kamailio`main(argc=7, argv=0x00007fffffffec70) at main.c:2856:6
    frame #23: 0x00000000002d1af0 kamailio`_start(ap=<unavailable>, cleanup=<unavailable>) at crt1.c:76:7

or

    frame #8: 0x0000000800aa8d8d libc.so.7`syslog(pri=<unavailable>, fmt=<unavailable>) at syslog.c:132:2
    frame #9: 0x00000000006688b7 kamailio`handle_tcp_child(tcp_c=0x00000008014dcec8, fd_i=-1) at tcp_main.c:3686:4
    frame #10: 0x000000000065b7e9 kamailio`handle_io(fm=0x00000008014e6020, ev=1, idx=-1) at tcp_main.c:4523:8

or

    frame #20: 0x000000000063f216 kamailio`io_watch_add(h=0x00000000008dbf50, fd=53, events=1, type=2, data=0x0000000802e6f740) at io_wait.h:374:2
    frame #21: 0x0000000000667805 kamailio`handle_tcp_child(tcp_c=0x00000008014dcf28, fd_i=-1) at tcp_main.c:3664:7
    frame #22: 0x000000000065b7e9 kamailio`handle_io(fm=0x00000008014e60b0, ev=1, idx=-1) at tcp_main.c:4523:8

What do you think might be causing the problem?

[miconda]

It is known not to work with libssl, they removed some features from libssl that are needed by Kamailio (iirc, custom memory management).

Are those crashes by a kamailio with tls module still loaded, or not?

For the core of the first backtrace in the previous comment, can you get the output of the gdb commands:

frame 17
info locals
list
p tcp_children

I see you use lldb, not that familiar with, that's why I gave the gdb commands, probably you can find the equivalent of them.

[drTr0jan]

@miconda, do you prefer a libressl?

Yep, Kamailio is with a tls module.

(lldb) f 17
frame #17: 0x0000000000668966 kamailio`handle_tcp_child(tcp_c=0x00000008014dcf68, fd_i=-1) at tcp_main.c:3706:5

(lldb) fr v
(tcp_child *) tcp_c = 0x00000008014dcf68
(int) fd_i = -1
(tcp_connection *) tcpconn = 0x0000000802e93270
(long [2]) response = ([0] = 34408575600, [1] = -1)
(int) cmd = -1
(int) bytes = 16
(int) n = 0
(ticks_t) t = 745497382
(ticks_t) crt_timeout = 28880
(ticks_t) con_lifetime = 28880

(lldb) ta v tcp_children
(tcp_child *) tcp_children = 0x00000008014dcec8

there're no sources on a target machine for the list/source list command

P.S. We can help to find the possible bug in our environment. But if you suggest where to look.

[sergey-safarov]

I think this also not will work with libressl.
Reson: some time ago Alpine Linux have used libressl and with libressl TLS connection also lead to Kamaili crashes.

[miconda]

It is known not to work with libressl, I wanted to be sure that is not used.

Can you also get the output for:

p *tcp_children
p *tcpconn
p *tcp_c

[drTr0jan]

@miconda, we use only OpenSSL.

(lldb) p *tcp_children
(tcp_child) $0 = {
  pid = 51051
  proc_no = 25
  unix_sock = 40
  busy = 0
  mysocket = 0x0000000000000000
  n_reqs = 56
}

(lldb) p *tcpconn
(tcp_connection) $2 = {
  s = -1
  fd = -1
  write_lock = 0
  id = 29
  reader_pid = 0
  rcv = {
    src_ip = {
      af = 2
      len = 4
      u = {
        addrl = ([0] = 1404229979, [1] = 0)
        addr32 = ([0] = 1404229979, [1] = 0, [2] = 0, [3] = 0)
        addr16 = ([0] = 55643, [1] = 21426, [2] = 0, [3] = 0, [4] = 0, [5] = 0, [6] = 0, [7] = 0)
        addr = {
          [0] = '['
          [1] = '\xd9'
          [2] = '\xb2'
          [3] = 'S'
          [4] = '\0'
          [5] = '\0'
          [6] = '\0'
          [7] = '\0'
          [8] = '\0'
          [9] = '\0'
          [10] = '\0'
          [11] = '\0'
          [12] = '\0'
          [13] = '\0'
          [14] = '\0'
          [15] = '\0'
        }
      }
    }
    dst_ip = {
      af = 2
      len = 4
      u = {
        addrl = ([0] = 1555224923, [1] = 0)
        addr32 = ([0] = 1555224923, [1] = 0, [2] = 0, [3] = 0)
        addr16 = ([0] = 55643, [1] = 23730, [2] = 0, [3] = 0, [4] = 0, [5] = 0, [6] = 0, [7] = 0)
        addr = {
          [0] = '['
          [1] = '\xd9'
          [2] = '\xb2'
          [3] = '\'
          [4] = '\0'
          [5] = '\0'
          [6] = '\0'
          [7] = '\0'
          [8] = '\0'
          [9] = '\0'
          [10] = '\0'
          [11] = '\0'
          [12] = '\0'
          [13] = '\0'
          [14] = '\0'
          [15] = '\0'
        }
      }
    }
    src_port = 5071
    dst_port = 0
    proto_reserved1 = 29
    proto_reserved2 = 0
    src_su = {
      s = (sa_len = '\x10', sa_family = '\x02', sa_data = char [14] @ 0x000000083078485a)
      sin = {
        sin_len = '\x10'
        sin_family = '\x02'
        sin_port = 53011
        sin_addr = (s_addr = 1404229979)
        sin_zero = {
          [0] = '\0'
          [1] = '\0'
          [2] = '\0'
          [3] = '\0'
          [4] = '\0'
          [5] = '\0'
          [6] = '\0'
          [7] = '\0'
        }
      }
      sin6 = {
        sin6_len = '\x10'
        sin6_family = '\x02'
        sin6_port = 53011
        sin6_flowinfo = 1404229979
        sin6_addr = {
          __u6_addr = {
            __u6_addr8 = {
              [0] = '\0'
              [1] = '\0'
              [2] = '\0'
              [3] = '\0'
              [4] = '\0'
              [5] = '\0'
              [6] = '\0'
              [7] = '\0'
              [8] = '\0'
              [9] = '\0'
              [10] = '\0'
              [11] = '\0'
              [12] = '\0'
              [13] = '\0'
              [14] = '\0'
              [15] = '\0'
            }
            __u6_addr16 = ([0] = 0, [1] = 0, [2] = 0, [3] = 0, [4] = 0, [5] = 0, [6] = 0, [7] = 0)
            __u6_addr32 = ([0] = 0, [1] = 0, [2] = 0, [3] = 0)
          }
        }
        sin6_scope_id = 0
      }
      sas = (ss_len = '\x10', ss_family = '\x02', __ss_pad1 = char [6] @ 0x000000083078485a, __ss_align = 0, __ss_pad2 = char [112] @ 0x0000000830784868)
    }
    bind_address = 0x0000000801492170
    proto = '\x03'
    proto_pad0 = '\0'
    proto_pad1 = 0
  }
  cinfo = {
    src_ip = {
      af = 0
      len = 0
      u = {
        addrl = ([0] = 0, [1] = 0)
        addr32 = ([0] = 0, [1] = 0, [2] = 0, [3] = 0)
        addr16 = ([0] = 0, [1] = 0, [2] = 0, [3] = 0, [4] = 0, [5] = 0, [6] = 0, [7] = 0)
        addr = {
          [0] = '\0'
          [1] = '\0'
          [2] = '\0'
          [3] = '\0'
          [4] = '\0'
          [5] = '\0'
          [6] = '\0'
          [7] = '\0'
          [8] = '\0'
          [9] = '\0'
          [10] = '\0'
          [11] = '\0'
          [12] = '\0'
          [13] = '\0'
          [14] = '\0'
          [15] = '\0'
        }
      }
    }
    dst_ip = {
      af = 0
      len = 0
      u = {
        addrl = ([0] = 0, [1] = 0)
        addr32 = ([0] = 0, [1] = 0, [2] = 0, [3] = 0)
        addr16 = ([0] = 0, [1] = 0, [2] = 0, [3] = 0, [4] = 0, [5] = 0, [6] = 0, [7] = 0)
        addr = {
          [0] = '\0'
          [1] = '\0'
          [2] = '\0'
          [3] = '\0'
          [4] = '\0'
          [5] = '\0'
          [6] = '\0'
          [7] = '\0'
          [8] = '\0'
          [9] = '\0'
          [10] = '\0'
          [11] = '\0'
          [12] = '\0'
          [13] = '\0'
          [14] = '\0'
          [15] = '\0'
        }
      }
    }
    src_port = 0
    dst_port = 0
    proto = 0
    csocket = 0x0000000000000000
  }
  req = {
    next = 0x0000000000000000
    buf = 0x0000000802e93610 "\r\n\r\n2.0 487 Request Terminated\r\nVia: SIP/2.0/TLS 91.217.xx.yy:5070;rport=12181;received=91.217.xx.yy;branch=z9hG4bK6b3e.a1465b8bd9ff395e0dd82d3998ac2841.0;i=1\r\nVia: SIP/2.0/UDP 127.0.0.127;branch=z9hG4bKsr-TU0.jAsiBomT.bdNBXQqjzxIGo33Go3q8XebBLYqG-n0YIKJVvKQlXxrGg3-Bg3C8AQiBz.qGbpslupJVzWqwhmqVLUb8Lxr8zWRwv4iYINmFz0epApRgAxUGL.q8zx-BAd*\r\nRecord-Route: <sip:91.217.xx.yy:5070;transport=tls;lr;r2=on;ftag=304836990;nat=yes>\r\nRecord-Route: <sip:127.0.0.127;line=sr-wI0rGzQCjzsC8q3C8ANiGXskVZnO258r2-nUlapzwLWqBzbM2zWtwzbM2zWvVh45lXBr8LNA8zQEBLWiYa.mFuKA>\r\nCall-ID: 1675015211@192.168.88.25\r\nFrom: "222" <sip:222@pbx.domain.tld>;tag=304836990\r\nTo: <sip:333@pbx.domain.tld>;tag=0cd46e4d-0a5b-4574-8984-dbe7076db118\r\nCSeq: 2 INVITE\r\nServer: PBX\r\nAllow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REFER\r\nRemote-Party-ID: "phone3" <sip:333@pbx.domain.tld>;party=called;privacy=off;screen=no\r\nContent-Length:  0\r\n\r\n=off;screen=no\r\nContent-Length:  0\r\n\r\n0\r\n\r\n\na=ptime:20\r\na=maxptime:150\r\na=sendre"
    start = 0x0000000802e93610 "\r\n\r\n2.0 487 Request Terminated\r\nVia: SIP/2.0/TLS 91.217.xx.yy:5070;rport=12181;received=91.217.xx.yy;branch=z9hG4bK6b3e.a1465b8bd9ff395e0dd82d3998ac2841.0;i=1\r\nVia: SIP/2.0/UDP 127.0.0.127;branch=z9hG4bKsr-TU0.jAsiBomT.bdNBXQqjzxIGo33Go3q8XebBLYqG-n0YIKJVvKQlXxrGg3-Bg3C8AQiBz.qGbpslupJVzWqwhmqVLUb8Lxr8zWRwv4iYINmFz0epApRgAxUGL.q8zx-BAd*\r\nRecord-Route: <sip:91.217.xx.yy:5070;transport=tls;lr;r2=on;ftag=304836990;nat=yes>\r\nRecord-Route: <sip:127.0.0.127;line=sr-wI0rGzQCjzsC8q3C8ANiGXskVZnO258r2-nUlapzwLWqBzbM2zWtwzbM2zWvVh45lXBr8LNA8zQEBLWiYa.mFuKA>\r\nCall-ID: 1675015211@192.168.88.25\r\nFrom: "222" <sip:222@pbx.domain.tld>;tag=304836990\r\nTo: <sip:333@pbx.domain.tld>;tag=0cd46e4d-0a5b-4574-8984-dbe7076db118\r\nCSeq: 2 INVITE\r\nServer: PBX\r\nAllow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REFER\r\nRemote-Party-ID: "phone3" <sip:333@pbx.domain.tld>;party=called;privacy=off;screen=no\r\nContent-Length:  0\r\n\r\n=off;screen=no\r\nContent-Length:  0\r\n\r\n0\r\n\r\n\na=ptime:20\r\na=maxptime:150\r\na=sendre"
    pos = 0x0000000802e93610 "\r\n\r\n2.0 487 Request Terminated\r\nVia: SIP/2.0/TLS 91.217.xx.yy:5070;rport=12181;received=91.217.xx.yy;branch=z9hG4bK6b3e.a1465b8bd9ff395e0dd82d3998ac2841.0;i=1\r\nVia: SIP/2.0/UDP 127.0.0.127;branch=z9hG4bKsr-TU0.jAsiBomT.bdNBXQqjzxIGo33Go3q8XebBLYqG-n0YIKJVvKQlXxrGg3-Bg3C8AQiBz.qGbpslupJVzWqwhmqVLUb8Lxr8zWRwv4iYINmFz0epApRgAxUGL.q8zx-BAd*\r\nRecord-Route: <sip:91.217.xx.yy:5070;transport=tls;lr;r2=on;ftag=304836990;nat=yes>\r\nRecord-Route: <sip:127.0.0.127;line=sr-wI0rGzQCjzsC8q3C8ANiGXskVZnO258r2-nUlapzwLWqBzbM2zWtwzbM2zWvVh45lXBr8LNA8zQEBLWiYa.mFuKA>\r\nCall-ID: 1675015211@192.168.88.25\r\nFrom: "222" <sip:222@pbx.domain.tld>;tag=304836990\r\nTo: <sip:333@pbx.domain.tld>;tag=0cd46e4d-0a5b-4574-8984-dbe7076db118\r\nCSeq: 2 INVITE\r\nServer: PBX\r\nAllow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REFER\r\nRemote-Party-ID: "phone3" <sip:333@pbx.domain.tld>;party=called;privacy=off;screen=no\r\nContent-Length:  0\r\n\r\n=off;screen=no\r\nContent-Length:  0\r\n\r\n0\r\n\r\n\na=ptime:20\r\na=maxptime:150\r\na=sendre"
    parsed = 0x0000000802e93610 "\r\n\r\n2.0 487 Request Terminated\r\nVia: SIP/2.0/TLS 91.217.xx.yy:5070;rport=12181;received=91.217.xx.yy;branch=z9hG4bK6b3e.a1465b8bd9ff395e0dd82d3998ac2841.0;i=1\r\nVia: SIP/2.0/UDP 127.0.0.127;branch=z9hG4bKsr-TU0.jAsiBomT.bdNBXQqjzxIGo33Go3q8XebBLYqG-n0YIKJVvKQlXxrGg3-Bg3C8AQiBz.qGbpslupJVzWqwhmqVLUb8Lxr8zWRwv4iYINmFz0epApRgAxUGL.q8zx-BAd*\r\nRecord-Route: <sip:91.217.xx.yy:5070;transport=tls;lr;r2=on;ftag=304836990;nat=yes>\r\nRecord-Route: <sip:127.0.0.127;line=sr-wI0rGzQCjzsC8q3C8ANiGXskVZnO258r2-nUlapzwLWqBzbM2zWtwzbM2zWvVh45lXBr8LNA8zQEBLWiYa.mFuKA>\r\nCall-ID: 1675015211@192.168.88.25\r\nFrom: "222" <sip:222@pbx.domain.tld>;tag=304836990\r\nTo: <sip:333@pbx.domain.tld>;tag=0cd46e4d-0a5b-4574-8984-dbe7076db118\r\nCSeq: 2 INVITE\r\nServer: PBX\r\nAllow: OPTIONS, SUBSCRIBE, NOTIFY, PUBLISH, INVITE, ACK, BYE, CANCEL, UPDATE, PRACK, REFER\r\nRemote-Party-ID: "phone3" <sip:333@pbx.domain.tld>;party=called;privacy=off;screen=no\r\nContent-Length:  0\r\n\r\n=off;screen=no\r\nContent-Length:  0\r\n\r\n0\r\n\r\n\na=ptime:20\r\na=maxptime:150\r\na=sendre"
    body = 0x0000000000000000 <no value available>
    b_size = 16383
    content_len = 0
    chunk_size = 0
    flags = 0
    bytes_to_go = 0
    error = TCP_REQ_OK
    state = H_SKIP_EMPTY
  }
  refcnt = (val = 0)
  type = PROTO_TLS
  flags = 296
  send_flags = (f = 4, blst_imask = 0)
  state = S_CONN_BAD
  extra_data = 0x0000000802e9b3a8
  timer = {
    next = 0x0000000000000000
    prev = 0x0000000000000000
    expire = 745506227
    initial_timeout = 9600
    data = 0x0000000802e93270
    f = 0x000000000060e510 (kamailio`tcpconn_main_timeout at tcp_main.c:4545)
    flags = 512
    slow_idx = 0
  }
  timeout = 745497609
  lifetime = 9600
  id_hash = 29
  id_next = 0x0000000000000000
  id_prev = 0x0000000000000000
  c_next = 0x0000000000000000
  c_prev = 0x0000000000000000
  con_aliases = {
    [0] = {
      parent = 0x0000000802e93270
      next = 0x0000000000000000
      prev = 0x0000000000000000
      port = 5071
      hash = 1675
    }
    [1] = {
      parent = 0x0000000802e93270
      next = 0x0000000000000000
      prev = 0x0000000000000000
      port = 5071
      hash = 1127
    }
    [2] = {
      parent = 0x0000000000000000
      next = 0x0000000000000000
      prev = 0x0000000000000000
      port = 0
      hash = 0
    }
    [3] = {
      parent = 0x0000000000000000
      next = 0x0000000000000000
      prev = 0x0000000000000000
      port = 0
      hash = 0
    }
    [4] = {
      parent = 0x0000000000000000
      next = 0x0000000000000000
      prev = 0x0000000000000000
      port = 0
      hash = 0
    }
    [5] = {
      parent = 0x0000000000000000
      next = 0x0000000000000000
      prev = 0x0000000000000000
      port = 0
      hash = 0
    }
    [6] = {
      parent = 0x0000000000000000
      next = 0x0000000000000000
      prev = 0x0000000000000000
      port = 0
      hash = 0
    }
    [7] = {
      parent = 0x0000000000000000
      next = 0x0000000000000000
      prev = 0x0000000000000000
      port = 0
      hash = 0
    }
    [8] = {
      parent = 0x0000000000000000
      next = 0x0000000000000000
      prev = 0x0000000000000000
      port = 0
      hash = 0
    }
    [9] = {
      parent = 0x0000000000000000
      next = 0x0000000000000000
      prev = 0x0000000000000000
      port = 0
      hash = 0
    }
    [10] = {
      parent = 0x0000000000000000
      next = 0x0000000000000000
      prev = 0x0000000000000000
      port = 0
      hash = 0
    }
    [11] = {
      parent = 0x0000000000000000
      next = 0x0000000000000000
      prev = 0x0000000000000000
      port = 0
      hash = 0
    }
  }
  aliases = 0
  wbuf_q = {
    first = 0x0000000000000000
    last = 0x0000000000000000
    wr_timeout = 0
    queued = 0
    offset = 0
    last_used = 0
  }
}

(lldb) p *tcp_c
(tcp_child) $1 = {
  pid = 51056
  proc_no = 30
  unix_sock = 50
  busy = 0
  mysocket = 0x0000000000000000
  n_reqs = 56
}

[poandrei]

From the initial dump it looks like the problem is with ssl and memory management (it uses the wrong malloc).

[dwagin]

Crash with CRYPTO_THREAD_lock_free() fixed

FreeBSD Bugzilla – Bug 255486

The problem was that the implementation of the pthreads library is different. pthread_rwlock_init() function was allocating memory in a non-shared area.

[drTr0jan]

I'm closing the issue as a resolved main annoying problem.

I will open new issue if new problem will have occured (ex. on syslog() function).