Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

On first boot systemd believes some successfully mounted block devices have been unplugged and unmounts them #26254

Closed
anish opened this issue Jan 30, 2023 · 10 comments
Closed

On first boot systemd believes some successfully mounted block devices have been unplugged and unmounts them #26254

anish opened this issue Jan 30, 2023 · 10 comments
Labels
bug 🐛 Programming errors, that need preferential fixing udev

Comments

@anish
Copy link

anish commented Jan 30, 2023

systemd version the issue has been seen with

250

Used distribution

Rhel 9/systemd-250-12.el9_1

Linux kernel version used

5.14.0-162.6.1.el9_1.x86_64

CPU architectures issue was seen on

x86_64

Component

systemd-udevd

Expected behaviour you didn't see

On first boot, systemd should successfully mount all devices specified in fstab

Unexpected behaviour you saw

On first boot systemd mounts all devices in fstab, then believes that some devices, consequently propagating the error to the mdraid devices on top, marking them offline and unmounts the corresponding mount points, eventually stopping local-fs.target. This also affects other devices (like systemd thinking the nic/terminal device are also unplugged)

Steps to reproduce the problem

[root@fluffy.bunny ~]# systemctl status local-fs.target
○ local-fs.target - Local File Systems
     Loaded: loaded (/usr/lib/systemd/system/local-fs.target; static)
     Active: inactive (dead) since Mon 2023-01-30 03:57:03 UTC; 3h 1min ago
       Docs: man:systemd.special(7)

Jan 30 03:57:02 fluffy.bunny systemd[1]: local-fs.target: Job 139 local-fs.target/start finished, result=done
Jan 30 03:57:02 fluffy.bunny systemd[1]: Reached target Local File Systems.
Jan 30 03:57:03 fluffy.bunny systemd[1]: local-fs.target: Installed new job local-fs.target/stop as 498
Jan 30 03:57:03 fluffy.bunny systemd[1]: local-fs.target: Merged local-fs.target/stop into installed job local-fs.target/stop as 498
Jan 30 03:57:03 fluffy.bunny systemd[1]: local-fs.target: Merged local-fs.target/stop into installed job local-fs.target/stop as 498
Jan 30 03:57:03 fluffy.bunny systemd[1]: local-fs.target: Merged local-fs.target/stop into installed job local-fs.target/stop as 498
Jan 30 03:57:03 fluffy.bunny systemd[1]: local-fs.target: Merged local-fs.target/stop into installed job local-fs.target/stop as 498
Jan 30 03:57:03 fluffy.bunny systemd[1]: local-fs.target: Job 498 local-fs.target/stop finished, result=done
Jan 30 03:57:03 fluffy.bunny systemd[1]: Stopped target Local File Systems.
[root@fluffy.bunny ~]# cat /etc/fstab 
LABEL=root              /                       ext4    defaults        1 1
LABEL=boot              /boot                   ext2    defaults        2 2
LABEL=role              /home                   xfs     defaults        0 0
LABEL=EFI               /boot/efi               vfat    defaults,uid=0,gid=0,umask=077,shortname=winnt 0 2
[root@fluffy.bunny ~]# systemctl status boot.mount
○ boot.mount - /boot
     Loaded: loaded (/etc/fstab; generated)
     Active: inactive (dead) since Mon 2023-01-30 03:57:03 UTC; 3h 1min ago
   Duration: 1.523s
      Where: /boot
       What: /dev/disk/by-label/boot
       Docs: man:fstab(5)
             man:systemd-fstab-generator(8)
        CPU: 22ms

Jan 30 03:57:03 fluffy.bunny systemd[1]: boot.mount: Changed mounted -> unmounting
Jan 30 03:57:03 fluffy.bunny systemd[1]: Unmounting /boot...
Jan 30 03:57:03 fluffy.bunny systemd[1598]: boot.mount: Executing: /usr/bin/umount /boot -c
Jan 30 03:57:03 fluffy.bunny systemd[1]: boot.mount: Child 1598 belongs to boot.mount.
Jan 30 03:57:03 fluffy.bunny systemd[1]: boot.mount: Mount process exited, code=exited, status=0/SUCCESS (success)
Jan 30 03:57:03 fluffy.bunny systemd[1]: boot.mount: Deactivated successfully.
Jan 30 03:57:03 fluffy.bunny systemd[1]: boot.mount: Changed unmounting -> dead
Jan 30 03:57:03 fluffy.bunny systemd[1]: boot.mount: Job 496 boot.mount/stop finished, result=done
Jan 30 03:57:03 fluffy.bunny systemd[1]: Unmounted /boot.
Jan 30 03:57:03 fluffy.bunny systemd[1]: boot.mount: Consumed 22ms CPU time.

