<div dir="ltr"><div><div><div>Hi all,<br><br></div><div>In case anybody is interested.<br></div>After some heavy debugging I was able to bisect the issue to the following pull request (which was backported to v247) <a href="https://github.com/systemd/systemd/pull/18802#issuecomment-827707662" target="_blank">https://github.com/systemd/systemd/pull/18802#issuecomment-827707662</a> . I left comments there on what broke.<br><br></div><div>Thanks for the help either way!<br></div><div><br></div></div></div><br><div class="gmail_quote"><div dir="ltr" class="gmail_attr">On Sat, Apr 24, 2021 at 5:03 PM Arian van Putten <<a href="mailto:arian.vanputten@gmail.com" target="_blank">arian.vanputten@gmail.com</a>> wrote:<br></div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"><div dir="ltr"><div>Dear list,</div><div><br></div><div>I've been working on trying to integrate systemd-gpt-auto and systemd-cryptsetup into NixOS's stage-1 init.</div><div><br></div><div>Everything
was working great on 246; but when I updated from kernel 5.4 to 5.10
and from systemd 246 to 247, the setup stopped working.<br><br></div><div>After entering my LUKS password, the boot keeps hanging with:</div><div><br></div><div><span style="font-family:monospace">A start job is running for /dev/gpt-auto-root</span><br><br></div><div>and eventually fails with:</div><div><br></div><div><span style="font-family:monospace">[ TIME ] Timed out waiting for device /dev/gpt-auto-root.</span></div><div><span style="font-family:monospace"><br></span></div><div><span style="font-family:monospace"></span>Interestingly. Both <span style="font-family:monospace">/dev/gpt-auto-root</span> and <span style="font-family:monospace">/dev/gpt-auto-root-luks</span> exist in the <span style="font-family:monospace">/dev</span> tree so the udev rules are all fired correctly; but for some reason they are not propagating to the device unit.</div><div>Also the <span style="font-family:monospace">btrfs</span> kernel module didn't seem to get automatically loaded for some reason.</div><div><br></div><div>For the failed boot on 247; this seems to be the interesting bit of the log:</div><div><span style="font-family:monospace">Apr 24 12:18:46 localhost systemd-udevd[209]: dm-0: Adding watch on '/dev/dm-0'<br>Apr 24 12:18:46 localhost systemd-udevd[209]: dm-0: sd-device: Created db file '/run/udev/data/b254:0' for '/devices/virtual/block/dm-0'<br>Apr 24 12:18:46 localhost systemd-udevd[209]: dm-0: Device (SEQNUM=1720, ACTION=change) processed<br>Apr 24 12:18:46 localhost systemd-udevd[209]: dm-0: sd-device-monitor: Passed 947 byte to netlink monitor<br>Apr 24 12:18:46 localhost systemd[1]: systemd-journald.service: Received EPOLLHUP on stored fd 46 (stored), closing.<br>Apr 24 12:18:46 localhost systemd[1]: Received SIGCHLD from PID 192 (systemd-cryptse).<br>Apr 24 12:18:46 localhost systemd[1]: Child 192 (systemd-cryptse) died (code=exited, status=0/SUCCESS)<br>Apr 24 12:18:46 localhost systemd[1]: systemd-cryptsetup@root.service: Child 192 belongs to systemd-cryptsetup@root.service.<br>Apr 24 12:18:46 localhost systemd[1]: systemd-cryptsetup@root.service: Main process exited, code=exited, status=0/SUCCESS<br>Apr 24 12:18:46 localhost systemd[1]: systemd-cryptsetup@root.service: Changed start -> exited<br>Apr 24 12:18:46 localhost systemd[1]: systemd-cryptsetup@root.service: Job 59 systemd-cryptsetup@root.service/start finished, result=done<br>Apr 24 12:18:46 localhost systemd[1]: Finished Cryptography Setup for root.<br>Apr 24 12:18:46 localhost audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=systemd-cryptsetup@root comm="systemd" exe="/nix/store/ixpwj1cxl4rp2qbyn0s2h4k5zj731q7c-systemd-247.6/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'<br>Apr 24 12:18:46 localhost systemd[1]: systemd-cryptsetup@root.service: Control group is empty.<br>Apr 24 12:18:46 localhost systemd[1]: blockdev@dev-mapper-root.target changed dead -> active<br>Apr 24 12:18:46 localhost systemd[1]: blockdev@dev-mapper-root.target: Job 72 blockdev@dev-mapper-root.target/start finished, result=done<br>Apr 24 12:18:46 localhost systemd[1]: Reached target Block Device Preparation for /dev/mapper/root.<br>Apr 24 12:18:46 localhost kernel: kauditd_printk_skb: 4 callbacks suppressed<br>Apr 24 12:18:46 localhost kernel: audit: type=1130 audit(1619266726.241:15): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=systemd-cryptsetup@root comm="systemd" exe="/nix/store/ixpwj1cxl4rp2qbyn0s2h4k5zj731q7c-systemd-247.6/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'<br>Apr 24 12:18:50 localhost systemd-udevd[148]: Cleanup idle workers<br>Apr 24 12:18:50 localhost systemd-udevd[207]: Unload module index<br>Apr 24 12:18:50 localhost systemd-udevd[209]: Unload module index<br>Apr 24 12:18:50 localhost systemd-udevd[205]: Unload module index<br>Apr 24 12:18:50 localhost systemd-udevd[206]: Unload module index<br>Apr 24 12:18:50 localhost systemd-udevd[207]: Unloaded link configuration context.<br>Apr 24 12:18:50 localhost systemd-udevd[209]: Unloaded link configuration context.<br>Apr 24 12:18:50 localhost systemd-udevd[205]: Unloaded link configuration context.<br>Apr 24 12:18:50 localhost systemd-udevd[206]: Unloaded link configuration context.<br>Apr 24 12:18:50 localhost systemd-udevd[148]: Worker [205] exited<br>Apr 24 12:18:50 localhost systemd-udevd[148]: Worker [206] exited<br>Apr 24 12:18:50 localhost systemd-udevd[148]: Worker [207] exited<br>Apr 24 12:18:50 localhost systemd-udevd[148]: Worker [209] exited<br>Apr 24 12:19:48 localhost systemd[1]: dev-gpt\x2dauto\x2droot.device: Job dev-gpt\x2dauto\x2droot.device/start timed out.<br>Apr 24 12:19:48 localhost systemd[1]: dev-gpt\x2dauto\x2droot.device: Job 56 dev-gpt\x2dauto\x2droot.device/start finished, result=timeout<br>Apr 24 12:19:48 localhost systemd[1]: Timed out waiting for device /dev/gpt-auto-root.<br>Apr 24 12:19:48 localhost systemd[1]: initrd-root-device.target: Job 57 initrd-root-device.target/start finished, result=dependency<br>Apr 24 12:19:48 localhost systemd[1]: Dependency failed for Initrd Root Device.<br>Apr 24 12:19:48 localhost systemd[1]: initrd-root-device.target: Job initrd-root-device.target/start failed with result 'dependency'.</span></div><div><br></div><div>Whilst the successful boot on 246 looks like this:<br><br><span style="font-family:monospace">r 24 12:44:32 localhost systemd-cryptsetup[176]: root: retaining kernel read ahead of 256 (requested 256)<br>Apr 24 12:44:32 localhost systemd-cryptsetup[176]: Releasing crypt device /dev/gpt-auto-root-luks context.<br>Apr 24 12:44:32 localhost systemd-cryptsetup[176]: Releasing device-mapper backend.<br>Apr 24 12:44:32 localhost systemd-udevd[193]: dm-0: Adding watch on '/dev/dm-0'<br>Apr 24 12:44:32 localhost systemd-cryptsetup[176]: Closing read only fd for /dev/gpt-auto-root-luks.<br>Apr 24 12:44:32 localhost systemd-udevd[193]: dm-0: sd-device: Created db file '/run/udev/data/b254:0' for '/devices/virtual/block/dm-0'<br>Apr 24 12:44:32 localhost systemd-udevd[193]: dm-0: Device (SEQNUM=2066, ACTION=change) processed<br>Apr 24 12:44:32 localhost systemd-udevd[193]: dm-0: sd-device-monitor: Passed 891 byte to netlink monitor<br>Apr 24 12:44:32 localhost systemd[1]: dev-gpt\x2dauto\x2droot.device: Changed dead -> plugged<br>Apr 24 12:44:32 localhost systemd[1]: dev-gpt\x2dauto\x2droot.device: Job 52 dev-gpt\x2dauto\x2droot.device/start finished, result=done<br>Apr 24 12:44:32 localhost systemd[1]: Found device /dev/gpt-auto-root.<br>Apr 24 12:44:32 localhost systemd[1]: dev-disk-by\x2did-dm\x2dname\x2droot.device: Changed dead -> plugged<br>Apr 24 12:44:32 localhost systemd[1]: dev-disk-by\x2did-dm\x2duuid\x2dCRYPT\x2dLUKS1\x2d0c642ebc2b7643dcb9ba34f1125d7f16\x2droot.device: Changed dead -> plugged<br>Apr 24 12:44:32 localhost systemd[1]: dev-mapper-root.device: Changed dead -> plugged<br>Apr 24 12:44:32 localhost systemd[1]: dev-disk-by\x2duuid-5cb38441\x2d7012\x2d4aaf\x2da70c\x2db11aaaa212d3.device: Changed dead -> plugged<br>Apr 24 12:44:32 localhost systemd[1]: dev-dm\x2d0.device: Changed dead -> plugged<br>Apr 24 12:44:32 localhost systemd[1]: sys-devices-virtual-block-dm\x2d0.device: Changed dead -> plugged<br>Apr 24 12:44:32 localhost systemd[1]: Received SIGCHLD from PID 176 (systemd-cryptse).<br>Apr 24 12:44:32 localhost systemd[1]: Child 176 (systemd-cryptse) died (code=exited, status=0/SUCCESS)<br>Apr 24 12:44:32 localhost systemd[1]: systemd-cryptsetup@root.service: Failed to read oom_kill field of memory.events cgroup attribute: No such file or directory<br>Apr 24 12:44:32 localhost systemd[1]: systemd-cryptsetup@root.service: Child 176 belongs to systemd-cryptsetup@root.service.<br>Apr 24 12:44:32 localhost systemd[1]: systemd-cryptsetup@root.service: Main process exited, code=exited, status=0/SUCCESS<br>Apr 24 12:44:32 localhost systemd[1]: systemd-cryptsetup@root.service: Changed start -> exited<br>Apr 24 12:44:32 localhost systemd[1]: systemd-cryptsetup@root.service: Job 56 systemd-cryptsetup@root.service/start finished, result=done<br>Apr 24 12:44:32 localhost systemd[1]: Finished Cryptography Setup for root.<br>Apr 24 12:44:32 localhost audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=systemd-cryptsetup@root comm="systemd" exe="/nix/store/zpzn7c5g58srji21flwqmxzbnaa8w29j-systemd-246.6/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'<br>Apr 24 12:44:32 localhost systemd[1]: systemd-cryptsetup@root.service: Control group is empty.<br>Apr 24 12:44:32 localhost kernel: kauditd_printk_skb: 1 callbacks suppressed<br>Apr 24 12:44:32 localhost kernel: audit: type=1130 audit(1619268272.815:12): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=systemd-cryptsetup@root comm="systemd" exe="/nix/store/zpzn7c5g58srji21flwqmxzbnaa8w29j-systemd-246.6/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'<br>Apr 24 12:44:32 localhost systemd[1]: systemd-journald.service: Received EPOLLHUP on stored fd 43 (stored), closing.<br>Apr 24 12:44:32 localhost systemd[1]: blockdev@dev-mapper-root.target changed dead -> active<br>Apr 24 12:44:32 localhost systemd[1]: blockdev@dev-mapper-root.target: Job 69 blockdev@dev-mapper-root.target/start finished, result=done<br>Apr 24 12:44:32 localhost systemd[1]: Reached target Block Device Preparation for /dev/mapper/root.<br>Apr 24 12:44:32 localhost systemd[1]: initrd-root-device.target: ConditionPathExists=/etc/initrd-release succeeded.<br>Apr 24 12:44:32 localhost systemd[1]: initrd-root-device.target changed dead -> active<br>Apr 24 12:44:32 localhost systemd[1]: initrd-root-device.target: Job 55 initrd-root-device.target/start finished, result=done<br>Apr 24 12:44:32 localhost systemd[1]: Reached target Initrd Root Device.<br>Apr 24 12:44:32 localhost systemd[1]: initrd.target: starting held back, waiting for: initrd-root-fs.target<br>Apr 24 12:44:32 localhost systemd[1]: Failed to read pids.max attribute of cgroup root, ignoring: No data available<br>Apr 24 12:44:32 localhost systemd[1]: sysroot.mount: About to execute: /nix/store/wcbrp1x2xfmqdpg4vs759irmm1k74c0s-util-linux-2.36-bin/bin/mount /dev/gpt-auto-root /sysroot -o ro<br>Apr 24 12:44:32 localhost systemd[1]: sysroot.mount: Forked /nix/store/wcbrp1x2xfmqdpg4vs759irmm1k74c0s-util-linux-2.36-bin/bin/mount as 202<br>Apr 24 12:44:32 localhost systemd[1]: sysroot.mount: Changed dead -> mounting<br>Apr 24 12:44:32 localhost systemd[1]: Mounting Root Partition...<br>Apr 24 12:44:32 localhost systemd[202]: sysroot.mount: Executing: /nix/store/wcbrp1x2xfmqdpg4vs759irmm1k74c0s-util-linux-2.36-bin/bin/mount /dev/gpt-auto-root /sysroot -o ro</span><br><br></div><div><br><div>I have attached the full boot log of the initrd as an attachment. initrd-246.log succeeds; whilst initrd-247.log fails <br></div><div><br></div><div>Would love to get some pointers on how to further debug this. I can't tell from the logs what exactly is going wrong.<br></div><div><br></div></div></div>
</blockquote></div>