Bug 43625 - daemon-reload can cause in-progress service restarts to fail
Summary: daemon-reload can cause in-progress service restarts to fail
Status: RESOLVED FIXED
Alias: None
Product: systemd
Classification: Unclassified
Component: general (show other bugs)
Version: unspecified
Hardware: x86-64 (AMD64) Linux (All)
: medium normal
Assignee: Lennart Poettering
QA Contact:
URL:
Whiteboard:
Keywords:
Depends on:
Blocks:
 
Reported: 2011-12-08 03:53 UTC by Chris Paulson-Ellis
Modified: 2012-02-02 10:15 UTC (History)
0 users

See Also:
i915 platform:
i915 features:

Attachments
Raw log for easier reading (25.57 KB, text/plain)
2011-12-08 03:58 UTC, Chris Paulson-Ellis 		Details
View All

Description Chris Paulson-Ellis 2011-12-08 03:53:06 UTC 
If a daemon-reload arrives after a service restart job has been submitted, but before systemd handles the SIGCHLD for the restarting service, then when systemd does handle the SIGCHLD after the reload, it doesn't seem to understand that the service has exited until and fails to restart the service until after some timeouts.

I've managed to create a cut-down example of my real scenario that shows the problem. The timing is critical, so you may have trouble reproducing this...

I've got 2 services, A & B. A represents a normal daemon and B a oneshot job that happens to do a daemon-reload. Here is a.service...

[Unit]
Description=A: a long running daemon

[Service]
ExecStart=/bin/a

StandardOutput=syslog
SyslogIdentifier=A
Restart=always
RestartSec=5


...and b.service...

[Unit]
Description=B: a run once program

[Service]
Type=oneshot
ExecStart=/bin/systemctl daemon-reload
StandardOutput=syslog
SyslogIdentifier=B
TimeoutSec=0
RemainAfterExit=yes


...and here is the source for a...

#include <stdio.h>
#include <signal.h>
#include <unistd.h>

void term( int signo )
{
    fprintf( stderr, "A exiting on SIGTERM\n" );
    _exit( 0 );
}

int main( int argc, char **argv )
{
    signal( SIGTERM, term );
    fprintf( stderr, "A started\n" );
    pause();
    fprintf( stderr, "A exiting unexpectedly\n" );
    return 1;
}


We start with A running with pid 3297, so in syslog we have:

Dec  8 10:24:50 douglas A[3297]: A started

Then I restart A & start B at the same time:

$ sudo systemctl restart b.service a.service

A exits, but sometimes the SIGCHLD isn't handled until after the reload caused by B. I've annotated the syslog a bit...

Dec  8 10:36:28 douglas systemd[1]: Accepted connection on private bus.
Dec  8 10:36:28 douglas systemd[1]: Got D-Bus request: org.freedesktop.systemd1.Manager.RestartUnit() on /org/freedesktop/systemd1
Dec  8 10:36:28 douglas systemd[1]: Trying to enqueue job b.service/restart/replace
Dec  8 10:36:28 douglas systemd[1]: Installed new job b.service/restart as 1545
Dec  8 10:36:28 douglas systemd[1]: Enqueued job b.service/restart as 1545
Dec  8 10:36:28 douglas systemd[1]: b.service changed exited -> dead
Dec  8 10:36:28 douglas systemd[1]: Converting job b.service/restart -> b.service/start
Dec  8 10:36:28 douglas systemd[1]: About to execute: /bin/systemctl daemon-reload
Dec  8 10:36:28 douglas systemd[1]: Forked /bin/systemctl as 3426
Dec  8 10:36:28 douglas systemd[1]: b.service changed dead -> start

B has been started. It will shortly request a daemon-reload

