Bug 1744617

Summary: Memory leak in readjournal() when cs.bWorkAroundJournalBug = 1
Product: Red Hat Enterprise Linux 7 Reporter: Kyle Walker <kwalker>
Component: rsyslogAssignee: Jiří Vymazal <jvymazal>
Status: CLOSED ERRATA QA Contact: Dalibor Pospíšil <dapospis>
Severity: high Docs Contact:
Priority: high    
Version: 7.7CC: cylopez, dapospis, jvymazal, rmeggins
Target Milestone: rcKeywords: EasyFix, Patch, Triaged
Target Release: ---   
Hardware: All   
OS: Linux   
Whiteboard:
Fixed In Version: rsyslog-8.24.0-46.el7 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2020-03-31 19:10:09 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description Kyle Walker 2019-08-22 14:28:58 UTC
Description of problem:
 The WorkAroundJournalBug imjournal plugin configuration leads to a memory leak. With enough time and use, the leak grows sufficiently large to cause system outages.

Version-Release number of selected component (if applicable):
 rsyslog-8.24.0-41.el7_7.x86_64

How reproducible:
 Easily

Steps to Reproduce:
1. Remove the "imjournal" plugin configuration options from the /etc/rsyslog.conf and add the applicable module configuration option
    # diff -up /etc/rsyslog.conf.orig /etc/rsyslog.conf
    --- /etc/rsyslog.conf.orig      2019-08-22 10:12:22.152412234 -0400
    +++ /etc/rsyslog.conf   2019-08-21 12:01:53.838303690 -0400
    @@ -7,7 +7,7 @@
     
     # The imjournal module bellow is now used as a message source instead of imuxsock.
     $ModLoad imuxsock # provides support for local system logging (e.g. via logger command)
    -$ModLoad imjournal # provides access to the systemd journal
    +#$ModLoad imjournal # provides access to the systemd journal
     #$ModLoad imklog # reads kernel messages (the same are read from journald)
     #$ModLoad immark  # provides --MARK-- message capability
     
    @@ -40,7 +40,8 @@ $IncludeConfig /etc/rsyslog.d/*.conf
     $OmitLocalLogging on
     
     # File to store the position in the journal
    -$IMJournalStateFile imjournal.state
    +#$IMJournalStateFile imjournal.state
    +module(load="imjournal" StateFile="imjournal.state" WorkAroundJournalBug="on")
     
     
     #### RULES ####

2. Stop the service-initiated rsyslog instance
    # systemctl stop rsyslog

3. Start rsyslog in a valgrind instance with the following flags
    # valgrind --keep-debuginfo=yes --show-leak-kinds=definite --leak-check=full --show-leak-kinds=all -v --log-file=/tmp/valgrind.rsyslog $(which rsyslogd) -n

4. Issue a fairly large amount of "logger" commands to exercise the logging processes, and then stop the valgrind/rsyslog instance
    # for entry in {0..9999}; do logger test-$entry; done && kill $(cat /var/run/syslogd.pid)

5. Verify the output of the /tmp/valgrind.rsyslog log file to verify the amount of definitely lost memory chunks. Specifically within the readjournal() codepath

Actual results:

    ==29126== 5,462,423 bytes in 44,073 blocks are definitely lost in loss record 22 of 22
    ==29126==    at 0x4C29E63: malloc (vg_replace_malloc.c:309)
    ==29126==    by 0x5FB5F6F: __vasprintf_chk (vasprintf_chk.c:80)
    ==29126==    by 0x5FB5E41: __asprintf_chk (asprintf_chk.c:33)
    ==29126==    by 0x6C8E7B0: UnknownInlinedFun (stdio2.h:178)
    ==29126==    by 0x6C8E7B0: sd_journal_get_cursor (sd-journal.c:926)
    ==29126==    by 0x6A7E6C7: readjournal (imjournal.c:414)
    ==29126==    by 0x6A7E6C7: runInput (imjournal.c:691)
    ==29126==    by 0x150443: thrdStarter (threads.c:226)
    ==29126==    by 0x5054EA4: start_thread (pthread_create.c:307)
    ==29126==    by 0x5F9C8CC: clone (clone.S:111)


Expected results:
    <None>


Additional info:
 Though the workaround may not be necessary, it will still be necessary to resolve this memory leak so that users that already deployed the workaround do not experience system outages.

Comment 2 Kyle Walker 2019-08-22 14:56:17 UTC
Whoops! Missed a step in my reproducer. You wont get stacktraces without the applicable debuginfo installed. 

That necessary change results in the following reproducer:

1. Remove the "imjournal" plugin configuration options from the /etc/rsyslog.conf and add the applicable module configuration option
    # diff -up /etc/rsyslog.conf.orig /etc/rsyslog.conf
    --- /etc/rsyslog.conf.orig      2019-08-22 10:12:22.152412234 -0400
    +++ /etc/rsyslog.conf   2019-08-21 12:01:53.838303690 -0400
    @@ -7,7 +7,7 @@
     
     # The imjournal module bellow is now used as a message source instead of imuxsock.
     $ModLoad imuxsock # provides support for local system logging (e.g. via logger command)
    -$ModLoad imjournal # provides access to the systemd journal
    +#$ModLoad imjournal # provides access to the systemd journal
     #$ModLoad imklog # reads kernel messages (the same are read from journald)
     #$ModLoad immark  # provides --MARK-- message capability
     
    @@ -40,7 +40,8 @@ $IncludeConfig /etc/rsyslog.d/*.conf
     $OmitLocalLogging on
     
     # File to store the position in the journal
    -$IMJournalStateFile imjournal.state
    +#$IMJournalStateFile imjournal.state
    +module(load="imjournal" StateFile="imjournal.state" WorkAroundJournalBug="on")
     
     
     #### RULES ####

2. Stop the service-initiated rsyslog instance
    # systemctl stop rsyslog

3. Install the applicable debuginfo
    # debuginfo-install rsyslog

4. Start rsyslog in a valgrind instance with the following flags
    # valgrind --keep-debuginfo=yes --show-leak-kinds=definite --leak-check=full --show-leak-kinds=all -v --log-file=/tmp/valgrind.rsyslog $(which rsyslogd) -n

5. Issue a fairly large amount of "logger" commands to exercise the logging processes, and then stop the valgrind/rsyslog instance
    # for entry in {0..9999}; do logger test-$entry; done && kill $(cat /var/run/syslogd.pid)

6. Verify the output of the /tmp/valgrind.rsyslog log file to verify the amount of definitely lost memory chunks. Specifically within the readjournal() codepath


Sorry for the confusion!

Comment 17 errata-xmlrpc 2020-03-31 19:10:09 UTC
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHSA-2020:1000