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 1632211 - sd_journal_get_cursor() failed - when time is changed
Summary: sd_journal_get_cursor() failed - when time is changed
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Enterprise Linux 7
Classification: Red Hat
Component: rsyslog
Version: 7.6
Hardware: All
OS: Linux
urgent
high
Target Milestone: rc
: ---
Assignee: Jiří Vymazal
QA Contact: Dalibor Pospíšil
URL:
Whiteboard:
: 1647307 1698218 (view as bug list)
Depends On:
Blocks: 1647307 1698218 1707454 1722165
TreeView+ depends on / blocked
 
Reported: 2018-09-24 11:15 UTC by Ondrej Moriš
Modified: 2023-10-06 17:55 UTC (History)
35 users (show)

Fixed In Version: rsyslog-8.24.0-37.el7
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
: 1698218 1722165 (view as bug list)
Environment:
Last Closed: 2019-08-06 12:48:13 UTC
Target Upstream Version:
Embargoed:

Attachments (Terms of Use)
simple systemtap probe (534 bytes, text/plain)
2019-03-11 11:48 UTC, Jan Synacek 		no flags Details
View All


Links
System ID Private Priority Status Summary Last Updated
Github rsyslog rsyslog issues 862 0 'None' closed rsyslog stops reading journal data after journal file rotation 2021-02-15 01:37:45 UTC
Github systemd systemd issues 1752 0 'None' open API: sd_journal_seek_monotonic_usec doesn't work as expected 2021-02-15 01:37:45 UTC
Red Hat Bugzilla 1088021 0 high CLOSED Changing a VM host's time disables rsyslog file logging 2023-03-24 13:28:48 UTC
Red Hat Bugzilla 1292447 0 urgent CLOSED journald stop logging 2023-10-06 17:30:58 UTC
Red Hat Bugzilla 1538372 0 urgent CLOSED rsyslog appears to duplicate messages from journald when journald rotates its log files 2021-12-10 15:36:06 UTC
Red Hat Bugzilla 1615014 0 low CLOSED sd_journal_get_cursor() failed: Cannot assign requested address 2022-03-13 15:22:57 UTC
Red Hat Knowledge Base (Solution) 3705051 0 None None None 2019-01-29 19:20:45 UTC
Red Hat Product Errata RHSA-2019:2110 0 None None None 2019-08-06 12:48:36 UTC

Internal Links: 1088021 1292447 1538372 1615014

Description Ondrej Moriš 2018-09-24 11:15:45 UTC 
Description of problem:

When time is changed on a machine, rsyslogd reports the following error:

rsyslogd: sd_journal_get_cursor() failed: 'Cannot assign requested address'  [v8.24.0-34.el7]

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

rsyslog-8.24.0-34.el7

How reproducible:

100%

Steps to Reproduce:

1. Make sure rsyslog is running:

# service rsyslog status

2. Change time:

# date -s "$(date -d "now +1000 hours")"

3. Check /var/log/messages

Actual results:

* time is changed correctly
* rsyslog is running and works correctly before and after time change
* /var/log/messages contains sd_journal_get_cursor() failed:

