Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

rsyslog crash with "double free or corruption (out)" #5343

Open
gaaf opened this issue Mar 5, 2024 · 4 comments
Open

rsyslog crash with "double free or corruption (out)" #5343

gaaf opened this issue Mar 5, 2024 · 4 comments
Milestone

Comments

@gaaf
Copy link

gaaf commented Mar 5, 2024

Expected behavior

No crash

Actual behavior

Crash. The only correlation I could find is that the systems resumed from boot a few minutes (~4) before.
The crash was triggered by this message:

mrt 05 14:36:51 pc1 kernel: Uhhuh. NMI received for unknown reason 2c on CPU 0.
mrt 05 14:36:51 pc1 kernel: Dazed and confused, but trying to continue

I've had these multiple times after resume, but I've ever noticed a crash before.

Steps to reproduce the behavior

This has ever happened only a single time. This config has been running trouble free for years, including several supend-resume cycles.

Environment

  • rsyslog version:
rsyslogd  8.2312.0 (aka 2023.12) compiled with:
        PLATFORM:                               x86_64-pc-linux-gnu
        PLATFORM (lsb_release -d):
        FEATURE_REGEXP:                         Yes
        GSSAPI Kerberos 5 support:              Yes
        FEATURE_DEBUG (debug build, slow code): No
        32bit Atomic operations supported:      Yes
        64bit Atomic operations supported:      Yes
        memory allocator:                       system default
        Runtime Instrumentation (slow code):    No
        uuid support:                           Yes
        systemd support:                        Yes
        Config file:                            /etc/rsyslog.conf
        PID file:                               /run/rsyslogd.pid
        Number of Bits in RainerScript integers: 64
  • platform: Debian Sid

Backtrace

