From 32ef61efc2d5d9070f80787e1daac45220595692 Mon Sep 17 00:00:00 2001 From: Carl de Billy Date: Tue, 22 Sep 2026 18:04:01 -0400 Subject: [PATCH 1/2] feat(mcp): log the failures the server hides from its clients MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Repl.Mcp had no logging at all, yet three of its paths absorb a failure on purpose: a command's failure detail is withheld from the remote client, a failed catalog rebuild is hidden behind the connection's previous catalog, and a failed roots prime is swallowed so a command that never reads roots still runs. Each was right for the client and left the operator with nothing — InvalidateRouting() looking like a no-op for as long as a rebuild kept failing, or a client stalling on roots/list invisibly. McpLoggerDiagnostics follows ReplResultFlowLoggerDiagnostics: the ILoggerFactory is taken from the services when present, NullLoggerFactory otherwise, under the category "Repl.Mcp", with source-generated [LoggerMessage] methods (event ids 2001-2006). No wiring changes: AddReplLogging() already reaches every MCP path. The two failures that can repeat on every request warn once per episode and log repeats at Debug. The stale catalog is republished stale, so every request retries the build — tools/call and prompts/get included, on every connection — and logging each retry would repeat the same exception for as long as the failure lasts. The episode is tracked per connection and per failing routing version, under the SnapshotGate that already serialises those builds, and a successful rebuild logs the recovery. The roots prime tracks its episode with an Interlocked flag, since concurrent tool calls prime concurrently. TDD: all three tests red first, with only the log assertion failing. Each policy was then falsified with a substitution that still compiles — warning on every retry, dropping the recovery log, inverting which failure of an episode warns, dropping the rendered detail — and each turned exactly its own test red. Refs #99 --- docs/mcp-reference.md | 21 +++ src/Repl.Mcp/McpClientRootsService.cs | 22 ++- src/Repl.Mcp/McpLoggerDiagnostics.cs | 46 ++++++ src/Repl.Mcp/McpServerHandler.cs | 22 ++- src/Repl.Mcp/McpSessionContext.cs | 34 ++++ src/Repl.Mcp/McpToolAdapter.cs | 11 +- src/Repl.McpTests/Given_McpDiagnostics.cs | 187 ++++++++++++++++++++++ 7 files changed, 338 insertions(+), 5 deletions(-) create mode 100644 src/Repl.Mcp/McpLoggerDiagnostics.cs create mode 100644 src/Repl.McpTests/Given_McpDiagnostics.cs diff --git a/docs/mcp-reference.md b/docs/mcp-reference.md index 3c55633..86e2c26 100644 --- a/docs/mcp-reference.md +++ b/docs/mcp-reference.md @@ -515,6 +515,27 @@ Command-backed resources expose the rendered handler return value as the resource body. Low-level writes to `IReplIoContext.Output` are treated as side-channel command output and are not included in `resources/read` bodies. +## Operator diagnostics + +Some failures are hidden from the MCP client on purpose. `Repl.Mcp` records them for the operator +through `Microsoft.Extensions.Logging`, under the category `Repl.Mcp`: + +| Event | Level | What the client saw instead | +|---|---|---| +| 2001 | Error | A command failed with a detail that is not meant for a remote caller, such as an unhandled exception's message. The client gets `Command failed with exit code N.`; the log gets the exception and the rendered detail. | +| 2002 | Warning | A catalog rebuild failed on an initialize-era connection. That connection keeps its previous catalog until a rebuild succeeds or a visibility retraction withdraws it. | +| 2003 | Warning | Priming the client's roots failed. The command still ran. | +| 2004 | Debug | 2002 again for the same routing version. | +| 2005 | Information | A rebuild succeeded after a 2002. | +| 2006 | Debug | 2003 again before any prime succeeded. | + +A failure that can repeat on every request warns once per episode and logs its repeats at Debug, so a +client that keeps asking cannot flood the log. + +`ReplApp` registers logging by default, but it stays silent until the app adds a provider. Under +`mcp serve` on stdio, standard output carries the protocol, so send logs to standard error or a file. +For the console provider, set `LogToStandardErrorThreshold = LogLevel.Trace`. + ## Client compatibility Feature support varies across agents. Check [mcp-availability.com](https://mcp-availability.com/) for current data. diff --git a/src/Repl.Mcp/McpClientRootsService.cs b/src/Repl.Mcp/McpClientRootsService.cs index 058b34f..214233f 100644 --- a/src/Repl.Mcp/McpClientRootsService.cs +++ b/src/Repl.Mcp/McpClientRootsService.cs @@ -18,6 +18,9 @@ internal sealed class McpClientRootsService : IMcpClientRoots private readonly ICoreReplApp _app; private readonly McpRequestServerAccessor _servers; private readonly McpRootsScope _scope; + // 1 while a failure to prime is being reported at Debug instead of Warning; reset by a successful + // prime. Interlocked, since concurrent tool calls on one connection prime concurrently. + private int _primeFailureReported; private readonly Lock _syncRoot = new(); // Bounds the one outbound call this type makes. Request scope pays it per request rather than once // per connection, so a client that never answers roots/list would otherwise hold every tool call @@ -384,7 +387,8 @@ private async Task> FetchHardRootsOnceAsync(McpServ } /// - /// Primes the connection's native roots from , swallowing a failure. + /// Primes the connection's native roots from , logging and swallowing a + /// failure. /// /// /// Called from every execution entry point. A handler that never reads roots must not fail because @@ -403,14 +407,26 @@ internal static async ValueTask PrimeFromServicesAsync( try { await roots.PrimeCurrentAsync(cancellationToken).ConfigureAwait(false); + Interlocked.Exchange(ref roots._primeFailureReported, 0); } catch (OperationCanceledException) when (cancellationToken.IsCancellationRequested) { throw; } - catch (Exception) + catch (Exception ex) { - // Swallowed: see the remarks above. + // Swallowed for the command (see the remarks above), not for the operator. Warned once per + // failure episode: a fast failure is retried on every tool call, where the prime cooldown only + // covers one that exhausted its budget. Built only here, so a successful prime pays nothing. + var diagnostics = new McpLoggerDiagnostics(services); + if (Interlocked.Exchange(ref roots._primeFailureReported, 1) == 0) + { + diagnostics.RootsPrimeFailed(ex); + } + else + { + diagnostics.RootsPrimeStillFailing(ex); + } } } diff --git a/src/Repl.Mcp/McpLoggerDiagnostics.cs b/src/Repl.Mcp/McpLoggerDiagnostics.cs new file mode 100644 index 0000000..667243d --- /dev/null +++ b/src/Repl.Mcp/McpLoggerDiagnostics.cs @@ -0,0 +1,46 @@ +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Logging.Abstractions; + +namespace Repl.Mcp; + +/// +/// Operator-facing record of the failures this package absorbs on purpose. Each one is withheld from, +/// or hidden behind a fallback for, the remote MCP client by design; this is what keeps it from also +/// disappearing for the operator. +/// +/// +/// Event ids 2000-2999 belong to this package; Repl.Logging uses the 1000 range. A failure that +/// can repeat on every request warns once per episode and logs its repeats at Debug, so a client that +/// keeps asking cannot flood the operator's log with the same exception. +/// +internal sealed partial class McpLoggerDiagnostics +{ + private const string LoggerCategory = "Repl.Mcp"; + private readonly ILogger _logger; + + public McpLoggerDiagnostics(IServiceProvider services) + { + ArgumentNullException.ThrowIfNull(services); + var loggerFactory = services.GetService(typeof(ILoggerFactory)) as ILoggerFactory + ?? NullLoggerFactory.Instance; + _logger = loggerFactory.CreateLogger(LoggerCategory); + } + + [LoggerMessage(EventId = 2001, Level = LogLevel.Error, Message = "An MCP command failed with exit code {ExitCode}; the client received a generic message instead of this detail: {Detail}")] + public partial void ToolFailureWithheld(Exception? exception, int exitCode, string detail); + + [LoggerMessage(EventId = 2002, Level = LogLevel.Warning, Message = "Building the MCP catalog at routing version {FailingVersion} failed; the connection keeps its previous catalog (version {ServedVersion}) until a rebuild succeeds or a visibility retraction withdraws it. Repeats are logged at Debug.")] + public partial void StaleCatalogServed(Exception exception, long failingVersion, long servedVersion); + + [LoggerMessage(EventId = 2003, Level = LogLevel.Warning, Message = "Priming the MCP client's roots failed; commands still run, and a handler that reads roots asks the client again. Repeats are logged at Debug until a prime succeeds.")] + public partial void RootsPrimeFailed(Exception exception); + + [LoggerMessage(EventId = 2004, Level = LogLevel.Debug, Message = "Building the MCP catalog at routing version {FailingVersion} failed again; the previous catalog is still served.")] + public partial void StaleCatalogStillServed(Exception exception, long failingVersion); + + [LoggerMessage(EventId = 2005, Level = LogLevel.Information, Message = "The MCP catalog was rebuilt at routing version {Version} after a failure; the connection serves the current catalog again.")] + public partial void CatalogRecovered(long version); + + [LoggerMessage(EventId = 2006, Level = LogLevel.Debug, Message = "Priming the MCP client's roots failed again.")] + public partial void RootsPrimeStillFailing(Exception exception); +} diff --git a/src/Repl.Mcp/McpServerHandler.cs b/src/Repl.Mcp/McpServerHandler.cs index 4f7bf72..ddd79f9 100644 --- a/src/Repl.Mcp/McpServerHandler.cs +++ b/src/Repl.Mcp/McpServerHandler.cs @@ -33,6 +33,7 @@ internal sealed class McpServerHandler private readonly McpSamplingService _sampling; private readonly McpElicitationService _elicitation; private readonly McpFeedbackService _feedback; + private readonly McpLoggerDiagnostics _diagnostics; // Context for work that belongs to no MCP session: eager fail-fast validation, the pre-built // catalog behind BuildMcpServerOptions, and the snapshot test seams. One per handler, sharing its // lifetime, so nothing disposes it — and CreateSessionContext deliberately opens it no DI scope to @@ -101,6 +102,7 @@ public McpServerHandler( _sampling = new McpSamplingService(_requestServers); _elicitation = new McpElicitationService(_requestServers); _feedback = new McpFeedbackService(_requestServers); + _diagnostics = new McpLoggerDiagnostics(services); _catalogContext = CreateSessionContext(McpRootsScope.Request); } @@ -500,6 +502,11 @@ private async ValueTask BuildOrServePreviousAsync( { var built = await BuildCurrentSnapshotAsync(context, snapshotVersion, sessionless, cancellationToken) .ConfigureAwait(false); + if (context.TryClearCatalogFailure()) + { + _diagnostics.CatalogRecovered(snapshotVersion); + } + return built; } // Filtered on the caller's own token, like every other cancellation catch here: a projection @@ -515,7 +522,7 @@ private async ValueTask BuildOrServePreviousAsync( ThrowSanitizedIfAClientAlreadyHasASchema(previousSnapshot); throw; } - catch (Exception) when (IsFallbackEligible(context, sessionless)) + catch (Exception ex) when (IsFallbackEligible(context, sessionless)) { // Preserve availability for transient projection failures, but republish as stale so the // next request retries without requiring another routing mutation. The entry keeps the @@ -530,6 +537,19 @@ private async ValueTask BuildOrServePreviousAsync( throw; } + // The client cannot tell a stale catalog from a current one, so the operator log is the only + // sign the failure is going on. Warned once per failing version: the fallback is republished + // stale, so every request retries the build — tools/call and prompts/get included, on every + // connection — and would otherwise repeat the same exception each time. + if (context.TryMarkCatalogFailure(snapshotVersion)) + { + _diagnostics.StaleCatalogServed(ex, snapshotVersion, fallback.Version); + } + else + { + _diagnostics.StaleCatalogStillServed(ex, snapshotVersion); + } + context.PublishStaleSnapshot(fallback.Snapshot, fallback.Version, fallback.Sessionless); return fallback.Snapshot; } diff --git a/src/Repl.Mcp/McpSessionContext.cs b/src/Repl.Mcp/McpSessionContext.cs index e90aacb..c01e3d5 100644 --- a/src/Repl.Mcp/McpSessionContext.cs +++ b/src/Repl.Mcp/McpSessionContext.cs @@ -22,6 +22,9 @@ internal sealed class McpSessionContext : IAsyncDisposable { private SnapshotCacheEntry? _snapshotCache; private int _compatibilityIntroServed; + // The routing version whose build last failed onto the availability fallback, or 0 for none — + // versions start at 1. Read and written only under SnapshotGate, like the cache it describes. + private long _catalogFailureVersion; private readonly AsyncServiceScope? _scope; @@ -67,6 +70,37 @@ public void PublishStaleSnapshot( bool sessionless) => Volatile.Write(ref _snapshotCache, new SnapshotCacheEntry(snapshot, version, IsStale: true, sessionless)); + /// + /// Records that the build for failed onto the fallback; + /// the first time for that version, so the failure warns once rather than + /// on every request that retries it. Call only under . + /// + public bool TryMarkCatalogFailure(long failingVersion) + { + if (_catalogFailureVersion == failingVersion) + { + return false; + } + + _catalogFailureVersion = failingVersion; + return true; + } + + /// + /// Ends a failure episode after a successful build; if one was in progress. + /// Call only under . + /// + public bool TryClearCatalogFailure() + { + if (_catalogFailureVersion == 0) + { + return false; + } + + _catalogFailureVersion = 0; + return true; + } + /// /// Claims this session's one-time compatibility-shim intro; for the first /// caller only. diff --git a/src/Repl.Mcp/McpToolAdapter.cs b/src/Repl.Mcp/McpToolAdapter.cs index f19cb53..fb7bab5 100644 --- a/src/Repl.Mcp/McpToolAdapter.cs +++ b/src/Repl.Mcp/McpToolAdapter.cs @@ -24,6 +24,7 @@ internal sealed partial class McpToolAdapter private readonly ReplMcpServerOptions _options; private readonly IServiceProvider _services; private readonly McpRequestServerAccessor _requestServers; + private readonly McpLoggerDiagnostics _diagnostics; // Whether the catalog this adapter serves was built from the frozen discovery view. A property of // the catalog, not of the request: a reusable BuildMcpServerOptions() result is frozen once and then // serves clients of either era, so asking the request would leave an initialize-era caller unable to @@ -44,6 +45,7 @@ public McpToolAdapter( _services = services; _requestServers = requestServers; _catalogIsFrozen = catalogIsFrozen; + _diagnostics = new McpLoggerDiagnostics(services); } /// @@ -323,11 +325,18 @@ public static CommandOutputCapture Create(bool captureCommandOutput) /// unable to say what it needs. /// /// - private static string DescribeFailure(in McpPipelineInvocation invocation) + private string DescribeFailure(in McpPipelineInvocation invocation) { var withheld = $"Command failed with exit code {invocation.ExitCode}."; if (WithholdsFailureText(invocation)) { + // Withheld from the client, not discarded: the rendered detail and the exception behind it + // are exactly what the operator needs, and the log is the one reader that should get them. + var detail = string.IsNullOrWhiteSpace(invocation.Output) ? invocation.Error : invocation.Output; + _diagnostics.ToolFailureWithheld( + invocation.Failure, + invocation.ExitCode, + string.IsNullOrWhiteSpace(detail) ? "(nothing was rendered)" : detail); return withheld; } diff --git a/src/Repl.McpTests/Given_McpDiagnostics.cs b/src/Repl.McpTests/Given_McpDiagnostics.cs new file mode 100644 index 0000000..2dc9578 --- /dev/null +++ b/src/Repl.McpTests/Given_McpDiagnostics.cs @@ -0,0 +1,187 @@ +using System.Collections.Concurrent; +using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.Logging; +using ModelContextProtocol.Client; +using ModelContextProtocol.Protocol; +using Repl.Mcp; + +namespace Repl.McpTests; + +/// +/// Repl.Mcp absorbs three failures by design: a tool failure's detail is withheld from the client, a +/// failed catalog build is hidden behind the previous catalog, and a failed roots prime is swallowed. +/// Each must still reach the operator's log — once per episode, not once per request that retries it. +/// +[TestClass] +public sealed class Given_McpDiagnostics +{ + // The category and event ids are what an operator filters on, so the tests pin them rather than + // matching any entry that happens to carry an exception. + private const string Category = "Repl.Mcp"; + private const int ToolFailureWithheldEvent = 2001; + private const int StaleCatalogServedEvent = 2002; + private const int RootsPrimeFailedEvent = 2003; + private const int StaleCatalogStillServedEvent = 2004; + private const int CatalogRecoveredEvent = 2005; + private const int RootsPrimeStillFailingEvent = 2006; + + [TestMethod] + [Description("A tool call that fails with a withheld detail (an unhandled exception, not McpException/McpInteractionException) must still record that detail for the operator: the client's generic 'Command failed' message is deliberate, discarding invocation.Failure and its rendered text entirely is not.")] + public async Task When_AToolFailureDetailIsWithheld_Then_TheOperatorSinkRecordsIt() + { + var provider = new CapturingLoggerProvider(); + await using var fixture = await McpTestFixture.CreateAsync( + app => app.Map("boom", object () => throw new InvalidOperationException("secret-detail")), + services => CaptureLogs(services, provider)).ConfigureAwait(false); + + var result = await CallAsync(fixture.Client, "boom").ConfigureAwait(false); + + result.Should().NotContain("secret-detail", "the withheld detail must not reach the remote client"); + var entry = provider.Single(ToolFailureWithheldEvent); + entry.Category.Should().Be(Category); + entry.Level.Should().Be(LogLevel.Error); + entry.Exception.Should().BeOfType().Which.Message.Should().Be("secret-detail"); + entry.Message.Should().Contain("secret-detail", "the rendered detail the client did not get belongs in the message"); + } + + [TestMethod] + [Description("Roots priming swallows everything but the caller's own cancellation by design: every execution entry point primes, and a handler that never reads roots must not fail because the client could not answer. The failure must still reach the operator — but a fast failure is retried on every tool call, so only the first of an episode warns and the repeats go to Debug.")] + public async Task When_RootsPrimingKeepsFailing_Then_OnlyTheFirstFailureWarns() + { + var provider = new CapturingLoggerProvider(); + await using var fixture = await McpTestFixture.CreateAsync( + app => app.Map("touch", () => "ok"), + configureOptions: null, + clientOptions: CreateBrokenRootsClient(), + configureServices: services => CaptureLogs(services, provider)).ConfigureAwait(false); + + await CallAsync(fixture.Client, "touch").ConfigureAwait(false); + + var warning = provider.Single(RootsPrimeFailedEvent); + warning.Category.Should().Be(Category); + warning.Level.Should().Be(LogLevel.Warning); + warning.Exception.Should().BeOfType("the client answered roots/list with an unparseable URI"); + provider.Count(RootsPrimeStillFailingEvent).Should().Be(0, "the first failure of an episode is the one that warns"); + + await CallAsync(fixture.Client, "touch").ConfigureAwait(false); + + provider.Count(RootsPrimeFailedEvent).Should().Be(1, "a repeat of the same episode must not warn again"); + provider.Count(RootsPrimeStillFailingEvent).Should().Be(1, "the repeat is still recorded, at Debug"); + } + + [TestMethod] + [Description("The availability fallback re-serves an initialize-era connection's previous catalog when a build fails, and republishes it stale, so every request retries the build. The failure must reach the operator — once, as a warning, rather than once per request for as long as it lasts — and the end of the episode must be visible too, or a quiet log would read as 'still failing'.")] + public async Task When_AStaleCatalogIsServedUntilRecovery_Then_ItWarnsOnceAndLogsTheRecovery() + { + var provider = new CapturingLoggerProvider(); + var app = ReplApp.Create(services => CaptureLogs(services, provider)); + app.UseMcpServer(); + app.Map("initial", () => "ok"); + var options = new ReplMcpServerOptions { TransportFactory = McpTestFixture.PipeTransportFactory }; + var handler = new McpServerHandler(app.Core, options, app.Services); + + using var cts = new CancellationTokenSource(TimeSpan.FromSeconds(30)); + var session = await McpPipeSession.StartAsync( + handler.RunAsync, + new McpClientOptions { ProtocolVersion = McpProtocolRevisions.LastWithSessions }, + cts.Token).ConfigureAwait(false); + await using var sessionScope = session.ConfigureAwait(false); + + await session.Client.ListToolsAsync(cancellationToken: cts.Token).ConfigureAwait(false); + options.CommandFilter = _ => throw new InvalidOperationException("projection-boom"); + app.Core.InvalidateRouting(); + + var stale = await session.Client.ListToolsAsync(cancellationToken: cts.Token).ConfigureAwait(false); + + stale.Should().ContainSingle( + tool => string.Equals(tool.Name, "initial", StringComparison.Ordinal), + "the fallback itself is unchanged: the previous catalog is still served"); + var warning = provider.Single(StaleCatalogServedEvent); + warning.Category.Should().Be(Category); + warning.Level.Should().Be(LogLevel.Warning); + warning.Exception.Should().BeOfType().Which.Message.Should().Be("projection-boom"); + provider.Count(StaleCatalogStillServedEvent).Should().Be(0, "the first failure of an episode is the one that warns"); + + await session.Client.ListToolsAsync(cancellationToken: cts.Token).ConfigureAwait(false); + + provider.Count(StaleCatalogServedEvent).Should().Be(1, "a retry of the same failing version must not warn again"); + provider.Count(StaleCatalogStillServedEvent).Should().BeGreaterThan(0, "the retry's failure is still recorded, at Debug"); + provider.Count(CatalogRecoveredEvent).Should().Be(0, "nothing has recovered yet"); + + options.CommandFilter = null; + await session.Client.ListToolsAsync(cancellationToken: cts.Token).ConfigureAwait(false); + + provider.Single(CatalogRecoveredEvent).Level.Should().Be(LogLevel.Information); + provider.Count(StaleCatalogServedEvent).Should().Be(1, "recovering must not re-warn the episode it just ended"); + } + + private static void CaptureLogs(IServiceCollection services, CapturingLoggerProvider provider) => + services.AddLogging(builder => + { + builder.ClearProviders(); + builder.SetMinimumLevel(LogLevel.Debug); + builder.AddProvider(provider); + }); + + private static McpClientOptions CreateBrokenRootsClient() + { + // Roots is deprecated by MCP spec 2026-07-28 (SEP-2577), but hosts still use it and Repl keeps + // supporting it until the SDK removes the surface (#51). +#pragma warning disable MCP9005 + return new McpClientOptions + { + Capabilities = new ClientCapabilities { Roots = new RootsCapability() }, + Handlers = new McpClientHandlers + { + // An unparseable URI fails server-side while being mapped — a real fetch failure that needs + // no client-side throw, which would escape the SDK's own message loop instead. + RootsHandler = static (_, _) => ValueTask.FromResult(new ListRootsResult + { + Roots = [new Root { Uri = "http://", Name = "invalid" }], + }), + }, + }; +#pragma warning restore MCP9005 + } + + private static async Task CallAsync(McpClient client, string tool) + { + var result = await client.CallToolAsync( + toolName: tool, + arguments: new Dictionary(StringComparer.Ordinal)).ConfigureAwait(false); + return result.Content.OfType().First().Text; + } + + // Concurrent because the server logs from its own threads while the test reads from another. + private sealed class CapturingLoggerProvider : ILoggerProvider + { + private readonly ConcurrentQueue _entries = new(); + + public ILogger CreateLogger(string categoryName) => new CapturingLogger(categoryName, _entries); + + public CapturedLogEntry Single(int eventId) => _entries.Should().ContainSingle(entry => entry.EventId == eventId).Subject; + + public int Count(int eventId) => _entries.Count(entry => entry.EventId == eventId); + + public void Dispose() + { + } + } + + private sealed class CapturingLogger(string categoryName, ConcurrentQueue entries) : ILogger + { + public IDisposable? BeginScope(TState state) where TState : notnull => null; + + public bool IsEnabled(LogLevel logLevel) => true; + + public void Log( + LogLevel logLevel, + EventId eventId, + TState state, + Exception? exception, + Func formatter) => + entries.Enqueue(new CapturedLogEntry(categoryName, logLevel, eventId.Id, formatter(state, exception), exception)); + } + + private sealed record CapturedLogEntry(string Category, LogLevel Level, int EventId, string Message, Exception? Exception); +} From d46dfc65d37b055f524f0a86498f2d35c0815025 Mon Sep 17 00:00:00 2001 From: Carl de Billy Date: Tue, 22 Sep 2026 18:22:29 -0400 Subject: [PATCH 2/2] fix(mcp): end a failure episode only on what actually recovered MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Two ways the once-per-episode logging ended an episode that had not ended, both raised in review on #106. A roots prime skipped during the stand-down after a slow failure returned normally, and a normal return reset the episode — so once the stand-down lifted and the still-broken client failed again, the same outage warned a second time. PrimeCurrentAsync now reports whether it actually fetched, and only a real fetch ends the episode. The catalog recovery was logged at the version the build set out to serve, and whenever the build returned. A build that races a routing change is republished stale, and one that races a visibility retraction starts over at a newer version. The recovery is now read back from the entry actually published: only a current one ends the episode, and it is logged at the version it was built at. TDD: each of the three new tests red first for the reason given in review — a second 2003 after the skipped prime; a 2005 while the published catalog was still stale; a 2005 naming version 2 when version 3 was published. Each fix was then falsified with a compiling substitution and turned its own test red. Refs #99 --- src/Repl.Mcp/McpClientRootsService.cs | 20 ++- src/Repl.Mcp/McpServerHandler.cs | 7 +- src/Repl.McpTests/Given_McpDiagnostics.cs | 150 +++++++++++++++++++++- 3 files changed, 166 insertions(+), 11 deletions(-) diff --git a/src/Repl.Mcp/McpClientRootsService.cs b/src/Repl.Mcp/McpClientRootsService.cs index 214233f..9f96620 100644 --- a/src/Repl.Mcp/McpClientRootsService.cs +++ b/src/Repl.Mcp/McpClientRootsService.cs @@ -122,11 +122,15 @@ public IReadOnlyList Current /// is documented as only what this request already resolved, and an eager fetch /// would add a round-trip to every request rather than to every connection. /// - internal async ValueTask PrimeCurrentAsync(CancellationToken cancellationToken) + /// + /// only when roots were actually fetched; when the + /// prime did not ask at all — outside connection scope, without client support, or standing down. + /// + internal async ValueTask PrimeCurrentAsync(CancellationToken cancellationToken) { if (_scope is not McpRootsScope.Connection || !IsSupported) { - return; + return false; } lock (_syncRoot) @@ -137,7 +141,7 @@ internal async ValueTask PrimeCurrentAsync(CancellationToken cancellationToken) && _primeFailedAt is { } failedAt && Stopwatch.GetElapsedTime(failedAt) < PrimeRetryCooldown) { - return; + return false; } } @@ -178,6 +182,8 @@ internal async ValueTask PrimeCurrentAsync(CancellationToken cancellationToken) { _primeFailedAt = null; } + + return true; } public async ValueTask> GetAsync(CancellationToken cancellationToken = default) @@ -406,8 +412,12 @@ internal static async ValueTask PrimeFromServicesAsync( try { - await roots.PrimeCurrentAsync(cancellationToken).ConfigureAwait(false); - Interlocked.Exchange(ref roots._primeFailureReported, 0); + // Only a prime that actually asked ends the episode: one skipped while standing down says + // nothing about whether the client can answer yet. + if (await roots.PrimeCurrentAsync(cancellationToken).ConfigureAwait(false)) + { + Interlocked.Exchange(ref roots._primeFailureReported, 0); + } } catch (OperationCanceledException) when (cancellationToken.IsCancellationRequested) { diff --git a/src/Repl.Mcp/McpServerHandler.cs b/src/Repl.Mcp/McpServerHandler.cs index ddd79f9..0e95a7c 100644 --- a/src/Repl.Mcp/McpServerHandler.cs +++ b/src/Repl.Mcp/McpServerHandler.cs @@ -502,9 +502,12 @@ private async ValueTask BuildOrServePreviousAsync( { var built = await BuildCurrentSnapshotAsync(context, snapshotVersion, sessionless, cancellationToken) .ConfigureAwait(false); - if (context.TryClearCatalogFailure()) + // Read back what was just published rather than trusting snapshotVersion: a build that raced a + // routing change is republished stale, and one that raced a retraction is rebuilt at a newer + // version. Only a current entry ends the episode, and it is logged at the version it was built. + if (context.SnapshotCache is { IsStale: false } published && context.TryClearCatalogFailure()) { - _diagnostics.CatalogRecovered(snapshotVersion); + _diagnostics.CatalogRecovered(published.Version); } return built; diff --git a/src/Repl.McpTests/Given_McpDiagnostics.cs b/src/Repl.McpTests/Given_McpDiagnostics.cs index 2dc9578..07a83f5 100644 --- a/src/Repl.McpTests/Given_McpDiagnostics.cs +++ b/src/Repl.McpTests/Given_McpDiagnostics.cs @@ -69,6 +69,51 @@ public async Task When_RootsPrimingKeepsFailing_Then_OnlyTheFirstFailureWarns() provider.Count(RootsPrimeStillFailingEvent).Should().Be(1, "the repeat is still recorded, at Debug"); } + [TestMethod] + [Description("A prime skipped because the connection is standing down after a slow failure is not a successful prime, so it must not end the failure episode. Resetting on any normal return made the next real failure — once the stand-down lifts — warn again, so one ongoing outage produced repeated 2003 warnings. roots/list_changed lifts the stand-down on purpose; the routing invalidation it raises right after, in the same handler, orders the lift before the next call.")] + public async Task When_AStandDownSkipsThePrime_Then_TheFailureEpisodeIsNotReset() + { + var provider = new CapturingLoggerProvider(); + var fetches = 0; + var slowNext = 0; + // Longer than half the ten-second roots budget, which is what makes a failure worth standing + // down for; well under the budget itself, so the fetch fails on the bad URI rather than timing out. + var slowFailure = TimeSpan.FromSeconds(5.5); + await using var fixture = await McpTestFixture.CreateAsync( + app => app.Map("touch", () => "ok"), + configureOptions: null, + clientOptions: CreateBrokenRootsClient(async cancellationToken => + { + Interlocked.Increment(ref fetches); + if (Interlocked.Exchange(ref slowNext, 0) == 1) + { + await Task.Delay(slowFailure, cancellationToken).ConfigureAwait(false); + } + }), + configureServices: services => CaptureLogs(services, provider)).ConfigureAwait(false); + var standDownLifted = new TaskCompletionSource(TaskCreationOptions.RunContinuationsAsynchronously); + fixture.App.Core.RoutingInvalidated += (_, _) => standDownLifted.TrySetResult(); + + // Opens the episode with a fast failure, which does not stand the prime down. + await CallAsync(fixture.Client, "touch").ConfigureAwait(false); + provider.Count(RootsPrimeFailedEvent).Should().Be(1); + + Volatile.Write(ref slowNext, 1); + await CallAsync(fixture.Client, "touch").ConfigureAwait(false); + var afterSlowFailure = Volatile.Read(ref fetches); + await CallAsync(fixture.Client, "touch").ConfigureAwait(false); + Volatile.Read(ref fetches).Should().Be(afterSlowFailure, "the slow failure stood the prime down, so this call asked nothing"); + +#pragma warning disable MCP9005 + await fixture.Client.SendNotificationAsync(NotificationMethods.RootsListChangedNotification).ConfigureAwait(false); +#pragma warning restore MCP9005 + await standDownLifted.Task.WaitAsync(TimeSpan.FromSeconds(10)).ConfigureAwait(false); + await CallAsync(fixture.Client, "touch").ConfigureAwait(false); + + Volatile.Read(ref fetches).Should().BeGreaterThan(afterSlowFailure, "roots/list_changed lifted the stand-down"); + provider.Count(RootsPrimeFailedEvent).Should().Be(1, "the skipped prime did not end the episode, so no failure in it warns again"); + } + [TestMethod] [Description("The availability fallback re-serves an initialize-era connection's previous catalog when a build fails, and republishes it stale, so every request retries the build. The failure must reach the operator — once, as a warning, rather than once per request for as long as it lasts — and the end of the episode must be visible too, or a quiet log would read as 'still failing'.")] public async Task When_AStaleCatalogIsServedUntilRecovery_Then_ItWarnsOnceAndLogsTheRecovery() @@ -115,6 +160,97 @@ public async Task When_AStaleCatalogIsServedUntilRecovery_Then_ItWarnsOnceAndLog provider.Count(StaleCatalogServedEvent).Should().Be(1, "recovering must not re-warn the episode it just ended"); } + [TestMethod] + [Description("Recovery is logged for the catalog actually published, not for the version the build set out to serve. A rebuild that succeeds while routing moves under it is republished stale, so the connection does not serve the current catalog yet — announcing recovery then, with the version the build started at, would tell the operator a failure had ended that the next request may still hit.")] + public async Task When_RoutingMovesDuringTheRecoveryBuild_Then_RecoveryWaitsForACurrentCatalog() + { + var provider = new CapturingLoggerProvider(); + var app = ReplApp.Create(services => CaptureLogs(services, provider)); + app.UseMcpServer(); + app.Map("initial", () => "ok"); + var options = new ReplMcpServerOptions { TransportFactory = McpTestFixture.PipeTransportFactory }; + var handler = new McpServerHandler(app.Core, options, app.Services); + + using var cts = new CancellationTokenSource(TimeSpan.FromSeconds(30)); + var session = await McpPipeSession.StartAsync( + handler.RunAsync, + new McpClientOptions { ProtocolVersion = McpProtocolRevisions.LastWithSessions }, + cts.Token).ConfigureAwait(false); + await using var sessionScope = session.ConfigureAwait(false); + + await session.Client.ListToolsAsync(cancellationToken: cts.Token).ConfigureAwait(false); + options.CommandFilter = _ => throw new InvalidOperationException("projection-boom"); + app.Core.InvalidateRouting(); + await session.Client.ListToolsAsync(cancellationToken: cts.Token).ConfigureAwait(false); + provider.Count(StaleCatalogServedEvent).Should().Be(1); + + // The recovery build succeeds, but invalidates routing while it runs — the build it returns is + // republished stale. + var moveRoutingOnce = 1; + options.CommandFilter = _ => + { + if (Interlocked.Exchange(ref moveRoutingOnce, 0) == 1) + { + app.Core.InvalidateRouting(); + } + + return true; + }; + await session.Client.ListToolsAsync(cancellationToken: cts.Token).ConfigureAwait(false); + + provider.Count(CatalogRecoveredEvent).Should().Be(0, "the catalog that build published is already stale"); + + await session.Client.ListToolsAsync(cancellationToken: cts.Token).ConfigureAwait(false); + + provider.Single(CatalogRecoveredEvent).Message.Should().Contain( + "version 3", + "the recovery is the build at the routing version that moved during the first attempt"); + } + + [TestMethod] + [Description("A recovery build that races a visibility retraction starts over at the newer version and publishes that one. The recovery must be logged at the version actually published, not the one the build set out to serve, or the operator is told the connection recovered at a routing version it never served.")] + public async Task When_ARetractionRestartsTheRecoveryBuild_Then_RecoveryIsLoggedAtThePublishedVersion() + { + var provider = new CapturingLoggerProvider(); + var app = ReplApp.Create(services => CaptureLogs(services, provider)); + app.UseMcpServer(); + app.Map("initial", () => "ok"); + var extra = app.Map("extra", () => "x"); + var options = new ReplMcpServerOptions { TransportFactory = McpTestFixture.PipeTransportFactory }; + var handler = new McpServerHandler(app.Core, options, app.Services); + + using var cts = new CancellationTokenSource(TimeSpan.FromSeconds(30)); + var session = await McpPipeSession.StartAsync( + handler.RunAsync, + new McpClientOptions { ProtocolVersion = McpProtocolRevisions.LastWithSessions }, + cts.Token).ConfigureAwait(false); + await using var sessionScope = session.ConfigureAwait(false); + + // Version 1 is served; the failing rebuild is requested at version 2. + await session.Client.ListToolsAsync(cancellationToken: cts.Token).ConfigureAwait(false); + options.CommandFilter = _ => throw new InvalidOperationException("projection-boom"); + app.Core.InvalidateRouting(); + await session.Client.ListToolsAsync(cancellationToken: cts.Token).ConfigureAwait(false); + provider.Count(StaleCatalogServedEvent).Should().Be(1); + + // The recovery build at version 2 hides a command while it runs: a visibility retraction to + // version 3, which makes the build discard its result and start over there. + var retractOnce = 1; + options.CommandFilter = _ => + { + if (Interlocked.Exchange(ref retractOnce, 0) == 1) + { + extra.Hidden(); + } + + return true; + }; + (await session.Client.ListToolsAsync(cancellationToken: cts.Token).ConfigureAwait(false)) + .Should().NotContain(tool => string.Equals(tool.Name, "extra", StringComparison.Ordinal)); + + provider.Single(CatalogRecoveredEvent).Message.Should().Contain("version 3"); + } + private static void CaptureLogs(IServiceCollection services, CapturingLoggerProvider provider) => services.AddLogging(builder => { @@ -123,7 +259,7 @@ private static void CaptureLogs(IServiceCollection services, CapturingLoggerProv builder.AddProvider(provider); }); - private static McpClientOptions CreateBrokenRootsClient() + private static McpClientOptions CreateBrokenRootsClient(Func? beforeAnswer = null) { // Roots is deprecated by MCP spec 2026-07-28 (SEP-2577), but hosts still use it and Repl keeps // supporting it until the SDK removes the surface (#51). @@ -135,10 +271,16 @@ private static McpClientOptions CreateBrokenRootsClient() { // An unparseable URI fails server-side while being mapped — a real fetch failure that needs // no client-side throw, which would escape the SDK's own message loop instead. - RootsHandler = static (_, _) => ValueTask.FromResult(new ListRootsResult + RootsHandler = async (_, cancellationToken) => { - Roots = [new Root { Uri = "http://", Name = "invalid" }], - }), + var invalid = new Root { Uri = "http://", Name = "invalid" }; + if (beforeAnswer is not null) + { + await beforeAnswer(cancellationToken).ConfigureAwait(false); + } + + return new ListRootsResult { Roots = [invalid] }; + }, }, }; #pragma warning restore MCP9005