Debian Bug report logs - #624599
systemd: DHCP hook scripts calling invoke-rc.d causes boot hang

Toggle useless messages

Message #5 received at submit@bugs.debian.org (full text, mbox, reply):

From: Will Dyson <will_dyson@pobox.com>

To: Debian Bug Tracking System <submit@bugs.debian.org>

Subject: systemd: DHCP hook scripts calling invoke-rc.d causes boot hang

Date: Fri, 29 Apr 2011 20:21:19 -0400

Package: systemd
Version: 25-2
Severity: normal

When a package (such as samba-common) provides a dhcp hook script that
calls invoke-rc.d reload on DHCP state change and the system brings up
a DHCP interface on boot, systemd fails to start the system.

Below is the last few lines of serial console log, before it hangs
indefinitely.


[   15.902776] <31>systemd[1]: Got D-Bus request: org.freedesktop.DBus.Local.Disconnected() on /org/freedesktop/DBus/Local
[   15.902797] <31>systemd[1]: Got D-Bus request: org.freedesktop.DBus.Local.Disconnected() on /org/freedesktop/DBus/Local
Configuring network interfaces...logger[876]: WAR[   16.907365] <31>NING: Initialisi<27>logger[876]: WARNING: Initialising interface eth0 which does not have link
ng interface eth[   16.920436] systemd0 which does not[1]:  have link
Incoming traffic on syslog.socket
[   16.931380] <31>systemd[1]: syslog.socket changed listening -> running
[   16.939728] <31>systemd[1]: Got direct mount request for ffff88012b97ad80, triggered by 879 (wpasupplicant)
[   16.951253] <31>systemd[1]: Trying to enqueue job lib-init-rw.mount/start/replace
[   16.960542] <31>systemd[1]: Installed new job lib-init-rw.mount/start as 230
[   16.969365] <31>systemd[1]: Enqueued job lib-init-rw.mount/start as 230
[   16.977739] <31>systemd[1]: lib-init-rw.automount changed waiting -> running
Starting Debian [   16.986613] <31>early rw mount..systemd.
[1]: About to execute: /bin/mount tmpfs /lib/init/rw -t tmpfs -o mode=0755,nosuid
[   17.028025] <31>systemd[1]: Forked /bin/mount as 880

[   17.034771] <31>systemd[1]: lib-init-rw.mount changed dead -> mounting
[   17.043272] <31>systemd[1]: lib-init-rw.mount changed mounting -> mounting-done
[   17.052339] <31>systemd[1]: Job lib-init-rw.mount/start finished, result=done
Started Debian e[   17.061304] <31>arly rw mount.
systemd[1]: Received SIGCHLD from PID 880 (mount).
[   17.071933] <31>systemd[1]: Got SIGCHLD for process 880 (mount)
[   17.079604] <31>systemd[1]: Child 880 died (code=exited, status=0/SUCCESS)
[   17.088187] <31>systemd[1]: Child 880 belongs to lib-init-rw.mount
[   17.096056] <31>systemd[1]: lib-init-rw.mount mount process exited, code=exited status=0
[   17.105835] <31>systemd[1]: Sending success.
[   17.111767] <31>systemd[1]: lib-init-rw.mount changed mounting-done -> mounted
[   17.120790] <31>systemd[1]: Accepted connection on private bus.
[   17.128540] <31>systemd[1]: Got D-Bus request: org.freedesktop.systemd1.Agent.Released() on /org/freedesktop/systemd1/agent
[   17.141388] <31>systemd[1]: Got D-Bus request: org.freedesktop.DBus.Local.Disconnected() on /org/freedesktop/DBus/Local
Internet Systems[   17.172246] <30> Consortium DHCPdhclient Client 4.1.1-P1[886]: Internet Systems Consortium DHCP Client 4.1.1-P1
Copyright 2004
-2010 Internet S[   17.186715] <30>ystems Consortiudhclientm.
All rights r[886]: eserved.
For inCopyright 2004-2010 Internet Systems Consortium.fo, please visit
 https://www.isc[   17.202574] <30>.org/software/dhdhclientcp/

[886]: All rights reserved.
[   17.212414] <30>dhclient[886]: For info, please visit https://www.isc.org/software/dhcp/
[   17.304397] r8169 0000:03:00.0: eth0: link down
[   17.308394] r8169 0000:03:00.0: eth0: link down
[   17.316858] ADDRCONF(NETDEV_UP): eth0: link is not ready
Listening on LPF[   17.344112] <30>/eth0/00:22:68:4dhclient6:1b:96
Sending[886]:  on   LPF/eth0/0Listening on LPF/eth0/00:22:68:46:1b:960:22:68:46:1b:96

Sending on   S[   17.359157] <30>ocket/fallback
dhclient[886]: Sending on   LPF/eth0/00:22:68:46:1b:96
[   17.369964] <30>dhclient[886]: Sending on   Socket/fallback
[   19.735272] r8169 0000:03:00.0: eth0: link up
[   19.739261] ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
DHCPDISCOVER on [   21.001625] <30>eth0 to 255.255.dhclient255.255 port 67 [886]: interval 7
DHCPDHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 7OFFER from 192.1
68.128.1
DHCPREQUEST on eth0 to[   21.018350] <30> 255.255.255.255dhclient port 67
DHCPAC[886]: K from 192.168.1DHCPOFFER from 192.168.128.128.1

[   21.031432] <30>dhclient[886]: DHCPREQUEST on eth0 to 255.255.255.255 port 67
[   21.040074] <30>dhclient[886]: DHCPACK from 192.168.128.1
[   21.077228] <31>systemd[1]: Accepted connection on private bus.
[   21.084793] <31>systemd[1]: Got D-Bus request: org.freedesktop.systemd1.Manager.LoadUnit() on /org/freedesktop/systemd1
[   21.097109] <31>systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/samba_2eservice
[   21.111262] <31>systemd[1]: Got D-Bus request: org.freedesktop.DBus.Local.Disconnected() on /org/freedesktop/DBus/Local
[   21.123553] <31>systemd[1]: Accepted connection on private bus.
[   21.131040] <31>systemd[1]: Got D-Bus request: org.freedesktop.systemd1.Manager.LoadUnit() on /org/freedesktop/systemd1
[   21.143346] <31>systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/samba_2eservice
[   21.157480] <31>Reloading samba systemdconfiguration (v[1]: ia systemctl): sGot D-Bus request: org.freedesktop.DBus.Local.Disconnected() on /org/freedesktop/DBus/Localamba.service
[   21.174930] <31>systemd[1]: Accepted connection on private bus.
[   21.182429] <31>systemd[1]: Got D-Bus request: org.freedesktop.systemd1.Manager.ReloadUnit() on /org/freedesktop/systemd1
[   21.194842] <31>systemd[1]: Trying to enqueue job samba.service/reload/replace
[   21.203540] <31>systemd[1]: Installed new job samba.service/reload as 233
[   21.211789] <31>systemd[1]: Enqueued job samba.service/reload as 233
[   21.219649] <31>systemd[1]: Got D-Bus request: org.freedesktop.systemd1.Manager.GetUnit() on /org/freedesktop/systemd1
[   21.231855] <31>systemd[1]: Got D-Bus request: org.freedesktop.DBus.Properties.Get() on /org/freedesktop/systemd1/unit/samba_2eservice



-- System Information:
Debian Release: wheezy/sid
  APT prefers unstable
  APT policy: (500, 'unstable'), (101, 'experimental')
Architecture: amd64 (x86_64)

Kernel: Linux 2.6.38-2-amd64 (SMP w/2 CPU cores)
Locale: LANG=en_US.UTF-8, LC_CTYPE=en_US.UTF-8 (charmap=UTF-8) (ignored: LC_ALL set to en_US.UTF-8)
Shell: /bin/sh linked to /bin/dash

Versions of packages systemd depends on:
ii  initscripts                 2.88dsf-13.5 scripts for initializing and shutt
ii  libaudit0                   1.7.13-1+b2  Dynamic library for security audit
ii  libc6                       2.11.2-13    Embedded GNU C Library: Shared lib
ii  libcap2                     1:2.20-1     support for getting/setting POSIX.
ii  libcryptsetup1              2:1.2.0-2    libcryptsetup shared library
ii  libdbus-1-3                 1.4.8-3      simple interprocess messaging syst
ii  libpam0g                    1.1.2-2      Pluggable Authentication Modules l
ii  libselinux1                 2.0.98-1     SELinux runtime shared libraries
ii  libudev0                    168-1        libudev shared library
ii  libwrap0                    7.6.q-19     Wietse Venema's TCP wrappers libra
ii  util-linux                  2.17.2-9.1   Miscellaneous system utilities

Versions of packages systemd recommends:
ii  libpam-systemd                25-2       system and service manager - PAM m

Versions of packages systemd suggests:
ii  python                        2.6.6-14   interactive high-level object-orie
ii  systemd-gui                   25-2       system and service manager - GUI

-- Configuration Files:
/etc/systemd/system.conf changed:
[Manager]
LogLevel=info
LogTarget=syslog-or-kmsg
LogColor=yes
ShowStatus=yes
SysVConsole=yes
MountAuto=yes
SwapAuto=yes


-- no debconf information

Message #10 received at 624599@bugs.debian.org (full text, mbox, reply):

From: rektide <rektide@voodoowarez.com>

To: 624599@bugs.debian.org

Subject: workarounds?

Date: Fri, 3 Feb 2012 21:11:02 -0500

any workarounds for this? have been disabling samba, would like it back some time. :/

Message #15 received at 624599@bugs.debian.org (full text, mbox, reply):

From: Michael Biebl <biebl@debian.org>

To: 635777@bugs.debian.org, Bernhard Schmidt <berni@birkenwald.de>, 624599@bugs.debian.org

Subject: 90-seconds delay on reboot/shutdown when postfix is installed

Date: Wed, 29 Aug 2012 15:57:48 +0200

[Message part 1 (text/plain, inline)]

Hi Bernhard,

I see the same issue with samba, which installs a DHCP hook which calls
"invoke-rc.d samba stop" whenever the DHCP state changes, e.g. when you
ifup the device during boot or ifdown during shutdown.

So this might be duplicate of
http://bugs.debian.org/cgi-bin/bugreport.cgi?bug=624599
or at least be related.

I think your observation is correct that this is due to a reload command
being issued to a service which is not fully ready yet/anymore and this
is indeed a timing issue.



-- 
Why is it that all of the instruments seeking intelligent life in the
universe are pointed away from Earth?

[signature.asc (application/pgp-signature, attachment)]

Message #20 received at 624599@bugs.debian.org (full text, mbox, reply):

From: Michael Biebl <biebl@debian.org>

To: 624599@bugs.debian.org

Cc: 635777@bugs.debian.org, Bernhard Schmidt <berni@birkenwald.de>

Subject: Re: Bug#624599: 90-seconds delay on reboot/shutdown when postfix is installed

Date: Wed, 29 Aug 2012 16:05:31 +0200

[Message part 1 (text/plain, inline)]

On 29.08.2012 15:57, Michael Biebl wrote:

> I see the same issue with samba, which installs a DHCP hook which calls
> "invoke-rc.d samba stop" whenever the DHCP state changes, e.g. when you
                     ^
                      reload


-- 
Why is it that all of the instruments seeking intelligent life in the
universe are pointed away from Earth?

[signature.asc (application/pgp-signature, attachment)]

Message #25 received at 624599@bugs.debian.org (full text, mbox, reply):

From: Michael Biebl <biebl@debian.org>

