[systemd-devel] systemd-journald, syslog.socket and service activation

[Thomas HUMMEL]

Hello,

On CentOS Linux release 8.1.1911 (Core) x86_64 running systemd-239 and 
rsyslog-8.37.0 I'm experiencing a sometime strange (to me) activation of 
rsyslog.service when I would expect it to fail for a dependency reason.

Note : I know how to make rsyslog and systemd coexist and I did 
successfully set it up like below. My post is about a test case I 
stumbled upon which I cannot explain and not about how to properly set 
rsyslog/systemd up.

My production setup is like this:

1. make systemd-journald forward to rsyslog :

[Journal]
ForwardToSyslog=yes

2. state an activation dependency of rsyslog.service on syslog.socket 
(/run/systemd/journal/syslog) and have rsyslog.service aliased to 
syslog.service:

[Unit]
Requires=syslog.socket

[Install]
Alias=syslog.service

3. let rsyslog manage its own sockets, leaving the ones passed by systemd:


module
(
     load="imuxsock"
     SysSock.Use="on"
     SysSock.Unlink="on"
)

This setup works well. In particular, I can see, as expected:

- /dev/log beeing symlinked /run/systemd/journal/dev-log
- /run/systemd/journal/syslog socket being pulled in as a dependency and 
used by both journald and rsyslog

Now, when I comment (and remove) the Alias:

[Unit]
Requires=syslog.socket

[Install]
;Alias=syslog.service

and reboot the host. I end up, as expected with:

- rsyslog.service being dead
- /run/systemd/journal/syslog not having been created
- still /dev/log -> /run/systemd/journal/dev-log

debug logs showing:

Jul 02 12:27:15 maestro-log systemd[1]: rsyslog.service: Installed new 
job rsyslog.service/start as 251

Jul 02 12:27:15 maestro-log systemd[1]: rsyslog.service: Job 
rsyslog.service/start finished, result=dependency
Jul 02 12:27:15 maestro-log systemd[1]: Dependency failed for System 
Logging Service.
Jul 02 12:27:15 maestro-log systemd[1]: rsyslog.service: Job 
rsyslog.service/start failed with result 'dependency'.

But when I manually start rsyslog.service (systemctl start 
rsyslog.service),again, as expected, a message about the failed 
dependency is printed:

# systemctl start rsyslog
A dependency job for rsyslog.service failed. See 'journalctl -xe' for 
details.

BUT rsyslog service (and daemon) are actually running:

    Active: active (running) since Thu 2020-07-02 14:45:37 CEST; 2min 
10s ago

[The fact that the process was run can also be confirmed by the override 
of the /dev/log symlink by an actual /dev/log socket managed by rsyslog 
as it could not detect the journald /run/systemd/journal/syslog socket 
(which, as expected is still not created)]

Debug logs (I skipped the d-bus lines) show something like:
Jul 02 12:51:13 maestro-log systemd[1]: rsyslog.service: Trying to 
enqueue job rsyslog.service/start/replace
Jul 02 12:51:13 maestro-log systemd[1]: syslog.socket: Installed new job 
syslog.socket/start as 923
Jul 02 12:51:13 maestro-log systemd[1]: rsyslog.service: Installed new 
job rsyslog.service/start as 922
Jul 02 12:51:13 maestro-log systemd[1]: rsyslog.service: Enqueued job 
rsyslog.service/start as 922


Jul 02 12:51:13 maestro-log systemd[1]: rsyslog.service: Passing 0 fds 
to service
Jul 02 12:51:13 maestro-log systemd[1]: rsyslog.service: About to 
execute: /usr/sbin/rsyslogd -n $SYSLOGD_OPTIONS
Jul 02 12:51:13 maestro-log systemd[1]: rsyslog.service: Forked 
/usr/sbin/rsyslogd as 2267
Jul 02 12:51:13 maestro-log systemd[1]: rsyslog.service: Changed dead -> 
start
Jul 02 12:51:13 maestro-log systemd[1]: Starting System Logging Service...
Jul 02 12:51:13 maestro-log systemd[1]: syslog.socket: Socket service 
syslog.service not loaded, refusing.
Jul 02 12:51:13 maestro-log systemd[1]: syslog.socket: Job 
syslog.socket/start finished, result=failed
Jul 02 12:51:13 maestro-log systemd[1]: Failed to listen on Syslog Socket.

Jul 02 12:51:13 maestro-log systemd[1]: rsyslog.service: Job 
rsyslog.service/start finished, result=dependency
Jul 02 12:51:13 maestro-log systemd[1]: Dependency failed for System 
Logging Service.

Jul 02 12:51:13 maestro-log systemd[1]: rsyslog.service: Job 
rsyslog.service/start failed with result 'dependency'.
Jul 02 12:51:13 maestro-log systemd[2267]: rsyslog.service: Executing: 
/usr/sbin/rsyslogd -n

Jul 02 12:51:13 maestro-log systemd[1]: rsyslog.service: Got 
notification message from PID 2267 (READY=1)
Jul 02 12:51:13 maestro-log systemd[1]: rsyslog.service: Changed start 
-> running

Question 1:
------------
  How is it that despite a Requires= not satisfied the service is run 
(and that this behavior is different at boot time) ?

Question 2:
-----------

Where (is it hard coded) can I get the info telling me that 
syslog.socket unit can socket-activate the syslog.service (hence the 
need of the Alias I guess) ?

Question 3:
------------

I can also issue, right after boot several systemctl start rsyslog 
command. The first few ones will print the 'A dependency job for 
rsyslog.service failed. See 'journalctl -xe' for details.' message, but 
ultimately, the last one will launch rsyslog service without any message :

# systemctl start rsyslog
A dependency job for rsyslog.service failed. See 'journalctl -xe' for 
details.
# systemctl start rsyslog
A dependency job for rsyslog.service failed. See 'journalctl -xe' for 
details.
# systemctl start rsyslog
A dependency job for rsyslog.service failed. See 'journalctl -xe' for 
details.
# systemctl start rsyslog
A dependency job for rsyslog.service failed. See 'journalctl -xe' for 
details.
# systemctl start rsyslog
#

rsyslog service will end up running but still no syslog journald socket 
(which seems normal considering the dependency but weird as I did not 
have any message about it at the last start command)

# ls -l /run/systemd/journal/syslog
ls: cannot access '/run/systemd/journal/syslog': No such file or directory


What am I missing ?

Note: rsyslog service is of Type notify and has a Restart value of no-fail

Thanks for your help

--
Thomas HUMMEL