Additional program output to the terminal or log subsystem illustrating the issue

Jan 30 03:57:03 fluffy.bunny systemd[1]: local-fs.target changed dead -> active
Jan 30 03:57:03 fluffy.bunny systemd[1]: dev-disk-by\x2did-scsi\x2d3614187705fb035002a47ae9b4cf6174d.device: Changed dead -> plugged
Jan 30 03:57:03 fluffy.bunny systemd[1]: systemd-fsck@dev-disk-by\x2dlabel-EFI.service: Changed dead -> exited
Jan 30 03:57:03 fluffy.bunny systemd[1]: dev-disk-by\x2dpath-pci\x2d0000:01:00.0\x2dscsi\x2d0:2:4:0.device: Changed dead -> plugged
Jan 30 03:57:03 fluffy.bunny systemd[1]: dev-disk-by\x2duuid-9179d386\x2d8b0d\x2d4456\x2d8a3c\x2d66bc3cbc470e.device: Changed dead -> plugged
Jan 30 03:57:03 fluffy.bunny systemd[1]: dev-disk-by\x2dpartlabel-BIOS.device: Changed dead -> plugged
Jan 30 03:57:03 fluffy.bunny systemd[1]: dev-disk-by\x2did-scsi\x2d3614187705fb035002a47ae974cc255e5\x2dpart4.device: Changed dead -> plugged
Jan 30 03:57:03 fluffy.bunny systemd[1]: dev-disk-by\x2dpartuuid-eb49ba0c\x2d4600\x2d4290\x2dbbf0\x2d247a39026889.device: Changed dead -> plugged
Jan 30 03:57:03 fluffy.bunny systemd[1]: dev-sde.device: Changed dead -> plugged
Jan 30 03:57:03 fluffy.bunny systemd[1]: dev-disk-by\x2dpath-pci\x2d0000:01:00.0\x2dscsi\x2d0:2:0:0\x2dpart2.device: Changed dead -> plugged
Jan 30 03:57:03 fluffy.bunny systemd[1]: sys-devices-pci0000:00-0000:00:01.0-0000:01:00.0-host0-target0:2:2-0:2:2:0-block-sdc.device: Changed dea>
Jan 30 03:57:03 fluffy.bunny systemd[1]: sysinit.target changed dead -> active
Jan 30 03:57:03 fluffy.bunny systemd[1]: systemd-udev-trigger.service: Changed dead -> exited
Jan 30 03:57:03 fluffy.bunny systemd[1]: dev-disk-by\x2did-scsi\x2d3614187705fb035002a47ae974cc255e5\x2dpart5.device: Changed dead -> plugged
Jan 30 03:57:03 fluffy.bunny systemd[1]: dev-disk-by\x2did-md\x2duuid\x2d8fbbb75f:36cc7597:9f1a4b91:200ab286.device: Changed dead -> plugged
Jan 30 03:57:03 fluffy.bunny systemd[1]: sys-devices-pci0000:00-0000:00:01.0-0000:01:00.0-host0-target0:2:0-0:2:0:0-block-sda.device: Changed dea>
Jan 30 03:57:03 fluffy.bunny systemd[1]: sys-devices-pci0000:00-0000:00:01.0-0000:01:00.0-host0-target0:2:0-0:2:0:0-block-sda-sda6.device: Change>
Jan 30 03:57:03 fluffy.bunny systemd[1]: sys-devices-pci0000:00-0000:00:1c.2-0000:02:00.0-net-eno1.device: Changed dead -> plugged
Jan 30 03:57:03 fluffy.bunny systemd[1]: dev-disk-by\x2dpartlabel-ROOT.device: Changed dead -> plugged
Jan 30 03:57:03 fluffy.bunny systemd[1]: sys-devices-pci0000:00-0000:00:01.0-0000:01:00.0-host0-target0:2:2-0:2:2:0-block-sdc-sdc2.device: Change>
Jan 30 03:57:03 fluffy.bunny systemd[1]: dev-disk-by\x2did-md\x2dname\x2dboot.device: Changed dead -> plugged
Jan 30 03:57:03 fluffy.bunny systemd[1]: dev-disk-by\x2did-wwn\x2d0x614187705fb035002a47ae964ca9ffdf\x2dpart4.device: Changed dead -> plugged
Jan 30 03:57:03 fluffy.bunny systemd[1]: dev-disk-by\x2dpartuuid-534d3be2\x2dce0e\x2d4780\x2d913f\x2d91035b0168cf.device: Changed dead -> plugged
Jan 30 03:57:03 fluffy.bunny systemd[1]: dev-sdb4.device: Changed dead -> plugged
Jan 30 03:57:03 fluffy.bunny systemd[1]: irqbalance.service: Changed dead -> running
Jan 30 03:57:03 fluffy.bunny systemd[1]: dev-disk-by\x2did-wwn\x2d0x614187705fb035002a47ae974cc255e5\x2dpart7.device: Changed dead -> plugged
Jan 30 03:57:03 fluffy.bunny systemd[1]: systemd-machine-id-commit.service: Changed dead -> exited
Jan 30 03:57:03 fluffy.bunny systemd[1]: systemd-modules-load.service: Changed dead -> exited
Jan 30 03:57:03 fluffy.bunny systemd[1]: timers.target changed dead -> active
Jan 30 03:57:03 fluffy.bunny systemd[1]: dev-disk-by\x2did-wwn\x2d0x614187705fb035002a47ae994cdbcd37.device: Changed dead -> plugged
Jan 30 03:57:03 fluffy.bunny systemd[1]: dev-disk-by\x2dpath-pci\x2d0000:01:00.0\x2dscsi\x2d0:2:1:0\x2dpart4.device: Changed dead -> plugged
Jan 30 03:57:03 fluffy.bunny systemd[1]: nss-user-lookup.target changed dead -> active
Jan 30 03:57:03 fluffy.bunny systemd[1]: dev-disk-by\x2did-scsi\x2d3614187705fb035002a47ae994cdbcd37\x2dpart2.device: Changed dead -> plugged
Jan 30 03:57:03 fluffy.bunny systemd[1]: dev-disk-by\x2did-wwn\x2d0x614187705fb035002a47ae944c9232a1\x2dpart4.device: Changed dead -> plugged
Jan 30 03:57:03 fluffy.bunny systemd[1]: dev-sda.device: Changed dead -> plugged
Jan 30 03:57:03 fluffy.bunny systemd[1]: NetworkManager.service: Changed dead -> start
Jan 30 03:57:03 fluffy.bunny systemd[1]: dev-disk-by\x2did-scsi\x2d3614187705fb035002a47ae944c9232a1\x2dpart7.device: Changed dead -> plugged
Jan 30 03:57:03 fluffy.bunny systemd[1]: dracut-shutdown.service: Changed dead -> exited
Jan 30 03:57:03 fluffy.bunny systemd[1]: dev-sdc3.device: Changed dead -> plugged
Jan 30 03:57:03 fluffy.bunny systemd[1]: systemd-sysctl.service: Changed dead -> exited
Jan 30 03:57:03 fluffy.bunny systemd[1]: dev-disk-by\x2did-wwn\x2d0x614187705fb035002a47ae994cdbcd37\x2dpart2.device: Changed dead -> plugged
Jan 30 03:57:03 fluffy.bunny systemd[1]: dbus-broker.service: Changed dead -> running
Jan 30 03:57:03 fluffy.bunny systemd[1]: dev-disk-by\x2dpath-pci\x2d0000:01:00.0\x2dscsi\x2d0:2:1:0\x2dpart7.device: Changed dead -> plugged
Jan 30 03:57:03 fluffy.bunny systemd[1]: dev-disk-by\x2dpath-pci\x2d0000:01:00.0\x2dscsi\x2d0:2:0:0\x2dpart5.device: Changed dead -> plugged
Jan 30 03:57:03 fluffy.bunny systemd[1]: run-rf003f157b2ed40f0b6c2f64359725628.service: Changed dead -> running
Jan 30 03:57:03 fluffy.bunny systemd[1]: dev-disk-by\x2dpath-pci\x2d0000:01:00.0\x2dscsi\x2d0:2:3:0\x2dpart6.device: Changed dead -> plugged
Jan 30 03:57:03 fluffy.bunny systemd[1]: dev-disk-by\x2did-wwn\x2d0x614187705fb035002a47ae944c9232a1\x2dpart5.device: Changed dead -> plugged
Jan 30 03:57:03 fluffy.bunny systemd[1]: dev-disk-by\x2did-wwn\x2d0x614187705fb035002a47ae994cdbcd37\x2dpart7.device: Changed dead -> plugged
...skipping...
Jan 30 03:57:03 fluffy.bunny systemd[1]: local-fs.target: Installed new job local-fs.target/stop as 498
Jan 30 03:57:03 fluffy.bunny systemd[1]: systemd-fsck@dev-disk-by\x2dlabel-boot.service: Installed new job systemd-fsck@dev-disk-by\x2dlabel-boot>
Jan 30 03:57:03 fluffy.bunny systemd[1]: systemd-fsck@dev-disk-by\x2dlabel-boot.service: Enqueued job systemd-fsck@dev-disk-by\x2dlabel-boot.serv>
Jan 30 03:57:03 fluffy.bunny systemd[1]: dev-sde5.device: Changed plugged -> dead
Jan 30 03:57:03 fluffy.bunny systemd[1]: dev-disk-by\x2did-scsi\x2d3614187705fb035002a47ae9c4d0d19ff\x2dpart1.device: Changed plugged -> dead
Jan 30 03:57:03 fluffy.bunny systemd[1]: dev-disk-by\x2did-scsi\x2d3614187705fb035002a47ae974cc255e5.device: Changed plugged -> dead
Jan 30 03:57:03 fluffy.bunny systemd[1]: sys-subsystem-net-devices-eno3.device: Changed plugged -> dead
Jan 30 03:57:03 fluffy.bunny systemd[1]: dev-disk-by\x2dpartuuid-725902f5\x2de9a0\x2d4de4\x2d9d05\x2ddd6682add964.device: Changed plugged -> dead
Jan 30 03:57:03 fluffy.bunny systemd[1]: sys-devices-pci0000:00-0000:00:01.0-0000:01:00.0-host0-target0:2:3-0:2:3:0-block-sde-sde7.device: Change>
Jan 30 03:57:03 fluffy.bunny systemd[1]: dev-disk-by\x2dpath-pci\x2d0000:01:00.0\x2dscsi\x2d0:2:1:0\x2dpart3.device: Changed plugged -> dead
Jan 30 03:57:03 fluffy.bunny systemd[1]: dev-disk-by\x2dpath-pci\x2d0000:01:00.0\x2dscsi\x2d0:2:4:0\x2dpart1.device: Changed plugged -> dead
Jan 30 03:57:03 fluffy.bunny systemd[1]: dev-disk-by\x2dpath-pci\x2d0000:01:00.0\x2dscsi\x2d0:2:3:0.device: Changed plugged -> dead
Jan 30 03:57:03 fluffy.bunny systemd[1]: dev-disk-by\x2did-scsi\x2d3614187705fb035002a47ae974cc255e5\x2dpart7.device: Changed plugged -> dead
Jan 30 03:57:03 fluffy.bunny systemd[1]: dev-disk-by\x2dpartlabel-FASTDATA.device: Changed plugged -> dead
Jan 30 03:57:03 fluffy.bunny systemd[1]: dev-disk-by\x2did-wwn\x2d0x614187705fb035002a47ae974cc255e5\x2dpart2.device: Changed plugged -> dead
Jan 30 03:57:03 fluffy.bunny systemd[1]: sys-devices-pci0000:00-0000:00:01.0-0000:01:00.0-host0-target0:2:3-0:2:3:0-block-sde-sde6.device: Change>
Jan 30 03:57:03 fluffy.bunny systemd[1]: sys-devices-virtual-block-md124.device: Changed plugged -> dead
Jan 30 03:57:03 fluffy.bunny systemd[1]: sys-devices-pci0000:00-0000:00:01.0-0000:01:00.0-host0-target0:2:1-0:2:1:0-block-sdb-sdb1.device: Change>
Jan 30 03:57:03 fluffy.bunny systemd[1]: dev-disk-by\x2dpath-pci\x2d0000:01:00.0\x2dscsi\x2d0:2:1:0\x2dpart5.device: Changed plugged -> dead
Jan 30 03:57:03 fluffy.bunny systemd[1]: dev-disk-by\x2did-wwn\x2d0x614187705fb035002a47ae974cc255e5\x2dpart3.device: Changed plugged -> dead
Jan 30 03:57:03 fluffy.bunny systemctl[1508]: Got message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/syste>
Jan 30 03:57:03 fluffy.bunny systemd[1]: dev-sda3.device: Changed plugged -> dead
Jan 30 03:57:03 fluffy.bunny systemd[1]: dev-sdc7.device: Changed plugged -> dead
Jan 30 03:57:03 fluffy.bunny systemctl[1508]: Got message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/syste>
Jan 30 03:57:03 fluffy.bunny systemd[1]: sys-devices-pnp0-00:03-tty-ttyS1.device: Changed plugged -> dead
Jan 30 03:57:03 fluffy.bunny systemd[1]: sys-devices-pci0000:00-0000:00:01.0-0000:01:00.0-host0-target0:2:2-0:2:2:0-block-sdc-sdc3.device: Change>
Jan 30 03:57:03 fluffy.bunny systemd[1]: dev-sdc6.device: Changed plugged -> dead
Jan 30 03:57:03 fluffy.bunny systemd[1]: dev-disk-by\x2dpath-pci\x2d0000:01:00.0\x2dscsi\x2d0:2:3:0\x2dpart4.device: Changed plugged -> dead
Jan 30 03:57:03 fluffy.bunny systemctl[1508]: Got message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/syste>
Jan 30 03:57:03 fluffy.bunny systemd[1]: sys-devices-pci0000:00-0000:00:01.0-0000:01:00.0-host0-target0:2:3-0:2:3:0-block-sde-sde2.device: Change>
Jan 30 03:57:03 fluffy.bunny systemd[1]: dev-disk-by\x2dpartuuid-cdf623b7\x2d8ffb\x2d4750\x2d9716\x2d9a59c49c87ea.device: Changed plugged -> dead
Jan 30 03:57:03 fluffy.bunny systemd[1]: dev-sde3.device: Changed plugged -> dead
Jan 30 03:57:03 fluffy.bunny systemctl[1508]: Got message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/syste>
Jan 30 03:57:03 fluffy.bunny systemd[1]: dev-disk-by\x2did-scsi\x2d3614187705fb035002a47ae964ca9ffdf.device: Changed plugged -> dead
Jan 30 03:57:03 fluffy.bunny systemd[1]: dev-sda4.device: Changed plugged -> dead
Jan 30 03:57:03 fluffy.bunny systemd[1]: dev-ttyS3.device: Changed plugged -> dead

