From 6eff667bacf1c8e7952a44e803ef7e58049b06a8 Mon Sep 17 00:00:00 2001 From: Juan Antonio Osorio Date: Mon, 27 Jul 2026 20:56:23 +0000 Subject: [PATCH 1/5] Stop warn-mode verification failing runs on TUF outages In the default warn mode, VerifyImage returned verifier construction errors and non-signature verification errors as fatal, while an actual failed verification only warned. A sigstore TUF CDN connection reset therefore hard-failed 'thv run' for any registry server with provenance (observed repeatedly in CI, e.g. run 30297766499). Warn mode now warns and continues on every verification failure; enabled mode still fails closed. Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_01Y5WXPQr5Da9Cox2nZWhg6n --- pkg/runner/retriever/retriever.go | 17 +++++-- pkg/runner/retriever/retriever_test.go | 69 ++++++++++++++++++++++++++ 2 files changed, 82 insertions(+), 4 deletions(-) diff --git a/pkg/runner/retriever/retriever.go b/pkg/runner/retriever/retriever.go index 0235236a37..5cc2432e00 100644 --- a/pkg/runner/retriever/retriever.go +++ b/pkg/runner/retriever/retriever.go @@ -358,16 +358,25 @@ func VerifyImage(image string, server *types.ImageMetadata, verifySetting string return verifier.ErrProvenanceServerInformationNotSet } - // Create a new verifier + // Create a new verifier. In warn mode this must not block the run: + // construction reaches out to the sigstore TUF repository, so a CDN + // outage or connection reset would otherwise hard-fail a mode whose + // contract is "warn and continue" — an actual failed verification + // below only warns, so an unreachable verifier must not be stricter. v, err := verifier.New(server.Provenance, images.NewCompositeKeychain()) if err != nil { + if verifySetting == VerifyImageWarn { + slog.Warn("image verification unavailable, continuing without it", "image", image, "reason", err) + return nil + } return err } - // Verify the image passing the provenance info + // Verify the image passing the provenance info. Warn mode downgrades + // every failure — signature mismatches and transient registry errors + // alike — to a warning; only enabled mode fails closed. if err = v.VerifyServer(image, server.Provenance); err != nil { - if (errors.Is(err, verifier.ErrImageNotSigned) || errors.Is(err, verifier.ErrProvenanceMismatch)) && - verifySetting == VerifyImageWarn { + if verifySetting == VerifyImageWarn { slog.Warn("MCP server failed image verification", "image", image, "reason", err) return nil } diff --git a/pkg/runner/retriever/retriever_test.go b/pkg/runner/retriever/retriever_test.go index 92d8eb64f9..3701026fe7 100644 --- a/pkg/runner/retriever/retriever_test.go +++ b/pkg/runner/retriever/retriever_test.go @@ -11,6 +11,7 @@ import ( "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" + "github.com/stacklok/toolhive-core/container/verifier" regtypes "github.com/stacklok/toolhive-core/registry/types" "github.com/stacklok/toolhive/pkg/runner" ) @@ -134,6 +135,74 @@ func TestHasLatestTag(t *testing.T) { } } +func TestVerifyImage(t *testing.T) { + t.Parallel() + + const testImage = "ghcr.io/example/server:v1.0.0" + + // A SigstoreURL with no embedded TUF root makes verifier.New fail + // deterministically without touching the network — the same "verifier + // cannot be constructed" return path a sigstore TUF CDN outage takes. + unreachableVerifier := ®types.ImageMetadata{ + Provenance: ®types.Provenance{SigstoreURL: "tuf.invalid.example"}, + } + + tests := []struct { + name string + server *regtypes.ImageMetadata + verifySetting string + expectErr string + }{ + { + name: "disabled skips verification", + server: unreachableVerifier, + verifySetting: VerifyImageDisabled, + }, + { + name: "warn without provenance continues", + server: ®types.ImageMetadata{}, + verifySetting: VerifyImageWarn, + }, + { + name: "enabled without provenance fails", + server: ®types.ImageMetadata{}, + verifySetting: VerifyImageEnabled, + expectErr: verifier.ErrProvenanceServerInformationNotSet.Error(), + }, + { + name: "warn with unavailable verifier continues", + server: unreachableVerifier, + verifySetting: VerifyImageWarn, + }, + { + name: "enabled with unavailable verifier fails", + server: unreachableVerifier, + verifySetting: VerifyImageEnabled, + expectErr: "root.json", + }, + { + name: "invalid setting fails", + server: ®types.ImageMetadata{}, + verifySetting: "sometimes", + expectErr: "invalid value for --image-verification", + }, + } + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + t.Parallel() + + err := VerifyImage(testImage, tt.server, tt.verifySetting) + if tt.expectErr != "" { + require.Error(t, err) + assert.Contains(t, err.Error(), tt.expectErr) + } else { + require.NoError(t, err) + } + }) + } +} + // errorPolicyGate is a test PolicyGate that rejects server creation with a // configurable error. It embeds runner.NoopPolicyGate for forward compatibility. type errorPolicyGate struct { From 10f92114ec2c1c229fba0807118d6a074b3a35af Mon Sep 17 00:00:00 2001 From: Juan Antonio Osorio Date: Mon, 27 Jul 2026 20:56:23 +0000 Subject: [PATCH 2/5] Surface why a workload failed or stalls in starting startWorkload and the detached-spawn failure path wrote status error with an empty context, clobbering the failure reason RunWorkload's retry loop had just recorded; CI readiness timeouts then showed only a bare status "error". Record err.Error() instead. The readiness probe logged per-attempt outcomes at DEBUG only, so a workload stuck in starting left no visible trace of what the probe observed. Log an INFO progress line every 30s with the last observed outcome, and include it in the timeout error. Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_01Y5WXPQr5Da9Cox2nZWhg6n --- pkg/runner/runner.go | 21 ++++++++++++++++++++- pkg/workloads/manager.go | 10 +++++++--- 2 files changed, 27 insertions(+), 4 deletions(-) diff --git a/pkg/runner/runner.go b/pkg/runner/runner.go index a3c9922433..311bbeb28b 100644 --- a/pkg/runner/runner.go +++ b/pkg/runner/runner.go @@ -1052,6 +1052,15 @@ func waitForInitializeSuccess( delay := 100 * time.Millisecond maxDelay := 2 * time.Second // Cap at 2 seconds between retries + // Per-attempt outcomes below log at DEBUG, which is invisible in a default + // deployment — a workload stuck in `starting` for minutes then shows no + // trace of WHY the probe kept failing. Surface a periodic INFO progress + // line (long-running operation) carrying the last observed outcome. + // Every loop iteration assigns lastObserved before it is read. + var lastObserved string + const progressInterval = 30 * time.Second + nextProgressLog := progressInterval + slog.Info("Waiting for MCP server to be ready", "endpoint", endpoint, "timeout", maxWaitTime) // Create HTTP client with a reasonable timeout for requests @@ -1073,6 +1082,7 @@ func waitForInitializeSuccess( if err != nil { slog.Debug("Failed to create request", "attempt", attempt, "error", err) + lastObserved = fmt.Sprintf("failed to create request: %v", err) } else { if method == "POST" { req.Header.Set("Content-Type", "application/json") @@ -1097,15 +1107,24 @@ func waitForInitializeSuccess( slog.Debug("Server returned status", //nolint:gosec // G706: status code and attempt are integers "status_code", resp.StatusCode, "attempt", attempt) + lastObserved = fmt.Sprintf("HTTP %d", resp.StatusCode) } else { slog.Debug("Failed to reach endpoint", "attempt", attempt, "error", err) + lastObserved = fmt.Sprintf("unreachable: %v", err) } } // Check if we've exceeded the maximum wait time elapsed := time.Since(startTime) if elapsed >= maxWaitTime { - return fmt.Errorf("initialize not successful after %v (%d attempts)", elapsed, attempt) + return fmt.Errorf("initialize not successful after %v (%d attempts, last observed: %s)", + elapsed, attempt, lastObserved) + } + + if elapsed >= nextProgressLog { + slog.Info("Still waiting for MCP server to be ready", //nolint:gosec // G706: attempt is an integer + "endpoint", endpoint, "elapsed", elapsed.Round(time.Second), "attempt", attempt, "last_observed", lastObserved) + nextProgressLog += progressInterval } // Wait before retrying diff --git a/pkg/workloads/manager.go b/pkg/workloads/manager.go index f208d96168..644abef2fb 100644 --- a/pkg/workloads/manager.go +++ b/pkg/workloads/manager.go @@ -793,7 +793,7 @@ func (d *DefaultManager) spawnDetached(ctx context.Context, runConfig *runner.Ru } if err := detachedCmd.Start(); err != nil { - if statusErr := d.statuses.SetWorkloadStatus(ctx, runConfig.BaseName, rt.WorkloadStatusError, ""); statusErr != nil { + if statusErr := d.statuses.SetWorkloadStatus(ctx, runConfig.BaseName, rt.WorkloadStatusError, err.Error()); statusErr != nil { slog.Warn("Failed to set workload status to error", "workload", runConfig.BaseName, "error", statusErr) } return 0, err @@ -1554,8 +1554,12 @@ func (d *DefaultManager) startWorkload(ctx context.Context, name string, mcpRunn } if err != nil { - // If we could not start the workload, set the status to error before returning - if statusErr := d.statuses.SetWorkloadStatus(ctx, name, rt.WorkloadStatusError, ""); statusErr != nil { + // If we could not start the workload, set the status to error before + // returning. Record err itself as the status context: RunWorkload's + // retry loop has already written the failure reason there, and an + // empty context here would clobber it — CI debug output then shows a + // bare status "error" with no way to tell what actually failed. + if statusErr := d.statuses.SetWorkloadStatus(ctx, name, rt.WorkloadStatusError, err.Error()); statusErr != nil { slog.Warn("Failed to set workload status to error", "workload", name, "error", statusErr) } } From a46d23c1fa45e1b16a8c945d94625960492c3bb9 Mon Sep 17 00:00:00 2001 From: Juan Antonio Osorio Date: Mon, 27 Jul 2026 20:56:23 +0000 Subject: [PATCH 3/5] Dump proxy logs when an e2e readiness wait times out DebugServerState only printed container logs, which show a healthy server while the workload sits in starting or error: the failure is in the detached supervisor, whose output goes to the proxy log file. Dump 'thv logs --proxy' too so a CI timeout names the actual blocker. Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_01Y5WXPQr5Da9Cox2nZWhg6n --- test/e2e/helpers.go | 12 ++++++++++++ 1 file changed, 12 insertions(+) diff --git a/test/e2e/helpers.go b/test/e2e/helpers.go index 90ebb52913..1dccff283a 100644 --- a/test/e2e/helpers.go +++ b/test/e2e/helpers.go @@ -349,6 +349,18 @@ func DebugServerState(config *TestConfig, serverName string) { GinkgoWriter.Printf("Server logs:\n%s\n", logs) } + // The container log alone has repeatedly been useless for readiness + // timeouts: a workload stuck in `starting` or flipped to `error` fails + // inside the detached supervisor (transport start, readiness probe, + // restart loop), whose output goes to the proxy log file — not to the + // container. Dump it too so a CI failure names the actual blocker. + proxyLogs, stderr, err := NewTHVCommand(config, "logs", serverName, "--proxy").Run() + if err != nil { + GinkgoWriter.Printf("Failed to get proxy logs: %v\nStderr: %s\n", err, stderr) + } else { + GinkgoWriter.Printf("Proxy logs:\n%s\n", proxyLogs) + } + GinkgoWriter.Printf("=== End debugging for %s ===\n", serverName) } From f32454a8f9b90f2a2e6073bab569344c4f0acd9b Mon Sep 17 00:00:00 2001 From: Juan Antonio Osorio Date: Mon, 27 Jul 2026 20:56:41 +0000 Subject: [PATCH 4/5] Quarantine all four server-to-client conformance flakes Suite v0.1.16 has four scenarios that drive a server->client request and are exposed to the upstream ordering race (conformance#407): tools-call-sampling, tools-call-elicitation, elicitation-sep1034-defaults and elicitation-sep1330-enums. The gate only ignored the first two, so runs where the race hit an elicitation-sep scenario (both hit on one PR run, each timing out at exactly 60s) still hard-failed. Extend the alternation to the set verified from the suite source; any other scenario still fails the job. Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_01Y5WXPQr5Da9Cox2nZWhg6n --- test/conformance/run-conformance.sh | 25 ++++++++++++++++--------- 1 file changed, 16 insertions(+), 9 deletions(-) diff --git a/test/conformance/run-conformance.sh b/test/conformance/run-conformance.sh index 596ec61424..07ad488cea 100755 --- a/test/conformance/run-conformance.sh +++ b/test/conformance/run-conformance.sh @@ -266,25 +266,32 @@ npx -y "@modelcontextprotocol/conformance@${CONFORMANCE_VERSION}" server \ suite_rc=${PIPESTATUS[0]} set -e -# Quarantine: tools-call-sampling and tools-call-elicitation flake intermittently -# (~1/3) due to an upstream reference-server bug, NOT a ToolHive defect. The -# everything-server sends its server->client request (sampling/createMessage or -# elicitation/create) on the client's standalone GET SSE stream without a -# relatedRequestId, so it races the tools/call handler; when the handler wins, -# the request is dropped and the client times out at 60s. See: +# Quarantine: the scenarios that drive a server->client request flake +# intermittently (~1/3) due to an upstream reference-server bug, NOT a ToolHive +# defect. The everything-server sends its server->client request +# (sampling/createMessage or elicitation/create) on the client's standalone GET +# SSE stream without a relatedRequestId, so it races the tools/call handler; +# when the handler wins, the request is dropped and the client times out at 60s. +# In suite v0.1.16 exactly four scenarios register client-side handlers for +# server->client requests (src/scenarios/server/tools.ts and +# elicitation-{defaults,enums}.ts) and are therefore exposed to the race: +# tools-call-sampling, tools-call-elicitation, +# elicitation-sep1034-defaults, elicitation-sep1330-enums +# See: # upstream: https://github.com/modelcontextprotocol/conformance/issues/407 # toolhive: #5886 (ingress Squid cold-start mitigation, reduces but can't # eliminate the client-side ordering race) # We can't use expected-failures.yaml (a flaky entry stale-fails the ~2/3 of runs -# where it passes), so ignore ONLY these two scenarios in the gating here; every +# where it passes), so ignore ONLY these scenarios in the gating here; every # other scenario still fails the job. Remove this block once #407 is fixed # upstream and CONFORMANCE_VERSION is bumped to a release that contains the fix. +quarantined='tools-call-sampling|tools-call-elicitation|elicitation-sep1034-defaults|elicitation-sep1330-enums' if [ "${suite_rc}" -ne 0 ]; then unexpected="$(sed -n '/Unexpected failures (not in baseline):/,$p' "${RESULTS_DIR}/suite-output.log" \ | grep -oE '✗ [a-z0-9-]+' | sed 's/✗ //' | sort -u)" - others="$(printf '%s\n' "${unexpected}" | grep -vE '^(tools-call-sampling|tools-call-elicitation)?$' || true)" + others="$(printf '%s\n' "${unexpected}" | grep -vE "^(${quarantined})?\$" || true)" if [ -n "${unexpected}" ] && [ -z "${others}" ]; then - echo "==> Ignoring quarantined flaky scenarios 'tools-call-sampling'/'tools-call-elicitation' (upstream conformance#407 / toolhive#5886); no other unexpected failures." + echo "==> Ignoring quarantined flaky server->client scenarios (${quarantined}) per upstream conformance#407 / toolhive#5886; no other unexpected failures." exit 0 fi exit "${suite_rc}" From 1f14126a7051f37d0bae245003e6f7c9fdf68cdc Mon Sep 17 00:00:00 2001 From: Juan Antonio Osorio Date: Mon, 27 Jul 2026 20:56:41 +0000 Subject: [PATCH 5/5] Settle Ready condition before no-reconcile baseline The unrelated-composite-tool spec captured its Ready-condition timestamp baseline right after a gate that only proves ObservedGeneration > 0, so a controller still settling flipped the condition inside the 2s observation window and failed the spec (3 main-branch failures since 2026-07-06). Wait for the transition time to hold stable across ~2s of polls before taking the baseline. Co-Authored-By: Claude Opus 5 (1M context) Claude-Session: https://claude.ai/code/session_01Y5WXPQr5Da9Cox2nZWhg6n --- ...rtualmcpserver_compositetool_watch_test.go | 33 +++++++++++++++++++ 1 file changed, 33 insertions(+) diff --git a/cmd/thv-operator/test-integration/virtualmcp/virtualmcpserver_compositetool_watch_test.go b/cmd/thv-operator/test-integration/virtualmcp/virtualmcpserver_compositetool_watch_test.go index 33caa4682e..38e8bfd027 100644 --- a/cmd/thv-operator/test-integration/virtualmcp/virtualmcpserver_compositetool_watch_test.go +++ b/cmd/thv-operator/test-integration/virtualmcp/virtualmcpserver_compositetool_watch_test.go @@ -393,6 +393,39 @@ var _ = Describe("VirtualMCPServer CompositeToolDefinition Watch Integration Tes }) It("Should NOT trigger VirtualMCPServer reconciliation when unrelated composite tool definition is created", func() { + // BeforeAll only gates on ObservedGeneration > 0, so the controller + // may still be settling (the Ready condition flipping as discovery + // and config generation complete) when this spec starts. A baseline + // captured mid-settle fails the timestamp assertion below even + // though the unrelated create never triggered anything. Wait until + // the Ready condition has held the same transition time across + // several consecutive polls before taking the baseline. + var lastSeenReadyTime metav1.Time + stablePolls := 0 + Eventually(func() bool { + vmcpNow := &mcpv1beta1.VirtualMCPServer{} + if err := k8sClient.Get(ctx, types.NamespacedName{ + Name: vmcpName, + Namespace: namespace, + }, vmcpNow); err != nil { + return false + } + for _, cond := range vmcpNow.Status.Conditions { + if cond.Type == conditionReady { + if cond.LastTransitionTime.Equal(&lastSeenReadyTime) { + stablePolls++ + } else { + lastSeenReadyTime = cond.LastTransitionTime + stablePolls = 0 + } + // ~2s of stability at the 250ms poll interval: the + // observed flake transitioned ~2s after the baseline. + return stablePolls >= 8 + } + } + return false + }, timeout, interval).Should(BeTrue(), "Ready condition should settle before capturing the baseline") + // Get initial generation and observed generation initialVMCP := &mcpv1beta1.VirtualMCPServer{} Expect(k8sClient.Get(ctx, types.NamespacedName{