From 6297e3417f036b3b1383acbab8025b6c827cdd8d Mon Sep 17 00:00:00 2001 From: Debosmit Ray Date: Fri, 10 Jul 2026 17:10:51 -0700 Subject: [PATCH] fix: don't fabricate time_to_ready_ms when rediscovering an already-ready container trackStartupLifecycle created a fresh tracker entry whenever it observed a (podUID, containerName, restartCount) combination with no live entry, using the pod's original PodScheduled condition timestamp as pendingAt. If the container was ALREADY Running and Ready in that same observation (no genuine Pending->ContainerCreating->Running->Ready transition watched), the Ready branch computed time_to_ready_ms = now.Sub(pendingAt) and emitted immediately, then deleted the entry -- guaranteeing the next unrelated status update for the same stable pod would repeat the exact cycle, each time computing an even larger, wrong duration. This fires for any long-lived, already-Ready pod every time zxporter (re)starts, or a previously emitted entry gets rediscovered on a later, unrelated status update (e.g. a routine kubelet condition/heartbeat refresh) -- not just on collector restart. Confirmed against live preprod ClickHouse data: 10,953 of the affected rows (100% of the implausible time_to_ready_ms values, up to 58+ hours) all had container_creating_at IS NULL, i.e. never observed the ContainerCreating transition -- exactly the signature of this bug. See devzero-inc/services#8891 for full investigation. Fix: when creating a new tracker entry, skip it entirely if the container is already Running and Ready at first observation. That container's genuine startup was either already captured by snapshotStartupLifecycles (which correctly uses real historical condition timestamps, not now()) during the initial informer sync, or was already correctly reported by an earlier real transition and this is a stale rediscovery with no reliable data to report. Added pod_collector_test.go (new file for this package) with a failing test that reproduces the bug against the pre-fix code (confirmed: produced time_to_ready_ms=172800000 for a pod scheduled 48h earlier) and a control test proving genuine fresh Pending->ContainerCreating-> Running->Ready transitions still correctly emit a small, real duration. --- internal/collector/pod_collector.go | 19 +++ internal/collector/pod_collector_test.go | 165 +++++++++++++++++++++++ 2 files changed, 184 insertions(+) create mode 100644 internal/collector/pod_collector_test.go diff --git a/internal/collector/pod_collector.go b/internal/collector/pod_collector.go index 95605ab1..d26f7019 100644 --- a/internal/collector/pod_collector.go +++ b/internal/collector/pod_collector.go @@ -641,6 +641,25 @@ func (c *PodCollector) trackStartupLifecycle(_, newPod *corev1.Pod) { entry, exists := c.startupTracker[key] if !exists { + // If the container is already Running and Ready the first time we + // observe it (no live tracker entry), we have no reliable data for + // how long it actually took to start: either it existed before this + // collector started watching it (snapshotStartupLifecycles already + // handles that case once, using real historical condition + // timestamps, during the initial informer cache sync) or a + // previously tracked entry for this exact (pod, container, + // restartCount) was already emitted and deleted, and this is an + // unrelated, later status update re-discovering the same stable + // container. Creating a fresh entry here would immediately match + // the Ready branch below using now() as a stand-in for the real + // ready time, fabricating an ever-growing, wrong duration that + // gets worse the longer the container has actually been running. + // Skip it rather than report data we can't trust. + if newStatus.Ready && newStatus.State.Running != nil { + c.startupTrackerMu.Unlock() + continue + } + // New lifecycle entry — pod is in Pending or later phase workloadName, workloadKind := getWorkloadInfo(newPod) entry = &startupLifecycleEntry{ diff --git a/internal/collector/pod_collector_test.go b/internal/collector/pod_collector_test.go new file mode 100644 index 00000000..47ddc94e --- /dev/null +++ b/internal/collector/pod_collector_test.go @@ -0,0 +1,165 @@ +package collector + +import ( + "testing" + "time" + + "github.com/go-logr/logr" + "github.com/stretchr/testify/assert" + "github.com/stretchr/testify/require" + corev1 "k8s.io/api/core/v1" + metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" + "k8s.io/apimachinery/pkg/types" +) + +// newTestPodCollector builds a minimal PodCollector sufficient to exercise +// trackStartupLifecycle in isolation, without the full NewPodCollector +// dependency graph (client, batcher, resourceChan). +func newTestPodCollector() (*PodCollector, chan CollectedResource) { + batchChan := make(chan CollectedResource, 10) + return &PodCollector{ + batchChan: batchChan, + logger: logr.Discard(), + startupTracker: make(map[startupLifecycleKey]*startupLifecycleEntry), + }, batchChan +} + +// alreadyReadyLongLivedPod builds a pod whose PodScheduled condition and +// container Running state both point far in the past (2 days), with +// Ready already true — simulating a stable, long-running pod being +// (re)discovered by trackStartupLifecycle with no live tracker entry, e.g. +// after the prior entry for this (pod, container, restartCount) key was +// already emitted-and-deleted, and a later, unrelated pod status update +// (kubelet heartbeat, condition timestamp refresh, etc.) triggers another +// UpdateFunc callback. +func alreadyReadyLongLivedPod(scheduledAt, startedAt time.Time) *corev1.Pod { + return &corev1.Pod{ + ObjectMeta: metav1.ObjectMeta{ + UID: types.UID("pod-uid-1"), + Name: "cnpg-controller-manager-abc123", + Namespace: "cnpg-system", + }, + Status: corev1.PodStatus{ + Conditions: []corev1.PodCondition{ + { + Type: corev1.PodScheduled, + Status: corev1.ConditionTrue, + LastTransitionTime: metav1.NewTime(scheduledAt), + }, + }, + ContainerStatuses: []corev1.ContainerStatus{ + { + Name: "app", + Ready: true, + RestartCount: 0, + State: corev1.ContainerState{ + Running: &corev1.ContainerStateRunning{ + StartedAt: metav1.NewTime(startedAt), + }, + }, + }, + }, + }, + } +} + +// TestTrackStartupLifecycle_DoesNotFabricateReadyDurationForStaleRediscovery +// reproduces the bug behind services#8891: a container observed for the +// first time by trackStartupLifecycle (no live tracker entry) that is +// ALREADY Running and Ready has no reliable "time to ready" data available — +// the only timestamps on hand are the pod's original PodScheduled time +// (days old) and time.Now() (this callback's wall-clock time), and computing +// now.Sub(pendingAt) fabricates an ever-growing, wrong duration on every +// re-observation instead of reporting the real (short) startup time. +// +// No lifecycle event should be emitted in this case — the container's +// genuine startup was either already captured by snapshotStartupLifecycles +// during the initial informer sync, or was already correctly reported by an +// earlier, real transition observation and this is a stale re-discovery. +func TestTrackStartupLifecycle_DoesNotFabricateReadyDurationForStaleRediscovery(t *testing.T) { + c, batchChan := newTestPodCollector() + + scheduledAt := time.Now().Add(-48 * time.Hour) + startedAt := scheduledAt.Add(3 * time.Second) + pod := alreadyReadyLongLivedPod(scheduledAt, startedAt) + + c.trackStartupLifecycle(nil, pod) + + select { + case ev := <-batchChan: + t.Fatalf("expected no lifecycle event to be emitted for a stale rediscovery, got: %+v", ev) + default: + // No event emitted — correct. + } + + assert.Empty(t, c.startupTracker, "no tracker entry should be left behind for a stale rediscovery") +} + +// TestTrackStartupLifecycle_EmitsCorrectDurationForGenuineFreshStartup is the +// control case: a container genuinely observed transitioning through +// Pending -> ContainerCreating -> Running -> Ready across separate calls +// (the normal, working path) must still emit a correct, small duration. +func TestTrackStartupLifecycle_EmitsCorrectDurationForGenuineFreshStartup(t *testing.T) { + c, batchChan := newTestPodCollector() + + scheduledAt := time.Now().Add(-5 * time.Second) + pod := &corev1.Pod{ + ObjectMeta: metav1.ObjectMeta{ + UID: types.UID("pod-uid-2"), + Name: "fresh-pod-abc123", + Namespace: "default", + }, + Status: corev1.PodStatus{ + Conditions: []corev1.PodCondition{ + { + Type: corev1.PodScheduled, + Status: corev1.ConditionTrue, + LastTransitionTime: metav1.NewTime(scheduledAt), + }, + }, + ContainerStatuses: []corev1.ContainerStatus{ + { + Name: "app", + Ready: false, + RestartCount: 0, + State: corev1.ContainerState{ + Waiting: &corev1.ContainerStateWaiting{Reason: "ContainerCreating"}, + }, + }, + }, + }, + } + + // Step 1: observe the container while it's still ContainerCreating. + c.trackStartupLifecycle(nil, pod) + require.Len(t, c.startupTracker, 1, "entry should be tracked after observing ContainerCreating") + + select { + case ev := <-batchChan: + t.Fatalf("expected no lifecycle event yet (container not Ready), got: %+v", ev) + default: + } + + // Step 2: container transitions to Running and Ready. + runningAt := scheduledAt.Add(2 * time.Second) + pod.Status.ContainerStatuses[0].Ready = true + pod.Status.ContainerStatuses[0].State = corev1.ContainerState{ + Running: &corev1.ContainerStateRunning{StartedAt: metav1.NewTime(runningAt)}, + } + c.trackStartupLifecycle(nil, pod) + + assert.Empty(t, c.startupTracker, "entry should be cleaned up after a successful emission") + + select { + case ev := <-batchChan: + payload, ok := ev.Object.(map[string]interface{}) + require.True(t, ok, "expected event payload to be a map[string]interface{}") + timeToReadyMs, ok := payload["time_to_ready_ms"].(int64) + require.True(t, ok, "expected time_to_ready_ms to be present as int64") + // Ready ~2s after scheduling; must be small and sane, not fabricated. + assert.Less(t, timeToReadyMs, int64(10_000), "genuine fresh startup must report a small, real duration") + assert.GreaterOrEqual(t, timeToReadyMs, int64(0)) + default: + t.Fatal("expected a lifecycle event to be emitted for a genuine fresh startup") + } +}