<snip>

Jan 30 03:57:03 fluffy.bunny systemd[1]: sys-devices-pci0000:00-0000:00:01.0-0000:01:00.0-host0-target0:2:2-0:2:2:0-block-sdc-sdc7.device: Change>
Jan 30 03:57:03 fluffy.bunny systemd[1]: dev-md124.device: Changed plugged -> dead
Jan 30 03:57:03 fluffy.bunny systemctl[1508]: Got message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/syste>
Jan 30 03:57:03 fluffy.bunny systemd[1]: dev-md125.device: Changed plugged -> dead
Jan 30 03:57:03 fluffy.bunny systemd[1]: boot.mount: Trying to enqueue job boot.mount/stop/replace
Jan 30 03:57:03 fluffy.bunny systemd[1]: boot.mount: Merged boot.mount/stop into installed job boot.mount/stop as 496
Jan 30 03:57:03 fluffy.bunny systemd[1]: local-fs.target: Merged local-fs.target/stop into installed job local-fs.target/stop as 498
Jan 30 03:57:03 fluffy.bunny systemctl[1508]: Got message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/syste>
Jan 30 03:57:03 fluffy.bunny systemd[1]: boot-efi.mount: Merged boot-efi.mount/stop into installed job boot-efi.mount/stop as 497
Jan 30 03:57:03 fluffy.bunny systemd[1]: boot.mount: Enqueued job boot.mount/stop as 496
Jan 30 03:57:03 fluffy.bunny systemd[1]: dev-disk-by\x2did-wwn\x2d0x614187705fb035002a47ae944c9232a1\x2dpart1.device: Changed plugged -> dead
Jan 30 03:57:03 fluffy.bunny systemctl[1508]: Got message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/syste>
Jan 30 03:57:03 fluffy.bunny systemd[1]: dev-disk-by\x2dpath-pci\x2d0000:01:00.0\x2dscsi\x2d0:2:3:0\x2dpart7.device: Changed plugged -> dead
Jan 30 03:57:03 fluffy.bunny systemd[1]: dev-disk-by\x2did-wwn\x2d0x614187705fb035002a47ae9c4d0d19ff\x2dpart1.device: Changed plugged -> dead
Jan 30 03:57:03 fluffy.bunny systemd[1]: dev-sdb2.device: Changed plugged -> dead
Jan 30 03:57:03 fluffy.bunny systemd[1]: boot-efi.mount: Trying to enqueue job boot-efi.mount/stop/replace
Jan 30 03:57:03 fluffy.bunny systemctl[1508]: Got message type=signal sender=org.freedesktop.systemd1 destination=n/a path=/org/freedesktop/syste>
Jan 30 03:57:03 fluffy.bunny systemd[1]: local-fs.target: Merged local-fs.target/stop into installed job local-fs.target/stop as 498
Jan 30 03:57:03 fluffy.bunny systemd[1]: boot-efi.mount: Merged boot-efi.mount/stop into installed job boot-efi.mount/stop as 497
Jan 30 03:57:03 fluffy.bunny systemd[1]: boot-efi.mount: Enqueued job boot-efi.mount/stop as 497
@anish anish added the bug 🐛 Programming errors, that need preferential fixing label Jan 30, 2023
@github-actions github-actions bot added the udev label Jan 30, 2023
@poettering
Copy link
Member

