Repository navigation
feat: truth under load — coalescing links, grace, ESI, restarts, pipe (tracing P3) - #111
Conversation
11 tasks, fixture-truth-first: upgraded recording rig with a traffic-shaping backend records coalescing/grace/esi/restart/retry/ pipe/synth VSL truth into NOTES.md; recursive span building, pipe and synth handling, split skip counters, a fetch-identity linker with coalescing detection, links and timings through export/sink/probe, generator ESI gate, full-suite E2E for coalescing/grace/honest timing and ESI, spec sync, verification battery. Assisted-by: Claude Fable 5
…retry, pipe, synth Recording rig v3 (record-fixtures-truth.sh + truthbackend.py) drives varnish:8.0.2 through a traffic-shaping backend to capture seven VSL truth fixtures under load: coalescing, grace/bgfetch, ESI, restart, retry, pipe, and synth. NOTES.md catalogs every observed shape (Link reasons and vxids, Hit payload variants, nesting depths, Timestamp label sets, minted BereqHeader traceparent values) that later P3 tasks reconcile their code against. STOP-gate hit and resolved: esi.txt initially produced no /frag subrequest (ESI_xmlerror: first char not '<'); fixed per the brief's named off-ramp by starting varnishd with -p feature=+esi_disable_xml_check. Documented for Task 7 to mirror into the generator. Assisted-by: Claude Fable 5
Review found the synth.txt quoted block showed VCL_call SYNTH before RespStatus/RespReason, but synth.txt's real order (lines 16-27) is RespStatus -> RespReason -> three RespHeader lines -> VCL_call SYNTH. Reordered the block to match true file order; re-verified against synth.txt directly. No fixture bytes changed. Assisted-by: Claude Fable 5
Adds Tx.Last(tag), the counterpart to First: it walks Records from the end and returns the payload of the last record with the given tag, for tags VCL logs more than once as it mutates a value within one transaction (e.g. one "TTL" record per beresp.ttl/beresp.grace mutation). The test is written against fixture truth, not the P3 plan's original sketch. Task 1's NOTES.md found restart.txt's restarted delivery does not rewrite RespStatus within a single Tx — it hits its own newly cached 418 in a *separate* top-level Request group, linked only via "Link req 4 restart", still 418 not 200. What that fixture's BeReq group genuinely carries within one Tx is three same-tag TTL records (RFC-computed, then two VCL mutations), which is what the test exercises. Assisted-by: Claude Fable 5
Build() now walks the whole descendant tree instead of only direct BeReq children of a Request: retry attempts nest under the failed attempt's fetch span (NOTES.md's retry.txt — retried bereq sits at one level deeper than the first attempt, not a sibling), ESI subrequests become recursive child request spans (SpanKindServer, varnish.esi=true), and every descendant emits under the top span's one trace id, flagging varnish.minted_trace_mismatch=true when a bereq's own minted trace id differs (true for ESI fragments and bgfetch, since Varnish never propagates req.http.traceparent into either). Request/fetch statuses now read vsl.Last instead of First. Per controller ruling, restart stitching stays out of this task: restart.txt's restarted request is a separate top-level Tx, not a Child, so Build only derives varnish.restarts from the originating Tx's own "Link req <vxid> restart" records — cross-tx parenting is left for the Linker task. Build also had to learn a Request Tx can close on a "Restart" timestamp instead of "Resp" (a restarted Tx never reaches vcl_deliver's Resp), or it silently produced no span at all for the originating request. All P1/P2 fixtures and tests pass unchanged; whole-repo make test and make lint are clean. Assisted-by: Claude Fable 5
Task 4 of the P3 truth plan. Pipe and synth transactions now build a usable request span: - handling() gains a "PIPE" VCL_call case (pipe.txt's client group: VCL_call RECV, HASH, PIPE, no MISS/HIT/PASS/SYNTH), and requestAttrs sets varnish.pipe=true / varnish.synthetic=true alongside the existing varnish.handling attribute. No code change was needed to suppress a fetch span for pipe: the piped bereq never reaches vcl_backend_fetch (NOTES.md: no minted BereqHeader traceparent, no BerespBody/Beresp timestamp), so buildChildren's existing fs/fe guard already skips it. - respEnd() gains a PipeSess fallback after Resp/Restart, since a piped Request tx's Timestamp label set is Start/Req/Process/Pipe/PipeSess only — no Resp, per NOTES.md's pipe.txt section. Build now exposes why it produced nothing via a new BuildWithOutcome(tx, ids) ([]Span, Outcome), so cmd/tracer can tell an intentionally-dropped unsampled trace apart from a genuinely truncated/unusable group instead of lumping both into vinyl_tracer_groups_unusable_total. Build is kept as a thin wrapper (built, _ := BuildWithOutcome(...)) so every existing caller and test is untouched. cmd/tracer/main.go's handle closure now switches on Outcome; supervise.go gets the new vinyl_tracer_groups_unsampled_total counter and groupsUnusable's Help text is reworded to mean genuinely-unusable only. TDD: RED (compile failure on the new BuildWithOutcome/Outcome API, per `go test ./internal/tracer/spans/...`) before implementation, GREEN after. Full internal/tracer/... + cmd/tracer/... and whole-repo `make test` green; `make lint` clean. Assisted-by: Claude Fable 5
Adds spans.Linker: a stateful, single-goroutine wrapper over BuildWithOutcome that resolves cross-transaction correlation a single vsl.Tx cannot see on its own. - Hit-to-fetch links: every HIT request span links to the fetch span that created its object (matched via the Hit record's vxid field against a bounded, TTL-expiring cache of fetch identities), tagged varnish.coalesced=true when the hit's Start precedes the cached fetch's end (the request overlapped the still-in-flight fetch). Confirmed against the real coalesce.txt bytes that the fetch group prints before the waiter's, so no pending-hits buffer is needed. - Restart continuation stitching: a restarted request (a separate top-level Tx, symmetrically correlated via the original's own "Link req <vxid> restart" record and the continuation's matching Tx.VXID) is reparented under the original request span and into its trace, tagged varnish.restart_continuation=true. - Both degrade honestly on a cache miss (varnish.coalesced_unlinked or a plain self-root) plus the new vinyl_tracer_link_cache_misses_total counter, wired via linker.OnCacheMiss from cmd/tracer. cmd/tracer's handle closure now calls linker.Build instead of spans.BuildWithOutcome directly; the Outcome switch is unchanged. Assisted-by: Claude Fable 5
Review follow-up on the Linker (Task 5): - NOTES.md's coalesce.txt group-header excerpt had the two vxid labels swapped (claimed the waiter/32770 prints first, initiator/2 second). The raw fixture bytes say the opposite — line 1 is Request 2 (the initiator, Link bereq 3 fetch at line 23), line 84 is Request 32770 (the waiter, Hit at line 104) — matching every other quote in that section once correctly attributed. Swapped the labels to match the file; no fixture bytes touched. - isRestartContinuation now checks Begin's reason field positionally (strings.Fields, third field == "restart") instead of a bare strings.Contains, avoiding a false positive on some future reason string that merely contains "restart" as a substring. Factored the "restart" reason literal into a shared restartReason constant alongside txTypeRequest (goconst: three call sites now share it). - Documented on vxidCache why a re-set of an already-cached vxid (the one case where insertion- vs access-order would matter) is not a realistic concern: Varnish vxids are minted monotonically per transaction for a varnishd process's lifetime. Assisted-by: Claude Fable 5
…ions Task 6 of the P3 plan: wires spans.Span.Links (Task 5) through the remaining layers so a Linker-attached link and a span's real VSL timestamps survive all the way to an E2E assertion. - export: roSpan.Links() maps spans.Span.Links to []sdktrace.Link (SpanContext from TraceID/SpanID + FlagsSampled, attributes passed through) instead of always returning nil. - sink: SpanSummary gains Links []LinkSummary and StartUnixNano/EndUnixNano int64, filled from a received span's GetLinks()/GetStartTimeUnixNano()/GetEndTimeUnixNano(). - cmd/vinylprobe: -assert-spans gains -link-span-id (a matching span must carry a link with this exact span id) and -min-duration (span duration must be at least this long), both requiring -assert-spans. decideSpans grows the two matching filter params; every existing call site and test updated with neutral values so prior behavior is unchanged. TDD per layer: export test round-trips a linked span through the real Batcher/tracetest.InMemoryExporter; sink test posts a real tracepb.Span_Link; cmd tests cover link match/mismatch and duration pass/fail plus the new validate() requirements. go test ./... green, go test -race on the touched packages green, gofmt/go vet clean, bash hack/check-e2e-boundary.sh OK, make lint 0 issues. Assisted-by: Claude Fable 5
… enabled Implements Task 7 of the vinyl-tracer P3 plan: adds ESI processing gate to vcl_backend_response that honors the feature flag. When VarnishParams includes "feature +esi", the generator now renders a block that checks Surrogate-Control header per W3C ESI 1.0 spec and conditionally enables do_esi processing. Per NOTES.md's "Rig deviation" section, operators must pair this VCL with varnishd's -p feature=+esi_disable_xml_check parameter to avoid silent degradation of ESI fragments to flat fetches when content starts with non-XML bytes. TDD: two new tests verify the block renders when enabled and is absent otherwise. All generator tests pass; lint clean. Assisted-by: Claude Fable 5
Task 8 of the P3 plan: a `suite: full` chainsaw test proving, against a real varnishd under real concurrent traffic, the three claims the unit/VSL layer could only prove from recorded fixtures — request coalescing (varnish.coalesced), grace/bgfetch (varnish.bgfetch), and honest fetch-span duration (-min-duration). Step 1 (mandatory traffic-shaping research, done before writing any yaml): the pinned ealen/echo-server:0.9.2 already supports both controls needed (echo_time query/header for delay, echo_header for arbitrary response headers incl. Cache-Control), confirmed from the upstream README and present since v0.4.0. No truth-backend fixture was added; e2e/fixtures/backends/echo-service.yaml is reused unmodified, shaped per-request via query strings. New e2e/fixtures/vinylcaches/truth.yaml (truth-cache) mirrors tracing.yaml under a distinct CR name to avoid colliding with e2e/tests/tracing's own resources. Validated: python3 yaml.safe_load on both new files, both hack/check-suite-labels.sh and hack/check-e2e-boundary.sh green, `chainsaw lint test` valid (matching the existing tracing test's own lint result). No local cluster run. Assisted-by: Claude Fable 5
…t sentence Review caught two issues in tracing-truth/chainsaw-test.yaml's description text: - The Step-1 decision claimed echo_header needed no feature-toggle and called ECHO__ENABLE__HEADER "unrelated". Re-checked the upstream echo-server README's Configuration table directly: its Condition column gates ?echo_header=/X-ECHO-HEADER behind "Enable header `true`" (ECHO__ENABLE__HEADER) — the same env var that also enables echoing request headers into the response body. It works in this suite only because echo-service.yaml already sets that env var to "true"; that setting is now load-bearing for two independent call sites (the tracing test's rewrite-proof step, and this suite's grace-bgfetch step), not one. echo_time's no-condition claim was already correct and is unchanged. - warm-up-traffic's budget sentence said "5 sleeps of 5s" for a 6-iteration retry loop that sleeps after every rc==2 attempt, including the 6th: worst case is 6 sleeps = 30s. Corrected; the already-merged tracing test's identical inherited sentence is intentionally left untouched (out of scope here). Text-only changes; no script/command content changed. Re-validated: python3 yaml.safe_load, hack/check-suite-labels.sh, hack/check-e2e-boundary.sh, chainsaw lint — all green. Assisted-by: Claude Fable 5
Task 9's E2E work (vinyl-tracer P3) discovered that any VinylCache CR
enabling ESI (varnishParameters["feature +esi"]) produced VCL that
fails to compile on real varnishd. main.vcl.tmpl emitted "import esi;"
whenever HasESI was true, but Varnish's ESI processing (beresp.do_esi,
set by Task 7's vcl_backend_response gate) is core functionality, not
a VMOD — varnish:8.0.2's bundled /usr/lib/varnish/vmods/ has no "esi"
entry. Confirmed against a real varnish:8.0.2 container both with a
hand-written repro and with this generator's own output for an
ESI+tracing-enabled CR: `varnishd -C -f` failed identically each time
("Could not find VMOD esi"), and compiled clean (exit 0, do_esi gate
intact) once the import was stripped.
The bug predates this branch (git blame: main.vcl.tmpl's HasESI-gated
import, generator.go's hasESI check, and the now-rewritten test all
trace to the initial commit) and went unnoticed because the only
covering unit test asserted a substring match on generated VCL text
rather than compiling it, and no envtest/E2E path had ever routed an
ESI-enabled CR through a real varnishd until Task 9 tried to.
- internal/generator/templates/main.vcl.tmpl: delete the 3-line
{{- if .HasESI }} import esi; {{- end }} guard. HasESI and Task 7's
do_esi gate in vcl_backend_response are untouched and now reachable.
- internal/generator/generator_test.go: rewrite
TestGenerate_ESI_ImportsEsiVmod into TestGenerate_ESI_NoVmodImport,
asserting "import esi" is absent even with feature +esi set, with a
comment naming the varnish-8-core-ESI truth and dated evidence.
VarnishParams→varnishd -p plumbing (a separate, pre-existing gap: no
CR key is forwarded to -p flags) remains out of scope here per the
coordinator's ruling — filed separately; E2E ESI itself stays deferred
out of P3.
go test ./internal/generator/... -v: all green, including both of
Task 7's do_esi tests. go build ./..., go test ./..., make lint: all
clean.
Assisted-by: Claude Fable 5
- Update Truth semantics table with attribute names as shipped: varnish.coalesced/coalesced_unlinked, restart_continuation, esi, retry, minted_trace_mismatch - Add Retries row (varnish.retry, varnish.minted_trace_mismatch) - Note ESI end-to-end deferral to issue #109 (varnishParameters not reaching varnishd -p; ESI span truth is unit-proven against fixtures) - Replace P1 plan stale Co-Authored-By trailer with Assisted-by: Claude Fable 5 Assisted-by: Claude Fable 5
… ordering race internal/tracer/spans/linker.go's resolveHit only sets varnish.coalesced=true when it resolves a Hit against a fetch span it had ALREADY cached from an earlier Build call. varnishlog -g request emits transaction groups by completion order, not causal order, so under real concurrent traffic there is no guarantee the initiator's fetch group is decoded before the waiter's Hit — if the waiter's group logs first, its Hit resolves against an empty cache and degrades to varnish.coalesced_unlinked=true instead (still correctly linked, just not the flag this test checks). Once resolveHit has run for that pair the outcome is final; no amount of polling recovers a flag that was missed at build time, so this was a latent flake independent of whether real coalescing occurred. Fix: wrap the traffic generation and the coalesced=true assert together in a bounded retry, up to 3 rounds, each against a FRESH path (/truth/coalesce-r1/-r2/-r3) so every round is a cold coalescing scenario (reusing one path would let round 2 just hit twice against round 1's already-cached object, with no fetch to coalesce on at all). A passing round breaks out immediately; three failing rounds exit 1. The fetch-sanity assert stays a single round-independent check before the loop. Traffic generation keeps its original transport-retry semantics unchanged (a round does not gate on either backgrounded call's exit status). This is a test-level workaround for live-log-processing nondeterminism, not a Linker design gap: Task 5's controller ruling against a pending-hits buffer stands unmodified, since every unit fixture's own ordering already exercises the flag correctly without one. Budget: 92s (one-shot sanity) + 3 x 127s (traffic + assert per round) = 473s worst case; script timeout raised to 530s (~57s margin, matching this suite's established margins elsewhere). Validated: python3 yaml.safe_load (and safe_load_all) clean, hack/check-suite-labels.sh and hack/check-e2e-boundary.sh green, chainsaw lint test valid. Assisted-by: Claude Fable 5
…-miss purity Three review cleanups bundled together: - internal/tracer/spans/linker_test.go: TestLinker_CoalescedHitLinksToOriginFetch's comment still accused NOTES.md of mislabeling coalesce.txt's vxid order; that was fixed in 8afb10c. Rewrite the comment to state the (now correct) file order plainly instead of re-litigating a fixed doc bug. - docs/superpowers/specs/2026-09-21-opentelemetry-tracing-design.md's truth-semantics table: the coalescing row implied every hit-link sets varnish.coalesced — in fact resolveHit links EVERY resolved hit to its origin fetch unconditionally (the shipped enhancement over the older waiters-only wording) and sets the coalesced flag only on genuine time overlap; a resolved plain/grace hit links without it. Reworded the row to say so. Also moved varnish.minted_trace_mismatch out of the Retries row — a retried bereq inherits its traceparent and only its span id is rewritten, so the trace id is always preserved and the flag never fires there — into the Grace/bgfetch and ESI rows, where it actually does: Varnish does not propagate the parent's traceparent into a bgfetch or ESI subrequest's bereq, so each mints its own fresh trace id. - internal/tracer/spans/linker.go: Build's early len(built)==0 branch counted a link-cache miss for a restart continuation whenever the restart-identity cache lookup failed, regardless of why built came back empty. BuildWithOutcome can return empty for OutcomeUnusable (missing timestamps) or OutcomeUnsampled as well as the "not a Request group" OutcomeSpans case; the first two are already-counted or intentional silence, not a failed restart-link correlation, and must not also inflate link_cache_misses. Guarded the check on outcome == OutcomeSpans and documented why that combination can, in practice, never coincide with isRestartContinuation(tx) being true (a real Request group with valid timestamps always builds at least one span) — the guard exists to state the invariant rather than rely on it silently. New test TestLinker_RestartMissNotCountedWhenGroupUnusable: a synthetic Request tx whose Begin marks it a restart continuation but which is missing its Start timestamp (forcing OutcomeUnusable). RED before the fix (miss count 1, expected 0); GREEN after. go test ./internal/tracer/... and the whole-repo go test are green; make lint is clean. Assisted-by: Claude Fable 5
varnishlog -g request emits a coalescing initiator's group (with the fetch) and the waiter's group (with the Hit) in completion order, a genuine ~50/50 race independent of which one actually started first (coalesce-investigation.md). Linker.Build used to resolve a hit's vxid against the fetch cache immediately: initiator-first landed the link and varnish.coalesced=true, waiter-first degraded permanently to varnish.coalesced_unlinked=true on the spot, since the span set was already enqueued. This is what made the tracing-truth E2E's coalescing assert flake ~50/50 per round (PR #111). Linker.Build now parks a group whose Hit vxid does not yet resolve (withholds it, keyed by that vxid, stamped with an arrival time) instead of degrading it immediately. Every subsequent Build call first releases any parked set older than ageLimit (10s) degraded - before recording its own fetch identities, so a long-stale parked vxid can never accidentally resolve against an unrelated but same-numbered fetch from a different varnishd lifetime - then resolves any parked set whose vxid the fetch-identity cache now covers, releasing it linked with the same overlap rule as an immediate resolution. The lot is bounded (maxParked 256); overflow releases the oldest parked set degraded before parking the new arrival. A new Flush() releases everything still parked, degraded, and is wired into cmd/tracer/main.go after the supervisor's run loop returns so a parked set never gets silently dropped at shutdown. link_cache_misses keeps its existing meaning (a hit released without ever resolving); a new vinyl_tracer_hits_parked_total counts the act of parking itself, purely for visibility into how often the race happens. Updates the truth-semantics spec's coalescing row and the tracing-truth chainsaw test's coalescing-traffic-and-assert step description: both orderings now resolve to the link; the step's retry loop stays as belt-and-braces insurance against residual pathologies (age-out under heavy scheduling contention, OTLP export timing) rather than as the primary fix for the ordering race. Assisted-by: Claude Fable 5
Code review of the parking-lot commit (3c08cae) found two critical bugs before both were fixed here: 1. Shutdown Flush enqueued into an already-drained batcher. export.Batcher.Run shared the signal context with the supervisor loop: a SIGTERM fires ctx.Done() for both at once, and Run's drain-on-cancel branch empties the channel and returns within microseconds - almost always before the supervisor finishes tearing down its varnishlog subprocess, and certainly before main's post-shutdown linker.Flush() loop runs. Spans enqueued in that window landed in a channel nobody was reading anymore - Enqueue still succeeded (room in the buffer), so even vinyl_tracer_spans_dropped_total never fired. Fixed by giving the batcher its own context (batcherCtx/stopBatcher), cancelled explicitly only after both the supervisor loop and the Flush-enqueue loop have returned. New regression test TestShutdown_PostSupervisorSpansStillExport in cmd/tracer drives this exact pattern directly (main() itself isn't independently testable) and fails under the old shared-ctx wiring. 2. Parking gated on the wrong predicate. Every Hit names its object's origin fetch vxid regardless of how long ago that fetch happened, so an ordinary WARM hit (origin evicted past the fetch-identity cache's TTL, or predating this process) is indistinguishable from a waiter-first hit by vxid lookup alone - but can never resolve no matter how long it waits. Parking on the vxid-miss test alone, as the previous version of resolveHit did, would delay the dominant warm-hit traffic class by up to ageLimit (indefinitely while idle) and would flood both new counters with non-race traffic. Fixed by gating parking on the tx's own "Timestamp Waitinglist:" record - present only for a genuine coalescing waiter (NOTES.md's coalesce.txt section; coalesce-investigation.md's local reproduction confirmed this 10/10 against a real Linker and a live varnishd). An unresolvable hit without it degrades immediately, exactly as before the parking lot existed. New test TestLinker_WarmHitWithoutWaitinglistDegradesImmediately pins this; TestLinker_ParkOverflowReleasesOldestDegraded's synthetic fixtures now carry a Waitinglist record where they must park. Also: one doc sentence on parkedSet about the residual (accepted, bounded-by-ageLimit) cross-process vxid aliasing window on a varnishd restart; one doc sentence on Build clarifying its returned Outcome describes only the current tx, not released/parked spans riding along in the same []Span; dropped a session-local scratchpad path citation from the chainsaw-test.yaml step description (kept the PR #111 pointer); tightened the hits_parked counter's help text and the spec's coalescing row to the now-accurate genuine-waiter-only-parks semantics. Assisted-by: Claude Fable 5
Update: the coalescing race is now fixed in the tracer, not just retried around itThe first
So three independent rounds failing was ~12.5% bad luck on a real 50/50, not a new bug — but retrying around a coin flip is not truth. The Linker now carries a bounded parking lot: a coalescing waiter whose originating fetch is not yet known is parked (keyed by that fetch's vxid) instead of being emitted degraded, and is released with its link and Bounds and honesty, because a parking lot that can grow or forget silently would be worse than the race:
The E2E retry loop stays as belt-and-braces for residual pathologies, and its description now says what the linker guarantees. Known residual: Assisted-by: Claude Fable 5 |
Summary
P3 of OpenTelemetry tracing, per the (herein synced) design spec: the traces tell the truth under load.
testdata/NOTES.md— every span-builder change was written against recorded bytes, and the fixtures corrected the plan more than once (restart is a cross-transaction affair; ESI subrequests get no traceparent propagation; Hit payloads come in 4- and 6-field shapes).varnish.minted_trace_mismatchwhere the wire couldn't), restart counting with an honest end-timestamp fallback, statuses via last-record truth.varnish.coalesced=trueon genuine time overlap; restarted requests are stitched across top-level VSL groups into the original's trace (varnish.restart_continuation); every unresolvable correlation is a visible attr + counter, never silence. Skip counters split: unsampled vs genuinely unusable; pipe no longer counts as data loss.-link-span-id,-min-duration).suite: full, this PR carriese2e-full): coalescing (two backgrounded probes on one slow cold URL, asserted viavarnish.coalescedwith a 3-round fresh-path retry against the VSL group-emission ordering race), grace/bgfetch (short-TTL traffic poll), and the spec's long-promised honest-timing assertion (-min-duration 1500mson a 2s-delayed fetch).import esi;referenced a vmod that does not exist in varnish 8 (removed; proven viavarnishd -C; ESI is core via the newdo_esi-on-Surrogate-Control gate) — andvarnishParametersnever reaches varnishd-pat all, which defers the ESI E2E to varnishParameters never reach varnishd, and the ESI import gate referenced a nonexistent vmod #109. The restart-then-miss mismatch-flag refinement is Tracer: restart-then-miss leaves backend spans orphaned without the minted_trace_mismatch flag #110.Verification
Full battery green at HEAD: lint, unit (incl. 8 Linker tests, race-clean), envtest, helm-unittest 59/59, both boundary/label checks, zero generated-file drift. Every task passed spec+quality review; the final whole-branch review's findings are fixed in the last two commits and re-reviewed (the coalescing retry loop was executed under both bash and dash against mocked commands).
Note for reviewers
The
tracing-truthsuite runs here for the first time (needs this PR'se2e-fulllabel). The final review recommends letting the full suite run 2–3 times before merging — the coalescing scenario is inherently racy and the retry is new. Budget arithmetic is documented inside each step.Assisted-by: Claude Fable 5