1271182 – journalctl --since ... does not work reliably

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 1271182 - journalctl --since ... does not work reliably

Summary: journalctl --since ... does not work reliably

Keywords:
Status:	CLOSED WONTFIX
Alias:	None
Product:	Red Hat Enterprise Linux 7
Classification:	Red Hat
Component:	systemd
Sub Component:
Version:	7.2
Hardware:	Unspecified
OS:	Unspecified
Priority:	medium
Severity:	medium
Target Milestone:	rc
Target Release:	---
Assignee:	systemd-maint
QA Contact:	qe-baseos-daemons
Docs Contact:
URL:
Whiteboard:
Depends On:
Blocks:	1400961 1472751
TreeView+	depends on / blocked

Reported:	2015-10-13 10:52 UTC by Martin Kyral
Modified:	2020-12-15 07:37 UTC (History)
CC List:	5 users (show)
Fixed In Version:
Doc Type:	If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed:	2020-12-15 07:37:47 UTC
Target Upstream Version:
Embargoed:

Attachments	(Terms of Use)

Description Martin Kyral 2015-10-13 10:52:40 UTC

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 07:34:45 UTC

I just met the issue on x86_64 so it's not arch related.

Comment 2 Jiří Vohánka 2016-01-14 12:05:04 UTC

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 14:01:10 UTC

I am sorry, we were not able to get to this one. Re-targeting to 7.4.

Comment 8 RHEL Program Management 2020-12-15 07:37:47 UTC

After evaluating this issue, there are no plans to address it further or fix it in an upcoming release.  Therefore, it is being closed.  If plans change such that this issue will be fixed in an upcoming release, then the bug can be reopened.

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