To: 624599@bugs.debian.org, Will Dyson <will_dyson@pobox.com>

Subject: systemd: DHCP hook scripts calling invoke-rc.d causes boot hang

Date: Wed, 29 Aug 2012 16:30:23 +0200

[Message part 1 (text/plain, inline)]

Hi Will,

do you still experience the issue during boot with a current version (v44)?
I can reproduce the problem (90sec hang) during shutdown, but failed to
reproduce it during boot.

Michael
-- 
Why is it that all of the instruments seeking intelligent life in the
universe are pointed away from Earth?

[signature.asc (application/pgp-signature, attachment)]

Message #30 received at 624599@bugs.debian.org (full text, mbox, reply):

From: Michael Stapelberg <stapelberg@debian.org>

To: 635777@bugs.debian.org, 624599@bugs.debian.org

Subject: [PATCH] systemd reload during shutdown issue

Date: Sun, 14 Oct 2012 16:27:15 +0200

[Message part 1 (text/plain, inline)]

Hi,

It seems to me that bug #624599 and #635777 are talking about the same
issue, thus this message goes to both.

To debug this problem, I’ve installed wheezy in a virtualbox VM and enabled the
serial port to go to /tmp/wheezy.pipe, then used mkfifo /tmp/wheezy.pipe and
ran the following script called follow.sh:

#!/bin/zsh
IFS=$'\n'
while :
do
    read line
    echo "$(date +'%X.%N') $line"
done

like this:
socat -d -d /tmp/wheezy.pipe - | ./follow.sh

I have then installed systemd 44-4, samba 2:3.6.6-3 and modified
/etc/default/grub to contain GRUB_CMDLINE_LINUX_DEFAULT="console=ttyS0
systemd.log_target=console systemd.log_level=debug init=/bin/systemd"

In the resulting logfiles with systemd 44-4, I interpret the reboot sequence
like this:

First, the reboot is scheduled and systemd adds a lot of jobs:

13:17:54.077835080 Trying to enqueue job reboot.target/start/replace
13:17:54.078445373 Installed new job reboot.target/start as 207
13:17:54.079062664 Installed new job reboot.service/start as 208
13:17:54.079694022 Installed new job shutdown.target/start as 209
13:17:54.080331569 Installed new job systemd-update-utmp-shutdown.service/start as 210

[systemd-ignore-reload-during-shutdown.patch (text/x-diff, attachment)]

[Message part 3 (text/plain, inline)]

…
13:17:54.241713303 Installed new job final.target/start as 281
13:17:54.242481254 Installed new job console-kit-log-system-restart.service/start as 282

It then goes on the execute the jobs, and at some point in time gets a reload
request for samba:

13:17:54.834616091 Got D-Bus request: org.freedesktop.systemd1.Manager.ReloadUnit() on /org/freedesktop/systemd1
13:17:54.835327899 Trying to enqueue job samba.service/reload/replace
13:17:54.835985739 Installed new job samba.service/reload as 283
13:17:54.836630671 Enqueued job samba.service/reload as 283

This reload request blocks until it is executed, but systemd will only execute
it after finishing all other queued jobs, thus locking the situation
(ifup@eth0.service cannot be stopped until the reload is completed, the reload
cannot complete until ifup@eth0.service is completed).
Ultimately, ifup@eth0.service times out and the sequence continues:

13:19:24.240183406 ifup@eth0.service stopping timed out. Terminating.


I have written a patch which works around this issue by denying reload and
restart requests when final.target is queued (it gets queued before
poweroff.service, reboot.service and halt.service), it is attached to this
message.

With the patch applied, the reboot sequence works smoothly, as you can observe
from the output:

15:28:54.924965520 Trying to enqueue job reboot.target/start/replace
15:28:54.925644182 Installed new job reboot.target/start as 204
15:28:54.928603812 Installed new job reboot.service/start as 205
…
15:29:00.075293851 Got D-Bus request: org.freedesktop.systemd1.Manager.ReloadUnit() on /org/freedesktop/systemd1
15:29:00.075934837 final.target is queued, ignoring reload request
15:29:00.076552572 Got D-Bus request: org.freedesktop.DBus.Local.Disconnected() on /org/freedesktop/DBus/Local
15:29:00.077173492 Received SIGCHLD from PID 747 (ifdown).
15:29:00.077774461 Got SIGCHLD for process 747 (ifdown)
15:29:00.078372169 Child 747 died (code=exited, status=0/SUCCESS)
15:29:01.755516484 [   23.886593] Restarting system.
15:29:01.756118029 [   23.886898] machine restart

Can you still reproduce the issue after re-building systemd with this
patch?

-- 
Best regards,
Michael

Message #35 received at 624599@bugs.debian.org (full text, mbox, reply):

From: Michael Stapelberg <stapelberg@debian.org>

To: 624599@bugs.debian.org

Subject: More debugging

Date: Sun, 14 Oct 2012 19:21:50 +0200

Hi,

I can reproduce this problem in a freshly installed VM with systemd
44-4, samba 2:3.6.6-3, ifupdown 0.7.2 and "auto eth0" and "iface eth0
inet dhcp" in /etc/network/interfaces (Using "allow-hotplug eth0"
instead of "auto eth0" does not trigger the problem for me).

Note that an easy workaround is to unplug your network cable while
booting, which will lead to DHCP timeouts and thus not triggering the
hook.

Also, my previous mail was wrong: This is not precisely the same issue
as #635777 (though related).

I debugged this by unchecking "cable connected" in virtualbox and using
the same technique as described in my previous mail. I gather from the
logfiles that networking.service (generated from LSB
/etc/init.d/networking) is of Type=forking and thus systemd blocks until
its process exits.

Now, when you have a network connection, /etc/init.d/networking will
blockingly get a DHCP lease, then call the hook, which in turn calls
invoke-rc.d samba reload, which gets diverted to systemctl reload
samba.service.

