[sr-dev] [kamailio/kamailio] SEGV coredump on Kamailio stop or restart (possibly related to use of systemd and log_systemd module) (#1454)

Anthony Messina notifications at github.com
Sat Feb 24 19:56:57 CET 2018


### Description
SEGV coredump on Kamailio stop or restart -- this doesn't happen every time, but about 90% of the time.
```
Stack trace of thread 12773:
#0  0x00007f02de3ad286 __GI___strlen_sse2 (libc.so.6)
#1  0x00007f02de385835 fputs_unlocked (libc.so.6)
#2  0x00007f02de4132b1 syslog (libc.so.6)
#3  0x000000000042aa60 main (kamailio)
#4  0x00007f02de32400a __libc_start_main (libc.so.6)
#5  0x000000000041800a _start (kamailio)
```
### Troubleshooting
I do not use the `xlog` module and use `log_systemd` module functions within the script but do not set `log_engine_type="systemd"`  due to issue #799.

Module loading order
```
~]# grep loadmod /etc/kamailio/kamailio.cfg
loadmodule "log_systemd.so"
loadmodule "tls.so"
loadmodule "db_postgres.so"
loadmodule "jsonrpcs.so"
loadmodule "kex.so"
loadmodule "corex.so"
loadmodule "tm.so"
loadmodule "tmx.so"
loadmodule "sl.so"
loadmodule "rr.so"
loadmodule "pv.so"
loadmodule "maxfwd.so"
loadmodule "usrloc.so"
loadmodule "registrar.so"
loadmodule "textops.so"
loadmodule "siputils.so"
#loadmodule "xlog.so"
loadmodule "sanity.so"
loadmodule "ctl.so"
loadmodule "cfg_rpc.so"
loadmodule "acc.so"
loadmodule "counters.so"
loadmodule "sqlops.so"
loadmodule "auth.so"
loadmodule "auth_db.so"
loadmodule "permissions.so"
loadmodule "alias_db.so"
loadmodule "speeddial.so"
loadmodule "domain.so"
loadmodule "presence.so"
loadmodule "presence_conference.so"
loadmodule "presence_dialoginfo.so"
loadmodule "presence_mwi.so"
loadmodule "presence_reginfo.so"
loadmodule "presence_xml.so"
loadmodule "pua.so"
loadmodule "pua_usrloc.so"
loadmodule "pua_dialoginfo.so"
loadmodule "nathelper.so"
loadmodule "rtpengine.so"
loadmodule "ipops.so"
loadmodule "sdpops.so"
loadmodule "htable.so"
loadmodule "pike.so"
loadmodule "xmlrpc.so"
loadmodule "debugger.so"
loadmodule "dialog.so"
loadmodule "group.so"
loadmodule "uac.so"
loadmodule "imc.so"
loadmodule "lcr.so"
loadmodule "app_python.so"
loadmodule "textopsx.so"
loadmodule "msilo.so"
loadmodule "tcpops.so"
loadmodule "topos.so"
loadmodule "diversion.so"
loadmodule "tmrec.so"
loadmodule "xhttp.so"
loadmodule "websocket.so"
loadmodule "auth_ephemeral.so"
```
systemd unit file
```
[Unit]
Description=Kamailio SIP Server
Documentation=man:kamailio(8) https://www.kamailio.org/
After=network.target

[Service]
Type=forking
User=kamailio
Environment=SHM_SIZE=64
Environment=PKG_SIZE=8
ExecStartPre=/usr/sbin/kamailio -c
ExecStart=/usr/sbin/kamailio -m $SHM_SIZE -M $PKG_SIZE -P /run/kamailio/kamailio.pid
ExecStopPost=/usr/bin/rm -f /run/kamailio/kamailio.pid
PIDFile=/run/kamailio/kamailio.pid
Restart=on-failure
RestartSec=30

[Install]
WantedBy=multi-user.target
```

#### Reproduction
The issue usually occurs when stopping or restarting Kamailio

#### Debugging Data
```
#0  __strlen_sse2 () at ../sysdeps/x86_64/multiarch/../strlen.S:120
No locals.
#1  0x00007f02de385835 in __GI___fputs_unlocked (str=0x7f02ddb597c8 <error: Cannot access memory at address 0x7f02ddb597c8>, fp=fp at entry=0x131ceb0) at iofputs_u.c:34
        len = <optimized out>
        result = <optimized out>
#2  0x00007f02de4132b1 in __GI___vsyslog_chk (ap=0x7ffe7e661398, fmt=0x742598 "%s: %s%s(): error sending exit status: %s [%d]\n", flag=-1, pri=<optimized out>) at ../misc/syslog.c:205
        buf = 0x0
        now_tm = {tm_sec = 49, tm_min = 29, tm_hour = 12, tm_mday = 24, tm_mon = 1, tm_year = 118, tm_wday = 6, tm_yday = 54, tm_isdst = 0, tm_gmtoff = -21600, tm_zone = 0x11a2350 "CST"}
        fd = <optimized out>
        failbuf = "\000\000\000\000\005\000\000\000\216\247J\336\002\177", '\000' <repeats 14 times>
        now = 1519496989
        f = 0x131ceb0
        bufsize = 0
        msgoff = 20
        saved_errno = 32
#3  __syslog (pri=<optimized out>, fmt=0x742598 "%s: %s%s(): error sending exit status: %s [%d]\n") at ../misc/syslog.c:117
        ap = {{gp_offset = 16, fp_offset = 48, overflow_arg_area = 0x7ffe7e661500, reg_save_area = 0x7ffe7e661410}}
#4  0x000000000042aa60 in main (argc=7, argv=0x7ffe7e6617a8) at main.c:2664
        __llevel = -1
        cfg_stream = 0x10fb260
        c = -1
        r = 0
        tmp = 0x7ffe7e662ee9 ""
        tmp_len = 0
        port = 0
        proto = 0
        options = 0x740400 ":f:cm:M:dVIhEeb:l:L:n:vKrRDTN:W:w:t:u:g:P:G:SQ:O:a:A:x:X:Y:"
        ret = -1
        seed = 2750509941
        rfd = 4
        debug_save = 0
        debug_flag = 0
        dont_fork_cnt = 0
        n_lst = 0x7f02ded2d6d0
        p = 0x7ffe7e661600 "\377\377\377\377"
        st = {st_dev = 22, st_ino = 23605, st_nlink = 2, st_mode = 16872, st_uid = 986, st_gid = 983, __pad0 = 0, st_rdev = 0, st_size = 40, st_blksize = 4096, st_blocks = 0, st_atim = {tv_sec = 1519444521, tv_nsec = 392061379}, st_mtim = {tv_sec = 1519496899,
            tv_nsec = 273235419}, st_ctim = {tv_sec = 1519496899, tv_nsec = 273235419}, __glibc_reserved = {0, 0, 0}}
        __func__ = "main"
__llevel = -1
cfg_stream = 0x10fb260
c = -1
r = 0
tmp = 0x7ffe7e662ee9 ""
tmp_len = 0
port = 0
proto = 0
options = 0x740400 ":f:cm:M:dVIhEeb:l:L:n:vKrRDTN:W:w:t:u:g:P:G:SQ:O:a:A:x:X:Y:"
ret = -1
seed = 2750509941
rfd = 4
debug_save = 0
debug_flag = 0
dont_fork_cnt = 0
n_lst = 0x7f02ded2d6d0
p = 0x7ffe7e661600 "\377\377\377\377"
st = {st_dev = 22, st_ino = 23605, st_nlink = 2, st_mode = 16872, st_uid = 986, st_gid = 983, __pad0 = 0, st_rdev = 0, st_size = 40, st_blksize = 4096, st_blocks = 0, st_atim = {tv_sec = 1519444521, tv_nsec = 392061379}, st_mtim = {tv_sec = 1519496899, tv_nsec = 273235419},
  st_ctim = {tv_sec = 1519496899, tv_nsec = 273235419}, __glibc_reserved = {0, 0, 0}}
__func__ = "main"
115     #ifdef AS_STRNLEN
116             andq    $-16, %rax
117             FIND_ZERO
118     #else
119             /* Test first 16 bytes unaligned.  */
120             movdqu  (%rax), %xmm4
121             PCMPEQ  %xmm0, %xmm4
122             pmovmskb        %xmm4, %edx
123             test    %edx, %edx
124             je      L(next48_bytes)
```

#### Log Messages
```
Feb 24 12:29:49 kamailio[12773]: ERROR: db_postgres [km_pg_con.c:115]: db_postgres_new_connection(): timeout expired
Feb 24 12:29:49 kamailio[12773]: ERROR: db_postgres [km_pg_con.c:148]: db_postgres_new_connection(): cleaning up 0x7f02ddcd2bb8=pkg_free()
Feb 24 12:29:49 kamailio[12773]: ERROR: <core> [db.c:318]: db_do_init2(): could not add connection to the pool
Feb 24 12:29:49 kamailio[12773]: ERROR: usrloc [usrloc_mod.c:421]: child_init(): child(0): failed to connect to database
Feb 24 12:29:49 kamailio[12784]: INFO: <core> [main.c:826]: sig_usr(): signal 15 received
Feb 24 12:29:49 kamailio[12773]: ERROR: <core> [core/sr_module.c:940]: init_mod_child(): error while initializing module usrloc (/usr/lib64/kamailio/modules/usrloc.so) (idx: 0 rank: 0 desc: [main])
Feb 24 12:29:49 kamailio[12773]: ERROR: <core> [main.c:1709]: main_loop(): error in init_child
Feb 24 12:29:49 kamailio[12783]: INFO: <core> [main.c:826]: sig_usr(): signal 15 received
Feb 24 12:29:49 kamailio[12778]: INFO: <core> [main.c:826]: sig_usr(): signal 15 received
Feb 24 12:29:49 kamailio[12781]: INFO: <core> [main.c:826]: sig_usr(): signal 15 received
Feb 24 12:29:49 kamailio[12776]: INFO: <core> [main.c:826]: sig_usr(): signal 15 received
Feb 24 12:29:49 kamailio[12782]: INFO: <core> [main.c:826]: sig_usr(): signal 15 received
Feb 24 12:29:49 systemd[1]: Failed to start Kamailio SIP Server.
Feb 24 12:29:49 audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=kamailio comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed'
Feb 24 12:29:49 systemd[1]: kamailio.service: Unit entered failed state.
Feb 24 12:29:49 systemd[1]: kamailio.service: Failed with result 'timeout'.
Feb 24 12:29:49 kamailio[12773]: WARNING: <core> [core/mem/q_malloc.c:476]: qm_free(): WARNING: free(0) called from permissions: permissions.c: mod_exit(666)
Feb 24 12:29:49 kamailio[12773]: WARNING: <core> [core/mem/q_malloc.c:476]: qm_free(): WARNING: free(0) called from permissions: permissions.c: mod_exit(669)
Feb 24 12:29:49 kamailio[12773]: INFO: <core> [core/sctp_core.c:53]: sctp_core_destroy(): SCTP API not initialized
Feb 24 12:29:49 audit[12773]: ANOM_ABEND auid=4294967295 uid=986 gid=983 ses=4294967295 subj=system_u:system_r:unconfined_service_t:s0 pid=12773 comm="kamailio" exe="/usr/sbin/kamailio" sig=11 res=1
Feb 24 12:29:49 kernel: show_signal_msg: 7 callbacks suppressed
Feb 24 12:29:49 kernel: kamailio[12773]: segfault at 7f02ddb597c8 ip 00007f02de3ad286 sp 00007ffe7e661308 error 4 in libc-2.26.so[7f02de303000+1da000]
Feb 24 12:29:49 systemd[1]: Created slice system-systemd\x2dcoredump.slice.
Feb 24 12:29:49 systemd[1]: Started Process Core Dump (PID 12817/UID 0).
Feb 24 12:29:49 audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-coredump at 0-12817-0 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Feb 24 12:29:50 systemd-coredump[12818]: Process 12773 (kamailio) of user 986 dumped core.
                                                              Stack trace of thread 12773:
                                                              #0  0x00007f02de3ad286 __GI___strlen_sse2 (libc.so.6)
                                                              #1  0x00007f02de385835 fputs_unlocked (libc.so.6)
                                                              #2  0x00007f02de4132b1 syslog (libc.so.6)
                                                              #3  0x000000000042aa60 main (kamailio)
                                                              #4  0x00007f02de32400a __libc_start_main (libc.so.6)
                                                              #5  0x000000000041800a _start (kamailio)
```

### Additional Information

  * **Kamailio Version** - output of `kamailio -v`

```
version: kamailio 5.1.1 (x86_64/linux) 
flags: STATS: Off, USE_TCP, USE_TLS, USE_SCTP, TLS_HOOKS, DISABLE_NAGLE, USE_MCAST, DNS_IP_HACK, SHM_MEM, 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
ADAPTIVE_WAIT_LOOPS=1024, MAX_RECV_BUFFER_SIZE 262144, MAX_LISTEN 16, 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 21:14:17 Feb 23 2018 with gcc 7.3.1
```

* **Operating System**:
```
Linux 4.15.4-300.fc27.x86_64 #1 SMP Mon Feb 19 23:31:15 UTC 2018 x86_64 x86_64 x86_64 GNU/Linux
```


-- 
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/1454
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.kamailio.org/pipermail/sr-dev/attachments/20180224/9af154fc/attachment.html>


More information about the sr-dev mailing list