[Canned reply follows]

This is the upstream bug and feature request tracker of systemd. Please use this only for issues in the two most current upstream systemd versions. See this link for the list of current releases.

https://github.com/systemd/systemd/releases

For support for older versions please contact your distribution instead.

In order to keep frustration at a minimum the submission form tried to make this all very clear.

@poettering
Copy link
Member

talk to your distro!

@anish
Copy link
Author

anish commented Jan 30, 2023

Sure, let me do that instead. Adding some logs for more info in case someone else comes across this issue that show the devices changing state between dead->plugged->dead->plugged. The final plugged state does not seem to kick off a remount. The kernel does not think this device has been unplugged per dmesg, device is accessible as well.

[root@fluffy.bunny ~]# systemctl status -- $(systemd-escape --suffix=mount --path /boot)           
○ boot.mount - /boot
     Loaded: loaded (/etc/fstab; generated)
     Active: inactive (dead) since Mon 2023-01-30 03:57:03 UTC; 12h ago
   Duration: 1.523s
      Where: /boot
       What: /dev/disk/by-label/boot
       Docs: man:fstab(5)
             man:systemd-fstab-generator(8)
        CPU: 22ms

Jan 30 03:57:03 fluffy.bunny systemd[1]: boot.mount: Changed mounted -> unmounting
Jan 30 03:57:03 fluffy.bunny systemd[1]: Unmounting /boot...
Jan 30 03:57:03 fluffy.bunny systemd[1598]: boot.mount: Executing: /usr/bin/umount /boot -c
Jan 30 03:57:03 fluffy.bunny systemd[1]: boot.mount: Child 1598 belongs to boot.mount.
Jan 30 03:57:03 fluffy.bunny systemd[1]: boot.mount: Mount process exited, code=exited, status=0/SUCCESS (success)
Jan 30 03:57:03 fluffy.bunny systemd[1]: boot.mount: Deactivated successfully.
Jan 30 03:57:03 fluffy.bunny systemd[1]: boot.mount: Changed unmounting -> dead
Jan 30 03:57:03 fluffy.bunny systemd[1]: boot.mount: Job 496 boot.mount/stop finished, result=done
Jan 30 03:57:03 fluffy.bunny systemd[1]: Unmounted /boot.
Jan 30 03:57:03 fluffy.bunny systemd[1]: boot.mount: Consumed 22ms CPU time.
[root@fluffy.bunny ~]# blkid -L boot
/dev/md125
[root@fluffy.bunny ~]# mdadm --detail /dev/md125
/dev/md125:
           Version : 1.0
     Creation Time : Mon Jan 30 03:48:03 2023
        Raid Level : raid1
        Array Size : 1048512 (1023.94 MiB 1073.68 MB)
     Used Dev Size : 1048512 (1023.94 MiB 1073.68 MB)
      Raid Devices : 4
     Total Devices : 4
       Persistence : Superblock is persistent

       Update Time : Mon Jan 30 03:57:04 2023
             State : clean 
    Active Devices : 4
   Working Devices : 4
    Failed Devices : 0
     Spare Devices : 0

