feat: Implement structured logging pattern from CAPM3

This commit introduces a consistent logging pattern following the
cluster-api-provider-metal3 PR #2971 approach:

- Add logging.go with VerbosityLevelDebug (4) and VerbosityLevelTrace (5)
- Define 40+ LogField* constants for consistent structured logging keys
- Update all controllers to use the new logging constants
- Add trace-level logging for function entry points
- Convert inline strings to LogField* constants for type safety
- Add LOG_LEVEL_REVIEW_TODO section for future log level decisions
- Change SecretManager to return error instead of panic for nil owner
- Update tests to match new logging format

The structured logging approach improves:
- Consistency across the codebase
- Log filtering and analysis capabilities
- Type safety for log field keys
- Debugging and troubleshooting workflows

Signed-off-by: Maximilian Rink <maximilian.rink@telekom.de>

Author: MaxRink

internal/controller/metal3.io/action_result.go

@@ -3,7 +3,7 @@ package controllers
 import (
 	"errors"
 	"math"
-	"math/rand"
+	"math/rand/v2"
 	"time"
 
 	metal3api "github.com/metal3-io/baremetal-operator/apis/metal3.io/v1alpha1"
@@ -18,10 +18,6 @@ const (
 	defaultBackoff  = 0.5
 )
 
-func init() {
-	rand.Seed(time.Now().UTC().UnixNano())
-}
-
 // actionResult is an interface that encapsulates the result of a Reconcile
 // call, as returned by the action corresponding to the current state.
 type actionResult interface {

internal/controller/metal3.io/baremetalhost_controller.go

@@ -114,7 +114,7 @@ func (hsm *hostStateMachine) updateHostStateFrom(ctx context.Context, initialSta
 		default:
 		}
 
-		info.log.Info("changing provisioning state",
+		info.log.V(VerbosityLevelDebug).Info("changing provisioning state",
 			"old", initialState,
 			"new", hsm.NextState)
 		now := metav1.Now()
@@ -139,8 +139,8 @@ func (hsm *hostStateMachine) updateHostStateFrom(ctx context.Context, initialSta
 			// it needs error handling logic that we can't support in
 			// this function.
 			if updateBootModeStatus(hsm.Host) {
-				info.log.Info("saving boot mode",
-					"new mode", hsm.Host.Status.Provisioning.BootMode)
+				info.log.V(VerbosityLevelDebug).Info("saving boot mode",
+					"newMode", hsm.Host.Status.Provisioning.BootMode)
 			}
 		default:
 		}
@@ -189,7 +189,7 @@ func (hsm *hostStateMachine) ReconcileState(ctx context.Context, info *reconcile
 	}
 
 	if hsm.checkInitiateDelete(info.log) {
-		info.log.Info("Initiating host deletion")
+		info.log.V(VerbosityLevelDebug).Info("initiating host deletion")
 		return actionComplete{}
 	}
 
@@ -206,7 +206,8 @@ func (hsm *hostStateMachine) ReconcileState(ctx context.Context, info *reconcile
 		return stateHandler(ctx, info)
 	}
 
-	info.log.Info("No handler found for state", "state", initialState)
+	info.log.Info("no handler found for state",
+		LogFieldProvisioningState, initialState)
 	return actionError{fmt.Errorf("no handler found for state \"%s\"", initialState)}
 }
 
@@ -235,7 +236,7 @@ func (hsm *hostStateMachine) checkInitiateDelete(log logr.Logger) bool {
 	case metal3api.StateProvisioning, metal3api.StateProvisioned:
 		if hsm.Host.OperationalStatus() == metal3api.OperationalStatusDetached {
 			if delayDeleteForDetachedHost(hsm.Host) {
-				log.Info("Delaying detached host deletion")
+				log.V(VerbosityLevelDebug).Info("delaying detached host deletion")
 				deleteDelayedForDetached.Inc()
 				return false
 			}
@@ -247,7 +248,7 @@ func (hsm *hostStateMachine) checkInitiateDelete(log logr.Logger) bool {
 	case metal3api.StateExternallyProvisioned:
 		if hsm.Host.OperationalStatus() == metal3api.OperationalStatusDetached {
 			if delayDeleteForDetachedHost(hsm.Host) {
-				log.Info("Delaying detached host deletion")
+				log.V(VerbosityLevelDebug).Info("delaying detached host deletion")
 				deleteDelayedForDetached.Inc()
 				return false
 			}
@@ -288,29 +289,6 @@ func hasDetachedAnnotation(host *metal3api.BareMetalHost) bool {
 	return false
 }
 
-// skipReconcileSubresource checks if the applied annotations and status
-// prevent a subresource (HFS/HFC) from being reconciled.
-func skipReconcileSubresource(host *metal3api.BareMetalHost, logger logr.Logger) bool {
-	switch host.Status.Provisioning.State {
-	case "", metal3api.StateUnmanaged:
-		logger.Info("host is unmanaged or not yet enrolled, skipping reconcile")
-		return true
-	default:
-	}
-
-	if host.Status.OperationalStatus == metal3api.OperationalStatusDetached || hasDetachedAnnotation(host) {
-		logger.Info("host is currently detached, skipping reconcile")
-		return true
-	}
-
-	if _, ok := host.Annotations[metal3api.PausedAnnotation]; ok {
-		logger.Info("host is currently paused, skipping reconcile")
-		return true
-	}
-
-	return false
-}
-
 func delayDeleteForDetachedHost(host *metal3api.BareMetalHost) bool {
 	annotations := host.GetAnnotations()
 	args := metal3api.DetachedAnnotationArguments{}
@@ -342,13 +320,14 @@ func (hsm *hostStateMachine) checkDetachedHost(ctx context.Context, info *reconc
 		case metal3api.StateProvisioned, metal3api.StateExternallyProvisioned, metal3api.StateReady, metal3api.StateAvailable:
 			return hsm.Reconciler.detachHost(ctx, hsm.Provisioner, info)
 		default:
-			info.log.Info("host cannot be detached yet, waiting for the current operation to finish", "provisioningState", info.host.Status.Provisioning.State)
+			info.log.V(VerbosityLevelDebug).Info("host cannot be detached yet, waiting for the current operation to finish",
+				LogFieldProvisioningState, info.host.Status.Provisioning.State)
 		}
 	}
 	if info.host.Status.ErrorType == metal3api.DetachError {
 		clearError(info.host)
 		hsm.Host.Status.ErrorCount = 0
-		info.log.Info("removed detach error")
+		info.log.V(VerbosityLevelDebug).Info("removed detach error")
 		return actionUpdate{}
 	}
 	if info.host.OperationalStatus() == metal3api.OperationalStatusDetached {
@@ -357,7 +336,7 @@ func (hsm *hostStateMachine) checkDetachedHost(ctx context.Context, info *reconc
 			newStatus = metal3api.OperationalStatusError
 		}
 		info.host.SetOperationalStatus(newStatus)
-		info.log.Info("removed detached status")
+		info.log.V(VerbosityLevelDebug).Info("removed detached status")
 		return actionUpdate{}
 	}
 	return nil
@@ -386,7 +365,8 @@ func (hsm *hostStateMachine) ensureRegistered(ctx context.Context, info *reconci
 	default:
 		if hsm.Host.Status.ErrorType == metal3api.RegistrationError ||
 			!hsm.Host.Status.GoodCredentials.Match(*info.bmcCredsSecret) {
-			info.log.Info("retrying registration", "LastError", hsm.Host.Status.ErrorMessage)
+			info.log.V(VerbosityLevelDebug).Info("retrying registration",
+				"lastError", hsm.Host.Status.ErrorMessage)
 			recordStateBegin(hsm.Host, metal3api.StateRegistering, metav1.Now())
 		}
 	}
@@ -603,8 +583,7 @@ func (hsm *hostStateMachine) handleDeprovisioning(ctx context.Context, info *rec
 			// If the provisioner gives up deprovisioning and
 			// deletion has been requested, continue to delete.
 			if hsm.Host.Status.ErrorCount > retryCount {
-				info.log.Info("Giving up on host clean up after 3 attempts. The host may still be operational " +
-					"and cause issues in your clusters. You should clean it up manually now.")
+				info.log.Info("giving up on host clean up after 3 attempts, the host may still be operational and cause issues in your clusters - clean it up manually")
 				hsm.NextState = metal3api.StatePoweringOffBeforeDelete
 				info.postSaveCallbacks = append(info.postSaveCallbacks, deleteWithoutDeprov.Inc)
 				return actionComplete{}
@@ -640,7 +619,7 @@ func (hsm *hostStateMachine) handlePoweringOffBeforeDelete(ctx context.Context,
 		// If the provisioner gives up deprovisioning and
 		// deletion has been requested, continue to delete.
 		if hsm.Host.Status.ErrorCount > retryCount {
-			info.log.Info("Giving up on host power off after 3 attempts.")
+			info.log.Info("giving up on host power off after 3 attempts")
 			return skipToDelete()
 		}
 	case actionError:

internal/controller/metal3.io/host_state_machine.go

@@ -95,8 +95,8 @@ func (info *rhfcInfo) publishEvent(reason, message string) {
 
 // Reconcile handles changes to HostFirmwareComponents resources.
 func (r *HostFirmwareComponentsReconciler) Reconcile(ctx context.Context, req ctrl.Request) (result ctrl.Result, err error) {
-	reqLogger := r.Log.WithValues("hostfirmwarecomponents", req.NamespacedName)
-	reqLogger.Info("start")
+	reqLogger := r.Log.WithValues(LogFieldHost, req.NamespacedName)
+	reqLogger.V(VerbosityLevelTrace).Info("reconciliation started")
 
 	// Get the corresponding baremetalhost in this namespace, if one doesn't exist don't continue processing
 	bmh := &metal3api.BareMetalHost{}
@@ -109,17 +109,24 @@ func (r *HostFirmwareComponentsReconciler) Reconcile(ctx context.Context, req ct
 		return ctrl.Result{Requeue: true, RequeueAfter: resourceNotAvailableRetryDelay}, err
 	}
 
-	if skipReconcileSubresource(bmh, reqLogger) {
-		// We'll get notified on BMH changes, no need to reconcile soon
+	if hasDetachedAnnotation(bmh) {
+		reqLogger.V(VerbosityLevelDebug).Info("the host is detached, not running hostfirmwarecomponents reconciler")
 		return ctrl.Result{Requeue: true, RequeueAfter: unmanagedRetryDelay}, nil
 	}
+	// If the reconciliation is paused, requeue
+	annotations := bmh.GetAnnotations()
+
+	if _, ok := annotations[metal3api.PausedAnnotation]; ok {
+		reqLogger.V(VerbosityLevelDebug).Info("host is paused, no work to do")
+		return ctrl.Result{Requeue: true, RequeueAfter: subResourceNotReadyRetryDelay}, nil
+	}
 
 	// Fetch the HostFirmwareComponents
 	hfc := &metal3api.HostFirmwareComponents{}
 	if err = r.Get(ctx, req.NamespacedName, hfc); err != nil {
 		// The HFC resource may have been deleted
 		if k8serrors.IsNotFound(err) {
-			reqLogger.Info("HostFirmwareComponents not found")
+			reqLogger.V(VerbosityLevelDebug).Info("HostFirmwareComponents not found")
 			return ctrl.Result{}, nil
 		}
 		// Error reading the object - requeue the request.
@@ -141,24 +148,30 @@ func (r *HostFirmwareComponentsReconciler) Reconcile(ctx context.Context, req ct
 		} else {
 			msg = err.Error()
 		}
-		reqLogger.Info("provisioner is not ready", "Error", msg, "RequeueAfter", provisionerRetryDelay)
+		reqLogger.Info("provisioner is not ready",
+			LogFieldError, msg,
+			LogFieldRequeueAfter, provisionerRetryDelay)
 		return ctrl.Result{Requeue: true, RequeueAfter: provisionerRetryDelay}, nil
 	}
 
-	info.log.V(1).Info("retrieving firmware components and saving to resource", "Node", bmh.Status.Provisioning.ID)
+	info.log.V(VerbosityLevelDebug).Info("retrieving firmware components and saving to resource",
+		LogFieldNode, bmh.Status.Provisioning.ID)
 	// Check ironic for the components information if possible
 	components, err := prov.GetFirmwareComponents(ctx)
 
 	if err != nil {
 		if errors.Is(err, provisioner.ErrFirmwareUpdateUnsupported) {
 			return ctrl.Result{}, nil
 		}
-		reqLogger.Info("provisioner returns error", "Error", err.Error(), "RequeueAfter", provisionerRetryDelay)
+		reqLogger.Info("provisioner returns error",
+			LogFieldError, err.Error(),
+			LogFieldRequeueAfter, provisionerRetryDelay)
 		return ctrl.Result{Requeue: true, RequeueAfter: provisionerRetryDelay}, nil
 	}
 
 	if err = r.updateHostFirmware(ctx, info, components); err != nil {
-		info.log.Info("updateHostFirmware returned error")
+		info.log.Info("updateHostFirmware returned error",
+			LogFieldError, err.Error())
 		return ctrl.Result{}, fmt.Errorf("could not update hostfirmwarecomponents: %w", err)
 	}
 
@@ -223,7 +236,7 @@ func (r *HostFirmwareComponentsReconciler) updateHostFirmware(ctx context.Contex
 
 	// Update Status if has changed
 	if dirty {
-		info.log.Info("Status for HostFirmwareComponents changed")
+		info.log.V(VerbosityLevelDebug).Info("status for HostFirmwareComponents changed")
 		info.hfc.Status = *newStatus.DeepCopy()
 
 		t := metav1.Now()
@@ -247,7 +260,7 @@ func (r *HostFirmwareComponentsReconciler) SetupWithManager(mgr ctrl.Manager, ma
 }
 
 func (r *HostFirmwareComponentsReconciler) updateEventHandler(e event.UpdateEvent) bool {
-	r.Log.Info("hostfirmwarecomponents in event handler")
+	r.Log.V(VerbosityLevelTrace).Info("hostfirmwarecomponents in event handler")
 
 	return e.ObjectNew.GetGeneration() != e.ObjectOld.GetGeneration()
 }
@@ -264,12 +277,16 @@ func (r *HostFirmwareComponentsReconciler) validateHostFirmwareComponents(info *
 }
 
 func (r *HostFirmwareComponentsReconciler) publishEvent(ctx context.Context, request ctrl.Request, event corev1.Event) {
-	reqLogger := r.Log.WithValues("hostfirmwarecomponents", request.NamespacedName)
-	reqLogger.Info("publishing event", "reason", event.Reason, "message", event.Message)
+	reqLogger := r.Log.WithValues(LogFieldHost, request.NamespacedName)
+	reqLogger.V(VerbosityLevelDebug).Info("publishing event",
+		LogFieldReason, event.Reason,
+		"message", event.Message)
 	err := r.Create(ctx, &event)
 	if err != nil {
-		reqLogger.Info("failed to record event, ignoring",
-			"reason", event.Reason, "message", event.Message, "error", err)
+		reqLogger.V(VerbosityLevelDebug).Info("failed to record event, ignoring",
+			LogFieldReason, event.Reason,
+			"message", event.Message,
+			LogFieldError, err)
 	}
 }
 

internal/controller/metal3.io/hostfirmwarecomponents_controller.go

@@ -113,21 +113,21 @@ func (info *rInfo) publishEvent(reason, message string) {
 // For more details, check Reconcile and its Result here:
 // - https://pkg.go.dev/sigs.k8s.io/controller-runtime@v0.6.4/pkg/reconcile
 func (r *HostFirmwareSettingsReconciler) Reconcile(ctx context.Context, req ctrl.Request) (result ctrl.Result, err error) {
-	reqLogger := r.Log.WithValues("hostfirmwaresettings", req.NamespacedName)
-	reqLogger.Info("start")
+	reqLogger := r.Log.WithValues(LogFieldHost, req.NamespacedName)
+	reqLogger.V(VerbosityLevelTrace).Info("reconciliation started")
 
 	// Get the corresponding baremetalhost in this namespace, if one doesn't exist don't continue processing
 	bmh := &metal3api.BareMetalHost{}
 	if err = r.Get(ctx, req.NamespacedName, bmh); err != nil {
-		reqLogger.Info("could not get baremetalhost, not running reconciler")
+		reqLogger.V(VerbosityLevelDebug).Info("could not get baremetalhost, not running reconciler")
 		if k8serrors.IsNotFound(err) {
 			return ctrl.Result{}, nil
 		}
 		return ctrl.Result{Requeue: true, RequeueAfter: resourceNotAvailableRetryDelay}, nil
 	}
 
-	if skipReconcileSubresource(bmh, reqLogger) {
-		// We'll get notified on BMH changes, no need to reconcile soon
+	if hasDetachedAnnotation(bmh) {
+		reqLogger.V(VerbosityLevelDebug).Info("the host is detached, not running reconciler")
 		return ctrl.Result{Requeue: true, RequeueAfter: unmanagedRetryDelay}, nil
 	}
 
@@ -137,7 +137,7 @@ func (r *HostFirmwareSettingsReconciler) Reconcile(ctx context.Context, req ctrl
 	if err = r.Get(ctx, req.NamespacedName, hfs); err != nil {
 		// The HFS resource may have been deleted
 		if k8serrors.IsNotFound(err) {
-			reqLogger.Info("hostFirmwareSettings not found")
+			reqLogger.V(VerbosityLevelDebug).Info("hostFirmwareSettings not found")
 			return ctrl.Result{Requeue: true, RequeueAfter: resourceNotAvailableRetryDelay}, nil
 		}
 		// Error reading the object - requeue the request.
@@ -158,16 +158,21 @@ func (r *HostFirmwareSettingsReconciler) Reconcile(ctx context.Context, req ctrl
 		} else {
 			msg = err.Error()
 		}
-		reqLogger.Info("provisioner is not ready", "Error", msg, "RequeueAfter", provisionerRetryDelay)
+		reqLogger.Info("provisioner is not ready",
+			LogFieldError, msg,
+			LogFieldRequeueAfter, provisionerRetryDelay)
 		return ctrl.Result{Requeue: true, RequeueAfter: provisionerRetryDelay}, nil
 	}
 
-	info.log.V(1).Info("retrieving firmware settings and saving to resource", "Node", bmh.Status.Provisioning.ID)
+	info.log.V(VerbosityLevelDebug).Info("retrieving firmware settings and saving to resource",
+		LogFieldNode, bmh.Status.Provisioning.ID)
 
 	// Get the current settings and schema, retry if provisioner returns error
 	currentSettings, schema, err := prov.GetFirmwareSettings(ctx, true)
 	if err != nil {
-		reqLogger.Info("provisioner returns error", "Error", err.Error(), "RequeueAfter", provisionerRetryDelay)
+		reqLogger.Info("provisioner returns error",
+			LogFieldError, err.Error(),
+			LogFieldRequeueAfter, provisionerRetryDelay)
 		return ctrl.Result{Requeue: true, RequeueAfter: provisionerRetryDelay}, nil
 	}
 
@@ -231,7 +236,10 @@ func (r *HostFirmwareSettingsReconciler) updateStatus(ctx context.Context, info
 	for k, v := range info.hfs.Spec.Settings {
 		if statusVal, ok := newStatus.Settings[k]; ok {
 			if v.String() != statusVal {
-				info.log.Info("spec value different than status", "name", k, "specvalue", v.String(), "statusvalue", statusVal)
+				info.log.V(VerbosityLevelDebug).Info("spec value different than status",
+					"name", k,
+					"specValue", v.String(),
+					"statusValue", statusVal)
 				specMismatch = true
 				break
 			}
@@ -281,7 +289,7 @@ func (r *HostFirmwareSettingsReconciler) updateStatus(ctx context.Context, info
 
 	// Update Status if it has changed
 	if dirty {
-		info.log.Info("Status has changed")
+		info.log.V(VerbosityLevelDebug).Info("status has changed")
 		info.hfs.Status = *newStatus.DeepCopy()
 
 		t := metav1.Now()
@@ -293,15 +301,15 @@ func (r *HostFirmwareSettingsReconciler) updateStatus(ctx context.Context, info
 
 // Get a firmware schema that matches the host vendor or create one if it doesn't exist.
 func (r *HostFirmwareSettingsReconciler) getOrCreateFirmwareSchema(ctx context.Context, info *rInfo, schema map[string]metal3api.SettingSchema) (fSchema *metal3api.FirmwareSchema, err error) {
-	info.log.V(1).Info("getting firmwareSchema")
+	info.log.V(VerbosityLevelTrace).Info("getting firmwareSchema")
 
 	schemaName := GetSchemaName(schema)
 	firmwareSchema := &metal3api.FirmwareSchema{}
 
 	// If a schema exists that matches, use that, otherwise create a new one
 	if err = r.Get(ctx, client.ObjectKey{Namespace: info.hfs.ObjectMeta.Namespace, Name: schemaName},
 		firmwareSchema); err == nil {
-		info.log.V(1).Info("found existing firmwareSchema resource")
+		info.log.V(VerbosityLevelDebug).Info("found existing firmwareSchema resource")
 
 		// Add hfs as owner so can be garbage collected on delete, if already an owner it will just be overwritten
 		if err = controllerutil.SetOwnerReference(info.hfs, firmwareSchema, r.Scheme()); err != nil {
@@ -353,7 +361,7 @@ func (r *HostFirmwareSettingsReconciler) getOrCreateFirmwareSchema(ctx context.C
 		return nil, err
 	}
 
-	info.log.Info("created new firmwareSchema resource")
+	info.log.V(VerbosityLevelDebug).Info("created new firmwareSchema resource")
 
 	return firmwareSchema, nil
 }
@@ -372,11 +380,11 @@ func (r *HostFirmwareSettingsReconciler) SetupWithManager(mgr ctrl.Manager, maxC
 }
 
 func (r *HostFirmwareSettingsReconciler) updateEventHandler(e event.UpdateEvent) bool {
-	r.Log.Info("hostfirmwaresettings in event handler")
+	r.Log.V(VerbosityLevelTrace).Info("hostfirmwaresettings in event handler")
 
 	// If the update increased the resource Generation then let's process it
 	if e.ObjectNew.GetGeneration() != e.ObjectOld.GetGeneration() {
-		r.Log.Info("returning true as generation changed from event handler")
+		r.Log.V(VerbosityLevelDebug).Info("returning true as generation changed from event handler")
 		return true
 	}