[Bug 1129487] New: Since kernel 5.0.1-1 boot is being delayed by "a stop job is running for udev Kernel Device Manager"

older
[Bug 1132088] New:...

bugzilla_noreply＠novell.com

17 Mar 2019 17 Mar '19

12:52

http://bugzilla.opensuse.org/show_bug.cgi?id=1129487 Bug ID: 1129487 Summary: Since kernel 5.0.1-1 boot is being delayed by "a stop job is running for udev Kernel Device Manager" Classification: openSUSE Product: openSUSE Tumbleweed Version: Current Hardware: x86-64 OS: Other Status: NEW Severity: Normal Priority: P5 - None Component: Kernel Assignee: kernel-maintainers@forge.provo.novell.com Reporter: paul.pgp-7@gmx.com QA Contact: qa-bugs@suse.de Found By: --- Blocker: --- TW snapshot 20190314 brought in V 5.0.1-1-default kernel. Since then, at every boot, I'm getting a 17sec delay part way through the boot process. I'm not using plymouth and see the message "a stop job is running for udev Kernel Device Manager" which lasts for 17sec (out of the 1m 30s timeout limit). Boot then continues as normal. There have been no changes to this machine other than a "zypper dup" from 20190312 to 20190314. If I boot using the previous 4.20.13-1 kernel I don't get the delay. This is running on a quite elderly AMD Athlon 64x2 based system. I guess this may be hardware specific. I initially posted to the openSuse user forum ( https://forums.opensuse.org/showthread.php/535308-Increased-boot-time-since-... ) where other users reported not seeing the problem. -- You are receiving this mail because: You are on the CC list for the bug.

Attachments:

attachment.htm (text/html — 3.1 KB)

Show replies by date

bugzilla_noreply＠novell.com

21 Mar 21 Mar

11:11

New subject: [Bug 1129487] Since kernel 5.0.1-1 boot is being delayed by "a stop job is running for udev Kernel Device Manager"

http://bugzilla.opensuse.org/show_bug.cgi?id=1129487 http://bugzilla.opensuse.org/show_bug.cgi?id=1129487#c3 --- Comment #3 from Paul Tannington --- I'm now on kernel 5.0.2-1 and this has changed the behaviour slightly in as much as the stop job now runs for 10-11secs rather than the 17secs I was seeing with 5.0.1-1. It consistently does this on every boot. Unfortunately when I append "debug printk.devmsg=on" to the kernel command line I no longer see the stop job message and boot appears to be normal. I have tried this multiple times, using both reboots and cold starts, with debug enabled it doesn't happen... If I boot normally, then again I see the "marching" red asterisks and "A stop job is running for udev Kernel Device Manager" with the timeout countdown timer. After which the boot then continues (as shown on screen) with: Stopped udev Kernel Device Manager. Stopped Create Static Device Nodes in /dev. and boot completes. Below is a section of the log for one of those boots. Mar 21 08:59:19 Orion-15 systemd[1]: Stopping udev Kernel Device Manager... Mar 21 08:59:19 Orion-15 systemd[1]: systemd-modules-load.service: Succeeded. Mar 21 08:59:19 Orion-15 systemd[1]: Stopped Load Kernel Modules. Mar 21 08:59:20 Orion-15 systemd[1]: Stopped target Remote File Systems (Pre). Mar 21 08:59:20 Orion-15 systemd[1]: Stopped target Timers. Mar 21 08:59:20 Orion-15 systemd[1]: Stopped target Paths. Mar 21 08:59:20 Orion-15 haveged[203]: haveged: listening socket at 3 Mar 21 08:59:20 Orion-15 systemd[1]: systemd-ask-password-console.path: Succeeded. Mar 21 08:59:20 Orion-15 systemd[1]: Stopped Dispatch Password Requests to Console Directory Watch. Mar 21 08:59:20 Orion-15 systemd[1]: haveged-switch-root.service: Succeeded. Mar 21 08:59:20 Orion-15 systemd[1]: Started Tell haveged about new root. Mar 21 08:59:20 Orion-15 systemd[1]: initrd-cleanup.service: Succeeded. Mar 21 08:59:20 Orion-15 systemd[1]: Started Cleaning Up and Shutting Down Daemons. Mar 21 08:59:21 Orion-15 haveged[203]: haveged: Fail:set_watermark()! Mar 21 08:59:21 Orion-15 haveged[203]: haveged starting up Mar 21 08:59:21 Orion-15 systemd[1]: haveged.service: Main process exited, code=exited, status=1/FAILURE Mar 21 08:59:21 Orion-15 systemd[1]: haveged.service: Failed with result 'exit-code'. Mar 21 08:59:21 Orion-15 systemd[1]: haveged.service: Service RestartSec=100ms expired, scheduling restart. Mar 21 08:59:21 Orion-15 systemd[1]: haveged.service: Scheduled restart job, restart counter is at 1. Mar 21 08:59:21 Orion-15 systemd[1]: Stopped Entropy Daemon based on the HAVEGE algorithm. Mar 21 08:59:22 Orion-15 systemd[1]: Started Entropy Daemon based on the HAVEGE algorithm. Mar 21 08:59:22 Orion-15 haveged[408]: haveged: listening socket at 3 Mar 21 08:59:25 Orion-15 kernel: scsi 6:0:0:3: Direct-Access Kingston FCR-HS219/1 9745 PQ: 0 ANSI: 0 Mar 21 08:59:25 Orion-15 kernel: sd 6:0:0:3: Attached scsi generic sg7 type 0 Mar 21 08:59:25 Orion-15 kernel: sd 6:0:0:3: [sdg] Attached SCSI removable disk Mar 21 08:59:30 Orion-15 systemd[1]: systemd-udevd.service: Succeeded. Mar 21 08:59:30 Orion-15 systemd[1]: Stopped udev Kernel Device Manager. Mar 21 08:59:30 Orion-15 systemd[1]: systemd-tmpfiles-setup-dev.service: Succeeded. Mar 21 08:59:30 Orion-15 systemd[1]: Stopped Create Static Device Nodes in /dev. which looking at the time stamps for "Stopping udev Kernel Device Manager..." and "Stopped udev Kernel Device Manager." correlates to the 10-11 secs I see the stop job running for. I could attach the complete logs, both for a non-debug boot (where the problem occurs), and a boot with the debug information. Although as I say, when debug is enabled I don't see the stop job running message, so I doubt that is of much use? -- You are receiving this mail because: You are on the CC list for the bug.

