Skip to content

feat: truth under load — coalescing links, grace, ESI, restarts, pipe (tracing P3) - #111

Merged
jensens merged 18 commits into
mainfrom
feat/otel-tracing-p3
Sep 30, 2026
Merged

jensens merged 18 commits into
mainfrom
feat/otel-tracing-p3

Conversation

@jensens

@jensens jensens commented Sep 30, 2026

Copy link
Copy Markdown
Member

Summary

P3 of OpenTelemetry tracing, per the (herein synced) design spec: the traces tell the truth under load.

  • Truth fixtures first: seven new VSL recordings from real varnish:8.0.2 (coalesce, grace/bgfetch, esi, restart, retry, pipe, synth) via an upgraded rig with a traffic-shaping backend, catalogued in 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).
  • Recursive span building: fetch spans per retry attempt (nested under the first attempt's span), bgfetch children, ESI child request spans carrying the parent's trace through the tree (varnish.minted_trace_mismatch where the wire couldn't), restart counting with an honest end-timestamp fallback, statuses via last-record truth.
  • The Linker (bounded LRU+TTL fetch-identity cache, single-goroutine): every hit links to the fetch that created its object; varnish.coalesced=true on 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.
  • Links and timings on the wire: through the ReadOnlySpan adapter, the E2E sink (links + start/end nanos), and vinylprobe (-link-span-id, -min-duration).
  • E2E (suite: full, this PR carries e2e-full): coalescing (two backgrounded probes on one slow cold URL, asserted via varnish.coalesced with 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 1500ms on a 2s-delayed fetch).
  • Two pre-existing defects flushed out: import esi; referenced a vmod that does not exist in varnish 8 (removed; proven via varnishd -C; ESI is core via the new do_esi-on-Surrogate-Control gate) — and varnishParameters never reaches varnishd -p at 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-truth suite runs here for the first time (needs this PR's e2e-full label). 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

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
@jensens jensens added the e2e-full Run the full E2E suite on this PR label Sep 30, 2026
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
@jensens

jensens commented Sep 30, 2026

Copy link
Copy Markdown
Member Author

Update: the coalescing race is now fixed in the tracer, not just retried around it

The first e2e-full run failed the coalescing assertion in all three retry rounds. Investigation (local rig reproducing the E2E's exact traffic shape, 10 rounds against real varnish 8.0.2, then the real Linker replayed over each recording):

  • Coalescing itself worked every time: 10/10 rounds produced exactly one fetch for two concurrent requests.
  • varnishlog -g request emitted the initiator's group first in 5/10 rounds and the waiter's first in the other 5 — a clean coin flip.
  • The Linker matched that split exactly: initiator-first → varnish.coalesced=true; waiter-first → varnish.coalesced_unlinked, permanently, because the hit was resolved against the fetch cache the instant its group arrived.

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 varnish.coalesced as soon as the initiator's group arrives. Both orderings now produce identical spans.

Bounds and honesty, because a parking lot that can grow or forget silently would be worse than the race:

  • Parking is gated on the waiter's own Timestamp Waitinglist: record, so only genuine race waiters park. An ordinary warm hit whose origin fetch has aged out of the cache degrades immediately, exactly as before — it is not a race and must not be delayed.
  • 256 sets max (overflow releases the oldest, degraded), 10s age limit, and a Flush() on shutdown so nothing is dropped when the process exits. Every release-without-resolution still sets varnish.coalesced_unlinked and counts vinyl_tracer_link_cache_misses_total; vinyl_tracer_hits_parked_total counts the race itself.
  • The batcher now runs on its own context, cancelled only after the supervisor returns and the flush is enqueued. Without that, the shutdown flush landed in a channel nobody was reading any more — the spans it exists to save were being lost, silently, without even incrementing the drop counter.

The E2E retry loop stays as belt-and-braces for residual pathologies, and its description now says what the linker guarantees.

Known residual: cmd/tracer/main.go has no testable seam, so the new shutdown regression test guards the pattern rather than main's own wiring. Extracting main's body into a run(ctx) error would close that; it is not part of this PR.

Assisted-by: Claude Fable 5

@jensens
jensens merged commit 481f54e into main Sep 30, 2026
9 checks passed
@jensens
jensens deleted the feat/otel-tracing-p3 branch September 30, 2026 19:11
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

e2e-full Run the full E2E suite on this PR

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant