effective-creation-timeout & new metrics for use by dependency-watchdog

pkg/apis/machine/v1alpha1/constants.go

@@ -7,7 +7,13 @@ package v1alpha1
 const (
 	// AnnotationKeyMachineUpdateFailedReason is the annotation key that indicates the reason for a machine update failure.
 	AnnotationKeyMachineUpdateFailedReason = "node.machine.sapcloud.io/update-failed-reason"
-
+	// AnnotationKeyMachineEffectiveCreationTimeout is the annotation key set on the MachineDeployment that indicates
+	// the effective creation timeout for all Machine's belonging to this MachineDeployment. If specified, the value for this
+	// annotation takes precedence over the MachineDeployment.Spec.Template.Spec.MachineCreationTimeout.
+	AnnotationKeyMachineEffectiveCreationTimeout = "node.machine.sapcloud.io/effective-creation-timeout"
+	// AnnotationKeyMachineJoinDuration is the annotation key set on the Machine that indicates the amount of time Machine
+	// took to join the cluster. The value is a Go Duration string.
+	AnnotationKeyMachineJoinDuration = "node.machine.sapcloud.io/machine-join-duration"
 	// LabelKeyNodeCandidateForUpdate is the label key that indicates a node is a candidate for update.
 	LabelKeyNodeCandidateForUpdate = "node.machine.sapcloud.io/candidate-for-update"
 	// LabelKeyNodeSelectedForUpdate is the label key that indicates a node has been selected for update.

pkg/controller/controller_utils.go

@@ -505,9 +505,13 @@ func getMachinesFinalizers(template *v1alpha1.MachineTemplateSpec) []string {
 	return desiredFinalizers
 }
 
-func getMachinesAnnotationSet(template *v1alpha1.MachineTemplateSpec, _ runtime.Object) labels.Set {
+func getMachinesAnnotationSet(template *v1alpha1.MachineTemplateSpec, parentObject metav1.Object) labels.Set {
 	desiredAnnotations := make(labels.Set)
 	maps.Copy(desiredAnnotations, template.Annotations)
+	effectiveCreationTimeoutStr, ok := parentObject.GetAnnotations()[v1alpha1.AnnotationKeyMachineEffectiveCreationTimeout]
+	if ok {
+		desiredAnnotations[v1alpha1.AnnotationKeyMachineEffectiveCreationTimeout] = effectiveCreationTimeoutStr
+	}
 	return desiredAnnotations
 }
 
@@ -535,13 +539,13 @@ func GetMachineFromTemplate(template *v1alpha1.MachineTemplateSpec, parentObject
 	desiredLabels := getMachinesLabelSet(template)
 	//klog.Info(desiredLabels)
 	desiredFinalizers := getMachinesFinalizers(template)
-	desiredAnnotations := getMachinesAnnotationSet(template, parentObject)
 
-	accessor, err := meta.Accessor(parentObject)
+	parentMetaObj, err := meta.Accessor(parentObject)
 	if err != nil {
 		return nil, fmt.Errorf("parentObject does not have ObjectMeta, %v", err)
 	}
-	prefix := getMachinesPrefix(accessor.GetName())
+	prefix := getMachinesPrefix(parentMetaObj.GetName())
+	desiredAnnotations := getMachinesAnnotationSet(template, parentMetaObj)
 
 	machine := &v1alpha1.Machine{
 		ObjectMeta: metav1.ObjectMeta{
@@ -550,15 +554,25 @@ func GetMachineFromTemplate(template *v1alpha1.MachineTemplateSpec, parentObject
 			GenerateName: prefix,
 			Finalizers:   desiredFinalizers,
 		},
-		Spec: v1alpha1.MachineSpec{
-			Class: template.Spec.Class,
-		},
+	}
+	machine.Spec = *template.Spec.DeepCopy()
+	effectiveCreationTimeout, err := annotationsutils.GetEffectiveMachineCreationTimeoutFromRuntimeObject(parentObject)
+	if err != nil {
+		klog.Warningf("Failed to obtain effective creation timeout from annotation %q on machine set %q due to %s",
+			v1alpha1.AnnotationKeyMachineEffectiveCreationTimeout, controllerRef, err)
+	}
+	if effectiveCreationTimeout != nil {
+		if machine.Spec.MachineConfiguration == nil {
+			machine.Spec.MachineConfiguration = &v1alpha1.MachineConfiguration{MachineCreationTimeout: effectiveCreationTimeout}
+		} else {
+			machine.Spec.MachineConfiguration.MachineCreationTimeout = effectiveCreationTimeout
+		}
+		klog.V(2).Infof("MachineCreationTimeout overridden on new Machine with GenerateName %q and parent MachineSet %q to %q",
+			machine.ObjectMeta.GenerateName, parentMetaObj.GetName(), effectiveCreationTimeout.Duration)
 	}
 	if controllerRef != nil {
 		machine.OwnerReferences = append(machine.OwnerReferences, *controllerRef)
 	}
-	machine.Spec = *template.Spec.DeepCopy()
-
 	return machine, nil
 }
 
@@ -696,13 +710,13 @@ func GetFakeMachineFromTemplate(template *v1alpha1.MachineTemplateSpec, parentOb
 	desiredLabels := getMachinesLabelSet(template)
 
 	desiredFinalizers := getMachinesFinalizers(template)
-	desiredAnnotations := getMachinesAnnotationSet(template, parentObject)
-
-	accessor, err := meta.Accessor(parentObject)
+	parentMetaObj, err := meta.Accessor(parentObject)
 	if err != nil {
 		return nil, fmt.Errorf("parentObject does not have ObjectMeta, %v", err)
 	}
-	prefix := getMachinesPrefix(accessor.GetName())
+	desiredAnnotations := getMachinesAnnotationSet(template, parentMetaObj)
+
+	prefix := getMachinesPrefix(parentMetaObj.GetName())
 	prefix = prefix + "-" + uuid.New().String()[:5]
 	machine := &v1alpha1.Machine{
 		ObjectMeta: metav1.ObjectMeta{

pkg/util/annotations/annotations.go

@@ -8,10 +8,14 @@ package annotations
 import (
 	"slices"
 	"strings"
+	"time"
 
 	"github.com/gardener/machine-controller-manager/pkg/apis/machine/v1alpha1"
 	"github.com/gardener/machine-controller-manager/pkg/util/provider/machineutils"
 	v1 "k8s.io/api/core/v1"
+	"k8s.io/apimachinery/pkg/api/meta"
+	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
+	"k8s.io/apimachinery/pkg/runtime"
 )
 
 // AddOrUpdateAnnotation tries to add an annotation. Returns a new copy of updated Node and true if something was updated
@@ -87,3 +91,21 @@ func CreateMachinesTriggeredForDeletionAnnotValue(machineNames []string) string
 	slices.Sort(machineNames)
 	return strings.Join(machineNames, ",")
 }
+
+// GetEffectiveMachineCreationTimeoutFromRuntimeObject gets the value of the annotation [v1alpha1.AnnotationKeyMachineEffectiveCreationTimeout]
+// as a [metav1.Duration] if present.
+func GetEffectiveMachineCreationTimeoutFromRuntimeObject(object runtime.Object) (*metav1.Duration, error) {
+	metaObject, err := meta.Accessor(object)
+	if err != nil {
+		return nil, err
+	}
+	effectiveMachineCreationTimeoutStr, ok := metaObject.GetAnnotations()[v1alpha1.AnnotationKeyMachineEffectiveCreationTimeout]
+	if !ok {
+		return nil, nil
+	}
+	effectiveMachineCreationTimeout, err := time.ParseDuration(effectiveMachineCreationTimeoutStr)
+	if err != nil {
+		return nil, err
+	}
+	return &metav1.Duration{Duration: effectiveMachineCreationTimeout}, nil
+}

pkg/util/provider/drain/drain.go

@@ -1187,6 +1187,11 @@ func (o *Options) RunCordonOrUncordon(ctx context.Context, desired bool) error {
 	return nil
 }
 
+// GetDrainDuration gets the duration of drain activity
+func (o *Options) GetDrainDuration() time.Duration {
+	return o.drainEndedOn.Sub(o.drainStartedOn)
+}
+
 func getPdbForPod(pdbLister policyv1listers.PodDisruptionBudgetLister, pod *corev1.Pod) *policyv1.PodDisruptionBudget {
 	// GetPodPodDisruptionBudgets returns an error only if no PodDisruptionBudgets are found.
 	// We don't return that as an error to the caller.

pkg/util/provider/machinecontroller/controller.go

@@ -301,8 +301,7 @@ type controller struct {
 	machineClassSynced      cache.InformerSynced
 	machineSynced           cache.InformerSynced
 	podSynced               cache.InformerSynced
-
-	resourceExhaustedRetry machineutils.RetryPeriod
+	resourceExhaustedRetry  machineutils.RetryPeriod
 }
 
 func (dc *controller) Run(workers int, stopCh <-chan struct{}) {

pkg/util/provider/machinecontroller/machine.go

@@ -13,6 +13,7 @@ import (
 	"strings"
 	"time"
 
+	"github.com/gardener/machine-controller-manager/pkg/util/provider/metrics"
 	corev1 "k8s.io/api/core/v1"
 	apierrors "k8s.io/apimachinery/pkg/api/errors"
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
@@ -327,6 +328,7 @@ func (c *controller) triggerCreationFlow(ctx context.Context, createMachineReque
 	var (
 		// Declarations
 		nodeName, providerID string
+		createDuration       time.Duration
 
 		// Initializations
 		machine              = createMachineRequest.Machine
@@ -392,7 +394,9 @@ func (c *controller) triggerCreationFlow(ctx context.Context, createMachineReque
 				providerID = createMachineResponse.ProviderID
 				addresses.Insert(createMachineResponse.Addresses...)
 				// Creation was successful
-				klog.V(2).Infof("Created new VM for machine: %q with ProviderID: %q and backing node: %q", machine.Name, providerID, nodeName)
+				createDuration = time.Since(machine.CreationTimestamp.Time)
+				klog.V(2).Infof("Created new VM for machine: %q with ProviderID: %q and backing node: %q, createDuration: %s", machine.Name, providerID, nodeName, createDuration)
+				metrics.UpdateMetricsForMachineDurations(machine, metrics.MachineDurations{Create: createDuration})
 
 				if c.nodeLister != nil {
 					// If a node obj already exists by the same nodeName, treat it as a stale node and trigger machine deletion.
@@ -489,12 +493,19 @@ func (c *controller) triggerCreationFlow(ctx context.Context, createMachineReque
 	}
 	//initialize VM if not initialized
 	if uninitializedMachine {
-		var retryPeriod machineutils.RetryPeriod
-		var initResponse *driver.InitializeMachineResponse
+		var (
+			retryPeriod         machineutils.RetryPeriod
+			initResponse        *driver.InitializeMachineResponse
+			initializeBeginTime = time.Now()
+			initializeDuration  time.Duration
+		)
 		initResponse, retryPeriod, err = c.initializeMachine(ctx, clone, createMachineRequest.MachineClass, createMachineRequest.Secret)
 		if err != nil {
 			return retryPeriod, err
 		}
+		initializeDuration = time.Since(initializeBeginTime)
+		klog.V(2).Infof("Machine %q was initialized in %q", machine.Name, initializeDuration)
+		metrics.UpdateMetricsForMachineDurations(machine, metrics.MachineDurations{Initialize: initializeDuration})
 
 		if c.targetCoreClient == nil {
 			// persist addresses from the InitializeMachine and CreateMachine responses

pkg/util/provider/machinecontroller/machine_util.go

@@ -35,6 +35,8 @@ import (
 	"strings"
 	"time"
 
+	annotationsutils "github.com/gardener/machine-controller-manager/pkg/util/annotations"
+
 	machineapi "github.com/gardener/machine-controller-manager/pkg/apis/machine"
 	"github.com/gardener/machine-controller-manager/pkg/apis/machine/v1alpha1"
 	"github.com/gardener/machine-controller-manager/pkg/util/nodeops"
@@ -43,6 +45,7 @@ import (
 	"github.com/gardener/machine-controller-manager/pkg/util/provider/machinecodes/codes"
 	"github.com/gardener/machine-controller-manager/pkg/util/provider/machinecodes/status"
 	"github.com/gardener/machine-controller-manager/pkg/util/provider/machineutils"
+	"github.com/gardener/machine-controller-manager/pkg/util/provider/metrics"
 	utilstrings "github.com/gardener/machine-controller-manager/pkg/util/strings"
 	utiltime "github.com/gardener/machine-controller-manager/pkg/util/time"
 
@@ -973,15 +976,19 @@ func (c *controller) reconcileMachineHealth(ctx context.Context, machine *v1alph
 				if clone.Status.CurrentStatus.Phase != v1alpha1.MachineRunning && !isPendingMachineWithCriticalComponentsNotReadyTaint(clone, node) {
 					if clone.Status.LastOperation.Type == v1alpha1.MachineOperationCreate &&
 						clone.Status.LastOperation.State != v1alpha1.MachineStateSuccessful {
+						joinDuration := time.Since(machine.CreationTimestamp.Time)
 						// When machine creation went through
-						description = fmt.Sprintf("Machine %s successfully joined the cluster", clone.Name)
+						description = fmt.Sprintf("Machine %s successfully joined the cluster in %s", clone.Name, joinDuration)
 						lastOperationType = v1alpha1.MachineOperationCreate
 
 						// Delete the bootstrap token
 						err = c.deleteBootstrapToken(ctx, clone.Name)
 						if err != nil {
 							klog.Warning(err)
 						}
+						klog.V(2).Infof("Machine %q joined the cluster in %q", machine.Name, joinDuration)
+						metrics.UpdateMetricsForMachineDurations(machine, metrics.MachineDurations{Join: joinDuration})
+						metav1.SetMetaDataAnnotation(&clone.ObjectMeta, v1alpha1.AnnotationKeyMachineJoinDuration, joinDuration.String())
 					} else {
 						// Machine rejoined the cluster after a health-check
 						description = fmt.Sprintf("Machine %s successfully re-joined the cluster", clone.Name)
@@ -1099,7 +1106,7 @@ func (c *controller) reconcileMachineHealth(ctx context.Context, machine *v1alph
 					timeOutDuration,
 					machine.Status.Conditions,
 				)
-				machineDeployName := getMachineDeploymentName(machine)
+				machineDeployName := machineutils.GetMachineDeploymentName(machine)
 				// creating lock for machineDeployment, if not allocated
 				c.permitGiver.RegisterPermits(machineDeployName, 1)
 				return c.tryMarkingMachineFailed(ctx, machine, clone, machineDeployName, description, lockAcquireTimeout)
@@ -1147,6 +1154,13 @@ func (c *controller) reconcileMachineHealth(ctx context.Context, machine *v1alph
 					PreserveExpiryTime: machine.Status.CurrentStatus.PreserveExpiryTime,
 				}
 				cloneDirty = true
+				machineClass, err := c.machineClassLister.MachineClasses(c.namespace).Get(machine.Spec.Class.Name)
+				if err != nil {
+					klog.Warningf("unable to get MachineClass %q for Machine %q: %v", machine.Spec.Class.Name, machine.Name, err)
+				}
+				if machineClass != nil {
+					metrics.IncrementNumFailedToJoin(machine, machineClass)
+				}
 			}
 		} else {
 			// If timeout has not occurred, re-enqueue the machine
@@ -1544,6 +1558,7 @@ func (c *controller) drainNodeForInPlace(ctx context.Context, machine *v1alpha1.
 			description = fmt.Sprintf("Drain successful. %s", machineutils.NodeReadyForUpdate)
 		}
 		state = v1alpha1.MachineStateProcessing
+		metrics.UpdateMetricsForMachineDurations(machine, metrics.MachineDurations{Drain: drainOptions.GetDrainDuration()})
 	} else {
 		klog.Warningf("Drain failed for machine %q , providerID %q ,backing node %q. \nBuf:%v \nErrBuf:%v \nErr-Message:%v", machine.Name, getProviderID(machine), getNodeName(machine), buf, errBuf, err)
 
@@ -1708,6 +1723,7 @@ func (c *controller) drainNode(ctx context.Context, deleteMachineRequest *driver
 				}
 				err = fmt.Errorf("%s", description)
 				state = v1alpha1.MachineStateProcessing
+				metrics.UpdateMetricsForMachineDurations(machine, metrics.MachineDurations{Drain: drainOptions.GetDrainDuration()})
 
 				// Return error even when machine object is updated
 			} else if err != nil && forceDeleteMachine {
@@ -1820,6 +1836,7 @@ func (c *controller) deleteVM(ctx context.Context, deleteMachineRequest *driver.
 		description    string
 		state          v1alpha1.MachineState
 		lastKnownState string
+		deleteDuration time.Duration
 	)
 
 	deleteMachineResponse, err := c.driver.DeleteMachine(ctx, deleteMachineRequest)
@@ -1853,6 +1870,11 @@ func (c *controller) deleteVM(ctx context.Context, deleteMachineRequest *driver.
 		description = fmt.Sprintf("VM deletion was successful. %s", machineutils.InitiateNodeDeletion)
 		state = v1alpha1.MachineStateProcessing
 
+		if machine.DeletionTimestamp != nil {
+			deleteDuration = time.Since(machine.DeletionTimestamp.Time)
+			metrics.UpdateMetricsForMachineDurations(machine, metrics.MachineDurations{Delete: deleteDuration})
+		}
+
 		err = fmt.Errorf("Machine deletion in process. %s", description)
 	}
 
@@ -2014,11 +2036,20 @@ func (c *controller) getEffectiveHealthTimeout(machine *v1alpha1.Machine) *metav
 // getEffectiveCreationTimeout returns the creationTimeout set on the machine-object, otherwise returns the timeout set using the global-flag.
 func (c *controller) getEffectiveCreationTimeout(machine *v1alpha1.Machine) *metav1.Duration {
 	var effectiveCreationTimeout *metav1.Duration
+	effectiveCreationTimeout, err := annotationsutils.GetEffectiveMachineCreationTimeoutFromRuntimeObject(machine)
+	if effectiveCreationTimeout != nil {
+		return effectiveCreationTimeout
+	}
+	if err != nil {
+		klog.Warningf("error obtaining effectiveCreationTimeout from annotation %q (if any) on machine %q: %v",
+			v1alpha1.AnnotationKeyMachineEffectiveCreationTimeout, machine.Name, err)
+	}
 	if machine.Spec.MachineConfiguration != nil && machine.Spec.MachineCreationTimeout != nil {
 		effectiveCreationTimeout = machine.Spec.MachineCreationTimeout
 	} else {
 		effectiveCreationTimeout = &c.safetyOptions.MachineCreationTimeout
 	}
+	klog.V(4).Infof("obtained effectiveCreationTimeout %q for machine %q", effectiveCreationTimeout, machine.Name)
 	return effectiveCreationTimeout
 }
 
@@ -2280,10 +2311,6 @@ func getNodeName(machine *v1alpha1.Machine) string {
 	return machine.Labels[v1alpha1.NodeLabelKey]
 }
 
-func getMachineDeploymentName(machine *v1alpha1.Machine) string {
-	return machine.Labels["name"]
-}
-
 func (c *controller) updateMachineNodeLabel(ctx context.Context, machine *v1alpha1.Machine, nodeName string) error {
 	klog.V(2).Infof("Updating %q label on machine %q to %q", v1alpha1.NodeLabelKey, machine.Name, nodeName)
 	clone := machine.DeepCopy()
@@ -2675,5 +2702,6 @@ func (c *controller) drainPreservedNode(ctx context.Context, machine *v1alpha1.M
 	} else {
 		klog.V(3).Infof("Drain successful for machine %q , providerID %q ,backing node %q.", machine.Name, getProviderID(machine), getNodeName(machine))
 	}
+	metrics.UpdateMetricsForMachineDurations(machine, metrics.MachineDurations{Drain: drainOptions.GetDrainDuration()})
 	return nil
 }

pkg/util/provider/machineutils/utils.go

@@ -7,6 +7,8 @@ package machineutils
 
 import (
 	"context"
+	"time"
+
 	"github.com/gardener/machine-controller-manager/pkg/apis/machine/v1alpha1"
 	v1alpha1client "github.com/gardener/machine-controller-manager/pkg/client/clientset/versioned/typed/machine/v1alpha1"
 	v1alpha1listers "github.com/gardener/machine-controller-manager/pkg/client/listers/machine/v1alpha1"
@@ -16,7 +18,6 @@ import (
 	"k8s.io/apimachinery/pkg/util/sets"
 	"k8s.io/client-go/util/retry"
 	"k8s.io/klog/v2"
-	"time"
 )
 
 const (
@@ -174,6 +175,11 @@ func IsMachinePreservationExpired(m *v1alpha1.Machine) bool {
 	return t != nil && !t.After(time.Now())
 }
 
+// GetMachineDeploymentName gets the name of the MachineDeployment associated with this Machine
+func GetMachineDeploymentName(machine *v1alpha1.Machine) string {
+	return machine.Labels["name"]
+}
+
 // see https://github.com/kubernetes/kubernetes/issues/21479
 type updateMachineFunc func(machine *v1alpha1.Machine) error