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.
