RHEL Engineering is moving the tracking of its product development work on RHEL 6 through RHEL 9 to Red Hat Jira (issues.redhat.com). If you're a Red Hat customer, please continue to file support cases via the Red Hat customer portal. If you're not, please head to the "RHEL project" in Red Hat Jira and file new tickets here. Individual Bugzilla bugs in the statuses "NEW", "ASSIGNED", and "POST" are being migrated throughout September 2023. Bugs of Red Hat partners with an assigned Engineering Partner Manager (EPM) are migrated in late September as per pre-agreed dates. Bugs against components "kernel", "kernel-rt", and "kpatch" are only migrated if still in "NEW" or "ASSIGNED". If you cannot log in to RH Jira, please consult article #7032570. That failing, please send an e-mail to the RH Jira admins at rh-issues@redhat.com to troubleshoot your issue as a user management inquiry. The email creates a ServiceNow ticket with Red Hat. Individual Bugzilla bugs that are migrated will be moved to status "CLOSED", resolution "MIGRATED", and set with "MigratedToJIRA" in "Keywords". The link to the successor Jira issue will be found under "Links", have a little "two-footprint" icon next to it, and direct you to the "RHEL project" in Red Hat Jira (issue links are of type "https://issues.redhat.com/browse/RHEL-XXXX", where "X" is a digit). This same link will be available in a blue banner at the top of the page informing you that that bug has been migrated.
Bug 1459633 - rsyslog sporadically fails to log message
Summary: rsyslog sporadically fails to log message
Keywords:
Status: CLOSED INSUFFICIENT_DATA
Alias: None
Product: Red Hat Enterprise Linux 7
Classification: Red Hat
Component: rsyslog
Version: 7.4
Hardware: Unspecified
OS: Unspecified
medium
medium
Target Milestone: rc
: ---
Assignee: Radovan Sroka
QA Contact: BaseOS QE Security Team
URL:
Whiteboard:
: 1473809 (view as bug list)
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2017-06-07 16:14 UTC by Jakub Raček
Modified: 2019-08-19 10:56 UTC (History)
8 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2018-11-05 08:58:01 UTC
Target Upstream Version:
Embargoed:


Attachments (Terms of Use)
rsyslog patch and debug log 1 (28.10 KB, text/plain)
2017-07-26 08:16 UTC, Jan Stancek
no flags Details


Links
System ID Private Priority Status Summary Last Updated
Red Hat Bugzilla 1473809 1 None None None 2021-01-20 06:05:38 UTC
Red Hat Bugzilla 1510593 1 None None None 2021-01-20 06:05:38 UTC

Internal Links: 1473809 1510593

Comment 3 Jan Stancek 2017-06-08 06:28:46 UTC
rsyslog config:
---
$ModLoad imjournal # provides access to the systemd journal
$WorkDirectory /var/lib/rsyslog
$IMJournalStateFile imjournal.state
mail.debug      /var/log/maillog
---

rsyslog is restarted and 2 seconds later application writes "syslogtst: mail crit test" to /dev/log. Message appears in journal, but not it /var/log/maillog.

@Radovan: Can you think of any debugging/extra options, or any ideas that would help to identify why this is failing? We can't reproduce it on demand by hand, but we can modify LTP testcase, which runs ~daily, and collect some logs that way when it fails next time.

