Capture backend server logs for conformance sampling flake#5867
Draft
jhrozek wants to merge 10 commits into
Draft
Capture backend server logs for conformance sampling flake#5867jhrozek wants to merge 10 commits into
jhrozek wants to merge 10 commits into
Conversation
DRAFT probe, not for merge. The tools-call-sampling conformance flake stopped appearing on runs that carry `thv run --debug` (4/4 debug runs passed vs a >50% base fail rate), suggesting the debug log I/O perturbs the timing race and masks the failure. Drop `--debug` while keeping the proxy-log capture (at default INFO level) to test that hypothesis: if this reliably fails tools-call-sampling again, --debug was masking it, and the captured INFO-level proxy logs (which still record a session/-32001 event) give a non-perturbing root-cause path. Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>
Codecov Report✅ All modified and coverable lines are covered by tests. Additional details and impacted files@@ Coverage Diff @@
## main #5867 +/- ##
==========================================
+ Coverage 71.28% 71.52% +0.23%
==========================================
Files 693 695 +2
Lines 70572 71005 +433
==========================================
+ Hits 50307 50785 +478
+ Misses 16633 16566 -67
- Partials 3632 3654 +22 ☔ View full report in Codecov by Harness. 🚀 New features to boost your workflow:
|
Debug logs from PR #5839's failing run showed --debug does NOT mask the sampling flake: the run failed with --debug on, and the trace localized the stall to a missing server->client sampling/createMessage delivery (the client never sends its sampling-response POST). So restore --debug (it is our best signal, not a mask) and add the one artifact still missing: the Node backend container's own logs, which reveal whether the backend emitted the sampling request (-> proxy relay race) or not (-> backend-side). SSE bodies are not in the proxy log, so this is the only way to split those two legs. Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>
github-actions
Bot
added
size/XS
jhrozek
changed the title
github-actions
Bot
added
size/XS
The backend/proxy logs cannot show whether the backend actually emitted the server->client sampling/createMessage on the SSE stream (SSE bodies are not logged, and the Node reference server may not log its own writes). A packet capture shows the bytes on both legs and definitively splits the remaining fork: sampling/createMessage present on backend->proxy but absent on proxy->client => ToolHive relay bug; absent on both => backend never emitted. Start tcpdump before the suite and stop it in cleanup(). `-i any` covers the loopback and docker-bridge legs (the backend is a docker-published port via docker-proxy); full snaplen is required to see SSE payloads; -U flushes per packet. Best-effort and non-fatal when tcpdump/passwordless sudo are absent (local macOS). The pcap lands in the results dir already uploaded as an artifact, so no workflow change is needed. Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>
github-actions
Bot
added
size/XS
The pcap showed the backend never emits sampling/createMessage and that ToolHive fronts the workload with a Squid ingress proxy (createIngressSquidContainer) plus the Go transparent proxy. It is unresolved whether that proxy stack causes or merely aggravates the client-ordering race that starves the server->client sampling stream. Add compare-sampling.sh: run the conformance suite N times against the reference container DIRECTLY (no thv) vs THROUGH the thv stack (Go proxy -> Squid ingress), and tally the tools-call-sampling failure rate. If it only flakes through the stack, ToolHive owns it (likely the Squid ingress). Wire it as a diagnostic step in the conformance job (draft-only) and bump the job timeout to 30m to accommodate the extra runs. Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>
github-actions
Bot
added
size/S
2 tasks
The direct-vs-stack comparison proves the ToolHive stack triggers the sampling flake but can't say whether the Squid ingress or the Go transparent proxy widens the tools/call-vs-GET-SSE race. Add a middle tier that hits the ingress Squid's published host port directly, dropping the Go proxy from the path, so a failing CI run localizes the culprit: DIRECT green + SQUID flaky => Squid; SQUID green + STACK bad => Go proxy. Switch the tally to the single tools-call-sampling scenario so three tiers stay affordable in CI. Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>
github-actions
Bot
added
size/S
The 3-tier comparison ran isolated `--scenario tools-call-sampling`, which completes in ~1s and never reproduces the 60s hang (the flake only manifests in the full-suite context), and its result grep matched the suite-summary format, so every tier reported UNKNOWN (0/N). Run the full `active` suite per iteration (which does reproduce), keep the suite-summary grep, and drop N to 4 so 3 tiers fit the job timeout. Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>
github-actions
Bot
added
size/S
The flake only reproduces on the FIRST suite run against a freshly created stack; the previous comparison reused one warm stack across iterations and so came back all-green (inconclusive). Give every iteration its own fresh stack, and measure SQUID and STACK from SEPARATE fresh stacks (sharing one would leave the second tier warm and hide the flake). This is what lets CI localize whether the Squid ingress or the Go transparent proxy widens the tools/call-vs-GET-SSE race. Costs 2N thv runs; N defaults to 3 to fit the 30m job budget. Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>
github-actions
Bot
added
size/S
The tools-call-sampling conformance flake was localized to the ingress Squid: on a cold stack the first GET /mcp SSE stream pays inline DNS + TCP connect latency to the upstream while a later tools/call POST reuses a warmed path, so the POST reaches the server and runs its handler before the standalone GET SSE stream is established. A server-initiated request (sampling) then has no stream to ride and the client times out at 60s. Add standby=2 to the ingress cache_peer so Squid keeps warm idle upstream connections; the first GET is forwarded without inline connect latency, removing the GET-vs-POST reorder. Config-only, no ACL change. Bump the diagnostic compare to N=8 to validate the SQUID tier goes green. Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>
github-actions
Bot
added
size/S
On a cold start, the transparent proxy forwarded requests over a bare shared http.DefaultTransport whose per-host idle pool starts empty, so the first upstream connection paid inline DNS+TCP dial latency. The client's standalone GET (SSE stream) and tools/call POST are forwarded on separate connections, so a cold dial on the GET could delay stream establishment past the point where the backend's tool handler sends a server-to-client request on it, causing a client timeout. Clone http.DefaultTransport (never mutate the shared global) with a small idle pool, and pre-warm it at startup with a burst of side-effect-free GET requests to the upstream. This is the Go-proxy analog of the Squid ingress cache_peer standby=2 fix for the squid->backend hop. Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>
This reverts commit 5fa0fa0.
github-actions
Bot
added
size/S
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
1 participant
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Summary
The
tools-call-samplingconformance scenario intermittently times out at60s in CI. This PR started as a probe to drop
--debug(on the theory thatdebug logging masked the flake), but the debug proxy log from PR #5839's
failing run disproves that theory and redirects the investigation:
--debugon — debug does not reliably mask it.initialize,notifications/initialized, thetools/callPOST (SSE stream) and thestandalone GET SSE stream all succeed, the session goes silent for 58s
(only the 10s health pinger runs), and the client never sends its
sampling-response POST. i.e. the client never received the server's
sampling/createMessagerequest.So
--debugis our best signal, not a mask. This PR therefore:--debug(reverts this branch's original change).conformance harness
cleanup(). The proxy log cannot show whether thebackend emitted
sampling/createMessage(SSE bodies are not logged), sothe backend log is the one missing artifact that splits the two remaining
hypotheses:
The new files (
backend-logs.txt,backend-docker-logs.txt) land intest/conformance/results/and are uploaded with the existingconformance-resultsartifact automatically.Type of change
Test plan
conformance-resultsartifact:sampling
checks.jsonshows the 60s-32001timeout;proxy-logs.txt(debug) shows the 58s silence and the abandoned session.
no gap, round-trip completes inline.
Generated with Claude Code