[itayherzberg]

Problem

When Ironic (metal3) inspects or provisions a VM-backed BareMetalHost it sends InsertMedia, the boot-device PATCH, and ComputerSystem.Reset On within about 50 ms of each other. Some hosts then sit at the firmware prompt and inspection times out:

BdsDxe: failed to load Boot0001 "UEFI QEMU DVD-ROM QM00001 " from PciRoot(0x0)/Pci(0x1F,0x2)/Sata(0x0,0xFFFF,0x0): Not Found
BdsDxe: No bootable option or device was found.
BdsDxe: Press any key to enter the Boot Manager Menu.

The VM was started before the ISO was written to its CD-ROM. The VM's virt-launcher then holds the ReadWriteOnce ISO volume, so the import helper pod cannot run, and what happens next depends on where it lands:

• on another node it stays in ContainerCreating with Multi-Attach error for volume "pvc-..." Volume is already used by pod(s) virt-launcher-...; the importing.redfish/cdrom0 label never comes off the VM, and because every power action is deferred while that label is present, Ironic's later power-off is deferred too. The host cannot recover on its own;
• on the same node it fails with dd: failed to open '/mnt/iso/disk.img': Permission denied, the label is removed, and the VM keeps running from an empty CD-ROM while GET .../VirtualMedia/Cd reports Inserted: true (the PVC is bound).

Which of the two happens is luck: the import pod and virt-launcher are created within a second of each other and whichever attaches the volume first wins. With many hosts enrolled at once the downloads are slower and the VM wins more often, so the failure shows up as "a handful of hosts out of a batch are stuck in inspecting, the rest came up", and the stuck set changes from run to run. A host that raced but whose import pod attached first boots a complete ISO and looks healthy.

Cause

handleInsertVirtualMedia answers 202 as soon as it has queued a task; a worker runs InsertVirtualMedia later. The only thing that holds back a Power On is IsImportInProgress, which looks for the importing.redfish/<device> label, and that label is the last thing the job writes: after the VM spec change (CD-ROM disk and volume added, CD placed first in the boot order), after the PVC, and after creating the helper pod (copyISOToPVC) or the VolumeImportSource (CDI path). Nothing marks the VM between the 202 and that write, which on a quiet cluster is tens of milliseconds and on a loaded one seconds. Ironic's Power On lands in that window, handlePowerAction sees no label and starts a VM whose spec already says "boot from the CD-ROM on PVC X" while PVC X is still empty.

The time the job spends in the queue is on top of that and is not what decides it: the window exists even when a worker picks the job up immediately, because the label is written at the end of the job.

Fix

• The handler marks the VM before it answers. After CheckInsertedMedia says nothing is inserted, handleInsertVirtualMedia calls MarkImportPending, which puts a dated placeholder (pending-<unix seconds>) into importing.redfish/<device> and records the image URL in virtual-media.redfish/<device>, in one metadata merge patch, and only then queues the task. A Power On that arrives from then on is deferred the way it already is during the import (power-after-import.redfish label, 202 with "deferred until ISO import completes") and runs when the label comes off. The job replaces the placeholder with the helper pod name (or the CDI marker) through the unchanged setImportingLabel, so the pod watcher's "is this pod still the tracked import" check and the eject path are untouched.

• A repeated InsertMedia while the placeholder is set queues no second job. Ironic retries an InsertMedia whose answer it lost. CheckInsertedMedia now treats the importing label as "media on its way" even before the PVC exists: same image → 202 "still in progress", different image → 409. MarkImportPending itself refuses to overwrite an existing label and the handler answers "in progress" in that case, which narrows the window for two requests that pass the check at the same time (it is a GET followed by a merge patch, so it does not close it; that hazard exists today as well and is not made worse).

• A placeholder nobody will replace is removed. Two cases:

  • the job gives up (after its retries) before it created an import pod: Worker.processJob clears the placeholder (ClearPendingImport, which only removes a pending- value and leaves a pod name or CDI marker to the watchers);
  • the job was lost, because the queue lives in memory and the bridge restarted, or the job never got a worker: the periodic import-pod reconcile (reconcileExistingImportPods, at watcher start and every minute) removes placeholders older than 5 minutes (stalePendingImportAge). The age check means a bridge instance starting during a rollout does not clear a placeholder the other instance is about to act on.

  Without this a VM with an orphaned placeholder would have every power action deferred forever.

