Bug 1245194

Summary: imjournal: fscanf on state file `/var/lib/rsyslog/imjournal.state' failed
Product: Red Hat Enterprise Linux 7 Reporter: Robert Scheck <redhat-bugzilla>
Component: rsyslogAssignee: Peter Vrabec <pvrabec>
Status: CLOSED ERRATA QA Contact: Stefan Dordevic <sdordevi>
Severity: high Docs Contact:
Priority: high    
Version: 7.1CC: cww, gayleard, gnaik, hartsjc, ksrot, mdshaikh, pablo.iranzo, popolon72, pvrabec, robert.scheck, rsroka
Target Milestone: rcKeywords: Patch
Target Release: ---   
Hardware: All   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2016-11-04 05:36:29 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:
Bug Depends On:    
Bug Blocks: 1203710, 1295396, 1296594, 1313485    
Attachments:
Description Flags
Patch that resolves reading and writing of statefile none

Description Robert Scheck 2015-07-21 12:46:09 UTC
Description of problem:
No more logging of anything, just the following stuff in /var/log/messages;
restarting of rsyslog or the whole system does not help:

Jul 19 03:42:03 backup rsyslogd: [origin software="rsyslogd" swVersion="7.4.7" x-pid="615" x-info="http://www.rsyslog.com"] rsyslogd was HUPed
^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@^@Jul 21 16:27:22 backup rsyslogd: [origin software="rsyslogd" swVersion="7.4.7" x-pid="614" x-info="http://www.rsyslog.com"] start
Jul 21 16:27:22 backup rsyslogd-2027: imjournal: fscanf on state file `/var/lib/rsyslog/imjournal.state' failed
 [try http://www.rsyslog.com/e/2027 ]
Jul 21 14:39:35 backup rsyslogd: [origin software="rsyslogd" swVersion="7.4.7" x-pid="614" x-info="http://www.rsyslog.com"] exiting on signal 15.
Jul 21 14:39:35 backup rsyslogd: [origin software="rsyslogd" swVersion="7.4.7" x-pid="1355" x-info="http://www.rsyslog.com"] start
Jul 21 14:39:35 backup rsyslogd-2027: imjournal: fscanf on state file `/var/lib/rsyslog/imjournal.state' failed
 [try http://www.rsyslog.com/e/2027 ]

Version-Release number of selected component (if applicable):
rsyslog-7.4.7-7.el7_0.x86_64

How reproducible:
No idea - but it feels strange.

Actual results:
imjournal: fscanf on state file `/var/lib/rsyslog/imjournal.state' failed

Expected results:
No errors.

Additional info:
[root@backup log]# cd /var/lib/rsyslog/
[root@backup rsyslog]# ls -l
insgesamt 0
-rw-r--r--. 1 root root 0  1. Sep 2014  imjournal.state
[root@backup rsyslog]# 

[root@backup rsyslog]# mv /var/lib/rsyslog/imjournal.state /var/lib/rsyslog/imjournal.state.broken
[root@backup rsyslog]# 

[root@backup rsyslog]# systemctl restart rsyslog.service
[root@backup rsyslog]# 

Afterwards it seems to have settled again:

Jul 21 14:39:48 backup rsyslogd: [origin software="rsyslogd" swVersion="7.4.7" x-pid="1355" x-info="http://www.rsyslog.com"] exiting on signal 15.
Jul 21 14:39:48 backup rsyslogd: [origin software="rsyslogd" swVersion="7.4.7" x-pid="1371" x-info="http://www.rsyslog.com"] start
Jul 21 16:27:12 backup journal: Runtime journal is using 8.0M (max 399.1M, leaving 598.7M of free 3.8G, current limit 399.1M).
Jul 21 16:27:12 backup journal: Runtime journal is using 8.0M (max 399.1M, leaving 598.7M of free 3.8G, current limit 399.1M).
Jul 21 16:27:12 backup kernel: Initializing cgroup subsys cpuset
Jul 21 16:27:12 backup kernel: Initializing cgroup subsys cpu
Jul 21 16:27:12 backup kernel: Initializing cgroup subsys cpuacct
[...]

The question is: Why does /var/lib/rsyslog/imjournal.state hold up the
whole logging? This feels like a bug to me.

Comment 2 Robert Scheck 2015-07-21 12:49:00 UTC
Cross-filed case 01479984 on Red Hat customer portal.

Comment 10 Timothy Murphy 2015-10-23 12:35:39 UTC
I'm getting this message on my Fedora-23beta/KDE laptop, when I restart rsyslog in order to get information in /var/log/messages .

Comment 16 Radovan Sroka 2016-06-21 08:50:54 UTC
Created attachment 1170158 [details]
Patch that resolves reading and writing of statefile

This bug is caused by not very atomic writing of imjournal statefile and it's hardly reproducible but there is a way.

fscanf error appears only when rsyslog reads empty statefile and it will cause that imjournal is stopped so no logging from journal is performed.
When statefile contains some random bytes error appears again but from journal and imjournal is stopped too.


In this patch Rsyslog is writing imjournal statefile more atomically and secure.

Reading of statefile is more robust and it doesn't affect imjournal module so when corrupted statefile is read then imjournal ignore statefile and continue with logging and it doesn't stop. We can use a logger as a test if it's logging or not.

Patch introduce new option in both old and new config "IgnoreNonValidStateFile" which is default "on" and it can turn off ignorance of non valid statefile.

New config:

module(load="imjournal" 
    StateFile="imjournal.state" 
    IgnoreNonValidStatefile="on"/"off" #default on
    #IgnorePreviousMessages="on"
)

Old config:

$ModLoad imjournal
$WorkDirectory /var/lib/rsyslog
$IMJournalStateFile imjournal.state
$IMJournalIgnoreNonValidStatefile on/off
#$IMJournalIgnorePreviousMessages on

Comment 26 errata-xmlrpc 2016-11-04 05:36:29 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://rhn.redhat.com/errata/RHEA-2016-2401.html

Comment 27 popolon72 2016-11-23 08:18:41 UTC
Is this change going to be put to upstream to github.com rsyslog repository?

Comment 28 Radovan Sroka 2016-11-23 11:17:58 UTC
Yes I hope so,

Most likely in near future.

Comment 29 Radovan Sroka 2016-12-08 16:00:54 UTC
We are already created a pull request on upstream github repository.

https://github.com/rsyslog/rsyslog/pull/1317