Bug 1770969

Created attachment 1664112 [details]
OEMDRV disk image with kickstart

Reproduced on RHEL-8.2 Beta, OEMDRV is not used unless rd.debug is added to the kernel command line.
Attaching an OEMDRV disk image with a kickstart file.

Created attachment 1664123 [details]
OEMDRV disk image with kickstart

Another attempt to attach an OEMDRV disk image with a kickstart file. It should contain usable data this time.

This issue is not 100% reproducible for me, around 50% of attempts in a virtual machine successfully used the kickstart file.

Created attachment 1664124 [details]
syslog, kickstart not used

syslog from an installation, where the kickstart file was not used automatically. Compose used for testing: RHEL-8.2 Beta.

Created attachment 1664125 [details]
syslog, kickstart used automatically

syslog from an installation, where the kickstart file was used automatically. The installation was booted with the rd.debug parameter.

Created attachment 1664138 [details]
syslog, kickstart used automatically, without rd.debug

And one more syslog - the kickstart was automatically used even without rd.debug on the kernel command line.
A virtual machine with just 1 CPU was used. The kickstart file was successfully used in all 5 attempts if only 1 CPU is present. Previous attempts were in a VM with 2 CPUs.

We can't use rd.debug to debug the option because it will slow down the process so the issue is not happening. We have to boot from DVD; pxeboot is again slower, so it won't reproduce the issue. Also as mentioned already in comment 6 you have to have more than 1 CPU. 
However, by adding debug prints and modifying dvd iso, I was able to find out that this is probably systemd/dracut issue.

We will create udev rule which is not triggered:

{
printf 'SUBSYSTEM=="block", KERNEL=="%s", RUN+="%s"\n' "$dev" "$cmd"
printf 'SUBSYSTEM=="block", SYMLINK=="%s", RUN+="%s"\n' "$dev" "$cmd"
} >> "/etc/udev/rules.d/90-anaconda.rules"

and our parameters are:

cmd="/sbin/initqueue --settled --onetime --name fetch-kickstart-disk $env{DEVNAME} /ks.cfg"
dev="disk/by-label/OEMDRV"

These rules are created in our kickstart-genrules.sh[1] which is a pre-trigger hook[2]. From my understanding, after pre-trigger hooks all the udev events should be trigger which should activate our rules. Our command in the rule doesn't seems to be triggered in this case.


[1]: https://github.com/rhinstaller/anaconda/blob/rhel-8/dracut/kickstart-genrules.sh#L34
[2]: https://github.com/rhinstaller/anaconda/blob/rhel-8/dracut/module-setup.sh#L38

I think the udev rule works just fine and the real problem is that it is triggered too late, after dracut-initqueue.service already finished. We can see in the "bad case" log that the kickstart disk is initialized just before dracut-initqueue.service is started (a oneshot service is considered started after all its ExecStart= commands finished):

18:30:34,074 NOTICE kernel:scsi 0:0:0:0: Direct-Access     QEMU     QEMU HARDDISK    2.5+ PQ: 0 ANSI: 5
18:30:34,075 NOTICE kernel:scsi 0:0:0:0: Attached scsi generic sg1 type 0
18:30:34,078 DEBUG kernel:ISO 9660 Extensions: Microsoft Joliet Level 3
18:30:34,082 INFO dracut-initqueue:mount: /run/install/repo: WARNING: device write-protected, mounted read-only.
18:30:34,083 DEBUG kernel:ISO 9660 Extensions: RRIP_1991A
18:30:34,087 NOTICE kernel:sd 0:0:0:0: [sda] 65536 512-byte logical blocks: (33.6 MB/32.0 MiB)
18:30:34,088 NOTICE kernel:sd 0:0:0:0: [sda] Write Protect is off
18:30:34,088 DEBUG kernel:sd 0:0:0:0: [sda] Mode Sense: 63 00 00 08
18:30:34,089 NOTICE kernel:sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
18:30:34,091 INFO kernel: sda: sda1
18:30:34,096 NOTICE kernel:sd 0:0:0:0: [sda] Attached SCSI disk
18:30:34,138 ERR multipath:sda: can't store path info
18:30:34,142 INFO multipathd:uevent trigger error
18:30:34,147 INFO dracut-initqueue:anaconda: found /run/install/repo//images/install.img
18:30:34,240 INFO kernel:loop: module loaded
18:30:34,383 INFO systemd:Started dracut initqueue hook.

dracut-initqueue finishes when there's no more work and all "finished" hooks succeed. There are 2 "finished" hooks installed, as evidenced by the last check_finished run from the debug log: 

