Bug 1271182 - journalctl --since ... does not work reliably
journalctl --since ... does not work reliably
Status: NEW
Product: Red Hat Enterprise Linux 7
Classification: Red Hat
Component: systemd (Show other bugs)
7.2
Unspecified Unspecified
medium Severity medium
: rc
: ---
Assigned To: systemd-maint
qe-baseos-daemons
:
Depends On:
Blocks: 1400961 1472751
  Show dependency treegraph
 
Reported: 2015-10-13 06:52 EDT by Martin Kyral
Modified: 2017-10-03 21:24 EDT (History)
6 users (show)

See Also:
Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed:
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)

  None (edit)
Description Martin Kyral 2015-10-13 06:52:40 EDT
Description of problem:
The abrt's 'meaningful*logs' upstream test frequently fails on ppc64/ppc64le/aarch64, because journalctl tends to 'ignore' the --since option when SYSLOG_IDENTIFIER is provided:

[root@ibm-p8-02-lp2 Upstream]# journalctl SYSLOG_IDENTIFIER=abrtd --since='2015-10-12 09:19:09'
-- Logs begin at Po 2015-10-12 09:03:43 EDT, end at Po 2015-10-12 09:19:19 EDT. --
říj 12 13:03:50 ibm-p8-02-lp2.rhts.eng.bos.redhat.com abrtd[1604]: Init complete, entering main loop
říj 12 09:12:44 ibm-p8-02-lp2.rhts.eng.bos.redhat.com abrtd[1604]: Got signal 15, exiting
říj 12 09:12:44 ibm-p8-02-lp2.rhts.eng.bos.redhat.com abrtd[23303]: Init complete, entering main loop
říj 12 09:12:47 ibm-p8-02-lp2.rhts.eng.bos.redhat.com abrtd[23303]: Got signal 15, exiting
říj 12 09:12:47 ibm-p8-02-lp2.rhts.eng.bos.redhat.com abrtd[23843]: Init complete, entering main loop
říj 12 09:12:55 ibm-p8-02-lp2.rhts.eng.bos.redhat.com abrtd[23843]: Got signal 15, exiting
říj 12 09:12:55 ibm-p8-02-lp2.rhts.eng.bos.redhat.com abrtd[24176]: Init complete, entering main loop
říj 12 09:13:12 ibm-p8-02-lp2.rhts.eng.bos.redhat.com abrtd[24176]: Got signal 15, exiting
říj 12 09:13:13 ibm-p8-02-lp2.rhts.eng.bos.redhat.com abrtd[25785]: Init complete, entering main loop
říj 12 09:13:47 ibm-p8-02-lp2.rhts.eng.bos.redhat.com abrtd[25785]: Got signal 15, exiting
říj 12 09:13:47 ibm-p8-02-lp2.rhts.eng.bos.redhat.com abrtd[28763]: Init complete, entering main loop
říj 12 09:13:50 ibm-p8-02-lp2.rhts.eng.bos.redhat.com abrtd[28763]: Got signal 15, exiting
říj 12 09:13:51 ibm-p8-02-lp2.rhts.eng.bos.redhat.com abrtd[29325]: '/var/spool/abrt/testsuite-sane-logs' is not a problem directory
říj 12 09:13:51 ibm-p8-02-lp2.rhts.eng.bos.redhat.com abrtd[29325]: Init complete, entering main loop
říj 12 09:13:52 ibm-p8-02-lp2.rhts.eng.bos.redhat.com abrtd[29325]: Got signal 15, exiting
říj 12 09:13:54 ibm-p8-02-lp2.rhts.eng.bos.redhat.com abrtd[29436]: '/var/spool/abrt/testsuite-sane-logs' is not a problem directory
říj 12 09:13:54 ibm-p8-02-lp2.rhts.eng.bos.redhat.com abrtd[29436]: Init complete, entering main loop
říj 12 09:13:54 ibm-p8-02-lp2.rhts.eng.bos.redhat.com abrtd[29436]: Got signal 15, exiting
říj 12 09:13:56 ibm-p8-02-lp2.rhts.eng.bos.redhat.com abrtd[29538]: '/var/spool/abrt/testsuite-sane-logs' is not a problem directory
říj 12 09:13:56 ibm-p8-02-lp2.rhts.eng.bos.redhat.com abrtd[29538]: Init complete, entering main loop
říj 12 09:13:57 ibm-p8-02-lp2.rhts.eng.bos.redhat.com abrtd[29538]: Got signal 15, exiting
říj 12 09:13:59 ibm-p8-02-lp2.rhts.eng.bos.redhat.com abrtd[29648]: '/var/spool/abrt/testsuite-sane-logs' is not a problem directory
říj 12 09:13:59 ibm-p8-02-lp2.rhts.eng.bos.redhat.com abrtd[29648]: Init complete, entering main loop
říj 12 09:13:59 ibm-p8-02-lp2.rhts.eng.bos.redhat.com abrtd[29648]: Got signal 15, exiting
říj 12 09:14:01 ibm-p8-02-lp2.rhts.eng.bos.redhat.com abrtd[29752]: Marking '/var/spool/abrt/testsuite-sane-logs' not reportable (no 'count' item)
říj 12 09:14:01 ibm-p8-02-lp2.rhts.eng.bos.redhat.com abrtd[29752]: Init complete, entering main loop
říj 12 09:14:01 ibm-p8-02-lp2.rhts.eng.bos.redhat.com abrtd[29752]: Got signal 15, exiting
říj 12 09:14:03 ibm-p8-02-lp2.rhts.eng.bos.redhat.com abrtd[29846]: Init complete, entering main loop
říj 12 09:14:03 ibm-p8-02-lp2.rhts.eng.bos.redhat.com abrtd[29846]: Got signal 15, exiting
říj 12 09:19:01 ibm-p8-02-lp2.rhts.eng.bos.redhat.com abrtd[31705]: Init complete, entering main loop
říj 12 09:19:02 ibm-p8-02-lp2.rhts.eng.bos.redhat.com abrtd[31705]: Got signal 15, exiting
říj 12 09:19:04 ibm-p8-02-lp2.rhts.eng.bos.redhat.com abrtd[32237]: '/var/spool/abrt/testsuite-sane-logs' is not a problem directory
říj 12 09:19:04 ibm-p8-02-lp2.rhts.eng.bos.redhat.com abrtd[32237]: Init complete, entering main loop
říj 12 09:19:04 ibm-p8-02-lp2.rhts.eng.bos.redhat.com abrtd[32237]: Got signal 15, exiting
říj 12 09:19:07 ibm-p8-02-lp2.rhts.eng.bos.redhat.com abrtd[32330]: '/var/spool/abrt/testsuite-sane-logs' is not a problem directory
říj 12 09:19:07 ibm-p8-02-lp2.rhts.eng.bos.redhat.com abrtd[32330]: Init complete, entering main loop
říj 12 09:19:07 ibm-p8-02-lp2.rhts.eng.bos.redhat.com abrtd[32330]: Got signal 15, exiting
říj 12 09:19:09 ibm-p8-02-lp2.rhts.eng.bos.redhat.com abrtd[32422]: '/var/spool/abrt/testsuite-sane-logs' is not a problem directory
říj 12 09:19:09 ibm-p8-02-lp2.rhts.eng.bos.redhat.com abrtd[32422]: Init complete, entering main loop
říj 12 09:19:09 ibm-p8-02-lp2.rhts.eng.bos.redhat.com abrtd[32422]: Got signal 15, exiting
říj 12 09:19:12 ibm-p8-02-lp2.rhts.eng.bos.redhat.com abrtd[32514]: '/var/spool/abrt/testsuite-sane-logs' is not a problem directory
říj 12 09:19:12 ibm-p8-02-lp2.rhts.eng.bos.redhat.com abrtd[32514]: Init complete, entering main loop
říj 12 09:19:12 ibm-p8-02-lp2.rhts.eng.bos.redhat.com abrtd[32514]: Got signal 15, exiting
říj 12 09:19:14 ibm-p8-02-lp2.rhts.eng.bos.redhat.com abrtd[32608]: Marking '/var/spool/abrt/testsuite-sane-logs' not reportable (no 'count' item)
říj 12 09:19:14 ibm-p8-02-lp2.rhts.eng.bos.redhat.com abrtd[32608]: Init complete, entering main loop
říj 12 09:19:14 ibm-p8-02-lp2.rhts.eng.bos.redhat.com abrtd[32608]: Got signal 15, exiting
říj 12 09:19:16 ibm-p8-02-lp2.rhts.eng.bos.redhat.com abrtd[32692]: Init complete, entering main loop
říj 12 09:19:16 ibm-p8-02-lp2.rhts.eng.bos.redhat.com abrtd[32692]: Got signal 15, exiting