Consistency Policy : resync

              Name : boot
              UUID : 92e8dbe7:2bee403b:e68bcdbd:25f4f991
            Events : 2

    Number   Major   Minor   RaidDevice State
       0       8       19        0      active sync   /dev/sdb3
       1       8        3        1      active sync   /dev/sda3
       2       8       67        2      active sync   /dev/sde3
       3       8       35        3      active sync   /dev/sdc3
[root@fluffy.bunny ~]# file !$
file /dev/md125
/dev/md125: block special (9/125)
[root@fluffy.bunny ~]# file /dev/sda3
/dev/sda3: block special (8/3)
[root@fluffy.bunny ~]# systemctl status dev-md125.device
● dev-md125.device - /dev/md125
    Follows: unit currently follows state of sys-devices-virtual-block-md125.device
     Loaded: loaded
     Active: active (plugged) since Mon 2023-01-30 03:57:06 UTC; 12h ago
      Until: Mon 2023-01-30 03:57:06 UTC; 12h ago
     Device: /sys/devices/virtual/block/md125

Jan 30 03:57:06 fluffy.bunny systemd[1]: dev-md125.device: Changed dead -> plugged

[root@fluffy.bunny ~]# journalctl -u dev-md127.device
Jan 30 03:56:58 fluffy.bunny systemd[1]: dev-md127.device: Changed dead -> plugged
Jan 30 03:56:59 fluffy.bunny systemd[1]: dev-md127.device: Installed new job dev-md127.device/nop as 62
Jan 30 03:56:59 fluffy.bunny systemd[1]: dev-md127.device: Job 62 dev-md127.device/nop finished, result=done
Jan 30 03:56:59 fluffy.bunny systemd[1]: dev-md127.device: Changed dead -> plugged
Jan 30 03:57:03 fluffy.bunny systemd[1]: dev-md127.device: Changed dead -> plugged
Jan 30 03:57:03 fluffy.bunny systemd[1]: dev-md127.device: Changed plugged -> dead
Jan 30 03:57:03 fluffy.bunny systemd[1]: dev-md127.device: Collecting.
Jan 30 03:57:03 fluffy.bunny systemd[1]: dev-md127.device: Changed dead -> tentative
Jan 30 03:57:06 fluffy.bunny systemd[1]: dev-md127.device: Changed tentative -> plugged

