fix(observability): stop single-binary Tempo evicting its only ingester (closes #156) #157

Merged
not merged 2 commits from fix/156-tempo-ingester-healthcheck into main 2026-09-01 08:31:37 +00:00
Contributor

What & why

verify-tracing flaked on verify-stack run 722 — FAIL — no single trace spanned ['bff', 'projection-api'] — and went green on a plain re-run of the same commit. The trace chain was not broken; Tempo could not ingest:

removing distributor_pool failing healthcheck addr=127.0.0.1:9095
  reason="rpc error: code = DeadlineExceeded"
pusher failed to consume trace data  err="context canceled"   (x18)

The root cause is the mechanism of the data loss, not whatever caused the stall. Tempo runs single-binary, so the distributor and the ingester are the same process and the distributor's ingester pool holds exactly one, in-process, member. dskit nevertheless health-checks that member over loopback gRPC with a 1 s deadline (checkinterval: 15s, confirmed from the running image's /status/config). On the shared runner a transient stall blows the deadline, the only ingester is evicted from the pool, and every subsequent push fails until the next check interval — spans silently dropped.

With one in-process ingester the health check can never route around a failure. Its only possible effect is to discard data. So it is off:

ingester_client:
  pool_config:
    healthcheckenabled: false

This lands at the point where both candidate triggers named in #156 (GC pressure near mem_limit, CPU contention from the grown stack) turn into lost spans, so mem_limit: 400m is untouched — raising it on a memory-tight runner risks reintroducing the verify-e2e OOM of #144. It also does not paper over anything the way a longer TRACING_TIMEOUT would (#156's own note).

Second change: infra/tracing-check.py prints tempo_distributor_ingester_clients on its failure path. From the check's side, Tempo-dropped-spans and missing instrumentation look identical — that ambiguity is what cost a container-log dive on run 722. A recurrence now names itself.

Closes #156