Comment 4 Radovan Sroka 2017-06-08 07:23:40 UTC
(In reply to Jan Stancek from comment #3)
> rsyslog config:
> ---
> $ModLoad imjournal # provides access to the systemd journal
> $WorkDirectory /var/lib/rsyslog
> $IMJournalStateFile imjournal.state
> mail.debug      /var/log/maillog
> ---
> 

Is this whole config ?

> rsyslog is restarted and 2 seconds later application writes "syslogtst: mail
> crit test" to /dev/log. Message appears in journal, but not it
> /var/log/maillog.
> 
> @Radovan: Can you think of any debugging/extra options, or any ideas that
> would help to identify why this is failing? We can't reproduce it on demand
> by hand, but we can modify LTP testcase, which runs ~daily, and collect some
> logs that way when it fails next time.

You can run rsyslog in debug mode e.g.:

# rsyslog -dn

Comment 5 Jan Stancek 2017-06-08 08:23:48 UTC
(In reply to Radovan Sroka from comment #4)
> (In reply to Jan Stancek from comment #3)
> > rsyslog config:
> > ---
> > $ModLoad imjournal # provides access to the systemd journal
> > $WorkDirectory /var/lib/rsyslog
> > $IMJournalStateFile imjournal.state
> > mail.debug      /var/log/maillog
> > ---
> > 
> 
> Is this whole config ?

Yes, the test replaces original with what you see above.

Comment 6 Radovan Sroka 2017-06-08 08:37:48 UTC
(In reply to Jan Stancek from comment #5)
> (In reply to Radovan Sroka from comment #4)
> > (In reply to Jan Stancek from comment #3)
> > > rsyslog config:
> > > ---
> > > $ModLoad imjournal # provides access to the systemd journal
> > > $WorkDirectory /var/lib/rsyslog
> > > $IMJournalStateFile imjournal.state
> > > mail.debug      /var/log/maillog
> > > ---
> > > 
> > 
> > Is this whole config ?
> 
> Yes, the test replaces original with what you see above.


hmm This is not standart usecase for imjournal. I would suggest to use something like in default .conf. 

#--------------------------------------
$ModLoad imuxsock 
$ModLoad imjournal
$WorkDirectory /var/lib/rsyslog
$ActionFileDefaultTemplate RSYSLOG_TraditionalFileFormat
$SystemLogSocketName /run/systemd/journal/syslog
$OmitLocalLogging on
$IMJournalStateFile imjournal.state

mail.debug      /var/log/maillog
#---------------------------------------

Try that.

Comment 7 Jan Stancek 2017-06-08 09:08:56 UTC
Can you elaborate on that? Is there some interaction between imuxsock and imjournal? The doc [1] says these are alternatives, so I'd expect they can work independently.

If we use config above, which plugin will take precedence?

[1] https://access.redhat.com/documentation/en-US/Red_Hat_Enterprise_Linux/7/html/System_Administrators_Guide/s1-interaction_of_rsyslog_and_journal.html

Comment 8 Jakub Raček 2017-06-08 10:27:19 UTC
> hmm This is not standart usecase for imjournal. I would suggest to use
> something like in default .conf. 
> 

Original config file says:

# Turn off message reception via local log socket;                              
# local messages are retrieved through imjournal now.                           
$OmitLocalLogging on                

As far as I can tell, only when this is set to off, then $SystemLogSocketName becomes relevant. If it's not and both modules are loaded, the message gets logged twice. 

$ActionFileDefaultTemplate just sets format.

Are you sure that the configuration you suggested is effectively different from the one we have in tests?

Comment 9 Radovan Sroka 2017-06-08 10:55:40 UTC
(In reply to Jan Stancek from comment #7)
> Can you elaborate on that? Is there some interaction between imuxsock and
> imjournal? The doc [1] says these are alternatives, so I'd expect they can
> work independently.
> 

They should.

> If we use config above, which plugin will take precedence?
> 
> [1]
> https://access.redhat.com/documentation/en-US/Red_Hat_Enterprise_Linux/7/
> html/System_Administrators_Guide/s1-interaction_of_rsyslog_and_journal.html



(In reply to Jakub Raček from comment #8)
> > hmm This is not standart usecase for imjournal. I would suggest to use
> > something like in default .conf. 
> > 
> 
> Original config file says:
> 
> # Turn off message reception via local log socket;                          
> 
> # local messages are retrieved through imjournal now.                       
> 
> $OmitLocalLogging on                
> 
> As far as I can tell, only when this is set to off, then
> $SystemLogSocketName becomes relevant. If it's not and both modules are
> loaded, the message gets logged twice. 

Yes. Imjournal reads systemd socket "SystemLogSocketName" and Imuxsock reads /dev/log byt default but that is symlink to systemd socket(at least on fedora and I'm not sure how is this provided in rhel7)

So this is why "OmitLocalLogging" is used.
> 
> $ActionFileDefaultTemplate just sets format.
> 
> Are you sure that the configuration you suggested is effectively different
> from the one we have in tests?

It shoud be ok. My comment about configuration is irrelevant.

Comment 10 Radovan Sroka 2017-06-08 11:05:27 UTC
You have such rule in configuration.

mail.debug      /var/log/maillog

I would left rule for /var/log/messages in your .conf. You can see whether the message arrived at least there.

Or create *.* this rule instead.

Good debug helper is debug template.

see http://www.rsyslog.com/doc/v8-stable/configuration/templates.html

Try it and you will see. I'm just guessing that the message has different priority or severity as you were expecting.

Comment 12 Jan Stancek 2017-07-26 08:16:11 UTC
Created attachment 1304638 [details]
rsyslog patch and debug log 1

I started running failing test with modified rsyslog, hoping it would sched more light on where things go wrong (imjournal, systemd or syslog02 test).

I added some extra logs to plugins/imjournal/imjournal.c, attached is rsyslog debug log. Looking at the end of log I see pollJournal()/sd_journal_process returned 4 times "1" (SD_JOURNAL_APPEND), but trace in readjournal() just stops appearing after "Starting System Logging Service..." message.

Comment 13 John Shortt 2017-07-27 14:22:15 UTC
*** Bug 1473809 has been marked as a duplicate of this bug. ***

Comment 14 Radovan Sroka 2017-08-30 12:57:19 UTC
Hi,

you should try to change rsyslog config to use imuxsock instead of imjournal.

Here is the config:

$ModLoad imuxsock
$WorkDirectory /var/lib/rsyslog
$SystemLogSocketName /run/systemd/journal/syslog
$OmitLocalLogging off

... #some rules like "mail.debug      /var/log/maillog"

If problem persist, there is probably something wrong in your test suite. If not, there is some race condition in imjournal module and we are closer to make this right. 

@Jan Stancek:
I would like to debug rsyslog but I need some ssh access to machine with failing test.
BTW that code was slightly refactored between 7.3 and 7.4 (bacause of rebase).

Comment 16 Jan Stancek 2017-08-31 06:51:38 UTC
(In reply to Radovan Sroka from comment #14)
> Hi,
> 
> you should try to change rsyslog config to use imuxsock instead of imjournal.
> 
> Here is the config:
> 
> $ModLoad imuxsock
> $WorkDirectory /var/lib/rsyslog
> $SystemLogSocketName /run/systemd/journal/syslog
> $OmitLocalLogging off
> 
> ... #some rules like "mail.debug      /var/log/maillog"

This is how test worked until July 2015. When imjournal became default in RHEL, LTP switched to that. First mention of syslog tests failing I can find is from May 2016.

> 
> If problem persist, there is probably something wrong in your test suite. If
> not, there is some race condition in imjournal module and we are closer to
> make this right. 

This is possible, but we'll likely know only many months later with relative certainty.

> 
> @Jan Stancek:
> I would like to debug rsyslog but I need some ssh access to machine with
> failing test.

In other words reliable reproducer. Unfortunately nobody has figured out yet how to reproduce this on demand. I think a debug patch for test/rsyslog has best chance of moving us forward - if/when we can reproduce it again with the extra logs.

Comment 17 Radovan Sroka 2017-08-31 08:01:34 UTC
(In reply to Jan Stancek from comment #16)
> (In reply to Radovan Sroka from comment #14)
> > Hi,
> > 
> > you should try to change rsyslog config to use imuxsock instead of imjournal.
> > 
> > Here is the config:
> > 
> > $ModLoad imuxsock
> > $WorkDirectory /var/lib/rsyslog
> > $SystemLogSocketName /run/systemd/journal/syslog
> > $OmitLocalLogging off
> > 
> > ... #some rules like "mail.debug      /var/log/maillog"
> 
> This is how test worked until July 2015. When imjournal became default in
> RHEL, LTP switched to that. First mention of syslog tests failing I can find
> is from May 2016.
> 
> > 
> > If problem persist, there is probably something wrong in your test suite. If
> > not, there is some race condition in imjournal module and we are closer to
> > make this right. 
> 
> This is possible, but we'll likely know only many months later with relative
> certainty.
> 
> > 
> > @Jan Stancek:
> > I would like to debug rsyslog but I need some ssh access to machine with
> > failing test.
> 
> In other words reliable reproducer. Unfortunately nobody has figured out yet
> how to reproduce this on demand. I think a debug patch for test/rsyslog has
> best chance of moving us forward - if/when we can reproduce it again with
> the extra logs.

So what are next steps? I think we can and we should schedule run for test suite with imuxsock and also another with patched rsyslog as many times as possible e.g. 100. We can use some compose that was problematic before.

Comment 18 Jan Stancek 2017-08-31 08:20:50 UTC
(In reply to Radovan Sroka from comment #17)
> So what are next steps? I think we can and we should schedule run for test
> suite with imuxsock and also another with patched rsyslog as many times as
> possible e.g. 100. We can use some compose that was problematic before.

I'm running patched rsyslog for a while now, but it didn't reproduce yet with my latest round of extra logs after 1000+ recipes. The one instance you see in comment 12 took couple hundred recipes.

Comment 19 PaulB 2018-01-26 14:04:55 UTC
All,
Here is a reproducer:
 arch: s390x
 host: ibm-z-21
 distro: RHEL-ALT-7.5-20180123.n.0 Server s390x
 kernel-alt: 4.14.0-32.el7a debug
 task: /kernel/distribution/ltp/lite 20180118-1

https://beaker.engineering.redhat.com/recipes/4724953#task66995856
http://beaker-archive.app.eng.bos.redhat.com/beaker-logs/2018/01/22692/2269256/4724953/66995856/329696347/resultoutputfile.log
---<-snip->---
syslog02                       FAIL       1    
---<-snip->---

http://beaker-archive.app.eng.bos.redhat.com/beaker-logs/2018/01/22692/2269256/4724953/66995856/RHELKT1LITE.FILTERED.run.log
---<-snip->---
<<<test_start>>>
tag=syslog02 stime=1516926043
cmdline="syslog02"
contacts=""
analysis=exit
<<<test_output>>>
syslog02    0  TINFO  :  Test if messages of all levels are logged.
syslog02    0  TINFO  :  For each level, a separate configuration file is
syslog02    0  TINFO  :  created and that will be used as syslog.conf file.
syslog02    0  TINFO  :  testing whether messages are logged into log file
syslog02    0  TINFO  :  Doing level: emerg...
syslog02    0  TINFO  :  restarting syslog daemon
syslog02    1  TPASS  :  ***** Level emerg passed *****
syslog02    0  TINFO  :  Doing level: alert...
syslog02    0  TINFO  :  restarting syslog daemon
syslog02    2  TPASS  :  ***** Level alert passed *****
syslog02    0  TINFO  :  Doing level: crit...
syslog02    0  TINFO  :  restarting syslog daemon
syslog02    3  TPASS  :  ***** Level crit passed *****
syslog02    0  TINFO  :  Doing level: err...
syslog02    0  TINFO  :  restarting syslog daemon
syslog02    4  TPASS  :  ***** Level err passed *****
syslog02    0  TINFO  :  Doing level: warning...
syslog02    0  TINFO  :  restarting syslog daemon
syslog02    5  TPASS  :  ***** Level warning passed *****
syslog02    0  TINFO  :  Doing level: notice...
syslog02    0  TINFO  :  restarting syslog daemon
syslog02    6  TFAIL  :  ltpapicmd.c:190: ***** Level notice failed *****
syslog02    0  TINFO  :  Doing level: info...
syslog02    0  TINFO  :  restarting syslog daemon
syslog02    7  TPASS  :  ***** Level info passed *****
syslog02    0  TINFO  :  Doing level: debug...
syslog02    0  TINFO  :  restarting syslog daemon
syslog02    8  TPASS  :  ***** Level debug passed *****
syslog02    0  TINFO  :  restarting syslog daemon
<<<execution_status>>>
initiation_status="ok"
duration=34 termination_type=exited termination_id=1 corefile=no
cutime=3 cstime=16
<<<test_end>>>
---<-snip->---


Best,
-pbunyan

Comment 20 PaulB 2018-01-30 13:46:24 UTC
All,
Here is a reproducer:
 distro: RHEL-ALT-7.5-20180128.n.0 Server s390x
 kernel-alt: 4.14.0-34.el7a debug
 task: /kernel/distribution/ltp/lite 20180118-1



https://beaker.engineering.redhat.com/recipes/4742759#task67179975
http://beaker-archive.app.eng.bos.redhat.com/beaker-logs/2018/01/22766/2276621/4742759/67179975/330495809/resultoutputfile.log
---<-snip->---
syslog04                       FAIL       1    
---<-snip->---

http://beaker-archive.app.eng.bos.redhat.com/beaker-logs/2018/01/22766/2276621/4742759/67179975/RHELKT1LITE.FILTERED.run.log
---<-snip->---
<<<test_start>>>
tag=syslog04 stime=1517292148
cmdline="syslog04"
contacts=""
analysis=exit
<<<test_output>>>
syslog04    0  TINFO  :  case4: Test the logging option: LOG_PID
syslog04    0  TINFO  :  Do openlog() with LOG_PID option and see whether pid
syslog04    0  TINFO  :  is logged with message.
syslog04    0  TINFO  :  Testing the log option: LOG_PID...
syslog04    0  TINFO  :  restarting syslog daemon
syslog04    0  TINFO  :  restarting syslog daemon
<<<execution_status>>>
initiation_status="ok"
duration=6 termination_type=exited termination_id=1 corefile=no
cutime=1 cstime=5
<<<test_end>>>
<<<test_start>>>
tag=syslog05 stime=1517292154
cmdline="syslog05"
contacts=""
analysis=exit
<<<test_output>>>
syslog05    0  TINFO  :   case5: Test the logging option: LOG_CONS
syslog05    0  TINFO  :   o Do openlog() with LOG_CONS option.
syslog05    0  TINFO  :   o Disable /dev/syslog by moving it to a temporary file name.
syslog05    0  TINFO  :   o Send the syslog message.
syslog05    0  TINFO  :   o Check whether this is written to the console i.e to
syslog05    0  TINFO  :     the file /usr/adm/ktlog/<this year>/<this month>/<to_day>
syslog05    0  TINFO  :  syslog: Testing the log option: LOG_CONS...
syslog05    0  TINFO  :  restarting syslog daemon
syslog05    0  TINFO  :  restarting syslog daemon
<<<execution_status>>>
initiation_status="ok"
duration=26 termination_type=exited termination_id=0 corefile=no
cutime=1 cstime=5
<<<test_end>>>
---<-snip->---




Best,
-pbunyan


Note You need to log in before you can comment on or make changes to this bug.