Bug 1216025 - System boots slowly with cdrom inserted
Summary: System boots slowly with cdrom inserted
Status: RESOLVED FIXED
Alias: None
Product: openSUSE Tumbleweed
Classification: openSUSE
Component: Kernel (show other bugs)
Version: Current
Hardware: x86-64 openSUSE Tumbleweed
: P5 - None : Normal (vote)
Target Milestone: ---
Assignee: dracut maintainers
QA Contact: E-mail List
URL:
Whiteboard:
Keywords:
Depends on:
Blocks:
 
Reported: 2023-10-07 19:37 UTC by Rafael Montes
Modified: 2023-10-20 15:32 UTC (History)
4 users (show)

See Also:
Found By: ---
Services Priority:
Business Priority:
Blocker: ---
Marketing QA Status: ---
IT Deployment: ---


Attachments
rdosreoport.txt (153.92 KB, text/plain)
2023-10-07 19:38 UTC, Rafael Montes
Details
dmesg (103.58 KB, text/plain)
2023-10-10 22:19 UTC, Rafael Montes
Details
Screenshot of Boot process (7.86 MB, image/jpeg)
2023-10-11 18:08 UTC, Rafael Montes
Details
journalctl -b -o short-monotonic (633.87 KB, text/plain)
2023-10-13 15:37 UTC, Rafael Montes
Details
journalctl -b -o short-monotonic with cd (633.87 KB, text/plain)
2023-10-13 15:39 UTC, Rafael Montes
Details
journalctl -b -o short-monotonic withoutcd (703.21 KB, text/plain)
2023-10-13 15:41 UTC, Rafael Montes
Details
rdosreport (3.60 KB, text/plain)
2023-10-18 16:15 UTC, Rafael Montes
Details
journalctl -b -o short-monotonic (1.38 MB, text/plain)
2023-10-18 16:16 UTC, Rafael Montes
Details
sudo journalctl -b -o short-monotonic (1.11 MB, text/plain)
2023-10-19 21:51 UTC, Rafael Montes
Details
rdosreport (2.06 MB, text/plain)
2023-10-19 21:52 UTC, Rafael Montes
Details
journalctl -b -o short-monotonic withoutcd during boot (1.62 MB, text/plain)
2023-10-20 15:06 UTC, Rafael Montes
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Rafael Montes 2023-10-07 19:37:11 UTC
User-Agent:       Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/117.0.0.0 Safari/537.36
Build Identifier: 

After applying latest Tumbleweed Patches system boots into emergency mode.
Current kernel 6.4.12-1 upgraded 6.5.4-1-default. 

Reproducible: Always

Steps to Reproduce:
1.Boot system
2. System seems to hang at setting up Virtual Console
3. Boot process timeouts out and enters emergency mode
Actual Results:  
Boots into emergency mode

Expected Results:  
Booted in gui

Captured a rdosreport.txt
Comment 1 Rafael Montes 2023-10-07 19:38:04 UTC
Created attachment 869987 [details]
rdosreoport.txt
Comment 2 Felix Miata 2023-10-09 07:51:19 UTC
(In reply to Rafael Montes from comment #1)
> rdosreoport.txt

318 lines containing ata[1-8], e.g.:
[  556.394165] tumbleweed kernel: ata7: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[  556.398222] tumbleweed kernel: ata7.00: configured for PIO0
and 40 lines containing strings Fail/fail:
[  573.979862] tumbleweed systemd[1]: sysroot.mount: Mounting timed out. Terminating.
[  573.981570] tumbleweed systemd[1]: sysroot.mount: Mount process exited, code=killed, status=15/TERM
[  573.981687] tumbleweed systemd[1]: sysroot.mount: Failed with result 'timeout'.
[  573.981952] tumbleweed systemd[1]: Failed to mount /sysroot.
[  573.982072] tumbleweed systemd[1]: Dependency failed for Initrd Root File System.
[  573.982143] tumbleweed systemd[1]: Dependency failed for Mountpoints Configured in the Real Root.

I don't think this has anything to do with bootloader.
Comment 3 Michal Suchanek 2023-10-09 14:12:00 UTC
[ 4386.594354] tumbleweed mount[958]: mount: /sysroot: /dev/sdd5 already mounted on /mnt.
[ 4386.594354] tumbleweed mount[958]:        dmesg(1) may have more information after failed mount system call.
[ 4386.595816] tumbleweed systemd[1]: sysroot.mount: Mount process exited, code=exited, status=32/n/a
[ 4386.595970] tumbleweed systemd[1]: sysroot.mount: Failed with result 'exit-code'.

This may be result of duplicate root= parameter.
Comment 4 Michal Suchanek 2023-10-10 17:40:12 UTC
There is only one root=parameter but later dracut duplicates it:

[    0.000000] tumbleweed kernel: Linux version 6.5.4-1-default (geeko@buildhost) (gcc (SUSE Linux) 13.2.1 20230912 [revision b96e66fd4ef3e36983969fb8cdd1956f551a074b], GNU ld (GNU Binutils; openSUSE Tumbleweed) 2.40.0.20230412-5) #1 SMP PREEMPT_DYNAMIC Wed Sep 20 05:07:04 UTC 2023 (fdd7e9e)
[    0.000000] tumbleweed kernel: Command line: BOOT_IMAGE=/vmlinuz-6.5.4-1-default root=UUID=c1fcf2d5-03b4-4efb-8efe-e80fe5c28441 splash=silent mitigations=auto quiet security=apparmor
[    0.000000] tumbleweed kernel: BIOS-provided physical RAM map:
...
[    1.254539] tumbleweed systemd[1]: Starting dracut cmdline hook...
[    1.282768] tumbleweed dracut-cmdline[262]: dracut-dracut-059+suse.501.gc44a365d-1.1
[    1.291111] tumbleweed dracut-cmdline[262]: Using kernel command line parameters:  resume=UUID=8a2265fb-9dea-42d7-a5bd-b098ae132450 root=UUID=c1fcf2d5-03b4-4efb-8efe-e80fe5c28441 rootfstype=ext4 rootflags=rw,relatime   BOOT_IMAGE=/vmlinuz-6.5.4-1-default root=UUID=c1fcf2d5-03b4-4efb-8efe-e80fe5c28441 splash=silent mitigations=auto quiet security=apparmor
[    1.330725] tumbleweed kernel: tsc: Refined TSC clocksource calibration: 4007.998 MHz

Looks like something to be diagnosed in dracut.
Comment 5 Rafael Montes 2023-10-10 22:18:42 UTC
Booted into kernel 6.5.4-1-default sucessfully 3rd time around. Boot seemed to hang at dracut-initqueue, but after some time booted successfully. Attaching dmesg bug.
Comment 6 Rafael Montes 2023-10-10 22:19:50 UTC
Created attachment 870064 [details]
dmesg
Comment 7 Antonio Feijoo 2023-10-11 06:18:12 UTC
What I can see is:

- root=UUID=c1fcf2d5-03b4-4efb-8efe-e80fe5c28441

- /dev/sdd5: UUID="c1fcf2d5-03b4-4efb-8efe-e80fe5c28441" BLOCK_SIZE="4096" TYPE="ext4" PARTUUID="abb89b60-8424-4dd7-8d81-812653655cf1"

- 63 1 8:53 / /mnt rw,relatime shared:28 - ext4 /dev/sdd5 rw

Apparently you are referencing a /mnt entry in fstab using /dev/sdXX instead of its UUID, am I right? If so, that's not reliable, you must set the UUID of the partition that you want to mount to /mnt.
Comment 8 Rafael Montes 2023-10-11 14:25:56 UTC
fstab file, no changes made

UUID=c1fcf2d5-03b4-4efb-8efe-e80fe5c28441  /           ext4  defaults  0  1
UUID=2afde86a-c809-43a5-84f6-01adbd429044  /boot       ext2  defaults  0  2
UUID=8a2265fb-9dea-42d7-a5bd-b098ae132450  swap        swap  defaults  0  0
UUID=163B-D6E7                             /boot/efi   vfat  utf8      0  2
UUID=dce83f5d-efec-469a-b774-1bf773e82bfa  /vmimages   xfs   defaults  0  0
UUID=486b22e8-2073-4a8c-9811-55b6664c1cf5  /kvmimages  xfs   defaults  0  0
Comment 9 Antonio Feijoo 2023-10-11 15:38:46 UTC
(In reply to Rafael Montes from comment #8)
> fstab file, no changes made
> 
> UUID=c1fcf2d5-03b4-4efb-8efe-e80fe5c28441  /           ext4  defaults  0  1
> UUID=2afde86a-c809-43a5-84f6-01adbd429044  /boot       ext2  defaults  0  2
> UUID=8a2265fb-9dea-42d7-a5bd-b098ae132450  swap        swap  defaults  0  0
> UUID=163B-D6E7                             /boot/efi   vfat  utf8      0  2
> UUID=dce83f5d-efec-469a-b774-1bf773e82bfa  /vmimages   xfs   defaults  0  0
> UUID=486b22e8-2073-4a8c-9811-55b6664c1cf5  /kvmimages  xfs   defaults  0  0

Could you print the output of `cat /proc/mounts` when the system is able to boot?
Comment 10 Rafael Montes 2023-10-11 18:03:05 UTC
(In reply to Antonio Feijoo from comment #9)
> (In reply to Rafael Montes from comment #8)
> > fstab file, no changes made
> > 
> > UUID=c1fcf2d5-03b4-4efb-8efe-e80fe5c28441  /           ext4  defaults  0  1
> > UUID=2afde86a-c809-43a5-84f6-01adbd429044  /boot       ext2  defaults  0  2
> > UUID=8a2265fb-9dea-42d7-a5bd-b098ae132450  swap        swap  defaults  0  0
> > UUID=163B-D6E7                             /boot/efi   vfat  utf8      0  2
> > UUID=dce83f5d-efec-469a-b774-1bf773e82bfa  /vmimages   xfs   defaults  0  0
> > UUID=486b22e8-2073-4a8c-9811-55b6664c1cf5  /kvmimages  xfs   defaults  0  0
> 
> Could you print the output of `cat /proc/mounts` when the system is able to
> boot?

/proc/mounts

sysfs /sys sysfs rw,nosuid,nodev,noexec,relatime 0 0
securityfs /sys/kernel/security securityfs rw,nosuid,nodev,noexec,relatime 0 0
cgroup2 /sys/fs/cgroup cgroup2 rw,nosuid,nodev,noexec,relatime,nsdelegate,memory_recursiveprot 0 0
pstore /sys/fs/pstore pstore rw,nosuid,nodev,noexec,relatime 0 0
efivarfs /sys/firmware/efi/efivars efivarfs rw,nosuid,nodev,noexec,relatime 0 0
bpf /sys/fs/bpf bpf rw,nosuid,nodev,noexec,relatime,mode=700 0 0
proc /proc proc rw,nosuid,nodev,noexec,relatime 0 0
tmpfs /run tmpfs rw,nosuid,nodev,size=13101312k,nr_inodes=819200,mode=755,inode64 0 0
systemd-1 /proc/sys/fs/binfmt_misc autofs rw,relatime,fd=31,pgrp=1,timeout=0,minproto=5,maxproto=5,direct,pipe_ino=14147 0 0
hugetlbfs /dev/hugepages hugetlbfs rw,nosuid,nodev,relatime,pagesize=2M 0 0
debugfs /sys/kernel/debug debugfs rw,nosuid,nodev,noexec,relatime 0 0
mqueue /dev/mqueue mqueue rw,nosuid,nodev,noexec,relatime 0 0
tracefs /sys/kernel/tracing tracefs rw,nosuid,nodev,noexec,relatime 0 0
fusectl /sys/fs/fuse/connections fusectl rw,nosuid,nodev,noexec,relatime 0 0
configfs /sys/kernel/config configfs rw,nosuid,nodev,noexec,relatime 0 0
tmpfs /tmp tmpfs rw,nosuid,nodev,nr_inodes=1048576,inode64 0 0
/dev/sdb /vmimages xfs rw,relatime,attr2,inode64,logbufs=8,logbsize=32k,noquota 0 0
/dev/sdc /kvmimages xfs rw,relatime,attr2,inode64,logbufs=8,logbsize=32k,noquota 0 0
/dev/sda4 /boot ext2 rw,relatime,stripe=4 0 0
/dev/sda2 /boot/efi vfat rw,relatime,fmask=0022,dmask=0022,codepage=437,iocharset=iso8859-1,shortname=mixed,utf8,errors=remount-ro 0 0
tmpfs /run/user/1000 tmpfs rw,nosuid,nodev,relatime,size=6550652k,nr_inodes=1637663,mode=700,uid=1000,gid=1000,inode64 0 0
gvfsd-fuse /run/user/1000/gvfs fuse.gvfsd-fuse rw,nosuid,nodev,relatime,user_id=1000,group_id=1000 0 0
portal /run/user/1000/doc fuse.portal rw,nosuid,nodev,relatime,user_id=1000,group_id=1000 0 0
Comment 11 Rafael Montes 2023-10-11 18:08:11 UTC
Created attachment 870105 [details]
Screenshot of Boot process
Comment 12 Rafael Montes 2023-10-11 18:59:28 UTC
I noticed some additional updates were availble including one for dracut.
Installed updates and the terminal never returns to prompt

dracut[I]: *** Stripping files done ***
dracut[I]: *** Creating image file '/boot/initrd-6.5.6-1-default' ***
dracut[I]: *** Creating initramfs image file '/boot/initrd-6.5.6-1-default' done ***

Ctrl-C returned the following
^C
Trying to exit gracefully...
^C
Zypper is currently cleaning up, exiting as soon as possible.

Initrd was created in /boot.
Comment 13 Rafael Montes 2023-10-11 19:01:18 UTC
(In reply to Rafael Montes from comment #12)
> I noticed some additional updates were availble including one for dracut.
> Installed updates and the terminal never returns to prompt
> 
> dracut[I]: *** Stripping files done ***
> dracut[I]: *** Creating image file '/boot/initrd-6.5.6-1-default' ***
> dracut[I]: *** Creating initramfs image file '/boot/initrd-6.5.6-1-default'
> done ***
> 
> Ctrl-C returned the following
> ^C
> Trying to exit gracefully...
> ^C
> Zypper is currently cleaning up, exiting as soon as possible.
> 
> Initrd was created in /boot.

ps aux |grep zypper
root     14782  6.4  0.2 623216 145236 pts/0   Sl+  14:17   2:44 zypper up -y
Comment 14 Rafael Montes 2023-10-11 19:20:57 UTC
Same boot issues with latest updates. Boot took approximately 11 mins
Comment 15 Rafael Montes 2023-10-12 20:29:02 UTC
Looks lie my issue was with cdrom device. Removed cd from device and boot process completed in a 1:18 sec.
Comment 16 Antonio Feijoo 2023-10-13 07:05:20 UTC
(In reply to Rafael Montes from comment #10)
> (In reply to Antonio Feijoo from comment #9)
> > Could you print the output of `cat /proc/mounts` when the system is able to
> > boot?
> 
> /proc/mounts

That's weird, there is not any /mnt mount point in your successful boot...

(In reply to Rafael Montes from comment #12)
> I noticed some additional updates were availble including one for dracut.

The latest dracut update was released with snapshot 20230911, and it was a minor change just needed for systemd-v254 (also released in the same snapshot). So my guess is that a change in the new systemd version is causing this.

(In reply to Rafael Montes from comment #12)
> I noticed some additional updates were availble including one for dracut.
> Installed updates and the terminal never returns to prompt
> 
> dracut[I]: *** Stripping files done ***
> dracut[I]: *** Creating image file '/boot/initrd-6.5.6-1-default' ***
> dracut[I]: *** Creating initramfs image file '/boot/initrd-6.5.6-1-default'
> done ***

This is the last line printed by dracut, everything ok, so it's not the cause of your hang.

(In reply to Rafael Montes from comment #15)
> Looks lie my issue was with cdrom device. Removed cd from device and boot
> process completed in a 1:18 sec.

I would need more logs to try to understand what is happening.

1 - With the cdrom, edit the kernel command line at boot, append `systemd.log_level=debug rd.udev.log_priority=debug rd.debug`, and attach the output of `journalctl -b -o short-monotonic` and `/run/initramfs/rdsosreport.txt`

2 - Without the cdrom, edit the kernel command line at boot, append `systemd.log_level=debug`, boot your system, then insert the cdrom and print the output of `journalctl -b -o short-monotonic`?

Thanks!
Comment 17 Rafael Montes 2023-10-13 15:37:47 UTC
Created attachment 870171 [details]
journalctl -b -o short-monotonic

No rdosreport since system did not go into emergency mode
Comment 18 Rafael Montes 2023-10-13 15:39:36 UTC
Created attachment 870172 [details]
journalctl -b -o short-monotonic with cd

no rdosreport since system did not boot into EM
Comment 19 Rafael Montes 2023-10-13 15:41:04 UTC
Created attachment 870173 [details]
journalctl -b -o short-monotonic withoutcd
Comment 20 Antonio Feijoo 2023-10-16 06:55:17 UTC
(In reply to Rafael Montes from comment #18)
> Created attachment 870172 [details]
> journalctl -b -o short-monotonic with cd
> 
> no rdosreport since system did not boot into EM

Does this mean that after updating your system now it now boots with and without the cdrom inserted, but slowly (as seen in the logs provided)?

I'm missing the logs before switching root, starting at [    0.000000], otherwise I cannot know what is happening in the initrd phase, and `journalctl -b -o short-monotonic` should provide that info. To force the entry into the emergency shell (and grab the rdsosreport there), add `rd.break` to the kernel command line.
Comment 21 Rafael Montes 2023-10-16 22:28:37 UTC
(In reply to Antonio Feijoo from comment #20)
> (In reply to Rafael Montes from comment #18)
> > Created attachment 870172 [details]
> > journalctl -b -o short-monotonic with cd
> > 
> > no rdosreport since system did not boot into EM
> 
> Does this mean that after updating your system now it now boots with and
> without the cdrom inserted, but slowly (as seen in the logs provided)?
> 
> I'm missing the logs before switching root, starting at [    0.000000],
> otherwise I cannot know what is happening in the initrd phase, and
> `journalctl -b -o short-monotonic` should provide that info. To force the
> entry into the emergency shell (and grab the rdsosreport there), add
> `rd.break` to the kernel command line.

Server did not go into rescue mode.

 cat /proc/cmdline 
BOOT_IMAGE=/vmlinuz-6.5.4-1-default root=UUID=c1fcf2d5-03b4-4efb-8efe-e80fe5c28441 splash=silent mitigations=auto quiet security=apparmor systemd.log_level=debug rd.udev.log_priority=debug rd.debug
Comment 22 Antonio Feijoo 2023-10-17 06:15:54 UTC
(In reply to Rafael Montes from comment #21)
> (In reply to Antonio Feijoo from comment #20)
> > (In reply to Rafael Montes from comment #18)
> > > Created attachment 870172 [details]
> > > journalctl -b -o short-monotonic with cd
> > > 
> > > no rdosreport since system did not boot into EM
> > 
> > Does this mean that after updating your system now it now boots with and
> > without the cdrom inserted, but slowly (as seen in the logs provided)?
> > 
> > I'm missing the logs before switching root, starting at [    0.000000],
> > otherwise I cannot know what is happening in the initrd phase, and
> > `journalctl -b -o short-monotonic` should provide that info. To force the
> > entry into the emergency shell (and grab the rdsosreport there), add
> > `rd.break` to the kernel command line.
> 
> Server did not go into rescue mode.

Then let's rewrite the bug title.

>  cat /proc/cmdline 
> BOOT_IMAGE=/vmlinuz-6.5.4-1-default
> root=UUID=c1fcf2d5-03b4-4efb-8efe-e80fe5c28441 splash=silent
> mitigations=auto quiet security=apparmor systemd.log_level=debug
> rd.udev.log_priority=debug rd.debug

As said in comment #20, you should also set `rd.break` to force the emergency shell.
Comment 23 Rafael Montes 2023-10-18 16:15:39 UTC
Created attachment 870309 [details]
rdosreport
Comment 24 Rafael Montes 2023-10-18 16:16:28 UTC
Created attachment 870310 [details]
journalctl -b -o short-monotonic
Comment 25 Antonio Feijoo 2023-10-19 12:22:29 UTC
I don't know why it's happening, but the logs you're attaching are incomplete...

(In reply to Rafael Montes from comment #23)
> Created attachment 870309 [details]
> rdosreport

See the difference between this rdosreport and the file attached in comment #1, it stops at `+ blkid`?

(In reply to Rafael Montes from comment #24)
> Created attachment 870310 [details]
> journalctl -b -o short-monotonic

Same here, this should start with [    0.000000], not [ 2113.254197], we are missing what happened before.
Comment 26 Antonio Feijoo 2023-10-19 12:49:03 UTC
(In reply to Antonio Feijoo from comment #25)
> (In reply to Rafael Montes from comment #24)
> > Created attachment 870310 [details]
> > journalctl -b -o short-monotonic
> 
> Same here, this should start with [    0.000000], not [ 2113.254197], we are
> missing what happened before.

Are you running `journalctl -b -o short-monotonic` as a regular user? If so, I'm sorry, I should have said that you must prepend `sudo` or run it being root.
Comment 27 Rafael Montes 2023-10-19 21:51:25 UTC
Created attachment 870346 [details]
sudo journalctl -b -o short-monotonic

My Apologies I should have known to run as root.
Comment 28 Rafael Montes 2023-10-19 21:52:30 UTC
Created attachment 870347 [details]
rdosreport
Comment 29 Antonio Feijoo 2023-10-20 09:08:42 UTC
(In reply to Rafael Montes from comment #27)
> Created attachment 870346 [details]
> sudo journalctl -b -o short-monotonic
> 
> My Apologies I should have known to run as root.

I'm the one who has to apologize. Although it is obvious to me because I have to do it all the time, not everyone has to know it.

Well, definitely there is an issue with the cd-rom (+10 minutes between [    4.118117] and [  619.566479], see below) and it's delaying the discovery of the root device (and therefore the boot process). All the "Timed out for waiting the udev queue being empty" messages in the dracut initqueue are issued by `udevadm settle`.

> [    1.577944] tumbleweed systemd[1]: systemd-udevd.service: Forked /usr/lib/systemd/systemd-udevd as 351
> [    1.578267] tumbleweed systemd[1]: systemd-udevd.service: Changed dead -> start
> ...
> [    1.954657] tumbleweed systemd[1]: Starting dracut initqueue hook...
> ...
> [    4.119867] tumbleweed systemd-udevd[351]: 2:0:0:0: Device is queued (SEQNUM=2826, ACTION=add)
> [    4.119976] tumbleweed systemd-udevd[351]: 2:0:0:0: SEQNUM=2826 blocked by SEQNUM=2202
> [    4.115436] tumbleweed kernel: ata3.00: configured for UDMA/133
> [    4.115661] tumbleweed kernel: scsi 2:0:0:0: Direct-Access     ATA      ST4000DM005-2DP1 0001 PQ: 0 ANSI: 5
> [    4.116215] tumbleweed kernel: scsi 2:0:0:0: Attached scsi generic sg3 type 0
> [    4.118117] tumbleweed kernel: scsi 6:0:0:0: CD-ROM            HL-DT-ST DVD+-RW GU90N    A1C3 PQ: 0 ANSI: 5
> [   35.857569] tumbleweed kernel: ata7: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
> [   35.865068] tumbleweed kernel: ata7.00: configured for UDMA/100
> [   62.841543] tumbleweed systemd-udevd[351]: 0000:00:17.0: Worker [353] processing SEQNUM=2202 is taking a long time
> ...
> [   62.842379] tumbleweed systemd-udevd[351]: 1-5:1.1: Worker [358] processing SEQNUM=2696 is taking a long time
> [   62.842485] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (WATCHDOG=1)
> [   62.842994] tumbleweed systemd-udevd[351]: Udev rules need reloading
> [   62.845899] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (RELOADING=1, STATUS=Flushing configuration..., MONOTONIC_USEC=62842797)
> [   62.857637] tumbleweed systemd-udevd[351]: 1-5:1.0: Worker [363] processing SEQNUM=2695 is taking a long time
> [   62.857732] tumbleweed systemd-udevd[351]: 0000:65:00.0: Worker [359] processing SEQNUM=2260 is taking a long time
> [   62.857804] tumbleweed systemd-udevd[351]: cpu0: Worker [373] processing SEQNUM=2391 is taking a long time
> [   62.857863] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (READY=1, STATUS=Processing with 32 children at max)
> [   62.857952] tumbleweed systemd-udevd[351]: cpu4: Worker [369] processing SEQNUM=2395 is taking a long time
> [   62.858099] tumbleweed systemd-udevd[351]: cpu5: Worker [368] processing SEQNUM=2396 is taking a long time
> [   62.858182] tumbleweed systemd-udevd[351]: cpu1: Worker [354] processing SEQNUM=2392 is taking a long time
> [   62.858243] tumbleweed systemd-udevd[351]: cpu6: Worker [352] processing SEQNUM=2397 is taking a long time
> [   62.858276] tumbleweed systemd-udevd[351]: cpu7: Worker [366] processing SEQNUM=2398 is taking a long time
> [   62.858307] tumbleweed systemd-udevd[351]: 0000:b2:05.5: Worker [364] processing SEQNUM=2297 is taking a long time
> [   62.858339] tumbleweed systemd-udevd[351]: cpu2: Worker [374] processing SEQNUM=2393 is taking a long time
> [   62.858370] tumbleweed systemd-udevd[351]: cpu3: Worker [370] processing SEQNUM=2394 is taking a long time
> [   63.840989] tumbleweed systemd-udevd[351]: 2-9:1.0: Worker [360] processing SEQNUM=2732 is taking a long time
> [   63.841150] tumbleweed systemd-udevd[351]: 0003:046D:C534.0004: Worker [367] processing SEQNUM=2760 is taking a long time
> [   63.841230] tumbleweed systemd-udevd[351]: 0003:046D:C534.0003: Worker [365] processing SEQNUM=2757 is taking a long time
> ...
> [  122.591443] tumbleweed dracut-initqueue[389]: Timed out for waiting the udev queue being empty.
> ...
> [  122.615379] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (WATCHDOG=1)
> [  122.618848] tumbleweed systemd-udevd[351]: Udev rules need reloading
> [  122.625230] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (RELOADING=1, STATUS=Flushing configuration..., MONOTONIC_USEC=122610448)
> [  122.627170] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (READY=1, STATUS=Processing with 32 children at max)
> [  182.842024] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (WATCHDOG=1)
> [  182.842421] tumbleweed systemd-udevd[351]: Udev rules need reloading
> [  182.842668] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (RELOADING=1, STATUS=Flushing configuration..., MONOTONIC_USEC=182842171)
> [  182.855092] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (READY=1, STATUS=Processing with 32 children at max)
> [  189.487379] tumbleweed systemd-udevd[351]: Udev rules need reloading
> [  189.490746] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (RELOADING=1, STATUS=Flushing configuration..., MONOTONIC_USEC=189487379)
> [  189.500991] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (READY=1, STATUS=Processing with 32 children at max)
> ...
> [  243.091445] tumbleweed dracut-initqueue[492]: Timed out for waiting the udev queue being empty.
> ...
> [  243.120655] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (WATCHDOG=1)
> [  243.125732] tumbleweed systemd-udevd[351]: Udev rules need reloading
> [  243.134665] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (RELOADING=1, STATUS=Flushing configuration..., MONOTONIC_USEC=243111310)
> [  243.135869] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (READY=1, STATUS=Processing with 32 children at max)
> ...
> [  363.591513] tumbleweed dracut-initqueue[508]: Timed out for waiting the udev queue being empty.
> ...
> [  363.629909] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (WATCHDOG=1)
> [  363.633993] tumbleweed systemd-udevd[351]: Udev rules need reloading
> [  363.640586] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (RELOADING=1, STATUS=Flushing configuration..., MONOTONIC_USEC=363623471)
> [  363.642219] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (READY=1, STATUS=Processing with 32 children at max)
> [  373.794394] tumbleweed systemd-udevd[351]: Udev rules need reloading
> [  373.794815] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (RELOADING=1, STATUS=Flushing configuration..., MONOTONIC_USEC=373794406)
> [  373.807357] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (READY=1, STATUS=Processing with 32 children at max)
> [  433.841483] tumbleweed systemd-udevd[351]: 1:0:0:0: Worker [548] processing SEQNUM=2818 is taking a long time
> [  433.842037] tumbleweed systemd-udevd[351]: 6:0:0:0: Worker [538] processing SEQNUM=2828 is taking a long time
> [  433.842099] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (WATCHDOG=1)
> [  433.847378] tumbleweed systemd-udevd[351]: Udev rules need reloading
> [  433.848955] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (RELOADING=1, STATUS=Flushing configuration..., MONOTONIC_USEC=433842270)
> [  433.857080] tumbleweed systemd-udevd[351]: 2:0:0:0: Worker [537] processing SEQNUM=2823 is taking a long time
> [  433.857115] tumbleweed systemd-udevd[351]: 0:0:0:0: Worker [551] processing SEQNUM=2699 is taking a long time
> [  433.857145] tumbleweed systemd-udevd[351]: 8:0:0:0: Worker [550] processing SEQNUM=2813 is taking a long time
> [  433.857236] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (READY=1, STATUS=Processing with 32 children at max)
> ...
> [  484.091426] tumbleweed dracut-initqueue[518]: Timed out for waiting the udev queue being empty.
> ...
> [  484.132175] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (WATCHDOG=1)
> [  484.139328] tumbleweed systemd-udevd[351]: Udev rules need reloading
> [  484.152227] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (RELOADING=1, STATUS=Flushing configuration..., MONOTONIC_USEC=484121871)
> [  484.153939] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (READY=1, STATUS=Processing with 32 children at max)
> [  553.842059] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (WATCHDOG=1)
> [  553.842523] tumbleweed systemd-udevd[351]: Udev rules need reloading
> [  553.842707] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (RELOADING=1, STATUS=Flushing configuration..., MONOTONIC_USEC=553842524)
> [  553.855285] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (READY=1, STATUS=Processing with 32 children at max)
> ...
> [  604.591394] tumbleweed dracut-initqueue[562]: Timed out for waiting the udev queue being empty.
> ...
> [  604.617635] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (WATCHDOG=1)
> [  604.624578] tumbleweed systemd-udevd[351]: Udev rules need reloading
> [  604.636713] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (RELOADING=1, STATUS=Flushing configuration..., MONOTONIC_USEC=604611110)
> [  604.640264] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (READY=1, STATUS=Processing with 32 children at max)
> [  619.549400] tumbleweed systemd-udevd[351]: Udev rules need reloading
> [  619.549743] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (RELOADING=1, STATUS=Flushing configuration..., MONOTONIC_USEC=619549401)
> [  619.562181] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (READY=1, STATUS=Processing with 32 children at max)
> ...
> [  619.566479] tumbleweed kernel: sr 6:0:0:0: Attached scsi CD-ROM sr0
> ...
> [  725.091527] tumbleweed dracut-initqueue[602]: Timed out for waiting the udev queue being empty.
> ...
> [  725.122688] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (WATCHDOG=1)
> [  725.125780] tumbleweed systemd-udevd[351]: Udev rules need reloading
> [  725.132555] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (RELOADING=1, STATUS=Flushing configuration..., MONOTONIC_USEC=725117030)
> [  725.133990] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (READY=1, STATUS=Processing with 32 children at max)
> ...
> [  845.591413] tumbleweed dracut-initqueue[615]: Timed out for waiting the udev queue being empty.
> ...
> [  845.628911] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (WATCHDOG=1)
> [  845.632320] tumbleweed systemd-udevd[351]: Udev rules need reloading
> [  845.641109] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (RELOADING=1, STATUS=Flushing configuration..., MONOTONIC_USEC=845622916)
> [  845.642719] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (READY=1, STATUS=Processing with 32 children at max)
> [  865.310456] tumbleweed systemd-udevd[351]: Udev rules need reloading
> [  865.310786] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (RELOADING=1, STATUS=Flushing configuration..., MONOTONIC_USEC=865310462)
> [  865.323235] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (READY=1, STATUS=Processing with 32 children at max)
> [  925.841496] tumbleweed systemd-udevd[351]: sr0: Worker [632] processing SEQNUM=2860 is taking a long time
> [  925.842003] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (WATCHDOG=1)
> [  925.842670] tumbleweed systemd-udevd[351]: Udev rules need reloading
> [  925.846208] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (RELOADING=1, STATUS=Flushing configuration..., MONOTONIC_USEC=925842672)
> [  925.856248] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (READY=1, STATUS=Processing with 32 children at max)
> ...
> [  966.091436] tumbleweed dracut-initqueue[625]: Timed out for waiting the udev queue being empty.
> ...
> [  966.134540] tumbleweed systemd[1]: Finished dracut initqueue hook.
> ...
> [  966.423498] tumbleweed systemd-udevd[351]: Udev rules need reloading
> [  966.424287] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (RELOADING=1, STATUS=Flushing configuration..., MONOTONIC_USEC=966423511)
> [  966.447717] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (READY=1, STATUS=Processing with 32 children at max)
> [ 1028.841653] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (WATCHDOG=1)
> [ 1045.842291] tumbleweed systemd-udevd[351]: Udev rules need reloading
> [ 1045.843098] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (RELOADING=1, STATUS=Flushing configuration..., MONOTONIC_USEC=1045842247)
> [ 1045.854497] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (READY=1, STATUS=Processing with 32 children at max)
> [ 1148.841606] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (WATCHDOG=1)
> [ 1172.517786] tumbleweed systemd-udevd[351]: Udev rules need reloading
> [ 1172.518094] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (RELOADING=1, STATUS=Flushing configuration..., MONOTONIC_USEC=1172517737)
> [ 1172.530043] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (READY=1, STATUS=Processing with 32 children at max)
> [ 1232.841467] tumbleweed systemd-udevd[351]: sr0: Worker [701] processing SEQNUM=2864 is taking a long time
> [ 1232.841980] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (WATCHDOG=1)
> [ 1232.842537] tumbleweed systemd-udevd[351]: Udev rules need reloading
> [ 1232.842841] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (RELOADING=1, STATUS=Flushing configuration..., MONOTONIC_USEC=1232842538)
> [ 1232.855394] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (READY=1, STATUS=Processing with 32 children at max)
> [ 1328.841605] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (WATCHDOG=1)
> [ 1352.842250] tumbleweed systemd-udevd[351]: Udev rules need reloading
> [ 1352.842566] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (RELOADING=1, STATUS=Flushing configuration..., MONOTONIC_USEC=1352842226)
> [ 1352.854650] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (READY=1, STATUS=Processing with 32 children at max)
> [ 1387.560282] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (WATCHDOG=1)
> [ 1508.841614] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (WATCHDOG=1)
> [ 1628.841987] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (WATCHDOG=1)
> [ 1748.841607] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (WATCHDOG=1)
> [ 1868.841605] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (WATCHDOG=1)
> [ 1988.841977] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (WATCHDOG=1)
> [ 2108.841604] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (WATCHDOG=1)
> [ 2228.841605] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (WATCHDOG=1)
> [ 2348.841604] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (WATCHDOG=1)
> [ 2468.841546] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (WATCHDOG=1)
> [ 2588.841547] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (WATCHDOG=1)
> [ 2708.841986] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (WATCHDOG=1)
> [ 2828.841608] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (WATCHDOG=1)
> [ 2948.841606] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (WATCHDOG=1)
> [ 3068.841988] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (WATCHDOG=1)
> [ 3188.841607] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (WATCHDOG=1)
> [ 3308.841606] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (WATCHDOG=1)
> [ 3428.841982] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (WATCHDOG=1)
> [ 3548.841607] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (WATCHDOG=1)
> [ 3668.841604] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (WATCHDOG=1)
> [ 3788.841545] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (WATCHDOG=1)
> [ 3908.841546] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (WATCHDOG=1)
> [ 4028.841545] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (WATCHDOG=1)
> [ 4148.841914] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (WATCHDOG=1)
> [ 4268.841555] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (WATCHDOG=1)
> [ 4388.841550] tumbleweed systemd[1]: systemd-udevd.service: Got notification message from PID 351 (WATCHDOG=1)
Comment 30 Antonio Feijoo 2023-10-20 09:09:06 UTC
I would first check if it's a hardware issue, but in comment #0 you said this does not happen to you if you boot with the previous kernel 6.4.12-1. Is this statement still valid?

Otherwise, something has changed in kernel 6.5.4-1 (btw the latest version is 6.5.6-1, so maybe a `zypper dup` would be good).

I need to check if the delay also happens out of the initrd. Could you perform a regular boot without any cd-rom inserted, then insert the cd-rom once you're already logged in your desktop environment, and attach the output of `sudo journalctl -b -o short-monotonic`?
Comment 31 Rafael Montes 2023-10-20 14:58:22 UTC
(In reply to Antonio Feijoo from comment #30)
> I would first check if it's a hardware issue, but in comment #0 you said
> this does not happen to you if you boot with the previous kernel 6.4.12-1.
> Is this statement still valid?
> 
> Otherwise, something has changed in kernel 6.5.4-1 (btw the latest version
> is 6.5.6-1, so maybe a `zypper dup` would be good).
> 
> I need to check if the delay also happens out of the initrd. Could you
> perform a regular boot without any cd-rom inserted, then insert the cd-rom
> once you're already logged in your desktop environment, and attach the
> output of `sudo journalctl -b -o short-monotonic`?

Look like zypper dup resolved the issue.

Thanks for your help
Comment 32 Rafael Montes 2023-10-20 15:06:45 UTC
Created attachment 870361 [details]
journalctl -b -o short-monotonic withoutcd during boot

Booted system
inserrted cd
Ran sudo ournalctl -b -o short-monotonic.
Comment 33 Antonio Feijoo 2023-10-20 15:32:09 UTC
(In reply to Rafael Montes from comment #31)
> Look like zypper dup resolved the issue.
> 
> Thanks for your help

Great, closing then. Thanks!