Description of problem: On Fedora 15 with systemd, rsyslogd stops very early in the shutdown process -- before (most) services that depend on syslog.target are stopped. Consequently, messages that services normally log during shutdown are lost. Version-Release number of selected component (if applicable): 5.8.5-1 How reproducible: Always Steps to Reproduce: 1. Reboot 2. Examine /var/log/messages Actual results: No "exiting" messages from services like ntpd, auditd, smartd. Expected results: "exiting" messages from services should been seen in the log, as on all previous Fedora releases. Additional info: The problem seems to be that rsyslog.service doesn't declare that it "provides" syslog.target, so systemd isn't aware that syslog.target-dependent services need to be stopped before rsyslogd.
I'm reassigning to systemd to get their input. I'm not sure how this needs to get expressed. I tried "ln -s ../rsyslog.service /lib/systemd/system/syslog.target.wants", but that doesn't appear to help, though it seems like it should.
If by "provide" you mean that the initscript has an LSB header with: # Provides: $foo That translates into systemd as: [Unit] Wants=syslog.target Before=syslog.target ( and ofcourse syslog.target needs to be removed from the After= line if it exists ) You can try to see if this solves your problem by copying the rsyslog unit to /etc/systemd/system directory and add the mentioned change and reload the daemon and restart the service
I made that change and I see this on shutdown (with debugging): Jan 25 09:56:10 vmf16 systemd[1]: Trying to enqueue job reboot.target/start/replace Jan 25 09:56:10 vmf16 systemd[1]: Installed new job reboot.target/start as 234 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job reboot.service/start as 235 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job shutdown.target/start as 236 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job alsa-store.service/start as 237 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job systemd-random-seed-save.service/start as 240 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job systemd-update-utmp-shutdown.service/start as 242 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job yum-cron.service/stop as 243 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job systemd-readahead-collect.service/stop as 245 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job systemd-readahead-done.timer/stop as 246 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job graphical.target/stop as 248 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job prefdm.service/stop as 249 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job systemd-vconsole-setup.service/stop as 252 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job systemd-ask-password-plymouth.path/stop as 253 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job getty.target/stop as 255 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job systemd-user-sessions.service/stop as 257 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job remote-fs.target/stop as 258 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job rc-local.service/stop as 259 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job network.target/stop as 260 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job nfs-idmap.service/stop as 261 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job nfs-lock.service/stop as 262 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job system-setup-keyboard.service/stop as 263 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job multi-user.target/stop as 266 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job systemd-ask-password-wall.path/stop as 267 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job systemd-logind.service/stop as 269 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job dbus.socket/stop as 270 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job dbus.service/stop as 271 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job avahi-daemon.service/stop as 272 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job NetworkManager.service/stop as 273 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job sockets.target/stop as 274 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job basic.target/stop as 275 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job crond.service/stop as 278 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job abrt-ccpp.service/stop as 279 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job nfs-server.service/stop as 281 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job mcelog.service/stop as 282 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job atd.service/stop as 283 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job rsyslog.service/stop as 284 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job sshd.service/stop as 285 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job sssd.service/stop as 286 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job ntpd.service/stop as 287 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job sshd-keygen.service/stop as 288 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job ntpdate.service/stop as 290 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job nfs-secure.service/stop as 291 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job rpcbind.service/stop as 292 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job abrtd.service/stop as 293 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job abrt-oops.service/stop as 294 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job abrt-vmcore.service/stop as 295 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job acpid.service/stop as 297 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job xinetd.service/stop as 298 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job auditd.service/stop as 299 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job netfs.service/stop as 303 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job sandbox.service/stop as 306 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job puppet.service/stop as 307 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job autofs.service/stop as 308 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job cups.socket/stop as 311 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job avahi-daemon.socket/stop as 312 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job fedora-storage-init-late.service/stop as 313 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job fedora-wait-storage.service/stop as 314 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job cryptsetup.target/stop as 315 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job fedora-storage-init.service/stop as 316 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job rpcbind.socket/stop as 317 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job pcscd.socket/stop as 318 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job cups.path/stop as 319 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job time-sync.target/stop as 320 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job sysinit.target/stop as 321 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job systemd-tmpfiles-clean.timer/stop as 322 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job systemd-sysctl.service/stop as 324 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job mdmonitor-takeover.service/stop as 328 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job lvm2-monitor.service/stop as 329 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job swap.target/stop as 330 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job local-fs.target/stop as 333 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job fedora-readonly.service/stop as 336 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job remount-rootfs.service/stop as 337 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job local-fs-pre.target/stop as 338 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job systemd-remount-api-vfs.service/stop as 339 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job fedora-loadmodules.service/stop as 341 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job umount.target/start as 344 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job media.mount/stop as 346 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job tmp.mount/stop as 349 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job dev-disk-by\x2duuid-f24568f2\x2d1194\x2d4b8b\x2da106\x2dd82e9415daa0.swap/stop as 350 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job dev-disk-by\x2dpath-pci\x2d0000:00:04.0\x2dvirtio\x2dpci\x2dvirtio1\x2dpart3.swap/stop as 351 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job dev-disk-by\x2dpartuuid-171feba6\x2de228\x2d4599\x2da192\x2d57665cb3d843.swap/stop as 353 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job home-orion.mount/stop as 354 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job nfs-local.mount/stop as 355 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job final.target/start as 356 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job halt-local.service/start as 357 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job console-kit-log-system-restart.service/start as 358 Jan 25 09:56:10 vmf16 systemd[1]: Installed new job plymouth-reboot.service/start as 359 Jan 25 09:56:10 vmf16 systemd[1]: About to execute: /bin/umount /nfs/local Jan 25 09:56:10 vmf16 systemd[1]: Forked /bin/umount as 1736 Jan 25 09:56:10 vmf16 systemd[1]: nfs-local.mount changed mounted -> unmounting Jan 25 09:56:10 vmf16 systemd[1]: About to execute: /bin/umount /home/orion Jan 25 09:56:10 vmf16 systemd[1]: Forked /bin/umount as 1738 Jan 25 09:56:10 vmf16 systemd[1]: home-orion.mount changed mounted -> unmounting Jan 25 09:56:10 vmf16 systemd[1]: Redirecting stop request from dev-disk-by\x2dpartuuid-171feba6\x2de228\x2d4599\x2da192\x2d57665cb3d843.swap to dev-vda3.swap. Jan 25 09:56:10 vmf16 systemd[1]: Job dev-disk-by\x2dpartuuid-171feba6\x2de228\x2d4599\x2da192\x2d57665cb3d843.swap/stop finished, result=done Jan 25 09:56:10 vmf16 systemd[1]: Redirecting stop request from dev-disk-by\x2dpath-pci\x2d0000:00:04.0\x2dvirtio\x2dpci\x2dvirtio1\x2dpart3.swap to dev-vda3.swap. Jan 25 09:56:10 vmf16 systemd[1]: Job dev-disk-by\x2dpath-pci\x2d0000:00:04.0\x2dvirtio\x2dpci\x2dvirtio1\x2dpart3.swap/stop finished, result=done Jan 25 09:56:10 vmf16 systemd[1]: fedora-readonly.service changed exited -> dead Jan 25 09:56:10 vmf16 systemd[1]: Job fedora-readonly.service/stop finished, result=done Jan 25 09:56:10 vmf16 kernel: Kernel logging (proc) stopped. Jan 25 09:56:10 vmf16 rsyslogd: [origin software="rsyslogd" swVersion="5.8.7" x-pid="1643" x-info="http://www.rsyslog.com"] exiting on signal 15. I'm not sure what all is determining the order relative to rsyslog.service at 284, and do these number reflect ordering at all? I also don't know if these tasks are done in a serial fashion or not - I assume not since I thought that was one of the goals of systemd. sssd and sshd appear to be set to stop after rsyslog even though they both have "After=syslog.target". There are still very few messages in the log from exiting services before rsyslogd stops.
As you can see Jan 25 09:56:10 vmf16 kernel: Kernel logging (proc) stopped and rsyslogd fails or stops after that ( understandably so). It does not get much later stopped on shut downs hence are you sure you don't you just have to bump up the verbosity/log level of those daemons For example if you shutdown the services in question do they leave any message in logs?
sshd doesn't, ntpd does: Jan 26 10:24:40 vmf16 ntpd[1210]: ntpd exiting on signal 15 # grep syslog ntpd.service After=syslog.target ntpdate.service So it seems from that that we should see the ntpd exiting message, but we don't. Or at least sometimes we do and sometimes we don't. I don't know how much we want to slow things down to make sure that things are done in order, but I'm still not convinced the requested ordering is happening at all. # grep -F exiting /var/log/messages-20120125 Dec 30 15:27:56 vmf16 ntpd[938]: ntpd exiting on signal 15 Dec 30 15:27:56 vmf16 avahi-daemon[657]: Disconnected from D-Bus, exiting. Dec 30 15:27:57 vmf16 rsyslogd: [origin software="rsyslogd" swVersion="5.8.5" x-pid="671" x-info="http://www.rsyslog.com"] exiting on signal 15. Jan 13 12:00:26 vmf16 acpid: exiting Jan 13 12:02:57 vmf16 rsyslogd: [origin software="rsyslogd" swVersion="5.8.5" x-pid="671" x-info="http://www.rsyslog.com"] exiting on signal 15. Jan 25 09:04:30 vmf16 rpc.statd[741]: Caught signal 15, un-registering and exiting Jan 25 09:04:31 vmf16 rpc.mountd[772]: Caught signal 15, un-registering and exiting. Jan 25 09:04:33 vmf16 rsyslogd: [origin software="rsyslogd" swVersion="5.8.5" x-pid="664" x-info="http://www.rsyslog.com"] exiting on signal 15.
As correctly recognized by Jordan Russell, syslog.target is ordered merely after syslog.socket, not after rsyslog.service. That's a good thing for bootup where we want to take advantage of socket activation, start everything in parallel and let the kernel synchronize the processes automatically via the sockets. However, the lack of an explicit order of services results in their parallel stopping during shutdown. rsyslog is one service where this can be worrisome. We should look for a solution that would ensure the expected ordering at shutdown, but not add any new ordering constraints on bootup. It seems there is a need for breaking the perfect anti-symmetry of ordering dependencies on startup and shutdown. Ideally the system would infer the shutdown ordering automatically. I haven't given it much thought yet to tell if it's possible.
Should not then it be sufficient to add to the rsyslog service... [Unit] Wants=syslog.target syslog.socket Before=syslog.target syslog.socket To ensure the correct ordering?
No, a service cannot start before its socket.
(In reply to comment #6) > We should look for a solution that would ensure the expected ordering at > shutdown, but not add any new ordering constraints on bootup. It seems there is > a need for breaking the perfect anti-symmetry of ordering dependencies on > startup and shutdown. > Ideally the system would infer the shutdown ordering automatically. I haven't > given it much thought yet to tell if it's possible. Here's a hand-wavy proposal: Obviously today systemd cannot infer the shutdown ordering between A.service and a socket-activated B.service completely automatically, because with the implicit startup ordering it has no knowledge of the fact that A.service is a client of B.service. Suppose that we give systemd a hint though: A.service will explicitly declare "After=B.socket". This ordering will not influence the actual startup ordering in any way, because it was already implied indirectly via basic.target and sockets.target. But later we'll teach systemd to interpret the explicit dependency as a hint for shutdown ordering... Today, when asked to stop A.service, B.service, B.socket in a single transaction, systemd would uphold two ordering dependencies: A.service/stop before B.socket/stop B.service/stop before B.socket/stop (A.service/stop and B.service/stop are allowed to run in parallel) So we'll teach systemd to do make up extra ordering when contemplating the ordering "A.service/stop before B.socket/stop", this way: B.socket has Triggers=B.service => let's add: A.service/stop before B.service/stop If necessary, the additional shutdown ordering dependency thus created could be made a "soft" dependency - in case its addition would cause an ordering cycle, it would be disregarded. Alternative proposal: If the automatic adding of ordering based on socket's Triggers feels like an ugly hack, then I guess there's no other option than to add an explicit "StopAfter=" option.
Currently everything specifies "After=syslog.target". If you are going to add magic dependency ordering I think it needs to work with that rather than "After=syslog.socket". I think the auto ordering is a good idea. I think it is a pretty natural assumption that if a process needs something at startup it will want it until it shuts down. Finally, I think you'll probably need an explicit StopAfter at some point for some future issue :)
I assume this is still an issue and am moving it against rawhide so it will not get closed in the EOL process for F15. Michal feel free to close this bug if this issue has been addressed in rawhide. Thanks
Adding "FutureFeature" to avoid automatic rebasing in Bugzilla.
I figure this is a problem of the past as rsyslog will read shutdown messages (and early-boot messages) from systemd's buffer on next reboot.