Bug 1984688

Summary: rawhide not booting in Hyper-V UEFI VMs - livecd media is ejected
Product: [Fedora] Fedora Reporter: Patrick Lang <patrick.lang>
Component: kernelAssignee: dracut-maint-list
Status: CLOSED RAWHIDE QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: rawhideCC: acaringi, adscvr, airlied, alciregi, bskeggs, dracut-maint-list, hdegoede, jarodwilson, jeremy, jglisse, jonathan, josef, kernel-maint, lgoncalv, linville, masami256, mchehab, mikelley, patrick.lang, ptalbert, steved, zbyszek
Target Milestone: ---   
Target Release: ---   
Hardware: x86_64   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: ---
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2021-08-12 01:24:36 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Attachments:
Description Flags
rdsosreport
none
Results from 20210731 live image none

Description Patrick Lang 2021-07-21 21:38:51 UTC 
Description of problem:

I was running a basic test (https://fedoraproject.org/wiki/QA:Testcase_Boot_default_install) with the rawhide workstation live boot ISO `Fedora-Workstation-Live-x86_64-Rawhide-20210721.n.0.iso`

Booting is failing.


Version-Release number of selected component (if applicable): 20210721 


How reproducible:
100% - this has failed with UEFI in each build I have tried. I do not know when the problem was introduced - 20210713 is the first one I have used.


Steps to Reproduce:
1. Create a Hyper-V Generation 2 VM on Windows 10 
2. Disable secure boot
3. Attach `Fedora-Workstation-Live-x86_64-Rawhide-20210721.n.0.iso`
4. Start the VM

Actual results:

As the live image boots, it errors out with this message and does not proceed.

```
[ 2.802595] dracut-initqueue[724]: mount: rum/initramf s/live: special device
/dev/disk/by-label/Fedora-WS-Live-rawh-20210721-n-0 does not exist. [ 2.804403) dracut: FATAL: Failed to mount block device of live image [
2.804420) dracut: Refusing to continue 2.849443] reboot: System halted

```

Expected results:

No errors

Additional info:

Running on Windows 10 build 19042.1110

BIOS boots fine from the ISOs I have tried.
Comment 1 Patrick Lang 2021-07-21 21:45:18 UTC 
Created attachment 1804270 [details]
rdsosreport

Adding rdsosreport - this shows the media being remounted at a different point, which triggers a SCSI eject event.
Comment 2 Patrick Lang 2021-07-22 18:01:34 UTC 
The same media boots correctly with the VM set to BIOS mode
Comment 3 Patrick Lang 2021-07-23 00:17:49 UTC 
I just double checked the Fedora 34 Workstation Live ISO - it works fine with the same configuration. Some change in rawhide has broken this.
Comment 4 Patrick Lang 2021-07-24 05:27:22 UTC 
There seem to be two relevant sections that lead to ejecting the media. 

It seems that one rule is correctly preserving the symlinks to /dev/sr0:

[    3.099758] fedora systemd-udevd[575]: sr0: /etc/udev/rules.d/99-live-squash.rules:2 RUN '/sbin/initqueue --settled --onetime --unique /sbin/dmsquash-live-root /dev/disk/by-label/Fedora-WS-Live-rawh-20210721-n-0'
[    3.099771] fedora systemd-udevd[575]: sr0: Handling device node '/dev/sr0', devnum=b11:0
[    3.099793] fedora systemd-udevd[575]: sr0: Setting permissions /dev/sr0, uid=0, gid=11, mode=0660
[    3.099808] fedora systemd-udevd[575]: sr0: Found 'b11:0' claiming '/run/udev/links/cdrom'
[    3.099832] fedora systemd-udevd[575]: sr0: Creating symlink '/dev/cdrom' to 'sr0'
[    3.099844] fedora systemd-udevd[575]: sr0: Found 'b11:0' claiming '/run/udev/links/disk\x2fby-label\x2fFedora-WS-Live-rawh-20210721-n-0'
[    3.099855] fedora systemd-udevd[575]: sr0: Creating symlink '/dev/disk/by-label/Fedora-WS-Live-rawh-20210721-n-0' to '../../sr0'
[    3.100406] fedora systemd-udevd[575]: sr0: Found 'b11:0' claiming '/run/udev/links/disk\x2fby-path\x2facpi-VMBUS:00-vmbus-0b66321fd45649638b1acc35020a7c00-lun-0'
[    3.100437] fedora systemd-udevd[575]: sr0: Creating symlink '/dev/disk/by-path/acpi-VMBUS:00-vmbus-0b66321fd45649638b1acc35020a7c00-lun-0' to '../../sr0'
[    3.100452] fedora systemd-udevd[575]: sr0: Found 'b11:0' claiming '/run/udev/links/disk\x2fby-id\x2fscsi-14d534654202020207305e3437703544694957d7ced624a7d'
[    3.100467] fedora systemd-udevd[575]: sr0: Creating symlink '/dev/disk/by-id/scsi-14d534654202020207305e3437703544694957d7ced624a7d' to '../../sr0'
[    3.100480] fedora systemd-udevd[575]: sr0: Found 'b11:0' claiming '/run/udev/links/disk\x2fby-uuid\x2f2021-07-21-08-21-35-00'
[    3.100493] fedora systemd-udevd[575]: sr0: Creating symlink '/dev/disk/by-uuid/2021-07-21-08-21-35-00' to '../../sr0'
[    3.100505] fedora systemd-udevd[575]: sr0: Creating symlink '/dev/block/11:0' to '../sr0'
[    3.100518] fedora systemd-udevd[575]: sr0: sd-device: Created db file '/run/udev/data/b11:0' for '/devices/LNXSYSTM:00/LNXSYBUS:00/ACPI0004:00/VMBUS:00/0b66321f-d456-4963-8b1a-cc35020a7c00/host0/target0:0:0/0:0:0:0/block/sr0'
[    3.100531] fedora systemd-udevd[575]: sr0: Handling device node '/dev/sr0', devnum=b11:0
[    3.100544] fedora systemd-udevd[575]: sr0: Preserve permissions of /dev/sr0, uid=0, gid=11, mode=0660
[    3.100557] fedora systemd-udevd[575]: sr0: Found 'b11:0' claiming '/run/udev/links/cdrom'
[    3.100569] fedora systemd-udevd[575]: sr0: Preserve already existing symlink '/dev/cdrom' to 'sr0'
[    3.100581] fedora systemd-udevd[575]: sr0: Found 'b11:0' claiming '/run/udev/links/disk\x2fby-label\x2fFedora-WS-Live-rawh-20210721-n-0'
[    3.100593] fedora systemd-udevd[575]: sr0: Preserve already existing symlink '/dev/disk/by-label/Fedora-WS-Live-rawh-20210721-n-0' to '../../sr0'
[    3.100606] fedora systemd-udevd[575]: sr0: Found 'b11:0' claiming '/run/udev/links/disk\x2fby-path\x2facpi-VMBUS:00-vmbus-0b66321fd45649638b1acc35020a7c00-lun-0'
[    3.100618] fedora systemd-udevd[575]: sr0: Preserve already existing symlink '/dev/disk/by-path/acpi-VMBUS:00-vmbus-0b66321fd45649638b1acc35020a7c00-lun-0' to '../../sr0'
[    3.100630] fedora systemd-udevd[575]: sr0: Found 'b11:0' claiming '/run/udev/links/disk\x2fby-id\x2fscsi-14d534654202020207305e3437703544694957d7ced624a7d'
[    3.100642] fedora systemd-udevd[575]: sr0: Preserve already existing symlink '/dev/disk/by-id/scsi-14d534654202020207305e3437703544694957d7ced624a7d' to '../../sr0'
[    3.100655] fedora systemd-udevd[575]: sr0: Found 'b11:0' claiming '/run/udev/links/disk\x2fby-uuid\x2f2021-07-21-08-21-35-00'
[    3.100667] fedora systemd-udevd[575]: sr0: Preserve already existing symlink '/dev/disk/by-uuid/2021-07-21-08-21-35-00' to '../../sr0'
[    3.100679] fedora systemd-udevd[575]: sr0: Preserve already existing symlink '/dev/block/11:0' to '../sr0'


Then a later one is choosing to eject sr0:
[    3.114641] fedora systemd-udevd[585]: sr0: Failed to get watch handle, ignoring: No such file or directory
[    3.114671] fedora systemd-udevd[585]: sr0: /usr/lib/udev/rules.d/60-cdrom_id.rules:16 RUN 'cdrom_id --eject-media $devnode'
[    3.114199] fedora kernel: hv_storvsc 0b66321f-d456-4963-8b1a-cc35020a7c00: tag#124 cmd 0x0 status: scsi 0x0 srb 0x81 hv 0x0
[    3.115063] fedora systemd-udevd[585]: sr0: /usr/lib/udev/rules.d/60-persistent-storage.rules:66 Importing properties from results of 'scsi_id --export --whitelisted -d /dev/sr0'
[    3.115108] fedora systemd-udevd[585]: sr0: Starting 'scsi_id --export --whitelisted -d /dev/sr0'
[    3.115143] fedora systemd-udevd[585]: Successfully forked off '(spawn)' as PID 643.
[    3.117993] fedora kernel: hv_storvsc 0b66321f-d456-4963-8b1a-cc35020a7c00: tag#126 cmd 0x0 status: scsi 0x0 srb 0x81 hv 0x0
[    3.118634] fedora kernel: hv_storvsc 0b66321f-d456-4963-8b1a-cc35020a7c00: tag#65 cmd 0x0 status: scsi 0x0 srb 0x81 hv 0x0
[    3.119075] fedora kernel: hv_storvsc 0b66321f-d456-4963-8b1a-cc35020a7c00: tag#67 cmd 0x0 status: scsi 0x0 srb 0x81 hv 0x0
[    3.119735] fedora kernel: hv_storvsc 0b66321f-d456-4963-8b1a-cc35020a7c00: tag#72 cmd 0x0 status: scsi 0x0 srb 0x81 hv 0x0
[    3.119875] fedora systemd-udevd[585]: sr0: 'scsi_id --export --whitelisted -d /dev/sr0'(out) 'ID_SCSI=1'
[    3.119948] fedora systemd-udevd[585]: sr0: 'scsi_id --export --whitelisted -d /dev/sr0'(out) 'ID_VENDOR=Msft'
[    3.119975] fedora systemd-udevd[585]: sr0: 'scsi_id --export --whitelisted -d /dev/sr0'(out) 'ID_VENDOR_ENC=Msft\x20\x20\x20\x20'
[    3.119987] fedora systemd-udevd[585]: sr0: 'scsi_id --export --whitelisted -d /dev/sr0'(out) 'ID_MODEL=Virtual_DVD-ROM'
[    3.119997] fedora systemd-udevd[585]: sr0: 'scsi_id --export --whitelisted -d /dev/sr0'(out) 'ID_MODEL_ENC=Virtual\x20DVD-ROM\x20'
[    3.120007] fedora systemd-udevd[585]: sr0: 'scsi_id --export --whitelisted -d /dev/sr0'(out) 'ID_REVISION=1.0'
[    3.120017] fedora systemd-udevd[585]: sr0: 'scsi_id --export --whitelisted -d /dev/sr0'(out) 'ID_TYPE=cd'
[    3.120027] fedora systemd-udevd[585]: sr0: 'scsi_id --export --whitelisted -d /dev/sr0'(out) 'ID_SERIAL=14d534654202020207305e3437703544694957d7ced624a7d'
[    3.120037] fedora systemd-udevd[585]: sr0: 'scsi_id --export --whitelisted -d /dev/sr0'(out) 'ID_SERIAL_SHORT=4d534654202020207305e3437703544694957d7ced624a7d'
[    3.120047] fedora systemd-udevd[585]: sr0: Process 'scsi_id --export --whitelisted -d /dev/sr0' succeeded.
[    3.120057] fedora systemd-udevd[585]: sr0: /usr/lib/udev/rules.d/60-persistent-storage.rules:68 LINK 'disk/by-id/scsi-14d534654202020207305e3437703544694957d7ced624a7d'
[    3.120117] fedora systemd-udevd[585]: sr0: /usr/lib/udev/rules.d/60-persistent-storage.rules:90 Importing properties from results of builtin command 'path_id'
[    3.120208] fedora systemd-udevd[585]: sr0: /usr/lib/udev/rules.d/60-persistent-storage.rules:92 LINK 'disk/by-path/acpi-VMBUS:00-vmbus-0b66321fd45649638b1acc35020a7c00-lun-0'
[    3.120297] fedora systemd-udevd[585]: sr0: /usr/lib/udev/rules.d/73-seat-late.rules:16 RUN 'uaccess'
[    3.120315] fedora systemd-udevd[585]: sr0: Updating old device symlink '/dev/cdrom', which is no longer belonging to this device.
[    3.120330] fedora systemd-udevd[585]: sr0: No reference left for '/dev/cdrom', removing
[    3.120342] fedora systemd-udevd[585]: sr0: Updating old device symlink '/dev/disk/by-label/Fedora-WS-Live-rawh-20210721-n-0', which is no longer belonging to this device.
[    3.120354] fedora systemd-udevd[585]: sr0: No reference left for '/dev/disk/by-label/Fedora-WS-Live-rawh-20210721-n-0', removing
[    3.120368] fedora systemd-udevd[585]: sr0: Updating old device symlink '/dev/disk/by-uuid/2021-07-21-08-21-35-00', which is no longer belonging to this device.
[    3.120381] fedora systemd-udevd[585]: sr0: No reference left for '/dev/disk/by-uuid/2021-07-21-08-21-35-00', removing
[    3.120391] fedora systemd-udevd[585]: sr0: Handling device node '/dev/sr0', devnum=b11:0
[    3.120403] fedora systemd-udevd[585]: sr0: Found 'b11:0' claiming '/run/udev/links/disk\x2fby-id\x2fscsi-14d534654202020207305e3437703544694957d7ced624a7d'
[    3.120414] fedora systemd-udevd[585]: sr0: Preserve already existing symlink '/dev/disk/by-id/scsi-14d534654202020207305e3437703544694957d7ced624a7d' to '../../sr0'
[    3.120426] fedora systemd-udevd[585]: sr0: Found 'b11:0' claiming '/run/udev/links/disk\x2fby-path\x2facpi-VMBUS:00-vmbus-0b66321fd45649638b1acc35020a7c00-lun-0'
[    3.120437] fedora systemd-udevd[585]: sr0: Preserve already existing symlink '/dev/disk/by-path/acpi-VMBUS:00-vmbus-0b66321fd45649638b1acc35020a7c00-lun-0' to '../../sr0'
[    3.120448] fedora systemd-udevd[585]: sr0: Preserve already existing symlink '/dev/block/11:0' to '../sr0'
[    3.120459] fedora systemd-udevd[585]: sr0: sd-device: Created db file '/run/udev/data/b11:0' for '/devices/LNXSYSTM:00/LNXSYBUS:00/ACPI0004:00/VMBUS:00/0b66321f-d456-4963-8b1a-cc35020a7c00/host0/target0:0:0/0:0:0:0/block/sr0'
[    3.120470] fedora systemd-udevd[585]: sr0: Updating old device symlink '/dev/cdrom', which is no longer belonging to this device.
[    3.120481] fedora systemd-udevd[585]: sr0: No reference left for '/dev/cdrom', removing
[    3.120491] fedora systemd-udevd[585]: sr0: Updating old device symlink '/dev/disk/by-label/Fedora-WS-Live-rawh-20210721-n-0', which is no longer belonging to this device.
[    3.120503] fedora systemd-udevd[585]: sr0: No reference left for '/dev/disk/by-label/Fedora-WS-Live-rawh-20210721-n-0', removing
[    3.120513] fedora systemd-udevd[585]: sr0: Updating old device symlink '/dev/disk/by-uuid/2021-07-21-08-21-35-00', which is no longer belonging to this device.
[    3.120524] fedora systemd-udevd[585]: sr0: No reference left for '/dev/disk/by-uuid/2021-07-21-08-21-35-00', removing
[    3.120534] fedora systemd-udevd[585]: sr0: Handling device node '/dev/sr0', devnum=b11:0
[    3.120544] fedora systemd-udevd[585]: sr0: Found 'b11:0' claiming '/run/udev/links/disk\x2fby-id\x2fscsi-14d534654202020207305e3437703544694957d7ced624a7d'
[    3.120555] fedora systemd-udevd[585]: sr0: Preserve already existing symlink '/dev/disk/by-id/scsi-14d534654202020207305e3437703544694957d7ced624a7d' to '../../sr0'
[    3.120568] fedora systemd-udevd[585]: sr0: Found 'b11:0' claiming '/run/udev/links/disk\x2fby-path\x2facpi-VMBUS:00-vmbus-0b66321fd45649638b1acc35020a7c00-lun-0'
[    3.120578] fedora systemd-udevd[585]: sr0: Preserve already existing symlink '/dev/disk/by-path/acpi-VMBUS:00-vmbus-0b66321fd45649638b1acc35020a7c00-lun-0' to '../../sr0'
[    3.120588] fedora systemd-udevd[585]: sr0: Preserve already existing symlink '/dev/block/11:0' to '../sr0'
[    3.120598] fedora systemd-udevd[585]: sr0: Running command "cdrom_id --eject-media /dev/sr0"
[    3.120611] fedora systemd-udevd[585]: sr0: Starting 'cdrom_id --eject-media /dev/sr0'

(this is in the full rdsosreport attached)
Comment 5 Patrick Lang 2021-07-24 06:43:17 UTC 
The oldest rawhide nightly I could find was Fedora-Workstation-Live-x86_64-Rawhide-20210709.n.0.iso. It still reproduces there.
Comment 6 Patrick Lang 2021-07-28 06:04:24 UTC 
Looking again, I think that maybe this is the first failure (SEQNUM=1512), which upon failure maybe triggers the eject in SEQNUM=1520? I'm just guessing here

[    3.110910] fedora systemd-udevd[487]: sr0: SEQNUM=1520 blocked by SEQNUM=1512
[    3.110956] fedora kernel: hv_storvsc 0b66321f-d456-4963-8b1a-cc35020a7c00: tag#17 cmd 0x0 status: scsi 0x0 srb 0x81 hv 0x0
[    3.113031] fedora systemd[1]: dev-cdrom.device: Changed dead -> plugged
[    3.113063] fedora systemd[1]: dev-disk-by\x2did-scsi\x2d14d534654202020207305e3437703544694957d7ced624a7d.device: Changed dead -> plugged
[    3.113081] fedora systemd[1]: dev-disk-by\x2dlabel-Fedora\x2dWS\x2dLive\x2drawh\x2d20210721\x2dn\x2d0.device: Changed dead -> plugged
[    3.113093] fedora systemd[1]: dev-disk-by\x2dpath-acpi\x2dVMBUS:00\x2dvmbus\x2d0b66321fd45649638b1acc35020a7c00\x2dlun\x2d0.device: Changed dead -> plugged
[    3.113106] fedora systemd[1]: dev-disk-by\x2duuid-2021\x2d07\x2d21\x2d08\x2d21\x2d35\x2d00.device: Changed dead -> plugged
[    3.113118] fedora systemd[1]: dev-sr0.device: Changed dead -> plugged
[    3.113134] fedora systemd[1]: sys-devices-LNXSYSTM:00-LNXSYBUS:00-ACPI0004:00-VMBUS:00-0b66321f\x2dd456\x2d4963\x2d8b1a\x2dcc35020a7c00-host0-target0:0:0-0:0:0:0-block-sr0.device: Changed dead -> plugged
[    3.113146] fedora systemd-udevd[573]: 0:0:0:0: Processing device (SEQNUM=1512, ACTION=bind)
[    3.113160] fedora systemd-udevd[573]: 0:0:0:0: /usr/lib/udev/rules.d/50-udev-default.rules:14 Importing properties from results of builtin command 'hwdb --subsystem=scsi'
[    3.113173] fedora systemd-udevd[573]: 0:0:0:0: /usr/lib/udev/rules.d/50-udev-default.rules:14 Failed to run builtin 'hwdb --subsystem=scsi': Invalid argument
[    3.113184] fedora systemd-udevd[573]: 0:0:0:0: Device processed (SEQNUM=1512, ACTION=bind)
[    3.113195] fedora systemd-udevd[573]: 0:0:0:0: sd-device-monitor: Passed 280 byte to netlink monitor
[    3.113249] fedora systemd-udevd[487]: 0:0:0:0: Device ready for processing (SEQNUM=1513, ACTION=add)
[    3.113272] fedora systemd-udevd[487]: 0:0:0:0: sd-device-monitor: Passed 255 byte to netlink monitor
[    3.113284] fedora systemd-udevd[487]: sg0: Device ready for processing (SEQNUM=1514, ACTION=add)
[    3.113296] fedora systemd-udevd[487]: sg0: sd-device-monitor: Passed 287 byte to netlink monitor
[    3.113306] fedora systemd-udevd[487]: 0:0:0:0: Device ready for processing (SEQNUM=1515, ACTION=add)
[    3.113319] fedora systemd-udevd[487]: 0:0:0:0: sd-device-monitor: Passed 282 byte to netlink monitor
[    3.113329] fedora systemd-udevd[487]: sr0: Device ready for processing (SEQNUM=1520, ACTION=change)
[    3.113340] fedora systemd-udevd[487]: sr0: sd-device-monitor: Passed 330 byte to netlink monitor
[    3.113351] fedora systemd-udevd[585]: sr0: Processing device (SEQNUM=1520, ACTION=change)
Comment 7 Michael Kelley 2021-07-30 20:41:50 UTC 
See https://bugzilla.kernel.org/show_bug.cgi?id=213759, and this fix: https://lore.kernel.org/lkml/20210726114227.3661-1-limanyi@uniontech.com/.
Comment 8 Patrick Lang 2021-08-01 00:27:28 UTC 
Thanks for the pointer! It looks like that fix should be in 5.14-rc3, so I will recheck on a spin based on that kernel.
Comment 9 Patrick Lang 2021-08-01 07:15:50 UTC 
This is still happening in the latest rawhide workstation live ISO with kernel 5.14.0-0.rc3.20210728git4010a528219e.32.fc35.x86_64

Attached new logs, but the pattern is the same.
Comment 10 Patrick Lang 2021-08-01 07:18:15 UTC 
Created attachment 1809833 [details]
Results from 20210731 live image
Comment 11 Patrick Lang 2021-08-01 07:39:45 UTC 
Oh, I think I misunderstood. The proposed fix in https://bugzilla.kernel.org/show_bug.cgi?id=213759#c7 is still not merged. I checked the sources this kernel was built from: https://gitlab.com/cki-project/kernel-ark/-/blob/kernel-5.14.0-0.rc3.20210728git4010a528219e.32/drivers/scsi/sr.c#L224
Comment 12 Patrick Lang 2021-08-12 01:24:36 UTC 
Thanks for the lead on this Michael! This change recently made it into rawhide just before it was branched. This is fixed, verified in https://kojipkgs.fedoraproject.org/compose/branched/Fedora-35-20210811.n.0/compose/Workstation/x86_64/iso/

I can boot up in UEFI mode, and have the expected enlightened drivers (hv_storvsc, ... and the new hyperv_drm). Resolution changing works too with the updated hyperv_drm driver!