Skip to content

fix: don't fabricate time_to_ready_ms when rediscovering an already-ready container#500

Merged
dray92 merged 1 commit into
mainfrom
fix/startup-lifecycle-stale-ready-observation
Jul 11, 2026
Merged

fix: don't fabricate time_to_ready_ms when rediscovering an already-ready container#500
dray92 merged 1 commit into
mainfrom
fix/startup-lifecycle-stale-ready-observation

Conversation

@dray92

@dray92 dray92 commented Jul 11, 2026

Copy link
Copy Markdown
Contributor

Why

Fixes the root cause investigated in devzero-inc/services#8891: container_startup_lifecycles rows in ClickHouse showed implausibly large time_to_ready_ms values (up to 58+ hours) for long-lived, stable pods, while time_to_running_ms for the same containers stayed correct. This corrupted avgTimeToReadyMs aggregates consumed by both the existing ContainerHealthService/GetWorkloadHealthSummaries frontend RPC and the new startup-timing fields streamed to the tunr WorkloadProfile CRD (devzero-inc/services#8886).

Root cause

trackStartupLifecycle creates a fresh tracker entry whenever it observes a (podUID, containerName, restartCount) key with no live entry, seeding pendingAt from the pod's PodScheduled condition — which can be days old for a long-lived pod. If the container is already Running and Ready in that same observation (no genuine watched transition through Pending -> ContainerCreating -> Running -> Ready), the code computed time_to_ready_ms = now.Sub(pendingAt) and emitted immediately, then deleted the entry. This guarantees the next unrelated status update for the same stable pod (a routine kubelet condition/heartbeat refresh, not necessarily a collector restart) repeats the exact cycle — recreating the entry, immediately matching Ready again, and computing an even larger, wrong duration each time.

Confirmed against live preprod ClickHouse data: of rows in the last 7 days, 10,953 had an implausible time_to_ready_ms (>10 min) — 100% of them also had container_creating_at IS NULL (never observed the ContainerCreating transition), and zero rows with container_creating_at populated showed the anomaly. That's the exact signature of this bug.

Fix

When creating a new tracker entry, skip it entirely if the container is already Running and Ready at first observation — there is no reliable data available to compute a real duration in that case. That container's genuine startup was either already captured correctly by snapshotStartupLifecycles (which uses real historical condition timestamps, not now(), specifically for containers observed as already-running during the initial informer cache sync), or was already correctly reported by an earlier real transition and this is a stale rediscovery.

Test plan

  • New test TestTrackStartupLifecycle_DoesNotFabricateReadyDurationForStaleRediscovery reproduces the bug against the pre-fix code (confirmed: produced time_to_ready_ms=172800000 — exactly 48h — for a pod scheduled 48h earlier) and passes against the fix (no event emitted, no tracker entry left behind).
  • New control test TestTrackStartupLifecycle_EmitsCorrectDurationForGenuineFreshStartup proves a genuine Pending -> ContainerCreating -> Running -> Ready transition (the normal, working path) still correctly emits a small, real duration — this fix doesn't affect legitimate fresh startups.
  • go build ./..., go vet ./internal/collector/..., gofmt -l all clean.
  • go test ./internal/... passes (full suite, excluding test/e2e which requires a live kind cluster + cert-manager/prometheus-operator not available in this environment — pre-existing, unrelated to this change).
  • golangci-lint not run locally (repeatedly OOM-killed in the sandbox this was developed in, even scoped to a single package) — please confirm it passes in CI.

…eady 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.
@gitar-bot

gitar-bot Bot commented Jul 11, 2026

Copy link
Copy Markdown
Code Review ✅ Approved

Prevents the fabrication of implausible time_to_ready_ms values for long-lived containers by skipping tracking when a container is already running and ready upon observation.

Was this helpful? React with 👍 / 👎 | Gitar

@dray92 dray92 merged commit 91bf516 into main Jul 11, 2026
23 checks passed
@dray92 dray92 deleted the fix/startup-lifecycle-stale-ready-observation branch July 11, 2026 15:34
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants