more ml

internal/kubernetes/watcher.go

@@ -28,8 +28,12 @@ const maxRollouts = 500
 type Watcher struct {
 	mu       sync.RWMutex
 	rollouts map[string]Rollout
-	enabled  bool
-	err      string
+	// revisions maps "namespace/deployment/revision" to the creation time of
+	// the ReplicaSet backing that revision - the cluster's own record of when
+	// each rollout started, so times survive watcher restarts.
+	revisions map[string]int64
+	enabled   bool
+	err       string
 }
 
 // NewFromEnv enables observation in-cluster, or with KUBECONFIG locally. It is
@@ -50,7 +54,7 @@ func NewFromEnv(ctx context.Context) (*Watcher, error) {
 		return nil, fmt.Errorf("create kubernetes client: %w", err)
 	}
 
-	w := &Watcher{rollouts: make(map[string]Rollout), enabled: true}
+	w := &Watcher{rollouts: make(map[string]Rollout), revisions: make(map[string]int64), enabled: true}
 	namespace := os.Getenv("OTEL_KUBERNETES_NAMESPACE")
 	selector := os.Getenv("OTEL_KUBERNETES_LABEL_SELECTOR")
 	factory := informers.NewSharedInformerFactoryWithOptions(client, 30*time.Second,
@@ -69,9 +73,14 @@ func NewFromEnv(ctx context.Context) (*Watcher, error) {
 		AddFunc:    func(obj interface{}) { w.observe(obj) },
 		UpdateFunc: func(_, obj interface{}) { w.observe(obj) },
 	})
+	rsInformer := factory.Apps().V1().ReplicaSets().Informer()
+	_, _ = rsInformer.AddEventHandler(cache.ResourceEventHandlerFuncs{
+		AddFunc:    func(obj interface{}) { w.observeReplicaSet(obj) },
+		UpdateFunc: func(_, obj interface{}) { w.observeReplicaSet(obj) },
+	})
 	go func() {
 		factory.Start(ctx.Done())
-		if !cache.WaitForCacheSync(ctx.Done(), informer.HasSynced) {
+		if !cache.WaitForCacheSync(ctx.Done(), informer.HasSynced, rsInformer.HasSynced) {
 			w.setError("deployment informer did not sync")
 			return
 		}
@@ -107,19 +116,42 @@ func (w *Watcher) observe(obj interface{}) {
 	}
 	key := deployment.Namespace + "/" + deployment.Name + "/" + revision
 	phase, reason, message, completed := rolloutStatus(deployment)
-	started := now
-	for _, condition := range deployment.Status.Conditions {
-		if condition.Type == appsv1.DeploymentProgressing && !condition.LastUpdateTime.IsZero() {
-			started = condition.LastUpdateTime.UnixNano()
-		}
-		if condition.Type == appsv1.DeploymentAvailable && !condition.LastUpdateTime.IsZero() && completed {
-			completed = condition.LastUpdateTime.UnixNano() != 0
+
+	// StartedAt is when the rollout began. The ReplicaSet for this revision was
+	// created at that moment, so prefer the cluster's own timestamp; it is also
+	// correct for rollouts first observed long after they happened. Fall back
+	// to first-seen via the Progressing condition, then to this event.
+	started := w.revisionCreated(deployment.Namespace, deployment.Name, revision)
+	if started == 0 {
+		if old, exists := w.rollouts[key]; exists && old.StartedAt != 0 {
+			started = old.StartedAt
+		} else {
+			for _, condition := range deployment.Status.Conditions {
+				if condition.Type == appsv1.DeploymentProgressing && !condition.LastUpdateTime.IsZero() {
+					started = condition.LastUpdateTime.UnixNano()
+				}
+			}
+			if started == 0 {
+				started = now
+			}
 		}
 	}
-	if old, exists := w.rollouts[key]; exists {
-		started = old.StartedAt
-		if old.CompletedAt != 0 {
-			completed = true
+	// CompletedAt prefers the Progressing condition's own update time for a
+	// finished rollout, and once set is never re-bumped: a completed rollout
+	// stays completed at the moment it completed.
+	completedAt := int64(0)
+	if completed {
+		for _, condition := range deployment.Status.Conditions {
+			if condition.Type == appsv1.DeploymentProgressing && condition.Status == corev1.ConditionTrue && condition.Reason == "NewReplicaSetAvailable" {
+				completedAt = condition.LastUpdateTime.UnixNano()
+			}
+		}
+		if completedAt == 0 {
+			if old, exists := w.rollouts[key]; exists && old.CompletedAt != 0 {
+				completedAt = old.CompletedAt
+			} else {
+				completedAt = now
+			}
 		}
 	}
 	rollout := Rollout{
@@ -130,11 +162,15 @@ func (w *Watcher) observe(obj interface{}) {
 		Message: message, StartedAt: started, LastSeen: now, Generation: deployment.Generation,
 		DesiredReplicas: desiredReplicas(deployment), UpdatedReplicas: deployment.Status.UpdatedReplicas,
 		AvailableReplicas: deployment.Status.AvailableReplicas, ReadyReplicas: deployment.Status.ReadyReplicas,
-	}
-	if completed {
-		rollout.CompletedAt = now
+		CompletedAt: completedAt,
 	}
 	w.mu.Lock()
+	// The informer re-delivers every deployment on each resync (~30s). Only an
+	// observable change advances LastSeen, so a quiet rollout keeps its real
+	// last-changed time instead of looking perpetually fresh.
+	if old, exists := w.rollouts[key]; exists && !rolloutChanged(old, rollout) {
+		rollout.LastSeen = old.LastSeen
+	}
 	w.rollouts[key] = rollout
 	if len(w.rollouts) > maxRollouts {
 		w.evictOldestLocked()
@@ -142,12 +178,47 @@ func (w *Watcher) observe(obj interface{}) {
 	w.mu.Unlock()
 }
 
+func (w *Watcher) observeReplicaSet(obj interface{}) {
+	rs, ok := obj.(*appsv1.ReplicaSet)
+	if !ok {
+		return
+	}
+	revision := rs.Annotations["deployment.kubernetes.io/revision"]
+	owner := ""
+	for _, ref := range rs.OwnerReferences {
+		if ref.Kind == "Deployment" && ref.Name != "" {
+			owner = ref.Name
+		}
+	}
+	if revision == "" || owner == "" || rs.CreationTimestamp.IsZero() {
+		return
+	}
+	w.mu.Lock()
+	w.revisions[rs.Namespace+"/"+owner+"/"+revision] = rs.CreationTimestamp.UnixNano()
+	w.mu.Unlock()
+}
+
+func (w *Watcher) revisionCreated(namespace, workload, revision string) int64 {
+	w.mu.RLock()
+	defer w.mu.RUnlock()
+	return w.revisions[namespace+"/"+workload+"/"+revision]
+}
+
+// rolloutChanged reports whether anything observable about the rollout moved.
+func rolloutChanged(a, b Rollout) bool {
+	return a.Phase != b.Phase || a.Reason != b.Reason || a.Message != b.Message ||
+		a.Service != b.Service || a.Release != b.Release || a.Image != b.Image ||
+		a.Generation != b.Generation ||
+		a.DesiredReplicas != b.DesiredReplicas || a.UpdatedReplicas != b.UpdatedReplicas ||
+		a.AvailableReplicas != b.AvailableReplicas || a.ReadyReplicas != b.ReadyReplicas
+}
+
 func (w *Watcher) evictOldestLocked() {
 	var oldest string
 	var ts int64
 	for key, item := range w.rollouts {
-		if oldest == "" || item.LastSeen < ts {
-			oldest, ts = key, item.LastSeen
+		if oldest == "" || item.StartedAt < ts {
+			oldest, ts = key, item.StartedAt
 		}
 	}
 	if oldest != "" {
@@ -163,7 +234,12 @@ func (w *Watcher) List() []Rollout {
 	for _, item := range w.rollouts {
 		result = append(result, item)
 	}
-	sort.Slice(result, func(i, j int) bool { return result[i].LastSeen > result[j].LastSeen })
+	sort.Slice(result, func(i, j int) bool {
+		if result[i].StartedAt != result[j].StartedAt {
+			return result[i].StartedAt > result[j].StartedAt
+		}
+		return result[i].LastSeen > result[j].LastSeen
+	})
 	return result
 }
 func (w *Watcher) Get(id string) (Rollout, bool) {

internal/kubernetes/watcher_test.go

@@ -0,0 +1,182 @@
+package kubernetes
+
+import (
+	"testing"
+	"time"
+
+	appsv1 "k8s.io/api/apps/v1"
+	corev1 "k8s.io/api/core/v1"
+	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
+	"k8s.io/apimachinery/pkg/apis/meta/v1/unstructured"
+	"k8s.io/apimachinery/pkg/runtime"
+)
+
+// conditionTime is the cluster's own stamp for "this rollout completed",
+// pinned so assertions can compare nanoseconds exactly.
+var conditionTime = metav1.NewTime(time.Unix(1700000000, 0))
+
+func testDeployment(overrides func(*appsv1.Deployment)) *appsv1.Deployment {
+	created := metav1.NewTime(time.Now().Add(-2 * time.Hour))
+	deployReplicas := int32(3)
+	deployment := &appsv1.Deployment{
+		ObjectMeta: metav1.ObjectMeta{
+			Namespace:         "shop",
+			Name:              "checkout",
+			Generation:        3,
+			CreationTimestamp: created,
+			Annotations: map[string]string{
+				"deployment.kubernetes.io/revision": "7",
+			},
+		},
+		Spec: appsv1.DeploymentSpec{Replicas: &deployReplicas},
+		Status: appsv1.DeploymentStatus{
+			Replicas:          3,
+			UpdatedReplicas:   3,
+			AvailableReplicas: 3,
+			ReadyReplicas:     3,
+			Conditions: []appsv1.DeploymentCondition{
+				{
+					Type:               appsv1.DeploymentProgressing,
+					Status:             corev1.ConditionTrue,
+					Reason:             "NewReplicaSetAvailable",
+					Message:            "ReplicaSet \"checkout-abc\" has successfully progressed.",
+					LastUpdateTime:     conditionTime,
+					LastTransitionTime: conditionTime,
+				},
+				{
+					Type:               appsv1.DeploymentAvailable,
+					Status:             corev1.ConditionTrue,
+					LastUpdateTime:     conditionTime,
+					LastTransitionTime: conditionTime,
+				},
+			},
+		},
+	}
+	if overrides != nil {
+		overrides(deployment)
+	}
+	return deployment
+}
+
+func observeDeployment(w *Watcher, deployment *appsv1.Deployment) {
+	w.observe(deployment)
+}
+
+func TestObserveCompletedRolloutKeepsTimesAcrossResync(t *testing.T) {
+	w := &Watcher{rollouts: make(map[string]Rollout), revisions: make(map[string]int64)}
+
+	observeDeployment(w, testDeployment(nil))
+	first, ok := w.rollouts["shop/checkout/7"]
+	if !ok {
+		t.Fatal("rollout not recorded")
+	}
+	if first.Phase != "completed" {
+		t.Fatalf("phase = %q, want completed", first.Phase)
+	}
+	if first.CompletedAt == 0 {
+		t.Fatal("completed rollout missing CompletedAt")
+	}
+	// The Progressing condition's update time is the cluster's completion stamp,
+	// not "now".
+	if first.CompletedAt != conditionTime.UnixNano() {
+		t.Fatalf("CompletedAt = %d, want the condition time %d", first.CompletedAt, conditionTime.UnixNano())
+	}
+
+	// A resync ~30s later re-delivers the same deployment. A quiet rollout must
+	// keep its times instead of looking perpetually fresh.
+	time.Sleep(2 * time.Millisecond)
+	observeDeployment(w, testDeployment(nil))
+	second := w.rollouts["shop/checkout/7"]
+	if second.LastSeen != first.LastSeen {
+		t.Fatalf("LastSeen advanced from %d to %d on an unchanged resync", first.LastSeen, second.LastSeen)
+	}
+	if second.CompletedAt != first.CompletedAt {
+		t.Fatalf("CompletedAt re-bumped from %d to %d on an unchanged resync", first.CompletedAt, second.CompletedAt)
+	}
+
+	// Any observable change does advance LastSeen.
+	changed := testDeployment(func(d *appsv1.Deployment) {
+		d.Status.ReadyReplicas = 2
+	})
+	observeDeployment(w, changed)
+	third := w.rollouts["shop/checkout/7"]
+	if third.LastSeen == first.LastSeen {
+		t.Fatal("LastSeen did not advance after an observable change")
+	}
+}
+
+func TestObserveStartedAtPrefersReplicaSetCreation(t *testing.T) {
+	w := &Watcher{rollouts: make(map[string]Rollout), revisions: make(map[string]int64)}
+	rolloutStart := time.Now().Add(-48 * time.Hour)
+	w.observeReplicaSet(&appsv1.ReplicaSet{
+		ObjectMeta: metav1.ObjectMeta{
+			Namespace:         "shop",
+			Name:              "checkout-abc",
+			CreationTimestamp: metav1.NewTime(rolloutStart),
+			OwnerReferences:   []metav1.OwnerReference{{Kind: "Deployment", Name: "checkout"}},
+			Annotations:       map[string]string{"deployment.kubernetes.io/revision": "7"},
+		},
+	})
+
+	observeDeployment(w, testDeployment(nil))
+	rollout := w.rollouts["shop/checkout/7"]
+	if rollout.StartedAt != rolloutStart.UnixNano() {
+		t.Fatalf("StartedAt = %d, want ReplicaSet creation %d", rollout.StartedAt, rolloutStart.UnixNano())
+	}
+}
+
+func TestObserveFirstSeenBeforeReplicaSetInformerRecovers(t *testing.T) {
+	w := &Watcher{rollouts: make(map[string]Rollout), revisions: make(map[string]int64)}
+	// Deployment events can arrive before the ReplicaSet cache has synced; the
+	// recorded start must be corrected once the ReplicaSet timestamp appears.
+	observeDeployment(w, testDeployment(nil))
+	stale := w.rollouts["shop/checkout/7"]
+
+	rolloutStart := time.Now().Add(-24 * time.Hour)
+	w.observeReplicaSet(&appsv1.ReplicaSet{
+		ObjectMeta: metav1.ObjectMeta{
+			Namespace:         "shop",
+			Name:              "checkout-abc",
+			CreationTimestamp: metav1.NewTime(rolloutStart),
+			OwnerReferences:   []metav1.OwnerReference{{Kind: "Deployment", Name: "checkout"}},
+			Annotations:       map[string]string{"deployment.kubernetes.io/revision": "7"},
+		},
+	})
+	observeDeployment(w, testDeployment(nil))
+	rollout := w.rollouts["shop/checkout/7"]
+	if rollout.StartedAt != rolloutStart.UnixNano() {
+		t.Fatalf("StartedAt = %d, want corrected ReplicaSet creation %d", rollout.StartedAt, rolloutStart.UnixNano())
+	}
+	if stale.StartedAt == 0 {
+		t.Fatal("first observation should still record a fallback start")
+	}
+}
+
+func TestListSortsNewestRolloutFirst(t *testing.T) {
+	w := &Watcher{rollouts: make(map[string]Rollout), revisions: make(map[string]int64)}
+	old := testDeployment(nil)
+	old.Annotations["deployment.kubernetes.io/revision"] = "6"
+	old.CreationTimestamp = metav1.NewTime(time.Now().Add(-72 * time.Hour))
+	recent := testDeployment(nil)
+
+	observeDeployment(w, old)
+	observeDeployment(w, recent)
+
+	list := w.List()
+	if len(list) != 2 {
+		t.Fatalf("len(List) = %d, want 2", len(list))
+	}
+	if list[0].Revision != "7" || list[1].Revision != "6" {
+		t.Fatalf("List order = [%s, %s], want newest rollout first", list[0].Revision, list[1].Revision)
+	}
+}
+
+// Deletions and tombstones must not panic the handlers.
+func TestObserveIgnoresNonDeploymentObjects(t *testing.T) {
+	w := &Watcher{rollouts: make(map[string]Rollout), revisions: make(map[string]int64)}
+	w.observe(&unstructured.Unstructured{})
+	w.observeReplicaSet(runtime.Object(&unstructured.Unstructured{}))
+	if len(w.List()) != 0 {
+		t.Fatal("no rollouts should be recorded")
+	}
+}