Definition of Done

  • Linked Gitea issue (#156).
  • Failing test committed before the implementation — N/A, and deliberately so. The trigger is runner load, so no deterministic red exists; the "red" is run 722's observed verify-tracing failure plus its Tempo logs. Same precedent as d5e5fa2 (#115, Playwright OOM) and 4aafd32 (#147, uWSGI caps). A test asserting the config says what the config says would add no gate: Tempo hard-fails on an unknown key (verified — field health_check_enabled not found in type client.PoolConfig), so a typo or a config rename on a Tempo bump already turns verify-up red.
  • Conventional Commits referencing the issue (refs #156).
  • CI green — the point of the change.
  • docker compose up health unaffected (Tempo is not in WAIT_SVCS; config-only change, same image).
  • Docs updated — ADR-0023 Consequences.
  • ADR — amended ADR-0023 rather than adding a new one: this is a consequence of that ADR's single-binary Tempo choice, not a new decision (one decision per ADR, §12).
  • Demo note — N/A, not user-visible.

Notes for reviewers

Verified locally against the built image (the flake itself is not locally reproducible — see the runner-load point above):

  1. docker run --rm register-referentie/tempo:dev -config.file=/etc/tempo.yaml -config.verify=true → parses.
  2. GET /status/config on the running container → healthcheckenabled: false (was true).
  3. The new diagnostic reads tempo_distributor_ingester_clients off a live Tempo.

Worth knowing: that metric is legitimately 0 on an idle Tempo — the pool is populated lazily on first push. It only prints on the failure path of a check that has already generated traffic, so the reading is meaningful there, but don't read a bare 0 on a quiet stack as an eviction.

Follow-up left undone: if verify-tracing still flakes after this, the next suspect is the .NET OTLP exporter timeout (#156's last note), not Tempo's memory cap.

## What & why `verify-tracing` flaked on `verify-stack` run 722 — `FAIL — no single trace spanned ['bff', 'projection-api']` — and went green on a plain re-run of the same commit. **The trace chain was not broken; Tempo could not ingest:** ``` removing distributor_pool failing healthcheck addr=127.0.0.1:9095 reason="rpc error: code = DeadlineExceeded" pusher failed to consume trace data err="context canceled" (x18) ``` The root cause is the *mechanism* of the data loss, not whatever caused the stall. Tempo runs **single-binary**, so the distributor and the ingester are the same process and the distributor's ingester pool holds exactly one, in-process, member. dskit nevertheless health-checks that member over loopback gRPC with a **1 s** deadline (`checkinterval: 15s`, confirmed from the running image's `/status/config`). On the shared runner a transient stall blows the deadline, the only ingester is evicted from the pool, and every subsequent push fails until the next check interval — spans silently dropped. With one in-process ingester the health check can **never** route around a failure. Its only possible effect is to discard data. So it is off: ```yaml ingester_client: pool_config: healthcheckenabled: false ``` This lands at the point where *both* candidate triggers named in #156 (GC pressure near `mem_limit`, CPU contention from the grown stack) turn into lost spans, so **`mem_limit: 400m` is untouched** — raising it on a memory-tight runner risks reintroducing the `verify-e2e` OOM of #144. It also does not paper over anything the way a longer `TRACING_TIMEOUT` would (#156's own note). Second change: `infra/tracing-check.py` prints `tempo_distributor_ingester_clients` on its failure path. From the check's side, Tempo-dropped-spans and missing instrumentation look identical — that ambiguity is what cost a container-log dive on run 722. A recurrence now names itself. Closes #156 ## Definition of Done - [x] Linked Gitea issue (#156). - [ ] **Failing test committed before the implementation — N/A, and deliberately so.** The trigger is runner load, so no deterministic red exists; the "red" is run 722's observed `verify-tracing` failure plus its Tempo logs. Same precedent as d5e5fa2 (#115, Playwright OOM) and 4aafd32 (#147, uWSGI caps). A test asserting the config says what the config says would add no gate: Tempo hard-fails on an unknown key (verified — `field health_check_enabled not found in type client.PoolConfig`), so a typo or a config rename on a Tempo bump already turns `verify-up` red. - [x] Conventional Commits referencing the issue (`refs #156`). - [ ] CI green — the point of the change. - [x] `docker compose up` health unaffected (Tempo is not in `WAIT_SVCS`; config-only change, same image). - [x] Docs updated — ADR-0023 Consequences. - [x] ADR — amended **ADR-0023** rather than adding a new one: this is a consequence of that ADR's single-binary Tempo choice, not a new decision (one decision per ADR, §12). - [x] Demo note — N/A, not user-visible. ## Notes for reviewers Verified locally against the built image (the flake itself is not locally reproducible — see the runner-load point above): 1. `docker run --rm register-referentie/tempo:dev -config.file=/etc/tempo.yaml -config.verify=true` → parses. 2. `GET /status/config` on the running container → `healthcheckenabled: false` (was `true`). 3. The new diagnostic reads `tempo_distributor_ingester_clients` off a live Tempo. Worth knowing: that metric is legitimately `0` on an idle Tempo — the pool is populated lazily on first push. It only prints on the failure path of a check that has already generated traffic, so the reading is meaningful there, but don't read a bare `0` on a quiet stack as an eviction. Follow-up left undone: if `verify-tracing` still flakes after this, the next suspect is the .NET OTLP exporter timeout (#156's last note), not Tempo's memory cap.
not added 2 commits 2026-09-01 07:46:23 +00:00
`verify-tracing` flaked on run 722: `FAIL — no single trace spanned ['bff',
'projection-api']`, green on a plain re-run of the same commit. Not a broken trace
chain — Tempo could not ingest:

    removing distributor_pool failing healthcheck addr=127.0.0.1:9095
      reason="rpc error: code = DeadlineExceeded"
    pusher failed to consume trace data  err="context canceled"   (x18)

Root cause is the mechanism of the data loss, not whatever caused the stall. Tempo
runs single-binary, so distributor and ingester are the *same process* and the
distributor's ingester pool holds exactly one, in-process, member. dskit still
health-checks it over loopback gRPC with a 1s deadline; on the shared runner a
transient stall blows that, the only ingester is dropped from the pool, and every
push fails until the next 15s check interval — spans silently lost. With one
in-process ingester the check can never route around a failure, so it can only ever
discard data.

Fix: `ingester_client.pool_config.healthcheckenabled: false`. This addresses both
candidate triggers (GC pressure near `mem_limit`, CPU contention) at the point where
they turn into lost data, so `mem_limit: 400m` stays untouched — raising it would
risk reintroducing the verify-e2e OOM of #144 on a memory-tight runner.

Also print `tempo_distributor_ingester_clients` on the check's failure path: a
recurrence then names Tempo-dropped-spans instead of costing another container-log
dive, since from the check's side that is indistinguishable from missing
instrumentation.

Verified against the built image: config parses (`-config.verify`), the effective
`/status/config` reports `healthcheckenabled: false`, and the diagnostic reads the
metric off a live Tempo.
docs(architecture): record why single-binary Tempo has its ingester health check off (refs #156)
CI / lint (pull_request) Successful in 1m41s
CI / build (pull_request) Successful in 1m8s
CI / unit (pull_request) Successful in 1m23s
CI / frontend (pull_request) Successful in 3m21s
CI / mutation (pull_request) Successful in 6m32s
CI / verify-stack (pull_request) Successful in 9m31s
60d556b46e
not added the type:bugarea:infra labels 2026-09-01 07:46:35 +00:00
not merged commit 94720f0fcb into main 2026-09-01 08:31:37 +00:00
Sign in to join this conversation.