See the meesage timestamps and compare with alternative way of filtering the abrtd messages:

[root@ibm-p8-02-lp2 Upstream]# journalctl --since='2015-10-12 09:19:09' | grep abrtd
říj 12 09:19:09 ibm-p8-02-lp2.rhts.eng.bos.redhat.com abrtd[32422]: '/var/spool/abrt/testsuite-sane-logs' is not a problem directory
říj 12 09:19:09 ibm-p8-02-lp2.rhts.eng.bos.redhat.com abrtd[32422]: Init complete, entering main loop
říj 12 09:19:09 ibm-p8-02-lp2.rhts.eng.bos.redhat.com abrtd[32422]: Got signal 15, exiting
říj 12 09:19:12 ibm-p8-02-lp2.rhts.eng.bos.redhat.com abrtd[32514]: '/var/spool/abrt/testsuite-sane-logs' is not a problem directory
říj 12 09:19:12 ibm-p8-02-lp2.rhts.eng.bos.redhat.com abrtd[32514]: Init complete, entering main loop
říj 12 09:19:12 ibm-p8-02-lp2.rhts.eng.bos.redhat.com abrtd[32514]: Got signal 15, exiting
říj 12 09:19:14 ibm-p8-02-lp2.rhts.eng.bos.redhat.com abrtd[32608]: Marking '/var/spool/abrt/testsuite-sane-logs' not reportable (no 'count' item)
říj 12 09:19:14 ibm-p8-02-lp2.rhts.eng.bos.redhat.com abrtd[32608]: Init complete, entering main loop
říj 12 09:19:14 ibm-p8-02-lp2.rhts.eng.bos.redhat.com abrtd[32608]: Got signal 15, exiting
říj 12 09:19:16 ibm-p8-02-lp2.rhts.eng.bos.redhat.com abrtd[32692]: Init complete, entering main loop
říj 12 09:19:16 ibm-p8-02-lp2.rhts.eng.bos.redhat.com abrtd[32692]: Got signal 15, exiting
[root@ibm-p8-02-lp2 Upstream]#

