Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

CentOS 7 with rsyslog 8.30.0 or 8.31.0 installed results in missing detail in 'systemctl status rsyslog' output #2150

Closed
deoren opened this issue Dec 1, 2017 · 20 comments

Comments

@deoren
Copy link
Contributor

deoren commented Dec 1, 2017

Note: Moved bulk of details over from discussion on rsyslog/rsyslog-doc#397 per recommendation from @rgerhards

Test environment

  • CentOS Linux release 7.4.1708 (Core), with all of the latest patches
  • VMware Workstation 12.5.8
  • Using Adiscon yum repo: http://rpms.adiscon.com/v8-stable/rsyslog.repo
  • first tested rsyslog-8.30.0-4.el7.x86_64
  • then tried rsyslog-8.31.0-3.el7.x86_64

Test configuration

Should this configuration provide output to both /var/log/messages and systemctl status rsyslog?

module(load="imuxsock")
module(load="imklog")   # provides kernel logging support (previously done by rklogd)
module(load="immark")  # provides --MARK-- message capability
module(load="builtin:omfile" Template="RSYSLOG_FileFormat")
global (
    action.reportSuspension="on"
    action.reportSuspensionContinuation="on"
    workDirectory="/var/lib/rsyslog"
    processInternalMessages="off"
)
$WorkDirectory /var/lib/rsyslog
$RepeatedMsgReduction off
$IncludeConfig /etc/rsyslog.d/*.conf
*.info;mail.none;authpriv.none;cron.none                /var/log/messages
authpriv.*                                              /var/log/secure
mail.*                                                  /var/log/maillog
cron.*                                                  /var/log/cron
*.emerg                                                 :omusrmsg:*
uucp,news.crit                                          /var/log/spooler
local7.*                                                /var/log/boot.log

Adiscon yum repo's /etc/rsyslog.conf file

For reference, here is the stock configuration provided by the latest Adiscon package (rsyslog-8.31.0-3.el7.x86_64 as of this writing):

[root@localhost yum.repos.d]# grep -Ev '^$|^\s*#' /etc/rsyslog.conf

module(load="imuxsock") # provides support for local system logging (e.g. via logger command)
module(load="imklog")   # provides kernel logging support (previously done by rklogd)
$ActionFileDefaultTemplate RSYSLOG_TraditionalFileFormat
$IncludeConfig /etc/rsyslog.d/*.conf
*.info;mail.none;authpriv.none;cron.none                /var/log/messages
authpriv.*                                              /var/log/secure
mail.*                                                  /var/log/maillog
cron.*                                                  /var/log/cron
*.emerg                                                 :omusrmsg:*
uucp,news.crit                                          /var/log/spooler
local7.*                                                /var/log/boot.log

/etc/rsyslog.d/listen.conf fragment provided by systemd package

This was discussed on #1367 without resolution.

Contents:

[root@localhost yum.repos.d]# grep -Ev '^$|^\s*#' /etc/rsyslog.d/*.conf

$SystemLogSocketName /run/systemd/journal/syslog

Warning when file is present:

command 'SystemLogSocketName' is currently not permitted - did you already set it via a RainerScript command (v6+ config)? [v8.31.0 try http://www.rsyslog.com/e/2222 ]

Workaround

Configure the imuxsock module load statement like this:

module(
    load="imuxsock"
    sysSock.use="on"
    sysSock.name="/run/systemd/journal/syslog"
)

Now you see the expected output in /var/log/messages and systemctl status rsyslog.

Example output:

[root@localhost redhat]# systemctl status rsyslog

● rsyslog.service - System Logging Service
   Loaded: loaded (/usr/lib/systemd/system/rsyslog.service; enabled; vendor preset: enabled)
   Active: active (running) since Fri 2017-12-01 16:02:43 CST; 27s ago
     Docs: man:rsyslogd(8)
           http://www.rsyslog.com/doc/
 Main PID: 664 (rsyslogd)
   CGroup: /system.slice/rsyslog.service
           └─664 /sbin/rsyslogd -n

Dec 01 16:02:43 localhost.localdomain systemd[1]: Started System Logging Service.
Dec 01 16:02:43 localhost.localdomain systemd[1]: Starting System Logging Service...
Dec 01 16:02:43 localhost.localdomain rsyslogd[664]:  [origin software="rsyslogd" swVersion="8.31.0" x-pid="664" x-info="http://www.rsyslog.com"] start

[root@localhost redhat]# grep chronyd /var/log/messages | head -n 1

2017-12-01T16:02:27.618161-06:00 localhost chronyd[727]: chronyd exiting

I picked chronyd for no particular reason other than it was my test non-rsyslog daemon to help ensure I wasn't getting the wrong impression re the issue.

Full "workaround" conf for reference

global (
    action.reportSuspension="on"
    action.reportSuspensionContinuation="on"
    workDirectory="/var/lib/rsyslog"
    processInternalMessages="off"
)
module(
    load="imuxsock"
    sysSock.use="on"
    sysSock.name="/run/systemd/journal/syslog"
)
module(load="imklog")   # provides kernel logging support (previously done by rklogd)
module(load="immark")  # provides --MARK-- message capability
module(load="builtin:omfile" Template="RSYSLOG_FileFormat")
$WorkDirectory /var/lib/rsyslog
$RepeatedMsgReduction off
$IncludeConfig /etc/rsyslog.d/*.conf
*.info;mail.none;authpriv.none;cron.none                /var/log/messages
authpriv.*                                              /var/log/secure
mail.*                                                  /var/log/maillog
cron.*                                                  /var/log/cron
*.emerg                                                 :omusrmsg:*
uucp,news.crit                                          /var/log/spooler
local7.*                                                /var/log/boot.log
@deoren
Copy link
Contributor Author

deoren commented Dec 1, 2017

Is the following the expected behavior?

  1. Load the imuxsock module without any special options (e.g., module(load="imuxsock"))
  2. imuxsock module works out where the applicable input socket is located on its own, uses that to read in messages passed from systemd (happens to be /run/systemd/journal/syslog)
  3. Route emitted messages from rsyslog back to systemd when using processInternalMessages="off" (apparently the default with v8.21.0 and newer)

@rgerhards
Copy link
Member

rgerhards commented Dec 2, 2017

processInternalMessages is not directly related to imuxsock -- it just tells that rsyslog should use the default logging provider (syslog() API if not otherwise configured) for emitting error messages. It then depends on who actually listens for syslog messages and how the syslog() API is configured. Usually, it should go to /dev/log, and on journal systems usually the journal listens to it, and, if so, systemctl status will show the message -- but it really depends on how all this is configured in the operating system (yes, systemd journal has very much complicated the once simple thing ;-)).

imuxsock simply follows what you configured, with the exception on systemd systems with socket activation. Then, systemd passes in the log socket that it considers rsyslog should read. There currently is no informational message logged by rsyslog in that case -- we should probably add this. There is no other logic in imuxsock - its very simple.

My understanding (not necessarily correct) is that with systemd journal, the journal listens to /dev/log and systemd passes imuxsock the /run/systemd/journal/syslog socket. But given your initial posting, this doesn't seem to be the case. Instead, the journal package seems to use some legacy construct which does not work correctly with new-style definitions (by design). Smells much like a bug in the journal package to me.

rgerhards added a commit to rgerhards/rsyslog that referenced this issue Dec 2, 2017
... of course only if this capability is used on systemd systems.

see also rsyslog#2150
@rgerhards
Copy link
Member

Of course, a work-around is to use the old styl $ModLoad imuxsock inside the config. But that's really a bad fix.

@deoren
Copy link
Contributor Author

deoren commented Dec 4, 2017

@rgerhards: Of course, a work-around is to use the old styl $ModLoad imuxsock inside the config.

If it's not too much of a pain to explain, what is the difference between the two statements, other than how they visually look when configuring them:

  • module(load="imuxsock")
  • $ModLoad imuxsock

Is it just the difference between how the config is processed?

@deoren
Copy link
Contributor Author

deoren commented Dec 4, 2017

@rgerhards If there is a nightly for the yum repo I will give that a try and see what is logged re what socket systemd passes to rsyslog.

@rgerhards
Copy link
Member

If it's not too much of a pain to explain, what is the difference between the two statements, other than how they visually look when configuring them:

module(load="imuxsock")
$ModLoad imuxsock
Is it just the difference between how the config is processed?

A core problem with legacy conf is that config snippets could override each other settings. The new style fixes that. In the concrete example: if you use $ModLoad you can use $systemlogsocketname multiple times and one of them would win (not even necessarily that last or the first one, it's undefined).

Thus, in new-style, all module parameters need to be set with the module statement. So you know what you selected. So in new style, you use

module(load="imuxsock" syssock.name="/path/to/it")

and you cannot cannot change it later on. You now know exactly what happens. For the same reason, we do NOT permit the use of old-style constructs to override this at a later point in time -- that would re-introduce the same mess that we originally wanted to solve. Permitting this would actually cause even more confusion.

Having said that, it looks like going back to old-style for imuxsock load seems the only solution currently for the way the RH journal packages works. I admit that it is somewhat unfortunate the imuxsock does not require an explicit input definition for the system socket, but this is how it always worked. The journal package, though, could drop a dedicated listen socket instead of the legacy directive and all would be well.

@rgerhards
Copy link
Member

@rgerhards If there is a nightly for the yum repo I will give that a try and see what is logged re what socket systemd passes to rsyslog.

Unfortunately not. But I am now (as a side-activity) working on new packages via the SUSE open build service. I hope we can get daily packages via that in the not too distant future (whatever that means...).

@deoren
Copy link
Contributor Author

deoren commented Dec 4, 2017

@deoren: @rgerhards If there is a nightly for the yum repo I will give that a try and see what is logged re what socket systemd passes to rsyslog.

I took a stab at building from source and initially ran into the same problem where a dependency wasn't available and rsyslog wouldn't start.

I ran systemctl disable rsyslog and then systemctl enable rsyslog and that resolved the immediate problem.

I then started up rsyslog to see what the new log message looks like:

[root@localhost redhat]# systemctl status rsyslog

● rsyslog.service - System Logging Service
   Loaded: loaded (/usr/lib/systemd/system/rsyslog.service; enabled; vendor preset: enabled)
   Active: active (running) since Mon 2017-12-04 13:39:40 CST; 4s ago
     Docs: man:rsyslogd(8)
           http://www.rsyslog.com/doc/
 Main PID: 46489 (rsyslogd)
   CGroup: /system.slice/rsyslog.service
           └─46489 /usr/sbin/rsyslogd -n

Dec 04 13:39:40 localhost.localdomain systemd[1]: Starting System Logging Service...
Dec 04 13:39:40 localhost.localdomain rsyslogd[46489]: imuxsock: Acquired UNIX socket '/run/systemd/journal/syslog' (fd 3) from systemd.  [v8.32.0.master]
Dec 04 13:39:40 localhost.localdomain rsyslogd[46489]:  [origin software="rsyslogd" swVersion="8.32.0.master" x-pid="46489" x-info="http://www.rsyslog.com"] start
Dec 04 13:39:40 localhost.localdomain systemd[1]: Started System Logging Service.

I manually commented out the entry in /etc/rsyslog.d/listen.conf:

#$SystemLogSocketName /run/systemd/journal/syslog

and have /etc/rsyslog.conf currently setup like so:

module(load="imuxsock")
module(load="imklog")
module(load="immark")
$WorkDirectory /var/lib/rsyslog
$ActionFileDefaultTemplate RSYSLOG_TraditionalFileFormat
$IncludeConfig /etc/rsyslog.d/*.conf
*.info;mail.none;authpriv.none;cron.none                /var/log/messages
authpriv.*                                              /var/log/secure
mail.*                                                  -/var/log/maillog
cron.*                                                  /var/log/cron
*.emerg                                                 :omusrmsg:*
uucp,news.crit                                          /var/log/spooler
local7.*                                                /var/log/boot.log

@deoren
Copy link
Contributor Author

deoren commented Dec 4, 2017

@rgerhards: The journal package, though, could drop a dedicated listen socket instead of the legacy directive and all would be well.

I want to say that I tested that and still didn't have the expected output in systemctl status rsyslog, but I will need to go back and recheck to be sure. I think I tried so many scenarios that they've blended together in my mind.

@deoren
Copy link
Contributor Author

deoren commented Dec 4, 2017

/usr/lib/systemd/system/rsyslog.service: rsyslog-8.31.0-3.el7 Adiscon package

[Unit]
Description=System Logging Service
Requires=syslog.socket
Documentation=man:rsyslogd(8)
Documentation=http://www.rsyslog.com/doc/

[Service]
#Type=notify
EnvironmentFile=-/etc/sysconfig/rsyslog
ExecStart=/sbin/rsyslogd -n $SYSLOGD_OPTIONS
Restart=on-failure
UMask=0066
StandardOutput=null
Restart=on-failure

[Install]
WantedBy=multi-user.target
Alias=syslog.service

/usr/lib/systemd/system/rsyslog.service : source (bb93de7)

[Unit]
Description=System Logging Service
Requires=syslog.socket
Documentation=man:rsyslogd(8)
Documentation=http://www.rsyslog.com/doc/

[Service]
Type=notify
ExecStart=/usr/sbin/rsyslogd -n
StandardOutput=null
Restart=on-failure

[Install]
WantedBy=multi-user.target
Alias=syslog.service

systemd documentation

From the Writing syslog Daemons Which Cooperate Nicely With systemd doc:

[Unit]
Description=System Logging Service
Requires=syslog.socket

[Service]
ExecStart=/usr/sbin/syslog-ng -n
StandardOutput=null

[Install]
Alias=syslog.service
WantedBy=multi-user.target

Granted it's for syslog-ng and not rsyslog, but it does mostly match what the latest yum repo packages and source are using. Posting this here as a reference (for myself if nothing else).

@deoren
Copy link
Contributor Author

deoren commented Dec 4, 2017

@rgerhards In short, it seems that building from source is giving the expected results:

  1. service rsyslog stop
  2. Build from source
  3. Use stock /etc/rsyslog.conf from Adiscon repo
  4. Disable entry in /etc/rsyslog.d/listen.conf (or just let rsyslog complain)
  5. Run systemctl disable rsyslog to toggle off the existing symlink
  6. Run systemctl enable rsyslog to create the required symbolic links: /etc/systemd/system/syslog.service and /etc/systemd/system/multi-user.target.wants/rsyslog.service, both pointing to /usr/lib/systemd/system/rsyslog.service.
  7. Run systemctl start rsyslog
  8. Run systemctl status rsyslog, visually confirm that the results are as expected
  9. Visually confirm that the entries in /var/log/messages are as expected

@deoren
Copy link
Contributor Author

deoren commented Dec 5, 2017

rsyslog v8.31.0 from Adiscon repo

load imuxsock, sysSock.Use="off"

Starting with the stock /etc/rsyslog.conf from Adiscon repo file, I got the expected results with configuring imuxsock like so:

module(load="imuxsock" sysSock.Use="off")

[root@localhost redhat]# fuser -v /dev/log /run/systemd/journal/syslog

                     USER        PID ACCESS COMMAND
/dev/log:            root          1 F.... systemd
                     root        474 F.... systemd-journal
/run/systemd/journal/syslog:
                     root          1 F.... systemd
                     root        668 F.... rsyslogd

load imuxsock, no parameters

Without specifying the sysSock.Use="off parameter, rsyslog appears to have bound to both /dev/log/ and /run/systemd/journal/syslog:

[root@localhost redhat]# fuser -v /dev/log /run/systemd/journal/syslog

                     USER        PID ACCESS COMMAND
/dev/log:            root          1 F.... systemd
                     root        474 F.... systemd-journal
                     root       2500 F.... rsyslogd
/run/systemd/journal/syslog:
                     root          1 F.... systemd
                     root       2500 F.... rsyslogd

rsyslog from source (bb93de7)

As noted earlier, building from source did not require any changes to the stock /etc/rsyslog.conf from Adiscon repo file.

There was the complaint re the legacy /etc/rsyslog.d/listen.conf parameter, but rsyslog appeared to function normally.

[root@localhost rsyslog]# systemctl status rsyslog -l

● rsyslog.service - System Logging Service
   Loaded: loaded (/usr/lib/systemd/system/rsyslog.service; enabled; vendor preset: enabled)
   Active: active (running) since Mon 2017-12-04 18:51:48 CST; 4min 57s ago
     Docs: man:rsyslogd(8)
           http://www.rsyslog.com/doc/
 Main PID: 694 (rsyslogd)
   CGroup: /system.slice/rsyslog.service
           └─694 /usr/sbin/rsyslogd -n

Dec 04 18:51:47 localhost.localdomain systemd[1]: Starting System Logging Service...
Dec 04 18:51:47 localhost.localdomain rsyslogd[694]: command 'SystemLogSocketName' is currently not permitted - did you already set it via a RainerScript command (v6+ config)? [v8.32.0.master try http://www.rsyslog.com/e/2222 ]
Dec 04 18:51:47 localhost.localdomain rsyslogd[694]: imuxsock: Acquired UNIX socket '/run/systemd/journal/syslog' (fd 3) from systemd.  [v8.32.0.master]
Dec 04 18:51:47 localhost.localdomain rsyslogd[694]:  [origin software="rsyslogd" swVersion="8.32.0.master" x-pid="694" x-info="http://www.rsyslog.com"] start
Dec 04 18:51:48 localhost.localdomain systemd[1]: Started System Logging Service.

[root@localhost rsyslog]# tail /var/log/messages -n 2

Dec  4 18:57:43 localhost systemd[1]: Started NTP client/server.
Dec  4 18:57:48 localhost chronyd[2441]: Selected source 162.221.74.15

[root@localhost rsyslog]# fuser -v /dev/log /run/systemd/journal/syslog

                     USER        PID ACCESS COMMAND
/dev/log:            root          1 F.... systemd
                     root        475 F.... systemd-journal
/run/systemd/journal/syslog:
                     root          1 F.... systemd
                     root        694 F.... rsyslogd

This looks normal?

@deoren
Copy link
Contributor Author

deoren commented Dec 7, 2017

@rgerhards @friedl After installing the rsyslog-8.31.0-5 package (with the stock config) AND after applying a workaround (see below), rsyslogd no longer binds directly to /dev/log on my test CentOS 7 system:

[root@centos7-test redhat]# fuser -v /dev/log /run/systemd/journal/syslog

                     USER        PID ACCESS COMMAND
/dev/log:            root          1 F.... systemd
                     root        474 F.... systemd-journal
/run/systemd/journal/syslog:
                     root          1 F.... systemd
                     root        667 F.... rsyslogd

[root@centos7-test redhat]# grep -Ev '^\s*#|^$' /etc/rsyslog.conf /etc/rsyslog.d/*.conf

/etc/rsyslog.conf:module(load="imuxsock") # provides support for local system logging (e.g. via logger command)
/etc/rsyslog.conf:module(load="imklog")   # provides kernel logging support (previously done by rklogd)
/etc/rsyslog.conf:$ActionFileDefaultTemplate RSYSLOG_TraditionalFileFormat
/etc/rsyslog.conf:$IncludeConfig /etc/rsyslog.d/*.conf
/etc/rsyslog.conf:*.info;mail.none;authpriv.none;cron.none                /var/log/messages
/etc/rsyslog.conf:authpriv.*                                              /var/log/secure
/etc/rsyslog.conf:mail.*                                                  /var/log/maillog
/etc/rsyslog.conf:cron.*                                                  /var/log/cron
/etc/rsyslog.conf:*.emerg                                                 :omusrmsg:*
/etc/rsyslog.conf:uucp,news.crit                                          /var/log/spooler
/etc/rsyslog.conf:local7.*                                                /var/log/boot.log
/etc/rsyslog.d/listen.conf:$SystemLogSocketName /run/systemd/journal/syslog

Workarounds (either works):

  • systemctl disable rsyslog; systemctl enable rsyslog; reboot
  • systemctl --no-reload preset rsyslog; reboot

@rgerhards
Copy link
Member

rsyslogd no longer binds directly to /dev/log on my test CentOS 7

I am really getting confused: wasn't the journal destined to listen for that? (I admit I just briefly gazed over the message -- if the is the source of my confusion, just tell me ;-)).

@deoren
Copy link
Contributor Author

deoren commented Dec 7, 2017

@rgerhards I am really getting confused: wasn't the journal destined to listen for that?

I should clarify: rsyslog no longer attempts to bind to /dev/log when using the default configuration provided by the rsyslog rpm from the Adiscon yum repo, even with an untouched stock /etc/rsyslog.d/listen.conf file in place. This is with rsyslog-8.31.0-5 installed.

(I admit I just briefly gazed over the message -- if the is the source of my confusion, just tell me ;-)).

The issue we discussed on rsyslog/rsyslog-doc#397, specifically rsyslog/rsyslog-doc#397 (comment), was that rsyslog appeared to be binding to /dev/log, with or without SysSock.Use explicitly defined on a CentOS 7 system.

From what I understand of our recent conversations, the expected behavior for a systemd system is that if imuxsock's SysSock.Use and SysSock.Name parameters are left at their default values (by using a standard module load statement: module(load="imuxsock")), then /dev/log should be ignored and rsyslog will instead use the value passed to it by systemd (e.g., /run/systemd/journal/syslog). If systemd is not in-use, then rsyslog (with default imuxsock parameter values) will manage /dev/log directly.

Based on my report (on rsyslog/rsyslog-doc#397 and again on this ticket), it sounded like the behavior I was encountering was a bug.

If I build from source (as noted earlier on this ticket), or use the newly provided rsyslog-8.31.0-5 package then I see the missing systemctl status rsyslog output and rsyslog doesn't attempt to bind to /dev/log.

To the point:

@wdauchy
Copy link
Contributor

wdauchy commented Dec 22, 2017

@deoren I cannot find any rsyslog-8.31.0-5 package on adiscon; could you help me out?

@deoren
Copy link
Contributor Author

deoren commented Dec 22, 2017

@wdauchy: @deoren I cannot find any rsyslog-8.31.0-5 package on adiscon; could you help me out?

See #2167 (comment)

In short, it's a "testing" version that @friedl released for additional feedback. #2134 is still open to track the need for a workaround (see #2150 (comment)) after a fresh installation of rsyslog when using the http://rpms.adiscon.com/v8-stable/rsyslog.repo config.

@friedl
Copy link
Contributor

friedl commented Dec 22, 2017

@wdauchy The 8.31.0-5 is only the package version in the testing repository. For the same changes from stable, use 8.31.0-4.

@deoren
Copy link
Contributor Author

deoren commented Jan 10, 2018

I think this issue has been mostly supplanted by the package changes noted on #2134. I'll go ahead and close out this ticket that I originally opened.

@deoren deoren closed this as completed Jan 10, 2018
@lock
Copy link

lock bot commented Dec 26, 2019

This thread has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.

@lock lock bot locked as resolved and limited conversation to collaborators Dec 26, 2019
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
None yet
Projects
None yet
Development

No branches or pull requests

4 participants