[systemd-devel] shutdown delayed by failure to start a service
Felix Miata
mrmazda at earthlink.net
Wed Jun 15 02:36:25 UTC 2016
Lennart Poettering composed on 2016-05-30 17:37 (UTC+0200):
> Felix Miata wrote:
>> Lennart Poettering composed on 2016-05-29 18:40 (UTC+0200):
>> >Felix Miata wrote:
>> >>The message I see is equivalent in form as during boot, e.g. when a
>> >>filesystem not noauto in fstab is to be mounted but cannot be found, so a
>> >>delay of typically 90sec, but sometimes much longer, occurs. Mount
>> >>specification mistyped or a subsequently changed volume label, or similarly
>> >>a change of filesystem UUID should be an easy enough way to observe what
>> >>I've not infrequently seen, though the cause(s) of the more irritating
>> >>shutdown delays isn't coming to mind ATM. If this was something I had a
>> >>reliable recreate scenario for I'd have filed a bug somewhere by now, likely
>> >>at least a year ago.
>> >Well, we put a timeout of 90s on *everything* systemd starts or
>> >stops. Hence, saying that you see some 90s timeout just means
>> >*something* isn't finishing as quickly as it should, with exactly zero
>> >information about what that something might be...
>> Now that I know this isn't something familiar to you, I'll be on the watch
>> to collect specifics to report next time I encounter it. Will there be a
>> specific journalctl option to use at that time, or will -b do it?
> "journalctl -b" shows you everything that happened during your current
> boot. If you are trying to find log data generated during shutdown
> this probably won't give you what you want, as you probably want the
> data from the previous boot, not the current one, i.e. "journalctl
> -b-1" is what you want...
Caught one by journal. I had forgotten to edit fstab after some partition shuffling.
Old/unchanged fstab (excerpt):
LABEL=2st17f24 /disks/f24 ext4 noatime,nofail 1 2
# blkid /dev/sda17 /dev/sda21
/dev/sda17: LABEL="2st17f25" UUID="bcb777c0-2283-41f8-a345-30356d7f253e" TYPE="ext4" PTTYPE="dos" PARTUUID="0051ea28-11"
/dev/sda21: LABEL="2st21f24" UUID="98b1d584-6a0f-4b02-8dd4-e47f11ab994a" TYPE="ext4" PTTYPE="dos" PARTUUID="0051ea28-15"
Subsequently repaired fstab (excerpt):
LABEL=2st17f25 /disks/f25 ext4 noatime,nofail 0 0
LABEL=2st21f24 /disks/f24 ext4 noatime,nofail 0 0
# uname -a
Linux g5eas 3.16.7-35-desktop #1 SMP PREEMPT Sun Feb 7 17:32:21 UTC 2016 (832c776) x86_64 x86_64 x86_64 GNU/Linux
# zypper se -si | egrep 'systemd|udev'
i | libgudev-1_0-0 | package | 210.1463730809.e37fc98-25.40.2 | x86_64 | Update
i | libudev1 | package | 210.1463730809.e37fc98-25.40.2 | x86_64 | Update
i | python-pyudev | package | 0.16.1-9.1.5 | noarch | OSS
i | systemd | package | 210.1463730809.e37fc98-25.40.2 | x86_64 | Update
i | systemd-bash-completion | package | 210.1463730809.e37fc98-25.40.2 | noarch | Update
i | systemd-logger | package | 210.1463730809.e37fc98-25.40.2 | x86_64 | Update
i | systemd-presets-branding-openSUSE | package | 0.3.0-12.7.1 | noarch | Update
i | systemd-sysvinit | package | 210.1463730809.e37fc98-25.40.2 | x86_64 | Update
i | udev | package | 210.1463730809.e37fc98-25.40.2 | x86_64 | Update
i | util-linux-systemd | package | 2.25.1-20.1 | x86_64 | Update
# journalctl -b -1 | tail -n55
Jun 14 22:14:21 g5eas systemd[1]: Stopping Apply Kernel Variables...
Jun 14 22:14:21 g5eas systemd[1]: Stopped Apply Kernel Variables.
Jun 14 22:14:21 g5eas systemd[1]: Stopping Setup Virtual Console...
Jun 14 22:14:21 g5eas systemd[1]: Stopping Load Kernel Modules...
Jun 14 22:14:21 g5eas systemd[1]: Stopped Load Kernel Modules.
Jun 14 22:14:21 g5eas systemd[1]: Stopping Encrypted Volumes.
Jun 14 22:14:21 g5eas systemd[1]: Stopped target Encrypted Volumes.
Jun 14 22:14:21 g5eas systemd[1]: Stopping Swap.
Jun 14 22:14:21 g5eas systemd[1]: Deactivating swap /dev/sda7...
Jun 14 22:14:21 g5eas systemd[1]: Deactivating swap /dev/sda7...
Jun 14 22:14:21 g5eas systemd[1]: Deactivating swap /dev/sda7...
Jun 14 22:14:21 g5eas systemd[1]: Deactivating swap /dev/sda7...
Jun 14 22:14:21 g5eas systemd[1]: Deactivating swap /dev/sda7...
Jun 14 22:14:21 g5eas systemd[1]: Stopping Update UTMP about System Reboot/Shutdown...
Jun 14 22:14:21 g5eas systemd[1]: Stopped Entropy Daemon based on the HAVEGE algorithm.
Jun 14 22:14:21 g5eas systemd[1]: Stopped LSB: Set default boot entry if called.
Jun 14 22:14:21 g5eas systemd[1]: Stopping Load/Save Random Seed...
Jun 14 22:14:21 g5eas haveged[483]: haveged: Stopping due to signal 15
Jun 14 22:14:21 g5eas haveged[483]: haveged starting up
Jun 14 22:14:21 g5eas systemd[1]: Deactivated swap /dev/disk/by-path/pci-0000:00:1f.2-scsi-0:0:0:0-part7.
Jun 14 22:14:21 g5eas systemd[1]: Deactivated swap /dev/disk/by-path/pci-0000:00:1f.2-ata-1.0-part7.
Jun 14 22:14:21 g5eas systemd[1]: Deactivated swap /dev/disk/by-id/scsi-SATA_ST3200822AS_3LJ22WE0-part7.
Jun 14 22:14:21 g5eas systemd[1]: Deactivated swap /dev/disk/by-id/scsi-1ATA_ST3200822AS_3LJ22WE0-part7.
Jun 14 22:14:21 g5eas systemd[1]: Deactivated swap /dev/disk/by-id/scsi-0ATA_ST3200822AS_3LJ22WE0-part7.
Jun 14 22:14:21 g5eas systemd[1]: Deactivated swap /dev/disk/by-id/ata-ST3200822AS_3LJ22WE0-part7.
Jun 14 22:14:21 g5eas systemd[1]: Deactivated swap /dev/disk/by-label/2st07swapper.
Jun 14 22:14:21 g5eas systemd[1]: Deactivated swap /dev/sda7.
Jun 14 22:14:21 g5eas systemd[1]: Starting Unmount All Filesystems.
Jun 14 22:14:21 g5eas systemd[1]: Reached target Unmount All Filesystems.
Jun 14 22:14:21 g5eas systemd[1]: Stopping Create Volatile Files and Directories...
Jun 14 22:14:21 g5eas systemd[1]: Stopped Create Volatile Files and Directories.
Jun 14 22:14:21 g5eas systemd[1]: Stopping Local File Systems.
Jun 14 22:14:21 g5eas systemd[1]: Stopped target Local File Systems.
Jun 14 22:14:21 g5eas systemd[1]: Stopping Local File Systems (Pre).
Jun 14 22:14:21 g5eas systemd[1]: Stopped target Local File Systems (Pre).
Jun 14 22:14:21 g5eas systemd[1]: Stopped Load/Save Random Seed.
Jun 14 22:14:21 g5eas systemd[1]: Stopping Remount Root and Kernel File Systems...
Jun 14 22:14:21 g5eas systemd[1]: Stopped Remount Root and Kernel File Systems.
Jun 14 22:14:54 g5eas systemd[1]: Job dev-disk-by\x2dlabel-2st17f24.device/start timed out.
Jun 14 22:14:54 g5eas systemd[1]: Timed out waiting for device dev-disk-by\x2dlabel-2st17f24.device.
Jun 14 22:14:54 g5eas systemd[1]: Dependency failed for File System Check on /dev/disk/by-label/2st17f24.
Jun 14 22:14:54 g5eas systemd[1]: Starting Shutdown.
Jun 14 22:14:54 g5eas systemd[1]: Reached target Shutdown.
Jun 14 22:14:54 g5eas systemd[1]: Starting /etc/init.d/halt.local Compatibility...
Jun 14 22:14:54 g5eas systemd[1]: Started /etc/init.d/halt.local Compatibility.
Jun 14 22:14:54 g5eas systemd[1]: Starting Final Step.
Jun 14 22:14:54 g5eas systemd[1]: Reached target Final Step.
Jun 14 22:14:54 g5eas systemd[1]: Starting Reboot...
Jun 14 22:14:54 g5eas systemd[1]: Shutting down.
Jun 14 22:14:54 g5eas systemd[1]: Hardware watchdog 'iTCO_wdt', version 0
Jun 14 22:14:54 g5eas systemd[1]: Set hardware watchdog to 10min.
Jun 14 22:14:54 g5eas kernel: watchdog watchdog0: watchdog did not stop!
Jun 14 22:14:55 g5eas systemd-shutdown[1]: Sending SIGTERM to remaining processes...
Jun 14 22:14:54 g5eas rpcbind[387]: rpcbind terminating on signal. Restart with "rpcbind -w"
Jun 14 22:14:55 g5eas systemd-journal[358]: Journal stopped
> That said, the journal itself is also terminated at shutdown. It's
> terminated quite late, but it might happen that something that also
> runs pretty late isn't covered anymore. This is harder to debug, and
> documented here:
> https://freedesktop.org/wiki/Software/systemd/Debugging/#index2h1
--
"The wise are known for their understanding, and pleasant
words are persuasive." Proverbs 16:21 (New Living Translation)
Team OS/2 ** Reg. Linux User #211409 ** a11y rocks!
Felix Miata *** http://fm.no-ip.com/
More information about the systemd-devel
mailing list