Debian Bug report logs - #635777
90-seconds delay on reboot/shutdown when postfix is installed

Toggle useless messages

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

From: Bernhard Schmidt <berni@birkenwald.de>

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

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

Date: Thu, 28 Jul 2011 22:02:36 +0200

Package: systemd
Version: 29-1
Severity: minor
Tags: sid

Hi,

I have a weird issue with systemd I cannot quite grasp. I think this is a bug,
but maybe someone more experienced can shed some light on it.

My new Mailserver-to-be is a KVM VM (on a Squeeze host), that has been installed
as a minimal squeeze system, then fully upgraded to wheezy, and then added sid 
with a lower preference to be able to install systemd (basically util-linux, udev
and systemd come from unstable). 

After installing Postfix each shutdown of the VM is delayed by 90 seconds. I've
made a stab at debugging and I think there could be a systemd bug involved.

When looking at the process table while the system is shutting down, it is
spending the 90 seconds with the following processes:

root       922  0.0  0.2 124720  2096 pts/0    Ss   21:39   0:00 -bash
root       986  0.0  0.1  19000  1012 ?        Ss   21:40   0:00 /lib/systemd/systemd-initctl
root       987  0.0  0.0   4060   544 ?        Ss   21:40   0:00 /sbin/ifdown eth0
root       988  0.0  0.0   4144   580 ?        S    21:40   0:00 /bin/sh -c run-parts  /etc/network/if-down.d
root       989  0.0  0.0   4044   576 ?        S    21:40   0:00 run-parts /etc/network/if-down.d
root       991  0.0  0.0   4144   580 ?        S    21:40   0:00 /bin/sh -e /etc/network/if-down.d/postfix
root       998  0.0  0.0   4144   656 ?        S    21:40   0:00 /bin/sh -e /etc/init.d/postfix reload
root      1125  0.0  0.0  16676   652 ?        Ss   21:40   0:00 /lib/systemd/systemd-kmsg-syslogd
root      1326  0.0  0.1  19116   976 ?        S    21:40   0:00 /bin/systemctl reload postfix.service

basically it is spending 90 seconds in systemctl reload postfix.service,
which is executed by /etc/network/if-down.d/postfix through redirection
of /etc/init.d/postfix. 

systemctl at this point:
root@mail:~# systemctl
UNIT                      LOAD   ACTIVE       SUB       JOB    DESCRIPTION
dev-hugepages.automount   loaded active       waiting          Huge Pages File System Automount Point
dev-mqueue.automount      loaded active       waiting          POSIX Message Queue File System Automount Point
lib-init-rw.automount     loaded active       waiting          Debian early rw Automount Point
proc-sys...misc.automount loaded active       waiting          Arbitrary Executable File Formats File System Automount Point
sys-kern...ebug.automount loaded active       waiting          Debug File System Automount Point
sys-kern...rity.automount loaded active       waiting          Security File System Automount Point
sys-devi...ock-sr0.device loaded active       plugged          QEMU_DVD-ROM
sys-devi...et-eth0.device loaded active       plugged          Virtio network device
sys-devi...da-vda1.device loaded active       plugged          /sys/devices/pci0000:00/0000:00:04.0/virtio1/block/vda/vda1
sys-devi...da-vda2.device loaded active       plugged          /sys/devices/pci0000:00/0000:00:04.0/virtio1/block/vda/vda2
sys-devi...da-vda5.device loaded active       plugged          /sys/devices/pci0000:00/0000:00:04.0/virtio1/block/vda/vda5
sys-devi...ock-vda.device loaded active       plugged          /sys/devices/pci0000:00/0000:00:04.0/virtio1/block/vda
sys-devi...y-ttyS0.device loaded active       plugged          /sys/devices/platform/serial8250/tty/ttyS0
sys-devi...y-ttyS1.device loaded active       plugged          /sys/devices/platform/serial8250/tty/ttyS1
sys-devi...y-ttyS2.device loaded active       plugged          /sys/devices/platform/serial8250/tty/ttyS2
sys-devi...y-ttyS3.device loaded active       plugged          /sys/devices/platform/serial8250/tty/ttyS3
sys-devi...ty-tty0.device loaded active       plugged          /sys/devices/virtual/tty/tty0
sys-devi...ty-tty1.device loaded active       plugged          /sys/devices/virtual/tty/tty1
sys-devi...y-tty10.device loaded active       plugged          /sys/devices/virtual/tty/tty10
sys-devi...y-tty11.device loaded active       plugged          /sys/devices/virtual/tty/tty11
sys-devi...y-tty12.device loaded active       plugged          /sys/devices/virtual/tty/tty12
sys-devi...ty-tty2.device loaded active       plugged          /sys/devices/virtual/tty/tty2
sys-devi...ty-tty3.device loaded active       plugged          /sys/devices/virtual/tty/tty3
sys-devi...ty-tty4.device loaded active       plugged          /sys/devices/virtual/tty/tty4
sys-devi...ty-tty5.device loaded active       plugged          /sys/devices/virtual/tty/tty5
sys-devi...ty-tty6.device loaded active       plugged          /sys/devices/virtual/tty/tty6
sys-devi...ty-tty7.device loaded active       plugged          /sys/devices/virtual/tty/tty7
sys-devi...ty-tty8.device loaded active       plugged          /sys/devices/virtual/tty/tty8
sys-devi...ty-tty9.device loaded active       plugged          /sys/devices/virtual/tty/tty9
-.mount                   loaded active       mounted          /
media.mount               loaded active       mounted   stop   Media Directory
systemd-...d-console.path loaded active       waiting   stop   Dispatch Password Requests to Console Directory Watch
systemd-...word-wall.path loaded active       waiting   stop   Forward Password Requests to Wall Directory Watch
console-setup.service     loaded active       exited           LSB: Set console font and keymap
ifup@eth0.service         loaded deactivating stop      stop   Start ifup for eth0
ifupdown-clean.service    loaded active       exited           LSB: Clean old interface status info during boot.
ifupdown.service          loaded active       exited    stop   LSB: Prepare the system for taking up interfaces.
kbd.service               loaded active       exited           LSB: Prepare console
keyboard-setup.service    loaded active       exited           LSB: Set preliminary keymap
mountoverflowtmp.service  loaded active       exited           LSB: mount emergency /tmp.
networking.service        loaded active       exited    stop   LSB: Raise network interfaces.
postfix.service           loaded inactive     dead      reload LSB: start and stop the Postfix Mail Transport Agent
reboot.service            loaded inactive     dead      start  Reboot
remount-rootfs.service    loaded active       exited    stop   Remount Root FS
ssh.service               loaded failed       failed           LSB: OpenBSD Secure Shell server
systemd-initctl.service   loaded active       running          /dev/initctl Compatibility Daemon
systemd-...yslogd.service loaded active       running          Syslog Kernel Log Buffer Bridge
systemd-logger.service    loaded active       running          Stdio Syslog Bridge
systemd-...s-load.service loaded active       exited    stop   Load Kernel Modules
systemd-...pi-vfs.service loaded active       exited    stop   Remount API VFS
systemd-sysctl.service    loaded active       exited    stop   Apply Kernel Variables
systemd-...-setup.service loaded active       exited           Recreate Volatile Files and Directories
systemd-...utdown.service loaded inactive     dead      start  Notify Audit System and Update UTMP about System Shutdown
udev-trigger.service      loaded active       exited           udev Coldplug all Devices
udev.service              loaded active       running          udev Kernel Device Manager
syslog.socket             loaded active       running          Syslog Socket
systemd-initctl.socket    loaded active       running          /dev/initctl Compatibility Named Pipe
systemd-logger.socket     loaded active       running          Stdio Syslog Bridge Socket
systemd-shutdownd.socket  loaded active       listening        Delayed Shutdown Socket
udev-control.socket       loaded active       listening        udev Control Socket
udev-kernel.socket        loaded active       listening        udev Kernel Socket
dev-disk...68bd493be.swap loaded active       active    stop   /dev/disk/by-uuid/e7e860ca-18ba-4aa3-a495-f9968bd493be
basic.target              loaded active       active    stop   Basic System
final.target              loaded inactive     dead      start  Final Step
local-fs.target           loaded active       active    stop   Local File Systems
reboot.target             loaded inactive     dead      start  Reboot
shutdown.target           loaded inactive     dead      start  Shutdown
sockets.target            loaded active       active    stop   Sockets
swap.target               loaded active       active    stop   Swap
sysinit.target            loaded active       active    stop   System Initialization
syslog.target             loaded active       active           Syslog
umount.target             loaded inactive     dead      start  Unmount All Filesystems
systemd-...es-clean.timer loaded active       waiting   stop   Daily Cleanup of Temporary Directories