bugzilla_noreply＠novell.com

13:09

New subject: [Bug 1129487] Since kernel 5.0.1-1 boot is being delayed by "a stop job is running for udev Kernel Device Manager"

http://bugzilla.opensuse.org/show_bug.cgi?id=1129487 http://bugzilla.opensuse.org/show_bug.cgi?id=1129487#c4 --- Comment #4 from Franck Bui --- (In reply to Franck Bui from comment #2)

...

It's surprising that udev itself takes so long to start.

So I misread your initial comment: the hang happens just before switching to rootfs when all services are requested to stop. Since the full debug logs have a negative side effect for reproducing, can you try to enable udev debug logs only and see if you can still reproduce ? (append "rd.udev.log_priority=debug" to the kernel command line). Also frpm the last logs you showed:

...

Mar 21 08:59:25 Orion-15 kernel: sd 6:0:0:3: [sdg] Attached SCSI removable disk

Can you try to remove this disk before booting and see if it helps ? Thanks. -- You are receiving this mail because: You are on the CC list for the bug.

bugzilla_noreply＠novell.com

15:55

New subject: [Bug 1129487] Since kernel 5.0.1-1 boot is being delayed by "a stop job is running for udev Kernel Device Manager"

http://bugzilla.opensuse.org/show_bug.cgi?id=1129487 http://bugzilla.opensuse.org/show_bug.cgi?id=1129487#c5 --- Comment #5 from Paul Tannington --- Taking your last question first... With the device removed, I don't see the stop job running. (I tried five consecutive reboots). Mar 21 14:42:03 Orion-15 systemd[1]: Stopped dracut pre-trigger hook. Mar 21 14:42:03 Orion-15 systemd[1]: Stopping udev Kernel Device Manager... Mar 21 14:42:03 Orion-15 systemd[1]: Stopped target Initrd Root Device. Mar 21 14:42:03 Orion-15 systemd[1]: Stopped target Paths. Mar 21 14:42:03 Orion-15 systemd[1]: systemd-ask-password-console.path: Succeeded. Mar 21 14:42:03 Orion-15 systemd[1]: Stopped Dispatch Password Requests to Console Directory Watch. Mar 21 14:42:03 Orion-15 systemd[1]: Stopped target Sockets. Mar 21 14:42:03 Orion-15 systemd[1]: systemd-udevd.service: Succeeded. Mar 21 14:42:03 Orion-15 systemd[1]: Stopped udev Kernel Device Manager. Mar 21 14:42:03 Orion-15 systemd[1]: haveged-switch-root.service: Succeeded. Mar 21 14:42:03 Orion-15 systemd[1]: Started Tell haveged about new root. Mar 21 14:42:03 Orion-15 systemd[1]: systemd-tmpfiles-setup-dev.service: Succeeded. Mar 21 14:42:03 Orion-15 systemd[1]: Stopped Create Static Device Nodes in /dev. The device is not a disk per se, it's an external card reader connected via a USB2 port. I leave it permanently plugged in as it's used almost every day to transfer images from digital camera CF cards. https://www.kingston.com/en/support/technical/products?model=fcr-hs219 After reattaching the device and rebooting the issue returned. Appending "rd.udev.log_priority=debug" to the kernel command line was this time successful, although it doesn't happen on every boot, it took three attempts before I saw the stop job running. Here is a fragment of the log from "Stopping udev Kernel Device Manager..." to "Stopped udev Kernel Device Manager." Mar 21 15:31:45 Orion-15 systemd[1]: Stopping udev Kernel Device Manager... Mar 21 15:31:45 Orion-15 systemd-udevd[310]: Process '/usr/bin/sg_inq --export --inhex=/sys/class/scsi_device/6:0:0:1/device/inquiry --raw' succeeded. Mar 21 15:31:45 Orion-15 systemd-udevd[310]: sde: IMPORT '/usr/bin/sg_inq --export --inhex=/sys/class/scsi_device/6:0:0:1/device/vpd_pg80 --raw' /usr/lib/udev/rules.d/55-scsi-sg3_id.rules:62 Mar 21 15:31:45 Orion-15 systemd-udevd[310]: Starting '/usr/bin/sg_inq --export --inhex=/sys/class/scsi_device/6:0:0:1/device/vpd_pg80 --raw' Mar 21 15:31:45 Orion-15 systemd-udevd[310]: Successfully forked off '(spawn)' as PID 401. Mar 21 15:31:45 Orion-15 haveged[203]: haveged: listening socket at 3 Mar 21 15:31:45 Orion-15 systemd-udevd[310]: '/usr/bin/sg_inq --export --inhex=/sys/class/scsi_device/6:0:0:1/device/vpd_pg80 --raw'(err) 'unable to open binary file /sys/class/scsi_device/6:0:0:1/device/vpd_pg80: No such file or directory' Mar 21 15:31:45 Orion-15 systemd[1]: Stopped target Local File Systems. Mar 21 15:31:45 Orion-15 systemd-udevd[310]: Process '/usr/bin/sg_inq --export --inhex=/sys/class/scsi_device/6:0:0:1/device/vpd_pg80 --raw' failed with exit code 52. Mar 21 15:31:45 Orion-15 systemd-udevd[310]: sde: IMPORT '/usr/bin/sg_inq --export --inhex=/sys/class/scsi_device/6:0:0:1/device/vpd_pg83 --raw' /usr/lib/udev/rules.d/55-scsi-sg3_id.rules:63 Mar 21 15:31:45 Orion-15 systemd-udevd[310]: Starting '/usr/bin/sg_inq --export --inhex=/sys/class/scsi_device/6:0:0:1/device/vpd_pg83 --raw' Mar 21 15:31:45 Orion-15 systemd-udevd[310]: Successfully forked off '(spawn)' as PID 402. Mar 21 15:31:45 Orion-15 systemd-udevd[310]: '/usr/bin/sg_inq --export --inhex=/sys/class/scsi_device/6:0:0:1/device/vpd_pg83 --raw'(err) 'unable to open binary file /sys/class/scsi_device/6:0:0:1/device/vpd_pg83: No such file or directory' Mar 21 15:31:45 Orion-15 systemd[1]: Stopped target Local File Systems (Pre). Mar 21 15:31:45 Orion-15 systemd[1]: Stopped target Paths. Mar 21 15:31:45 Orion-15 systemd-udevd[310]: Process '/usr/bin/sg_inq --export --inhex=/sys/class/scsi_device/6:0:0:1/device/vpd_pg83 --raw' failed with exit code 52. Mar 21 15:31:45 Orion-15 systemd-udevd[310]: sde: LINK 'disk/by-id/usb-Kingston_FCR-HS219_1_101901001299-0:1' /usr/lib/udev/rules.d/60-persistent-storage.rules:54 Mar 21 15:31:45 Orion-15 systemd-udevd[310]: sde: IMPORT builtin skip 'path_id' /usr/lib/udev/rules.d/60-persistent-storage.rules:78 Mar 21 15:31:45 Orion-15 systemd-udevd[310]: sde: LINK 'disk/by-path/pci-0000:00:13.5-usb-0:5:1.0-scsi-0:0:0:1' /usr/lib/udev/rules.d/60-persistent-storage.rules:80 Mar 21 15:31:45 Orion-15 systemd-udevd[310]: sde: IMPORT builtin 'blkid' /usr/lib/udev/rules.d/60-persistent-storage.rules:95 Mar 21 15:31:45 Orion-15 systemd-udevd[310]: sde: Failed to open block device /dev/sde: No medium found Mar 21 15:31:45 Orion-15 systemd-udevd[310]: sde: IMPORT builtin 'blkid' fails: No medium found Mar 21 15:31:45 Orion-15 systemd-udevd[310]: sde: Handling device node '/dev/sde', devnum=b8:64, mode=0600, uid=0, gid=0 Mar 21 15:31:45 Orion-15 systemd-udevd[310]: sde: Preserve already existing symlink '/dev/block/8:64' to '../sde' Mar 21 15:31:45 Orion-15 systemd-udevd[310]: sde: Found 'b8:64' claiming '/run/udev/links/\x2fdisk\x2fby-id\x2fusb-Kingston_FCR-HS219_1_101901001299-0:1' Mar 21 15:31:45 Orion-15 systemd-udevd[310]: sde: Preserve already existing symlink '/dev/disk/by-id/usb-Kingston_FCR-HS219_1_101901001299-0:1' to '../../sde' Mar 21 15:31:45 Orion-15 systemd-udevd[310]: sde: Found 'b8:64' claiming '/run/udev/links/\x2fdisk\x2fby-path\x2fpci-0000:00:13.5-usb-0:5:1.0-scsi-0:0:0:1' Mar 21 15:31:45 Orion-15 systemd-udevd[310]: sde: Preserve already existing symlink '/dev/disk/by-path/pci-0000:00:13.5-usb-0:5:1.0-scsi-0:0:0:1' to '../../sde' Mar 21 15:31:45 Orion-15 systemd-udevd[310]: sde: sd-device: Created db file '/run/udev/data/b8:64' for '/devices/pci0000:00/0000:00:13.5/usb1/1-5/1-5:1.0/host6/target6:0:0/6:0:0:1/block/sde' Mar 21 15:31:45 Orion-15 systemd-udevd[310]: sde: Adding watch on '/dev/sde' Mar 21 15:31:45 Orion-15 systemd-udevd[310]: sde: sd-device: Created db file '/run/udev/data/b8:64' for '/devices/pci0000:00/0000:00:13.5/usb1/1-5/1-5:1.0/host6/target6:0:0/6:0:0:1/block/sde' Mar 21 15:31:45 Orion-15 systemd-udevd[310]: sde: Device (SEQNUM=1426, ACTION=change) processed Mar 21 15:31:45 Orion-15 systemd-udevd[310]: sde: sd-device-monitor: Passed 1139 byte to netlink monitor Mar 21 15:31:45 Orion-15 systemd-udevd[310]: Unload module index Mar 21 15:31:45 Orion-15 systemd-udevd[310]: Unloaded link configuration context. Mar 21 15:31:45 Orion-15 systemd-udevd[276]: Worker [310] exited Mar 21 15:31:45 Orion-15 systemd[1]: systemd-ask-password-console.path: Succeeded. Mar 21 15:31:45 Orion-15 systemd[1]: Stopped Dispatch Password Requests to Console Directory Watch. Mar 21 15:31:45 Orion-15 systemd[1]: dracut-cmdline-ask.service: Succeeded. Mar 21 15:31:45 Orion-15 systemd[1]: Stopped dracut ask for additional cmdline parameters. Mar 21 15:31:45 Orion-15 systemd[1]: haveged-switch-root.service: Succeeded. Mar 21 15:31:45 Orion-15 systemd[1]: Started Tell haveged about new root. Mar 21 15:31:45 Orion-15 systemd[1]: initrd-cleanup.service: Succeeded. Mar 21 15:31:45 Orion-15 systemd[1]: Started Cleaning Up and Shutting Down Daemons. Mar 21 15:31:46 Orion-15 haveged[203]: haveged: Fail:set_watermark()! Mar 21 15:31:46 Orion-15 haveged[203]: haveged starting up Mar 21 15:31:46 Orion-15 systemd[1]: haveged.service: Main process exited, code=exited, status=1/FAILURE Mar 21 15:31:46 Orion-15 systemd[1]: haveged.service: Failed with result 'exit-code'. Mar 21 15:31:47 Orion-15 systemd[1]: haveged.service: Service RestartSec=100ms expired, scheduling restart. Mar 21 15:31:47 Orion-15 systemd[1]: haveged.service: Scheduled restart job, restart counter is at 1. Mar 21 15:31:47 Orion-15 systemd[1]: Stopped Entropy Daemon based on the HAVEGE algorithm. Mar 21 15:31:47 Orion-15 systemd[1]: Started Entropy Daemon based on the HAVEGE algorithm. Mar 21 15:31:47 Orion-15 haveged[403]: haveged: listening socket at 3 Mar 21 15:31:51 Orion-15 kernel: scsi 6:0:0:2: Direct-Access Kingston FCR-HS219/1 9745 PQ: 0 ANSI: 0 Mar 21 15:31:51 Orion-15 kernel: sd 6:0:0:2: Attached scsi generic sg6 type 0 Mar 21 15:31:51 Orion-15 kernel: sd 6:0:0:2: [sdf] Attached SCSI removable disk Mar 21 15:31:51 Orion-15 kernel: scsi 6:0:0:3: Direct-Access Kingston FCR-HS219/1 9745 PQ: 0 ANSI: 0 Mar 21 15:31:51 Orion-15 kernel: sd 6:0:0:3: Attached scsi generic sg7 type 0 Mar 21 15:31:51 Orion-15 kernel: sd 6:0:0:3: [sdg] Attached SCSI removable disk Mar 21 15:31:56 Orion-15 kernel: sd 6:0:0:0: [sdd] Attached SCSI removable disk Mar 21 15:31:56 Orion-15 systemd-udevd[306]: sdd: GROUP 6 /usr/lib/udev/rules.d/50-udev-default.rules:59 Mar 21 15:31:56 Orion-15 systemd-udevd[306]: sdd: IMPORT builtin 'usb_id' /usr/lib/udev/rules.d/54-before-scsi-sg3_id.rules:35 Mar 21 15:31:56 Orion-15 systemd-udevd[306]: 1-5:1.0: if_class:8 protocol:6 Mar 21 15:31:56 Orion-15 systemd-udevd[306]: sdd: IMPORT builtin 'path_id' /usr/lib/udev/rules.d/54-before-scsi-sg3_id.rules:41 Mar 21 15:31:56 Orion-15 systemd-udevd[306]: sdd: IMPORT '/usr/bin/sg_inq --export --inhex=/sys/class/scsi_device/6:0:0:0/device/inquiry --raw' /usr/lib/udev/rules.d/55-scsi-sg3_id.rules:58 Mar 21 15:31:56 Orion-15 systemd-udevd[306]: Starting '/usr/bin/sg_inq --export --inhex=/sys/class/scsi_device/6:0:0:0/device/inquiry --raw' Mar 21 15:31:56 Orion-15 systemd-udevd[306]: Successfully forked off '(spawn)' as PID 404. Mar 21 15:31:56 Orion-15 systemd-udevd[306]: '/usr/bin/sg_inq --export --inhex=/sys/class/scsi_device/6:0:0:0/device/inquiry --raw'(out) 'SCSI_TPGS=0' Mar 21 15:31:56 Orion-15 systemd-udevd[306]: '/usr/bin/sg_inq --export --inhex=/sys/class/scsi_device/6:0:0:0/device/inquiry --raw'(out) 'SCSI_TYPE=disk' Mar 21 15:31:56 Orion-15 systemd-udevd[306]: '/usr/bin/sg_inq --export --inhex=/sys/class/scsi_device/6:0:0:0/device/inquiry --raw'(out) 'SCSI_VENDOR=Kingston' Mar 21 15:31:56 Orion-15 systemd-udevd[306]: '/usr/bin/sg_inq --export --inhex=/sys/class/scsi_device/6:0:0:0/device/inquiry --raw'(out) 'SCSI_VENDOR_ENC=Kingston' Mar 21 15:31:56 Orion-15 systemd-udevd[306]: '/usr/bin/sg_inq --export --inhex=/sys/class/scsi_device/6:0:0:0/device/inquiry --raw'(out) 'SCSI_MODEL=FCR-HS219/1' Mar 21 15:31:56 Orion-15 systemd-udevd[306]: '/usr/bin/sg_inq --export --inhex=/sys/class/scsi_device/6:0:0:0/device/inquiry --raw'(out) 'SCSI_MODEL_ENC=FCR-HS219/1\x20\x20\x20\x20\x20' Mar 21 15:31:56 Orion-15 systemd-udevd[306]: '/usr/bin/sg_inq --export --inhex=/sys/class/scsi_device/6:0:0:0/device/inquiry --raw'(out) 'SCSI_REVISION=9745' Mar 21 15:31:56 Orion-15 systemd-udevd[306]: Process '/usr/bin/sg_inq --export --inhex=/sys/class/scsi_device/6:0:0:0/device/inquiry --raw' succeeded. Mar 21 15:31:56 Orion-15 systemd-udevd[306]: sdd: IMPORT '/usr/bin/sg_inq --export --inhex=/sys/class/scsi_device/6:0:0:0/device/vpd_pg80 --raw' /usr/lib/udev/rules.d/55-scsi-sg3_id.rules:62 Mar 21 15:31:56 Orion-15 systemd-udevd[306]: Starting '/usr/bin/sg_inq --export --inhex=/sys/class/scsi_device/6:0:0:0/device/vpd_pg80 --raw' Mar 21 15:31:56 Orion-15 systemd-udevd[306]: Successfully forked off '(spawn)' as PID 405. Mar 21 15:31:56 Orion-15 systemd-udevd[306]: '/usr/bin/sg_inq --export --inhex=/sys/class/scsi_device/6:0:0:0/device/vpd_pg80 --raw'(err) 'unable to open binary file /sys/class/scsi_device/6:0:0:0/device/vpd_pg80: No such file or directory' Mar 21 15:31:56 Orion-15 systemd-udevd[306]: Process '/usr/bin/sg_inq --export --inhex=/sys/class/scsi_device/6:0:0:0/device/vpd_pg80 --raw' failed with exit code 52. Mar 21 15:31:56 Orion-15 systemd-udevd[306]: sdd: IMPORT '/usr/bin/sg_inq --export --inhex=/sys/class/scsi_device/6:0:0:0/device/vpd_pg83 --raw' /usr/lib/udev/rules.d/55-scsi-sg3_id.rules:63 Mar 21 15:31:56 Orion-15 systemd-udevd[306]: Starting '/usr/bin/sg_inq --export --inhex=/sys/class/scsi_device/6:0:0:0/device/vpd_pg83 --raw' Mar 21 15:31:56 Orion-15 systemd-udevd[306]: Successfully forked off '(spawn)' as PID 406. Mar 21 15:31:56 Orion-15 systemd-udevd[306]: '/usr/bin/sg_inq --export --inhex=/sys/class/scsi_device/6:0:0:0/device/vpd_pg83 --raw'(err) 'unable to open binary file /sys/class/scsi_device/6:0:0:0/device/vpd_pg83: No such file or directory' Mar 21 15:31:56 Orion-15 systemd-udevd[306]: Process '/usr/bin/sg_inq --export --inhex=/sys/class/scsi_device/6:0:0:0/device/vpd_pg83 --raw' failed with exit code 52. Mar 21 15:31:56 Orion-15 systemd-udevd[306]: sdd: LINK 'disk/by-id/usb-Kingston_FCR-HS219_1_101901001299-0:0' /usr/lib/udev/rules.d/60-persistent-storage.rules:54 Mar 21 15:31:56 Orion-15 systemd-udevd[306]: sdd: IMPORT builtin skip 'path_id' /usr/lib/udev/rules.d/60-persistent-storage.rules:78 Mar 21 15:31:56 Orion-15 systemd-udevd[306]: sdd: LINK 'disk/by-path/pci-0000:00:13.5-usb-0:5:1.0-scsi-0:0:0:0' /usr/lib/udev/rules.d/60-persistent-storage.rules:80 Mar 21 15:31:56 Orion-15 systemd-udevd[306]: sdd: IMPORT builtin 'blkid' /usr/lib/udev/rules.d/60-persistent-storage.rules:95 Mar 21 15:31:56 Orion-15 systemd-udevd[306]: sdd: Failed to open block device /dev/sdd: No medium found Mar 21 15:31:56 Orion-15 systemd-udevd[306]: sdd: IMPORT builtin 'blkid' fails: No medium found Mar 21 15:31:56 Orion-15 systemd-udevd[306]: sdd: Handling device node '/dev/sdd', devnum=b8:48, mode=0660, uid=0, gid=6 Mar 21 15:31:56 Orion-15 systemd-udevd[306]: sdd: Setting permissions /dev/sdd, 060660, uid=0, gid=6 Mar 21 15:31:56 Orion-15 systemd-udevd[306]: sdd: Creating symlink '/dev/block/8:48' to '../sdd' Mar 21 15:31:56 Orion-15 systemd-udevd[306]: sdd: Creating symlink '/dev/disk/by-id/usb-Kingston_FCR-HS219_1_101901001299-0:0' to '../../sdd' Mar 21 15:31:56 Orion-15 systemd-udevd[306]: sdd: Creating symlink '/dev/disk/by-path/pci-0000:00:13.5-usb-0:5:1.0-scsi-0:0:0:0' to '../../sdd' Mar 21 15:31:56 Orion-15 systemd-udevd[306]: sdd: sd-device: Created db file '/run/udev/data/b8:48' for '/devices/pci0000:00/0000:00:13.5/usb1/1-5/1-5:1.0/host6/target6:0:0/6:0:0:0/block/sdd' Mar 21 15:31:56 Orion-15 systemd-udevd[306]: sdd: Adding watch on '/dev/sdd' Mar 21 15:31:56 Orion-15 systemd-udevd[306]: sdd: sd-device: Created db file '/run/udev/data/b8:48' for '/devices/pci0000:00/0000:00:13.5/usb1/1-5/1-5:1.0/host6/target6:0:0/6:0:0:0/block/sdd' Mar 21 15:31:56 Orion-15 systemd-udevd[306]: sdd: Device (SEQNUM=1417, ACTION=add) processed Mar 21 15:31:56 Orion-15 systemd-udevd[306]: sdd: sd-device-monitor: Passed 1117 byte to netlink monitor Mar 21 15:31:56 Orion-15 systemd-udevd[306]: Unload module index Mar 21 15:31:56 Orion-15 systemd-udevd[306]: Unloaded link configuration context. Mar 21 15:31:56 Orion-15 systemd-udevd[276]: Worker [306] exited Mar 21 15:31:56 Orion-15 systemd-udevd[276]: Unload module index Mar 21 15:31:56 Orion-15 systemd-udevd[276]: Unloaded link configuration context. Mar 21 15:31:56 Orion-15 systemd[1]: systemd-udevd.service: Succeeded. Mar 21 15:31:56 Orion-15 systemd[1]: Stopped udev Kernel Device Manager. Mar 21 15:31:56 Orion-15 systemd[1]: systemd-tmpfiles-setup-dev.service: Succeeded. Mar 21 15:31:56 Orion-15 systemd[1]: Stopped Create Static Device Nodes in /dev. Mar 21 15:31:56 Orion-15 systemd[1]: kmod-static-nodes.service: Succeeded. Mar 21 15:31:56 Orion-15 systemd[1]: Stopped Create list of required static device nodes for the current kernel. Mar 21 15:31:56 Orion-15 systemd[1]: systemd-udevd-kernel.socket: Succeeded. The entire log is some 868k - I can attach it if required. Many thanks for your time. -- You are receiving this mail because: You are on the CC list for the bug.

