A stop job is running for udev Kernel Device Manager - systemd 243.162-2 - initramfs delay

[CarbonChauvinist]

systemd version the issue has been seen with

systemd 243.162-2

systemd 243 (243.162-2-arch)
+PAM +AUDIT -SELINUX -IMA -APPARMOR +SMACK -SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=hybrid

Used distribution

ARCH

Linux 5.3.12-arch1-1 SMP PREEMPT Wed, 20 Nov 2019 19:45:16 +0000 x86_64 GNU/Linux

Expected behaviour you didn't see

normal boot including initramfs

Unexpected behaviour you saw

30 sec delay due to "A stop job is running for udev Kernel Device Manager" message

Steps to reproduce the problem

Boot with systemd initramfs with version systemd 243.162-2.

Steps to avoid - revert commit 5db454b

Dmesg from an affected boot

[ghost]

I'm affected as well by this since the upgrade to systemd 243.162

[yuwata]

cc @mwilck.

[yuwata]

Could you boot the system with udev.log_priority=debug kernel command line option?

[CarbonChauvinist]

@yuwata sure, here's the journal and the dmesg.

Interestingly, upon adding the udev.log_priority=debug kernel command line option, the first boot after that change loaded normally - here's the journal from that boot; however, subsequent boots still had the delay.

[mcaliandro]

I'm affected by the same issue too, after having updated systemd to version 243.162-2. Here, journalctl and dmesg logs with udev.log_priority=debug set on boot options.

[mwilck]

This is indeed related to my changeset #13961. However, please don't shoot the messenger. You've got 23 uevents that never finish: SEQNUM 1973-1979 and 2001-2017. This indicates that's something wrong with a few devices and/or drivers, perhaps you just never noticed so far.

You have rebooted quickly, so that at the time the system is shutting down, some workers from the system startup haven't even finished yet:

Nov 25 13:12:29 archlinux systemd-udevd[193]: ata1: Device (SEQNUM=1973, ACTION=add) is queued
Nov 25 13:12:29 archlinux systemd-udevd[193]: link1: Device (SEQNUM=1974, ACTION=add) is queued
Nov 25 13:12:29 archlinux systemd-udevd[193]: dev1.0: Device (SEQNUM=1975, ACTION=add) is queued
Nov 25 13:12:29 archlinux systemd-udevd[193]: scsi_sense_cache: Device (SEQNUM=1976, ACTION=add) is queued
....

So it seems that you have a problem with an ata device. You may want to hit alt-sysrq-w to figure out what processes are hanging. The second batch of unfinished events looks like USB:

Nov 25 13:12:29 archlinux systemd-udevd[193]: 1-3: Device (SEQNUM=2001, ACTION=add) is queued
Nov 25 13:12:29 archlinux systemd-udevd[193]: 1-3:1.0: Device (SEQNUM=2002, ACTION=add) is queued
Nov 25 13:12:29 archlinux systemd-udevd[193]: 1-3:1.1: Device (SEQNUM=2003, ACTION=add) is queued

If you don't care about the root cause and just want to reboot more quickly, you can add TimeoutStopSec=30 to systemd-udevd.service to work around this problem; it should lead to the same behavior as before (30s exit timeout for udevd), albeit with some other messages in the system log, as udevd and its workers will now be killed by systemd. You could even specify TimeoutStopSec=10 which should make your reboot faster than it used to be.

[CarbonChauvinist]

Thanks for the detailed response @mwilck. It looks like you parsed @mcaliandro logs and not mine, which is fine.

Also just to be clear this only happens on boot up for me, does not happen when shutting-down/rebooting.

I do wonder though how you identify the "23 uevents that never finish". What is the best way to identify those queued actions that never complete? I'd like to go through my logs and see if I can figure out what device/driver is causing it for me specifically.

Is it just finding all QUEUED events that don't also have a PROCESSED event? i.e Using @mcaliandro logs as an example, SEQNUM 2086 is queued in the first line, and then processed in the last line quoted below:

