Onboarding: Timeout on active instance eventually

The code currently assumes, that an instance would
report the expected string eventually, which assumes
that the metadata service lookup works.

The active state only reflects that the hypervisor
could boot the VM.

As the instance usually boots within seconds,
a five minute timeout seems save enough to
catch this eventuality.

Author: fwiesel

go.mod

@@ -104,7 +104,7 @@ require (
 	k8s.io/component-base v0.35.0 // indirect
 	k8s.io/klog/v2 v2.130.1 // indirect
 	k8s.io/kube-openapi v0.0.0-20250910181357-589584f1c912 // indirect
-	k8s.io/utils v0.0.0-20251002143259-bc988d571ff4 // indirect
+	k8s.io/utils v0.0.0-20251002143259-bc988d571ff4
 	sigs.k8s.io/apiserver-network-proxy/konnectivity-client v0.33.0 // indirect
 	sigs.k8s.io/gateway-api v1.4.0 // indirect
 	sigs.k8s.io/json v0.0.0-20250730193827-2d320260d730 // indirect

internal/controller/onboarding_controller.go

@@ -31,6 +31,7 @@ import (
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
 	"k8s.io/apimachinery/pkg/runtime"
 	"k8s.io/apimachinery/pkg/types"
+	"k8s.io/utils/clock"
 	ctrl "sigs.k8s.io/controller-runtime"
 	k8sclient "sigs.k8s.io/controller-runtime/pkg/client"
 	logger "sigs.k8s.io/controller-runtime/pkg/log"
@@ -51,6 +52,7 @@ var errRequeue = errors.New("requeue requested")
 
 const (
 	defaultWaitTime          = 1 * time.Minute
+	smokeTestTimeout         = 5 * time.Minute
 	testProjectName          = "test"
 	testDomainName           = "cc3test"
 	testImageName            = "cirros-kvm"
@@ -63,6 +65,7 @@ type OnboardingController struct {
 	k8sclient.Client
 	Scheme            *runtime.Scheme
 	TestFlavorID      string
+	Clock             clock.Clock
 	computeClient     *gophercloud.ServiceClient
 	testComputeClient *gophercloud.ServiceClient
 	testImageClient   *gophercloud.ServiceClient
@@ -286,6 +289,21 @@ func (r *OnboardingController) smokeTest(ctx context.Context, hv *kvmv1.Hypervis
 		}
 
 		if !strings.Contains(consoleOutput, server.Name) {
+			if !server.LaunchedAt.IsZero() && r.Clock.Now().After(server.LaunchedAt.Add(smokeTestTimeout)) {
+				base := hv.DeepCopy()
+				meta.SetStatusCondition(&hv.Status.Conditions, metav1.Condition{
+					Type:    kvmv1.ConditionTypeOnboarding,
+					Status:  metav1.ConditionTrue,
+					Reason:  kvmv1.ConditionReasonTesting,
+					Message: fmt.Sprintf("timeout waiting for console output since %v", server.LaunchedAt),
+				})
+				if err := r.patchStatus(ctx, hv, base); err != nil {
+					return ctrl.Result{}, err
+				}
+				if err = servers.Delete(ctx, r.testComputeClient, server.ID).ExtractErr(); err != nil {
+					return ctrl.Result{}, fmt.Errorf("failed to delete timed out test instance %v: %w", server.ID, err)
+				}
+			}
 			return ctrl.Result{RequeueAfter: defaultWaitTime}, nil
 		}
 
@@ -613,6 +631,8 @@ func (r *OnboardingController) SetupWithManager(mgr ctrl.Manager) error {
 	}
 	r.testNetworkClient.ResourceBase = fmt.Sprintf("%vv2.0/", r.testNetworkClient.Endpoint)
 
+	r.Clock = clock.RealClock{}
+
 	return ctrl.NewControllerManagedBy(mgr).
 		Named(OnboardingControllerName).
 		For(&kvmv1.Hypervisor{}).

internal/controller/onboarding_controller_test.go

@@ -21,6 +21,7 @@ import (
 	"fmt"
 	"net/http"
 	"os"
+	"time"
 
 	"github.com/gophercloud/gophercloud/v2/testhelper"
 	"github.com/gophercloud/gophercloud/v2/testhelper/client"
@@ -30,6 +31,8 @@ import (
 	"k8s.io/apimachinery/pkg/api/meta"
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
 	"k8s.io/apimachinery/pkg/types"
+	"k8s.io/utils/clock"
+	clocktesting "k8s.io/utils/clock/testing"
 	ctrl "sigs.k8s.io/controller-runtime"
 
 	kvmv1 "github.com/cobaltcore-dev/openstack-hypervisor-operator/api/v1"
@@ -162,7 +165,8 @@ var _ = Describe("Onboarding Controller", func() {
 		createServerBody = `{
     "server": {
         "id": "server-id",
-		"status": "ACTIVE"
+        "status": "ACTIVE",
+        "OS-SRV-USG:launched_at": "2025-01-01T12:00:00.000000"
     }
 }`
 	)
@@ -221,6 +225,7 @@ var _ = Describe("Onboarding Controller", func() {
 			Client:            k8sClient,
 			Scheme:            k8sClient.Scheme(),
 			TestFlavorID:      "1",
+			Clock:             clock.RealClock{},
 			computeClient:     client.ServiceClient(fakeServer),
 			testComputeClient: client.ServiceClient(fakeServer),
 			testImageClient:   client.ServiceClient(fakeServer),
@@ -340,6 +345,11 @@ var _ = Describe("Onboarding Controller", func() {
 	})
 
 	Context("running tests after initial setup", func() {
+		var (
+			serverActionHandler func(http.ResponseWriter, *http.Request)
+			serverDeleteHandler func(http.ResponseWriter, *http.Request)
+		)
+
 		BeforeEach(func(ctx SpecContext) {
 			hv := &kvmv1.Hypervisor{}
 			Expect(k8sClient.Get(ctx, namespacedName, hv)).To(Succeed())
@@ -406,15 +416,21 @@ var _ = Describe("Onboarding Controller", func() {
 				Expect(err).NotTo(HaveOccurred())
 			})
 
-			fakeServer.Mux.HandleFunc("POST /servers/server-id/action", func(w http.ResponseWriter, r *http.Request) {
+			serverActionHandler = func(w http.ResponseWriter, _ *http.Request) {
 				w.Header().Add("Content-Type", "application/json")
 				w.WriteHeader(http.StatusOK)
 				_, err := fmt.Fprintf(w, `{"output": "FAKE CONSOLE OUTPUT\nANOTHER\nLAST LINE\nohooc--%v-%v\n"}`, hv.Name, hv.UID)
 				Expect(err).NotTo(HaveOccurred())
-
+			}
+			fakeServer.Mux.HandleFunc("POST /servers/server-id/action", func(w http.ResponseWriter, r *http.Request) {
+				serverActionHandler(w, r)
 			})
-			fakeServer.Mux.HandleFunc("DELETE /servers/server-id", func(w http.ResponseWriter, r *http.Request) {
+
+			serverDeleteHandler = func(w http.ResponseWriter, _ *http.Request) {
 				w.WriteHeader(http.StatusAccepted)
+			}
+			fakeServer.Mux.HandleFunc("DELETE /servers/server-id", func(w http.ResponseWriter, r *http.Request) {
+				serverDeleteHandler(w, r)
 			})
 		})
 
@@ -497,6 +513,7 @@ var _ = Describe("Onboarding Controller", func() {
 				))
 			})
 		})
+
 		When("SkipTests is set to false", func() {
 			BeforeEach(func(ctx SpecContext) {
 				hv := &kvmv1.Hypervisor{}
@@ -571,5 +588,53 @@ var _ = Describe("Onboarding Controller", func() {
 			})
 		})
 
+		When("smoke test times out waiting for console output", func() {
+			var serverDeletedCalled bool
+
+			BeforeEach(func(ctx SpecContext) {
+				By("Overriding HV status to Testing state")
+				hv := &kvmv1.Hypervisor{}
+				Expect(k8sClient.Get(ctx, namespacedName, hv)).To(Succeed())
+				meta.SetStatusCondition(&hv.Status.Conditions, metav1.Condition{
+					Type:   kvmv1.ConditionTypeOnboarding,
+					Status: metav1.ConditionTrue,
+					Reason: kvmv1.ConditionReasonTesting,
+				})
+				Expect(k8sClient.Status().Update(ctx, hv)).To(Succeed())
+
+				By("Setting fake clock past the smoke test timeout")
+				// createServerBody has LaunchedAt "2025-01-01T12:00:00", so 6 minutes later is past the 5-minute deadline
+				onboardingReconciler.Clock = clocktesting.NewFakeClock(time.Date(2025, 1, 1, 12, 6, 0, 0, time.UTC))
+				serverDeletedCalled = false
+
+				serverActionHandler = func(w http.ResponseWriter, _ *http.Request) {
+					w.Header().Add("Content-Type", "application/json")
+					w.WriteHeader(http.StatusOK)
+					_, err := fmt.Fprint(w, `{"output": "some unrelated console output\n"}`)
+					Expect(err).NotTo(HaveOccurred())
+				}
+				serverDeleteHandler = func(w http.ResponseWriter, _ *http.Request) {
+					serverDeletedCalled = true
+					w.WriteHeader(http.StatusAccepted)
+				}
+			})
+
+			It("should delete the stalled server and record a timeout in the status", func(ctx SpecContext) {
+				By("Reconciling smoke test past the timeout deadline")
+				_, err := onboardingReconciler.Reconcile(ctx, reconcileReq)
+				Expect(err).NotTo(HaveOccurred())
+
+				By("Verifying the timed-out server was deleted")
+				Expect(serverDeletedCalled).To(BeTrue())
+
+				By("Verifying the onboarding condition message indicates a timeout")
+				hv := &kvmv1.Hypervisor{}
+				Expect(k8sClient.Get(ctx, namespacedName, hv)).To(Succeed())
+				onboardingCond := meta.FindStatusCondition(hv.Status.Conditions, kvmv1.ConditionTypeOnboarding)
+				Expect(onboardingCond).NotTo(BeNil())
+				Expect(onboardingCond.Reason).To(Equal(kvmv1.ConditionReasonTesting))
+				Expect(onboardingCond.Message).To(ContainSubstring("timeout"))
+			})
+		})
 	})
 })