• The new code is in pkg/kubevirt/import_pending.go; CheckInsertedMedia and reconcileExistingImportPods get a few lines, the handler and the worker a few more. No new goroutine; all state lives on the VM object, so a restart in the middle of an insert changes nothing.

Behaviour changes: InsertMedia writes the importing.redfish/<device> label (value pending-<unix seconds>) and the URL annotation before answering; a repeated InsertMedia while a request is pending answers 202 "in progress" (same image) or 409 (other image) instead of queueing again; a pending import whose job failed or vanished is cleared within about 5 minutes and logged as a warning.

Observed, not changed here (each is pre-existing and separate):

• a power-off that arrives while an import is pending is deferred like a power-on, which is what kept the stuck hosts from recovering when Ironic timed out; ForceOff/GracefulShutdown should run immediately and cancel the deferred power-on — fix(server): a power-off is never deferred by a pending ISO import, and withdraws a deferred power-on #37;
• an import that fails (helper pod Failed) removes the label and lets the deferred power-on start the VM on an empty CD-ROM, and GET VirtualMedia reports Inserted: true for any bound PVC — fix(kubevirt): a failed ISO import must not start the VM, read as inserted, or block a re-insert #39;
• Inserting virtual media ... with image <URL> logs the full image URL, which for an assisted-installer discovery ISO carries the image service token — fix(logger): do not log the virtual media image URL (it carries the image service token) #38.

Verification on the cluster

OpenShift 4.22 / OpenShift Virtualization 4.22, three nodes, 8 halted VMs, the bridge built from this tree and driven by a script that replays Ironic's sequence against all 8 VMs in parallel (InsertMedia, boot override Cd/Once, Reset On one second after the insert). The ISO was served from an in-cluster nginx rate-limited to 1.5 MB/s so a copy takes about 45 s, long enough for a prematurely started VM to grab the volume first.

Before (same tree without this change): 5 of 8 Power On requests executed (200), 3 deferred. Bridge log of two of the five; Successfully started is written after the start call returned, so "during import" and "before label" are the same race seen from two sides:

17:01:03.862Z Inserting virtual media cdrom0 with image <url> for VM redfish-prtest-vms/rl-vm-8
17:01:13.286Z Successfully started VM redfish-prtest-vms/rl-vm-8                      ← Power On passed the check
17:01:13.480Z Set importing label importing.redfish/cdrom0=copy-iso-rl-vm-8-... on VM redfish-prtest-vms/rl-vm-8
17:01:26.916Z Import pod copy-iso-rl-vm-8-... failed for VM redfish-prtest-vms/rl-vm-8. Logs: dd: failed to open '/mnt/iso/disk.img': Permission denied

17:01:03.660Z Inserting virtual media cdrom0 with image <url> for VM redfish-prtest-vms/rl-vm-1
17:01:12.681Z Set importing label importing.redfish/cdrom0=copy-iso-rl-vm-1-... on VM redfish-prtest-vms/rl-vm-1
17:01:12.887Z Successfully started VM redfish-prtest-vms/rl-vm-1                      ← checked before the label, logged after
17:01:26.103Z Import pod copy-iso-rl-vm-1-... failed for VM redfish-prtest-vms/rl-vm-1. Logs: dd: failed to open '/mnt/iso/disk.img': Permission denied

All five imports failed that way (every pod landed on the node that already ran the VM), the five VMs stayed Running on an empty CD-ROM and GET .../VirtualMedia/Cd answered Inserted: true. The three deferred VMs imported in 45 s and started afterwards.