[root@fluffy.bunny ~]# systemctl status /sys/devices/virtual/block/md127
● sys-devices-virtual-block-md127.device - /sys/devices/virtual/block/md127
     Loaded: loaded
     Active: active (plugged) since Mon 2023-01-30 03:57:06 UTC; 12h ago
      Until: Mon 2023-01-30 03:57:06 UTC; 12h ago
     Device: /sys/devices/virtual/block/md127

Jan 30 03:57:06 fluffy.bunny systemd[1]: sys-devices-virtual-block-md127.device: Changed dead -> plugged
[root@fluffy.bunny ~]# journalctl -u /sys/devices/virtual/block/md127
Jan 30 03:56:58 fluffy.bunny systemd[1]: sys-devices-virtual-block-md127.device: Changed dead -> plugged
Jan 30 03:56:59 fluffy.bunny systemd[1]: sys-devices-virtual-block-md127.device: Installed new job sys-devices-virtual-block-md127.device/nop as 63
Jan 30 03:56:59 fluffy.bunny systemd[1]: sys-devices-virtual-block-md127.device: Job 63 sys-devices-virtual-block-md127.device/nop finished, result=done
Jan 30 03:56:59 fluffy.bunny systemd[1]: sys-devices-virtual-block-md127.device: Changed dead -> plugged
Jan 30 03:57:03 fluffy.bunny systemd[1]: sys-devices-virtual-block-md127.device: Changed dead -> plugged
Jan 30 03:57:03 fluffy.bunny systemd[1]: sys-devices-virtual-block-md127.device: Changed plugged -> dead
Jan 30 03:57:03 fluffy.bunny systemd[1]: sys-devices-virtual-block-md127.device: Collecting.
Jan 30 03:57:06 fluffy.bunny systemd[1]: sys-devices-virtual-block-md127.device: Changed dead -> plugged