bugzilla_noreply＠novell.com

22 Mar 22 Mar

07:05

New subject: [Bug 1129487] Since kernel 5.0.1-1 boot is being delayed by "a stop job is running for udev Kernel Device Manager"

http://bugzilla.opensuse.org/show_bug.cgi?id=1129487 http://bugzilla.opensuse.org/show_bug.cgi?id=1129487#c6 --- Comment #6 from Franck Bui --- (In reply to Paul Tannington from comment #5)

...

The entire log is some 868k - I can attach it if required.

Yes please attach the entire log preferably by running "journalctl -b -o short-monotonic". -- You are receiving this mail because: You are on the CC list for the bug.

bugzilla_noreply＠novell.com

09:41

New subject: [Bug 1129487] Since kernel 5.0.1-1 boot is being delayed by "a stop job is running for udev Kernel Device Manager"

http://bugzilla.opensuse.org/show_bug.cgi?id=1129487 http://bugzilla.opensuse.org/show_bug.cgi?id=1129487#c7 --- Comment #7 from Paul Tannington --- Created attachment 800912 --> http://bugzilla.opensuse.org/attachment.cgi?id=800912&action=edit log file as requested OK. Log file as requested. (This is a later log than the one from which I posted a fragment.) The stop job was running for approx 18 secs on this boot. Thanks. -- You are receiving this mail because: You are on the CC list for the bug.