[root@pc1:~] DEBUGINFOD_URLS="https://debuginfod.debian.net" coredumpctl gdb
           PID: 1026 (rsyslogd)
           UID: 0 (root)
           GID: 0 (root)
        Signal: 6 (ABRT)
     Timestamp: Tue 2024-03-05 14:36:51 CET (15min ago)
  Command Line: /usr/sbin/rsyslogd -n -iNONE
    Executable: /usr/sbin/rsyslogd
 Control Group: /system.slice/rsyslog.service
          Unit: rsyslog.service
         Slice: system.slice
       Boot ID: afe4b3f3dc144519b4432866372058a0
    Machine ID: 1a0476bf79132acaaffd1df6482ef8d9
      Hostname: pc1
       Storage: /var/lib/systemd/coredump/core.rsyslogd.0.afe4b3f3dc144519b4432866372058a0.1026.1709645811000000 (present)
  Size on Disk: 22.6M
       Message: Process 1026 (rsyslogd) of user 0 dumped core.
                
                Module libzstd.so.1 from deb libzstd-1.5.5+dfsg2-2.amd64
                Module libsystemd.so.0 from deb systemd-255.3-2.amd64
                Stack trace of thread 1075:
                #0  0x00007fa92de0816c __pthread_kill_implementation (libc.so.6 + 0x8a16c)
                #1  0x00007fa92ddba472 __GI_raise (libc.so.6 + 0x3c472)
                #2  0x00007fa92dda44b2 __GI_abort (libc.so.6 + 0x264b2)
                #3  0x00007fa92dda51ed __libc_message (libc.so.6 + 0x271ed)
                #4  0x00007fa92de11ae5 malloc_printerr (libc.so.6 + 0x93ae5)
                #5  0x00007fa92de13b40 _int_free (libc.so.6 + 0x95b40)
                #6  0x00007fa92de161df __GI___libc_free (libc.so.6 + 0x981df)
                #7  0x0000564a197ac844 n/a (rsyslogd + 0x1b844)
                #8  0x0000564a197fdec2 n/a (rsyslogd + 0x6cec2)
                #9  0x0000564a197ff7dd n/a (rsyslogd + 0x6e7dd)
                #10 0x0000564a197ffaa9 n/a (rsyslogd + 0x6eaa9)
                #11 0x0000564a197f6c4f n/a (rsyslogd + 0x65c4f)
                #12 0x0000564a197f6c9d n/a (rsyslogd + 0x65c9d)
                #13 0x0000564a197f7915 n/a (rsyslogd + 0x66915)
                #14 0x0000564a197a8dcc n/a (rsyslogd + 0x17dcc)
                #15 0x0000564a197f2674 n/a (rsyslogd + 0x61674)
                #16 0x0000564a197ef159 wtiWorker (rsyslogd + 0x5e159)
                #17 0x0000564a197ed922 n/a (rsyslogd + 0x5c922)
                #18 0x00007fa92de0645c start_thread (libc.so.6 + 0x8845c)
                #19 0x00007fa92de86bbc __clone3 (libc.so.6 + 0x108bbc)
                
                Stack trace of thread 1072:
                #0  0x00007fa92de75b3c __GI___libc_read (libc.so.6 + 0xf7b3c)
                #1  0x00007fa92e1739ba n/a (imklog.so + 0x39ba)
                #2  0x00007fa92e173d0d klogLogKMsg (imklog.so + 0x3d0d)
                #3  0x00007fa92e172c8c n/a (imklog.so + 0x2c8c)
                #4  0x0000564a198013f5 n/a (rsyslogd + 0x703f5)
                #5  0x00007fa92de0645c start_thread (libc.so.6 + 0x8845c)
                #6  0x00007fa92de86bbc __clone3 (libc.so.6 + 0x108bbc)
                
                Stack trace of thread 1071:
                #0  0x00007fa92de79abf __GI___poll (libc.so.6 + 0xfbabf)
                #1  0x00007fa92e17b868 n/a (imuxsock.so + 0x4868)
                #2  0x0000564a198013f5 n/a (rsyslogd + 0x703f5)
                #3  0x00007fa92de0645c start_thread (libc.so.6 + 0x8845c)
                #4  0x00007fa92de86bbc __clone3 (libc.so.6 + 0x108bbc)
                
                Stack trace of thread 1026:
                #0  0x00007fa92de7c3b1 pselect64_syscall (libc.so.6 + 0xfe3b1)
                #1  0x0000564a197ab5e2 n/a (rsyslogd + 0x1a5e2)
                #2  0x0000564a197a81b8 main (rsyslogd + 0x171b8)
                #3  0x00007fa92dda56ca __libc_start_call_main (libc.so.6 + 0x276ca)
                #4  0x00007fa92dda5785 __libc_start_main_impl (libc.so.6 + 0x27785)
                #5  0x0000564a197a8541 _start (rsyslogd + 0x17541)
                
                Stack trace of thread 1074:
                #0  0x00007fa92de86fc6 epoll_wait (libc.so.6 + 0x108fc6)
                #1  0x00007fa92e1696b0 n/a (imudp.so + 0x36b0)
                #2  0x00007fa92e16a033 n/a (imudp.so + 0x4033)
                #3  0x00007fa92e16a17f n/a (imudp.so + 0x417f)
                #4  0x0000564a198013f5 n/a (rsyslogd + 0x703f5)
                #5  0x00007fa92de0645c start_thread (libc.so.6 + 0x8845c)
                #6  0x00007fa92de86bbc __clone3 (libc.so.6 + 0x108bbc)
                ELF object binary architecture: AMD x86-64

GNU gdb (Debian 13.2-1) 13.2
Copyright (C) 2023 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/rsyslogd...

This GDB supports auto-downloading debuginfo from the following URLs:
  <https://debuginfod.debian.net>
Enable debuginfod for this session? (y or [n]) y
Debuginfod has been enabled.
To make this setting permanent, add 'set debuginfod enabled on' to .gdbinit.
Downloading separate debug info for /usr/sbin/rsyslogd
Reading symbols from /root/.cache/debuginfod_client/e45fc78570f928fbc3b9a131e83c06d48791e6c2/debuginfo...                                                                                                                                                   
Downloading separate debug info for /root/.cache/debuginfod_client/e45fc78570f928fbc3b9a131e83c06d48791e6c2/debuginfo
[New LWP 1075]                                                                                                                                                                                                                                              
[New LWP 1072]
[New LWP 1071]
[New LWP 1026]
[New LWP 1074]

warning: Section `.reg-xstate/1075' in core file too small.
Downloading separate debug info for /lib/x86_64-linux-gnu/libz.so.1
Downloading separate debug info for /lib/x86_64-linux-gnu/libestr.so.0                                                                                                                                                                                      
Downloading separate debug info for /lib/x86_64-linux-gnu/libfastjson.so.4                                                                                                                                                                                  
Downloading separate debug info for /lib/x86_64-linux-gnu/libsystemd.so.0                                                                                                                                                                                   
Downloading separate debug info for /lib/x86_64-linux-gnu/libuuid.so.1                                                                                                                                                                                      
Downloading separate debug info for /lib/x86_64-linux-gnu/libcap.so.2
Downloading separate debug info for /root/.cache/debuginfod_client/0de798e666619228de79d08d74552105a15a0a73/debuginfo                                                                                                                                       
Downloading separate debug info for /lib/x86_64-linux-gnu/libgcrypt.so.20                                                                                                                                                                                   
Downloading separate debug info for /lib/x86_64-linux-gnu/liblz4.so.1                                                                                                                                                                                       
Downloading separate debug info for /lib/x86_64-linux-gnu/liblzma.so.5                                                                                                                                                                                      
Downloading separate debug info for /lib/x86_64-linux-gnu/libzstd.so.1                                                                                                                                                                                      
Downloading separate debug info for /lib/x86_64-linux-gnu/libgpg-error.so.0                                                                                                                                                                                 
Downloading separate debug info for /usr/lib/x86_64-linux-gnu/rsyslog/lmnet.so                                                                                                                                                                              
Downloading separate debug info for /usr/lib/x86_64-linux-gnu/rsyslog/imuxsock.so                                                                                                                                                                           
Downloading separate debug info for /usr/lib/x86_64-linux-gnu/rsyslog/imklog.so                                                                                                                                                                             
Downloading separate debug info for /usr/lib/x86_64-linux-gnu/rsyslog/imudp.so                                                                                                                                                                              
Downloading separate debug info for system-supplied DSO at 0x7fffa0d92000                                                                                                                                                                                   
[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/rsyslogd -n -iNONE'.
Program terminated with signal SIGABRT, Aborted.

warning: Section `.reg-xstate/1075' in core file too small.
#0  __pthread_kill_implementation (threadid=<optimized out>, signo=signo@entry=6, no_tid=no_tid@entry=0) at ./nptl/pthread_kill.c:44
Download failed: Invalid argument.  Continuing without source file ./nptl/./nptl/pthread_kill.c.                                                                                                                                                            
44      ./nptl/pthread_kill.c: No such file or directory.
[Current thread is 1 (Thread 0x7fa92cd986c0 (LWP 1075))]
(gdb) bt fulll
No symbol "fulll" in current context.
(gdb) bt full
#0  __pthread_kill_implementation (threadid=<optimized out>, signo=signo@entry=6, no_tid=no_tid@entry=0) at ./nptl/pthread_kill.c:44
        tid = <optimized out>
        ret = 0
        pd = <optimized out>
        old_mask = {__val = {0}}
        ret = <optimized out>
#1  0x00007fa92de081cf in __pthread_kill_internal (signo=6, threadid=<optimized out>) at ./nptl/pthread_kill.c:78
No locals.
#2  0x00007fa92ddba472 in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
        ret = <optimized out>
#3  0x00007fa92dda44b2 in __GI_abort () at ./stdlib/abort.c:79
        save_stage = 1
        act = {__sigaction_handler = {sa_handler = 0x20, sa_sigaction = 0x20}, sa_mask = {__val = {140364595945951, 94876262312288, 140364597982057, 0, 1204854406372768256, 140364578648736, 18446744073709551192, 0, 140364497321456, 0, 10, 0, 
              140364595945951, 20, 8, 140364497321456}}, sa_flags = 20, sa_restorer = 0x8}