Dec  8 10:36:28 douglas systemd[1]: Got D-Bus request: org.freedesktop.systemd1.Manager.GetUnit() on /org/freedesktop/systemd1
Dec  8 10:36:28 douglas systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.Get() on /org/freedesktop/systemd1/unit/b_2eservice
Dec  8 10:36:28 douglas systemd[1]: Got D-Bus request: org.freedesktop.systemd1.Manager.RestartUnit() on /org/freedesktop/systemd1
Dec  8 10:36:28 douglas systemd[1]: Trying to enqueue job a.service/restart/replace
Dec  8 10:36:28 douglas systemd[1]: Installed new job a.service/restart as 1546
Dec  8 10:36:28 douglas systemd[1]: Enqueued job a.service/restart as 1546
Dec  8 10:36:28 douglas systemd[1]: a.service changed running -> stop-sigterm

A has been sent a SIGTERM

Dec  8 10:36:28 douglas systemd[1]: Got D-Bus request: org.freedesktop.systemd1.Manager.GetUnit() on /org/freedesktop/systemd1
Dec  8 10:36:28 douglas systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.Get() on /org/freedesktop/systemd1/unit/a_2eservice
Dec  8 10:36:28 douglas systemd[1]: Accepted connection on private bus.
Dec  8 10:36:28 douglas systemd[1]: Got D-Bus request: org.freedesktop.systemd1.Manager.Reload() on /org/freedesktop/systemd1
Dec  8 10:36:28 douglas systemd[1]: Reloading.
Dec  8 10:36:28 douglas systemd[1]: Serializing state to /run/systemd/dump-1-Q2mhii

The daemon-reload request from B has been handled.

Dec  8 10:36:28 douglas A[3297]: A exiting on SIGTERM

A is exiting.

