Bug 1495631

Summary: Journal is reloaded and duplicate messages are output into log file.
Product: Red Hat Enterprise Linux 7 Reporter: Xueying Nie <xnie>
Component: rsyslogAssignee: Radovan Sroka <rsroka>
Status: CLOSED NOTABUG QA Contact: BaseOS QE Security Team <qe-baseos-security>
Severity: high Docs Contact:
Priority: unspecified    
Version: 7.4CC: bwelterl, mpoole, qguo, sdordevi, xnie
Target Milestone: rc   
Target Release: ---   
Hardware: x86_64   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2017-10-10 08:29:45 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 Xueying Nie 2017-09-26 11:13:38 UTC
Description of problem:

Journal is reloaded and duplicate messages are output into log file.

Version-Release number of selected component (if applicable):

rsyslog-8.24.0-12.el7.x86_64

How reproducible:


Steps to Reproduce:
1. Disable the rate-limiting of journald.
    -/etc/systemd/journald.conf
  RateLimitInterval=0  

2. Execute the command below.
   # for i in `seq 1 3000`;do logger -p local5.info "modify syslog rate limit modify 1640: $i" ;done 

3. Check /var/log/messages.

Actual results:

Journal reloaded and some duplicate messages are output to log file.
~~~
Sep 14 20:19:01 R74Router root: modify syslog rate limit modify 1640: 871
Sep 14 20:19:01 R74Router root: modify syslog rate limit modify 1640: 872
Sep 14 20:19:01 R74Router root: modify syslog rate limit modify 1640: 873
Sep 14 20:19:01 R74Router root: modify syslog rate limit modify 1640: 865  <
Sep 14 20:19:01 R74Router root: modify syslog rate limit modify 1640: 866  <
Sep 14 20:19:01 R74Router root: modify syslog rate limit modify 1640: 867  <
Sep 14 20:19:01 R74Router root: modify syslog rate limit modify 1640: 868  <
Sep 14 20:19:01 R74Router root: modify syslog rate limit modify 1640: 869  <
Sep 14 20:19:01 R74Router root: modify syslog rate limit modify 1640: 870  <
Sep 14 20:19:01 R74Router root: modify syslog rate limit modify 1640: 871  <
Sep 14 20:19:01 R74Router root: modify syslog rate limit modify 1640: 872  <
Sep 14 20:19:01 R74Router root: modify syslog rate limit modify 1640: 873  <
Sep 14 20:19:01 R74Router root: modify syslog rate limit modify 1640: 874
Sep 14 20:19:01 R74Router rsyslogd: imjournal: journal reloaded... [v8.24.0 try http://www.rsyslog.com/e/0 ]
Sep 14 20:19:01 R74Router root: modify syslog rate limit modify 1640: 875
~~~

Expected results:

No duplicate messages are output to the file.
~~~
Sep 14 20:19:01 R74Router root: modify syslog rate limit modify 1640: 871
Sep 14 20:19:01 R74Router root: modify syslog rate limit modify 1640: 872
Sep 14 20:19:01 R74Router root: modify syslog rate limit modify 1640: 873
Sep 14 20:19:01 R74Router root: modify syslog rate limit modify 1640: 874
Sep 14 20:19:01 R74Router root: modify syslog rate limit modify 1640: 875
~~~

Additional info:

There is no duplicate messages in Journal.

Comment 2 Radovan Sroka 2017-09-27 15:38:23 UTC
Actually I cannot reproduce this issue. 

Can you try to set PersistStateInterval for imjournal to 1?

If this works, this is expected behavior.

With reloading of journal or rsyslog itself, it comes the price. It is technically impossible to handle duplication of messages. Duplication is always =< PersistStateInterval. But PersistStateInterval = 1 has impact on performance.