[root@fluffy.bunny ~]# dmesg | grep md127 -C2
[   11.215246] md125: detected capacity change from 0 to 2097024
[   11.222377] md/raid10:md126: active with 4 out of 4 devices
[   11.222408] md/raid10:md127: active with 4 out of 4 devices
[   11.222423] md/raid10:md124: active with 4 out of 4 devices
[   11.222437] md124: detected capacity change from 0 to 209580032
[   11.243004] md126: detected capacity change from 0 to 1048047616
[   11.247661] md127: detected capacity change from 0 to 209580032
[   11.810536] systemd-journald[622]: Successfully sent stream file descriptor to service manager.
[   11.810608] systemd-journald[622]: Successfully sent stream file descriptor to service manager.
[   11.829314] systemd-journald[622]: Successfully sent stream file descriptor to service manager.
[   11.895256] systemd-journald[622]: Successfully sent stream file descriptor to service manager.
[   11.992866] EXT4-fs (md127): mounted filesystem with ordered data mode. Quota mode: none.
[   12.020434] systemd-journald[622]: Successfully sent stream file descriptor to service manager.
[   12.057483] systemd-fstab-generator[1210]: Found entry what=/dev/disk/by-label/root where=/sysroot type=n/a opts=ro
--
[   13.283306] systemd-gpt-auto-generator[1279]: Disabling root partition auto-detection, root= is defined.
[   13.283395] systemd-gpt-auto-generator[1279]: Failed to chase block device, ignoring: Name not unique on network
[   13.283539] systemd-gpt-auto-generator[1279]: md127: Not a partitioned device, ignoring: No such file or directory
[   13.295884] systemd-rc-local-generator[1282]: /etc/rc.d/rc.local is not marked executable, skipping.
[   13.315700] systemd-fstab-generator[1277]: SELinux enabled state cached to: disabled
--
[   14.510269] systemd-journald[1305]: Successfully sent stream file descriptor to service manager.
[   14.520658] systemd-journald[1305]: Successfully sent stream file descriptor to service manager.
[   14.525264] EXT4-fs (md127): re-mounted. Quota mode: none.
[   14.655181] systemd-journald[1305]: Successfully sent stream file descriptor to service manager.
[   14.665264] systemd-journald[1305]: Successfully sent stream file descriptor to service manager.
--
[   16.185531] systemd-gpt-auto-generator[1569]: Disabling root partition auto-detection, root= is defined.
[   16.185621] systemd-gpt-auto-generator[1569]: Failed to chase block device, ignoring: Name not unique on network
[   16.185772] systemd-gpt-auto-generator[1569]: md127: Not a partitioned device, ignoring: No such file or directory
[   16.186126] systemd-hibernate-resume-generator[1571]: Not running in an initrd, quitting.
[   16.186562] systemd-rc-local-generator[1573]: /etc/rc.d/rc.local is not marked executable, skipping.