bugzilla_noreply＠novell.com

10 Apr 10 Apr

08:06

New subject: [Bug 1129487] Since kernel 5.0.1-1 boot is being delayed by "a stop job is running for udev Kernel Device Manager"

http://bugzilla.opensuse.org/show_bug.cgi?id=1129487 http://bugzilla.opensuse.org/show_bug.cgi?id=1129487#c8 --- Comment #8 from Franck Bui --- Hmm I'm wondering if this regression couldn't have been introduced by new version of udev (241) instead even though you said that it appeared after upgrading the kernel (only). udev has received a bucnh of changes since v239. Could you try the old version of udev/systemd with the latest kernel ? You can still find the old version of udev here: https://download.opensuse.org/history/20190225/tumbleweed/repo/oss/x86_64/ Thanks. -- You are receiving this mail because: You are on the CC list for the bug.

bugzilla_noreply＠novell.com

08:51

New subject: [Bug 1129487] Since kernel 5.0.1-1 boot is being delayed by "a stop job is running for udev Kernel Device Manager"

http://bugzilla.opensuse.org/show_bug.cgi?id=1129487 http://bugzilla.opensuse.org/show_bug.cgi?id=1129487#c9 --- Comment #9 from Paul Tannington --- OK, I'll give that a try tomorrow (11th Apr), rather busy now :) Just to clarify though: The problem started immediately after a "zypper dup" from TW snapshot 20190312 to 20190314. TW snapshot 20190314 brought in V 5.0.1-1-default kernel. At that time I was still able to boot using the previous kernel, 4.20.13-1, doing so I didn't get the delay. Thanks. -- You are receiving this mail because: You are on the CC list for the bug.

bugzilla_noreply＠novell.com

10:35

New subject: [Bug 1129487] Since kernel 5.0.1-1 boot is being delayed by "a stop job is running for udev Kernel Device Manager"

http://bugzilla.opensuse.org/show_bug.cgi?id=1129487 http://bugzilla.opensuse.org/show_bug.cgi?id=1129487#c10 Franck Bui changed: What |Removed |Added ---------------------------------------------------------------------------- Status|NEW |IN_PROGRESS CC| |martin.wilck@suse.com Flags| |needinfo?(martin.wilck@suse | |.com) --- Comment #10 from Franck Bui --- Martin,

...

From the debug logs provided in comment #7:

...

[ 8.388246] Orion-15 systemd-udevd[276]: sdd: Device (SEQNUM=1405, ACTION=add) is queued

[ 8.391547] Orion-15 systemd-udevd[290]: sdd: Processing device (SEQNUM=1405, ACTION=add)

[ 8.521679] Orion-15 systemd[1]: Stopping udev Kernel Device Manager...

[ 26.132085] Orion-15 kernel: sd 6:0:0:0: [sdd] Attached SCSI removable disk [ 26.147772] Orion-15 systemd-udevd[290]: sdd: GROUP 6 /usr/lib/udev/rules.d/50-udev-default.rules:59 [ 26.148431] Orion-15 systemd-udevd[290]: sdd: IMPORT builtin 'usb_id' /usr/lib/udev/rules.d/54 [...] [...] [ 26.157478] Orion-15 systemd-udevd[290]: sdd: Device (SEQNUM=1405, ACTION=add) processed [ 26.158906] Orion-15 systemd-udevd[290]: sdd: sd-device-monitor: Passed 1117 byte to netlink monitor

[ 26.356092] Orion-15 systemd[1]: Switching root.

It seems that udev worker whose PID=290 is stuck until the following kernel trace is emitted:

...

[ 26.132085] Orion-15 kernel: sd 6:0:0:0: [sdd] Attached SCSI removable disk

I don't know why the kernel event happened long before sdd seems usable. Can this be due to a change brought by the new kernel ? Also I'm not sure where the udev worker is stuck... it should be in worker_lock_block_device()[1] either stuck at open() (although it's unlikely because O_NONBLOCK is passed) or at flock(). [1] https://github.com/openSUSE/systemd/blob/openSUSE-Factory/src/udev/udevd.c#L... -- You are receiving this mail because: You are on the CC list for the bug.

bugzilla_noreply＠novell.com

12:10

New subject: [Bug 1129487] Since kernel 5.0.1-1 boot is being delayed by "a stop job is running for udev Kernel Device Manager"

http://bugzilla.opensuse.org/show_bug.cgi?id=1129487 http://bugzilla.opensuse.org/show_bug.cgi?id=1129487#c11 --- Comment #11 from Paul Tannington --- Thought I might be able to find time this lunchtime :) However when attempting to downgrade udev and libudev1 to 239-5.1 I'm getting dependency issues: systemd-241-1.1.x86_64 requires udev = 241-1.1, ... downgrade of systemd-241-1.1.x86_64 to systemd-239-5.1.x86_64 systemd-sysvinit-241-1.1.x86_64 requires systemd = 241-1.1, ... downgrade of systemd-sysvinit-241-1.1.x86_64 to systemd-sysvinit-239-5.1.x86_64 Shall I downgrade those also and still try? (Which will now have to wait until tomorrow.) Thanks. -- You are receiving this mail because: You are on the CC list for the bug.

bugzilla_noreply＠novell.com

12:14

New subject: [Bug 1129487] Since kernel 5.0.1-1 boot is being delayed by "a stop job is running for udev Kernel Device Manager"

http://bugzilla.opensuse.org/show_bug.cgi?id=1129487 http://bugzilla.opensuse.org/show_bug.cgi?id=1129487#c12 --- Comment #12 from Franck Bui --- (In reply to Paul Tannington from comment #11)

...

Shall I downgrade those also and still try? (Which will now have to wait until tomorrow.)

Yes please also downgrade all dependencies. -- You are receiving this mail because: You are on the CC list for the bug.

bugzilla_noreply＠novell.com

20:31

New subject: [Bug 1129487] Since kernel 5.0.1-1 boot is being delayed by "a stop job is running for udev Kernel Device Manager"

http://bugzilla.opensuse.org/show_bug.cgi?id=1129487 http://bugzilla.opensuse.org/show_bug.cgi?id=1129487#c13 Martin Wilck changed: What |Removed |Added ---------------------------------------------------------------------------- CC| |paul.pgp-7@gmx.com Flags|needinfo?(martin.wilck@suse |needinfo?(paul.pgp-7@gmx.co |.com) |m) --- Comment #13 from Martin Wilck --- (In reply to Franck Bui from comment #10)

...

It seems that udev worker whose PID=290 is stuck until the following kernel trace is emitted:

...
[ 26.132085] Orion-15 kernel: sd 6:0:0:0: [sdd] Attached SCSI removable disk

Yes, and strangely, it's stuck before it even starts doing anything.

...

I don't know why the kernel event happened long before sdd seems usable. Can this be due to a change brought by the new kernel ?

Between the generation of the ADD uevent and the "Attached SCSI removable disk" message, there's at least one sd_revalidate_disk() call. But that's definitely not new. I can see one change in sd_revalidate_disk() that came with v5.0, e4a056987 "scsi: sd: fix entropy gathering for most rotational disks". I don't know why it would matter, but once we know if it's udev or the kernel, we could try it.

...

Also I'm not sure where the udev worker is stuck... it should be in worker_lock_block_device()[1] either stuck at open() (although it's unlikely because O_NONBLOCK is passed) or at flock().

The SCSI device might be blocked, because it's not yet fully initialized after the ADD event. I haven't checked all details, but that might explain it. -- You are receiving this mail because: You are on the CC list for the bug.

bugzilla_noreply＠novell.com

20:35

New subject: [Bug 1129487] Since kernel 5.0.1-1 boot is being delayed by "a stop job is running for udev Kernel Device Manager"

http://bugzilla.opensuse.org/show_bug.cgi?id=1129487 http://bugzilla.opensuse.org/show_bug.cgi?id=1129487#c14 --- Comment #14 from Martin Wilck --- @Paul, When the system hangs 17s during boot, could you please hit Alt-Sysrq-w and provide us the journalctl output? It might help us figure out what's hanging. -- You are receiving this mail because: You are on the CC list for the bug.

bugzilla_noreply＠novell.com

11 Apr 11 Apr

07:56

New subject: [Bug 1129487] Since kernel 5.0.1-1 boot is being delayed by "a stop job is running for udev Kernel Device Manager"

http://bugzilla.opensuse.org/show_bug.cgi?id=1129487 http://bugzilla.opensuse.org/show_bug.cgi?id=1129487#c15 --- Comment #15 from Paul Tannington --- (In reply to Franck Bui from comment #12)

...

Yes please also downgrade all dependencies.

With the downgraded packages: udev-239-5.1.x86_64 libudev1-239-5.1.x86_64 systemd-239-5.1.x86_64 systemd-sysvinit-239-5.1.x86_64 and using kernel: kernel-default-5.0.5-1.2.x86_64 I've booted/rebooted this system 12 times without seeing the issue. @Martin, OK, I'll revert udev/systemd to the current V241 and get back to you later today. Thanks guys. -- You are receiving this mail because: You are on the CC list for the bug.

bugzilla_noreply＠novell.com

11:03

New subject: [Bug 1129487] Since kernel 5.0.1-1 boot is being delayed by "a stop job is running for udev Kernel Device Manager"

http://bugzilla.opensuse.org/show_bug.cgi?id=1129487 http://bugzilla.opensuse.org/show_bug.cgi?id=1129487#c16 Paul Tannington changed: What |Removed |Added ---------------------------------------------------------------------------- Flags|needinfo?(paul.pgp-7@gmx.co | |m) | --- Comment #16 from Paul Tannington --- (In reply to Martin Wilck from comment #14)

...

@Paul,

When the system hangs 17s during boot, could you please hit Alt-Sysrq-w and provide us the journalctl output?

It might help us figure out what's hanging.

This is so very weird... Having updated the udev/systemd packages back to 241-1.1 (still with the 5.0.5-1.2 kernel) upon reboot it was normal without the "a stop job is runing ..." I subsequently rebooted a couple of times and also did a few cold starts, on each occasion boot was normal. The only changes made were the downgrade to 239 followed a short time later by the upgrade back to 241 - prior to those I was seeing the delay on every boot. I'm sorry, I feel I've wasted your time. If in the course of normal use over the next few days it happens I'll use the Alt-SysRq-w sequence and attach the journal. Apologies once more and many thanks. -- You are receiving this mail because: You are on the CC list for the bug.

bugzilla_noreply＠novell.com

12:07

New subject: [Bug 1129487] Since kernel 5.0.1-1 boot is being delayed by "a stop job is running for udev Kernel Device Manager"

http://bugzilla.opensuse.org/show_bug.cgi?id=1129487 http://bugzilla.opensuse.org/show_bug.cgi?id=1129487#c17 Martin Wilck changed: What |Removed |Added ---------------------------------------------------------------------------- Status|IN_PROGRESS |RESOLVED Resolution|--- |WORKSFORME --- Comment #17 from Martin Wilck --- (In reply to Paul Tannington from comment #16)

...

I'm sorry, I feel I've wasted your time.

If in the course of normal use over the next few days it happens I'll use the Alt-SysRq-w sequence and attach the journal.

Apologies once more and many thanks.

Weird indeed. No need to apologize. I'm closing this for now; re-open if you see the issue again. -- You are receiving this mail because: You are on the CC list for the bug.

bugzilla_noreply＠novell.com

12:08

New subject: [Bug 1129487] Since kernel 5.0.1-1 boot is being delayed by "a stop job is running for udev Kernel Device Manager"

http://bugzilla.opensuse.org/show_bug.cgi?id=1129487 http://bugzilla.opensuse.org/show_bug.cgi?id=1129487#c18 --- Comment #18 from Martin Wilck --- Btw if you are using btrfs, you could attempt to reproduce with a snapshot. If you feel like it, that is. -- You are receiving this mail because: You are on the CC list for the bug.

bugzilla_noreply＠novell.com

13:18

New subject: [Bug 1129487] Since kernel 5.0.1-1 boot is being delayed by "a stop job is running for udev Kernel Device Manager"

http://bugzilla.opensuse.org/show_bug.cgi?id=1129487 http://bugzilla.opensuse.org/show_bug.cgi?id=1129487#c19 --- Comment #19 from Paul Tannington --- (In reply to Martin Wilck from comment #18)

...

Btw if you are using btrfs, you could attempt to reproduce with a snapshot. If you feel like it, that is.

ext4 I'm afraid, otherwise I'd have gave it a go. Thanks. -- You are receiving this mail because: You are on the CC list for the bug.

1848

Age (days ago)

1873

Last active (days ago)

List overview

Download

17 comments

1 participants

participants (1)

bugzilla_noreply＠novell.com

[Bug 1129487] New: Since kernel 5.0.1-1 boot is being delayed by "a stop job is running for udev Kernel Device Manager"

tags

participants (1)