After, same script, same VMs, same ISO server: 8 of 8 deferred, 8 of 8 imports succeeded, 8 VMs started after their Removed importing label. The placeholder is on the VM before the job starts, and the deferral for rl-vm-5 hit the placeholder (the job's own label came 1.2 s later):

17:26:11.032Z Marked import of cdrom0 as pending on VM redfish-prtest-vms/rl-vm-5
17:26:11.093Z Inserting virtual media cdrom0 with image <url> for VM redfish-prtest-vms/rl-vm-5
17:26:18.828Z Power action On deferred for VM redfish-prtest-vms/rl-vm-5 (import in progress)
17:26:20.033Z Set importing label importing.redfish/cdrom0=copy-iso-rl-vm-5-... on VM redfish-prtest-vms/rl-vm-5
17:27:15.150Z Import pod copy-iso-rl-vm-5-... succeeded for VM redfish-prtest-vms/rl-vm-5 volume cdrom0

The label removal and the deferred On followed the pod's success for each VM; 45 s after the run all 8 VMIs were Running, no VM carried an importing.redfish/* or power-after-import.redfish label, and no import pod was left.

• InsertMedia with an image URL that cannot be parsed: 202, placeholder on the VM, the job fails on every attempt, and 30 s later (three retries with the existing backoff) Cleared pending import of cdrom0 from VM ...; the label is gone and the VM accepts power actions.
• A placeholder written by hand with an old timestamp (importing.redfish/cdrom0=pending-1000000000) was removed by the next reconcile sweep, 36 s later: Import of cdrom0 on VM ... was accepted but never started (label importing.redfish/cdrom0=pending-1000000000), clearing it.
• With the script waiting for the boot PATCH to complete before sending Power On (22 s after the insert on this cluster, where that PATCH is slow), both trees defer all 8; the change only matters in the window, which is where Ironic normally lands.

Tests

pkg/server/insert_pending_test.go, with a task manager that has no workers so queued jobs never run (the state a Power On meets right after the 202): InsertMedia leaves the placeholder and the URL annotation on the VM before answering, and a Power On then is answered 202 deferred with power-after-import.redfish=On and the VM still halted; a repeated InsertMedia answers "in progress" and queues no second task, a different image answers 409; a job that fails after its retries clears the placeholder and marks the task Exception. With the handler change reverted (the tests need the new client helpers to compile, so they cannot run on main as is) the first fails with label importing.redfish/cdrom0 = "" after InsertMedia and the repeat test with tasks = 2 after the repeat, want 1; with the worker change reverted the third fails with label ... = "pending-..." is still on the VM after the job failed.

pkg/kubevirt/import_pending_test.go: MarkImportPending writes label and annotation and leaves other metadata alone, refuses to overwrite a running or pending import, errors on a missing VM; ClearPendingImport removes a placeholder and keeps a pod name or CDI marker; placeholder values parse and age correctly, an unparsable one counts as stale; the sweep removes only stale placeholders, in the given namespace, and leaves the other device's label on a VM alone; CheckInsertedMedia reports importing/conflict on a placeholder without a PVC and nothing-inserted when only a stale URL annotation is left; setImportingLabel replaces the placeholder.

go build ./..., go vet ./..., go test ./..., gofmt, go mod tidy (no change) pass; go test -race ./pkg/kubevirt/ passes.

Related

• fix(kubevirt): concurrent virtual-media insert and boot override could drop the CD-ROM disk from the VM spec #33: no overlapping hunks (that PR routes the spec writes through updateVM; this one adds metadata-only patches next to setImportingLabel, which fix(kubevirt): concurrent virtual-media insert and boot override could drop the CD-ROM disk from the VM spec #33 leaves alone on purpose). Verified by merging this branch onto a tree that carries fix(server): Worker.Stop blocked forever, so shutdown waited for SIGKILL #29–fix(kubevirt): concurrent virtual-media insert and boot override could drop the CD-ROM disk from the VM spec #33: builds, tests pass, and the cluster runs above were made with that merged tree.
• feat(kubevirt): serve read-only VM/VMI lookups from an informer cache #32 declares a vmGVR in cache.go; this PR uses virtualMachinesGVR so the two merge in either order.
• fix(server): spread background jobs across workers; make the pool size configurable #31: the worker pool only changes how long a job waits before it starts, and the window is at the end of the job, so no interaction.

[kubevirt-prow]

Hi @itayherzberg. Thanks for your PR.

PRs from untrusted users cannot be marked as trusted with /ok-to-test in this repo meaning untrusted PR authors can never trigger tests themselves. Collaborators can still trigger tests on the PR using /test all.

I understand the commands that are listed here.

Details

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes-sigs/prow repository.

[MarSik]

/lgtm
/approve

[kubevirt-prow]

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: MarSik

The full list of commands accepted by this bot can be found here.

The pull request process is described here

Details

Needs approval from an approver in each of these files:

• OWNERS [MarSik]

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment