When upstart launches rsyslog via the syslog.conf job, it declares the job started before rsyslog starts servicing /dev/log. This leads to jobs that depend on "started syslog" (and potentially also "started boot-services") to race against rsyslog initialization and early log messages may get lost as a result.
To reproduce:
1. Add a job /etc/init/logtest.conf with the following definition:
description "syslog test"
author "chromium-os-dev@chromium.org"
start on started syslog
exec echo "this should show in syslog" | tee /run/logtest | logger
2. Reboot
3. Observe that /run/logtest exists, but there is no log message in /var/log/messages
Note that sometimes rsyslog wins the race and the line actually does appear. In my testing on cyan, it doesn't for most reboots.
To keep our sanity, we should probably ensure that "started syslog" lives up to its promise. Note that when rsyslogd is invoked without -n, then the parent rsyslogd process only exits after the backgrounded child process is fully initialized. I don't see how to hook this up with the standard recipes to make upstart detect service readiness though:
1. Adding expect fork to the syslog job definition: This will only result in upstart to wait until the fork. Testing suggests this actually does reliably fix above repro, but looking at the rsyslog source and confirming with strace, rsyslogd forks before bind()ing to /dev/log, so I don't think this is a valid fix.
2. Adding a post-start process to the syslog job definition: This would have to wait on /dev/log to appear or alternatively to poll for a successful connect(/dev/log), or alternatively wait for the initial rsyslogd process to exit (requiring polling again). Neither of these options seem lightweight enough?
3. The upstart docs also mention an "expect stop" mechanism in which the started process sends a SIGSTOP to itself to indicate readiness, which is caught by init which declares the job ready and immediately sends a SIGCONT to let it continue. rsyslogd doesn't support this, but we could add a small patch I guess...
Finally, I observed that rsyslogd does sd_notify(0, "READY=1"), so this wouldn't have been a problem with systemd.
Comment 1 by vapier@chromium.org
, Aug 25 2017