#4  0x00007fa92dda51ed in __libc_message (fmt=fmt@entry=0x7fa92df1778c "%s\n") at ../sysdeps/posix/libc_fatal.c:150
        ap = {{gp_offset = 16, fp_offset = 32681, overflow_arg_area = 0x7fa92cd972f0, reg_save_area = 0x7fa92cd97280}}
        fd = <optimized out>
        list = <optimized out>
        nlist = <optimized out>
        cp = <optimized out>
#5  0x00007fa92de11ae5 in malloc_printerr (str=str@entry=0x7fa92df1a638 "double free or corruption (out)") at ./malloc/malloc.c:5658
No locals.
#6  0x00007fa92de13b40 in _int_free (av=0x7fa92df51c80 <main_arena>, p=0x7fa9180045d0, have_lock=<optimized out>, have_lock@entry=0) at ./malloc/malloc.c:4581
        size = 1040
        fb = <optimized out>
        nextchunk = 0x7fa9180049e0
        nextsize = <optimized out>
        nextinuse = <optimized out>
        prevsize = <optimized out>
        bck = <optimized out>
        fwd = <optimized out>
        __PRETTY_FUNCTION__ = "_int_free"
#7  0x00007fa92de161df in __GI___libc_free (mem=mem@entry=0x7fa9180045e0) at ./malloc/malloc.c:3367
        ar_ptr = <optimized out>
        p = 0x7fa9180045d0
        err = 0
#8  0x0000564a197ac844 in wallmsg (pMsg=0x7fa928018e90 "\r\n\aMessage from syslogd@pc1 at Mar  5 14:36:51 ...\r\n kernel: Dazed and confused, but trying to continue\n\r", pData=0x564a19e9a960) at ./tools/omusrmsg.c:306
        tty = 0x7fa9180100c0 "\240\215\221\342\256\177"
        szErr = "No data available", '\000' <repeats 494 times>
        user = 0x7fa9180045e0 "lightdm"
        uid = 135
        pws = <optimized out>
        j = 0
        sdRet = <optimized out>
        sessions_list = 0x7fa928006e80
        sessions = <optimized out>
        i = 20
        ut = {ut_type = 0, ut_pid = 0, ut_line = '\000' <repeats 31 times>, ut_id = "\000\000\000", ut_user = '\000' <repeats 31 times>, ut_host = '\000' <repeats 255 times>, ut_exit = {e_termination = 0, e_exit = 0}, ut_session = 0, ut_tv = {
            tv_sec = 0, tv_usec = 0}, ut_addr_v6 = {0, 0, 0, 0}, __glibc_reserved = '\000' <repeats 19 times>}
        uptr = <optimized out>
        iRet = RS_RET_OK
#9  0x0000564a197fdec2 in actionCallDoAction (pWti=0x564a19e9c140, iparams=0x564a19e9dcf0, pThis=0x564a19e9ac10) at ../action.c:1276
        param = {0x7fa928018e90, 0x10b880b2f1e9ba00, 0x7fa920000ee0, 0x564a19e9ac10, 0x564a19e9dcd0}
        i = <optimized out>
        iRet = RS_RET_OK
        param = <optimized out>
        i = <optimized out>
        iRet = <optimized out>
#10 actionProcessMessage (pThis=pThis@entry=0x564a19e9ac10, actParams=actParams@entry=0x564a19e9dcf0, pWti=pWti@entry=0x564a19e9c140) at ../action.c:1318
        iRet = <optimized out>
#11 0x0000564a197ff7dd in actionProcessMessage (pWti=0x564a19e9c140, actParams=0x564a19e9dcf0, pThis=0x564a19e9ac10) at ../action.c:1689
        iRet = <optimized out>
        iRet = <optimized out>
        finalize_it = <optimized out>