Dec  8 10:36:28 douglas systemd[1]: Looking for unit files in:
Dec  8 10:36:28 douglas systemd[1]: #011/etc/systemd/system
Dec  8 10:36:28 douglas systemd[1]: #011/lib/systemd/system
Dec  8 10:36:28 douglas systemd[1]: Looking for SysV init scripts in:
Dec  8 10:36:28 douglas systemd[1]: #011/etc/rc.d/init.d
Dec  8 10:36:28 douglas systemd[1]: Looking for SysV rcN.d links in:
Dec  8 10:36:28 douglas systemd[1]: #011/etc/rc.d
Dec  8 10:36:28 douglas systemd[1]: Spawned /lib/systemd/system-generators/systemd-cryptsetup-generator as 3428
Dec  8 10:36:28 douglas systemd[1]: Spawned /lib/systemd/system-generators/systemd-getty-generator as 3429
Dec  8 10:36:28 douglas systemd[1]: /lib/systemd/system-generators/systemd-cryptsetup-generator exited successfully.
Dec  8 10:36:28 douglas systemd[1]: /lib/systemd/system-generators/systemd-getty-generator exited successfully.
Dec  8 10:36:28 douglas systemd[1]: Failed to load configuration for livesys-late.service: No such file or directory
Dec  8 10:36:28 douglas systemd[1]: Failed to load configuration for firstboot-text.service: No such file or directory
Dec  8 10:36:28 douglas systemd[1]: Failed to load configuration for livesys.service: No such file or directory
Dec  8 10:36:28 douglas systemd[1]: Failed to load configuration for exim.service: No such file or directory
Dec  8 10:36:28 douglas systemd[1]: Failed to load configuration for postfix.service: No such file or directory
Dec  8 10:36:28 douglas systemd[1]: Failed to load configuration for named.service: No such file or directory
Dec  8 10:36:28 douglas systemd[1]: Failed to load configuration for tgtd.service: No such file or directory
Dec  8 10:36:28 douglas systemd[1]: Deserializing state...
Dec  8 10:36:28 douglas systemd[1]: Failed to load configuration for dbus-org.bluez.service: No such file or directory
Dec  8 10:36:28 douglas systemd[1]: Failed to load configuration for A.service: No such file or directory
Dec  8 10:36:28 douglas systemd[1]: httpd.service changed dead -> running
Dec  8 10:36:28 douglas systemd[1]: Successfully opened syslog for logging.
Dec  8 10:36:28 douglas systemd[1]: fedora-storage-init.service changed dead -> exited
Dec  8 10:36:28 douglas systemd[1]: fedora-storage-init-late.service changed dead -> exited
Dec  8 10:36:28 douglas systemd[1]: cryptsetup.target changed dead -> active
Dec  8 10:36:28 douglas systemd[1]: fedora-wait-storage.service changed dead -> exited
Dec  8 10:36:28 douglas systemd[1]: var-lib-nfs-rpc_pipefs.mount changed dead -> mounted
Dec  8 10:36:28 douglas systemd[1]: network.target changed dead -> active
Dec  8 10:36:28 douglas systemd[1]: proc-fs-nfsd.mount changed dead -> mounted
Dec  8 10:36:28 douglas systemd[1]: swap.target changed dead -> active
Dec  8 10:36:28 douglas systemd[1]: mdmonitor-takeover.service changed dead -> exited
Dec  8 10:36:28 douglas systemd[1]: lvm2-monitor.service changed dead -> exited
Dec  8 10:36:28 douglas systemd[1]: systemd-sysctl.service changed dead -> exited
Dec  8 10:36:28 douglas systemd[1]: sys-fs-fuse-connections.mount changed dead -> mounted
Dec  8 10:36:28 douglas systemd[1]: dev-mqueue.mount changed dead -> mounted
Dec  8 10:36:28 douglas systemd[1]: sys-kernel-debug.mount changed dead -> mounted
Dec  8 10:36:28 douglas systemd[1]: dev-hugepages.mount changed dead -> mounted
Dec  8 10:36:28 douglas systemd[1]: proc-sys-fs-binfmt_misc.automount changed dead -> running
Dec  8 10:36:28 douglas systemd[1]: sys-kernel-security.mount changed dead -> mounted
Dec  8 10:36:28 douglas systemd[1]: systemd-binfmt.service changed dead -> exited
Dec  8 10:36:28 douglas systemd[1]: proc-sys-fs-binfmt_misc.mount changed dead -> mounted
Dec  8 10:36:28 douglas systemd[1]: remount-rootfs.service changed dead -> exited
Dec  8 10:36:28 douglas systemd[1]: fedora-readonly.service changed dead -> exited
Dec  8 10:36:28 douglas systemd[1]: systemd-remount-api-vfs.service changed dead -> exited
Dec  8 10:36:28 douglas systemd[1]: var-run.mount changed dead -> mounted
Dec  8 10:36:28 douglas systemd[1]: media.mount changed dead -> mounted
Dec  8 10:36:28 douglas systemd[1]: var-lock.mount changed dead -> mounted
Dec  8 10:36:28 douglas systemd[1]: local-fs-pre.target changed dead -> active
Dec  8 10:36:28 douglas systemd[1]: ip6tables.service changed dead -> exited
Dec  8 10:36:28 douglas systemd[1]: iptables.service changed dead -> exited
Dec  8 10:36:28 douglas systemd[1]: systemd-tmpfiles-clean.timer changed dead -> waiting
Dec  8 10:36:28 douglas systemd[1]: fedora-loadmodules.service changed dead -> exited
Dec  8 10:36:28 douglas systemd[1]: console-kit-log-system-start.service changed dead -> exited
Dec  8 10:36:28 douglas systemd[1]: systemd-stdout-syslog-bridge.service changed dead -> running
Dec  8 10:36:28 douglas systemd[1]: sys-devices-pci0000:00-0000:00:01.0-0000:01:00.1-sound-card1.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: sound.target changed dead -> active
Dec  8 10:36:28 douglas systemd[1]: sys-devices-pci0000:00-0000:00:1b.0-sound-card0.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: sys-devices-pci0000:00-0000:00:1c.3-0000:03:00.0-net-eth0.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: sys-devices-pci0000:00-0000:00:1d.0-usb2-2\x2d1-2\x2d1.1-2\x2d1.1.4-2\x2d1.1.4:1.0-host9-target9:0:0-9:0:0:0-block-sdb.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: dev-sdb.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: dev-disk-by\x2did-usb\x2dHTC_Android_Phone_HT0BRPL08254\x2d0:0.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: dev-disk-by\x2dpath-pci\x2d0000:00:1d.0\x2dusb\x2d0:1.1.4:1.0\x2dscsi\x2d0:0:0:0.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: sys-devices-pci0000:00-0000:00:1f.2-host0-target0:0:0-0:0:0:0-block-sda.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: dev-sda.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: dev-disk-by\x2did-ata\x2dSAMSUNG_HD322GJ_S2B0J90B208005.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: dev-disk-by\x2did-scsi\x2dSATA_SAMSUNG_HD322GJ_S2B0J90B208005.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: dev-disk-by\x2dpath-pci\x2d0000:00:1f.2\x2dscsi\x2d0:0:0:0.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: dev-disk-by\x2did-wwn\x2d0x50024e92047e2d74.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: sys-devices-pci0000:00-0000:00:1f.2-host0-target0:0:0-0:0:0:0-block-sda-sda1.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: dev-sda1.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: dev-disk-by\x2did-ata\x2dSAMSUNG_HD322GJ_S2B0J90B208005\x2dpart1.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: dev-disk-by\x2did-scsi\x2dSATA_SAMSUNG_HD322GJ_S2B0J90B208005\x2dpart1.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: dev-disk-by\x2dpath-pci\x2d0000:00:1f.2\x2dscsi\x2d0:0:0:0\x2dpart1.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: dev-disk-by\x2duuid-62d6d1e1\x2d829b\x2d439d\x2d8b9c\x2de4641a8dae94.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: dev-disk-by\x2did-wwn\x2d0x50024e92047e2d74\x2dpart1.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: sys-devices-pci0000:00-0000:00:1f.2-host0-target0:0:0-0:0:0:0-block-sda-sda2.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: dev-sda2.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: dev-disk-by\x2did-ata\x2dSAMSUNG_HD322GJ_S2B0J90B208005\x2dpart2.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: dev-disk-by\x2did-scsi\x2dSATA_SAMSUNG_HD322GJ_S2B0J90B208005\x2dpart2.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: dev-disk-by\x2dpath-pci\x2d0000:00:1f.2\x2dscsi\x2d0:0:0:0\x2dpart2.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: dev-disk-by\x2did-wwn\x2d0x50024e92047e2d74\x2dpart2.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: sys-devices-pci0000:00-0000:00:1f.2-host1-target1:0:0-1:0:0:0-block-sr0.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: dev-sr0.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: dev-scd0.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: dev-disk-by\x2did-ata\x2dTSSTcorpDVD\x2dROM_TS\x2dH353C_R60668BB417444.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: dev-disk-by\x2dpath-pci\x2d0000:00:1f.2\x2dscsi\x2d1:0:0:0.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: dev-cdrom.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: dev-dvd.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: sys-devices-platform-serial8250-tty-ttyS0.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: dev-ttyS0.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: sys-devices-platform-serial8250-tty-ttyS1.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: dev-ttyS1.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: sys-devices-platform-serial8250-tty-ttyS2.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: dev-ttyS2.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: sys-devices-platform-serial8250-tty-ttyS3.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: dev-ttyS3.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: sys-devices-virtual-tty-tty0.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: dev-tty0.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: sys-devices-virtual-tty-tty1.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: sys-devices-virtual-tty-tty10.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: dev-tty10.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: sys-devices-virtual-tty-tty11.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: dev-tty11.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: sys-devices-virtual-tty-tty12.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: dev-tty12.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: sys-devices-virtual-tty-tty2.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: sys-devices-virtual-tty-tty3.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: sys-devices-virtual-tty-tty4.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: sys-devices-virtual-tty-tty5.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: sys-devices-virtual-tty-tty6.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: sys-devices-virtual-tty-tty7.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: dev-tty7.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: sys-devices-virtual-tty-tty8.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: dev-tty8.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: sys-devices-virtual-tty-tty9.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: dev-tty9.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: sys-module-fuse.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: sys-devices-virtual-block-dm\x2d0.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: dev-dm\x2d0.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: dev-mapper-vg_douglas\x2dlv_root.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: dev-vg_douglas-lv_root.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: dev-disk-by\x2did-dm\x2dname\x2dvg_douglas\x2dlv_root.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: dev-disk-by\x2did-dm\x2duuid\x2dLVM\x2dcTZmwMbE9FroPiVY3hnbpLolu5y26nspy6m11TbGMfmcgOfHeCdGcNkmupndq27k.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: dev-disk-by\x2duuid-73dfc66e\x2dedcf\x2d4934\x2d9399\x2d2c55ebe0a04d.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: sys-devices-virtual-block-dm\x2d1.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: dev-dm\x2d1.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: dev-mapper-vg_douglas\x2dlv_home.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: dev-vg_douglas-lv_home.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: dev-disk-by\x2did-dm\x2dname\x2dvg_douglas\x2dlv_home.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: dev-disk-by\x2did-dm\x2duuid\x2dLVM\x2dcTZmwMbE9FroPiVY3hnbpLolu5y26nspjII25dZf02APXiArvw3Mm7dzVfd1l95n.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: dev-disk-by\x2duuid-0cd4dbe4\x2d8b31\x2d42d9\x2dacbb\x2d04e04ea8d923.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: sys-devices-virtual-block-dm\x2d2.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: dev-dm\x2d2.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: dev-mapper-vg_douglas\x2dlv_swap.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: dev-vg_douglas-lv_swap.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: dev-disk-by\x2did-dm\x2dname\x2dvg_douglas\x2dlv_swap.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: dev-disk-by\x2did-dm\x2duuid\x2dLVM\x2dcTZmwMbE9FroPiVY3hnbpLolu5y26nspoB7RB9ADGogoCG8KUlTZSN3VGFikM5HU.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: dev-disk-by\x2duuid-149d7fda\x2d5869\x2d4a9d\x2db382\x2d7cbe9338b2ea.device changed dead -> plugged
Dec  8 10:36:28 douglas systemd[1]: -.mount changed dead -> mounted
Dec  8 10:36:28 douglas systemd[1]: boot.mount changed dead -> mounted
Dec  8 10:36:28 douglas systemd[1]: home.mount changed dead -> mounted
Dec  8 10:36:28 douglas systemd[1]: dev-mapper-vg_douglas\x2dlv_swap.swap changed dead -> active
Dec  8 10:36:28 douglas systemd[1]: home-chris-.gvfs.mount changed dead -> mounted
Dec  8 10:36:28 douglas systemd[1]: dev-dm\x2d2.swap changed dead -> active
Dec  8 10:36:28 douglas systemd[1]: dev-vg_douglas-lv_swap.swap changed dead -> active
Dec  8 10:36:28 douglas systemd[1]: dev-disk-by\x2did-dm\x2dname\x2dvg_douglas\x2dlv_swap.swap changed dead -> active
Dec  8 10:36:28 douglas systemd[1]: dev-disk-by\x2did-dm\x2duuid\x2dLVM\x2dcTZmwMbE9FroPiVY3hnbpLolu5y26nspoB7RB9ADGogoCG8KUlTZSN3VGFikM5HU.swap changed dead -> active
Dec  8 10:36:28 douglas systemd[1]: dev-disk-by\x2duuid-149d7fda\x2d5869\x2d4a9d\x2db382\x2d7cbe9338b2ea.swap changed dead -> active
Dec  8 10:36:28 douglas systemd[1]: console-kit-daemon.service changed dead -> running
Dec  8 10:36:28 douglas systemd[1]: accounts-daemon.service changed dead -> running
Dec  8 10:36:28 douglas systemd[1]: rtkit-daemon.service changed dead -> running
Dec  8 10:36:28 douglas systemd[1]: dhcpd.service changed dead -> running
Dec  8 10:36:28 douglas systemd[1]: a.service changed dead -> stop-sigterm
Dec  8 10:36:28 douglas systemd[1]: Trying to enqueue job a.service/restart/ignore-requirements
Dec  8 10:36:28 douglas systemd[1]: Installed new job a.service/restart as 1547
Dec  8 10:36:28 douglas systemd[1]: Enqueued job a.service/restart as 1547
Dec  8 10:36:28 douglas systemd[1]: b.service changed dead -> start
Dec  8 10:36:28 douglas systemd[1]: Trying to enqueue job b.service/start/ignore-requirements
Dec  8 10:36:28 douglas systemd[1]: Installed new job b.service/start as 1548
Dec  8 10:36:28 douglas systemd[1]: Enqueued job b.service/start as 1548
Dec  8 10:36:28 douglas systemd[1]: Closing left-over fd 52
Dec  8 10:36:28 douglas systemd[1]: Closing left-over fd 53
Dec  8 10:36:28 douglas systemd[1]: Closing left-over fd 54
Dec  8 10:36:28 douglas systemd[1]: Running GC...
Dec  8 10:36:28 douglas systemd[1]: Got D-Bus request: org.freedesktop.DBus.Local.Disconnected() on /org/freedesktop/DBus/Local
Dec  8 10:36:28 douglas systemd[1]: Received SIGCHLD from PID 3297 (n/a).

The SIGCHLD from A, but systemd normally prints (a), not (n/a) when a.service is restarted without the reload and normally prints messages about the child belonging to a.service. It appears to have been confused by the reload.

Dec  8 10:36:28 douglas systemd[1]: Got SIGCHLD for process 3426 (systemctl)
Dec  8 10:36:28 douglas systemd[1]: Child 3426 died (code=exited, status=0/SUCCESS)
Dec  8 10:36:28 douglas systemd[1]: Child 3426 belongs to b.service
Dec  8 10:36:28 douglas systemd[1]: b.service: main process exited, code=exited, status=0
Dec  8 10:36:28 douglas systemd[1]: b.service changed start -> exited
Dec  8 10:36:28 douglas systemd[1]: Job b.service/start finished, result=done

The SIGCHLD from B has been handled correctly.

Dec  8 10:36:28 douglas systemd[1]: Accepted connection on private bus.
Dec  8 10:36:28 douglas systemd[1]: Got D-Bus request: org.freedesktop.DBus.Local.Disconnected() on /org/freedesktop/DBus/Local
Dec  8 10:36:28 douglas systemd[1]: Got D-Bus request: org.freedesktop.systemd1.Agent.Released() on /org/freedesktop/systemd1/agent
Dec  8 10:36:28 douglas systemd[1]: a.service: cgroup is empty

systemd has noticed the empty cgroup for A, but does nothing about it.

Dec  8 10:36:28 douglas systemd[1]: Got D-Bus request: org.freedesktop.DBus.Local.Disconnected() on /org/freedesktop/DBus/Local
Dec  8 10:36:28 douglas systemd[1]: Accepted connection on private bus.
Dec  8 10:36:28 douglas systemd[1]: Got D-Bus request: org.freedesktop.systemd1.Agent.Released() on /org/freedesktop/systemd1/agent
Dec  8 10:36:28 douglas systemd[1]: b.service: cgroup is empty
Dec  8 10:36:28 douglas systemd[1]: Got D-Bus request: org.freedesktop.DBus.Local.Disconnected() on /org/freedesktop/DBus/Local
Dec  8 10:36:28 douglas systemd[1]: Got D-Bus request: org.freedesktop.DBus.NameOwnerChanged() on /org/freedesktop/DBus

Time passes. Some unrelated stuff happens...

Dec  8 10:36:55 douglas systemd[1]: Received SIGCHLD from PID 3420 (fprintd).
Dec  8 10:36:55 douglas systemd[1]: Got SIGCHLD for process 3420 (fprintd)
Dec  8 10:36:55 douglas systemd[1]: Child 3420 died (code=exited, status=0/SUCCESS)
Dec  8 10:36:55 douglas systemd[1]: Got D-Bus request: org.freedesktop.DBus.NameOwnerChanged() on /org/freedesktop/DBus
Dec  8 10:36:55 douglas systemd[1]: Got D-Bus request: org.freedesktop.DBus.NameOwnerChanged() on /org/freedesktop/DBus

