## 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.Reviewed-on: #157
This commit was merged in pull request #157.
This commit is contained in:
@@ -67,6 +67,14 @@ itself, so no in-image healthcheck tool is required.
|
||||
- Three more images built each CI run (kept small; not on the health-gate list).
|
||||
- Storage is ephemeral container fs — a demo backplane, not a retention target.
|
||||
Object storage for Tempo / remote-write for Prometheus is a later concern.
|
||||
- Tempo runs **single-binary**, so its distributor and ingester are one process and
|
||||
some of its distributed-mode machinery is not just redundant but harmful. Its
|
||||
ingester-pool health check is disabled (`ingester_client.pool_config`) because with
|
||||
a single in-process ingester the check can never route around a failure — a 1s
|
||||
loopback-gRPC deadline missed under CI load only evicted the one ingester and made
|
||||
Tempo drop spans, which is how `verify-tracing` flaked (#156). Expect the same
|
||||
shape from other distributed-mode knobs if we tune them; the fix is to switch to
|
||||
real multi-ingester Tempo, not to re-enable them here.
|
||||
|
||||
## Coupling rules touched (CLAUDE.md §8)
|
||||
|
||||
|
||||
@@ -25,3 +25,15 @@ storage:
|
||||
path: /var/tempo/blocks
|
||||
wal:
|
||||
path: /var/tempo/wal
|
||||
|
||||
# #156: don't let the distributor evict its own ingester. Tempo runs single-binary here, so the
|
||||
# distributor and the ingester are the same process and the "pool" holds exactly one, in-process,
|
||||
# member. dskit still health-checks it over loopback gRPC with a 1s deadline (checkinterval 15s);
|
||||
# on the shared CI runner a transient stall blows that deadline, the only ingester is dropped from
|
||||
# the pool ("removing distributor_pool failing healthcheck"), and every push then fails ("pusher
|
||||
# failed to consume trace data", err="context canceled") until the next check — silently losing
|
||||
# spans, which is how verify-tracing flaked. With one in-process ingester the check can never route
|
||||
# around a failure, so it can only ever discard data. Turn it off.
|
||||
ingester_client:
|
||||
pool_config:
|
||||
healthcheckenabled: false
|
||||
|
||||
@@ -59,6 +59,20 @@ def services_in_trace(trace_id):
|
||||
return names
|
||||
|
||||
|
||||
def tempo_ingest_state():
|
||||
"""#156: distinguish a broken trace chain from Tempo dropping spans. `ingester_clients` is 0
|
||||
when the distributor has evicted its (single, in-process) ingester over a failed loopback
|
||||
health check — pushes fail and spans are lost, which looks identical to missing instrumentation
|
||||
from here. Diagnostics only; never fails the check."""
|
||||
try:
|
||||
for line in _get(f"{TEMPO}/metrics").decode().splitlines():
|
||||
if line.startswith("tempo_distributor_ingester_clients "):
|
||||
return f"tempo {line.strip()} (0 = no ingester in the pool — evicted, so pushes\n are failing and spans are being dropped; see #156)"
|
||||
except Exception as e:
|
||||
return f"tempo /metrics unreadable: {e}"
|
||||
return "tempo_distributor_ingester_clients not reported"
|
||||
|
||||
|
||||
def main():
|
||||
deadline = time.time() + TIMEOUT
|
||||
generate_traffic()
|
||||
@@ -74,6 +88,7 @@ def main():
|
||||
generate_traffic()
|
||||
print(f"FAIL — no single trace spanned {sorted(WANT)}; services seen: {sorted(seen)}",
|
||||
file=sys.stderr)
|
||||
print(f" {tempo_ingest_state()}", file=sys.stderr)
|
||||
return 1
|
||||
|
||||
|
||||
|
||||
Reference in New Issue
Block a user