Bug 1660933

Summary:	/var/log/messages out of chronological order
Product:	[Fedora] Fedora	Reporter:	RobbieTheK <rkudyba>
Component:	rsyslog	Assignee:	Jiří Vymazal <jvymazal>
Status:	CLOSED EOL	QA Contact:	Fedora Extras Quality Assurance <extras-qa>
Severity:	medium	Docs Contact:
Priority:	unspecified
Version:	29	CC:	dkopecek, jlieskov, jvymazal, lkundrak, mah.darade, rsroka, tosykora
Target Milestone:	---
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:	2019-05-28 23:28:40 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 RobbieTheK 2018-12-19 16:10:24 UTC

Similar to BZ 1120894, logs in /var/log/messages are out of order.  journalctl appears to be in good order and running journalctl --verify, all showed PASS.

rsyslog-8.39.0-1.fc28.x86_64 & systemd-238-10.git438ac26.fc28.x86_64

I do see logs like:

Dec 16 19:26:11 storm rsyslogd: imjournal: sd_journal_get_cursor() failed: Cannot assign requested address [v8.39.0]
Dec 16 19:26:11 storm rsyslogd: imjournal: journal reloaded... [v8.39.0 try http://www.rsyslog.com/e/0 ]

and then:
Dec 16 19:26:37 storm rsyslogd: imjournal: loaded invalid cursor, seeking to the head of journal : Cannot assign requested address [v8.39.0 try http://www.rsyslog.com/e/2027 ]
Dec 16 19:26:37 storm rsyslogd: imjournal: journal reloaded... [v8.39.0 try http://www.rsyslog.com/e/0 ]
Oct 27 07:02:24 storm systemd[2462]: Stopped target Default.
Oct 27 07:02:25 storm systemd[2462]: Stopped target Basic System.

Then logs like these:
Dec 14 17:10:21 storm systemd[8381]: Starting Exit the Session...
Dec 14 17:10:21 storm systemd[8381]: Received SIGRTMIN+24 from PID 10899 (kill).
Jan  8 03:08:09 storm systemd[27471]: Stopped target Default.
Jan  8 03:08:10 storm systemd[27471]: Stopped target Basic System.
Jan  8 03:08:10 storm systemd[27471]: Stopped target Paths.
Jan  8 03:08:10 storm systemd[27471]: Stopped target Sockets.
Jan  8 03:08:10 storm systemd[27471]: Closed D-Bus User Message Bus Socket.
Jan  8 03:08:10 storm systemd[27471]: Reached target Shutdown.
Jan  8 03:08:10 storm systemd[27471]: Starting Exit the Session...
Jan  8 03:08:10 storm systemd[27471]: Stopped target Timers.
Jan  8 03:08:10 storm systemd[27471]: Received SIGRTMIN+24 from PID 30660 (kill).
May 15 07:03:38 storm systemd[7003]: Stopped target Default.
May 15 07:04:02 storm systemd[24508]: Received SIGRTMIN+24 from PID 28198 (kill).

Nov  8 13:26:54 storm systemd[30136]: Closed Multimedia System.
Nov  8 13:26:54 storm systemd[30136]: Reached target Shutdown.
Nov  8 13:26:54 storm systemd[30136]: Starting Exit the Session...
Nov  8 13:26:54 storm systemd[30136]: Received SIGRTMIN+24 from PID 6795 (kill).
Dec 16 19:26:11 storm systemd[7685]: Listening on Sound System.
Dec 16 19:26:38 storm systemd[7685]: Listening on Multimedia System.


Could https://bugzilla.redhat.com/show_bug.cgi?id=1615014 be related 

# egrep '^(Jan|Feb|Mar|Apr|May|Jun|Jul|Aug|Sep|Nov|Dec)' /var/log/messages | awk '{print $1,$2}' | uniq
Dec 16
Dec 27
May 17
Nov 2
Dec 7
Dec 8
Dec 9
Dec 10
Dec 11
Dec 12
Dec 13
Dec 14
Jan 8
May 15
May 16
May 17
May 18
May 19
May 20
May 21
May 23
May 25
May 26
May 29
May 30
May 31
Jun 3
Jun 4
Jun 5
Jun 6
Jul 10
Nov 4
Nov 5
Nov 6
Nov 7
Nov 8
Dec 16
Dec 17
Dec 18
Dec 27
May 17
Nov 2
Dec 7
Dec 8
Dec 9
Dec 10
Dec 11
Dec 12
Dec 13
Dec 14
Jan 8
May 15
May 16
May 17
May 18
May 19
May 20
May 21
May 23
May 25
May 26
May 29
May 30
May 31
Jun 3
Jun 4
Jun 5
Jun 6
Jul 10
Nov 4
Nov 5
Nov 6
Nov 7
Nov 8
Dec 18

Comment 1 Jiří Vymazal 2018-12-20 09:31:56 UTC

Hi, does this happen also with the new WorkAroundJournalBug option "on" or "off" (default)?

Thanks.

Comment 2 RobbieTheK 2018-12-20 14:11:59 UTC

I added the option:

#$IMJournalStateFile imjournal.state
module(load="imjournal" StateFile="imjournal.state" WorkAroundJournalBug="on")

in /etc/rsyslog.conf

I restar rsyslog, it reloads the logs and ends with: 
Dec 20 09:08:54 storm rsyslogd: imjournal from <storm:cupsd>: begin to drop messages due to rate-limiting

Still seeing out of order entries like:
Dec 16 19:26:37 storm rsyslogd: imjournal: journal reloaded... [v8.39.0 try http://www.rsyslog.com/e/0 ]
Dec 16 19:26:37 storm rsyslogd: imjournal: journal reloaded... [v8.39.0 try http://www.rsyslog.com/e/0 ]
Dec 16 19:26:37 storm rsyslogd: imjournal: loaded invalid cursor, seeking to the head of journal : Cannot assign requested address [v8.39.0 try http://www.rsyslog.com/e/2027 ]
Dec 16 19:26:37 storm rsyslogd: imjournal: journal reloaded... [v8.39.0 try http://www.rsyslog.com/e/0 ]
Oct 27 07:02:24 storm systemd[2462]: Stopped target Default.

Comment 3 RobbieTheK 2018-12-20 16:13:41 UTC

Just a quick comment, the problem still happens but I finally got WorkAroundJournalBug working after commenting both:
$ModLoad imjournal
and
$IMJournalStateFile imjournal.state

They were not next to each other in the rsyslog.conf. After restarting the rate-limiting message went away but the logs are still out of order.

Comment 4 Ben Cotton 2019-05-02 20:06:24 UTC

This message is a reminder that Fedora 28 is nearing its end of life.
On 2019-May-28 Fedora will stop maintaining and issuing updates for
Fedora 28. It is Fedora's policy to close all bug reports from releases
that are no longer maintained. At that time this bug will be closed as
EOL if it remains open with a Fedora 'version' of '28'.

Package Maintainer: If you wish for this bug to remain open because you
plan to fix it in a currently maintained version, simply change the 'version' 
to a later Fedora version.

Thank you for reporting this issue and we are sorry that we were not 
able to fix it before Fedora 28 is end of life. If you would still like 
to see this bug fixed and are able to reproduce it against a later version 
of Fedora, you are encouraged  change the 'version' to a later Fedora 
version prior this bug is closed as described in the policy above.

Although we aim to fix as many bugs as possible during every release's 
lifetime, sometimes those efforts are overtaken by events. Often a 
more recent Fedora release includes newer upstream software that fixes 
bugs or makes them obsolete.

Comment 5 Ben Cotton 2019-05-28 23:28:40 UTC

Fedora 28 changed to end-of-life (EOL) status on 2019-05-28. Fedora 28 is
no longer maintained, which means that it will not receive any further
security or bug fix updates. As a result we are closing this bug.

If you can reproduce this bug against a currently maintained version of
Fedora please feel free to reopen this bug against that version. If you
are unable to reopen this bug, please file a new report against the
current release. If you experience problems, please add a comment to this
bug.

Thank you for reporting this bug and we are sorry it could not be fixed.

Comment 6 RobbieTheK 2019-05-28 23:53:09 UTC

Still happens on 29