I verify that A is in the wrong state...

$ sudo systemctl status a.service
a.service - A: a long running daemon
	  Loaded: loaded (/lib/systemd/system/a.service; static)
	  Active: deactivating (stop-sigterm) since Thu, 08 Dec 2011 10:36:28 +0000; 46s ago
	Main PID: 3297
	  CGroup: name=systemd:/system/a.service

Dec  8 10:37:15 douglas systemd[1]: Accepted connection on private bus.
Dec  8 10:37:15 douglas systemd[1]: Got D-Bus request: org.freedesktop.systemd1.Manager.LoadUnit() on /org/freedesktop/systemd1
Dec  8 10:37:15 douglas systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/a_2eservice
Dec  8 10:37:15 douglas systemd[1]: Looking for unit files in:
Dec  8 10:37:15 douglas systemd[1]: #011/etc/systemd/system
Dec  8 10:37:15 douglas systemd[1]: #011/lib/systemd/system
Dec  8 10:37:15 douglas systemd[1]: Looking for SysV init scripts in:
Dec  8 10:37:15 douglas systemd[1]: #011/etc/rc.d/init.d
Dec  8 10:37:15 douglas systemd[1]: Looking for SysV rcN.d links in:
Dec  8 10:37:15 douglas systemd[1]: #011/etc/rc.d
Dec  8 10:37:15 douglas systemd[1]: Got D-Bus request: org.freedesktop.DBus.Local.Disconnected() on /org/freedesktop/DBus/Local