The problem is that systemctl reload blocks by default (unless
--no-block is given) and thus it waits until systemd actually does the
reload. However, systemd cannot do that right now, since it is waiting
for networking.service to complete, thus we’re in a deadlock.

Summary: systemd blocks on networking.service, networking.service’s
systemctl blocks on systemd → deadlock.

For the record, here is the serial console output of the deadlock:

17:11:34.156170701 networking[360]: Listening on LPF/eth0/08:00:27:aa:5c:50
17:11:34.156883222 networking[360]: Sending on   LPF/eth0/08:00:27:aa:5c:50
17:11:34.157563858 networking[360]: Sending on   Socket/fallback
17:11:34.158290907 networking[360]: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 7
17:11:34.158921965 networking[360]: DHCPREQUEST on eth0 to 255.255.255.255 port 67
17:11:34.159559876 networking[360]: DHCPOFFER from 192.168.1.1
17:11:34.161844597 networking[360]: DHCPACK from 192.168.1.1
17:11:34.169969096 console-setup[359]: Setting up console font and keymap...done.
17:11:34.170668053 Received SIGCHLD from PID 359 (console-setup).
17:11:34.171440944 Got SIGCHLD for process 359 (console-setup)
17:11:34.172096872 Child 359 died (code=exited, status=0/SUCCESS)
17:11:34.172745800 Child 359 belongs to console-setup.service
17:11:34.173406636 console-setup.service: control process exited, code=exited status=0
17:11:34.174020720 console-setup.service got final SIGCHLD for state start
17:11:34.174813825 console-setup.service changed start -> exited
17:11:34.175468131 Job console-setup.service/start finished, result=done
17:11:34.176099249 Started LSB: Set console font and keymap                               [ESC[1;32m  OK  ESC[0m]
17:11:34.176753535 Successfully opened /dev/console for logging.
17:11:34.182303441 Got SIGCHLD for process 415 (swapon)
17:11:34.183021451 Child 415 died (code=exited, status=0/SUCCESS)
17:11:34.184730616 Child 415 belongs to dev-disk-byx2duuid-ac316750x2da460x2d4127x2dbb66x2d4e71dc6c6b8f.swap
17:11:34.185770760 dev-disk-byx2duuid-ac316750x2da460x2d4127x2dbb66x2d4e71dc6c6b8f.swap swap process exited, code=exited status=0
17:11:34.186728006 dev-disk-byx2duuid-ac316750x2da460x2d4127x2dbb66x2d4e71dc6c6b8f.swap changed activating -> active
17:11:34.189909576 Job dev-disk-byx2duuid-ac316750x2da460x2d4127x2dbb66x2d4e71dc6c6b8f.swap/start finished, result=done
17:11:34.190746451 Started /dev/disk/by-uuid/ac316750-a460-4127-bb66-4e71dc6c6b8f         [ESC[1;32m  OK  ESC[0m]
17:11:34.191834995 Successfully opened /dev/console for logging.
17:11:34.193353524 swap.target changed dead -> active
17:11:34.194001206 Job swap.target/start finished, result=done
17:11:34.194616208 Successfully opened /dev/console for logging.
17:11:34.195357661 Received SIGCHLD from PID 415 (n/a).
17:11:34.196012111 Accepted connection on private bus.
17:11:34.196615698 Accepted connection on private bus.
17:11:34.199264311 Got D-Bus request: org.freedesktop.systemd1.Agent.Released() on /org/freedesktop/systemd1/agent
17:11:34.200442242 Got D-Bus request: org.freedesktop.systemd1.Agent.Released() on /org/freedesktop/systemd1/agent
17:11:34.201098370 console-setup.service: cgroup is empty
17:11:34.202985767 Got D-Bus request: org.freedesktop.DBus.Local.Disconnected() on /org/freedesktop/DBus/Local
17:11:34.205056937 Got D-Bus request: org.freedesktop.DBus.Local.Disconnected() on /org/freedesktop/DBus/Local
17:11:34.211200418 Accepted connection on private bus.
17:11:34.217744309 Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1
17:11:34.218533332 Got D-Bus request: org.freedesktop.DBus.Local.Disconnected() on /org/freedesktop/DBus/Local
17:11:34.219211844 Accepted connection on private bus.
17:11:34.220837791 Got D-Bus request: org.freedesktop.systemd1.Manager.LoadUnit() on /org/freedesktop/systemd1
17:11:34.221822873 Got D-Bus request: org.freedesktop.DBus.Properties.GetAll() on /org/freedesktop/systemd1/unit/samba_2eservice
17:11:34.224857802 Got D-Bus request: org.freedesktop.DBus.Local.Disconnected() on /org/freedesktop/DBus/Local
17:11:34.225533475 Accepted connection on private bus.
17:11:34.226278986 Got D-Bus request: org.freedesktop.systemd1.Manager.ReloadUnit() on /org/freedesktop/systemd1
17:11:34.226965623 Trying to enqueue job samba.service/reload/replace
17:11:34.227602893 Installed new job samba.service/reload-or-start as 119
17:11:34.228361455 Enqueued job samba.service/reload as 119
17:11:34.229022305 Got D-Bus request: org.freedesktop.systemd1.Manager.GetUnit() on /org/freedesktop/systemd1
17:11:34.229675049 Got D-Bus request: org.freedesktop.DBus.Properties.Get() on /org/freedesktop/systemd1/unit/samba_2eservice

-- 
Best regards,
Michael

Message #40 received at 624599@bugs.debian.org (full text, mbox, reply):

From: Michael Biebl <biebl@debian.org>

To: Michael Stapelberg <stapelberg@debian.org>, 624599@bugs.debian.org

Cc: Lennart Poettering <lennart@poettering.net>

Subject: Re: Bug#624599: More debugging

Date: Sun, 14 Oct 2012 20:06:32 +0200

[Message part 1 (text/plain, inline)]

On 14.10.2012 19:21, Michael Stapelberg wrote:
> Hi,
> 
> I can reproduce this problem in a freshly installed VM with systemd
> 44-4, samba 2:3.6.6-3, ifupdown 0.7.2 and "auto eth0" and "iface eth0
> inet dhcp" in /etc/network/interfaces (Using "allow-hotplug eth0"
> instead of "auto eth0" does not trigger the problem for me).
> 
> Note that an easy workaround is to unplug your network cable while
> booting, which will lead to DHCP timeouts and thus not triggering the
> hook.
> 
> Also, my previous mail was wrong: This is not precisely the same issue
> as #635777 (though related).
> 
> I debugged this by unchecking "cable connected" in virtualbox and using
> the same technique as described in my previous mail. I gather from the
> logfiles that networking.service (generated from LSB
> /etc/init.d/networking) is of Type=forking and thus systemd blocks until
> its process exits.
> 
> Now, when you have a network connection, /etc/init.d/networking will
> blockingly get a DHCP lease, then call the hook, which in turn calls
> invoke-rc.d samba reload, which gets diverted to systemctl reload
> samba.service.
> 
> The problem is that systemctl reload blocks by default (unless
> --no-block is given) and thus it waits until systemd actually does the
> reload. However, systemd cannot do that right now, since it is waiting
> for networking.service to complete, thus we’re in a deadlock.
> 
> Summary: systemd blocks on networking.service, networking.service’s
> systemctl blocks on systemd → deadlock.


As discussed on IRC: I think there is a bit more to that then the above
explanation.
If you run "systemctl reload" on a non-running service, it will *not*
block and simply returns immediately. So this can't explain the problem
above.

From past discussions with Lennart, I think the problem is, that systemd
tries to minimize unnecessary actions.

Say during an transaction, a service is started and reloaded.
systemd will try to reorder the service so it can avoid the reload.
I guess in this case this means blocking, until the actual start
happens. And then we indeed get the deadlock.

As my memory is a bit vague here, I've CCed Lennart, since I don't want
to tell nonsense. Lennart, I hope you can chime in here and shed some
light on this problem.

Cheers,
Michael


-- 
Why is it that all of the instruments seeking intelligent life in the
universe are pointed away from Earth?

[signature.asc (application/pgp-signature, attachment)]

Message #45 received at 624599@bugs.debian.org (full text, mbox, reply):

From: Michael Biebl <biebl@debian.org>

To: Michael Stapelberg <stapelberg@debian.org>, 624599@bugs.debian.org, 624599-submitter@bugs.debian.org

Subject: Re: Bug#624599: More debugging

Date: Sun, 14 Oct 2012 23:25:20 +0200

[Message part 1 (text/plain, inline)]

On 14.10.2012 19:21, Michael Stapelberg wrote:
> Hi,
> 
> I can reproduce this problem in a freshly installed VM with systemd
> 44-4, samba 2:3.6.6-3, ifupdown 0.7.2 and "auto eth0" and "iface eth0
> inet dhcp" in /etc/network/interfaces (Using "allow-hotplug eth0"
> instead of "auto eth0" does not trigger the problem for me).

An obversation I made:
If I use "auto eth0", I can reliably trigger the deadlock on boot.
If I change auto to allow-hotplug, the system boots properly, but I get
the 90sec timeout on shutdown.
Both times, the last message is the samba reload.

Michael


-- 
Why is it that all of the instruments seeking intelligent life in the
universe are pointed away from Earth?

[signature.asc (application/pgp-signature, attachment)]

Message #53 received at 624599@bugs.debian.org (full text, mbox, reply):

From: Lennart Poettering <lennart@poettering.net>

To: Michael Biebl <biebl@debian.org>

Cc: Michael Stapelberg <stapelberg@debian.org>, 624599@bugs.debian.org

Subject: Re: Bug#624599: More debugging

Date: Mon, 15 Oct 2012 17:33:01 +0200

On Sun, 14.10.12 20:06, Michael Biebl (biebl@debian.org) wrote:

> > Summary: systemd blocks on networking.service, networking.service’s
> > systemctl blocks on systemd → deadlock.
> 
> 
> As discussed on IRC: I think there is a bit more to that then the above
> explanation.
> If you run "systemctl reload" on a non-running service, it will *not*
> block and simply returns immediately. So this can't explain the problem
> above.
> 
> From past discussions with Lennart, I think the problem is, that systemd
> tries to minimize unnecessary actions.
> 
> Say during an transaction, a service is started and reloaded.
> systemd will try to reorder the service so it can avoid the reload.
> I guess in this case this means blocking, until the actual start
> happens. And then we indeed get the deadlock.
> 
> As my memory is a bit vague here, I've CCed Lennart, since I don't want
> to tell nonsense. Lennart, I hope you can chime in here and shed some
> light on this problem.

systemd only orderes queued jobs against each other. And yes if you have
a service foobar.service ordered after waldo.service, and waldo.service
issues a job for foobar.service and blocks on it, then systemd will
honour the ordering and you might deadlock, indeed. There are various
fixes thinkable: Most likely there should not be any ordering between
the two units, or you could pass --no-block to avoid the problem. There
are even hacks available, such as --ignore-dependencies, but I'd really
not recommend using those...

Lennart

-- 
Lennart Poettering - Red Hat, Inc.

Message #58 received at 624599@bugs.debian.org (full text, mbox, reply):

From: Michael Biebl <biebl@debian.org>

To: Michael Stapelberg <stapelberg@debian.org>, 624599@bugs.debian.org

Subject: Re: Bug#624599: [PATCH] systemd reload during shutdown issue

Date: Tue, 16 Oct 2012 00:15:50 +0200

[Message part 1 (text/plain, inline)]

Small nitpick:

Since you are denying start, reload and restart requests during
shutdown, the debug message

 log_debug("final.target is queued, ignoring reload request");
 dbus_set_error(e, BUS_ERROR_INVALID_JOB_MODE, "final.target is queued,
ignoring reload request");

could be a bit misleading. It might be a good idea to both list the
service, for which the action was denied, and the action. Something like

"final.target is queued, ignoring $action request for $service"

Cheers,
Michael
-- 
Why is it that all of the instruments seeking intelligent life in the
universe are pointed away from Earth?

[signature.asc (application/pgp-signature, attachment)]

Message #63 received at 624599@bugs.debian.org (full text, mbox, reply):

From: Michael Stapelberg <stapelberg@debian.org>

To: Michael Biebl <biebl@debian.org>, 624599@bugs.debian.org

Subject: Re: Bug#624599: [PATCH] systemd reload during shutdown issue

Date: Tue, 16 Oct 2012 10:37:23 +0200

[Message part 1 (text/plain, inline)]

Hi Michael,

Michael Biebl <biebl@debian.org> writes:
> could be a bit misleading. It might be a good idea to both list the
> service, for which the action was denied, and the action. Something like
>
> "final.target is queued, ignoring $action request for $service"
True, fixed.

The new message looks like this:
10:35:37.864754109 final.target is queued, ignoring reload request for unit samba.service

-- 
Best regards,
Michael

[ignore_reload.patch (text/x-diff, attachment)]

Message #68 received at 624599@bugs.debian.org (full text, mbox, reply):

From: Michael Biebl <biebl@debian.org>

To: Lennart Poettering <lennart@poettering.net>, 624599@bugs.debian.org

Cc: Michael Stapelberg <stapelberg@debian.org>

Subject: Re: Bug#624599: More debugging

Date: Wed, 17 Oct 2012 00:23:13 +0200

[Message part 1 (text/plain, inline)]

On 15.10.2012 17:33, Lennart Poettering wrote:
> On Sun, 14.10.12 20:06, Michael Biebl (biebl@debian.org) wrote:
> 
>>> Summary: systemd blocks on networking.service, networking.service’s
>>> systemctl blocks on systemd → deadlock.
>>
>>
>> As discussed on IRC: I think there is a bit more to that then the above
>> explanation.
>> If you run "systemctl reload" on a non-running service, it will *not*
>> block and simply returns immediately. So this can't explain the problem
>> above.
>>
>> From past discussions with Lennart, I think the problem is, that systemd
>> tries to minimize unnecessary actions.
>>
>> Say during an transaction, a service is started and reloaded.
>> systemd will try to reorder the service so it can avoid the reload.
>> I guess in this case this means blocking, until the actual start
>> happens. And then we indeed get the deadlock.
>>
>> As my memory is a bit vague here, I've CCed Lennart, since I don't want
>> to tell nonsense. Lennart, I hope you can chime in here and shed some
>> light on this problem.
> 
> systemd only orderes queued jobs against each other. And yes if you have
> a service foobar.service ordered after waldo.service, and waldo.service
> issues a job for foobar.service and blocks on it, then systemd will
> honour the ordering and you might deadlock, indeed. There are various

Would it be possible to detect such dead lock situations and simply
refuse new requests which would cause a dead lock?
This would make systemd more robust overall.


-- 
Why is it that all of the instruments seeking intelligent life in the
universe are pointed away from Earth?

[signature.asc (application/pgp-signature, attachment)]

Message #73 received at 624599@bugs.debian.org (full text, mbox, reply):

From: Lennart Poettering <lennart@poettering.net>

To: Michael Biebl <biebl@debian.org>

Cc: 624599@bugs.debian.org, Michael Stapelberg <stapelberg@debian.org>

Subject: Re: Bug#624599: More debugging

Date: Tue, 23 Oct 2012 21:03:42 +0200

On Wed, 17.10.12 00:23, Michael Biebl (biebl@debian.org) wrote:

> >> As my memory is a bit vague here, I've CCed Lennart, since I don't want
> >> to tell nonsense. Lennart, I hope you can chime in here and shed some
> >> light on this problem.
> > 
> > systemd only orderes queued jobs against each other. And yes if you have
> > a service foobar.service ordered after waldo.service, and waldo.service
> > issues a job for foobar.service and blocks on it, then systemd will
> > honour the ordering and you might deadlock, indeed. There are various
> 
> Would it be possible to detect such dead lock situations and simply
> refuse new requests which would cause a dead lock?
> This would make systemd more robust overall.

Sure, but this is a bit like solving the halting problem... I fear this
is not really feasible... We thought about this before, but came to no
conclusion, and usually the better fix is to just not to wait
here. After all, and that is kinda key here: what is expressed in the
config file/hook calls *is* simply contradictory...


Lennart

-- 
Lennart Poettering - Red Hat, Inc.

Message #78 received at 624599@bugs.debian.org (full text, mbox, reply):

From: Tollef Fog Heen <tfheen@err.no>

To: Lennart Poettering <lennart@poettering.net>

Subject: Re: Bug#624599: More debugging

Date: Wed, 24 Oct 2012 16:16:37 +0200

]] Lennart Poettering 

> On Wed, 17.10.12 00:23, Michael Biebl (biebl@debian.org) wrote:
> 
> > >> As my memory is a bit vague here, I've CCed Lennart, since I don't want
> > >> to tell nonsense. Lennart, I hope you can chime in here and shed some
> > >> light on this problem.
> > > 
> > > systemd only orderes queued jobs against each other. And yes if you have
> > > a service foobar.service ordered after waldo.service, and waldo.service
> > > issues a job for foobar.service and blocks on it, then systemd will
> > > honour the ordering and you might deadlock, indeed. There are various
> > 
> > Would it be possible to detect such dead lock situations and simply
> > refuse new requests which would cause a dead lock?
> > This would make systemd more robust overall.
> 
> Sure, but this is a bit like solving the halting problem... I fear this
> is not really feasible... We thought about this before, but came to no
> conclusion, and usually the better fix is to just not to wait
> here. After all, and that is kinda key here: what is expressed in the
> config file/hook calls *is* simply contradictory...

No, it's not.  Doing a reload when a service is not started is a no-op,
so I actually think that the reordering done when there is a start
action in the queue is simply wrong, and systemd should simply return
OK.

-- 
Tollef Fog Heen
UNIX is user friendly, it's just picky about who its friends are

Message #83 received at 624599-close@bugs.debian.org (full text, mbox, reply):

From: Michael Biebl <biebl@debian.org>

To: 624599-close@bugs.debian.org

Subject: Bug#624599: fixed in systemd 44-5

Date: Thu, 25 Oct 2012 20:48:20 +0000

Source: systemd
Source-Version: 44-5

We believe that the bug you reported is fixed in the latest version of
systemd, which is due to be installed in the Debian FTP archive.

A summary of the changes between this version and the previous one is
attached.

Thank you for reporting the bug, which will now be closed.  If you
have further comments please address them to 624599@bugs.debian.org,
and the maintainer will reopen the bug report if appropriate.

Debian distribution maintenance software
pp.
Michael Biebl <biebl@debian.org> (supplier of updated systemd package)

(This message was generated automatically at their request; if you
believe that there is a problem with it please contact the archive
administrators by mailing ftpmaster@debian.org)


-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA256

Format: 1.8
Date: Thu, 25 Oct 2012 21:41:23 +0200
Source: systemd
Binary: systemd systemd-sysv libpam-systemd systemd-gui libsystemd-login0 libsystemd-login-dev libsystemd-daemon0 libsystemd-daemon-dev libsystemd-journal0 libsystemd-journal-dev libsystemd-id128-0 libsystemd-id128-dev
Architecture: source amd64
Version: 44-5
Distribution: unstable
Urgency: low
Maintainer: Tollef Fog Heen <tfheen@debian.org>
Changed-By: Michael Biebl <biebl@debian.org>
Description: 
 libpam-systemd - system and service manager - PAM module
 libsystemd-daemon-dev - systemd utility library - development files
 libsystemd-daemon0 - systemd utility library
 libsystemd-id128-0 - systemd 128 bit ID utility library
 libsystemd-id128-dev - systemd 128 bit ID utility library - development files
 libsystemd-journal-dev - systemd journal utility library - development files
 libsystemd-journal0 - systemd journal utility library
 libsystemd-login-dev - systemd login utility library - development files
 libsystemd-login0 - systemd login utility library
 systemd    - system and service manager
 systemd-gui - system and service manager - GUI
 systemd-sysv - system and service manager - SysV links
Closes: 624599 650382 668344 686115 688635 690916
Changes: 
 systemd (44-5) unstable; urgency=low
 .
   * Team upload.
 .
   [ Tollef Fog Heen ]
   * disable killing on entering START_PRE, START, thanks to Michael
     Stapelberg for patch.  This avoids killing VMs run through libvirt
     when restarting libvirtd.  Closes: #688635.
   * Avoid reloading services when shutting down, since that won't work and
     makes no sense.  Thanks to Michael Stapelberg for the patch.
     Closes: #624599.
   * Try to determine which init scripts support the reload action
     heuristically.  Closes: #686115, #650382.
 .
   [ Michael Biebl ]
   * Update Vcs-* fields, the Git repository is hosted on alioth now. Set the
     default branch to "debian".
   * Avoid reload and (re)start requests during early boot which can lead to
     deadlocks.  Closes: #624599
   * Make systemd-cgroup work even if not all cgroup mounts are available on
     startup.  Closes: #690916
   * Fix typos in the systemd.path and systemd.unit man page.  Closes: #668344
   * Add watch file to track new upstream releases.
Checksums-Sha1: 
 a2934df2b077f3dc09eb55424d867549b03b4724 2882 systemd_44-5.dsc
 66303b45b773b49f5aac668f34584e3ae6608ac4 26277 systemd_44-5.debian.tar.gz
 b32a530bb3d5dfbdb7936de839dff1c9336fa13f 1445478 systemd_44-5_amd64.deb
 f0ae2ee1dc4147b75224fe4a1811870fe70e5410 14026 systemd-sysv_44-5_amd64.deb
 fcd6bee8733ec6965abbbb1a7bb8af57a96e11fe 31476 libpam-systemd_44-5_amd64.deb
 b0899be717965874ec6049ceff25682b78781238 65896 systemd-gui_44-5_amd64.deb
 bcda472ef70290c8ccecc968e2c86137aed41578 28218 libsystemd-login0_44-5_amd64.deb
 cce8cdea872aecf214db4284f96fb225c92bedbf 10766 libsystemd-login-dev_44-5_amd64.deb
 123f052fb906a7bdda291efcba573ead3e42f40d 13802 libsystemd-daemon0_44-5_amd64.deb
 699117f66298737eabc7a6c7d9ead9d8773b0d52 13244 libsystemd-daemon-dev_44-5_amd64.deb
 730bf11b0a8a6e3a5339ea77fe7970a1516689c6 41360 libsystemd-journal0_44-5_amd64.deb
 c9f4c37c61a63df800beb9ddd4a6f790db62599e 10372 libsystemd-journal-dev_44-5_amd64.deb
 ed1288c5e58ecb201f017681d4c758c46788bea6 19916 libsystemd-id128-0_44-5_amd64.deb
 d1ec2234116fe08cf84ffb0985ebb233e73ea755 9740 libsystemd-id128-dev_44-5_amd64.deb
Checksums-Sha256: 
 a4af9bb9407313339b51717242f7f010761933c32767a03e7e4ac99d48b12e63 2882 systemd_44-5.dsc
 3c0a6fc22cd9656e3bb039b4e12f95899e2702567ebf9da6294c9bb3e83a9b57 26277 systemd_44-5.debian.tar.gz
 21da64797703fe3de4eacaf092e1b69e96d44c94932599903b93d9e665fa4ca2 1445478 systemd_44-5_amd64.deb
 37014d5338b1a19b17b877fc9d436d6f30ad3d9692aae08b2485142ff8b7747f 14026 systemd-sysv_44-5_amd64.deb
 282b29ee4d6015e3f2d0a4e56b99fc763600c7aeed143073a4206cc79a55e625 31476 libpam-systemd_44-5_amd64.deb
 1975c1c2b63e181285697fedd0a5e90ebcc580ecf11506123c27a1df6e236a2e 65896 systemd-gui_44-5_amd64.deb
 8215c858b6235e0ca81d1f2ab1788d4d415f9438dc7148c97f196b293ca7a012 28218 libsystemd-login0_44-5_amd64.deb
 c3bb0db8c22fde5fe198368ab15801bd9ef1da2ab2b92f87fa0071325bbe83d6 10766 libsystemd-login-dev_44-5_amd64.deb
 864de664fcd06e531fad0cf6f3da2538eeb6771ea1299f30ee3aa15599f17453 13802 libsystemd-daemon0_44-5_amd64.deb
 8ad7b09dbbeef7b9c452d7407afb406c6254f2996aa910f0fc8f262b241c4407 13244 libsystemd-daemon-dev_44-5_amd64.deb
 8bb0408bba9efee4202fb0fdb2e981335604cc57522f34275ef014987e231e45 41360 libsystemd-journal0_44-5_amd64.deb
 cf6cde74256219132152a81b29938125a82f90523ad434df12fa85cafbb72304 10372 libsystemd-journal-dev_44-5_amd64.deb
 39c04d5d87708657d1ef16e324b187e7b4a361aec214ee69e2b0d52e2554228b 19916 libsystemd-id128-0_44-5_amd64.deb
 05c16ce7940f1521d2623f727a353ec38bb2cd2e90471f9c6167db3ef47aba76 9740 libsystemd-id128-dev_44-5_amd64.deb
Files: 
 8565480f819ad09a0ff049a7d3e5ef43 2882 admin extra systemd_44-5.dsc
 81b74e50b9075bfc72474e1f7c4040b3 26277 admin extra systemd_44-5.debian.tar.gz
 7b26f209e32b22cfda1138cec2bd98eb 1445478 admin extra systemd_44-5_amd64.deb
 07aeec9fede157c732660e44806441a1 14026 admin extra systemd-sysv_44-5_amd64.deb
 3b516bf70a1ae2d88d34e3ab4790a1fc 31476 admin extra libpam-systemd_44-5_amd64.deb
 99c4618858e3deed96e3ceff9e190da6 65896 admin extra systemd-gui_44-5_amd64.deb
 7b5f196e2e370aa2b682d25a831bb1b3 28218 libs extra libsystemd-login0_44-5_amd64.deb
 658e68371286a6fde6eabcf9a933a0b5 10766 libdevel extra libsystemd-login-dev_44-5_amd64.deb
 31b043a971ae61ffcbf4d97ae6d895bf 13802 libs extra libsystemd-daemon0_44-5_amd64.deb
 4801c1b269bb6fd8fc09f22afe1d0987 13244 libdevel extra libsystemd-daemon-dev_44-5_amd64.deb
 138c438ff63df661aecd3e9ece076407 41360 libs extra libsystemd-journal0_44-5_amd64.deb
 6bf3cc427487c04f4c994c314d25c4f4 10372 libdevel extra libsystemd-journal-dev_44-5_amd64.deb
 23fb0148f3544f8988f78836713df09d 19916 libs extra libsystemd-id128-0_44-5_amd64.deb
 c23cf694cbd5c977d637decf5e980eba 9740 libdevel extra libsystemd-id128-dev_44-5_amd64.deb

-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.12 (GNU/Linux)

iQIcBAEBCAAGBQJQiZzPAAoJEGrh3w1gjyLcY6YP+gJVs/l2vKdqESnqNjTg+1y/
SIJfF3PABF2Jo5/0xyS+mtRVkp5mF//8FP1r96rJtk7mvclAOvdmYS/26lZg214x
qfkgwN5p+QnuFWpdlwt9ijfK5DoBMunFB9bOtQJjUoOrAfGiE36wgesfClXD5yJ+
anT7P7Pcfas9ZVXa10PV6evmXBTLXt7v+/NYVL+TI0sTXY8yhzCUqD08wg0wIsFq
kflFYqtbr20xbancXClRmC8HwF75kCK+I6qzbU6rJUHRDoW1Xp0LkCO9S1UlaJj9
YVsuw6gCpym9sp4Q5j7z6JNFK/AN3FvPbPnAvA/L10ESJwtEo5S+vMmq5C7B4f9G
1nh05aKDIHre/AO50lPG8fQF8M5+appNEb6ccZ72sgzYO6Dh8LgfxZZtuVC2P9jb
r2DCPaALEqwT87QLNsV8VC1VjX2QZuwiOwHeJhnYjc5PWU0NpMPwFxFALgbCz/v2
p2nvGeZp3whhhYAx+91yNrAAeAvv4OF0M1wvXhsf0KIkqAWsXuTSmaPvxHDS02SG
t3A/yBime0XrU0G5DmEsfqGa0iRgNBd7GBYFgbndB9+CCIBAqDK4kUupEFiSdCU3
1q0kzgvIt0XOGnOkrUoxK65S+vwVtVMib8DY1E7u3wYMuCeLnngg7MV8AZJjz5t0
1XZjarS5VXMthQszuwhM
=0dyv
-----END PGP SIGNATURE-----

Send a report that this bug log contains spam.