Nov 25 13:13:00 archsus systemd-udevd[282]: pci: Device (SEQNUM=2086, ACTION=add) is queued
Nov 25 13:13:00 archsus systemd-udevd[304]: pci: Processing device (SEQNUM=2086, ACTION=add)
Nov 25 13:13:00 archsus systemd-udevd[287]: nd: Device (SEQNUM=2080, ACTION=add) processed
Nov 25 13:13:00 archsus systemd-udevd[287]: nd: sd-device-monitor: Passed 132 byte to netlink monitor
Nov 25 13:13:00 archsus systemd-udevd[305]: nvmem: Processing device (SEQNUM=2085, ACTION=add)
Nov 25 13:13:00 archsus systemd-udevd[289]: node: Device (SEQNUM=2084, ACTION=add) processed
Nov 25 13:13:00 archsus systemd-udevd[289]: node: sd-device-monitor: Passed 134 byte to netlink monitor
Nov 25 13:13:00 archsus systemd-udevd[282]: pci: sd-device-monitor: Passed 133 byte to netlink monitor
Nov 25 13:13:00 archsus systemd-udevd[282]: nd_bus: sd-device-monitor: Passed 151 byte to netlink monitor
Nov 25 13:13:00 archsus systemd-udevd[304]: pci: Device (SEQNUM=2086, ACTION=add) processed

So I'd be looking for queued SEQNUMs that don't have a processed entry? Any insight is appreciated.

You do mention using alt-sysrq-w to figure out what processes are hanging. I've never used the 'w' key with sysrq before, only REISUB keys. But it looks like that's to:

Display list of blocked (D state) tasks

So when I experience the 30s delay in my initrd when booting, just press the alt-sysrq-w keys and it will/should display the hung tasks? If so, I will try this and post back any findings.

[mwilck]

So I'd be looking for queued SEQNUMs that don't have a processed entry? Any insight is appreciated.

Yes, that's what I did. Here's the awk script that I used. However, it turned out in #14140 that some of these may be false positives due to lost messages. Please make sure that rate limiting is off in /etc/systemd/journald.conf.

So when I experience the 30s delay in my initrd when booting, just press the alt-sysrq-w keys and it will/should display the hung tasks?

Yes. You may need to boot with sysrq_always_enabled to enable this key combo.

[mwilck]

@CarbonChauvinist, you are not using the version with my changeset #13961. If you did, you wouldn't see the messages below:

Nov 25 07:36:36 archlinux systemd-udevd[194]: Giving up waiting for workers to finish.
Nov 25 07:36:36 archlinux systemd-udevd[194]: Event loop failed: Connection timed out

In your case, the events that don't finish appear to be related to your SSD:

Nov 25 07:36:05 archlinux kernel: scsi 1:0:0:0: Direct-Access     ATA      Samsung SSD 860  3B6Q PQ: 0 ANSI: 5
Nov 25 07:36:05 archlinux systemd-udevd[194]: 1:0:0:0: Device (SEQNUM=2000, ACTION=add) is queued
Nov 25 07:36:05 archlinux systemd-udevd[194]: 1:0:0:0: Device (SEQNUM=2001, ACTION=add) is queued
Nov 25 07:36:05 archlinux systemd-udevd[194]: 1:0:0:0: Device (SEQNUM=2002, ACTION=add) is queued

How is your root device set up? I can see LVM devices, are they mapped onto that SSD?

[CarbonChauvinist]

you are not using the version with my changeset #13961. If you did, you wouldn't see the messages below

@mwilck, obviously I defer to your expertise, but this seems strange to me:

1. I'm using the standard systemd package from the arch repos, which is the same systemd being used by @mcaliandro whom you've confirmed is affected.
   Here's the line from my latest journalctl log:
   Nov 26 09:56:45 archlinux systemd[1]: systemd 243.162-2-arch running in system mode. (+PAM +AUDIT -SELINUX -IMA -APPARMOR +SMACK -SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=hybrid)
   and here's the line from the journal from @mcaliandro:
   Nov 25 13:12:29 archlinux systemd[1]: systemd 243.162-2-arch running in system mode. (+PAM +AUDIT -SELINUX -IMA -APPARMOR +SMACK -SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=hybrid)
2. In doing testing recommended on the arch forums when initially researching this issue I was instructed to edit the package build for systemd which was using commit (e51d9bf9e5ac5a6618c175cd9b5cfdc6733cd5d1) -- and by adding commit (5db454b8031c58a743cc4ee3d5d1dd01dcff17e8) to the reverts list, I no longer experienced the delay when booting.

However, it turned out in #14140 that some of these may be false positives due to lost messages. Please make sure that rate limiting is off in /etc/systemd/journald.conf.

Thanks for the awk script, I'll try that shortly. As for rate limiting/printk, I've done the following:

1. Added RateLimitIntervalSec=0s to /etc/systemd/journald.conf
2. Added printk.devkmsg=on and printk.ratelimit_burst=0 to boot parameters in /boot/loader/entries/arch.conf
3. Added log_buf_len=262144 to boot parameters in /boot/loader/entries/arch.conf

How is your root device set up? I can see LVM devices, are they mapped onto that SSD?

