rsyslog not logging

Question

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?

Answer 1

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

Answer 2

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/[email protected]~ (4096 bytes).

Answer 3

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"

Answer 4

There's a surprising fragile dependency between journald and rsyslogd, especially in RHEL7. Journald becomes the first, canonical log handler. It should handle logs sent to /dev/log and forward them on to rsyslogd. However, very default installations of rsyslogd will try to read from /dev/log. The RHEL package managers do circumvent that by adding a directive

$SystemLogSocketName /run/systemd/journal/syslog

That is the path to a socket that the rsyslog creates and that systemd-journald.socket will write to. That unit also creates /dev/log and triggers the start of systemd-journald.service.

But if for some reason, that directive is missing or there is a non-fatal error in the rsyslogd configuration somewhere, it will use the default /dev/log and recreate that socket so that it can listen. This has two effects:

• messages sent by processes to /dev/log will not reach journald.
• journald messages will not reach rsyslogd

So, to debug this, you can restart the rsyslog service and check the timestamp on /dev/log. If the times match up, you've got a config error somewhere or it is missing that directive.