Nov  4 21:54:09 host-172-16-36-101 systemd: Time has been changed
Nov  4 21:54:09 host-172-16-36-101 rsyslogd: sd_journal_get_cursor() failed: 'Cannot assign requested address'  [v8.24.0-34.el7]
Nov  4 21:54:09 host-172-16-36-101 rsyslogd: imjournal: journal reloaded... [v8.24.0-34.el7 try http://www.rsyslog.com/e/0 ]

Expected results:

* time is changed correctly
* rsyslog is running and works correctly before and after time change
* /var/log/messages DOES NOT contain sd_journal_get_cursor() failed'

Additional info:

This issue seems no to have any negative impact on rsyslog behaviour. BUT there was no such message on RHEL-7.5.
Comment 4 Dalibor Pospíšil 2018-11-13 17:49:55 UTC 
*** Bug 1647307 has been marked as a duplicate of this bug. ***
Comment 11 Klaas Demter 2019-01-07 08:22:28 UTC 
This also seems to happen on every journal reload.

Jan 01 22:57:48 server.domain.tld rsyslogd[64946]: sd_journal_get_cursor() failed: 'Cannot assign requested address'  [v8.24.0-34.el7]
Jan 01 22:57:48 server.domain.tld rsyslogd[64946]: imjournal: journal reloaded... [v8.24.0-34.el7 try http://www.rsyslog.com/e/0 ]
Jan 05 09:34:16 server.domain.tld rsyslogd[64946]: sd_journal_get_cursor() failed: 'Cannot assign requested address'  [v8.24.0-34.el7]
Jan 05 09:34:16 server.domain.tld rsyslogd[64946]: imjournal: journal reloaded... [v8.24.0-34.el7 try http://www.rsyslog.com/e/0 ]

I've opened a support case about this: https://access.redhat.com/support/cases/#/case/02278579

Support engineer suggested workaround from ticket upstream ticket: https://bugzilla.redhat.com/show_bug.cgi?id=1615014#c6
Comment 14 Jan Synacek 2019-03-11 11:47:11 UTC 
907 _public_ int sd_journal_get_cursor(sd_journal *j, char **cursor) {
908         Object *o;
909         int r;
910         char bid[33], sid[33];
911 
912         assert_return(j, -EINVAL);
913         assert_return(!journal_pid_changed(j), -ECHILD);
914         assert_return(cursor, -EINVAL);
915 
916         if (!j->current_file || j->current_file->current_offset <= 0) // <----------------- HERE
917                 return -EADDRNOTAVAIL;
918 
919         r = journal_file_move_to_object(j->current_file, OBJECT_ENTRY, j->current_file->current_offset, &o);
920         if (r < 0)
921                 return r;

I've marked the place where the code exists from the sd-journal library. The j->current_file is set to NULL.

I believe that this is simply a user error while handling the API. rsyslog should react to the time change and reset the cursor properly.
Comment 15 Jan Synacek 2019-03-11 11:48:16 UTC 
Created attachment 1542831 [details]
simple systemtap probe
Comment 16 Jiří Vymazal 2019-03-11 12:44:36 UTC 
(In reply to Jan Synacek from comment #14)
> 907 _public_ int sd_journal_get_cursor(sd_journal *j, char **cursor) {
> 908         Object *o;
> 909         int r;
> 910         char bid[33], sid[33];
> 911 
> 912         assert_return(j, -EINVAL);
> 913         assert_return(!journal_pid_changed(j), -ECHILD);
> 914         assert_return(cursor, -EINVAL);
> 915 
> 916         if (!j->current_file || j->current_file->current_offset <= 0) //
> <----------------- HERE
> 917                 return -EADDRNOTAVAIL;
> 918 
> 919         r = journal_file_move_to_object(j->current_file, OBJECT_ENTRY,
> j->current_file->current_offset, &o);
> 920         if (r < 0)
> 921                 return r;
> 
> I've marked the place where the code exists from the sd-journal library. The
> j->current_file is set to NULL.
> 
> I believe that this is simply a user error while handling the API. rsyslog
> should react to the time change and reset the cursor properly.

Hi, thanks for analysis, however how can I know that j->current_file is NULL in user code? You do not export journal object properties via API (unless there is some usable hack around it?)
Comment 17 Jan Synacek 2019-03-11 15:29:14 UTC 
IMHO, you have to do it the other way around. Isn't there a piece of code that rsyslog already uses to deal with time jumps? If you detect a jump, simply reset the cursor. Or, you can simply do it once when you get -EADDRNOTAVAIL from the journal API. I don't know how rsyslog uses the API, so I can't be any more precise.
Comment 18 Jiří Vymazal 2019-03-11 16:30:32 UTC 
(In reply to Jan Synacek from comment #17)
> IMHO, you have to do it the other way around. Isn't there a piece of code
> that rsyslog already uses to deal with time jumps? If you detect a jump,
> simply reset the cursor. Or, you can simply do it once when you get
> -EADDRNOTAVAIL from the journal API. I don't know how rsyslog uses the API,
> so I can't be any more precise.

Thanks for suggestion, while I could add another switch which will ignore this error resulting in quieting the flooding, I find it strange that you issue errors on otherwise finely working usage of the API; I am definitely not going to risk to change the logic now that it is finally working as it should for all use-cases we need. If it comes to silencing the error, are there any other "ignorable" failures I should be handling on rsyslog side?
Comment 20 Jan Synacek 2019-03-13 13:05:46 UTC 
After debugging this in person, we've managed to find the cause and the correct place to fix this in rsyslog's imjournal. Jiri is currently working on the fix and as soon as one is available, I will test it again and confirm the fix.
Comment 29 Jiří Vymazal 2019-03-22 07:39:00 UTC 
*** Bug 1647307 has been marked as a duplicate of this bug. ***
Comment 35 Chris Williams 2019-05-22 20:02:52 UTC 
*** Bug 1698218 has been marked as a duplicate of this bug. ***
Comment 37 errata-xmlrpc 2019-08-06 12:48:13 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://access.redhat.com/errata/RHSA-2019:2110
Note You need to log in before you can comment on or make changes to this bug.