90-second timeout during boot -- interaction between systemd and encrypted disk with LVM root/swap/home
In my continuing quest for enough understanding of systemd to be able to actually use it in real-life situations, I’ve set up a VM running the latest Jessie release. In the spirit of experimentation, I set it up with root, swap and home as LVs on an encrypted PV. In a real-world situation, I’d have the key for the encrypted PV on a USB-stick, so I gave the VM a small (1GB) ext2 disk with just a key file on it. The /etc/crypttab file looks like this:
sda5_crypt UUID=e2bd09e9-9e01-484a-99f7-9a0b5d8a2bc3 /dev/disk/by-label/KEY:/key luks,keyscript=/lib/cryptsetup/scripts/passdev
It boots all OK except that there is a ~90 second delay while it looks for the key file… Anybody know what’s going on? And what to do about it?
I have a Wheezy system (without systemd) that has a similar setup. I don’t get this kind of delay there.
The attachment is an excerpt from the systemd journal that shows the behavior. The delay and timeout occur between 18:54:10 to 18:55:39.
NOTE: the root and /home filesystems have already been fsck’ed and mount’ed *well before* the time-out occurs, so it *is* finding the key file.
Enjoy!
Rick
PS: As always, I’m happy to RTFM — if someone is kind enough to point me at the FM.
Jul 27 18:54:09 jessie systemd-journal[253]: Journal started
Jul 27 18:54:09 jessie systemd[1]: Starting Apply Kernel Variables...
Jul 27 18:54:09 jessie systemd[1]: Starting Dispatch Password Requests to Console Directory Watch.
Jul 27 18:54:09 jessie systemd[1]: Started Dispatch Password Requests to Console Directory Watch.
Jul 27 18:54:09 jessie systemd[1]: Starting Paths.
Jul 27 18:54:09 jessie systemd[1]: Reached target Paths.
Jul 27 18:54:09 jessie systemd[1]: Mounting Debug File System...
Jul 27 18:54:09 jessie systemd[1]: Expecting device dev-disk-by\x2duuid-e2bd09e9\x2d9e01\x2d484a\x2d99f7\x2d9a0b5d8a2bc3.device...
Jul 27 18:54:09 jessie systemd[1]: Expecting device dev-mapper-sda5_crypt.device...
Jul 27 18:54:09 jessie systemd[1]: Expecting device dev-disk-by\x2dlabel-KEY:-key.device...
Jul 27 18:54:09 jessie systemd-modules-load[250]: Inserted module 'fuse'
Jul 27 18:54:09 jessie systemd[1]: Starting Create list of required static device nodes for the current kernel...
Jul 27 18:54:09 jessie systemd[1]: Starting File System Check on Root Device...
Jul 27 18:54:09 jessie systemd[1]: Starting udev Kernel Socket.
Jul 27 18:54:09 jessie systemd[1]: Listening on udev Kernel Socket.
Jul 27 18:54:09 jessie systemd[1]: Starting udev Control Socket.
Jul 27 18:54:09 jessie systemd[1]: Listening on udev Control Socket.
Jul 27 18:54:09 jessie systemd[1]: Starting udev Coldplug all Devices...
Jul 27 18:54:09 jessie systemd[1]: Mounting Temporary Directory...
Jul 27 18:54:09 jessie systemd[1]: tmp.mount: Directory /tmp to mount over is not empty, mounting anyway.
Jul 27 18:54:09 jessie systemd[1]: Expecting device dev-disk-by\x2duuid-6cb9fa29\x2d8ee6\x2d493c\x2d907b\x2de508662f2e1a.device...
Jul 27 18:54:09 jessie systemd[1]: Starting Root Slice.
Jul 27 18:54:09 jessie systemd[1]: Created slice Root Slice.
Jul 27 18:54:09 jessie systemd[1]: Starting User and Session Slice.
Jul 27 18:54:09 jessie systemd[1]: Created slice User and Session Slice.
Jul 27 18:54:09 jessie systemd[1]: Starting System Slice.
Jul 27 18:54:09 jessie systemd[1]: Created slice System Slice.
Jul 27 18:54:09 jessie systemd[1]: Starting system-getty.slice.
Jul 27 18:54:09 jessie systemd[1]: Created slice system-getty.slice.
Jul 27 18:54:09 jessie systemd[1]: Starting Slices.
Jul 27 18:54:09 jessie systemd[1]: Reached target Slices.
Jul 27 18:54:09 jessie systemd[1]: Expecting device dev-mapper-jessie\x2d\x2dvg\x2dhome.device...
Jul 27 18:54:09 jessie systemd[1]: Started Load Kernel Modules.
Jul 27 18:54:09 jessie systemd[1]: Mounted Huge Pages File System.
Jul 27 18:54:09 jessie systemd[1]: Mounted POSIX Message Queue File System.
Jul 27 18:54:09 jessie systemd[1]: Started Apply Kernel Variables.
Jul 27 18:54:09 jessie systemd[1]: Mounted Debug File System.
Jul 27 18:54:09 jessie systemd[1]: Started Create list of required static device nodes for the current kernel.
Jul 27 18:54:09 jessie systemd[1]: Mounted Temporary Directory.
Jul 27 18:54:09 jessie systemd[1]: Starting Create static device nodes in /dev...
Jul 27 18:54:09 jessie systemd[1]: Mounted Configuration File System.
Jul 27 18:54:09 jessie systemd[1]: Mounting FUSE Control File System...
Jul 27 18:54:09 jessie systemd[1]: Started Create static device nodes in /dev.
Jul 27 18:54:09 jessie systemd[1]: Mounted FUSE Control File System.
Jul 27 18:54:09 jessie systemd[1]: Started udev Coldplug all Devices.
Jul 27 18:54:09 jessie systemd[1]: Starting udev Wait for Complete Device Initialization...
Jul 27 18:54:09 jessie systemd[1]: Starting udev Kernel Device Manager...
Jul 27 18:54:09 jessie systemd-fsck[264]: ROOT: clean, 111250/273632 files, 849883/1092608 blocks
Jul 27 18:54:09 jessie systemd[1]: Started udev Kernel Device Manager.
Jul 27 18:54:09 jessie systemd[1]: Starting LSB: Set preliminary keymap...
Jul 27 18:54:09 jessie systemd[1]: Starting LSB: Tune IDE hard disks...
Jul 27 18:54:09 jessie systemd-udevd[277]: starting version 208
Jul 27 18:54:09 jessie systemd[1]: Started File System Check on Root Device.
Jul 27 18:54:09 jessie hdparm[279]: Setting parameters of disc: (none).
Jul 27 18:54:09 jessie systemd[1]: Started LSB: Tune IDE hard disks.
Jul 27 18:54:09 jessie kernel: input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input3
Jul 27 18:54:09 jessie kernel: ACPI: Power Button [PWRF]
Jul 27 18:54:09 jessie kernel: ACPI: AC Adapter [ACAD] (on-line)
Jul 27 18:54:09 jessie kernel: shpchp: Standard Hot Plug PCI Controller Driver version: 0.4
Jul 27 18:54:09 jessie kernel: parport_pc 00:08: reported by Plug and Play ACPI
Jul 27 18:54:09 jessie kernel: parport0: PC-style at 0x378, irq 7 [PCSPP,TRISTATE]
Jul 27 18:54:09 jessie kernel: vmw_vmci 0000:00:07.7: Found VMCI PCI device at 0x11080, irq 16
Jul 27 18:54:09 jessie kernel: vmw_vmci 0000:00:07.7: Using capabilities 0xc
Jul 27 18:54:09 jessie kernel: vmw_vmci 0000:00:07.7: irq 72 for MSI/MSI-X
Jul 27 18:54:09 jessie kernel: vmw_vmci 0000:00:07.7: irq 73 for MSI/MSI-X
Jul 27 18:54:09 jessie kernel: Guest personality initialized and is active
Jul 27 18:54:09 jessie kernel: VMCI host device registered (name=vmci, major=10, minor=59)
Jul 27 18:54:09 jessie kernel: Initialized host personality
Jul 27 18:54:09 jessie kernel: [drm] Initialized drm 1.1.0 20060810
Jul 27 18:54:09 jessie kernel: piix4_smbus 0000:00:07.3: SMBus Host Controller not enabled!
Jul 27 18:54:09 jessie kernel: [drm] DMA map mode: Using physical TTM page addresses.
Jul 27 18:54:09 jessie kernel: [drm] Capabilities:
Jul 27 18:54:09 jessie kernel: [drm] Rect copy.
Jul 27 18:54:09 jessie kernel: [drm] Cursor.
Jul 27 18:54:09 jessie kernel: [drm] Cursor bypass.
Jul 27 18:54:09 jessie kernel: [drm] Cursor bypass 2.
Jul 27 18:54:09 jessie kernel: [drm] 8bit emulation.
Jul 27 18:54:09 jessie kernel: [drm] Alpha cursor.
Jul 27 18:54:09 jessie kernel: [drm] 3D.
Jul 27 18:54:09 jessie kernel: [drm] Extended Fifo.
Jul 27 18:54:09 jessie kernel: [drm] Multimon.
Jul 27 18:54:09 jessie kernel: [drm] Pitchlock.
Jul 27 18:54:09 jessie kernel: [drm] Irq mask.
Jul 27 18:54:09 jessie kernel: [drm] Display Topology.
Jul 27 18:54:09 jessie kernel: [drm] GMR.
Jul 27 18:54:09 jessie kernel: [drm] Traces.
Jul 27 18:54:09 jessie kernel: [drm] GMR2.
Jul 27 18:54:09 jessie kernel: [drm] Screen Object 2.
Jul 27 18:54:09 jessie kernel: [drm] Command Buffers.
Jul 27 18:54:09 jessie kernel: [drm] Max GMR ids is 64
Jul 27 18:54:09 jessie kernel: [drm] Max number of GMR pages is 196608
Jul 27 18:54:09 jessie kernel: [drm] Max dedicated hypervisor surface memory is 786432 kiB
Jul 27 18:54:09 jessie kernel: [drm] Maximum display memory size is 131072 kiB
Jul 27 18:54:09 jessie kernel: [drm] VRAM at 0xe8000000 size is 131072 kiB
Jul 27 18:54:09 jessie kernel: [drm] MMIO at 0xfe000000 size is 2048 kiB
Jul 27 18:54:09 jessie kernel: [drm] global init.
Jul 27 18:54:09 jessie kernel: [TTM] Zone kernel: Available graphics memory: 508824 kiB
Jul 27 18:54:09 jessie kernel: [TTM] Initializing pool allocator
Jul 27 18:54:09 jessie kernel: [TTM] Initializing DMA pool allocator
Jul 27 18:54:09 jessie kernel: [drm] Supports vblank timestamp caching Rev 2 (21.10.2013).
Jul 27 18:54:09 jessie kernel: [drm] No driver support for vblank timestamp query.
Jul 27 18:54:09 jessie kernel: [drm] Screen objects system initialized
Jul 27 18:54:09 jessie kernel: [drm] Initialized vmwgfx 2.5.0 20140228 for 0000:00:0f.0 on minor 0
Jul 27 18:54:09 jessie kernel: input: PC Speaker as /devices/platform/pcspkr/input/input4
Jul 27 18:54:09 jessie mtp-probe[344]: checking bus 1, device 2: "/sys/devices/pci0000:00/0000:00:11.0/0000:02:00.0/usb1/1-1"
Jul 27 18:54:09 jessie mtp-probe[344]: bus: 1, device: 2 was not an MTP device
Jul 27 18:54:09 jessie systemd[1]: Expecting device sys-subsystem-net-devices-eth0.device...
Jul 27 18:54:09 jessie systemd[1]: Found device 82545EM Gigabit Ethernet Controller (Copper) (PRO/1000 MT Single Port Adapter).
Jul 27 18:54:09 jessie kernel: Bluetooth: Core ver 2.18
Jul 27 18:54:09 jessie kernel: NET: Registered protocol family 31
Jul 27 18:54:09 jessie kernel: Bluetooth: HCI device and connection manager initialized
Jul 27 18:54:09 jessie kernel: Bluetooth: HCI socket layer initialized
Jul 27 18:54:09 jessie kernel: Bluetooth: L2CAP socket layer initialized
Jul 27 18:54:09 jessie kernel: Bluetooth: SCO socket layer initialized
Jul 27 18:54:09 jessie kernel: usbcore: registered new interface driver btusb
Jul 27 18:54:09 jessie systemd[1]: Found device VMware_Virtual_S.
Jul 27 18:54:09 jessie kernel: ppdev: user-space parallel port driver
Jul 27 18:54:09 jessie keyboard-setup[278]: Setting preliminary keymap...done.
Jul 27 18:54:09 jessie systemd[1]: Started LSB: Set preliminary keymap.
Jul 27 18:54:09 jessie systemd[1]: Starting Remount Root and Kernel File Systems...
Jul 27 18:54:09 jessie kernel: intel_rapl: domain package energy ctr 0:0 not working, skip
Jul 27 18:54:09 jessie systemd[1]: Starting Bluetooth.
Jul 27 18:54:09 jessie kernel: EXT4-fs (dm-3): re-mounted. Opts: errors=remount-ro
Jul 27 18:54:09 jessie systemd[1]: Reached target Bluetooth.
Jul 27 18:54:09 jessie systemd[1]: Found device /dev/mapper/jessie--vg-swap.
Jul 27 18:54:09 jessie systemd[1]: Activating swap /dev/mapper/jessie--vg-swap...
Jul 27 18:54:09 jessie systemd[1]: Started udev Wait for Complete Device Initialization.
Jul 27 18:54:09 jessie systemd[1]: Started Remount Root and Kernel File Systems.
Jul 27 18:54:09 jessie systemd[1]: Starting Load/Save Random Seed...
Jul 27 18:54:09 jessie systemd[1]: Started Various fixups to make systemd work better on Debian.
Jul 27 18:54:09 jessie systemd[1]: Starting Local File Systems (Pre).
Jul 27 18:54:09 jessie systemd[1]: Reached target Local File Systems (Pre).
Jul 27 18:54:09 jessie systemd[1]: Mounting Lock Directory...
Jul 27 18:54:09 jessie systemd[1]: run-lock.mount: Directory /run/lock to mount over is not empty, mounting anyway.
Jul 27 18:54:09 jessie systemd[1]: Mounting User Runtime Directory...
Jul 27 18:54:09 jessie systemd[1]: Starting Copy rules generated while the root was ro...
Jul 27 18:54:09 jessie systemd[1]: Starting Activation of LVM2 logical volumes...
Jul 27 18:54:09 jessie systemd[1]: Found device /dev/mapper/sda5_crypt.
Jul 27 18:54:09 jessie systemd[1]: Mounted User Runtime Directory.
Jul 27 18:54:09 jessie kernel: Adding 2928636k swap on /dev/mapper/jessie--vg-swap. Priority:-1 extents:1 across:2928636k
Jul 27 18:54:09 jessie systemd[1]: Activated swap /dev/mapper/jessie--vg-swap.
Jul 27 18:54:09 jessie systemd[1]: Starting Swap.
Jul 27 18:54:09 jessie systemd[1]: Reached target Swap.
Jul 27 18:54:09 jessie systemd[1]: Found device /dev/mapper/jessie--vg-home.
Jul 27 18:54:09 jessie systemd[1]: Starting File System Check on /dev/mapper/jessie--vg-home...
Jul 27 18:54:09 jessie systemd[1]: Started Load/Save Random Seed.
Jul 27 18:54:09 jessie systemd[1]: Started Copy rules generated while the root was ro.
Jul 27 18:54:09 jessie systemd[1]: Mounted Lock Directory.
Jul 27 18:54:09 jessie lvm[428]: /run/lock/lvm/V_jessie-vg:aux: open failed: No such file or directory
Jul 27 18:54:09 jessie lvm[428]: Can't get lock for jessie-vg
Jul 27 18:54:09 jessie lvm[428]: Skipping volume group jessie-vg
Jul 27 18:54:09 jessie systemd[1]: lvm2-activation-early.service: main process exited, code=exited, status=5/NOTINSSTALLED
Jul 27 18:54:09 jessie systemd[1]: Failed to start Activation of LVM2 logical volumes.
Jul 27 18:54:09 jessie systemd[1]: Unit lvm2-activation-early.service entered failed state.
Jul 27 18:54:09 jessie systemd[1]: Found device VMware_Virtual_S.
Jul 27 18:54:09 jessie systemd[1]: Starting File System Check on /dev/disk/by-uuid/6cb9fa29-8ee6-493c-907b-e508662f2e1a...
Jul 27 18:54:09 jessie systemd-fsck[440]: HOME: clean, 817/183264 files, 38965/732160 blocks
Jul 27 18:54:09 jessie systemd-fsck[446]: BOOT: clean, 285/62248 files, 38117/248832 blocks
Jul 27 18:54:09 jessie systemd[1]: Started File System Check on /dev/disk/by-uuid/6cb9fa29-8ee6-493c-907b-e508662f2e1a.
Jul 27 18:54:09 jessie systemd[1]: Mounting /boot...
Jul 27 18:54:09 jessie systemd[1]: Started File System Check on /dev/mapper/jessie--vg-home.
Jul 27 18:54:09 jessie systemd[1]: Mounting /home...
Jul 27 18:54:09 jessie kernel: input: ImPS/2 Generic Wheel Mouse as /devices/platform/i8042/serio1/input/input5
Jul 27 18:54:09 jessie systemd[1]: Mounted /boot.
Jul 27 18:54:09 jessie kernel: EXT4-fs (sda1): mounting ext2 file system using the ext4 subsystem
Jul 27 18:54:09 jessie kernel: EXT4-fs (sda1): mounted filesystem without journal. Opts: (null)
Jul 27 18:54:09 jessie kernel: intel_rapl: domain core energy ctr 0:0 not working, skip
Jul 27 18:54:09 jessie systemd[1]: Mounted /home.
Jul 27 18:54:09 jessie kernel: EXT4-fs (dm-2): mounted filesystem with ordered data mode. Opts: (null)
Jul 27 18:54:09 jessie kernel: intel_rapl: domain uncore energy ctr 0:0 not working, skip
Jul 27 18:54:10 jessie kernel: intel_rapl: domain dram energy ctr 0:0 not working, skip
Jul 27 18:54:10 jessie kernel: intel_rapl: no valid rapl domains found in package 0
Jul 27 18:54:10 jessie kernel: intel_rapl: domain package energy ctr 0:0 not working, skip
Jul 27 18:54:10 jessie systemd[1]: Starting Sound Card.
Jul 27 18:54:10 jessie systemd[1]: Reached target Sound Card.
Jul 27 18:54:10 jessie kernel: intel_rapl: domain core energy ctr 0:0 not working, skip
Jul 27 18:54:10 jessie kernel: intel_rapl: domain uncore energy ctr 0:0 not working, skip
Jul 27 18:54:10 jessie kernel: intel_rapl: domain dram energy ctr 0:0 not working, skip
Jul 27 18:54:10 jessie kernel: intel_rapl: no valid rapl domains found in package 0
Jul 27 18:55:39 jessie systemd[1]: Job dev-disk-by\x2dlabel-KEY:-key.device/start timed out.
Jul 27 18:55:39 jessie systemd-journal[253]: Forwarding to syslog missed 94 messages.
Jul 27 18:55:39 jessie systemd[1]: Timed out waiting for device dev-disk-by\x2dlabel-KEY:-key.device.
Jul 27 18:55:39 jessie systemd[1]: Dependency failed for Cryptography Setup for sda5_crypt.
Jul 27 18:55:39 jessie systemd[1]: Dependency failed for Encrypted Volumes.
Jul 27 18:55:39 jessie systemd[1]: Starting Activation of LVM2 logical volumes...
Jul 27 18:55:39 jessie lvm[468]: 3 logical volume(s) in volume group "jessie-vg" now active
Jul 27 18:55:39 jessie systemd[1]: Started Activation of LVM2 logical volumes.
Jul 27 18:55:39 jessie systemd[1]: Starting Local File Systems.
Jul 27 18:55:39 jessie systemd[1]: Reached target Local File Systems.
Reply to: