Fix bootstrap NRC duration metric

Author: rawadhossain

internal/controller/node_controller.go

@@ -20,6 +20,8 @@ import (
 	"context"
 	"errors"
 	"fmt"
+	"strings"
+	"time"
 
 	corev1 "k8s.io/api/core/v1"
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
@@ -147,6 +149,16 @@ func (r *RuleReadinessController) processNodeAgainstAllRules(ctx context.Context
 			continue
 		}
 
+		// Recover a missing TaintAppliedAt before evaluating the rule.
+		// Skip repeated recovery checks for adopted taints.
+		if rule.Spec.EnforcementMode == readinessv1alpha1.EnforcementModeBootstrapOnly &&
+			r.hasTaintBySpec(node, rule.Spec.Taint) &&
+			r.taintAppliedAtMissing(rule, node.Name) &&
+			r.shouldAttemptTaintAppliedAtRecovery(rule.Name, node.Name) {
+			recovered := r.recoverTaintAppliedAtFromAPI(ctx, rule, node.Name)
+			r.recordTaintAppliedAtRecoveryOutcome(rule.Name, node.Name, recovered)
+		}
+
 		log.Info("Evaluating rule for node",
 			"node", node.Name,
 			"rule", rule.Name,
@@ -188,6 +200,9 @@ func (r *RuleReadinessController) processNodeAgainstAllRules(ctx context.Context
 			found := false
 			for i := range latestRule.Status.NodeEvaluations {
 				if latestRule.Status.NodeEvaluations[i].NodeName == node.Name {
+					if currEval.TaintAppliedAt.IsZero() && !latestRule.Status.NodeEvaluations[i].TaintAppliedAt.IsZero() {
+						currEval.TaintAppliedAt = latestRule.Status.NodeEvaluations[i].TaintAppliedAt
+					}
 					latestRule.Status.NodeEvaluations[i] = currEval
 					found = true
 					break
@@ -246,6 +261,106 @@ func (r *RuleReadinessController) processNodeAgainstAllRules(ctx context.Context
 	return errors.Join(errs...)
 }
 
+const maxTaintAnchorRecoveryAttempts = 2
+
+// Reports whether the cached evaluation is missing TaintAppliedAt.
+func (r *RuleReadinessController) taintAppliedAtMissing(rule *readinessv1alpha1.NodeReadinessRule, nodeName string) bool {
+	r.ruleCacheMutex.Lock()
+	defer r.ruleCacheMutex.Unlock()
+
+	prevEval := r.getPreviousNodeEvaluation(rule, nodeName)
+	return prevEval == nil || prevEval.TaintAppliedAt.IsZero()
+}
+
+// Reports whether recovery should still be attempted.
+func (r *RuleReadinessController) shouldAttemptTaintAppliedAtRecovery(ruleName, nodeName string) bool {
+	r.taintAnchorRecoveryMutex.Lock()
+	defer r.taintAnchorRecoveryMutex.Unlock()
+
+	return r.taintAnchorRecoveryAttempts[ruleName+"/"+nodeName] < maxTaintAnchorRecoveryAttempts
+}
+
+// Records the outcome of a recovery attempt.
+func (r *RuleReadinessController) recordTaintAppliedAtRecoveryOutcome(ruleName, nodeName string, recovered bool) {
+	key := ruleName + "/" + nodeName
+
+	r.taintAnchorRecoveryMutex.Lock()
+	defer r.taintAnchorRecoveryMutex.Unlock()
+
+	if recovered {
+		delete(r.taintAnchorRecoveryAttempts, key)
+		return
+	}
+	if r.taintAnchorRecoveryAttempts == nil {
+		r.taintAnchorRecoveryAttempts = make(map[string]int)
+	}
+	r.taintAnchorRecoveryAttempts[key]++
+}
+
+// Clears recovery tracking for a deleted rule.
+func (r *RuleReadinessController) clearTaintAppliedAtRecoveryForRule(ruleName string) {
+	prefix := ruleName + "/"
+
+	r.taintAnchorRecoveryMutex.Lock()
+	defer r.taintAnchorRecoveryMutex.Unlock()
+
+	for key := range r.taintAnchorRecoveryAttempts {
+		if strings.HasPrefix(key, prefix) {
+			delete(r.taintAnchorRecoveryAttempts, key)
+		}
+	}
+}
+
+// Clears recovery tracking for a rule/node pair.
+func (r *RuleReadinessController) clearTaintAppliedAtRecoveryForNode(ruleName, nodeName string) {
+	r.taintAnchorRecoveryMutex.Lock()
+	defer r.taintAnchorRecoveryMutex.Unlock()
+
+	delete(r.taintAnchorRecoveryAttempts, ruleName+"/"+nodeName)
+}
+
+// Recovers a missing TaintAppliedAt from the API and updates the cached rule.
+// Returns true if an existing anchor was found.
+func (r *RuleReadinessController) recoverTaintAppliedAtFromAPI(ctx context.Context, rule *readinessv1alpha1.NodeReadinessRule, nodeName string) bool {
+	log := ctrl.LoggerFrom(ctx)
+
+	const (
+		attempts = 3
+		delay    = 500 * time.Millisecond
+	)
+
+	for i := range attempts {
+		if i > 0 {
+			select {
+			case <-ctx.Done():
+				return false
+			case <-time.After(delay):
+			}
+		}
+
+		latestRule := &readinessv1alpha1.NodeReadinessRule{}
+		if err := r.Get(ctx, client.ObjectKey{Name: rule.Name}, latestRule); err != nil {
+			log.V(4).Info("Failed to refresh rule for TaintAppliedAt recovery",
+				"rule", rule.Name, "node", nodeName, "error", err.Error())
+			continue
+		}
+
+		for _, eval := range latestRule.Status.NodeEvaluations {
+			if eval.NodeName == nodeName && !eval.TaintAppliedAt.IsZero() {
+				r.ruleCacheMutex.Lock()
+				nodeEval := r.getOrCreateNodeEvaluation(rule, nodeName)
+				nodeEval.TaintAppliedAt = eval.TaintAppliedAt
+				r.ruleCacheMutex.Unlock()
+
+				log.V(4).Info("Recovered TaintAppliedAt anchor from API into stale cache entry",
+					"rule", rule.Name, "node", nodeName, "taintAppliedAt", eval.TaintAppliedAt)
+				return true
+			}
+		}
+	}
+	return false
+}
+
 // getConditionStatus gets the status of a condition on a node.
 func (r *RuleReadinessController) getConditionStatus(
 	node *corev1.Node,

internal/controller/nodereadinessrule_controller.go

@@ -59,6 +59,10 @@ type RuleReadinessController struct {
 	// Cache for efficient rule lookup
 	ruleCacheMutex sync.RWMutex
 	ruleCache      map[string]*readinessv1alpha1.NodeReadinessRule // ruleName -> rule
+
+	// taintAnchorRecoveryMutex guards taintAnchorRecoveryAttempts.
+	taintAnchorRecoveryMutex    sync.Mutex
+	taintAnchorRecoveryAttempts map[string]int
 }
 
 // RuleReconciler handles NodeReadinessRule reconciliation.
@@ -237,6 +241,8 @@ func (r *RuleReadinessController) cleanupDeletedNodes(ctx context.Context, rule
 	for _, evaluation := range rule.Status.NodeEvaluations {
 		if existingNodes[evaluation.NodeName] {
 			newNodeEvaluations = append(newNodeEvaluations, evaluation)
+		} else {
+			r.clearTaintAppliedAtRecoveryForNode(rule.Name, evaluation.NodeName)
 		}
 	}
 
@@ -416,9 +422,12 @@ func (r *RuleReadinessController) evaluateRuleForNode(ctx context.Context, rule
 
 			// Observe NRC-attributable hold time only on the first bootstrap completion.
 			// Skip repeated completions and adopted taints.
-			if !wasAlreadyCompleted {
+			//
+			// Match BootstrapDuration's guard conditions.
+			if !wasAlreadyCompleted &&
+				!node.CreationTimestamp.Time.Before(rule.CreationTimestamp.Time) && !latestTransition.IsZero() {
 				if prevEval := r.getPreviousNodeEvaluation(rule, node.Name); prevEval != nil && !prevEval.TaintAppliedAt.IsZero() {
-					duration := time.Since(prevEval.TaintAppliedAt.Time).Seconds()
+					duration := latestTransition.Time.Sub(prevEval.TaintAppliedAt.Time).Seconds()
 
 					if duration < 0 {
 						log.Info("Skipping bootstrap NRC duration metric due to negative duration",
@@ -581,6 +590,8 @@ func (r *RuleReadinessController) removeRuleFromCache(ctx context.Context, ruleN
 	delete(r.ruleCache, ruleName)
 	metrics.RulesTotal.Set(float64(len(r.ruleCache)))
 	log.Info("Removed rule from cache", "rule", ruleName, "totalRules", len(r.ruleCache))
+
+	r.clearTaintAppliedAtRecoveryForRule(ruleName)
 }
 
 // updateRuleStatus updates the status of a NodeReadinessRule.

internal/controller/nodereadinessrule_controller_test.go

@@ -55,6 +55,12 @@ func histogramSampleCount(histogram interface{ Write(*dto.Metric) error }) uint6
 	return metric.GetHistogram().GetSampleCount()
 }
 
+func histogramSampleSum(histogram interface{ Write(*dto.Metric) error }) float64 {
+	metric := &dto.Metric{}
+	Expect(histogram.Write(metric)).To(Succeed())
+	return metric.GetHistogram().GetSampleSum()
+}
+
 // errorInjectingClient forces Patch to fail for selected nodes.
 type errorInjectingClient struct {
 	client.Client
@@ -2327,7 +2333,7 @@ var _ = Describe("NodeReadinessRule Controller", func() {
 
 			Expect(k8sClient.Get(ctx, types.NamespacedName{Name: nodeName}, node)).To(Succeed())
 			node.Status.Conditions = []corev1.NodeCondition{
-				{Type: "Ready", Status: corev1.ConditionTrue},
+				{Type: "Ready", Status: corev1.ConditionTrue, LastTransitionTime: metav1.NewTime(time.Now().Add(2 * time.Second))},
 			}
 			Expect(k8sClient.Status().Update(ctx, node)).To(Succeed())
 			Expect(k8sClient.Get(ctx, types.NamespacedName{Name: nodeName}, node)).To(Succeed())
@@ -2369,7 +2375,7 @@ var _ = Describe("NodeReadinessRule Controller", func() {
 
 			Expect(k8sClient.Get(ctx, types.NamespacedName{Name: nodeName}, node)).To(Succeed())
 			node.Status.Conditions = []corev1.NodeCondition{
-				{Type: "Ready", Status: corev1.ConditionTrue},
+				{Type: "Ready", Status: corev1.ConditionTrue, LastTransitionTime: metav1.NewTime(time.Now().Add(2 * time.Second))},
 			}
 			Expect(k8sClient.Status().Update(ctx, node)).To(Succeed())
 			Expect(k8sClient.Get(ctx, types.NamespacedName{Name: nodeName}, node)).To(Succeed())
@@ -2484,6 +2490,105 @@ var _ = Describe("NodeReadinessRule Controller", func() {
 			Expect(taintAppliedAtIsZero(rule, nodeName)).To(BeTrue())
 		})
 
+		It("should use LastTransitionTime to calculate BootstrapNRCDuration", func() {
+			ruleName := "nrc-dur-clock-anchor-rule"
+			nodeName := "nrc-dur-clock-anchor-node"
+			labelKey := "nrc-dur-clock-anchor"
+
+			rule := newBootstrapOnlyRule(ruleName, labelKey)
+			Expect(k8sClient.Create(ctx, rule)).To(Succeed())
+			defer func() { _ = k8sClient.Delete(ctx, rule) }()
+
+			// Node without taint, condition NOT satisfied.
+			node := &corev1.Node{
+				ObjectMeta: metav1.ObjectMeta{
+					Name:   nodeName,
+					Labels: map[string]string{labelKey: "true"},
+				},
+				Status: corev1.NodeStatus{
+					Conditions: []corev1.NodeCondition{
+						{Type: "Ready", Status: corev1.ConditionFalse},
+					},
+				},
+			}
+			Expect(k8sClient.Create(ctx, node)).To(Succeed())
+			defer func() { _ = k8sClient.Delete(ctx, node) }()
+
+			Expect(k8sClient.Get(ctx, types.NamespacedName{Name: ruleName}, rule)).To(Succeed())
+			Expect(readinessController.evaluateRuleForNode(ctx, rule, node)).To(Succeed())
+			Expect(taintAppliedAtIsZero(rule, nodeName)).To(BeFalse())
+
+			// Backdate TaintAppliedAt to verify the duration uses LastTransitionTime
+			backdated := metav1.NewTime(time.Now().Add(-1 * time.Hour))
+			for i := range rule.Status.NodeEvaluations {
+				if rule.Status.NodeEvaluations[i].NodeName == nodeName {
+					rule.Status.NodeEvaluations[i].TaintAppliedAt = backdated
+				}
+			}
+
+			transitionTime := metav1.NewTime(backdated.Add(2 * time.Second))
+			Expect(k8sClient.Get(ctx, types.NamespacedName{Name: nodeName}, node)).To(Succeed())
+			node.Status.Conditions = []corev1.NodeCondition{
+				{Type: "Ready", Status: corev1.ConditionTrue, LastTransitionTime: transitionTime},
+			}
+			Expect(k8sClient.Status().Update(ctx, node)).To(Succeed())
+			Expect(k8sClient.Get(ctx, types.NamespacedName{Name: nodeName}, node)).To(Succeed())
+
+			histogram := metrics.BootstrapNRCDuration.WithLabelValues(ruleName).(prometheus.Histogram)
+			sumBefore := histogramSampleSum(histogram)
+			countBefore := histogramSampleCount(histogram)
+
+			Expect(readinessController.evaluateRuleForNode(ctx, rule, node)).To(Succeed())
+
+			Expect(histogramSampleCount(histogram)).To(Equal(countBefore + 1))
+			observed := histogramSampleSum(histogram) - sumBefore
+
+			Expect(observed).To(BeNumerically(">=", 0))
+			Expect(observed).To(BeNumerically("<", 10))
+		})
+
+		It("should skip BootstrapNRCDuration when LastTransitionTime is unset", func() {
+			ruleName := "nrc-dur-zero-transition-rule"
+			nodeName := "nrc-dur-zero-transition-node"
+			labelKey := "nrc-dur-zero-transition"
+
+			rule := newBootstrapOnlyRule(ruleName, labelKey)
+			Expect(k8sClient.Create(ctx, rule)).To(Succeed())
+			defer func() { _ = k8sClient.Delete(ctx, rule) }()
+
+			node := &corev1.Node{
+				ObjectMeta: metav1.ObjectMeta{
+					Name:   nodeName,
+					Labels: map[string]string{labelKey: "true"},
+				},
+				Status: corev1.NodeStatus{
+					Conditions: []corev1.NodeCondition{
+						{Type: "Ready", Status: corev1.ConditionFalse},
+					},
+				},
+			}
+			Expect(k8sClient.Create(ctx, node)).To(Succeed())
+			defer func() { _ = k8sClient.Delete(ctx, node) }()
+
+			Expect(k8sClient.Get(ctx, types.NamespacedName{Name: ruleName}, rule)).To(Succeed())
+			Expect(readinessController.evaluateRuleForNode(ctx, rule, node)).To(Succeed())
+			Expect(taintAppliedAtIsZero(rule, nodeName)).To(BeFalse())
+
+			Expect(k8sClient.Get(ctx, types.NamespacedName{Name: nodeName}, node)).To(Succeed())
+			node.Status.Conditions = []corev1.NodeCondition{
+				{Type: "Ready", Status: corev1.ConditionTrue},
+			}
+			Expect(k8sClient.Status().Update(ctx, node)).To(Succeed())
+			Expect(k8sClient.Get(ctx, types.NamespacedName{Name: nodeName}, node)).To(Succeed())
+
+			histogram := metrics.BootstrapNRCDuration.WithLabelValues(ruleName).(prometheus.Histogram)
+			before := histogramSampleCount(histogram)
+
+			Expect(readinessController.evaluateRuleForNode(ctx, rule, node)).To(Succeed())
+
+			Expect(histogramSampleCount(histogram)).To(Equal(before))
+		})
+
 		It("should clean up BootstrapNRCDuration label values on rule deletion", func() {
 			ruleName := "nrc-dur-del-rule"
 			labelKey := "nrc-dur-del"