Deflake CI: TUF warn mode, readiness diagnostics, test races

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{

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
 			}

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 := &regtypes.ImageMetadata{
+		Provenance: &regtypes.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:        &regtypes.ImageMetadata{},
+			verifySetting: VerifyImageWarn,
+		},
+		{
+			name:          "enabled without provenance fails",
+			server:        &regtypes.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:        &regtypes.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 {

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

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

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

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