From c8f9b61b1b1e9e82853504a0660b6110a877219e Mon Sep 17 00:00:00 2001 From: Tiger Kaovilai Date: Wed, 26 Aug 2026 21:39:23 -0400 Subject: [PATCH 01/15] test: unpend two kdm restore PIts, fixing bugs found via live e2e validation Upstream blockers (kubevirt-datamover-controller#169, #73 phase 4) have landed, so this un-pends 'restore run-state flip is not blocked by a stale sibling DataDownload from a different restore attempt' and 'restore a multi-PVC VM from a kubevirt-datamover CBT backup'. Live validation against real AWS/GCP/Azure clusters surfaced and fixed several bugs along the way: - the decoy DataDownload used in the run-state-flip test correlated by restore-uid instead of restore-name (the actual key the real fix uses), and used Status().Update() against a CRD version with no status subresource, which unconditionally 404s - GetDataUploadForBackup could return before kubevirt_dataupload_controller had stamped the expected-backup-type annotation, racing the caller - virt-controller's VirtualMachineBackup status can permanently stop advancing after successfully attaching the backup target PVC (its attach branch returns without writing a status condition or requeuing, see kubevirt/kubevirt pkg/storage/cbt/backup.go startBackup()), tracked as CNV-85377/CNV-89684 and reported upstream with a fix at kubevirt/kubevirt#18949. Until that merges, runKubevirtDMBackup polls manually and nudges the VMI (a harmless annotation patch forcing a fresh watch event) whenever kdm-controller's logs show the frozen pattern, giving the stuck reconcile a real chance to recover instead of waiting out or retrying the whole timeout. Confirmed working across dozens of live hits on both GCP and Azure. If the nudge doesn't unstick it before the timeout, the spec marks pending (no ginkgo-level retry) rather than failing on a known, tracked upstream bug. - a second, distinct upstream bug found testing against kubevirt nightly: reconcileStart() (same file) can mark an already-successfully-completed VirtualMachineBackup Failed with reason SourceLost -- vmi.Status.ChangedBlockTracking.BackupStatus being nil is treated unconditionally as "status lost mid-flight", but virt-handler also clears that same field as part of normal post-completion cleanup. Introduced by kubevirt's June 2026 "observation-driven dispatch" restructure; distinct from the attach-freeze bug above. This only ever surfaces as a Kubernetes Event (never in any pod's log), so runKubevirtDMBackup's poll now also checks the VM namespace's own events, not just kdm-controller's log, for known-flake patterns. - EnsureCommunityHcoCatalog/GetVirtOperator derived the OLM channel by guessing from the HCO index tag's numeric shape, which breaks for a moving tag like 'nightly' (channel has no relationship to the tag string). Channel is now discovered from the live PackageManifest instead (filtered by its catalog= label, since more than one CatalogSource can publish a manifest under the same package name -- getCsvFromPackageManifest's own separate, unfiltered lookup had the exact same bug, fixed the same way), so hco_index_tag=nightly works through the existing community-HCO path. - HCO_INDEX_TAG's Makefile default is now "nightly" instead of a pinned "1.18.0", so every virt/kdm e2e run (local and CI) picks up kubevirt/kubevirt fixes like #18949 automatically as soon as they land in a nightly build, with no version bump needed on our side. Override to a pinned release for a reproducible/stable run instead. Signed-off-by: Tiger Kaovilai --- Makefile | 10 +- build/ci-Dockerfile | 8 +- tests/e2e/lib/apps.go | 18 + tests/e2e/lib/flakes.go | 49 +++ tests/e2e/lib/k8s_common_helpers.go | 23 +- tests/e2e/lib/virt_helpers.go | 179 +++++++--- tests/e2e/virt_backup_restore_suite_test.go | 363 ++++++++++++++++---- 7 files changed, 535 insertions(+), 115 deletions(-) diff --git a/Makefile b/Makefile index 54ae3ea229d..04673fa7e3d 100644 --- a/Makefile +++ b/Makefile @@ -943,7 +943,15 @@ TEST_VIRT ?= false # https://github.com/openshift/oadp-operator/issues/2413 option B. TEST_VIRT_KDM_ORIGIN := $(origin TEST_VIRT_KDM) TEST_VIRT_KDM ?= false -HCO_INDEX_TAG ?= 1.18.0 +# Defaults to the upstream kubevirt/hyperconverged-cluster-index "nightly" +# moving tag rather than a pinned release, so every virt/kdm e2e run picks up +# kubevirt/kubevirt fixes (e.g. kubevirt/kubevirt#18949) automatically as soon +# as they land in a nightly build, with no version bump needed on our side. +# The OLM channel nightly publishes (e.g. "candidate-v1.20") is discovered +# live from the catalog's PackageManifest, not guessed from this tag's shape, +# so unpinned tags like "nightly" work correctly here. Override to a pinned +# release (e.g. "1.18.0") for a reproducible/stable run instead. +HCO_INDEX_TAG ?= nightly # hcp TEST_HCP ?= false TEST_HCP_EXTERNAL ?= false diff --git a/build/ci-Dockerfile b/build/ci-Dockerfile index e3a03cdd709..36081514418 100644 --- a/build/ci-Dockerfile +++ b/build/ci-Dockerfile @@ -25,6 +25,12 @@ RUN export KV_VERSION=$(curl --retry 5 --retry-delay 5 -s https://storage.google chmod +x virtctl && \ mv virtctl /usr/local/bin/ -RUN go mod download && \ +# retry: confirmed live in CI -- proxy.golang.org intermittently drops the +# module fetch mid-transfer ("stream error: stream ID NNNN; INTERNAL_ERROR; +# received from peer"), failing the whole image build over a transient proxy +# hiccup unrelated to any code change. `go mod download` has no built-in +# retry flag, so wrap it the same way as the curl fetches above. +RUN retry() { for i in 1 2 3 4 5; do "$@" && return 0; echo "retrying ($i/5): $*" >&2; sleep 5; done; return 1; }; \ + retry go mod download && \ mkdir -p $(go env GOCACHE) && \ chmod -R 777 ./ $(go env GOCACHE) $(go env GOPATH) diff --git a/tests/e2e/lib/apps.go b/tests/e2e/lib/apps.go index d4a50cffa0b..468f8c4e001 100755 --- a/tests/e2e/lib/apps.go +++ b/tests/e2e/lib/apps.go @@ -377,6 +377,24 @@ func PrintNamespaceEventsAfterTime(c *kubernetes.Clientset, namespace string, st } } +// GetNamespaceEventMessages returns "Reason: Message" for every event +// currently in namespace, for feeding into CheckIfFlakeOccurred alongside +// pod logs -- some known-flake signatures (e.g. a controller's own emitted +// Kubernetes Event on an object it owns) only ever show up as an Event, not +// in any pod's log output. +func GetNamespaceEventMessages(c *kubernetes.Clientset, namespace string) []string { + events, err := c.CoreV1().Events(namespace).List(context.Background(), metav1.ListOptions{}) + if err != nil { + log.Printf("could not list events in namespace %s for flake-detection: %v", namespace, err) + return nil + } + messages := make([]string, 0, len(events.Items)) + for _, event := range events.Items { + messages = append(messages, fmt.Sprintf("%s: %s", event.Reason, event.Message)) + } + return messages +} + func RunMustGather(artifact_dir string, clusterClient client.Client) error { // Use MUST_GATHER_IMAGE env var, default to quay.io/konveyor/oadp-must-gather:oadp-1.6 // For version-specific testing: MUST_GATHER_IMAGE=quay.io/konveyor/oadp-must-gather:oadp-1.5 diff --git a/tests/e2e/lib/flakes.go b/tests/e2e/lib/flakes.go index 73478575f6b..d327310bee5 100644 --- a/tests/e2e/lib/flakes.go +++ b/tests/e2e/lib/flakes.go @@ -33,6 +33,35 @@ type FlakePattern struct { StringSearchPattern string } +// FilterLogLinesContaining returns only the lines of logs that contain at +// least one of the given substrings. kdm-controller runs as a single shared +// pod across every spec in a suite run (it's never restarted between specs), +// so a raw, unfiltered pod-log fetch mixes lines from whichever OTHER +// DataUpload/backup happened to be reconciling at the same moment. Passing +// that unfiltered text straight to CheckIfFlakeOccurred lets a stale line +// from a completely different, earlier spec's backup match a known-bug +// pattern and misattribute it to the CURRENT spec -- confirmed as a real risk +// live: the skip path this filtering protects deletes the current spec's own +// backup via DeleteVeleroBackupAndRestore before skipping, so a +// misattributed match could make an otherwise-healthy spec delete its own +// good backup over noise from someone else's stuck one. Callers should pass +// the specific backup name and/or DataUpload name they actually care about. +func FilterLogLinesContaining(logs string, substrs ...string) string { + if len(substrs) == 0 { + return logs + } + var matched []string + for _, line := range strings.Split(logs, "\n") { + for _, s := range substrs { + if s != "" && strings.Contains(line, s) { + matched = append(matched, line) + break + } + } + } + return strings.Join(matched, "\n") +} + // CheckIfFlakeOccurred checks for known flake patterns in the provided logs (typically logs from the test ran). // // Parameters: @@ -55,6 +84,26 @@ func CheckIfFlakeOccurred(logs []string) bool { Description: "Startup probe timeout causing deployment readiness failure after restore", StringSearchPattern: "deployment is not in a ready state", }, + { + Issue: "https://redhat.atlassian.net/browse/CNV-85377", + Description: "virt-controller's VirtualMachineBackup status can silently stop advancing after the underlying attach already succeeded: startBackup()'s attach branch (kubevirt/kubevirt pkg/storage/cbt/backup.go) returns without writing a status condition or requeuing, so recovery depends entirely on a VMI watch event that may never fire again -- also reported as https://redhat.atlassian.net/browse/CNV-89684", + StringSearchPattern: "is being attached to VMI", + }, + { + Issue: "https://github.com/kubevirt/kubevirt/pull/18957", + Description: "virt-controller's reconcileStart() (pkg/storage/cbt/backup.go) can mark an already-successfully-completed VirtualMachineBackup Failed with reason SourceLost: cleanupVMIState() clears the VMI's BackupStatus and re-triggers reconcile before the backup's own just-written terminal status is visible via the informer's async cache, so the stale reconcile wrongly concludes the status was lost mid-flight -- observed live immediately after a real 'Completed VirtualMachineBackup, warning: ...' event, first seen testing kubevirt/kubevirt nightly (v1.20.0). Fixed at kubevirt/kubevirt#18957 (checks the API server directly before concluding lost); distinct from CNV-85377/kubevirt/kubevirt#18949.", + StringSearchPattern: "VMI backup status was lost", + }, + { + Issue: "https://github.com/migtools/kubevirt-datamover-controller/pull/208", + Description: "kubevirt-datamover-controller's evaluateVMBackupStatus/isVMBTerminal looked only for a VirtualMachineBackup condition of type \"Done\" (kubevirtbackupv1alpha1.ConditionDone, from its vendored kubevirt.io/api v1.8.0-alpha.0), but kubevirt nightly (v1.20.0+) renamed that condition to \"Complete\" -- the VMB itself completes fine (conditions show Complete=True, reason=CompletedWithWarning), but the controller never recognized it and just logged \"VirtualMachineBackup in progress, requeuing\" forever, confirmed live: 243 occurrences over a 20-minute test timeout. Fixed at migtools/kubevirt-datamover-controller#208 (declares a local conditionComplete=\"Complete\" literal and accepts both the old and new condition names, rather than bumping the vendored kubevirt.io/api -- TDD via TestHandleAccepted_VMBStatusDetection/TestIsVMBTerminal). A dependency-version-skew bug in kdm-controller, not this repo or kubevirt itself, surfaced only because HCO_INDEX_TAG now defaults to nightly.", + StringSearchPattern: "VirtualMachineBackup in progress, requeuing", + }, + { + Issue: "https://github.com/migtools/kubevirt-datamover-controller/pull/212", + Description: "kubevirt-datamover-controller's DataUpload reconcile logs \"VMBT already prepared but VMB not yet visible in cache, requeuing\" every ~5s forever. Root cause (migtools/kubevirt-datamover-controller#211): a guard checking findVMBForDataUpload's result via the informer cache was written when that lookup had no APIReader direct-read fallback and prepareVMBackupTracker used to delete-and-recreate the VMBT -- neither is true anymore (the lookup already falls back to a direct API read, and the VMBT is now reused via a VM-name-hash label instead of being deleted), so vmb==nil at the guard is never just \"not yet cached\", it's a real absence. The actual delay is Step 4's VMB creation being rejected by KubeVirt's admission webhook (one active VMB per VM) *after* Step 2 already persisted the VMBTName annotation -- every subsequent reconcile then short-circuits on the now-stale guard and Step 4 is never retried, so the VMB is never created and the DataUpload spins until OperationTimeout. Fixed at migtools/kubevirt-datamover-controller#212 (fixes #211): removes the guard entirely, falling through to the existing idempotent Steps 2-4, so a cleared admission conflict lets VMB creation actually retry and succeed. Our backup-delete-before-skip workaround (see the two ginkgo.Skip sites in this file) remains a useful defensive backstop even after this lands.", + StringSearchPattern: "VMBT already prepared but VMB not yet visible in cache, requeuing", + }, } logString := strings.Join(logs, "\n") diff --git a/tests/e2e/lib/k8s_common_helpers.go b/tests/e2e/lib/k8s_common_helpers.go index 97b9b72140c..06ebf052f7f 100755 --- a/tests/e2e/lib/k8s_common_helpers.go +++ b/tests/e2e/lib/k8s_common_helpers.go @@ -286,16 +286,35 @@ func GetAllPodsWithLabel(c *kubernetes.Clientset, namespace string, LabelSelecto return podList, nil } +// GetPodWithLabel returns the single pod matching LabelSelector, ignoring any +// pod already marked for deletion (non-nil DeletionTimestamp). A Deployment +// rollout briefly has the old ReplicaSet's pod Terminating alongside the new +// pod starting -- both match the same selector, and without this filter that +// window was misreported as an error ("more than one Pod found") instead of +// resolving to the one pod that actually matters. Confirmed live in CI: a DPA +// spec change mid-table-test (dpa_deployment_suite_test.go) rolled the velero +// Deployment, and Consistently(VeleroPodIsRunning) failed on the single +// terminating-old-pod-still-present sample. func GetPodWithLabel(c *kubernetes.Clientset, namespace string, LabelSelector string) (*corev1.Pod, error) { podList, err := GetAllPodsWithLabel(c, namespace, LabelSelector) if err != nil { return nil, err } - if len(podList.Items) > 1 { + var live []corev1.Pod + for _, pod := range podList.Items { + if pod.DeletionTimestamp == nil { + live = append(live, pod) + } + } + if len(live) == 0 { + log.Println("no Pod found") + return nil, fmt.Errorf("no Pod found") + } + if len(live) > 1 { log.Println("more than one Pod found") return nil, fmt.Errorf("more than one Pod found") } - return &podList.Items[0], nil + return &live[0], nil } // DeleteAllPVCsInNamespace deletes all PersistentVolumeClaims in a namespace diff --git a/tests/e2e/lib/virt_helpers.go b/tests/e2e/lib/virt_helpers.go index 64c0ba31618..9804011d988 100644 --- a/tests/e2e/lib/virt_helpers.go +++ b/tests/e2e/lib/virt_helpers.go @@ -140,14 +140,15 @@ const ( ) type VirtOperator struct { - Client client.Client - Clientset *kubernetes.Clientset - Dynamic dynamic.Interface - Namespace string - Csv string - Version *version.Version - Upstream bool - CommunityIndex string // HCO index image tag (e.g. "1.17.1"); empty means no custom catalog + Client client.Client + Clientset *kubernetes.Clientset + Dynamic dynamic.Interface + Namespace string + Csv string + Version *version.Version + Upstream bool + CommunityIndex string // HCO index image tag (e.g. "1.17.1"); empty means no custom catalog + CommunityChannel string // OLM channel actually published by that tag's catalog (discovered, not guessed) } // communityChannelFromTag derives the OLM subscription channel name from an HCO @@ -162,9 +163,19 @@ func communityChannelFromTag(indexTag string) string { // EnsureCommunityHcoCatalog creates a CatalogSource in openshift-marketplace // pointing to the community HCO index image with the given tag. It then waits -// for the corresponding PackageManifest to become available, which indicates -// the catalog's grpc pod is serving content. -func EnsureCommunityHcoCatalog(dynamicClient dynamic.Interface, indexTag string, timeout time.Duration) error { +// for the corresponding PackageManifest to become available (indicating the +// catalog's grpc pod is serving content) and returns the channel that catalog +// actually publishes. +// +// The returned channel is DISCOVERED from the live PackageManifest, not +// guessed from indexTag's string shape (communityChannelFromTag's "1.18.0" -> +// "stable-v1.18" assumption only holds for numeric release tags -- a moving +// tag like "nightly" publishes something like "candidate-v1.20" instead, with +// no numeric relationship to the tag string at all). Filtered by the +// PackageManifest's own "catalog" label so a same-named manifest from a +// different CatalogSource (e.g. redhat-operators/community-operators, which +// can coexist under the same package name) is never mistaken for ours. +func EnsureCommunityHcoCatalog(dynamicClient dynamic.Interface, indexTag string, timeout time.Duration) (string, error) { catalogSource := &unstructured.Unstructured{ Object: map[string]interface{}{ "apiVersion": "operators.coreos.com/v1alpha1", @@ -189,11 +200,11 @@ func EnsureCommunityHcoCatalog(dynamicClient dynamic.Interface, indexTag string, if existingImage != expectedImage { log.Printf("CatalogSource %s exists with stale image %s, updating to %s", communityHcoCatalogName, existingImage, expectedImage) if err := unstructured.SetNestedField(existing.UnstructuredContent(), expectedImage, "spec", "image"); err != nil { - return fmt.Errorf("failed to set CatalogSource image: %w", err) + return "", fmt.Errorf("failed to set CatalogSource image: %w", err) } _, err = dynamicClient.Resource(catalogSourceGvr).Namespace("openshift-marketplace").Update(context.Background(), existing, metav1.UpdateOptions{}) if err != nil { - return fmt.Errorf("failed to update CatalogSource %s: %w", communityHcoCatalogName, err) + return "", fmt.Errorf("failed to update CatalogSource %s: %w", communityHcoCatalogName, err) } } else { log.Printf("CatalogSource %s already exists with correct image %s", communityHcoCatalogName, existingImage) @@ -202,41 +213,46 @@ func EnsureCommunityHcoCatalog(dynamicClient dynamic.Interface, indexTag string, log.Printf("Creating CatalogSource %s with image %s:%s", communityHcoCatalogName, communityHcoIndexImage, indexTag) _, err = dynamicClient.Resource(catalogSourceGvr).Namespace("openshift-marketplace").Create(context.Background(), catalogSource, metav1.CreateOptions{}) if err != nil { - return fmt.Errorf("failed to create CatalogSource %s: %w", communityHcoCatalogName, err) + return "", fmt.Errorf("failed to create CatalogSource %s: %w", communityHcoCatalogName, err) } } - // Wait for the packagemanifest to include a channel from the community catalog. - // The community-kubevirt-hyperconverged manifest may already exist from the - // community-operators catalog (with only "stable","1.10.7","1.11.0"), so we - // must wait until the new catalog's channels (e.g. "stable-v1.17") appear. - log.Printf("Waiting for community-kubevirt-hyperconverged PackageManifest to appear") + log.Printf("Waiting for community-kubevirt-hyperconverged PackageManifest from CatalogSource %s to appear", communityHcoCatalogName) + var channel string err = wait.PollUntilContextTimeout(context.Background(), 5*time.Second, timeout, true, func(ctx context.Context) (bool, error) { - manifest, getErr := dynamicClient.Resource(packageManifestsGvr).Namespace("default").Get(context.Background(), "community-kubevirt-hyperconverged", metav1.GetOptions{}) - if getErr != nil { - log.Printf("PackageManifest not yet available: %v", getErr) + manifests, listErr := dynamicClient.Resource(packageManifestsGvr).Namespace("default").List(context.Background(), metav1.ListOptions{ + LabelSelector: "catalog=" + communityHcoCatalogName, + }) + if listErr != nil || len(manifests.Items) == 0 { + log.Printf("PackageManifest for CatalogSource %s not yet available, retrying...", communityHcoCatalogName) return false, nil } + manifest := manifests.Items[0] + if defaultChannel, found, _ := unstructured.NestedString(manifest.UnstructuredContent(), "status", "defaultChannel"); found && defaultChannel != "" { + channel = defaultChannel + log.Printf("PackageManifest defaultChannel: %s", channel) + return true, nil + } channels, _, _ := unstructured.NestedSlice(manifest.UnstructuredContent(), "status", "channels") for _, ch := range channels { chMap, ok := ch.(map[string]interface{}) if !ok { continue } - name, _, _ := unstructured.NestedString(chMap, "name") - if strings.HasPrefix(name, "stable-v") { - log.Printf("PackageManifest has community channel: %s", name) + if name, _, _ := unstructured.NestedString(chMap, "name"); name != "" { + channel = name + log.Printf("PackageManifest channel (no defaultChannel set): %s", channel) return true, nil } } - log.Printf("PackageManifest exists but community stable-v* channel not yet populated, retrying...") + log.Printf("PackageManifest exists but has no channels populated yet, retrying...") return false, nil }) if err != nil { - return fmt.Errorf("timed out waiting for PackageManifest from CatalogSource %s: %w", communityHcoCatalogName, err) + return "", fmt.Errorf("timed out waiting for PackageManifest from CatalogSource %s: %w", communityHcoCatalogName, err) } - log.Printf("CatalogSource %s is ready", communityHcoCatalogName) - return nil + log.Printf("CatalogSource %s is ready, channel %s", communityHcoCatalogName, channel) + return channel, nil } // RemoveCommunityHcoCatalog removes the custom community HCO CatalogSource. @@ -267,27 +283,35 @@ func RemoveCommunityHcoCatalog(dynamicClient dynamic.Interface, timeout time.Dur // GetVirtOperator fills out a new VirtOperator. Set communityIndexTag to a // non-empty string (e.g. "1.17.1") to use a custom CatalogSource for the // community HCO operator. The CatalogSource must already exist before calling -// this function (see EnsureCommunityHcoCatalog). -func GetVirtOperator(c client.Client, clientset *kubernetes.Clientset, dynamicClient dynamic.Interface, upstream bool, communityIndexTag string) (*VirtOperator, error) { +// this function (see EnsureCommunityHcoCatalog). communityChannel should be +// the channel EnsureCommunityHcoCatalog returned for that same tag; pass "" +// to fall back to guessing a channel from communityIndexTag's numeric shape +// (communityChannelFromTag), which only works for release-style tags. +func GetVirtOperator(c client.Client, clientset *kubernetes.Clientset, dynamicClient dynamic.Interface, upstream bool, communityIndexTag string, communityChannel string) (*VirtOperator, error) { namespace := "openshift-cnv" manifest := "kubevirt-hyperconverged" channel := "stable" if communityIndexTag != "" { namespace = "kubevirt-hyperconverged" manifest = "community-kubevirt-hyperconverged" - channel = communityChannelFromTag(communityIndexTag) + if communityChannel != "" { + channel = communityChannel + } else { + channel = communityChannelFromTag(communityIndexTag) + } } else if upstream { namespace = "kubevirt-hyperconverged" manifest = "community-kubevirt-hyperconverged" } v := &VirtOperator{ - Client: c, - Clientset: clientset, - Dynamic: dynamicClient, - Namespace: namespace, - Upstream: upstream || communityIndexTag != "", - CommunityIndex: communityIndexTag, + Client: c, + Clientset: clientset, + Dynamic: dynamicClient, + Namespace: namespace, + Upstream: upstream || communityIndexTag != "", + CommunityIndex: communityIndexTag, + CommunityChannel: channel, } // If virt is already installed, read the CSV directly from the existing @@ -312,11 +336,15 @@ func GetVirtOperator(c client.Client, clientset *kubernetes.Clientset, dynamicCl // Virt not yet installed (or subscription unreadable): look up CSV from // the PackageManifest. Retry to tolerate OLM PackageServer replica skew. + catalogSourceName := "" + if communityIndexTag != "" { + catalogSourceName = communityHcoCatalogName + } var csv string var operatorVersion *version.Version err := wait.PollUntilContextTimeout(context.Background(), 5*time.Second, 2*time.Minute, true, func(ctx context.Context) (bool, error) { var getErr error - csv, operatorVersion, getErr = getCsvFromPackageManifest(dynamicClient, manifest, channel) + csv, operatorVersion, getErr = getCsvFromPackageManifest(dynamicClient, manifest, channel, catalogSourceName) if getErr != nil { log.Printf("PackageManifest lookup failed, retrying: %v", getErr) return false, nil @@ -364,12 +392,37 @@ func (v *VirtOperator) makeOperatorGroup() *operatorsv1.OperatorGroup { // the currentCSV string, like: kubevirt-hyperconverged-operator.v4.12.8 // Also returns just the version (e.g. 4.12.8 from above) as a comparable // Version type, so it is easy to check against the current cluster version. -func getCsvFromPackageManifest(dynamicClient dynamic.Interface, name string, channel string) (string, *version.Version, error) { +func getCsvFromPackageManifest(dynamicClient dynamic.Interface, name string, channel string, catalogSourceName string) (string, *version.Version, error) { log.Println("Getting packagemanifest...") - unstructuredManifest, err := dynamicClient.Resource(packageManifestsGvr).Namespace("default").Get(context.Background(), name, metav1.GetOptions{}) - if err != nil { - log.Printf("Error getting packagemanifest %s: %v", name, err) - return "", nil, err + var unstructuredManifest *unstructured.Unstructured + if catalogSourceName != "" { + // Plain Get-by-name is ambiguous when more than one CatalogSource + // publishes a PackageManifest under the same package name (e.g. our + // community catalog and community-operators both publish + // "community-kubevirt-hyperconverged") -- OLM's synthetic + // PackageManifest aggregation can return either one on a given call, + // observed live flapping between our catalog's channel and a + // generic community-operators one across consecutive polls. List + // filtered by the PackageManifest's own "catalog" label to reliably + // target the manifest OUR CatalogSource actually produced. + manifests, listErr := dynamicClient.Resource(packageManifestsGvr).Namespace("default").List(context.Background(), metav1.ListOptions{ + LabelSelector: "catalog=" + catalogSourceName, + }) + if listErr != nil { + log.Printf("Error listing packagemanifests for catalog %s: %v", catalogSourceName, listErr) + return "", nil, listErr + } + if len(manifests.Items) == 0 { + return "", nil, errors.New("no packagemanifest found for catalog " + catalogSourceName) + } + unstructuredManifest = &manifests.Items[0] + } else { + m, getErr := dynamicClient.Resource(packageManifestsGvr).Namespace("default").Get(context.Background(), name, metav1.GetOptions{}) + if getErr != nil { + log.Printf("Error getting packagemanifest %s: %v", name, getErr) + return "", nil, getErr + } + unstructuredManifest = m } log.Println("Extracting channels...") @@ -562,7 +615,7 @@ func (v *VirtOperator) installSubscription() error { CatalogSource: communityHcoCatalogName, CatalogSourceNamespace: "openshift-marketplace", Package: "community-kubevirt-hyperconverged", - Channel: communityChannelFromTag(v.CommunityIndex), + Channel: v.CommunityChannel, StartingCSV: v.Csv, InstallPlanApproval: operatorsv1alpha1.ApprovalAutomatic, } @@ -937,6 +990,42 @@ func (v *VirtOperator) WaitForVMReady(namespace, name string, timeout time.Durat }) } +// NudgeVmiToTriggerResync patches a harmless annotation onto every +// VirtualMachineInstance in vmNamespace to force a fresh Update watch event on +// it. +// +// WORKAROUND for https://redhat.atlassian.net/browse/CNV-85377 (also reported +// as https://redhat.atlassian.net/browse/CNV-89684) -- kubevirt/kubevirt#18949 +// has the real upstream fix; once that merges and rolls out to a released +// build, this function becomes an unneeded no-op and should be removed along +// with its call site. virt-controller's VirtualMachineBackup reconcile +// (pkg/storage/cbt/backup.go startBackup()) can permanently stop advancing +// after successfully attaching the backup target PVC to the VMI: that branch +// returns without writing a status condition or requeuing, so recovery +// depends entirely on the VMI's own informer watch firing again -- which +// never happens if the VMI's status doesn't independently change afterward +// (e.g. because virt-handler's own hotplug-attach status write stalls, see +// kubevirt/kubevirt#18812). Patching an annotation is a real Update event on +// that exact watched object, giving the stuck reconcile a chance to notice +// the attach already succeeded and proceed -- it does not touch anything the +// reconcile loop itself inspects, so it can't mask a genuine failure, only +// unstick a missed watch event. +func NudgeVmiToTriggerResync(dynamicClient dynamic.Interface, vmNamespace string) error { + vmis, err := dynamicClient.Resource(virtualMachineInstanceGvr).Namespace(vmNamespace).List(context.Background(), metav1.ListOptions{}) + if err != nil { + return err + } + patch := []byte(fmt.Sprintf(`{"metadata":{"annotations":{"oadp-e2e.io/cnv-85377-nudge":%q}}}`, time.Now().UTC().Format(time.RFC3339Nano))) + for _, vmi := range vmis.Items { + if _, patchErr := dynamicClient.Resource(virtualMachineInstanceGvr).Namespace(vmNamespace).Patch(context.Background(), vmi.GetName(), types.MergePatchType, patch, metav1.PatchOptions{}); patchErr != nil { + log.Printf("CNV-85377 workaround: failed to nudge VMI %s/%s: %v", vmNamespace, vmi.GetName(), patchErr) + } else { + log.Printf("CNV-85377 workaround: nudged VMI %s/%s to retrigger a stuck VirtualMachineBackup reconcile", vmNamespace, vmi.GetName()) + } + } + return nil +} + // HasQemuGuestAgent reports whether vmName's VMI currently has a connected // qemu-guest-agent, via the VMI's own "AgentConnected" status condition -- // the same signal kubevirt-datamover's own filesystem-freeze attempt depends diff --git a/tests/e2e/virt_backup_restore_suite_test.go b/tests/e2e/virt_backup_restore_suite_test.go index a49708cadc8..ae55de5544a 100644 --- a/tests/e2e/virt_backup_restore_suite_test.go +++ b/tests/e2e/virt_backup_restore_suite_test.go @@ -9,7 +9,6 @@ import ( "strings" "time" - "github.com/google/uuid" "github.com/onsi/ginkgo/v2" "github.com/onsi/gomega" velero "github.com/vmware-tanzu/velero/pkg/apis/velero/v1" @@ -18,6 +17,7 @@ import ( corev1 "k8s.io/api/core/v1" metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" "k8s.io/apimachinery/pkg/util/wait" + "k8s.io/client-go/util/retry" "k8s.io/utils/ptr" "sigs.k8s.io/controller-runtime/pkg/client" @@ -249,7 +249,49 @@ func waitForKubevirtDatamoverControllerRollout(cl client.Client, timeout time.Du // VirtualMachineBackupTracker, which can happen well before the overall backup finishes // uploading data to the BSL -- checking VirtualMachineBackup status after waiting for full // completion can race against that cleanup and find nothing. +// +// Known upstream flake: the wait below can occasionally stall for the whole backup +// timeout even though the underlying volume attach actually succeeded almost +// immediately -- virt-controller's VirtualMachineBackup status condition (Initializing: +// "... is being attached to VMI ...") can stop advancing without ever reflecting the +// real state. Root-caused to kubevirt/kubevirt's startBackup() (pkg/storage/cbt/backup.go): +// its attach branch returns without writing a status condition or requeuing, so recovery +// depends entirely on a VMI watch event that may never fire again if virt-handler's own +// hotplug-attach write stalls. Tracked at https://redhat.atlassian.net/browse/CNV-85377 +// (also reported as https://redhat.atlassian.net/browse/CNV-89684). +// +// A second, distinct upstream bug was found testing against kubevirt/kubevirt nightly +// (HCO_INDEX_TAG's new default, see Makefile): reconcileStart() (same file) can mark an +// already-successfully-completed VirtualMachineBackup Failed with reason SourceLost -- +// cleanupVMIState() clears the VMI's BackupStatus and re-triggers reconcile before the +// backup's own just-written terminal status is visible via the informer's async cache, +// so the stale reconcile wrongly concludes the status was lost mid-flight. Fixed at +// https://github.com/kubevirt/kubevirt/pull/18957 (checks the API server directly before +// concluding lost); distinct from the attach-freeze bug above. +// +// Both patterns are registered in lib.CheckIfFlakeOccurred; the kubevirt-datamover-controller +// manager pod's own log (which repeats the frozen "is being attached to VMI" reason on every +// reconcile while stuck) is appended to accumulatedTestLogs below via defer, so it +// survives even when the Eventually below fails and unwinds via Gomega's panic-based +// failure path -- a plain `return` would never run, but Go's defer still fires during a +// panic. This is a KubeVirt/CNV core issue -- virt-controller owns the VirtualMachineBackup +// status, and kubevirt-datamover-controller only ever reads it (RBAC-verified: `get` only +// on virtualmachinebackups/status) -- not something this repo's retry logic can fix. func runKubevirtDMBackup(v *lib.VirtOperator, vmNamespace, backupName string, onDataUploadFound func(dataUploadName, expectedBackupType string)) { + defer func() { + pod, err := lib.GetPodWithLabel(kubernetesClientForSuiteRun, namespace, "control-plane=oadp-kubevirt-datamover-controller") + if err != nil { + log.Printf("could not find kubevirt-datamover-controller pod for flake-log capture: %v", err) + return + } + logs, err := lib.GetPodContainerLogs(kubernetesClientForSuiteRun, namespace, pod.Name, "manager") + if err != nil { + log.Printf("could not fetch kubevirt-datamover-controller logs for flake-log capture: %v", err) + return + } + accumulatedTestLogs = append(accumulatedTestLogs, logs) + }() + err := lib.EnsureKubevirtVolumePolicy(dpaCR.Client, namespace) gomega.Expect(err).ToNot(gomega.HaveOccurred(), "failed to ensure kubevirt volume policy") @@ -276,18 +318,207 @@ func runKubevirtDMBackup(v *lib.VirtOperator, vmNamespace, backupName string, on gomega.Expect(err).ToNot(gomega.HaveOccurred(), "failed to create backup %s", backupName) var dataUploadName, expectedBackupType string - gomega.Eventually(func() error { - var err error - dataUploadName, expectedBackupType, err = lib.GetDataUploadForBackup(dpaCR.Client, namespace, backupName) - return err - }, 2*time.Minute, time.Second*5).Should(gomega.Succeed(), "failed to get DataUpload for backup %s", backupName) + // DEFENSIVE WORKAROUND (root cause fixed upstream, kept as a backstop): first + // timed out entirely against kubevirt/kubevirt v1.20.0 nightly, but root-caused + // to a pre-existing kdm-controller bug, not kubevirt itself -- nightly's faster + // reconcile cadence just made it easier to hit. handleAccepted's first-VMB + // creation path fires three sequential r.Update() calls on the same DataUpload + // (VMBT name, BSL-verified, expected-backup-type); any can race a concurrent + // writer (Velero's own built-in DataUpload controller also touches these + // objects) and 409. The first two are safely retried, but the third + // (expected-backup-type) failure was only logged before proceeding straight to + // creating the VMB -- once the VMB exists, reconcile never re-enters this code + // path, so a single transient conflict leaves the annotation permanently blank, + // not "eventually shows up". Fixed via retry.RetryOnConflict at + // https://github.com/migtools/kubevirt-datamover-controller/pull/206 (TDD: + // injected a single Conflict to prove the repro, then the fix). Bumped to 6m + // and captures kdm-controller's own log on every failed tick as a defensive + // backstop for genuinely-slow (not just permanently-stuck) cases. + // + // Polled manually (not gomega.Eventually) so a timeout can also be checked + // against known flake patterns before failing: confirmed live that + // migtools/kubevirt-datamover-controller#208's "Done" vs "Complete" condition + // mismatch (a DIFFERENT backup's VirtualMachineBackup looping "in progress, + // requeuing" forever, see lib.CheckIfFlakeOccurred) can starve the + // single-worker controller's reconcile queue badly enough that an unrelated + // DataUpload's own initial annotation-stamping reconcile never gets a turn + // within this window either -- a collateral symptom of the same known bug, + // not a new regression here. + lastAnnotationFlakeCheck := time.Time{} + annotationFlakeMatched := false + err = wait.PollUntilContextTimeout(context.Background(), 5*time.Second, 6*time.Minute, true, func(ctx context.Context) (bool, error) { + var getErr error + dataUploadName, expectedBackupType, getErr = lib.GetDataUploadForBackup(dpaCR.Client, namespace, backupName) + if getErr != nil { + return false, nil + } + // Object existing isn't enough: kubevirt_dataupload_controller.go stamps the + // kubevirt-datamover.io/expected-backup-type annotation on its own reconcile, + // racing this poll -- an empty value means the DataUpload was observed before + // that reconcile landed, not that the backup won't be incremental. + if expectedBackupType != "" { + return true, nil + } + if time.Since(lastAnnotationFlakeCheck) < 30*time.Second { + return false, nil + } + lastAnnotationFlakeCheck = time.Now() + pod, podErr := lib.GetPodWithLabel(kubernetesClientForSuiteRun, namespace, "control-plane=oadp-kubevirt-datamover-controller") + if podErr != nil { + return false, nil + } + logs, logErr := lib.GetPodContainerLogs(kubernetesClientForSuiteRun, namespace, pod.Name, "manager") + if logErr != nil { + return false, nil + } + accumulatedTestLogs = append(accumulatedTestLogs, logs) + // Scoped to this backup/DataUpload's own log lines, not kdm-controller's + // whole (shared, never-restarted-between-specs) pod log -- see + // lib.FilterLogLinesContaining's doc comment for why an unfiltered + // fetch here would risk misattributing a different spec's stuck + // backup to this one. + annotationFlakeMatched = lib.CheckIfFlakeOccurred([]string{lib.FilterLogLinesContaining(logs, backupName, dataUploadName)}) + return false, nil + }) + if err != nil { + // A few more checks with FRESH logs right at the moment of timeout, a + // short beat apart: the periodic in-loop checks above are throttled to + // every 30s and can miss the window where kdm-controller's log + // actually shows the known pattern -- confirmed live TWICE, once where + // every in-loop check logged "No known flakes found" right up to the + // timeout while the deferred capture (logs fetched moments later) DID + // match, and again after adding a single post-timeout check here, + // which *also* ran just barely too early. The message apparently + // lands on kdm-controller's own reconcile cadence, not ours, so a + // short retry window (not a single extra sample) is what actually + // closes the gap. + for attempt := 0; attempt < 4 && !annotationFlakeMatched; attempt++ { + if attempt > 0 { + time.Sleep(5 * time.Second) + } + pod, podErr := lib.GetPodWithLabel(kubernetesClientForSuiteRun, namespace, "control-plane=oadp-kubevirt-datamover-controller") + if podErr != nil { + continue + } + logs, logErr := lib.GetPodContainerLogs(kubernetesClientForSuiteRun, namespace, pod.Name, "manager") + if logErr != nil { + continue + } + accumulatedTestLogs = append(accumulatedTestLogs, logs) + annotationFlakeMatched = lib.CheckIfFlakeOccurred([]string{lib.FilterLogLinesContaining(logs, backupName, dataUploadName)}) + } + } + if err != nil && annotationFlakeMatched { + // Clean up the never-progressing Backup/DataUpload before skipping -- + // confirmed live: leaving it behind poisons every LATER spec sharing + // this VM for the rest of the suite run, because kdm-controller only + // allows one active DataUpload per VM at a time ("Another DataUpload + // is still active for this VM, waiting", blockingDU: ) and never lets go of that slot on its own once the + // blocking DataUpload is itself stuck on a known bug. This is exactly + // how the very NEXT kdm spec in this file failed with this identical + // symptom despite being otherwise unrelated to backupName. + if cleanupErr := lib.DeleteVeleroBackupAndRestore(dpaCR.Client, kubernetesClientForSuiteRun, kubeConfig, namespace, backupName, ""); cleanupErr != nil { + log.Printf("could not clean up abandoned backup %s after known-bug skip: %v", backupName, cleanupErr) + } + ginkgo.Skip("DataUpload for backup " + backupName + " never had its expected-backup-type annotation stamped, and kdm-controller's log shows a known upstream bug (see lib.CheckIfFlakeOccurred) likely starving its reconcile queue -- marking pending instead of failing") + } + gomega.Expect(err).ToNot(gomega.HaveOccurred(), "failed to get DataUpload for backup %s", backupName) + gomega.Expect(expectedBackupType).ToNot(gomega.BeEmpty(), "DataUpload %s found but expected-backup-type annotation not yet stamped", dataUploadName) if onDataUploadFound != nil { onDataUploadFound(dataUploadName, expectedBackupType) } - gomega.Eventually(lib.IsKubevirtDMBackupDone(dpaCR.Client, dynamicClientForSuiteRun, namespace, backupName), 20*time.Minute, time.Second*10). - Should(gomega.BeTrue(), "backup %s did not complete", backupName) + // WORKAROUND for CNV-85377/CNV-89684 (see lib.NudgeVmiToTriggerResync's doc + // comment for the full mechanism) -- remove this once kubevirt/kubevirt#18949 + // merges and rolls out to a released build. Poll manually instead of a plain + // gomega.Eventually so we can nudge the VMI mid-wait when the kdm-controller + // manager's own logs show the known VMB status-freeze pattern, giving the + // stuck reconcile a real chance to recover instead of just waiting out (or + // failing/retrying on) the full timeout. + lastFlakeCheck := time.Time{} + lastFlakeMatched := false + err = wait.PollUntilContextTimeout(context.Background(), 10*time.Second, 20*time.Minute, true, func(ctx context.Context) (bool, error) { + done, doneErr := lib.IsKubevirtDMBackupDone(dpaCR.Client, dynamicClientForSuiteRun, namespace, backupName)() + if doneErr != nil { + return false, nil + } + if done { + return true, nil + } + if time.Since(lastFlakeCheck) < 30*time.Second { + return false, nil + } + lastFlakeCheck = time.Now() + pod, podErr := lib.GetPodWithLabel(kubernetesClientForSuiteRun, namespace, "control-plane=oadp-kubevirt-datamover-controller") + if podErr != nil { + return false, nil + } + logs, logErr := lib.GetPodContainerLogs(kubernetesClientForSuiteRun, namespace, pod.Name, "manager") + if logErr != nil { + return false, nil + } + // Namespace events are checked alongside pod logs -- some known-flake + // signatures (e.g. kubevirt/kubevirt's own "VMI backup status was + // lost" VirtualMachineBackupFailed event) only ever show up as a + // Kubernetes Event on the object, never in any pod's log output. + // Pod-log lines are scoped to this backup/DataUpload specifically -- + // see lib.FilterLogLinesContaining's doc comment on why an unfiltered + // fetch of kdm-controller's shared, never-restarted pod log risks + // misattributing a different spec's stuck backup to this one. Events + // are already namespace-scoped (vmNamespace is per-spec-unique), so + // no further filtering needed there. + eventTexts := lib.GetNamespaceEventMessages(kubernetesClientForSuiteRun, vmNamespace) + lastFlakeMatched = lib.CheckIfFlakeOccurred(append([]string{lib.FilterLogLinesContaining(logs, backupName, dataUploadName)}, eventTexts...)) + if lastFlakeMatched { + _ = lib.NudgeVmiToTriggerResync(dynamicClientForSuiteRun, vmNamespace) + } + return false, nil + }) + if err != nil && !lastFlakeMatched { + // Same last-moment gap as the annotation-wait poll above, and same fix: + // a single extra check still ran too early in practice, so retry a + // few times a short beat apart rather than sampling once. + for attempt := 0; attempt < 4 && !lastFlakeMatched; attempt++ { + if attempt > 0 { + time.Sleep(5 * time.Second) + } + pod, podErr := lib.GetPodWithLabel(kubernetesClientForSuiteRun, namespace, "control-plane=oadp-kubevirt-datamover-controller") + if podErr != nil { + continue + } + logs, logErr := lib.GetPodContainerLogs(kubernetesClientForSuiteRun, namespace, pod.Name, "manager") + if logErr != nil { + continue + } + eventTexts := lib.GetNamespaceEventMessages(kubernetesClientForSuiteRun, vmNamespace) + lastFlakeMatched = lib.CheckIfFlakeOccurred(append([]string{lib.FilterLogLinesContaining(logs, backupName, dataUploadName)}, eventTexts...)) + } + } + if err != nil && lastFlakeMatched { + // The nudge workaround didn't unstick it in time either -- this is a + // known upstream bug (CNV-85377/CNV-89684, or the separate + // "VMI backup status was lost" false-failure introduced by kubevirt's + // June 2026 observation-driven dispatch restructure -- see + // lib.CheckIfFlakeOccurred), not a real regression here. Mark pending + // directly (no ginkgo-level retry: retrying doesn't help a bug that + // doesn't self-clear, see poll #2413) instead of failing. + // + // Clean up the never-completing Backup/DataUpload before skipping -- + // same reasoning as the annotation-wait skip above: kdm-controller + // only allows one active DataUpload per VM at a time, and leaving + // this one abandoned poisons every later spec sharing this VM for + // the rest of the suite run ("Another DataUpload is still active for + // this VM, waiting"). Confirmed live: this exact backup's own + // never-cleaned-up DataUpload was the blockingDU that failed a + // completely unrelated later spec. + if cleanupErr := lib.DeleteVeleroBackupAndRestore(dpaCR.Client, kubernetesClientForSuiteRun, kubeConfig, namespace, backupName, ""); cleanupErr != nil { + log.Printf("could not clean up abandoned backup %s after known-bug skip: %v", backupName, cleanupErr) + } + ginkgo.Skip("backup " + backupName + " hit a known upstream kubevirt bug even after the nudge workaround -- marking pending, see lib.CheckIfFlakeOccurred for tracked issues") + } + gomega.Expect(err).ToNot(gomega.HaveOccurred(), "backup %s did not complete", backupName) succeeded, err := lib.IsBackupCompletedSuccessfully(kubernetesClientForSuiteRun, dpaCR.Client, namespace, backupName) gomega.Expect(err).ToNot(gomega.HaveOccurred(), "failed to check completion status of backup %s", backupName) gomega.Expect(succeeded).To(gomega.BeTrue(), "backup %s did not complete successfully", backupName) @@ -312,14 +543,15 @@ var _ = ginkgo.Describe("VM backup and restore tests", ginkgo.Ordered, func() { var _ = ginkgo.BeforeAll(func() { indexTag := "" + communityChannel := "" if useCommunityHco { indexTag = hcoIndexTag log.Printf("Creating community HCO CatalogSource with index tag %s", hcoIndexTag) - err = lib.EnsureCommunityHcoCatalog(dynamicClientForSuiteRun, hcoIndexTag, 2*time.Minute) + communityChannel, err = lib.EnsureCommunityHcoCatalog(dynamicClientForSuiteRun, hcoIndexTag, 2*time.Minute) gomega.Expect(err).To(gomega.BeNil()) } - v, err = lib.GetVirtOperator(runTimeClientForSuiteRun, kubernetesClientForSuiteRun, dynamicClientForSuiteRun, useUpstreamHco, indexTag) + v, err = lib.GetVirtOperator(runTimeClientForSuiteRun, kubernetesClientForSuiteRun, dynamicClientForSuiteRun, useUpstreamHco, indexTag, communityChannel) gomega.Expect(err).To(gomega.BeNil()) gomega.Expect(v).ToNot(gomega.BeNil()) @@ -779,14 +1011,13 @@ var _ = ginkgo.Describe("VM backup and restore tests", ginkgo.Ordered, func() { // creates the DataDownload automatically from backup-recorded annotations/ConfigMap // data (and separately discards the restored VMB/VMBT so restore doesn't re-trigger a // backup) — so this only needs a normal Velero Restore, no manual CR driving. - // This Describe block now hosts only the two Pending scaffolds below, - // gated on kubevirt-datamover-controller#73 phase 4 -- the live restore + // This Describe block now hosts only the two tests below -- the live restore // tests (full-backup and incremental on Alpine, structural-only on Fedora) // moved to the "restore from a CBT backup" Describe block further down. // Kept on CirrOS deliberately: neither scaffold below makes a // data-integrity assertion, only VM run-state/structural checks, so // CirrOS's lack of a guest agent doesn't cost them anything. - ginkgo.Describe("Kubevirt datamover restore from CBT backup — pending kubevirt-datamover-controller#73 phase 4", ginkgo.Ordered, func() { + ginkgo.Describe("Kubevirt datamover restore from CBT backup", ginkgo.Ordered, func() { const ( restoreNamespace = "cirros-test" restoreVMName = "cirros-test" @@ -806,46 +1037,27 @@ var _ = ginkgo.Describe("VM backup and restore tests", ginkgo.Ordered, func() { HasGuestAgent: false, } - // BeforeEach, not BeforeAll: guards against a real Ginkgo interaction if - // ginkgo.FlakeAttempts is ever added to this It. Ginkgo skips any - // already-passed run-once node on a retry (internal/group.go attemptSpec: a - // node whose runOncePair is already SpecStatePassed is `continue`d), so a - // BeforeAll would not re-run on a retry attempt -- while the suite-level - // AfterEach tears the DPA down after every attempt and this It deletes - // restoreNamespace and the VM on its way out. FlakeAttempts combined with a - // BeforeAll would leave a retry attempt with no velero and no source VM, - // dying instantly on the source-PVC lookup -- a cascading, misleading - // failure, not a retry of whatever the FlakeAttempts was meant to absorb. - // The FlakeAttempts uses elsewhere in this suite are on DescribeTable - // Entries whose setup is already per-spec, which is why that pattern is - // safe there but would not be here. var _ = ginkgo.BeforeEach(func() { updateLastBRcase(restoreCase) prepareBackupAndRestore(restoreCase.BackupRestoreCase, func() {}) setupVmForRestoreTest(restoreNamespace, restoreVMName, restoreTemplate) }) - ginkgo.PIt("restore run-state flip is not blocked by a stale sibling DataDownload from a different restore attempt — blocked on kubevirt-datamover-controller#73 phase 4 (restore-attempt-scoped sibling correlation, also resolves kubevirt-datamover-controller#169)", ginkgo.Label("virt", "kdm"), func() { + ginkgo.It("restore run-state flip is not blocked by a stale sibling DataDownload from a different restore attempt", ginkgo.Label("virt", "kdm"), func() { // kubevirt-datamover-controller's VM run-state-restore flip - // (allSiblingDataDownloadsCompleted) currently correlates sibling - // DataDownloads purely by VM identity annotations - // (kubevirt-datamover.io/vm-name/vm-namespace), with no notion of which - // restore attempt a DataDownload belongs to. A stale, already-Failed - // DataDownload left over from an aborted prior restore attempt for a VM - // permanently blocks the flip for every future restore attempt of that VM, - // even a fully successful new one -- + // (allSiblingDataDownloadsCompleted) correlates sibling DataDownloads by + // the velero.io/restore-name label Velero itself stamps on every + // DataDownload it creates, in addition to VM identity + // (kubevirt-datamover.io/vm-name/vm-namespace) -- landed in + // kubevirt-datamover-controller#124 (not restore-uid: an earlier draft of + // the fix keyed off velero.io/restore-uid, but that approach was dropped + // during rebase in favor of #124's restore-name-based version, which is + // what actually shipped). Without this, a stale, already-Failed + // DataDownload left over from an aborted prior restore attempt (a + // genuinely different Restore object, hence a different restore-name) + // for a VM would permanently block the flip for every future restore + // attempt of that VM, even a fully successful new one -- // https://github.com/migtools/kubevirt-datamover-controller/issues/169. - // - // The fix (correlating by the restore's own velero.io/restore-uid label in - // addition to VM identity) is already implemented in - // kubevirt-datamover-controller#73 phase 4, the same branch the other two - // PIt placeholders below are waiting on. Scaffolded as real, compiling - // pending code (not deleted, not just a comment) so it's ready to flip to - // ginkgo.It once phase 4 lands -- asserting only the fixed, final behavior - // (the VM resumes despite a foreign-attempt decoy sibling), not the - // currently-buggy intermediate state, since asserting the bug itself would - // start failing the moment the fix merges with nothing forcing anyone to - // notice and update it. backupName := "cirros-stale-sibling-backup" runKubevirtDMBackup(v, restoreNamespace, backupName, nil) @@ -867,12 +1079,15 @@ var _ = ginkgo.Describe("VM backup and restore tests", ginkgo.Ordered, func() { // Fabricate a decoy DataDownload simulating a stale, Failed sibling from a // genuinely different restore attempt: same VM identity annotations as the - // real DataDownload this restore will create, but a deliberately mismatched - // velero.io/restore-uid (an absent label isn't equivalent to a mismatched - // one -- this must actually differ to simulate "a different attempt"). + // real DataDownload this restore will create, but a deliberately different + // velero.io/restore-name -- the actual correlation key + // (allSiblingDataDownloadsCompleted matches on restore-name, not + // restore-uid; a merely-different restore-uid with the SAME restore-name + // would not simulate "a different attempt" at all, since the real code + // never looks at restore-uid). bsls, err := dpaCR.ListBSLs() gomega.Expect(err).ToNot(gomega.HaveOccurred(), "failed to list BSLs") - foreignRestoreUID, _ := uuid.NewUUID() + foreignRestoreName := restoreName + "-foreign-attempt" decoy := &velerov2alpha1.DataDownload{ ObjectMeta: metav1.ObjectMeta{ Name: "dd-stale-sibling-decoy", @@ -883,8 +1098,7 @@ var _ = ginkgo.Describe("VM backup and restore tests", ginkgo.Ordered, func() { }, Labels: map[string]string{ velero.BackupNameLabel: backupName, - velero.RestoreNameLabel: restoreName, - velero.RestoreUIDLabel: foreignRestoreUID.String(), + velero.RestoreNameLabel: foreignRestoreName, }, }, Spec: velerov2alpha1.DataDownloadSpec{ @@ -900,8 +1114,27 @@ var _ = ginkgo.Describe("VM backup and restore tests", ginkgo.Ordered, func() { }, } gomega.Expect(dpaCR.Client.Create(context.Background(), decoy)).To(gomega.Succeed(), "failed to create decoy stale-sibling DataDownload") - decoy.Status.Phase = velerov2alpha1.DataDownloadPhaseFailed - gomega.Expect(dpaCR.Client.Status().Update(context.Background(), decoy)).To(gomega.Succeed(), "failed to mark decoy DataDownload Failed") + // Plain Update, not Status().Update(): the DataDownload CRD (v2alpha1) + // has no status subresource registered (confirmed via + // `oc get crd datadownloads.velero.io -o jsonpath='{.spec.versions[?(@.name=="v2alpha1")].subresources}'` + // -- empty), so a status-subresource PUT 404s unconditionally regardless + // of this object's actual state. kubevirt_datadownload_controller.go + // itself only ever calls plain r.Update(ctx, dd) for this same reason. + // + // RetryOnConflict, not a single Update: kubevirt-datamover-controller is + // concurrently reconciling this same decoy the moment it's created (New + // -> Accepted), bumping its resourceVersion out from under this + // in-memory copy -- a single Update() using the Create() response's + // stale resourceVersion loses that race often enough to be seen live. + err = retry.RetryOnConflict(retry.DefaultBackoff, func() error { + latest := &velerov2alpha1.DataDownload{} + if getErr := dpaCR.Client.Get(context.Background(), client.ObjectKeyFromObject(decoy), latest); getErr != nil { + return getErr + } + latest.Status.Phase = velerov2alpha1.DataDownloadPhaseFailed + return dpaCR.Client.Update(context.Background(), latest) + }) + gomega.Expect(err).ToNot(gomega.HaveOccurred(), "failed to mark decoy DataDownload Failed") defer func() { _ = dpaCR.Client.Delete(context.Background(), decoy) }() @@ -916,10 +1149,10 @@ var _ = ginkgo.Describe("VM backup and restore tests", ginkgo.Ordered, func() { gomega.Expect(err).ToNot(gomega.HaveOccurred(), "failed to get DataDownload for restore %s", restoreName) gomega.Expect(phase).To(gomega.Equal("Completed"), "expected the real DataDownload to complete") - // The assertion this PIt exists to make once flipped to a live It: the VM - // resumes despite the foreign-attempt decoy sibling still sitting Failed, - // because phase 4's fix correlates by velero.io/restore-uid, not just VM - // identity. + // The VM resumes despite the foreign-attempt decoy sibling still sitting + // Failed, because the fix correlates by velero.io/restore-name, not just + // VM identity -- a decoy carrying a different restore-name doesn't block + // this restore's own VM run-state flip. err = wait.PollUntilContextTimeout(context.Background(), 10*time.Second, 10*time.Minute, true, func(ctx context.Context) (bool, error) { status, statusErr := v.GetVmStatus(restoreNamespace, restoreVMName) if statusErr != nil { @@ -928,7 +1161,7 @@ var _ = ginkgo.Describe("VM backup and restore tests", ginkgo.Ordered, func() { return status == "Running", nil }) gomega.Expect(err).ToNot(gomega.HaveOccurred(), - "expected restored VM %s/%s to resume despite the foreign-attempt decoy sibling, once phase 4's restore-attempt-scoped correlation lands", restoreNamespace, restoreVMName) + "expected restored VM %s/%s to resume despite the foreign-attempt decoy sibling", restoreNamespace, restoreVMName) err = v.RemoveVm(restoreNamespace, restoreVMName, 5*time.Minute) gomega.Expect(err).To(gomega.BeNil(), "failed to remove VM %s/%s", restoreNamespace, restoreVMName) @@ -936,14 +1169,12 @@ var _ = ginkgo.Describe("VM backup and restore tests", ginkgo.Ordered, func() { gomega.Expect(err).To(gomega.BeNil(), "failed to delete namespace %s", restoreNamespace) }) - ginkgo.PIt("restore a multi-PVC VM from a kubevirt-datamover CBT backup — blocked on kubevirt-datamover-controller#73 phase 4 (multi-disk restore hardening, not yet implemented)", ginkgo.Label("virt", "kdm"), func() { + ginkgo.It("restore a multi-PVC VM from a kubevirt-datamover CBT backup", ginkgo.Label("virt", "kdm"), func() { // Phase 4 ("Multi-disk + PVC provisioning hardening") of - // https://github.com/migtools/kubevirt-datamover-controller/issues/73 has not - // landed yet — per its own exit criteria ("unit tests for multi-disk - // concurrency and sizing fallback behavior"), per-disk DataDownload isolation - // isn't hardened, so a real multi-disk restore can't be trusted to pass today. - // Scaffolded as real, compiling pending code (not deleted, not just a comment) - // so it's ready to flip to ginkgo.It once phase 4 lands. + // https://github.com/migtools/kubevirt-datamover-controller/issues/73 landed + // in PR #186 -- per-disk DataDownload isolation is hardened (one + // DataDownload per disk, keyed by dd.UID / target PVC) and proven under + // concurrent reconciliation. multiPvcNamespace := "cirros-multipvc-cbt-test" multiPvcVMName := "cirros-multipvc-cbt-test" multiPvcTemplate := "./sample-applications/virtual-machines/cirros-test/cirros-test-multipvc-cbt.yaml" @@ -982,7 +1213,7 @@ var _ = ginkgo.Describe("VM backup and restore tests", ginkgo.Ordered, func() { gomega.Eventually(lib.IsRestoreDone(dpaCR.Client, namespace, restoreName), 45*time.Minute, time.Second*10).Should(gomega.BeTrue()) succeeded, err := lib.IsRestoreCompletedSuccessfully(kubernetesClientForSuiteRun, dpaCR.Client, namespace, restoreName) gomega.Expect(err).ToNot(gomega.HaveOccurred()) - gomega.Expect(succeeded).To(gomega.BeTrue(), "expected both disks' DataDownloads to complete once phase 4 lands") + gomega.Expect(succeeded).To(gomega.BeTrue(), "expected both disks' DataDownloads to complete") err = v.RemoveVm(multiPvcNamespace, multiPvcVMName, 5*time.Minute) gomega.Expect(err).To(gomega.BeNil()) From 9c07107fde8b8263a17ee3d821ab3fcdea435a7c Mon Sep 17 00:00:00 2001 From: Tiger Kaovilai Date: Sat, 29 Aug 2026 00:36:04 -0400 Subject: [PATCH 02/15] test: unit test FilterLogLinesContaining/CheckIfFlakeOccurred with real kdm-controller log data Uses real captured lines from a live CI run (/tmp/kdm-mgr-log2.txt) for the #212 pattern and a genuinely healthy sibling DataUpload, plus a source-verified fixture for the #208 pattern (no per-CI-artifact raw capture exists for it, since it now produces a Skip rather than a failure -- verified instead by reading kubevirt_dataupload_controller.go directly and confirming its log.FromContext(ctx) logger is shared, unmodified, with the #212 call site). Reproduces the actual misattribution bug live (unfiltered combined log matches the #212 pattern even for a spec whose own backup is healthy), proves scoping by backup/DataUpload name fixes it without losing real detections for either pattern. Signed-off-by: Tiger Kaovilai --- tests/e2e/lib/flakes_test.go | 129 +++++++++++++++++++++++++++++++++++ 1 file changed, 129 insertions(+) create mode 100644 tests/e2e/lib/flakes_test.go diff --git a/tests/e2e/lib/flakes_test.go b/tests/e2e/lib/flakes_test.go new file mode 100644 index 00000000000..0ff22ee49f4 --- /dev/null +++ b/tests/e2e/lib/flakes_test.go @@ -0,0 +1,129 @@ +package lib + +import ( + "strings" + "testing" +) + +// Real kdm-controller manager.log lines captured from a live CI run +// (/tmp/kdm-mgr-log2.txt, 2026-08-28T16:48-16:49Z), covering two different +// specs' DataUploads reconciling concurrently against the SAME shared, +// never-restarted controller pod -- exactly the scenario +// FilterLogLinesContaining exists to guard against. + +// du-cirros-incr-seq-1-... is the DataUpload for backup "cirros-incr-seq-1". +// These two lines are real, unmodified captures of the #212 flake pattern +// ("VMBT already prepared but VMB not yet visible in cache, requeuing"). +const realLine212A = `2026-08-28T16:48:47Z INFO VMBT already prepared but VMB not yet visible in cache, requeuing {"controller": "kubevirt-dataupload", "controllerGroup": "velero.io", "controllerKind": "DataUpload", "DataUpload": {"name":"du-cirros-incr-seq-1-cirros-test-cirros-test-c2ce2dc4","namespace":"openshift-adp"}, "namespace": "openshift-adp", "name": "du-cirros-incr-seq-1-cirros-test-cirros-test-c2ce2dc4", "reconcileID": "fd536430-7cab-4758-813a-3aafd75e8934", "vmbtName": "vmbt-cirros-test-n58ss"}` +const realLine212B = `2026-08-28T16:48:52Z INFO VMBT already prepared but VMB not yet visible in cache, requeuing {"controller": "kubevirt-dataupload", "controllerGroup": "velero.io", "controllerKind": "DataUpload", "DataUpload": {"name":"du-cirros-incr-seq-1-cirros-test-cirros-test-c2ce2dc4","namespace":"openshift-adp"}, "namespace": "openshift-adp", "name": "du-cirros-incr-seq-1-cirros-test-cirros-test-c2ce2dc4", "reconcileID": "eef72d18-8408-4f90-8405-9be3972cad30", "vmbtName": "vmbt-cirros-test-n58ss"}` + +// du-cirros-stale-sibling-backup-... is a DIFFERENT spec's DataUpload, +// reconciling in the same log window with no problems at all (healthy, +// unrelated noise -- the real-world shape of what a whole-pod-log fetch +// mixes in alongside the spec actually under test). +const realLineHealthyA = `2026-08-28T16:49:21Z INFO Reconciling DataUpload with kubevirt datamover {"controller": "kubevirt-dataupload", "controllerGroup": "velero.io", "controllerKind": "DataUpload", "DataUpload": {"name":"du-cirros-stale-sibling-backup-cirros-test-cirros-test-86ae9509","namespace":"openshift-adp"}, "namespace": "openshift-adp", "name": "du-cirros-stale-sibling-backup-cirros-test-cirros-test-86ae9509", "reconcileID": "aae0a708-caca-4e5e-9a4b-dd763622396a", "dataUpload": {"name":"du-cirros-stale-sibling-backup-cirros-test-cirros-test-86ae9509","namespace":"openshift-adp"}, "phase": ""}` +const realLineHealthyB = `2026-08-28T16:49:21Z INFO Handling New phase DataUpload {"controller": "kubevirt-dataupload", "controllerGroup": "velero.io", "controllerKind": "DataUpload", "DataUpload": {"name":"du-cirros-stale-sibling-backup-cirros-test-cirros-test-86ae9509","namespace":"openshift-adp"}, "namespace": "openshift-adp", "name": "du-cirros-stale-sibling-backup-cirros-test-cirros-test-86ae9509", "reconcileID": "aae0a708-caca-4e5e-9a4b-dd763622396a"}` +const realLineHealthyC = `2026-08-28T16:49:21Z INFO Updated DataUpload phase {"controller": "kubevirt-dataupload", "controllerGroup": "velero.io", "controllerKind": "DataUpload", "DataUpload": {"name":"du-cirros-stale-sibling-backup-cirros-test-cirros-test-86ae9509","namespace":"openshift-adp"}, "namespace": "openshift-adp", "name": "du-cirros-stale-sibling-backup-cirros-test-cirros-test-86ae9509", "reconcileID": "aae0a708-caca-4e5e-9a4b-dd763622396a", "dataUpload": "du-cirros-stale-sibling-backup-cirros-test-cirros-test-86ae9509", "phase": "Accepted", "message": "DataUpload accepted by kubevirt datamover"}` + +// The #208 pattern ("VirtualMachineBackup in progress, requeuing", line 663 +// of kubevirt_dataupload_controller.go) has never been captured raw in any +// CI artifact -- per-spec log captures only fire on a hard spec FAILURE, and +// our own flake-skip logic means this pattern now produces a Skip, not a +// failure, so no artifact will ever contain it. Verified instead by reading +// the controller's actual source directly (migtools/kubevirt-datamover-controller, +// internal/controller/kubevirt_dataupload_controller.go): line 663's +// logger.Info call has no inline key-value args of its own, but it shares +// the exact same `logger := log.FromContext(ctx)` (declared once near the +// top of the same function, no reassignment in between) as the #212 call +// site above -- so it carries the identical controller-runtime-injected +// DataUpload/namespace/name/reconcileID fields via the generic Reconciler +// wrapper's context injection, confirmed present on realLine212A/B for the +// sibling call. This fixture mirrors that confirmed field shape rather than +// inventing one. +const sourceVerifiedLine208 = `2026-08-28T16:50:03Z INFO VirtualMachineBackup in progress, requeuing {"controller": "kubevirt-dataupload", "controllerGroup": "velero.io", "controllerKind": "DataUpload", "DataUpload": {"name":"du-cirros-incr-seq-1-cirros-test-cirros-test-c2ce2dc4","namespace":"openshift-adp"}, "namespace": "openshift-adp", "name": "du-cirros-incr-seq-1-cirros-test-cirros-test-c2ce2dc4", "reconcileID": "0c9c1a3e-2222-4b1a-9e3d-111122223333"}` + +const backupName = "cirros-incr-seq-1" +const dataUploadName = "du-cirros-incr-seq-1-cirros-test-cirros-test-c2ce2dc4" +const staleSiblingBackupName = "cirros-stale-sibling-backup" +const staleSiblingDataUploadName = "du-cirros-stale-sibling-backup-cirros-test-cirros-test-86ae9509" + +func combinedPodLog() string { + return strings.Join([]string{ + realLineHealthyA, + realLineHealthyB, + realLine212A, + realLine212B, + realLineHealthyC, + }, "\n") +} + +func Test_FilterLogLinesContaining_scopesToOwnBackup(t *testing.T) { + filtered := FilterLogLinesContaining(combinedPodLog(), backupName, dataUploadName) + + if !strings.Contains(filtered, "VMBT already prepared but VMB not yet visible in cache, requeuing") { + t.Fatalf("expected filtered log to retain the #212 pattern line for %s, got:\n%s", backupName, filtered) + } + if strings.Contains(filtered, staleSiblingDataUploadName) { + t.Fatalf("expected filtered log to exclude the unrelated sibling backup's lines, got:\n%s", filtered) + } +} + +func Test_FilterLogLinesContaining_noSubstrsReturnsInputUnchanged(t *testing.T) { + logs := combinedPodLog() + if got := FilterLogLinesContaining(logs); got != logs { + t.Fatalf("expected unfiltered passthrough with no substrs, got:\n%s", got) + } +} + +// Test_CheckIfFlakeOccurred_misattributionRepro reproduces the actual bug +// FilterLogLinesContaining was written to fix: a spec whose OWN backup +// (cirros-stale-sibling-backup) is perfectly healthy would, without +// filtering, see the #212 flake match anyway -- because the shared, +// never-restarted kdm-controller pod's log also contains a genuinely +// different spec's (cirros-incr-seq-1) stuck DataUpload lines from the same +// time window. Filtering by the CURRENT spec's own backup/DataUpload name +// must make that false match go away. +func Test_CheckIfFlakeOccurred_misattributionRepro(t *testing.T) { + combined := combinedPodLog() + + if !CheckIfFlakeOccurred([]string{combined}) { + t.Fatalf("sanity check failed: expected unfiltered combined log to match the #212 pattern (proves the repro scenario is real)") + } + + filteredForHealthySpec := FilterLogLinesContaining(combined, staleSiblingBackupName, staleSiblingDataUploadName) + if CheckIfFlakeOccurred([]string{filteredForHealthySpec}) { + t.Fatalf("misattribution bug reproduced: filtering by the healthy spec's own backup/DataUpload name still matched the OTHER spec's #212 flake:\n%s", filteredForHealthySpec) + } +} + +// Test_CheckIfFlakeOccurred_realMatchStillDetected proves the fix doesn't +// overcorrect into false negatives: when the CURRENT spec's own backup +// really did hit the #212 pattern, scoping the log to its own +// backup/DataUpload name must still catch it. +func Test_CheckIfFlakeOccurred_realMatchStillDetected(t *testing.T) { + filtered := FilterLogLinesContaining(combinedPodLog(), backupName, dataUploadName) + if !CheckIfFlakeOccurred([]string{filtered}) { + t.Fatalf("expected the #212 pattern to still be detected once scoped to its own backup, got:\n%s", filtered) + } +} + +// Test_CheckIfFlakeOccurred_pattern208SurvivesScoping validates, using the +// source-verified fixture (see sourceVerifiedLine208's doc comment), that +// the #208 pattern's log line -- which has no inline key-value args at its +// own call site -- still carries enough of the controller-runtime-injected +// DataUpload/name fields to survive backup/DataUpload-name scoping the same +// way the #212 pattern does. If this ever regresses (e.g. the controller +// stops injecting those fields, or the call site moves to a differently- +// constructed logger), this test fails loudly instead of the fix silently +// dropping the #208 detection path. +func Test_CheckIfFlakeOccurred_pattern208SurvivesScoping(t *testing.T) { + logWithNoise := strings.Join([]string{realLineHealthyA, sourceVerifiedLine208, realLineHealthyC}, "\n") + + filtered := FilterLogLinesContaining(logWithNoise, backupName, dataUploadName) + if !strings.Contains(filtered, "VirtualMachineBackup in progress, requeuing") { + t.Fatalf("expected scoping by backup/DataUpload name to retain the #208 pattern line, got:\n%s", filtered) + } + if !CheckIfFlakeOccurred([]string{filtered}) { + t.Fatalf("expected the #208 pattern to still be detected once scoped to its own backup, got:\n%s", filtered) + } +} From 654850e9894ea0435b233ef7dd0521be515bca55 Mon Sep 17 00:00:00 2001 From: Tiger Kaovilai Date: Sat, 29 Aug 2026 00:39:40 -0400 Subject: [PATCH 03/15] docs: record name-bearing status of each flake pattern for CheckIfFlakeOccurred Per second-opinion review: name-scoping a log before flake-checking risks silently disabling detection for any pattern whose known-bug string doesn't appear on a line naming the object. Verified each currently-tracked pattern against kdm-controller's actual source -- all reachable via kdm-controller's own pod log share the same context-injected logger (name-bearing even with no inline args), the one event-only pattern is already excluded from filtering, and the remaining three patterns are velero/snapshot-controller strings never reachable via kdm-controller's log regardless of filtering. Documented so a future added pattern can be checked the same way. Signed-off-by: Tiger Kaovilai --- tests/e2e/lib/flakes.go | 23 +++++++++++++++++++++++ 1 file changed, 23 insertions(+) diff --git a/tests/e2e/lib/flakes.go b/tests/e2e/lib/flakes.go index d327310bee5..c988abddafe 100644 --- a/tests/e2e/lib/flakes.go +++ b/tests/e2e/lib/flakes.go @@ -67,6 +67,29 @@ func FilterLogLinesContaining(logs string, substrs ...string) string { // Parameters: // // logs ([]string): Logs to be examined for known flake patterns. +// +// Name-bearing status of each pattern below, for callers pre-filtering with +// FilterLogLinesContaining (verified against kdm-controller source +// migtools/kubevirt-datamover-controller@internal/controller/kubevirt_dataupload_controller.go, +// 2026-08-29 -- re-check this if that file's logger plumbing changes): +// - kdm-controller#208/#212: both log via a logger parameter threaded down +// unmodified from Reconcile's log.FromContext(ctx), so even a bare +// logger.Info() call (no inline args, e.g. #208's call site) still +// carries the DataUpload name/namespace via controller-runtime's +// per-request context injection. Safe to scope by backup/DataUpload name. +// - CNV-85377 ("is being attached to VMI"): not found verbatim in +// kdm-controller source; if it ever surfaces there it would be via a VMB +// condition Reason/Message logged inline (e.g. "reason", cond.Reason) on +// the same shared logger above -- also safe. Otherwise it's virt-controller's +// own condition text, which reaches us only via Kubernetes Events, same +// as the #18957 pattern below. +// - kubevirt#18957 ("VMI backup status was lost"): virt-controller's own +// event text, never appears in any pod log -- callers must check this +// against Namespace Events (already namespace-scoped), never filtered +// pod logs, or it will never match. +// - external-snapshotter#876, velero#5856, OADP-5086: velero/snapshot-controller +// strings that never appear in kdm-controller's own log; irrelevant to +// scoping decisions made against kdm-controller pod logs specifically. func CheckIfFlakeOccurred(logs []string) bool { flakePatterns := []FlakePattern{ { From ce314578fcae53bd3ef8af0d83d023c0f5abdbc8 Mon Sep 17 00:00:00 2001 From: Tiger Kaovilai Date: Sat, 29 Aug 2026 01:32:48 -0400 Subject: [PATCH 04/15] test: temporarily override kdm-controller image with a fix build for two unmerged upstream PRs Lets the incremental-sequence spec actually validate https://github.com/migtools/kubevirt-datamover-controller/pull/208 and https://github.com/migtools/kubevirt-datamover-controller/pull/212 (both unmerged upstream) instead of self-skipping on the known flake pattern every run. Uses DPA's spec.unsupportedOverrides (kubevirtDatamoverControllerImageFqin), not a direct Deployment/manifest patch, so it's a pure e2e-test-time override with no manifest churn. Remove once those two PRs merge upstream and a release picks them up. Signed-off-by: Tiger Kaovilai --- tests/e2e/e2e_suite_test.go | 13 +++++++++++++ 1 file changed, 13 insertions(+) diff --git a/tests/e2e/e2e_suite_test.go b/tests/e2e/e2e_suite_test.go index 8fe999fff20..0bf88b1b711 100644 --- a/tests/e2e/e2e_suite_test.go +++ b/tests/e2e/e2e_suite_test.go @@ -20,6 +20,7 @@ import ( "sigs.k8s.io/controller-runtime/pkg/client/config" "sigs.k8s.io/controller-runtime/pkg/log/zap" + oadpv1alpha1 "github.com/openshift/oadp-operator/api/v1alpha1" "github.com/openshift/oadp-operator/tests/e2e/lib" libhcp "github.com/openshift/oadp-operator/tests/e2e/lib/hcp" ) @@ -226,6 +227,18 @@ func TestOADPE2E(t *testing.T) { UnsupportedOverrides: dpa.DeepCopy().Spec.UnsupportedOverrides, } + // TEMPORARY: overrides kdm-controller with a build carrying + // migtools/kubevirt-datamover-controller#208 and #212 (neither merged + // upstream yet), so the incremental-sequence spec can actually validate + // those fixes instead of self-skipping on the known flake pattern every + // run (see lib.CheckIfFlakeOccurred). Remove this override once #208/#212 + // merge and a release picks them up -- the settings.json-driven + // UnsupportedOverrides above is the normal, permanent path for this. + if dpaCR.UnsupportedOverrides == nil { + dpaCR.UnsupportedOverrides = map[oadpv1alpha1.UnsupportedImageKey]string{} + } + dpaCR.UnsupportedOverrides[oadpv1alpha1.KubeVirtDatamoverControllerImageKey] = "quay.io/tkaovila/kubevirt-datamover-controller:combined-208-212-test" + ginkgo.RunSpecs(t, "OADP E2E using velero prefix: "+veleroPrefix) } From 2ce4aa9f842219e098a0daef84cc8926e2802abb Mon Sep 17 00:00:00 2001 From: Tiger Kaovilai Date: Sat, 29 Aug 2026 03:08:49 -0400 Subject: [PATCH 05/15] test: remove #208/#212 flake patterns, now fixed and confirmed live Verified against a real cluster (2026-08-29, AWS amd64) with the combined-208-212-test override image: the incremental-sequence spec ran to a genuine PASS in 7m20s with zero occurrences of either pattern's string in the whole run's logs -- previously this spec reliably flake-skipped within ~20 minutes on one or both patterns. See https://github.com/migtools/kubevirt-datamover-controller/pull/208 and https://github.com/migtools/kubevirt-datamover-controller/pull/212. Drops the two now-dead FlakePattern entries and the CheckIfFlakeOccurred- level tests that specifically exercised them; keeps the FilterLogLinesContaining-level tests and their real captured fixture data, which remain valid regardless of the pattern registry's contents. Signed-off-by: Tiger Kaovilai --- tests/e2e/lib/flakes.go | 22 ++-------- tests/e2e/lib/flakes_test.go | 79 +++++------------------------------- 2 files changed, 14 insertions(+), 87 deletions(-) diff --git a/tests/e2e/lib/flakes.go b/tests/e2e/lib/flakes.go index c988abddafe..bc0873461ab 100644 --- a/tests/e2e/lib/flakes.go +++ b/tests/e2e/lib/flakes.go @@ -72,17 +72,13 @@ func FilterLogLinesContaining(logs string, substrs ...string) string { // FilterLogLinesContaining (verified against kdm-controller source // migtools/kubevirt-datamover-controller@internal/controller/kubevirt_dataupload_controller.go, // 2026-08-29 -- re-check this if that file's logger plumbing changes): -// - kdm-controller#208/#212: both log via a logger parameter threaded down -// unmodified from Reconcile's log.FromContext(ctx), so even a bare -// logger.Info() call (no inline args, e.g. #208's call site) still -// carries the DataUpload name/namespace via controller-runtime's -// per-request context injection. Safe to scope by backup/DataUpload name. // - CNV-85377 ("is being attached to VMI"): not found verbatim in // kdm-controller source; if it ever surfaces there it would be via a VMB // condition Reason/Message logged inline (e.g. "reason", cond.Reason) on -// the same shared logger above -- also safe. Otherwise it's virt-controller's -// own condition text, which reaches us only via Kubernetes Events, same -// as the #18957 pattern below. +// kdm-controller's shared, context-injected logger -- also safe to scope +// by backup/DataUpload name. Otherwise it's virt-controller's own +// condition text, which reaches us only via Kubernetes Events, same as +// the #18957 pattern below. // - kubevirt#18957 ("VMI backup status was lost"): virt-controller's own // event text, never appears in any pod log -- callers must check this // against Namespace Events (already namespace-scoped), never filtered @@ -117,16 +113,6 @@ func CheckIfFlakeOccurred(logs []string) bool { Description: "virt-controller's reconcileStart() (pkg/storage/cbt/backup.go) can mark an already-successfully-completed VirtualMachineBackup Failed with reason SourceLost: cleanupVMIState() clears the VMI's BackupStatus and re-triggers reconcile before the backup's own just-written terminal status is visible via the informer's async cache, so the stale reconcile wrongly concludes the status was lost mid-flight -- observed live immediately after a real 'Completed VirtualMachineBackup, warning: ...' event, first seen testing kubevirt/kubevirt nightly (v1.20.0). Fixed at kubevirt/kubevirt#18957 (checks the API server directly before concluding lost); distinct from CNV-85377/kubevirt/kubevirt#18949.", StringSearchPattern: "VMI backup status was lost", }, - { - Issue: "https://github.com/migtools/kubevirt-datamover-controller/pull/208", - Description: "kubevirt-datamover-controller's evaluateVMBackupStatus/isVMBTerminal looked only for a VirtualMachineBackup condition of type \"Done\" (kubevirtbackupv1alpha1.ConditionDone, from its vendored kubevirt.io/api v1.8.0-alpha.0), but kubevirt nightly (v1.20.0+) renamed that condition to \"Complete\" -- the VMB itself completes fine (conditions show Complete=True, reason=CompletedWithWarning), but the controller never recognized it and just logged \"VirtualMachineBackup in progress, requeuing\" forever, confirmed live: 243 occurrences over a 20-minute test timeout. Fixed at migtools/kubevirt-datamover-controller#208 (declares a local conditionComplete=\"Complete\" literal and accepts both the old and new condition names, rather than bumping the vendored kubevirt.io/api -- TDD via TestHandleAccepted_VMBStatusDetection/TestIsVMBTerminal). A dependency-version-skew bug in kdm-controller, not this repo or kubevirt itself, surfaced only because HCO_INDEX_TAG now defaults to nightly.", - StringSearchPattern: "VirtualMachineBackup in progress, requeuing", - }, - { - Issue: "https://github.com/migtools/kubevirt-datamover-controller/pull/212", - Description: "kubevirt-datamover-controller's DataUpload reconcile logs \"VMBT already prepared but VMB not yet visible in cache, requeuing\" every ~5s forever. Root cause (migtools/kubevirt-datamover-controller#211): a guard checking findVMBForDataUpload's result via the informer cache was written when that lookup had no APIReader direct-read fallback and prepareVMBackupTracker used to delete-and-recreate the VMBT -- neither is true anymore (the lookup already falls back to a direct API read, and the VMBT is now reused via a VM-name-hash label instead of being deleted), so vmb==nil at the guard is never just \"not yet cached\", it's a real absence. The actual delay is Step 4's VMB creation being rejected by KubeVirt's admission webhook (one active VMB per VM) *after* Step 2 already persisted the VMBTName annotation -- every subsequent reconcile then short-circuits on the now-stale guard and Step 4 is never retried, so the VMB is never created and the DataUpload spins until OperationTimeout. Fixed at migtools/kubevirt-datamover-controller#212 (fixes #211): removes the guard entirely, falling through to the existing idempotent Steps 2-4, so a cleared admission conflict lets VMB creation actually retry and succeed. Our backup-delete-before-skip workaround (see the two ginkgo.Skip sites in this file) remains a useful defensive backstop even after this lands.", - StringSearchPattern: "VMBT already prepared but VMB not yet visible in cache, requeuing", - }, } logString := strings.Join(logs, "\n") diff --git a/tests/e2e/lib/flakes_test.go b/tests/e2e/lib/flakes_test.go index 0ff22ee49f4..f56797634a7 100644 --- a/tests/e2e/lib/flakes_test.go +++ b/tests/e2e/lib/flakes_test.go @@ -25,22 +25,16 @@ const realLineHealthyA = `2026-08-28T16:49:21Z INFO Reconciling DataUpload with const realLineHealthyB = `2026-08-28T16:49:21Z INFO Handling New phase DataUpload {"controller": "kubevirt-dataupload", "controllerGroup": "velero.io", "controllerKind": "DataUpload", "DataUpload": {"name":"du-cirros-stale-sibling-backup-cirros-test-cirros-test-86ae9509","namespace":"openshift-adp"}, "namespace": "openshift-adp", "name": "du-cirros-stale-sibling-backup-cirros-test-cirros-test-86ae9509", "reconcileID": "aae0a708-caca-4e5e-9a4b-dd763622396a"}` const realLineHealthyC = `2026-08-28T16:49:21Z INFO Updated DataUpload phase {"controller": "kubevirt-dataupload", "controllerGroup": "velero.io", "controllerKind": "DataUpload", "DataUpload": {"name":"du-cirros-stale-sibling-backup-cirros-test-cirros-test-86ae9509","namespace":"openshift-adp"}, "namespace": "openshift-adp", "name": "du-cirros-stale-sibling-backup-cirros-test-cirros-test-86ae9509", "reconcileID": "aae0a708-caca-4e5e-9a4b-dd763622396a", "dataUpload": "du-cirros-stale-sibling-backup-cirros-test-cirros-test-86ae9509", "phase": "Accepted", "message": "DataUpload accepted by kubevirt datamover"}` -// The #208 pattern ("VirtualMachineBackup in progress, requeuing", line 663 -// of kubevirt_dataupload_controller.go) has never been captured raw in any -// CI artifact -- per-spec log captures only fire on a hard spec FAILURE, and -// our own flake-skip logic means this pattern now produces a Skip, not a -// failure, so no artifact will ever contain it. Verified instead by reading -// the controller's actual source directly (migtools/kubevirt-datamover-controller, -// internal/controller/kubevirt_dataupload_controller.go): line 663's -// logger.Info call has no inline key-value args of its own, but it shares -// the exact same `logger := log.FromContext(ctx)` (declared once near the -// top of the same function, no reassignment in between) as the #212 call -// site above -- so it carries the identical controller-runtime-injected -// DataUpload/namespace/name/reconcileID fields via the generic Reconciler -// wrapper's context injection, confirmed present on realLine212A/B for the -// sibling call. This fixture mirrors that confirmed field shape rather than -// inventing one. -const sourceVerifiedLine208 = `2026-08-28T16:50:03Z INFO VirtualMachineBackup in progress, requeuing {"controller": "kubevirt-dataupload", "controllerGroup": "velero.io", "controllerKind": "DataUpload", "DataUpload": {"name":"du-cirros-incr-seq-1-cirros-test-cirros-test-c2ce2dc4","namespace":"openshift-adp"}, "namespace": "openshift-adp", "name": "du-cirros-incr-seq-1-cirros-test-cirros-test-c2ce2dc4", "reconcileID": "0c9c1a3e-2222-4b1a-9e3d-111122223333"}` +// The #208 pattern ("VirtualMachineBackup in progress, requeuing") and the +// #212 pattern above were both removed from CheckIfFlakeOccurred once a kdm-controller +// build carrying migtools/kubevirt-datamover-controller#208 and #212 was +// verified live (2026-08-29, quay.io/tkaovila/kubevirt-datamover-controller:combined-208-212-test) +// to produce a genuine PASS of the incremental-sequence spec with zero +// occurrences of either pattern string, where it had previously reliably +// flake-skipped within ~20 minutes. realLine212A/B stay as fixture data below +// since they're still useful, realistic-shaped log content for exercising +// FilterLogLinesContaining's own scoping logic -- they just no longer +// exercise CheckIfFlakeOccurred's pattern registry. const backupName = "cirros-incr-seq-1" const dataUploadName = "du-cirros-incr-seq-1-cirros-test-cirros-test-c2ce2dc4" @@ -74,56 +68,3 @@ func Test_FilterLogLinesContaining_noSubstrsReturnsInputUnchanged(t *testing.T) t.Fatalf("expected unfiltered passthrough with no substrs, got:\n%s", got) } } - -// Test_CheckIfFlakeOccurred_misattributionRepro reproduces the actual bug -// FilterLogLinesContaining was written to fix: a spec whose OWN backup -// (cirros-stale-sibling-backup) is perfectly healthy would, without -// filtering, see the #212 flake match anyway -- because the shared, -// never-restarted kdm-controller pod's log also contains a genuinely -// different spec's (cirros-incr-seq-1) stuck DataUpload lines from the same -// time window. Filtering by the CURRENT spec's own backup/DataUpload name -// must make that false match go away. -func Test_CheckIfFlakeOccurred_misattributionRepro(t *testing.T) { - combined := combinedPodLog() - - if !CheckIfFlakeOccurred([]string{combined}) { - t.Fatalf("sanity check failed: expected unfiltered combined log to match the #212 pattern (proves the repro scenario is real)") - } - - filteredForHealthySpec := FilterLogLinesContaining(combined, staleSiblingBackupName, staleSiblingDataUploadName) - if CheckIfFlakeOccurred([]string{filteredForHealthySpec}) { - t.Fatalf("misattribution bug reproduced: filtering by the healthy spec's own backup/DataUpload name still matched the OTHER spec's #212 flake:\n%s", filteredForHealthySpec) - } -} - -// Test_CheckIfFlakeOccurred_realMatchStillDetected proves the fix doesn't -// overcorrect into false negatives: when the CURRENT spec's own backup -// really did hit the #212 pattern, scoping the log to its own -// backup/DataUpload name must still catch it. -func Test_CheckIfFlakeOccurred_realMatchStillDetected(t *testing.T) { - filtered := FilterLogLinesContaining(combinedPodLog(), backupName, dataUploadName) - if !CheckIfFlakeOccurred([]string{filtered}) { - t.Fatalf("expected the #212 pattern to still be detected once scoped to its own backup, got:\n%s", filtered) - } -} - -// Test_CheckIfFlakeOccurred_pattern208SurvivesScoping validates, using the -// source-verified fixture (see sourceVerifiedLine208's doc comment), that -// the #208 pattern's log line -- which has no inline key-value args at its -// own call site -- still carries enough of the controller-runtime-injected -// DataUpload/name fields to survive backup/DataUpload-name scoping the same -// way the #212 pattern does. If this ever regresses (e.g. the controller -// stops injecting those fields, or the call site moves to a differently- -// constructed logger), this test fails loudly instead of the fix silently -// dropping the #208 detection path. -func Test_CheckIfFlakeOccurred_pattern208SurvivesScoping(t *testing.T) { - logWithNoise := strings.Join([]string{realLineHealthyA, sourceVerifiedLine208, realLineHealthyC}, "\n") - - filtered := FilterLogLinesContaining(logWithNoise, backupName, dataUploadName) - if !strings.Contains(filtered, "VirtualMachineBackup in progress, requeuing") { - t.Fatalf("expected scoping by backup/DataUpload name to retain the #208 pattern line, got:\n%s", filtered) - } - if !CheckIfFlakeOccurred([]string{filtered}) { - t.Fatalf("expected the #208 pattern to still be detected once scoped to its own backup, got:\n%s", filtered) - } -} From 50c80695a4dc65fc2cd57bb6321465f2ef8275e4 Mon Sep 17 00:00:00 2001 From: Tiger Kaovilai Date: Sat, 29 Aug 2026 04:48:31 -0400 Subject: [PATCH 06/15] fix: don't fail must-gather check on the expected unsupportedOverrides warning RunMustGather's check treated ANY content in the must-gather summary's "## Errors" section as a hard failure. The summary generator flags any DPA using spec.unsupportedOverrides at all as a warning, regardless of key or reason, since that field is inherently "unsupported" -- purely informational, not an actual problem. This broke live: adding a single test-time kdm-controller image override to the shared dpaCR (for validating https://github.com/migtools/kubevirt-datamover-controller/pull/208 and https://github.com/migtools/kubevirt-datamover-controller/pull/212 before they merge) made every e2e job's must-gather check fail, including completely unrelated CLI suites -- confirmed on ci/prow/5.0-e2e-test-cli-aws and ci/prow/5.1-e2e-test-cli-aws. Now tolerates that one specific, expected warning line while still failing on any other content in the Errors section. Verified against the real captured summary text from the failing 5.1-e2e-test-cli-aws run. Signed-off-by: Tiger Kaovilai --- tests/e2e/lib/apps.go | 60 +++++++++++++++++++++++++++++++++++++- tests/e2e/lib/apps_test.go | 52 +++++++++++++++++++++++++++++++++ 2 files changed, 111 insertions(+), 1 deletion(-) create mode 100644 tests/e2e/lib/apps_test.go diff --git a/tests/e2e/lib/apps.go b/tests/e2e/lib/apps.go index 468f8c4e001..0f5c1ff69c2 100755 --- a/tests/e2e/lib/apps.go +++ b/tests/e2e/lib/apps.go @@ -10,6 +10,7 @@ import ( "os/exec" "path/filepath" "reflect" + "regexp" "sort" "strings" "time" @@ -447,12 +448,69 @@ func RunMustGather(artifact_dir string, clusterClient client.Client) error { mustGatherSummaryText := string(mustGatherSummaryContent) if !strings.Contains(mustGatherSummaryText, "No errors happened or were found while running OADP must-gather") { - return errors.New("expected no errors in must-gather Errors section") + if !mustGatherErrorsAreOnlyKnownBenignWarnings(mustGatherSummaryText) { + return errors.New("expected no errors in must-gather Errors section") + } } return nil } +// mustGatherKnownBenignErrorPatterns are must-gather "Errors" section lines +// that are purely informational -- the summary generator flags any DPA using +// spec.unsupportedOverrides at all, regardless of which key or why, since +// that field is inherently "unsupported" by design. A test intentionally +// using it (e.g. to override kdm-controller's image with a candidate fix +// build before it merges upstream) is not itself an error condition, and +// treating it as one broke every e2e job's must-gather check the moment any +// suite's DPA carried an UnsupportedOverrides entry -- confirmed live on +// oadp-operator PR#2404, where a single test-time override in +// e2e_suite_test.go's shared dpaCR broke unrelated CLI e2e jobs across +// multiple OCP versions. Any OTHER line in the Errors section still fails +// the check below -- only this specific, expected caveat is tolerated. +var mustGatherKnownBenignErrorPatterns = []*regexp.Regexp{ + regexp.MustCompile(`is using \*\*unsupportedOverrides\*\*`), +} + +// mustGatherErrorsAreOnlyKnownBenignWarnings extracts the "## Errors" section +// of the must-gather summary and reports whether every non-blank line in it +// matches a known-benign pattern above. Returns false (i.e. a real error is +// present) if the section can't be found at all, to fail safe. +func mustGatherErrorsAreOnlyKnownBenignWarnings(summary string) bool { + lines := strings.Split(summary, "\n") + start := -1 + for i, line := range lines { + if strings.TrimSpace(line) == "## Errors" { + start = i + 1 + break + } + } + if start == -1 { + return false + } + + for _, line := range lines[start:] { + trimmed := strings.TrimSpace(line) + if trimmed == "" { + continue + } + if strings.HasPrefix(trimmed, "## ") { + break + } + matched := false + for _, p := range mustGatherKnownBenignErrorPatterns { + if p.MatchString(trimmed) { + matched = true + break + } + } + if !matched { + return false + } + } + return true +} + // VerifyBackupRestoreData verifies if app ready before backup and after restore to compare data. // skipReadyz skips the post-restore readyz endpoint check (use for VM-based tests where the // app route is not directly reachable from the test harness). diff --git a/tests/e2e/lib/apps_test.go b/tests/e2e/lib/apps_test.go new file mode 100644 index 00000000000..cb90482ecb5 --- /dev/null +++ b/tests/e2e/lib/apps_test.go @@ -0,0 +1,52 @@ +package lib + +import "testing" + +// realMustGatherSummaryUnsupportedOverridesOnly is the actual "## Errors" +// section (and the section immediately following it) captured from a real +// CI failure: openshift/oadp-operator PR#2404's ci/prow/5.1-e2e-test-cli-aws +// run (2093596791407644672), which failed with "expected no errors in +// must-gather Errors section" purely because the shared dpaCR carried a +// spec.unsupportedOverrides entry (a test-time kdm-controller image +// override, unrelated to the CLI suite that failed). +const realMustGatherSummaryUnsupportedOverridesOnly = `## Errors + +⚠️ DataProtectionApplication **ts-velero-test** in **openshift-adp** namespace is using **unsupportedOverrides** + + + +## Cluster information + +| Cluster ID | OpenShift version | Cloud provider | Architecture | +| ---------- | ----------------- | -------------- | ------------ | +| 65162e20 | 5.1.0-0.nightly-2026-08-27-012048 | AWS | linux/amd64 | +` + +func Test_mustGatherErrorsAreOnlyKnownBenignWarnings_realUnsupportedOverridesCapture(t *testing.T) { + if !mustGatherErrorsAreOnlyKnownBenignWarnings(realMustGatherSummaryUnsupportedOverridesOnly) { + t.Fatalf("expected the real captured unsupportedOverrides-only Errors section to be treated as benign") + } +} + +func Test_mustGatherErrorsAreOnlyKnownBenignWarnings_realErrorStillFails(t *testing.T) { + summary := `## Errors + +⚠️ DataProtectionApplication **ts-velero-test** in **openshift-adp** namespace is using **unsupportedOverrides** +❌ Velero pod is in CrashLoopBackOff + +## Cluster information +` + if mustGatherErrorsAreOnlyKnownBenignWarnings(summary) { + t.Fatalf("expected a genuine error line alongside the benign warning to still be treated as a real error") + } +} + +func Test_mustGatherErrorsAreOnlyKnownBenignWarnings_noErrorsSectionFailsSafe(t *testing.T) { + summary := `## Cluster information + +| Cluster ID | OpenShift version | +` + if mustGatherErrorsAreOnlyKnownBenignWarnings(summary) { + t.Fatalf("expected a missing Errors section to fail safe (treated as a real error)") + } +} From 1d036c266bf855c156643d7e3bdc152bbd898d07 Mon Sep 17 00:00:00 2001 From: Tiger Kaovilai Date: Sat, 29 Aug 2026 10:14:48 -0400 Subject: [PATCH 07/15] test: bump kdm-controller override to combined-208-212v2-test Adds a second fix on top of #208/#212: handleAccepted was trusting the informer cache's VirtualMachineBackup.Status, which can be stale after a missed/delayed watch event, instead of re-reading it via APIReader before concluding terminal state. Found live via a Prow failure (ci/prow/5.0-e2e-test-kubevirt-aws) where virt-controller had already written Done=True but kdm-controller's reconcile loop never observed it, confirmed via a live repro capturing the real VirtualMachineBackup object's status.conditions directly against the API server. https://github.com/migtools/kubevirt-datamover-controller/pull/212 Signed-off-by: Tiger Kaovilai --- tests/e2e/e2e_suite_test.go | 14 ++++++++++---- 1 file changed, 10 insertions(+), 4 deletions(-) diff --git a/tests/e2e/e2e_suite_test.go b/tests/e2e/e2e_suite_test.go index 0bf88b1b711..b14b8872173 100644 --- a/tests/e2e/e2e_suite_test.go +++ b/tests/e2e/e2e_suite_test.go @@ -231,13 +231,19 @@ func TestOADPE2E(t *testing.T) { // migtools/kubevirt-datamover-controller#208 and #212 (neither merged // upstream yet), so the incremental-sequence spec can actually validate // those fixes instead of self-skipping on the known flake pattern every - // run (see lib.CheckIfFlakeOccurred). Remove this override once #208/#212 - // merge and a release picks them up -- the settings.json-driven - // UnsupportedOverrides above is the normal, permanent path for this. + // run (see lib.CheckIfFlakeOccurred). #212 also now includes a second, + // intermittent fix: handleAccepted was trusting the informer cache's + // (possibly stale) VirtualMachineBackup.Status instead of re-reading it + // via APIReader before concluding terminal state -- found live via a + // Prow failure (ci/prow/5.0-e2e-test-kubevirt-aws) where virt-controller + // had already written Done=True but kdm-controller's reconcile loop + // never observed it. Remove this override once #208/#212 merge and a + // release picks them up -- the settings.json-driven UnsupportedOverrides + // above is the normal, permanent path for this. if dpaCR.UnsupportedOverrides == nil { dpaCR.UnsupportedOverrides = map[oadpv1alpha1.UnsupportedImageKey]string{} } - dpaCR.UnsupportedOverrides[oadpv1alpha1.KubeVirtDatamoverControllerImageKey] = "quay.io/tkaovila/kubevirt-datamover-controller:combined-208-212-test" + dpaCR.UnsupportedOverrides[oadpv1alpha1.KubeVirtDatamoverControllerImageKey] = "quay.io/tkaovila/kubevirt-datamover-controller:combined-208-212v2-test" ginkgo.RunSpecs(t, "OADP E2E using velero prefix: "+veleroPrefix) } From 4d5897ad1de66cb98c4d415b81500ddb1d27c9f9 Mon Sep 17 00:00:00 2001 From: Tiger Kaovilai Date: Sat, 29 Aug 2026 15:10:28 -0400 Subject: [PATCH 08/15] test: bump kdm-controller override to combined-208-212v3-test Adds debug logging to the uncached-status-refresh's own success/NotFound/ error branches, to settle -- on the next recurrence of the identical "in progress, requeuing" x243/0-completed signature -- whether the live API server itself never had Done=True (a virt-controller/kubevirt-level stall, not kdm-controller's bug) or the "uncached" read has some subtler issue, without needing another live-debug session. https://github.com/migtools/kubevirt-datamover-controller/pull/212 Signed-off-by: Tiger Kaovilai --- tests/e2e/e2e_suite_test.go | 14 +++++++++++--- 1 file changed, 11 insertions(+), 3 deletions(-) diff --git a/tests/e2e/e2e_suite_test.go b/tests/e2e/e2e_suite_test.go index b14b8872173..d9b7482d39d 100644 --- a/tests/e2e/e2e_suite_test.go +++ b/tests/e2e/e2e_suite_test.go @@ -231,19 +231,27 @@ func TestOADPE2E(t *testing.T) { // migtools/kubevirt-datamover-controller#208 and #212 (neither merged // upstream yet), so the incremental-sequence spec can actually validate // those fixes instead of self-skipping on the known flake pattern every - // run (see lib.CheckIfFlakeOccurred). #212 also now includes a second, + // run (see lib.CheckIfFlakeOccurred). #212 also includes a second, // intermittent fix: handleAccepted was trusting the informer cache's // (possibly stale) VirtualMachineBackup.Status instead of re-reading it // via APIReader before concluding terminal state -- found live via a // Prow failure (ci/prow/5.0-e2e-test-kubevirt-aws) where virt-controller // had already written Done=True but kdm-controller's reconcile loop - // never observed it. Remove this override once #208/#212 merge and a + // never observed it. That fix recurred with the identical symptom on its + // first build (v2) despite every mechanical piece checking out (image + // built after the fix commit, correctly pulled, APIReader correctly + // wired in main.go, refresh correctly placed before the status-check + // call) -- v3 adds logging to the refresh's own success/NotFound/error + // branches to settle, on the next recurrence, whether the live API + // server itself never had Done=True (a virt-controller/kubevirt-level + // stall, not kdm-controller's bug) or the "uncached" read has some + // subtler issue. Remove this override once #208/#212 merge and a // release picks them up -- the settings.json-driven UnsupportedOverrides // above is the normal, permanent path for this. if dpaCR.UnsupportedOverrides == nil { dpaCR.UnsupportedOverrides = map[oadpv1alpha1.UnsupportedImageKey]string{} } - dpaCR.UnsupportedOverrides[oadpv1alpha1.KubeVirtDatamoverControllerImageKey] = "quay.io/tkaovila/kubevirt-datamover-controller:combined-208-212v2-test" + dpaCR.UnsupportedOverrides[oadpv1alpha1.KubeVirtDatamoverControllerImageKey] = "quay.io/tkaovila/kubevirt-datamover-controller:combined-208-212v3-test" ginkgo.RunSpecs(t, "OADP E2E using velero prefix: "+veleroPrefix) } From 0777f1e429eef37910da1d9f957e0f352df9e8b3 Mon Sep 17 00:00:00 2001 From: Tiger Kaovilai Date: Sat, 29 Aug 2026 18:36:36 -0400 Subject: [PATCH 09/15] fix: also detect VMB-never-gets-any-condition as the CNV-85377/#18949 flake A third manifestation of the same upstream bug, confirmed by kubevirt-fixer to trace to the identical root cause as kubevirt/kubevirt#18949: the VirtualMachineBackup can sit with zero status.conditions for the whole backup timeout, not just a frozen "is being attached to VMI" message. Confirmed live via 244 consecutive uncached reads across 20 minutes, all nil. Has no distinguishing log text for lib.CheckIfFlakeOccurred to match, so lib.VirtOperator.VMBHasNoConditions checks the VMB object directly instead, gated on the condition persisting for a few checks (not just the first sighting) so a freshly-created VMB's normal brief pre-condition window isn't misdetected. Feeds the same existing nudge-then-skip path as the other CNV-85377 manifestation. Signed-off-by: Tiger Kaovilai --- tests/e2e/lib/virt_helpers.go | 38 +++++++++++++++++++++ tests/e2e/virt_backup_restore_suite_test.go | 31 +++++++++++++++++ 2 files changed, 69 insertions(+) diff --git a/tests/e2e/lib/virt_helpers.go b/tests/e2e/lib/virt_helpers.go index 9804011d988..d16b927004d 100644 --- a/tests/e2e/lib/virt_helpers.go +++ b/tests/e2e/lib/virt_helpers.go @@ -1554,6 +1554,44 @@ func (v *VirtOperator) GetVMBBackupType(namespace, dataUploadName string) (backu return "", "", fmt.Errorf("no VirtualMachineBackup found in %s with %s=%s", namespace, annotationDataUploadName, dataUploadName) } +// VMBHasNoConditions finds the VirtualMachineBackup in namespace whose +// annotationDataUploadName annotation matches dataUploadName, and reports +// whether it exists but has zero status.conditions (not merely missing a +// Done/Complete condition -- genuinely none at all). +// +// This is a second, distinct manifestation of the same upstream bug as +// CNV-85377/kubevirt/kubevirt#18949 (see lib.NudgeVmiToTriggerResync's doc +// comment): confirmed live (2026-08-29, oadp-operator PR#2404) via direct +// APIReader access on a real cluster that a VirtualMachineBackup can sit +// with status.conditions == nil for the ENTIRE backup timeout (20+ minutes, +// 244 consecutive uncached reads all nil) -- not even an Initializing/ +// Progressing condition ever gets written, so kdm-controller's own log has +// no distinguishing text to pattern-match against (its generic "in +// progress, requeuing" message is identical to a perfectly healthy backup's +// normal early-lifecycle message). kubevirt-fixer confirmed this traces to +// the exact same root cause as #18949 (startBackup()'s attach branch never +// writing a status condition), just with an even earlier/more complete +// failure to write anything at all -- not a separate bug. Returns +// found=false (not a match) if the VMB doesn't exist yet at all, since +// that's a different, earlier-stage scenario already handled elsewhere. +func (v *VirtOperator) VMBHasNoConditions(namespace, dataUploadName string) (empty bool, found bool, err error) { + list, err := v.Dynamic.Resource(virtualMachineBackupGvr).Namespace(namespace).List(context.Background(), metav1.ListOptions{}) + if err != nil { + return false, false, fmt.Errorf("failed to list VirtualMachineBackups in %s: %w", namespace, err) + } + for _, vmb := range list.Items { + if vmb.GetAnnotations()[annotationDataUploadName] != dataUploadName { + continue + } + conditions, _, err := unstructured.NestedSlice(vmb.Object, "status", "conditions") + if err != nil { + return false, true, fmt.Errorf("failed to read status.conditions from VirtualMachineBackup %s/%s: %w", namespace, vmb.GetName(), err) + } + return len(conditions) == 0, true, nil + } + return false, false, nil +} + // vmbBackupProtectionFinalizer is the finalizer virt-controller stamps on a // VirtualMachineBackup while it is protecting an in-progress backup. const vmbBackupProtectionFinalizer = "backup.kubevirt.io/vmbackup-protection" diff --git a/tests/e2e/virt_backup_restore_suite_test.go b/tests/e2e/virt_backup_restore_suite_test.go index ae55de5544a..57325dfd945 100644 --- a/tests/e2e/virt_backup_restore_suite_test.go +++ b/tests/e2e/virt_backup_restore_suite_test.go @@ -277,6 +277,16 @@ func waitForKubevirtDatamoverControllerRollout(cl client.Client, timeout time.Du // panic. This is a KubeVirt/CNV core issue -- virt-controller owns the VirtualMachineBackup // status, and kubevirt-datamover-controller only ever reads it (RBAC-verified: `get` only // on virtualmachinebackups/status) -- not something this repo's retry logic can fix. +// +// A third manifestation of the SAME attach-freeze bug (confirmed by kubevirt-fixer to +// trace to the identical root cause as kubevirt/kubevirt#18949, not a separate issue): +// the VirtualMachineBackup can sit with ZERO status.conditions for the entire backup +// timeout -- not even the Initializing "is being attached to VMI" condition ever gets +// written. Confirmed live (2026-08-29, direct APIReader access on a real cluster) via +// 244 consecutive uncached reads across 20 minutes, all nil. This has no distinguishing +// log text for CheckIfFlakeOccurred to match (kdm-controller's generic "in progress, +// requeuing" message is identical to a perfectly healthy backup's normal early-lifecycle +// state), so lib.VirtOperator.VMBHasNoConditions checks the VMB object directly instead. func runKubevirtDMBackup(v *lib.VirtOperator, vmNamespace, backupName string, onDataUploadFound func(dataUploadName, expectedBackupType string)) { defer func() { pod, err := lib.GetPodWithLabel(kubernetesClientForSuiteRun, namespace, "control-plane=oadp-kubevirt-datamover-controller") @@ -439,6 +449,7 @@ func runKubevirtDMBackup(v *lib.VirtOperator, vmNamespace, backupName string, on // failing/retrying on) the full timeout. lastFlakeCheck := time.Time{} lastFlakeMatched := false + emptyConditionsSince := time.Time{} err = wait.PollUntilContextTimeout(context.Background(), 10*time.Second, 20*time.Minute, true, func(ctx context.Context) (bool, error) { done, doneErr := lib.IsKubevirtDMBackupDone(dpaCR.Client, dynamicClientForSuiteRun, namespace, backupName)() if doneErr != nil { @@ -451,6 +462,26 @@ func runKubevirtDMBackup(v *lib.VirtOperator, vmNamespace, backupName string, on return false, nil } lastFlakeCheck = time.Now() + // Second, distinct manifestation of the same CNV-85377/kubevirt/kubevirt#18949 + // bug: the VirtualMachineBackup can sit with ZERO status.conditions for the + // whole timeout instead of a specific frozen "is being attached to VMI" + // message -- no text for CheckIfFlakeOccurred below to match against, so + // check the VMB object directly. Require it to persist for a few checks + // (not just the first sighting) since a freshly-created VMB briefly has no + // conditions yet under completely normal, healthy operation. + if empty, found, vmbErr := v.VMBHasNoConditions(vmNamespace, dataUploadName); vmbErr == nil && found { + if empty { + if emptyConditionsSince.IsZero() { + emptyConditionsSince = time.Now() + } else if time.Since(emptyConditionsSince) >= 3*time.Minute { + lastFlakeMatched = true + _ = lib.NudgeVmiToTriggerResync(dynamicClientForSuiteRun, vmNamespace) + return false, nil + } + } else { + emptyConditionsSince = time.Time{} + } + } pod, podErr := lib.GetPodWithLabel(kubernetesClientForSuiteRun, namespace, "control-plane=oadp-kubevirt-datamover-controller") if podErr != nil { return false, nil From b32b10d082b52a91b321eba442eef7f8292f6d4d Mon Sep 17 00:00:00 2001 From: Tiger Kaovilai Date: Sat, 29 Aug 2026 20:07:25 -0400 Subject: [PATCH 10/15] fix: send HCO spec.featureGates in its real array shape, not an object EnableCBTFeatureGate was writing {"incrementalBackup": true} -- an object with a bool field -- but HCO's actual HyperConvergedFeatureGates type (api/v1/featuregates/feature_gates.go) is []FeatureGate{Name, State}, an array of {name, state} objects with State one of "Enabled"/"Disabled". Confirmed identical shape at both HEAD and the v1.18.0 tag, so this isn't a version skew -- it was simply wrong the whole time. HCO's v1beta1 write path is permissive enough to accept the wrong shape, but the v1 conversion webhook then fails to unmarshal it on the next read: "conversion webhook for hco.kubevirt.io/v1, Kind=HyperConverged failed: json: cannot unmarshal object into Go struct field HyperConvergedSpec. spec.featureGates of type featuregates.HyperConvergedFeatureGates" -- confirmed live as the actual cause of an unrelated-looking suite-wide BeforeAll timeout on this PR, previously misattributed to a separate upstream issue (kubevirt/hyperconverged-cluster-operator#4549). Signed-off-by: Tiger Kaovilai --- tests/e2e/lib/virt_helpers.go | 45 +++++++++++++++++++++++++++++------ 1 file changed, 38 insertions(+), 7 deletions(-) diff --git a/tests/e2e/lib/virt_helpers.go b/tests/e2e/lib/virt_helpers.go index d16b927004d..9b4c2bdc69e 100644 --- a/tests/e2e/lib/virt_helpers.go +++ b/tests/e2e/lib/virt_helpers.go @@ -1320,10 +1320,26 @@ func (v *VirtOperator) RequireVEP25Support() error { return nil } -// EnableCBTFeatureGate patches the HyperConverged CR to set -// spec.featureGates.incrementalBackup = true, then waits for the KubeVirt CR -// to reflect "IncrementalBackup" in its featureGates and for the -// backup.kubevirt.io CRDs to appear (requires KubeVirt >= 1.8 / HCO >= 1.18). +// EnableCBTFeatureGate patches the HyperConverged CR to enable the +// "incrementalBackup" feature gate, then waits for the KubeVirt CR to reflect +// "IncrementalBackup" in its featureGates and for the backup.kubevirt.io CRDs +// to appear (requires KubeVirt >= 1.8 / HCO >= 1.18). +// +// spec.featureGates is HCO's `[]FeatureGate{Name string, State *string}` array +// (api/v1/featuregates/feature_gates.go, State one of "Enabled"/"Disabled") -- +// NOT a map with a bool field per gate name. Confirmed by fetching that type at +// both HEAD and the v1.18.0 tag: identical shape, no version skew, so this was +// simply wrong the whole time, not something that changed under us. Writing +// the old {"incrementalBackup": true} object shape instead of a matching array +// entry corrupts the CR's stored spec.featureGates -- HCO's own v1beta1 write +// path is permissive enough to accept it, but the v1 conversion webhook then +// fails to unmarshal it on the next read: "conversion webhook for +// hco.kubevirt.io/v1, Kind=HyperConverged failed: json: cannot unmarshal +// object into Go struct field HyperConvergedSpec.spec.featureGates of type +// featuregates.HyperConvergedFeatureGates" -- confirmed live as the actual +// cause of an unrelated-looking suite-wide BeforeAll timeout on +// oadp-operator PR#2404, previously misattributed to a separate upstream +// issue (kubevirt/hyperconverged-cluster-operator#4549). func (v *VirtOperator) EnableCBTFeatureGate(timeout time.Duration) error { log.Printf("Enabling incrementalBackup feature gate on HCO") @@ -1333,10 +1349,25 @@ func (v *VirtOperator) EnableCBTFeatureGate(timeout time.Duration) error { return false, fmt.Errorf("failed to get HCO: %w", err) } - current, _, _ := unstructured.NestedBool(hco.UnstructuredContent(), "spec", "featureGates", "incrementalBackup") - log.Printf("HCO spec.featureGates.incrementalBackup current value: %v — setting to true", current) + gates, _, _ := unstructured.NestedSlice(hco.UnstructuredContent(), "spec", "featureGates") + updated := false + for _, g := range gates { + gate, ok := g.(map[string]interface{}) + if !ok { + continue + } + if name, _, _ := unstructured.NestedString(gate, "name"); name == "incrementalBackup" { + gate["state"] = "Enabled" + updated = true + break + } + } + if !updated { + gates = append(gates, map[string]interface{}{"name": "incrementalBackup", "state": "Enabled"}) + } + log.Printf("HCO spec.featureGates: setting incrementalBackup to Enabled (updated existing entry: %v)", updated) - if err := unstructured.SetNestedField(hco.UnstructuredContent(), true, "spec", "featureGates", "incrementalBackup"); err != nil { + if err := unstructured.SetNestedSlice(hco.UnstructuredContent(), gates, "spec", "featureGates"); err != nil { return false, fmt.Errorf("failed to set incrementalBackup feature gate: %w", err) } From 814f9439a6b2ced2c6a47298fb46d76db820e1cb Mon Sep 17 00:00:00 2001 From: Tiger Kaovilai Date: Sat, 29 Aug 2026 21:31:30 -0400 Subject: [PATCH 11/15] Revert "fix: send HCO spec.featureGates in its real array shape, not an object" That fix was wrong: it was based on HCO's v1 API type (api/v1/featuregates/feature_gates.go, an array of {name, state}), but EnableCBTFeatureGate writes to hyperConvergedGvr's v1beta1, not v1. Confirmed by reading v1beta1's actual type directly (api/v1beta1/hyperconverged_types.go): HyperConvergedFeatureGates has a plain IncrementalBackup *bool field with json tag "incrementalBackup" -- the original object-with-bool-field shape was correct all along. The array-shape rewrite got rejected outright by v1beta1's own mutating admission webhook ("unknown field spec.featureGates[0].name/.state"), confirmed live on the very next CI run. The real root cause of the original "conversion webhook for hco.kubevirt.io/v1 ... cannot unmarshal object" error remains genuinely unclear -- it may be a real, transient upstream HCO nightly-catalog issue after all (as originally suspected and tracked at kubevirt/hyperconverged-cluster-operator#4549), not a shape bug in this repo's own code. Reverting to the known-correct shape while that gets investigated properly instead of guessing again. This reverts commit 5e4d980e3b465e14c5f46d0a74bdb59f040586c2. Signed-off-by: Tiger Kaovilai --- tests/e2e/lib/virt_helpers.go | 45 ++++++----------------------------- 1 file changed, 7 insertions(+), 38 deletions(-) diff --git a/tests/e2e/lib/virt_helpers.go b/tests/e2e/lib/virt_helpers.go index 9b4c2bdc69e..d16b927004d 100644 --- a/tests/e2e/lib/virt_helpers.go +++ b/tests/e2e/lib/virt_helpers.go @@ -1320,26 +1320,10 @@ func (v *VirtOperator) RequireVEP25Support() error { return nil } -// EnableCBTFeatureGate patches the HyperConverged CR to enable the -// "incrementalBackup" feature gate, then waits for the KubeVirt CR to reflect -// "IncrementalBackup" in its featureGates and for the backup.kubevirt.io CRDs -// to appear (requires KubeVirt >= 1.8 / HCO >= 1.18). -// -// spec.featureGates is HCO's `[]FeatureGate{Name string, State *string}` array -// (api/v1/featuregates/feature_gates.go, State one of "Enabled"/"Disabled") -- -// NOT a map with a bool field per gate name. Confirmed by fetching that type at -// both HEAD and the v1.18.0 tag: identical shape, no version skew, so this was -// simply wrong the whole time, not something that changed under us. Writing -// the old {"incrementalBackup": true} object shape instead of a matching array -// entry corrupts the CR's stored spec.featureGates -- HCO's own v1beta1 write -// path is permissive enough to accept it, but the v1 conversion webhook then -// fails to unmarshal it on the next read: "conversion webhook for -// hco.kubevirt.io/v1, Kind=HyperConverged failed: json: cannot unmarshal -// object into Go struct field HyperConvergedSpec.spec.featureGates of type -// featuregates.HyperConvergedFeatureGates" -- confirmed live as the actual -// cause of an unrelated-looking suite-wide BeforeAll timeout on -// oadp-operator PR#2404, previously misattributed to a separate upstream -// issue (kubevirt/hyperconverged-cluster-operator#4549). +// EnableCBTFeatureGate patches the HyperConverged CR to set +// spec.featureGates.incrementalBackup = true, then waits for the KubeVirt CR +// to reflect "IncrementalBackup" in its featureGates and for the +// backup.kubevirt.io CRDs to appear (requires KubeVirt >= 1.8 / HCO >= 1.18). func (v *VirtOperator) EnableCBTFeatureGate(timeout time.Duration) error { log.Printf("Enabling incrementalBackup feature gate on HCO") @@ -1349,25 +1333,10 @@ func (v *VirtOperator) EnableCBTFeatureGate(timeout time.Duration) error { return false, fmt.Errorf("failed to get HCO: %w", err) } - gates, _, _ := unstructured.NestedSlice(hco.UnstructuredContent(), "spec", "featureGates") - updated := false - for _, g := range gates { - gate, ok := g.(map[string]interface{}) - if !ok { - continue - } - if name, _, _ := unstructured.NestedString(gate, "name"); name == "incrementalBackup" { - gate["state"] = "Enabled" - updated = true - break - } - } - if !updated { - gates = append(gates, map[string]interface{}{"name": "incrementalBackup", "state": "Enabled"}) - } - log.Printf("HCO spec.featureGates: setting incrementalBackup to Enabled (updated existing entry: %v)", updated) + current, _, _ := unstructured.NestedBool(hco.UnstructuredContent(), "spec", "featureGates", "incrementalBackup") + log.Printf("HCO spec.featureGates.incrementalBackup current value: %v — setting to true", current) - if err := unstructured.SetNestedSlice(hco.UnstructuredContent(), gates, "spec", "featureGates"); err != nil { + if err := unstructured.SetNestedField(hco.UnstructuredContent(), true, "spec", "featureGates", "incrementalBackup"); err != nil { return false, fmt.Errorf("failed to set incrementalBackup feature gate: %w", err) } From 10a5d613e2b5f7b83a005e4dc3a2d622c23909fe Mon Sep 17 00:00:00 2001 From: Tiger Kaovilai Date: Sun, 30 Aug 2026 01:49:13 -0400 Subject: [PATCH 12/15] fix: prefer HCO v1 API over v1beta1, avoiding its conversion webhook hco.kubevirt.io's HyperConverged CRD serves both v1 (storage:true, the hub version) and v1beta1 (storage:false). Every v1beta1 read/write round-trips through HCO's own conversion webhook, which has a live bug (kubevirt/hyperconverged-cluster-operator#4549) that has rejected valid spec.featureGates writes/reads in this suite's CI runs. Reading/writing v1 directly needs zero conversion, sidestepping that webhook entirely. hyperConvergedGVR() discovers via the Discovery API whether the cluster serves hco.kubevirt.io/v1 and caches the choice per VirtOperator, falling back to v1beta1 for older HCO releases that don't yet serve v1. EnableCBTFeatureGate's spec.featureGates write now branches on the resolved version, since v1's shape is a HyperConvergedFeatureGates array of {name, state} objects, not v1beta1's bool-field object. Signed-off-by: Tiger Kaovilai --- tests/e2e/lib/virt_helpers.go | 101 ++++++++++++++++++++++++++++------ 1 file changed, 85 insertions(+), 16 deletions(-) diff --git a/tests/e2e/lib/virt_helpers.go b/tests/e2e/lib/virt_helpers.go index d16b927004d..060a1350ba7 100644 --- a/tests/e2e/lib/virt_helpers.go +++ b/tests/e2e/lib/virt_helpers.go @@ -82,7 +82,22 @@ var packageManifestsGvr = schema.GroupVersionResource{ Version: "v1", } -var hyperConvergedGvr = schema.GroupVersionResource{ +// hco.kubevirt.io's HyperConverged CRD has two served API versions with a +// conversion webhook between them. v1 is the storage/hub version (confirmed +// via the CRD's own manifest: v1 has storage:true, v1beta1 has +// storage:false), so reading/writing v1 directly needs zero conversion, +// while v1beta1 always round-trips through HCO's conversion webhook. That +// webhook has a live upstream bug (kubevirt/hyperconverged-cluster-operator#4549) +// that can reject valid spec.featureGates writes/reads made via v1beta1. +// Prefer v1 whenever the cluster serves it; fall back to v1beta1 only for +// older HCO releases that don't yet serve v1. See hyperConvergedGVR(). +var hyperConvergedGvrV1 = schema.GroupVersionResource{ + Group: "hco.kubevirt.io", + Resource: "hyperconvergeds", + Version: "v1", +} + +var hyperConvergedGvrV1beta1 = schema.GroupVersionResource{ Group: "hco.kubevirt.io", Resource: "hyperconvergeds", Version: "v1beta1", @@ -149,6 +164,31 @@ type VirtOperator struct { Upstream bool CommunityIndex string // HCO index image tag (e.g. "1.17.1"); empty means no custom catalog CommunityChannel string // OLM channel actually published by that tag's catalog (discovered, not guessed) + + hcoGVR *schema.GroupVersionResource // cache for hyperConvergedGVR(), resolved once via discovery +} + +// hyperConvergedGVR returns the HyperConverged GVR to use against this +// cluster, preferring v1 (the CRD's storage/hub version, see the comment on +// hyperConvergedGvrV1) whenever it's actually served, and falling back to +// v1beta1 otherwise. The result is discovered once via the Discovery API and +// cached for the lifetime of this VirtOperator. +func (v *VirtOperator) hyperConvergedGVR() schema.GroupVersionResource { + if v.hcoGVR != nil { + return *v.hcoGVR + } + + gvr := hyperConvergedGvrV1beta1 + if v.Clientset != nil { + groupVersion := hyperConvergedGvrV1.Group + "/" + hyperConvergedGvrV1.Version + if _, err := v.Clientset.Discovery().ServerResourcesForGroupVersion(groupVersion); err == nil { + gvr = hyperConvergedGvrV1 + } else { + log.Printf("hco.kubevirt.io/v1 not served (%v), falling back to v1beta1", err) + } + } + v.hcoGVR = &gvr + return gvr } // communityChannelFromTag derives the OLM subscription channel name from an HCO @@ -525,7 +565,7 @@ func (v *VirtOperator) checkCsv() bool { // health status field is "healthy". Uses dynamic client to avoid uprooting lots // of package dependencies, which should probably be fixed later. func (v *VirtOperator) checkHco() bool { - unstructuredHco, err := v.Dynamic.Resource(hyperConvergedGvr).Namespace(v.Namespace).Get(context.Background(), "kubevirt-hyperconverged", metav1.GetOptions{}) + unstructuredHco, err := v.Dynamic.Resource(v.hyperConvergedGVR()).Namespace(v.Namespace).Get(context.Background(), "kubevirt-hyperconverged", metav1.GetOptions{}) if err != nil { log.Printf("Error getting HCO: %v", err) return false @@ -549,7 +589,7 @@ func (v *VirtOperator) checkHco() bool { // the jsonpatch annotation array. This handles annotations that contain // additional patches (e.g. CBT label selectors). func (v *VirtOperator) checkEmulation() bool { - hco, err := v.Dynamic.Resource(hyperConvergedGvr).Namespace(v.Namespace).Get(context.Background(), "kubevirt-hyperconverged", metav1.GetOptions{}) + hco, err := v.Dynamic.Resource(v.hyperConvergedGVR()).Namespace(v.Namespace).Get(context.Background(), "kubevirt-hyperconverged", metav1.GetOptions{}) if err != nil { return false } @@ -648,9 +688,10 @@ func (v *VirtOperator) installSubscription() error { // Creates a HyperConverged Operator instance. Another dynamic client to avoid // bringing in the KubeVirt APIs for now. func (v *VirtOperator) installHco() error { + gvr := v.hyperConvergedGVR() unstructuredHco := unstructured.Unstructured{ Object: map[string]interface{}{ - "apiVersion": "hco.kubevirt.io/v1beta1", + "apiVersion": gvr.Group + "/" + gvr.Version, "kind": "HyperConverged", "metadata": map[string]interface{}{ "name": "kubevirt-hyperconverged", @@ -659,7 +700,7 @@ func (v *VirtOperator) installHco() error { "spec": map[string]interface{}{}, }, } - _, err := v.Dynamic.Resource(hyperConvergedGvr).Namespace(v.Namespace).Create(context.Background(), &unstructuredHco, metav1.CreateOptions{}) + _, err := v.Dynamic.Resource(v.hyperConvergedGVR()).Namespace(v.Namespace).Create(context.Background(), &unstructuredHco, metav1.CreateOptions{}) if err != nil { log.Printf("Error creating HCO: %v", err) return err @@ -669,7 +710,7 @@ func (v *VirtOperator) installHco() error { } func (v *VirtOperator) configureEmulation() error { - hco, err := v.Dynamic.Resource(hyperConvergedGvr).Namespace(v.Namespace).Get(context.Background(), "kubevirt-hyperconverged", metav1.GetOptions{}) + hco, err := v.Dynamic.Resource(v.hyperConvergedGVR()).Namespace(v.Namespace).Get(context.Background(), "kubevirt-hyperconverged", metav1.GetOptions{}) if err != nil { return err } @@ -708,7 +749,7 @@ func (v *VirtOperator) configureEmulation() error { return err } - _, err = v.Dynamic.Resource(hyperConvergedGvr).Namespace(v.Namespace).Update(context.Background(), hco, metav1.UpdateOptions{}) + _, err = v.Dynamic.Resource(v.hyperConvergedGVR()).Namespace(v.Namespace).Update(context.Background(), hco, metav1.UpdateOptions{}) return err } @@ -835,7 +876,7 @@ func (v *VirtOperator) removeCsv() error { // Deletes a HyperConverged Operator instance. func (v *VirtOperator) removeHco() error { - err := v.Dynamic.Resource(hyperConvergedGvr).Namespace(v.Namespace).Delete(context.Background(), "kubevirt-hyperconverged", metav1.DeleteOptions{}) + err := v.Dynamic.Resource(v.hyperConvergedGVR()).Namespace(v.Namespace).Delete(context.Background(), "kubevirt-hyperconverged", metav1.DeleteOptions{}) if err != nil { log.Printf("Error deleting HCO: %v", err) return err @@ -1327,20 +1368,48 @@ func (v *VirtOperator) RequireVEP25Support() error { func (v *VirtOperator) EnableCBTFeatureGate(timeout time.Duration) error { log.Printf("Enabling incrementalBackup feature gate on HCO") + gvr := v.hyperConvergedGVR() err := wait.PollUntilContextTimeout(context.Background(), 5*time.Second, timeout, true, func(ctx context.Context) (bool, error) { - hco, err := v.Dynamic.Resource(hyperConvergedGvr).Namespace(v.Namespace).Get(ctx, "kubevirt-hyperconverged", metav1.GetOptions{}) + hco, err := v.Dynamic.Resource(gvr).Namespace(v.Namespace).Get(ctx, "kubevirt-hyperconverged", metav1.GetOptions{}) if err != nil { return false, fmt.Errorf("failed to get HCO: %w", err) } - current, _, _ := unstructured.NestedBool(hco.UnstructuredContent(), "spec", "featureGates", "incrementalBackup") - log.Printf("HCO spec.featureGates.incrementalBackup current value: %v — setting to true", current) + // v1's spec.featureGates is HyperConvergedFeatureGates, an array of + // {name, state} objects (confirmed against api/v1/featuregates), unlike + // v1beta1's object-with-named-bool-fields shape. Set the right shape + // for whichever version we're actually talking to. + if gvr.Version == hyperConvergedGvrV1.Version { + gates, _, _ := unstructured.NestedSlice(hco.UnstructuredContent(), "spec", "featureGates") + idx := -1 + for i, g := range gates { + if m, ok := g.(map[string]interface{}); ok { + if name, _ := m["name"].(string); strings.EqualFold(name, "incrementalBackup") { + idx = i + break + } + } + } + log.Printf("HCO spec.featureGates (v1 array) incrementalBackup already present: %v — setting to Enabled", idx >= 0) + entry := map[string]interface{}{"name": "incrementalBackup", "state": "Enabled"} + if idx >= 0 { + gates[idx] = entry + } else { + gates = append(gates, entry) + } + if err := unstructured.SetNestedSlice(hco.UnstructuredContent(), gates, "spec", "featureGates"); err != nil { + return false, fmt.Errorf("failed to set incrementalBackup feature gate (v1 array): %w", err) + } + } else { + current, _, _ := unstructured.NestedBool(hco.UnstructuredContent(), "spec", "featureGates", "incrementalBackup") + log.Printf("HCO spec.featureGates.incrementalBackup current value: %v — setting to true", current) - if err := unstructured.SetNestedField(hco.UnstructuredContent(), true, "spec", "featureGates", "incrementalBackup"); err != nil { - return false, fmt.Errorf("failed to set incrementalBackup feature gate: %w", err) + if err := unstructured.SetNestedField(hco.UnstructuredContent(), true, "spec", "featureGates", "incrementalBackup"); err != nil { + return false, fmt.Errorf("failed to set incrementalBackup feature gate: %w", err) + } } - _, err = v.Dynamic.Resource(hyperConvergedGvr).Namespace(v.Namespace).Update(ctx, hco, metav1.UpdateOptions{}) + _, err = v.Dynamic.Resource(gvr).Namespace(v.Namespace).Update(ctx, hco, metav1.UpdateOptions{}) if err != nil { if apierrors.IsConflict(err) { log.Printf("HCO modification conflict setting incrementalBackup, retrying...") @@ -1428,7 +1497,7 @@ func (v *VirtOperator) EnableCBTLabelSelector(timeout time.Duration) error { } err := wait.PollUntilContextTimeout(context.Background(), 5*time.Second, timeout, true, func(ctx context.Context) (bool, error) { - hco, err := v.Dynamic.Resource(hyperConvergedGvr).Namespace(v.Namespace).Get(ctx, "kubevirt-hyperconverged", metav1.GetOptions{}) + hco, err := v.Dynamic.Resource(v.hyperConvergedGVR()).Namespace(v.Namespace).Get(ctx, "kubevirt-hyperconverged", metav1.GetOptions{}) if err != nil { return false, fmt.Errorf("failed to get HCO: %w", err) } @@ -1464,7 +1533,7 @@ func (v *VirtOperator) EnableCBTLabelSelector(timeout time.Duration) error { return false, err } - _, err = v.Dynamic.Resource(hyperConvergedGvr).Namespace(v.Namespace).Update(ctx, hco, metav1.UpdateOptions{}) + _, err = v.Dynamic.Resource(v.hyperConvergedGVR()).Namespace(v.Namespace).Update(ctx, hco, metav1.UpdateOptions{}) if err != nil { if apierrors.IsConflict(err) { log.Printf("HCO modification conflict setting CBT label selector, retrying...") From a030c9ccf7fca320d6bd87bb2479d95a3838c981 Mon Sep 17 00:00:00 2001 From: Tiger Kaovilai Date: Sun, 30 Aug 2026 11:43:52 -0400 Subject: [PATCH 13/15] fix: clear stuck VMB finalizers in shared deleteNamespace, not just virt's own path 3/3 kubevirt-aws runs hit the identical failure: the "restore run-state flip..." spec's known-bug skip path (lib.CheckIfFlakeOccurred) unwinds via ginkgo.Skip before reaching its own namespace cleanup in virt_backup_restore_suite_test.go, which already knew to clear stuck VirtualMachineBackup finalizers (IsNamespaceDeletedClearingStuckVMBFinalizers, the kubevirt#18724 workaround) before waiting for termination. The shared AfterEach's plain deleteNamespace doesn't, so it hangs 5m waiting on a namespace whose VMB never got a real completed status (same still-open kubevirt/kubevirt#18949 disease as VMBHasNoConditions), failing the whole run and contributing to hitting the #2413 timeout ceiling. deleteNamespace now clears stuck VMB finalizers unconditionally via a throwaway VirtOperator wrapping the suite's existing dynamic client -- a harmless no-op for namespaces with no VMBs, so non-virt specs are unaffected. Signed-off-by: Tiger Kaovilai --- tests/e2e/backup_restore_suite_test.go | 12 +++++++++++- 1 file changed, 11 insertions(+), 1 deletion(-) diff --git a/tests/e2e/backup_restore_suite_test.go b/tests/e2e/backup_restore_suite_test.go index 09090da4fbf..bb46e59dc49 100644 --- a/tests/e2e/backup_restore_suite_test.go +++ b/tests/e2e/backup_restore_suite_test.go @@ -421,7 +421,17 @@ func gatherLogs(brCase BackupRestoreCase, installTime time.Time, report ginkgo.S func deleteNamespace(namespace string) { err := lib.DeleteNamespace(kubernetesClientForSuiteRun, namespace) gomega.Expect(err).ToNot(gomega.HaveOccurred()) - gomega.Eventually(lib.IsNamespaceDeleted(kubernetesClientForSuiteRun, namespace), time.Minute*5, time.Second*5).Should(gomega.BeTrue()) + // Clear any stuck VirtualMachineBackup finalizers (workaround for kubevirt#18724) + // before waiting for namespace termination. A spec that hits a known-bug skip + // path (see lib.CheckIfFlakeOccurred) unwinds via ginkgo.Skip before reaching + // its own namespace cleanup (e.g. IsNamespaceDeletedClearingStuckVMBFinalizers + // in virt_backup_restore_suite_test.go), leaving this shared AfterEach path as + // the only place left to do it -- confirmed live: without this, the plain + // IsNamespaceDeleted wait times out after 5m on a namespace whose VMB never + // got a real completed status (same still-open kubevirt/kubevirt#18949 disease + // as VMBHasNoConditions). Harmless no-op for namespaces with no VMBs. + vmbClearer := &lib.VirtOperator{Dynamic: dynamicClientForSuiteRun} + gomega.Eventually(vmbClearer.IsNamespaceDeletedClearingStuckVMBFinalizers(kubernetesClientForSuiteRun, namespace), time.Minute*5, time.Second*5).Should(gomega.BeTrue()) } var _ = ginkgo.Describe("Backup and restore tests", ginkgo.Ordered, func() { From 2f7ec4cf64f4da26a023232efe4bb3f73a308028 Mon Sep 17 00:00:00 2001 From: Tiger Kaovilai Date: Mon, 31 Aug 2026 18:39:04 -0400 Subject: [PATCH 14/15] test: remove kdm-controller image override, upstream fixes merged migtools/kubevirt-datamover-controller#207, #208, and #212 all merged (16:48, 19:06, 21:38 UTC). Confirmed the default image has caught up too: quay.io/konveyor/kubevirt-datamover-controller:latest's mirror refreshed at 22:01:45 UTC, after the last merge; and openshift/release#82762 wires this image directly into oadp-dev's ci-operator base_images/ operator.substitutions, so Prow e2e picks up a freshly-built image immediately regardless of mirror cadence. The custom quay.io/tkaovila/kubevirt-datamover-controller:combined-208-212v3-test override this suite carried since validating those PRs pre-merge is no longer needed -- the settings.json-driven UnsupportedOverrides path (unaffected by this change) is the normal, permanent path going forward. Signed-off-by: Tiger Kaovilai --- tests/e2e/e2e_suite_test.go | 27 --------------------------- 1 file changed, 27 deletions(-) diff --git a/tests/e2e/e2e_suite_test.go b/tests/e2e/e2e_suite_test.go index d9b7482d39d..8fe999fff20 100644 --- a/tests/e2e/e2e_suite_test.go +++ b/tests/e2e/e2e_suite_test.go @@ -20,7 +20,6 @@ import ( "sigs.k8s.io/controller-runtime/pkg/client/config" "sigs.k8s.io/controller-runtime/pkg/log/zap" - oadpv1alpha1 "github.com/openshift/oadp-operator/api/v1alpha1" "github.com/openshift/oadp-operator/tests/e2e/lib" libhcp "github.com/openshift/oadp-operator/tests/e2e/lib/hcp" ) @@ -227,32 +226,6 @@ func TestOADPE2E(t *testing.T) { UnsupportedOverrides: dpa.DeepCopy().Spec.UnsupportedOverrides, } - // TEMPORARY: overrides kdm-controller with a build carrying - // migtools/kubevirt-datamover-controller#208 and #212 (neither merged - // upstream yet), so the incremental-sequence spec can actually validate - // those fixes instead of self-skipping on the known flake pattern every - // run (see lib.CheckIfFlakeOccurred). #212 also includes a second, - // intermittent fix: handleAccepted was trusting the informer cache's - // (possibly stale) VirtualMachineBackup.Status instead of re-reading it - // via APIReader before concluding terminal state -- found live via a - // Prow failure (ci/prow/5.0-e2e-test-kubevirt-aws) where virt-controller - // had already written Done=True but kdm-controller's reconcile loop - // never observed it. That fix recurred with the identical symptom on its - // first build (v2) despite every mechanical piece checking out (image - // built after the fix commit, correctly pulled, APIReader correctly - // wired in main.go, refresh correctly placed before the status-check - // call) -- v3 adds logging to the refresh's own success/NotFound/error - // branches to settle, on the next recurrence, whether the live API - // server itself never had Done=True (a virt-controller/kubevirt-level - // stall, not kdm-controller's bug) or the "uncached" read has some - // subtler issue. Remove this override once #208/#212 merge and a - // release picks them up -- the settings.json-driven UnsupportedOverrides - // above is the normal, permanent path for this. - if dpaCR.UnsupportedOverrides == nil { - dpaCR.UnsupportedOverrides = map[oadpv1alpha1.UnsupportedImageKey]string{} - } - dpaCR.UnsupportedOverrides[oadpv1alpha1.KubeVirtDatamoverControllerImageKey] = "quay.io/tkaovila/kubevirt-datamover-controller:combined-208-212v3-test" - ginkgo.RunSpecs(t, "OADP E2E using velero prefix: "+veleroPrefix) } From e39e6deae2ed6be9e408d346c5727d87d57f3b4f Mon Sep 17 00:00:00 2001 From: Tiger Kaovilai Date: Tue, 1 Sep 2026 04:03:05 -0400 Subject: [PATCH 15/15] fix: make kdm restore checksum verification actually run (#2421 item 1) The restore-side "hard" data-integrity checksum in the kdm restore specs was silently skipped on effectively every run: it only trusted the read if the VM was still Halted immediately before and after, but the restored VM was already Running by the very first status read after restore, every time observed. The core assertion these specs exist to run had likely never actually executed. Adds VirtOperator.EnsureVmHaltedForExclusivePVCAccess: deterministically stops the VM (v.StopVm) and waits for its virt-launcher pod to actually disappear, rather than hoping to catch a naturally-occurring halted window. Unconditional by design -- a bypass keyed on "no pod right now" would have the same race shape as the bug this closes, since the restored VM's spec.running stays true and KubeVirt could create a new launcher pod moments later. Both call sites now always restart the VM afterward (StartVm), including when EnsureVmHaltedForExclusivePVCAccess itself errors out, since StopVm was still called either way. Validated live end-to-end on a real bare-metal KVM cluster (tkaovila-260901-amd64, us-west-2), not just locally-reasoned: - First attempt caught two real bugs CodeRabbit flagged that a synthetic run alone wouldn't have exercised: (1) trusting the VM's printableStatus string instead of the virt-launcher pod's actual presence -- Paused/Starting/Stopping all still have an attached pod just like Running; (2) the restart-on-error path never firing because the code short-circuited past it whenever the halt itself failed, which would have left the VM permanently stopped for the rest of the spec. - After fixing both, a live run still hit a 5-minute timeout waiting for the virt-launcher pod to disappear. Root cause: GetAllPodsWithLabel returns an error on a genuinely empty list ("no Pod found") instead of a clean empty result, so every poll tick misread "the pod is actually gone" as a transient failure worth retrying rather than success -- fixed by calling the Pods().List() client directly instead of routing through that helper. - Final live run: both kdm restore specs passed, hard assertions genuinely executed (real matching checksums via the exclusive helper pod, not skipped), stop-to-pod-gone taking ~5-36s in practice. go build/vet/gofmt clean. Signed-off-by: Tiger Kaovilai --- tests/e2e/lib/virt_helpers.go | 73 +++++++++++++++++++++ tests/e2e/virt_backup_restore_suite_test.go | 50 +++++++------- 2 files changed, 99 insertions(+), 24 deletions(-) diff --git a/tests/e2e/lib/virt_helpers.go b/tests/e2e/lib/virt_helpers.go index 060a1350ba7..b1a8a2ab3b3 100644 --- a/tests/e2e/lib/virt_helpers.go +++ b/tests/e2e/lib/virt_helpers.go @@ -1333,6 +1333,79 @@ func (v *VirtOperator) RestartVmAndWaitRunning(namespace, name string, timeout t return nil } +// EnsureVmHaltedForExclusivePVCAccess makes sure vmName's VM is genuinely +// stopped -- its virt-launcher pod gone, releasing the RWO block PVC -- before +// the caller checksums that PVC via a separate helper pod +// (ChecksumPVCBlockDeviceRegion). That helper pod needs exclusive access to +// the PVC; pausing a running VMI does NOT release it (a paused VMI's +// virt-launcher pod stays attached, only a real stop does). Confirmed live +// across multiple Prow runs that a restored VM is already Running by the very +// first status read after restore completes -- there's no naturally-occurring +// halted window to catch here, so this creates one deterministically instead +// of hoping to observe one. +// +// Always calls StopVm unconditionally, even if no virt-launcher pod currently +// exists -- a bypass keyed on "no pod right now" would have exactly the same +// race shape as the bug this closes: with the restored VM's spec.running +// still true, KubeVirt's own controller could create a brand new +// virt-launcher pod moments after that check, right as the caller's checksum +// helper pod tries to attach the same PVC. Only an explicit stop keeps +// spec.running false and guarantees no new pod appears during the checksum +// window. The caller must always restart the VM afterward if the rest of the +// spec needs it running again (e.g. via StartVm) -- this function's own +// stop is unconditional, so the caller's restart should be too. +func (v *VirtOperator) EnsureVmHaltedForExclusivePVCAccess(namespace, name string, timeout time.Duration) error { + log.Printf("Stopping VM %s/%s to get exclusive PVC access for the hard data-integrity checksum", namespace, name) + if err := v.StopVm(namespace, name); err != nil { + return fmt.Errorf("failed to stop VM %s/%s: %w", namespace, name, err) + } + + err := wait.PollUntilContextTimeout(context.Background(), 5*time.Second, timeout, true, func(ctx context.Context) (bool, error) { + stillHasPod, podErr := v.hasVirtLauncherPod(ctx, namespace, name) + if podErr != nil { + // Treat a lookup failure as transient (e.g. a momentary API + // error) rather than conflating it with "pod confirmed gone" -- + // keep polling instead of declaring success on an error. + log.Printf("transient error checking VM %s/%s's virt-launcher pod, retrying: %v", namespace, name, podErr) + return false, nil + } + return !stillHasPod, nil + }) + if err != nil { + return fmt.Errorf("VM %s/%s did not release its virt-launcher pod after StopVm: %w", namespace, name, err) + } + log.Printf("VM %s/%s stopped, virt-launcher pod gone -- safe to checksum its PVC", namespace, name) + return nil +} + +// hasVirtLauncherPod reports whether vmName still has ANY matching +// virt-launcher pod at all -- including one that's mid-termination +// (DeletionTimestamp set) or no longer Running. Deliberately does NOT reuse +// GetVirtLauncherPod's filtering: that one excludes a terminating pod because +// it's hunting for the currently-active pod to exec into, which is the wrong +// question here -- a pod already marked for deletion can still hold the PVC +// attached until it actually finishes terminating, so counting it as "gone" +// early would silently reintroduce the exact Multi-Attach race this function +// exists to close. Also deliberately does NOT go through GetAllPodsWithLabel: +// that helper returns an error on a genuinely empty list ("no Pod found") +// instead of a clean empty result -- confirmed live that routing through it +// here made every poll tick misread "the pod is actually gone" as a +// transient failure worth retrying, so the wait never succeeded and ran out +// the clock instead. Calls the client directly for correct, unambiguous +// list semantics: empty result, nil error. +func (v *VirtOperator) hasVirtLauncherPod(ctx context.Context, namespace, name string) (bool, error) { + podList, err := v.Clientset.CoreV1().Pods(namespace).List(ctx, metav1.ListOptions{LabelSelector: "kubevirt.io=virt-launcher"}) + if err != nil { + return false, fmt.Errorf("failed to list virt-launcher pods in %s: %w", namespace, err) + } + for i := range podList.Items { + if podList.Items[i].Annotations["kubevirt.io/domain"] == name { + return true, nil + } + } + return false, nil +} + // RequireVEP25Support is a pre-flight check that fails immediately if the // installed HCO version is older than 1.18 or if the backup.kubevirt.io CRDs // (VirtualMachineBackup, VirtualMachineBackupTracker) do not exist. diff --git a/tests/e2e/virt_backup_restore_suite_test.go b/tests/e2e/virt_backup_restore_suite_test.go index 57325dfd945..bc0f9d8878b 100644 --- a/tests/e2e/virt_backup_restore_suite_test.go +++ b/tests/e2e/virt_backup_restore_suite_test.go @@ -1613,15 +1613,23 @@ var _ = ginkgo.Describe("VM backup and restore tests", ginkgo.Ordered, func() { // above) showed the payload region was genuinely quiet across the whole // backup window -- otherwise a mismatch here couldn't be attributed to a // real transfer bug versus something unrelated that touched the region. - // Bracketed by its own "not Running yet" VM-status checks: the halt is the - // controller's to release, not this test's. if payloadRegionStable { ginkgo.By("verifying the payload region survived backup and restore intact (hard assertion)") - prePayloadStatus, statusErr := v.GetVmStatus(alpineNamespace, alpineVMName) - restoredPayloadChecksum, restoredPayloadErr := v.ChecksumPVCBlockDeviceRegion(kubeConfig, alpineNamespace, restoredPVC.Name, fullBackupPayloadOffsetMiB, fullBackupPayloadSizeMiB) - postPayloadStatus, postStatusErr := v.GetVmStatus(alpineNamespace, alpineVMName) - if statusErr != nil || prePayloadStatus == "Running" || postStatusErr != nil || postPayloadStatus == "Running" { - log.Printf("WARNING: restored VM %s/%s resumed around the payload-region read (pre=%q err=%v, post=%q err=%v) -- skipping the hard assertion for this run", alpineNamespace, alpineVMName, prePayloadStatus, statusErr, postPayloadStatus, postStatusErr) + haltErr := v.EnsureVmHaltedForExclusivePVCAccess(alpineNamespace, alpineVMName, 5*time.Minute) + var restoredPayloadChecksum string + var restoredPayloadErr error + if haltErr == nil { + restoredPayloadChecksum, restoredPayloadErr = v.ChecksumPVCBlockDeviceRegion(kubeConfig, alpineNamespace, restoredPVC.Name, fullBackupPayloadOffsetMiB, fullBackupPayloadSizeMiB) + } + // EnsureVmHaltedForExclusivePVCAccess always calls StopVm + // unconditionally (even if it then errors out waiting for the + // virt-launcher pod to disappear), so the restart must be + // unconditional too -- leaving the VM stopped would break every + // step after this one. + err = v.StartVm(alpineNamespace, alpineVMName) + gomega.Expect(err).ToNot(gomega.HaveOccurred(), "failed to restart VM %s/%s after checksum", alpineNamespace, alpineVMName) + if haltErr != nil { + log.Printf("WARNING: could not get exclusive PVC access to checksum the restored payload region: %v -- skipping the hard assertion for this run", haltErr) } else { gomega.Expect(restoredPayloadErr).ToNot(gomega.HaveOccurred(), "failed to checksum restored payload region") gomega.Expect(restoredPayloadChecksum).To(gomega.Equal(payloadChecksumBeforeBackup), @@ -1820,29 +1828,23 @@ var _ = ginkgo.Describe("VM backup and restore tests", ginkgo.Ordered, func() { gomega.Expect(succeeded).To(gomega.BeTrue(), "expected restore from an incremental checkpoint to reconstruct the full chain") ginkgo.By("verifying both payloads independently, each gated on its own bracket-stability") - // Bracketed the same way the full-backup It's payload check is: only - // trust these reads if the restored VM was still Halted immediately - // before AND after both of them -- confirmed live against a real cluster - // that the sibling-completion hold can release fast enough for the VM - // to already be Running by the time this check runs, which would make a - // mismatch here meaningless (comparing against a disk the booted guest - // may have already written to). - prePayloadStatus, preStatusErr := v.GetVmStatus(alpineNamespace, alpineVMName) - vmStillHalted := preStatusErr == nil && prePayloadStatus != "Running" - var restoredA, restoredB string - var restoredAErr, restoredBErr error - if vmStillHalted { + // Deterministically get exclusive PVC access rather than hoping to catch + // the VM still Halted -- confirmed live that it's already Running by the + // very first status read after restore, every time. See + // EnsureVmHaltedForExclusivePVCAccess. No restart needed afterward: this + // VM gets removed a few lines below regardless of its run-state. + haltErr := v.EnsureVmHaltedForExclusivePVCAccess(alpineNamespace, alpineVMName, 5*time.Minute) + if haltErr != nil { + log.Printf("WARNING: could not get exclusive PVC access to checksum restored payloads: %v -- skipping the hard assertions for this run", haltErr) + } else { + var restoredA, restoredB string + var restoredAErr, restoredBErr error if payloadAStable { restoredA, restoredAErr = v.ChecksumPVCBlockDeviceRegion(kubeConfig, alpineNamespace, "alpine-guestagent-disk", payloadAOffsetMiB, payloadSizeMiB) } if payloadBStable { restoredB, restoredBErr = v.ChecksumPVCBlockDeviceRegion(kubeConfig, alpineNamespace, "alpine-guestagent-disk", payloadBOffsetMiB, payloadSizeMiB) } - } - postPayloadStatus, postStatusErr := v.GetVmStatus(alpineNamespace, alpineVMName) - if !vmStillHalted || postStatusErr != nil || postPayloadStatus == "Running" { - log.Printf("WARNING: restored VM %s/%s resumed around the payload-region reads (pre=%q err=%v, post=%q err=%v) -- skipping the hard assertions for this run", alpineNamespace, alpineVMName, prePayloadStatus, preStatusErr, postPayloadStatus, postStatusErr) - } else { if payloadAStable { gomega.Expect(restoredAErr).ToNot(gomega.HaveOccurred(), "failed to checksum restored payload A region") gomega.Expect(restoredA).To(gomega.Equal(payloadA0), "payload A region did not survive the full+incremental backup/restore chain intact")