Kamailio 5.6 (and 5.7) core dumps with uac_req_send() from uac module

[MattisLind]

Description

We have a quite basic scenario which sends a SIP MESSAGE and then receives SIP MESSAGE back. It also sets up two voice calls using SIP INVITE. It is only this specific scenario that is causing the core dump. Some time the core dump occur just a few seconds after the call/message scenario, but occasionally it takes up to 50 minutes.

We have been using the uac module for sending SIP MESSAGE in several other scenarios without experiencing a crash.

We always see the same lines in the log just prior to the core dump: CRITICAL: [core/pass_fd.c:281]: receive_fd(): EOF on 49

We are using Kamailio 5.6 retrieved from the kamailio repository: http://deb.kamailio.org/kamailio56. We are running Kamailio in a Docker container which runs on 5.10.0-25-cloud-amd64 #1 SMP Debian 5.10.191-1 (2023-08-16) x86_64 GNU/Linux

We have also tried Kamailio 5.7 from the same repo which crashes in exactly the same way.

Troubleshooting

Reproduction

We have troubles to consistently reproduce it and it only happen from time to time when running a specific scenario sending SIP MESSAGE using the uac module. It does not happen for every call of this call scenario. At one instance Kamailo crashed with just 15 seconds in-between during the call scenario.

Debugging Data

# gdb  /usr/sbin/kamailio  /core
GNU gdb (Debian 10.1-1.7) 10.1.90.20210103-git
Copyright (C) 2021 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.
Type "show copying" and "show warranty" for details.
This GDB was configured as "x86_64-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<https://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
    <http://www.gnu.org/software/gdb/documentation/>.

For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from /usr/sbin/kamailio...
(No debugging symbols found in /usr/sbin/kamailio)

warning: Can't open file /dev/zero (deleted) during file-backed mapping note processing
[New LWP 4777]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
Core was generated by `/usr/sbin/kamailio -DD -M 18 -m 192 -A serverId=17173 -A sendTraceLocal="sip:10'.
Program terminated with signal SIGSEGV, Segmentation fault.
#0  __strlen_evex () at ../sysdeps/x86_64/multiarch/strlen-evex.S:77
77	../sysdeps/x86_64/multiarch/strlen-evex.S: No such file or directory.
(gdb) bt full
#0  __strlen_evex () at ../sysdeps/x86_64/multiarch/strlen-evex.S:77
No locals.
#1  0x00007f5425e34b78 in __vfprintf_internal (s=s@entry=0x55a06e969a60, 
    format=format@entry=0x55a06e558020 "%s: %.*s%s%s%sBUG: qm: fragm. %p (address %p) beginning overwritten (%lx)! Memory allocator was called from %s:%u. Fragment marked by %s:%lu. Exec from %s:%u.\n", 
    ap=ap@entry=0x7ffd6bebfb50, mode_flags=mode_flags@entry=0) at vfprintf-internal.c:1647
        len = <optimized out>
        step0_jumps = {0, 1717, 1621, 3413, 3317, 3997, 2677, 2837, 3613, 1773, 4309, 4445, 3517, 4437, 4389, 2789, 4197, 3917, 3221, 2997, 1141, 1365, 1997, 1925, 1885, 733, 3709, 533, 533, 4101}
        space = <optimized out>
        is_short = <optimized out>
        use_outdigits = 0
        outc = <optimized out>
        step1_jumps = {0, 0, 0, 0, 0, 0, 0, 0, 0, 1773, 4309, 4445, 3517, 4437, 4389, 2789, 4197, 3917, 3221, 2997, 1141, 1365, 1997, 1925, 1885, 733, 3709, 533, 533, 0}
        group = 0
        prec = -1
        step2_jumps = {0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 4309, 4445, 3517, 4437, 4389, 2789, 4197, 3917, 3221, 2997, 1141, 1365, 1997, 1925, 1885, 733, 3709, 533, 533, 0}
        string = 0x756d6f7266222c22 <error: Cannot access memory at address 0x756d6f7266222c22>
        left = 0
        is_long_double = <optimized out>
        width = 0
        signed_number = <optimized out>
        step3a_jumps = {0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 4213, 0, 0, 0, 4389, 2789, 4197, 3917, 3221, 0, 0, 0, 0, 1925, 0, 0, 0, 0, 0, 0}
        alt = <optimized out>
        showsign = 0
        is_long = 0
        is_char = <optimized out>
        pad = <optimized out>
        step3b_jumps = {0 <repeats 11 times>, 3517, 0, 0, 4389, 2789, 4197, 3917, 3221, 2997, 1141, 1365, 1997, 1925, 1885, 733, 3709, 0, 0, 0}
        step4_jumps = {0 <repeats 14 times>, 4389, 2789, 4197, 3917, 3221, 2997, 1141, 1365, 1997, 1925, 1885, 733, 3709, 0, 0, 0}
        args_value = <optimized out>
        is_negative = <optimized out>
        number = {longlong = <optimized out>, word = <optimized out>}
        base = <optimized out>
        the_arg = {pa_wchar = 4777 L'\x12a9', pa_int = 4777, pa_long_int = 4777, pa_long_long_int = 4777, pa_u_int = 4777, pa_u_long_int = 4777, pa_u_long_long_int = 4777, 
          pa_double = 2.3601515901836347e-320, pa_long_double = 1.74131181638025811763e-4947, pa_float128 = 3.09319115455554459548860449034534676e-4962, 
          pa_string = 0x12a9 <error: Cannot access memory at address 0x12a9>, pa_wstring = 0x12a9 <error: Cannot access memory at address 0x12a9>, pa_pointer = 0x12a9, pa_user = 0x12a9}
        spec = 115 's'
        _buffer = {__routine = 0x4, __arg = 0xd, __canceltype = 1855363680, __prev = 0xe0}
        _avail = <optimized out>
        thousands_sep = 0x0
        grouping = 0xffffffffffffffff <error: Cannot access memory at address 0xffffffffffffffff>
        done = 238
        f = 0x55a06e5580a7 "s:%lu. Exec from %s:%u.\n"
        lead_str_end = 0x55a06e558020 "%s: %.*s%s%s%sBUG: qm: fragm. %p (address %p) beginning overwritten (%lx)! Memory allocator was called from %s:%u. Fragment marked by %s:%lu. Exec from %s:%u.\n"
        end_of_spec = <optimized out>
        work_buffer = "h\r\000\000\000\000\000\000\000\000\000\000\060\000\000\000\000\000\000\000\375\177\000\000 \372\353k\375\177\000\000\237MSn\n\000\000\000\000\000\000\000\240U", '\000' <repeats 18 times>, "P\225Un\240U\000\000\000\000\000\000[\214A\323\f\000\000\000\000\000\000\000\377\377\377\377\377\377\377\377\206\002", '\000' <repeats 14 times>, "\004\000\000\000\000\000\000\000 \367\353k\375\177\000\000\301\225Un\240U\000\000\323\262\vn\240U\000\000\000\000\000\000\000\000\000\000s\374On\240U\000\000W\225Un\240U\000\000\350>\212\027T\177\000\000 \323\365$T\177\000\000\060\a\354k\375\177\000\00--Type <RET> for more, q to quit, c to continue without paging-- 
0\220\371\227n\240U\000\000"...
        workend = 0x7ffd6bebf9f8 ""
        ap_save = {{gp_offset = 16, fp_offset = 48, overflow_arg_area = 0x7ffd6bebfc30, reg_save_area = 0x7ffd6bebfb70}}
        nspecs_done = 10
        save_errno = 4
        readonly_format = 0
        do_longlong_number = <optimized out>
        __result = <optimized out>
#2  0x00007f5425ec079f in __vsyslog_internal (pri=<optimized out>, 
    fmt=0x55a06e558020 "%s: %.*s%s%s%sBUG: qm: fragm. %p (address %p) beginning overwritten (%lx)! Memory allocator was called from %s:%u. Fragment marked by %s:%lu. Exec from %s:%u.\n", 
    ap=0x7ffd6bebfb50, mode_flags=0) at ../misc/syslog.c:233
        now_tm = {tm_sec = 8, tm_min = 18, tm_hour = 12, tm_mday = 23, tm_mon = 0, tm_year = 124, tm_wday = 2, tm_yday = 22, tm_isdst = 0, tm_gmtoff = 0, tm_zone = 0x55a06e94c5e0 "UTC"}
        now = 1706012288
        fd = <optimized out>
        f = 0x55a06e969a60
        buf = 0x0
        bufsize = 0
        msgoff = 21
        saved_errno = <optimized out>
        failbuf = "`\232\226n\240U\000\000\000\204\201\247[\214A\323`\374\353k\375\177\000\000\300p\371%T"
        clarg = {buf = <optimized out>, oldaction = <optimized out>}
#3  0x00007f5425ec0c46 in __syslog (pri=<optimized out>, fmt=<optimized out>) at ../misc/syslog.c:117
        ap = {{gp_offset = 48, fp_offset = 48, overflow_arg_area = 0x7ffd6bebfc70, reg_save_area = 0x7ffd6bebfb70}}
#4  0x000055a06e3b7839 in ?? ()
No symbol table info available.
#5  0x000055a06e3bc039 in qm_free ()
No symbol table info available.
#6  0x000055a06e3c7c28 in qm_shm_free ()
No symbol table info available.
#7  0x00007f542325fb8e in uac_send_tm_callback () from /usr/lib/x86_64-linux-gnu/kamailio/modules/uac.so
No symbol table info available.
#8  0x00007f5424a2f002 in run_trans_callbacks_internal () from /usr/lib/x86_64-linux-gnu/kamailio/modules/tm.so
No symbol table info available.
#9  0x00007f5424a2f179 in run_trans_callbacks () from /usr/lib/x86_64-linux-gnu/kamailio/modules/tm.so
No symbol table info available.
#10 0x00007f54249d5e8c in free_cell_helper () from /usr/lib/x86_64-linux-gnu/kamailio/modules/tm.so
No symbol table info available.
#11 0x00007f5424aa8f82 in wait_handler () from /usr/lib/x86_64-linux-gnu/kamailio/modules/tm.so
No symbol table info available.
#12 0x000055a06e37a263 in ?? ()
No symbol table info available.
#13 0x000055a06e37a79d in ?? ()
No symbol table info available.
#14 0x000055a06e37acc6 in timer_main ()
No symbol table info available.
#15 0x000055a06e0a5f62 in main_loop ()
No symbol table info available.
--Type <RET> for more, q to quit, c to continue without paging--
#16 0x000055a06e0b120c in main ()
No symbol table info available.
(gdb) info locals
No locals.
(gdb)  list
72	in ../sysdeps/x86_64/multiarch/strlen-evex.S

Log Messages

Log file:

2024-01-23T13:18:08.828+01:00 Jan 23 12:18:08  /usr/sbin/kamailio[4789]: INFO: <script>: Incoming SIP TCP request conid 21 call-id un0rihsRLJLvP-grn6LO-A
2024-01-23T13:18:08.835+01:00 Jan 23 12:18:08  /usr/sbin/kamailio[4789]: INFO: <script>: Incoming SIP TCP request conid 21 call-id WQjhldpRJbxjZRYe7fWgbw
2024-01-23T13:18:08.860+01:00 Jan 23 12:18:08  /usr/sbin/kamailio[4795]: CRITICAL: <core> [core/pass_fd.c:281]: receive_fd(): EOF on 49
2024-01-23T13:18:09.486+01:00 Jan 23 12:18:09  /usr/sbin/kamailio[4751]: ALERT: <core> [main.c:783]: handle_sigs(): child process 4777 exited by a signal 11
2024-01-23T13:18:09.486+01:00 Jan 23 12:18:09  /usr/sbin/kamailio[4751]: ALERT: <core> [main.c:787]: handle_sigs(): core was generated
2024-01-23T13:18:09.516+01:00 Jan 23 12:18:09  /usr/sbin/kamailio[4751]: INFO: <core> [core/sctp_core.c:53]: sctp_core_destroy(): SCTP API not initialized
2024-01-23T13:18:09.570+01:00 Started /root/sipconfig/startkamailio.sh
2024-01-23T13:18:09.570+01:00 info: :-) Starting Kamailio

SIP Traffic

Possible Solutions

Additional Information

• Kamailio Version - output of kamailio -v

# /usr/sbin/kamailio -v    
version: kamailio 5.6.5 (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_BLOCKLIST, 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 with gcc 10.2.1

• Operating System:

# lsb_release -a
No LSB modules are available.
Distributor ID:	Debian
Description:	Debian GNU/Linux 11 (bullseye)
Release:	11
Codename:	bullseye

Linux ip-nn-nn-nn-nn 5.10.0-25-cloud-amd64 #1 SMP Debian 5.10.191-1 (2023-08-16) x86_64 GNU/Linux

[miconda]

Can you install debugging symbols for Kamailio and retake the backtrace with gdb? The one above does not show the details of the code during the execution.

[MattisLind]

Yes, I will try to do that. Currently I am running 5.5 because that is not showing this behaviour. I will put 5.7 on the test system and see if I can reproduce the problem there. Do you have a link to a page that describe how to install the debugging symbols for Kamailio?

[linuxmaniac]

There are dbgsym packages available in the repo

[github-actions]

This issue is stale because it has been open 6 weeks with no activity. Remove stale label or comment or this will be closed in 2 weeks.