#12 processMsgMain (pAction=pAction@entry=0x564a19e9ac10, pWti=pWti@entry=0x564a19e9c140, ttNow=0x7fa92cd97850, pMsg=<optimized out>) at ../action.c:1688
        iRet = <optimized out>
#13 0x0000564a197ffaa9 in processMsgMain (ttNow=0x7fa92cd97850, pMsg=<optimized out>, pWti=0x564a19e9c140, pAction=0x564a19e9ac10) at ../action.c:1678
        iRet = RS_RET_OK
        finalize_it = <optimized out>
        iRet = <optimized out>
        finalize_it = <optimized out>
#14 doSubmitToActionQ (pAction=0x564a19e9ac10, pWti=0x564a19e9c140, pMsg=<optimized out>) at ../action.c:1855
        ttNow = {timeType = 32 ' ', month = 121 'y', day = -39 '\331', wday = 44 ',', hour = -87 '\251', minute = 127 '\177', second = 0 '\000', secfracPrecision = 0 '\000', OffsetMinute = 0 '\000', OffsetHour = 0 '\000', OffsetMode = 0 '\000', 
          year = 0, secfrac = 434724392, inUTC = 74 'J'}
        iRet = RS_RET_OK
#15 0x0000564a197f6c4f in execAct (pWti=<optimized out>, pMsg=<optimized out>, stmt=0x564a19e9a7d0) at ./runtime/ruleset.c:209
        iRet = RS_RET_OK
        finalize_it = <optimized out>
        iRet = <optimized out>
        finalize_it = <optimized out>
#16 scriptExec (root=<optimized out>, pMsg=pMsg@entry=0x7fa920000ee0, pWti=pWti@entry=0x564a19e9c140) at ./runtime/ruleset.c:599
        stmt = 0x564a19e9a7d0
        iRet = RS_RET_OK
#17 0x0000564a197f6c9d in execPROPFILT (pWti=<optimized out>, pMsg=<optimized out>, stmt=<optimized out>) at ./runtime/ruleset.c:546
        bRet = <optimized out>
        iRet = <optimized out>
        finalize_it = <optimized out>
        bRet = <optimized out>
        iRet = <optimized out>
        finalize_it = <optimized out>
#18 scriptExec (root=<optimized out>, pMsg=pMsg@entry=0x7fa920000ee0, pWti=pWti@entry=0x564a19e9c140) at ./runtime/ruleset.c:623
        stmt = 0x564a19e8d9f0
        iRet = RS_RET_OK
#19 0x0000564a197f7915 in processBatch (pBatch=0x564a19e9c170, pWti=0x564a19e9c140) at ./runtime/ruleset.c:660
        i = 1
        pMsg = 0x7fa920000ee0
        pRuleset = <optimized out>
        localRet = <optimized out>
        iRet = RS_RET_OK
#20 0x0000564a197a8dcc in msgConsumer (notNeeded=<optimized out>, pBatch=0x564a19e9c170, pWti=0x564a19e9c140) at ./tools/rsyslogd.c:787
        iRet = RS_RET_OK
        i = <optimized out>
#21 0x0000564a197f2674 in ConsumerReg (pThis=0x564a19e8dc00, pWti=0x564a19e9c140) at ./runtime/queue.c:2158
        iCancelStateSave = 1
        bNeedReLock = 1
        skippedMsgs = 0
        iRet = RS_RET_OK
        finalize_it = <optimized out>
#22 0x0000564a197ef159 in wtiWorker (pThis=pThis@entry=0x564a19e9c140) at ./runtime/wti.c:430
        bInactivityTOOccurred = <optimized out>
        __cancel_buf = {__cancel_jmp_buf = {{__cancel_jmp_buf = {140364578651184, -2693151238923651660, -424, 0, 140364591231888, 140364570263552, -8546025225302739532, -2693152469604928076}, __mask_was_saved = 0}}, __pad = {0x7fa92cd97c30, 0x0, 
            0x7fa92cd97c10, 0x7fa92cd97bd0}}
        __cancel_routine = 0x564a197ee830 <wtiWorkerCancelCleanup>
        __cancel_arg = 0x564a19e9c140
        __not_first_call = 0
        pWtp = 0x564a19e9bfc0
        pAction = <optimized out>
        localRet = <optimized out>
        terminateRet = RS_RET_OK
        wrkrInfo = <optimized out>
        iCancelStateSave = 0
        i = <optimized out>
        j = <optimized out>
        k = <optimized out>
        iRet = RS_RET_OK