17:54:56,265 INFO dracut-initqueue:/bin/dracut-initqueue@45(main): check_finished
17:54:56,265 INFO dracut-initqueue:/lib/dracut-lib.sh@444(check_finished): local f
17:54:56,265 INFO dracut-initqueue:/lib/dracut-lib.sh@445(check_finished): for f in $hookdir/initqueue/finished/*.sh
17:54:56,265 INFO dracut-initqueue:/lib/dracut-lib.sh@446(check_finished): '[' '/lib/dracut/hooks/initqueue/finished/devexists-\x2fdev\x2froot.sh' = '/lib/dracut/hooks/initqueue/finished/*.sh' ']'
17:54:56,265 INFO dracut-initqueue:/lib/dracut-lib.sh@447(check_finished): '[' -e '/lib/dracut/hooks/initqueue/finished/devexists-\x2fdev\x2froot.sh' ']'
17:54:56,280 INFO dracut-initqueue:/lib/dracut-lib.sh@447(check_finished): . '/lib/dracut/hooks/initqueue/finished/devexists-\x2fdev\x2froot.sh'
17:54:56,285 INFO dracut-initqueue://lib/dracut/hooks/initqueue/finished/devexists-\x2fdev\x2froot.sh@1(source): '[' -e /dev/root ']'
17:54:56,285 INFO dracut-initqueue:/lib/dracut-lib.sh@445(check_finished): for f in $hookdir/initqueue/finished/*.sh
17:54:56,285 INFO dracut-initqueue:/lib/dracut-lib.sh@446(check_finished): '[' /lib/dracut/hooks/initqueue/finished/wait_for_settle.sh = '/lib/dracut/hooks/initqueue/finished/*.sh' ']'
17:54:56,285 INFO dracut-initqueue:/lib/dracut-lib.sh@447(check_finished): '[' -e /lib/dracut/hooks/initqueue/finished/wait_for_settle.sh ']'
17:54:56,285 INFO dracut-initqueue:/lib/dracut-lib.sh@447(check_finished): . /lib/dracut/hooks/initqueue/finished/wait_for_settle.sh
17:54:56,286 INFO dracut-initqueue://lib/dracut/hooks/initqueue/finished/wait_for_settle.sh@1(source): '[' -f /tmp/settle.done ']'
17:54:56,286 INFO dracut-initqueue:/lib/dracut-lib.sh@449(check_finished): return 0

=> anaconda needs to add a check for the kickstart too.

*** Bug 1865851 has been marked as a duplicate of this bug. ***

PR: https://github.com/rhinstaller/anaconda/pull/4721

Tested with anaconda-33.16.9.1-1.el8.

When inst.wait_for_disks=0 was present on the kernel cmdline, the problem could be reproduced occasionally.
Without inst.wait_for_disks the installer waited ~5 seconds and then continued, as expected.
Tested also inst.wait_for_disks=30, which waited ~30 seconds during the boot process.

Marking as Verified:Tested

Removing Verified:Tested, since a possible issue has been found and additional tests are running.

Created attachment 1965145 [details]
journalctl

Tested also with driverdisks on an OEMDRV labeled device and it seems that driverdisks are processed multiple times now during boot:
...
[  OK  ] Reached target System Initialization.
[  OK  ] Reached target Basic System.
[   12.628726] dracut-initqueue[1294]: Examining /dev/sr1
[   12.682057] dracut-initqueue[1295]: mount: /media/DD-1: WARNING: device write-protected, mounted read-only.
[   12.709108] dracut-initqueue[1294]: Extracting: kmod-redhat-e1000e
[   12.741801] dracut-initqueue[1294]: Extracting: kmod-redhat-virtio_blk
[   12.756428] dracut-initqueue[1294]: Extracting: kmod-redhat-e1000
[   15.435990] dracut-initqueue[1294]: leaving the driver_updates script
[   15.490331] dracut-initqueue[1347]: Examining /dev/vdb1
[   15.543035] dracut-initqueue[1365]: mount: /media/DD-2: WARNING: device write-protected, mounted read-only.
[   17.204059] dracut-initqueue[1347]: leaving the driver_updates script
[   17.245024] dracut-initqueue[1380]: Examining /dev/sr1
[   17.295174] dracut-initqueue[1381]: mount: /media/DD-3: WARNING: device write-protected, mounted read-only.
[   17.305876] dracut-initqueue[1380]: Extracting: kmod-redhat-e1000e
[   17.324170] dracut-initqueue[1380]: Extracting: kmod-redhat-virtio_blk
[   17.333257] dracut-initqueue[1380]: Extracting: kmod-redhat-e1000
[   19.180701] dracut-initqueue[1380]: leaving the driver_updates script
[   19.243517] dracut-initqueue[1449]: Warning: Can't get kickstart from /dev/sr1:/ks.cfg
[   19.993875] dracut-initqueue[1752]: Examining /dev/vdb1
[   19.997825] dracut-initqueue[1753]: mount: /media/DD-4: WARNING: device write-protected, mounted read-only.
[   21.796877] dracut-initqueue[1752]: leaving the driver_updates script
[   21.841258] dracut-initqueue[1761]: Examining /dev/vdb1
[   21.846884] dracut-initqueue[1762]: mount: /media/DD-5: WARNING: device write-protected, mounted read-only.
[   23.616496] dracut-initqueue[1761]: leaving the driver_updates script
[   23.662465] dracut-initqueue[1770]: Examining /dev/vdb1
[   23.667909] dracut-initqueue[1771]: mount: /media/DD-6: WARNING: device write-protected, mounted read-only.
[   25.471137] dracut-initqueue[1770]: leaving the driver_updates script
[   25.516865] dracut-initqueue[1779]: Examining /dev/sr1
[   25.568351] dracut-initqueue[1780]: mount: /media/DD-7: WARNING: device write-protected, mounted read-only.
[   25.582550] dracut-initqueue[1779]: Extracting: kmod-redhat-e1000e
[   25.602456] dracut-initqueue[1779]: Extracting: kmod-redhat-virtio_blk
[   25.611371] dracut-initqueue[1779]: Extracting: kmod-redhat-e1000
[   27.396750] dracut-initqueue[1779]: leaving the driver_updates script
[   27.444876] dracut-initqueue[1849]: Examining /dev/vdb1
[   27.450939] dracut-initqueue[1873]: mount: /media/DD-8: WARNING: device write-protected, mounted read-only.
[   29.155045] dracut-initqueue[1849]: leaving the driver_updates script
[   29.200117] dracut-initqueue[1888]: Examining /dev/sr1
[   29.253432] dracut-initqueue[1889]: mount: /media/DD-9: WARNING: device write-protected, mounted read-only.
[   29.277564] dracut-initqueue[1888]: Extracting: kmod-redhat-e1000e
[   29.297830] dracut-initqueue[1888]: Extracting: kmod-redhat-virtio_blk
[   29.305814] dracut-initqueue[1888]: Extracting: kmod-redhat-e1000
[   31.099076] dracut-initqueue[1888]: leaving the driver_updates script
[   31.813721] dracut-initqueue[2087]: Examining /dev/vdb1
[   31.819245] dracut-initqueue[2088]: mount: /media/DD-10: WARNING: device write-protected, mounted read-only.
[   33.368326] dracut-initqueue[2087]: leaving the driver_updates script
[   33.411282] dracut-initqueue[2096]: Examining /dev/vdb1
[   33.416418] dracut-initqueue[2097]: mount: /media/DD-11: WARNING: device write-protected, mounted read-only.
[   35.092918] dracut-initqueue[2096]: leaving the driver_updates script
[   35.140438] dracut-initqueue[2105]: Examining /dev/vdb1
[   35.145680] dracut-initqueue[2106]: mount: /media/DD-12: WARNING: device write-protected, mounted read-only.
[   36.846936] dracut-initqueue[2105]: leaving the driver_updates script
[   36.890316] dracut-initqueue[2114]: Examining /dev/vdb1
[   36.894804] dracut-initqueue[2115]: mount: /media/DD-13: WARNING: device write-protected, mounted read-only.
[   38.604754] dracut-initqueue[2114]: leaving the driver_updates script
[  OK  ] Started dracut initqueue hook.
[  OK  ] Reached target Remote File Systems (Pre).
[  OK  ] Reached target Remote File Systems.
...

There was also a DUD-related bug 2154904 fixed in build anaconda-33.16.9.1-1.el8, so perhaps one of these two bugs caused this regression.

journalctl from the installation is attached.
 
Moving back to ASSIGNED.

Moving back to MODIFIED, Verified:Tested, additional testing didn't reveal any regression.

The problem mentioned in comment 25 was likely caused by bug 1700368 or bug 1729032, so I retested the bug using a DUD containing a different set of drivers.

During my testing I also saw another similar problem, when the DUD was examined and the drivers loaded twice. This is not related to this change, since the same issue can be reproduced on RHEL-8.8. The problem is tracked in a separate bug 2208252.

FYI, a new regression appeared, possibly caused by this change. See bug 2209602.

Hmm, looks like to me the logic was broken already but working because of the dynamic (race between loading stage2 and mounting cdrom root).
Now that the window is closed, this started failing.

*** Bug 2162730 has been marked as a duplicate of this bug. ***

I'm moving this bug to VERIFIED, bug 2209602 has a fix and no regression has been found for this bug.

Proposing a doc text for the release notes, Could you please review it, Sagar?

Also bug 2215506 was reported to document the new boot option in the installation guide.

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory (anaconda bug fix and enhancement update), and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2023:6957