This problem was spotted on ppc64, ppc64le and aarch64, but not on s390x nor x86_64. Also, it does not happen everytime.


Version-Release number of selected component (if applicable):
systemd-219-17.el7

How reproducible:
Most of the times


Steps to Reproduce:
1. see Description
2.
3.

Actual results:
Logs older than specified in --since are printed out



Expected results:
Logs older than specified in --since are filtered out


Additional info:
It seems this problem does not affect logs from every process - for instance with SYSLOG_IDENTIFIED=dracut the time filtering works as expected.
Comment 1 Martin Kyral 2015-10-21 03:34:45 EDT
I just met the issue on x86_64 so it's not arch related.
Comment 2 Jiří Vohánka 2016-01-14 07:05:04 EST
The problem might not be related to SYSLOG_IDENTIFIER, I have seen this happen (not every time) while using just '--since=' option.

# rpm -q systemd
systemd-219-19.el7.x86_64

# time="$(date +'%Y-%m-%d %H:%M:%S')"; echo "Time: $time"; echo x > /dev/kmsg; sleep 10; journalctl --no-pager --since="$time"
Time: 2016-01-14 06:40:06
-- Logs begin at Thu 2016-01-14 05:35:57 EST, end at Thu 2016-01-14 06:40:06 EST. --
Jan 14 10:36:04 amd-pence-02.lab.bos.redhat.com systemd-journal[651]: Runtime journal is using 8.0M (max allowed 2.3G, trying to leave 3.5G free of 23.4G available → current limit 2.3G).
...
Jan 14 10:36:23 amd-pence-02.lab.bos.redhat.com chronyd[932]: System clock wrong by -18000.814339 seconds, adjustment started
Jan 14 05:36:22 amd-pence-02.lab.bos.redhat.com chronyd[932]: System clock was stepped by -18000.814339 seconds
...
Jan 14 06:40:06 amd-pence-02.lab.bos.redhat.com unknown: x

# time="$(date --utc +'%Y-%m-%d %H:%M:%S')"; echo "UTC time: $time"; echo x > /dev/kmsg; sleep 10; journalctl --no-pager --utc --since="$time"
UTC time: 2016-01-14 11:43:13
-- Logs begin at Thu 2016-01-14 10:35:57 GMT, end at Thu 2016-01-14 11:43:13 GMT. --
Comment 4 Lukáš Nykrýn 2016-08-17 10:01:10 EDT
I am sorry, we were not able to get to this one. Re-targeting to 7.4.

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