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{ 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 { 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) } } 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}" 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) }