I think it is a systemd bug, because I have found two ways to solve
this problem:

a) add export _SYSTEMCTL_SKIP_REDIRECT="true" to /etc/network/if-down.d/postfix 
   to avoid the systemctl redirection in the initscript. Which makes me believe
   it is not the code in the initscript itself that is creating this delay

b) add sleep 1 to the top of this script.

I think the problem is a race condition. I think systemd treats postfix.service
as stopped and continues to deactivating ifup@eth0.service. Which executes the ifdown-
script. At least at the beginning of this script postfix must still be running, 
otherwise it would not execute postfix reload at all. It seems that issuing reload 
on a service that has just died (or is in process of dying) could cause this problem.

Do you need any more information to reproduce this? 

Bernhard

-- System Information:
Debian Release: wheezy/sid
  APT prefers testing
  APT policy: (900, 'testing'), (800, 'unstable')
Architecture: amd64 (x86_64)

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

Versions of packages systemd depends on:
ii  initscripts                2.88dsf-13.11 scripts for initializing and shutt
ii  libaudit0                  1.7.13-1.2    Dynamic library for security audit
ii  libc6                      2.13-10       Embedded GNU C Library: Shared lib
ii  libcap2                    1:2.21-2      support for getting/setting POSIX.
ii  libcryptsetup1             2:1.3.0-3     libcryptsetup shared library
ii  libdbus-1-3                1.4.12-5      simple interprocess messaging syst
ii  libpam0g                   1.1.3-2       Pluggable Authentication Modules l
ii  libselinux1                2.0.98-1.1    SELinux runtime shared libraries
ii  libudev0                   172-1         libudev shared library
ii  libwrap0                   7.6.q-21      Wietse Venema's TCP wrappers libra
ii  udev                       172-1         /dev/ and hotplug management daemo
ii  util-linux                 2.19.1-4      Miscellaneous system utilities

Versions of packages systemd recommends:
pn  libpam-systemd                <none>     (no description available)

Versions of packages systemd suggests:
ii  python                        2.6.7-1    interactive high-level object-orie
pn  systemd-gui                   <none>     (no description available)

-- no debconf information

Message #16 received at 635777@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 #21 received at 635777@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 #26 received at 635777@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 635777-done@bugs.debian.org (full text, mbox, reply):

From: Michael Biebl <biebl@debian.org>

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

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

Date: Fri, 26 Oct 2012 07:26:25 +0200

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

Version: 44-5

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: #635777.
  * 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.

 -- Michael Biebl <biebl@debian.org>  Thu, 25 Oct 2012 21:41:23 +0200

-- 
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)]

Send a report that this bug log contains spam.