So the 860 is SATA SSD I have installed in my system, which contains a seperate Arch install. It does have LVM, but none that are being mounted to my new system installed to a M2/NVME 960.

Not exactly sure what you want to see related to that, but here's the fstab from the system booting to the 960:

# Static information about the filesystems.
# See fstab(5) for details.

# <file system> <dir> <type> <options> <dump> <pass>

# /dev/mapper/nvg-root
UUID=4d59661c-0a7e-41ce-8d7b-6cdb367f6e91	/         	ext4      	rw,relatime	0 1

# /dev/mapper/nvg-home
UUID=dfbfa78a-e802-42a8-ac80-bbbc155c4a8b	/home     	ext4      	rw,relatime	0 2

# /dev/nvme0n1p1
UUID=58B8-7868      	/boot     	vfat      	rw,relatime,fmask=0022,dmask=0022,codepage=437,iocharset=iso8859-1,shortname=mixed,utf8,errors=remount-ro	0 2

# /dev/nvme0n1p3
UUID=1c5bc919-96eb-49e4-abaf-a990b1452147	none      	swap      	defaults  	0 0

and a lsblk -f when booted to the 960 for good measure:

NAME         FSTYPE      LABEL UUID                                   FSAVAIL FSUSE% MOUNTPOINT
sda                                                                                  
├─sda1       vfat              A5C3-02E1                                             
└─sda2       LVM2_member       C8oFfT-ZLRh-TxMA-dk9z-vHs2-N4OE-02gjl4                
  ├─vg-root  ext4              cb215580-917a-4370-88cb-0415b7e62c99                  
  ├─vg-var   ext4              979c96e5-7dcd-4564-8a19-72d6e8094b63                  
  ├─vg-home  ext4              fb822821-f4d2-4553-8ad8-6b8e186af1c0                  
  └─vg-kvm   ext4              c2f9af45-775e-4cd6-a391-73c8ed8bbfdd                  
nvme0n1                                                                              
├─nvme0n1p1  vfat              58B8-7868                               913.2M    11% /boot
├─nvme0n1p2  LVM2_member       bdHyrn-FiMV-kDuo-4WIY-Wcje-Lo40-fkDY8Q                
│ ├─nvg-root ext4              4d59661c-0a7e-41ce-8d7b-6cdb367f6e91       36G    21% /
│ └─nvg-home ext4              dfbfa78a-e802-42a8-ac80-bbbc155c4a8b     90.6G     2% /home
└─nvme0n1p3  swap              1c5bc919-96eb-49e4-abaf-a990b1452147                  [SWAP]

On a positive note, I have confirmed that I can edit the systemd-udevd.service per your instructions to add, for instance, TimeoutStopSec=03 and it appears to alleviate the stop job delay for udevd message.

But, I'll then get other delays for starting such as "Monitoring of LVM2 Mirrors", "Create Static Devices", and "Journal something or other", sorry they do start to quick to accurately write down.

Also I've found that I need to edit /usr/lib/systemd/system/systemd-udevd.service in order for the TimeoutStopSec field to be seen by the initramfs. IOW, just adding an override.conf did not appear to pass the change to initramfs.

Here's my latest boot dmesg and journalctl, because I'm sure I was clear as mud with all the above (though it looks like the dmesg didn't capture everything from the very beginning?).

[mwilck]

OK, let's get this straight: the arch package you are using does not contain the patch that I thought we were talking about: bfde942 ("udevd: wait for workers to finish when exiting").

It only contains 5db454b ("udevd: fix crash when workers time out after exit is signal caught"), which does not change udevd's runtime behavior, it just fixes a NULL pointer dereference.

So, I dispute being responsible for this regression ;-) This does not mean that I'm unwilling to help.

[mwilck]

arch linux issue.

[mwilck]

Oops, I should have read your text more carefully. So the culprit is 5db454b, wow. This patch does nothing but defer the dereferencing of the monitor from manager_exit() to manager_free(). Trying to understand how this could cause a hang...

[mwilck]

@CarbonChauvinist, please add 030f457 as backport or patch (keeping the revert of 5db454b in place), and try again. This would be equivalent to testing #14160. I believe the problem should not occur.

[CarbonChauvinist]

@mwilck, yes, thank you! Adding 030f457 and keeping the revert of 5db454b in place appears to address the reported issue. I can confirm that I'm no longer experiencing the delay when booting.

[eocene317]

@CarbonChauvinist You can check your /etc/fstab file. If you see something duplicated, just delete them. I have solved this problem this way. May you can try it.