#23 0x0000564a197ed922 in wtpWorker (arg=0x564a19e9c140) at ./runtime/wtp.c:435
        __cancel_buf = {__cancel_jmp_buf = {{__cancel_jmp_buf = {94876262318072, -2693151238923651660, -424, 0, 140364591231888, 140364570263552, -8546025225472608844, -2693152468250692172}, __mask_was_saved = 0}}, __pad = {0x7fa92cd97df0, 0x0, 0x0, 
            0x0}}
        __cancel_routine = 0x564a197ed720 <wtpWrkrExecCancelCleanup>
        __cancel_arg = 0x564a19e9c140
        __not_first_call = <optimized out>
        pWti = 0x564a19e9c140
        pThis = 0x564a19e9bfc0
        sigSet = {__val = {18446744067266051071, 0 <repeats 15 times>}}
        pszDbgHdr = <optimized out>
        thrdName = "rs:main Q:Reg", '\000' <repeats 18 times>
#24 0x00007fa92de0645c in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:444
        ret = <optimized out>
        pd = <optimized out>
        out = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {140364578655448, 8517488754025133492, -424, 0, 140364591231888, 140364570263552, -8546025225478900300, -8546027638765554252}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x0, 0x0}, data = {
              prev = 0x0, cleanup = 0x0, canceltype = 0}}}
        not_first_call = <optimized out>
#25 0x00007fa92de86bbc in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81
No locals.
(gdb)
@gaaf gaaf changed the title rsyslog crash with " rsyslog crash with "double free or corruption (out)" Mar 5, 2024
@davidelang
Copy link
Contributor

davidelang commented Mar 5, 2024 via email

@gaaf
Copy link
Author

gaaf commented Mar 5, 2024

You only saw a half filled report that github found necessary to submit on a yet unknown key(-combo?) I apparently hit while typing. The report is complete now.

My rsyslog version is 8.2312.0 (aka 2023.12) which is not the newest, but also not very old.

Config:

# grep -h -v ^# /etc/rsyslog.conf /etc/rsyslog.d/*.conf | grep \\S
module(load="imuxsock") # provides support for local system logging
module(load="imklog")   # provides kernel logging support
module(load="imudp")
input(type="imudp" port="514")
$ActionFileDefaultTemplate RSYSLOG_TraditionalFileFormat
$FileOwner root
$FileGroup adm
$FileCreateMode 0640
$DirCreateMode 0755
$Umask 0022
$WorkDirectory /var/spool/rsyslog
$IncludeConfig /etc/rsyslog.d/*.conf
auth,authpriv.*                 /var/log/auth.log
*.*                                     -/var/log/syslog
*.emerg                         :omusrmsg:*
template (name="VoipFile" type="string" string="/var/log/voip-%timestamp:::date-year%-%timestamp:::date-month%-%timestamp:::date-day%.log")
$fileGroup www-data
local0.* -?VoipFile;RSYSLOG_FileFormat
&stop
:programname, isequal, "asterisk"  -?VoipFile;RSYSLOG_FileFormat
&stop
:programname, isequal, "kamailio"  -?VoipFile;RSYSLOG_FileFormat
&stop

@rgerhards rgerhards added this to the v8.2404 milestone Mar 5, 2024
@davidelang
Copy link
Contributor

davidelang commented Mar 5, 2024 via email

@gaaf
Copy link
Author

gaaf commented Mar 5, 2024

Please take a look at the issue on github. Because of the submitted unfinished report, the emails don't have all information, including a full backtrace.

@rgerhards rgerhards modified the milestones: v8.2404, v8.2406 Apr 2, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants