17

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?

  • I haven't used RHEL7 before but I'd check /etc/rsyslog.conf and the /etc/rsyslog.d directories. It sounds like you don't have anything configured to be routed to a particular log file. You might also try specifying a syslog message with EMERG priority to see if that gets through. Example: logger -p EMERG not really an emergency – Bratchley Apr 15 '14 at 19:01
  • 1
    /etc/rsyslog.conf contains this: *.info;mail.none;authpriv.none;cron.none;local0.none /var/log/messages As for files in /etc/rsyslog.d, listen.conf, this: $SystemLogSocketName /run/systemd/journal/syslog and rate-unlimit.conf this: $SystemLogRateLimitInterval 0 $SystemLogRateLimitBurst 0 As for the EMERG priority, it doesn't get logged either. – Arkandel Apr 15 '14 at 19:04
  • You should probably either update your answer or pastebin that since we lost the line breaks there. – Bratchley Apr 15 '14 at 19:15
  • Sorry about that. For some reason it won't parse linefeeds in comments. When I comment this out in rsyslog.conf logging is enabled again: $OmitLocalLogging on . However on my other identical VM on the same host it's not commented out and logging works fine. – Arkandel Apr 15 '14 at 19:25
  • Looking into it, apparently that's an option for systemd (which RHEL7 migrated to, IIRC) Can you check journalctl -b to see if your logs are going to the systemd journal? – Bratchley Apr 15 '14 at 19:28
19

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.

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

  • I brought this up as a bug report and got a response from RedHat. Details can be seen at bugzilla.redhat.com/show_bug.cgi?id=1088021 . This is closed for now, thanks everyone for your help. :) – Arkandel Apr 22 '14 at 13:16
  • 1
    @Arkandel - thanks for closing the loop on this. I've incorporated your findings and the workaround into this A so we can close the Q&A cycle as resolved (at least in the sense that it's a confirmed bug w/ a workaround). Please mark this A as accepted if you agree w/ this synopsis. – slm Apr 23 '14 at 12:01
4

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).
1

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"

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.