Ytdyklly

This is an odd issue.

I was testing the chrony/ntp services on a RHEL7 VM and was resetting its time as well as the host's. Once I was satisfied with it I checked /var/log/messages and realized it hadn't been changed in a while.

Now no matter what I do nothing is being logged except for when I restart the rsyslog service itself; when I do I get this:

Apr 15 13:59:43 mymachine1 rsyslogd: [origin software="rsyslogd" swVersion="7.4.2" x-pid="2847" x-info="http://www.rsyslog.com"] exiting on signal 2.



Apr 15 13:59:59 mymachine1 rsyslogd: [origin software="rsyslogd" swVersion="7.4.2" x-pid="2853" x-info="http://www.rsyslog.com"] start



Apr 15 14:00:11 mymachine1 rsyslogd-3000: sd_journal_get_cursor() failed: 'Cannot assign requested address'

Trying things like logger test don't log, nothing else except rsyslog's own messages seems to. When I run rsyslog manually with -n -N1 as arguments I get:

rsyslogd: version 7.4.2, config validation run (level 1), master config /etc/rsyslog.conf



rsyslogd: End of config validation run. Bye

It just seems like nothing can log through rsyslog for some reason. And a second identical VM on the same host (which didn't go through quite the same circle of repeatedly disabling ntp, having the date changed and rebooted multiple times) with the same rsyslog.conf file logs just fine.

At this point the date/time is correct, chrony is enabled and running, and I've rebooted several times - after 30 seconds of kernel messages nothing else gets logged again.

Thoughts?

Not a direct solution but I would enable some debugging to see what's happening behind the scenes.

Idea #1 - Debugging logger

For starters when you run your logger commands you can do them like so, echoing out messages to STDERR.

$ logger -s "hi"

saml: hi

Idea #2 - validate your configuration file

You can also try validating your rsyslog configuration file:

$ sudo rsyslogd -N6 | head -10

rsyslogd: version 7.2.6, config validation run (level 6), master config /etc/rsyslog.conf

rsyslogd: End of config validation run. Bye.



6921.173842409:7f8b11df2780: rsyslogd 7.2.6 startup, module path '', cwd:/root

6921.175241008:7f8b11df2780: caller requested object 'net', not found (iRet -3003)

6921.175261977:7f8b11df2780: Requested to load module 'lmnet'

6921.175272711:7f8b11df2780: loading module '/lib64/rsyslog/lmnet.so'

6921.175505384:7f8b11df2780: module lmnet of type 2 being loaded (keepType=0).

6921.175520208:7f8b11df2780: entry point 'isCompatibleWithFeature' not present in module

6921.175528413:7f8b11df2780: entry point 'setModCnf' not present in module

6921.175535294:7f8b11df2780: entry point 'getModCnfName' not present in module

6921.175541502:7f8b11df2780: entry point 'beginCnfLoad' not present in module

Idea #3 - Turn up rsyslogd debugging

Also I'd try enabling debugging of the rsyslogd daemon for further insight.

$ sudo -i

$ export RSYSLOG_DEBUGLOG="/tmp/debuglog"

$ export RSYSLOG_DEBUG="Debug"



$ service rsyslog stop

$ rsyslogd -d | head -10    

7160.005597645:7fae096a3780: rsyslogd 7.2.6 startup, module path '', cwd:/root

7160.005872662:7fae096a3780: caller requested object 'net', not found (iRet -3003)

7160.005895004:7fae096a3780: Requested to load module 'lmnet'

7160.005906331:7fae096a3780: loading module '/lib64/rsyslog/lmnet.so'

7160.006023505:7fae096a3780: module lmnet of type 2 being loaded (keepType=0).

7160.006030872:7fae096a3780: entry point 'isCompatibleWithFeature' not present in module

7160.006033780:7fae096a3780: entry point 'setModCnf' not present in module

7160.006036209:7fae096a3780: entry point 'getModCnfName' not present in module

7160.006038359:7fae096a3780: entry point 'beginCnfLoad' not present in module

...

...

7160.006063913:7fae096a3780: rsyslog runtime initialized, version 7.2.6, current users 1

7160.006102179:7fae096a3780: source file syslogd.c requested reference for module 'lmnet', reference count now 2

7160.006113657:7fae096a3780: GenerateLocalHostName uses 'greeneggs'

Confirming version info

$ rsyslogd -version

rsyslogd 7.2.6, compiled with:

    FEATURE_REGEXP:             Yes

    FEATURE_LARGEFILE:          No

    GSSAPI Kerberos 5 support:      Yes

    FEATURE_DEBUG (debug build, slow code): No

    32bit Atomic operations supported:  Yes

    64bit Atomic operations supported:  Yes

    Runtime Instrumentation (slow code):    No

    uuid support:               Yes



See http://www.rsyslog.com for more information.

Confirmed bug and a workaround

The OP submitted this as a bug to Red Hat.

• 
  Bug 1088021 - Changing a VM host's time disables rsyslog file logging.

The bug was characterized as follows:

Sure enough when I set the host's own time the VM had the same wrong time as the host. That's when I noticed /var/log/messages was no longer being updated.

It turns out nothing other than restarting the rsyslog service itself logs to files at that point. If I do so this gets logged:

  ---

   Apr 15 16:39:39 rhel7time-dev rsyslogd-3000: sd_journal_get_cursor() failed: 'Cannot assign requested address'



  Apr 15 16:39:39 rhel7time-dev rsyslogd: [origin software="rsyslogd" swVersion="7.4.2" x-pid="574" x-info="http://www.rsyslog.com"] exiting on signal 15.

  Apr 15 16:39:39 rhel7time-dev rsyslogd: [origin software="rsyslogd" swVersion="7.4.2" x-pid="2117" x-info="http://www.rsyslog.com"] start

  ---

Otherwise nothing is logged to file, including logger.

If I comment out $OmitLocalLogging on in rsyslog.conf then file logging resumes (notice that until that point I hadn't changed rsyslog.conf).

Logging through journal is unaffected by all this. journalctl -b shows logging, including anything sent by logger.

To which the one of the developers responded:

When this issue occurs, you can delete /var/lib/rsyslog/imjournal.state and restart the daemon as a workaround.

rsyslog doesn't handle the date directly but only through the systemd API.
I've checked the code in imjournal a while ago and this looks like an issue in systemd.

For reference, see: https://github.com/rsyslog/rsyslog/issues/43

In my case systemctl restart systemd-journald helped, because

File /run/log/journal/29c32d60f93c42489aabb4ebeb593f5b/system.journal corrupted or uncleanly shut down, renaming and replacing.

[12274404.541271] systemd-journald[15492]: Deleted empty journal /run/log/journal/29c32d60f93c42489aabb4ebeb593f5b/system@0005317804680d96-e103c48634d16856.journal~ (4096 bytes).

Try to check rsyslog conf with: rsyslogd -f /etc/rsyslog.conf -N 1

If everything is ok try to restart systemd-journald.socket with:
systemctl restart systemd-journald.socket

you can use the command "logger" to check if rsyslog work or not: logger "hello"