@yuwata
Copy link
Member

yuwata commented Jan 30, 2023

We had similar issues, and we have modified the device enumeration logic recently to fix the issues. So, please try to reproduce the issue with an recent release or the current git HEAD. I hope the issue is already fixed.

@anish
Copy link
Author

anish commented Jan 30, 2023

@yuwata will do. Is there a specific set of fixes I should be looking for ?

@yuwata
Copy link
Member

yuwata commented Jan 30, 2023

I guess the related issues are #12953, #23208, and #23429.

These issues are fixed by 75d7b59 (cherry-picked as c293996, in v250.9), cf1ac0c (cherry-picked as a96ef94, in v250.9), and 4fc69e8 (Not backported to v250-stable yet).

I have not deeply checked your issue is actually the same as one of the above issues, but sounds similar.

@anish
Copy link
Author

anish commented Jan 30, 2023

thanks, I will try a cherry pick of 4fc69e8 to systemd-250-12.el9_1
I'm assuming the others are not required since it's already > 250.9, but will double check

@yuwata
Copy link
Member

yuwata commented Jan 30, 2023

Yes. Please. The above list may not complete. If 4fc69e8 does not help you, then please try to find relative commits for src/core/device.c, or try to reproduce the issue with newer release or the current git HEAD. Thank you. (Or, of course, as @poettering said, please contact to your distro.)

@anish
Copy link
Author

anish commented Jan 30, 2023

I'm doing both at the same time. On the distro side, tried launching systemd under strace and the delay introduced by strace does mitigate this to a large extent, pointing to some kinda of race condition. Still no clue as to why first boot would make a difference. I'll post back after testing with cherry picks as well as tip of tree both

@anish
Copy link
Author

anish commented Jan 31, 2023

On a very small sample space,
c293996
a96ef94
4fc69e8
together cherry picked on top of systemd-250-12.el9_1 does fix the problem for me

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug 🐛 Programming errors, that need preferential fixing udev
Milestone
No milestone
Development

No branches or pull requests
3 participants
@anish @poettering @yuwata