More time passes and systemd changes A's state...

Dec  8 10:37:58 douglas systemd[1]: a.service stopping timed out. Killing.
Dec  8 10:37:58 douglas systemd[1]: a.service changed stop-sigterm -> stop-sigkill

...same again...

Dec  8 10:39:28 douglas systemd[1]: a.service still around after SIGKILL. Ignoring.
Dec  8 10:39:28 douglas systemd[1]: a.service changed stop-sigkill -> final-sigterm

... more unrelated stuff...

Dec  8 10:40:54 douglas systemd[1]: Got D-Bus request: org.freedesktop.DBus.NameOwnerChanged() on /org/freedesktop/DBus
Dec  8 10:40:54 douglas systemd[1]: Got D-Bus request: org.freedesktop.DBus.NameOwnerChanged() on /org/freedesktop/DBus
Dec  8 10:40:54 douglas systemd[1]: Got D-Bus request: org.freedesktop.DBus.NameOwnerChanged() on /org/freedesktop/DBus
Dec  8 10:40:54 douglas systemd[1]: Got D-Bus request: org.freedesktop.DBus.NameOwnerChanged() on /org/freedesktop/DBus

...until finally systemd times out and restarts A...

Dec  8 10:40:58 douglas systemd[1]: a.service stopping timed out (2). Killing.
Dec  8 10:40:58 douglas systemd[1]: a.service changed final-sigterm -> failed
Dec  8 10:40:58 douglas systemd[1]: Converting job a.service/restart -> a.service/start
Dec  8 10:40:58 douglas systemd[1]: Unit a.service entered failed state.
Dec  8 10:40:58 douglas systemd[1]: About to execute: /bin/a
Dec  8 10:40:58 douglas systemd[1]: Forked /bin/a as 3465
Dec  8 10:40:58 douglas systemd[1]: a.service changed failed -> running
Dec  8 10:40:58 douglas systemd[1]: Job a.service/start finished, result=done
Dec  8 10:40:58 douglas A[3465]: A started


These logs are from a Fedora 16 box with systemd-37-3.fc16.x86_64
I've also seen the problem with a Fedora 15 box with systemd-26-13.fc15.x86_64

For the interested - In my real system, B is a job that has been submitted to do software updates. The daemon-reload comes from a package update. A is a watchdog service that gets restarted as part of the same package update. The delayed restart of A causes the watchdog to timeout :-(.

Chris.
Comment 1 Chris Paulson-Ellis 2011-12-08 03:58:06 UTC 
Created attachment 54233 [details]
Raw log for easier reading
Comment 2 Lennart Poettering 2012-02-02 10:11:36 UTC 
Patch applied in git. Thanks!

Use of freedesktop.org services, including Bugzilla, is subject to our Code of Conduct. How we collect and use information is described in our Privacy Policy.