Log and answer web-viewer read failures instead of an empty 500 (#4276)

[erikdarlingdata]

Closes #4276.

Why

A web-viewer read that ran past the viewer role's 15-second statement_timeout came back as an empty HTTP 500, and nothing went into the service log. /api/ag, /api/fleet and other routes had no try/catch of their own. Their exception reached ASP.NET Core's own error handling. That handling writes to the log providers that DarlingWebHostService clears on purpose, to keep request noise out of the service log. The only trace was in PostgreSQL's own log.

What changes

• A new shared helper, DarlingWebFailureLog (Darling/PerformanceMonitor.Darling.Service/Hosting/DarlingWebFailureLog.cs), tells a statement timeout apart from any other failure. A timeout is a PostgresException with SQLSTATE 57014, or an NpgsqlException that wraps a TimeoutException.
• The helper writes one log line per failure: a Warning for a timeout, an Error for anything else. The line names the route, the elapsed milliseconds, the kind of failure, the exception type and the SQLSTATE.
• The route comes from the request. So the helper cleans it with DarlingHttpRefusalLog.Sanitize before it logs it, the same way the refusal log cleans a Host header. A percent-encoded line break in a path cannot start a fake log line. (Commit db1c618.)
• The helper builds the {"error": "..."} body, the same shape DarlingWebEndpoints.ErrorResult already writes.
• One backstop exception handler sits in DarlingWebHostService.ConfigurePipeline, ahead of DarlingWebEndpoints.MapAll. MapAll is the only place /api/* routes are mapped, so the handler covers all of them.
  • A timeout answers 503 with this message: "The store took too long to answer this read. Try again in a moment."
  • Anything else answers 500 with a generic message. The response never carries the exception text.
  • A browser that left the page logs nothing and gets nothing written. That case is an OperationCanceledException while RequestAborted is cancelled.
  • If the response has already started, the handler only logs.
• The /api/read/* dispatcher (DarlingWebEndpoints.cs) now logs through the same helper when its own catch fires. It no longer turns a browser abort into a written body. It rethrows, and the backstop handles the abort.
• The viewer needs no change. classifyResponse in wwwroot/js/util.js already reads body.error for any response outside 2xx, and errorStrip shows it in the panel. apiGet and every panel loader go through it: pages/ag.js, pages/fleet.js, the Custom View loader in panels.js, and the server-tab composites.
• Lite has no web host, so there is nothing to mirror there (ruled).

Where the handler sits

The issue sketches the handler at the top of the web pipeline. It sits after UseResponseCompression, which stays first, and after the Host-header guard (the DNS-rebinding guard) and the network-mode auth gate. HostHeaderGuardTests pins that guard as the first app.Use middleware because of #1648, an exploited hole on the loopback bind. A handler ahead of the guard breaks that pin. It also puts new code ahead of a security gate for no gain, since both gates handle their own exceptions. The issue's real need still holds: the handler sits ahead of MapAll, so it covers every /api/* route.

Test plan

• Darling/Darling.Tests/DarlingWebFailureHandlingTests.cs is new. Its unit tests cover the classifier: both timeout shapes, the status code, the body and the log line.
• Four live TestServer tests run the real ConfigurePipeline, the pattern DarlingWebResponseCompressionTests set up in Darling: a live HTTP test for both hosts' gates, including /core #4128:
  • A route that throws a 57014 PostgresException returns 503 with the JSON body and writes exactly one Warning.
  • A generic exception returns 500 with no exception text and writes exactly one Error.
  • A browser abort writes no log line and no body.
  • A source pin checks that the handler is registered ahead of DarlingWebEndpoints.MapAll.
• Revert proof: with the wiring reverted (a scoped git stash), all four live tests fail. With it restored, they pass.
• Report_RouteCarriesCrLf_SanitizesSoNoForgedLineReachesTheLog passes a route that holds a CR/LF. It checks for exactly one log entry, with no line break in it. With the sanitize call removed, the test fails.
• After the sanitize fix and a merge of origin/dev: DarlingWebFailureHandlingTests 15/15 and HostHeaderGuardTests 46/46.
• PerformanceMonitor.Darling.Service and Darling.Tests build with 0 warnings.
• Targeted classes after the fixes, 86/86 pass: HostHeaderGuardTests, DarlingWebFailureHandlingTests, DarlingWebEditorAttributionTests, DarlingWebResponseCompressionTests, DarlingWebHostGateLiveTests.
• Full Darling.Tests suite, once, on a fresh darlingtest on a UTC rig after merging origin/dev: 13,975 total, 3 failed.
  • HostHeaderGuardTests.EachHost_InstallsTheHostHeaderGuard_AsItsFirstMiddleware failed because of this PR's first placement. The handler moved behind the guard, as described above, and the class passes.
  • TsqlConventionGuardTests.TheMemberScan_ReadsEveryDeclarationWhole failed because of this PR. DarlingWebFailureLog.IsStatementTimeout is an expression-bodied member, and the member-range walker reads its range short. PgBaselineProvider.IsCommandTimeout has the same harmless shape and is already on the allow list. DarlingWebFailureLog.cs IsStatementTimeout is now in KnownTruncatedRanges, as the test's failure message directs. The class passes alone, 14/14.
  • PgTargetAnomalyTests.TheAuroraWaitProfile_OneHotCollectionStaysQuiet_ASustainedShiftFires_AgainstDevPostgres is the known flake CI flake: PgTarget anomaly/blocking worst-tile assertions fail on first attempts unrelated to the change #4274 and touches none of this PR's files. It passed alone on the same rig, 44/44.
  • The full suite did not run again after those two fixes. CI runs it.
• Installer.Tests did not run, because the lane rules exclude them. No Lite test ran, since Lite has nothing to change.

CHANGELOG entry

SECTION: Fixed
ENTRY:

• Web viewer timeouts now show a message and get logged ([Log and answer web-viewer read failures instead of an empty 500 (#4276) #4281]) - A read that ran past the store's timeout used to show a blank error. The service log had nothing, so a timeout looked the same as a bug. Now the page says "The store took too long to answer this read. Try again in a moment." Other failures show a short generic message. For both, the service log records the route, how long the read ran and what kind of failure it was.
  REF:
  [Log and answer web-viewer read failures instead of an empty 500 (#4276) #4281]: Log and answer web-viewer read failures instead of an empty 500 (#4276) #4281

🤖 Generated with Claude Code

https://claude.ai/code/session_01FVjn4PBJN71NQXdFo6ZxNQ

[erikdarlingdata]

Pushed db1c618a to this branch, fixing the log-forging gap: DarlingWebFailureLog.Report wrote route into the log line unsanitized. The top-of-pipeline backstop passes context.Request.Path.Value straight off the wire. Kestrel decodes a percent-encoded CR/LF in a path into a real CR/LF. A crafted request path forged a second log line.

What changed

• DarlingWebFailureLog.Report now sanitizes once at the top: var safeRoute = DarlingHttpRefusalLog.Sanitize(route, 256);, and both the LogWarning (timeout) and LogError (generic failure) branches log safeRoute instead of route. 256, not the default 64, so a legitimate long API path is not truncated. Sanitizing inside Report covers both call sites: the backstop and the /api/read/* dispatcher.
• Updated Report's doc comment to say the route is request-supplied and sanitized the same way DarlingHttpRefusalLog.Sanitize handles a Host header.

Test

Added Report_RouteCarriesCrLf_SanitizesSoNoForgedLineReachesTheLog next to Report_GenericFailure_... in DarlingWebFailureHandlingTests.cs, using CapturingTestLogger:

DarlingWebFailureLog.Report(logger, "/api/ag\r\nForged: line", 5, new InvalidOperationException());

It asserts exactly one Error entry logged (CountAtLevel(Error) == 1, CountAtLevel(Warning) == 0). The joined log text contains neither \r nor \n, and does contain /api/ag..Forged: line (CR and LF each become a .).

Revert-proof: temporarily reverted Report to log the raw route (removed the sanitize call), rebuilt, and ran the new test alone. It failed as expected:

Report_RouteCarriesCrLf_SanitizesSoNoForgedLineReachesTheLog [FAIL]
  Assert.DoesNotContain() Failure: Sub-string found
Total: 1, Errors: 0, Failed: 1

Restored the sanitize call from a backup copy, confirmed the diff matched the original fix exactly, rebuilt clean (0 Warning(s), 0 Error(s)).

Test totals

• dotnet build Darling/Darling.Tests/Darling.Tests.csproj -c Debug: Build succeeded, 0 Warning(s), 0 Error(s).
• DarlingWebFailureHandlingTests: 15 total, 0 failed.
• HostHeaderGuardTests: 46 total, 0 failed.
• Both classes together: 61 total, 0 failed, 0 errors.

Other notes

• Branch was 1 commit behind origin/dev (MCP budget: default get_query_store_regressions under the response budget (#4198) #4264, query-store-regressions budget work). Merged it in with no conflicts (DarlingWebEndpoints.cs auto-merged) before pushing, then rebuilt and re-ran both classes clean.
• Touched only the two files in scope: Darling/PerformanceMonitor.Darling.Service/Hosting/DarlingWebFailureLog.cs and Darling/Darling.Tests/DarlingWebFailureHandlingTests.cs. Did not edit the PR body or CHANGELOG.md, per the brief.
• Did not run the full suite or a live-Postgres TestServer rig. Neither is needed for this change: it touches no store or database, and the brief scoped verification to the two named classes.

🤖 Generated with Claude Code

https://claude.ai/code/session_01TszxYhJJbTEh4LrZ56NYo3

[erikdarlingdata]

Round-1 security review (post-merge) at baaa4e0

Scope: the backstop in DarlingWebHostService.ConfigurePipeline, the /api/read/* dispatcher catch in DarlingWebEndpoints.cs, and the new Hosting/DarlingWebFailureLog.cs. I read the code at the squash commit. I also ran a standalone repro against a local Kestrel. Finding 1 describes it.

Result: 1 Medium and 4 Low. Nothing in the change weakens the Host-header guard order, the auth gate, or the tokenless loopback bind.

Answers to the four questions

1. Can the Host guard or the auth gate throw past their own handling? I found no path today by which crafted input makes either gate throw. The Host guard uses IPAddress.TryParse and string compares. The auth gate parses the cookie expiry with long.TryParse and catches the FormatException from the base64 decode. It hashes both tokens before it compares them. DarlingHttpRefusalLog.Observe runs under a lock. The only throw source left is the logging call itself. The file provider catches all of its own errors, and I found no realistic throw in the other providers. But the backstop comment is wrong, and finding 4 explains why.
2. Does a 500 or 503 carry exception text? The backstop does not. Its body is one of two constant strings, and it sets no header from the exception. The /api/read/* path does, and finding 2 names it.
3. Is the route sanitized at both call sites? Yes. Report sanitizes in one place (DarlingWebFailureLog.cs:71), and the /api/read/* site passes a constant route anyway. But the 256-character cut can split a surrogate pair (finding 1). Also, exception.Message reaches the file log with no sanitizing (finding 5).
4. Does anything weaken the gates? No. At baaa4e0 the order is compression (1009), the Host guard (1021) and the auth gate (1049, network mode only). The backstop (1201), the no-store stamp (1233) and the routes (1243) come after them. In network mode the backstop sees only requests that the auth gate allowed, after the read-only seat check. On the loopback bind it sees the same requests that the routes already see. Backstop answers still carry Cache-Control: no-store, because the stamp sets the header before it calls next.

1. Medium: a split surrogate pair drops a whole batch of the service log

Where: Hosting/DarlingHttpRefusalLog.cs:294-300 makes the cut. Hosting/DarlingWebFailureLog.cs:71 calls it. The failure happens at DarlingFileLoggerProvider.cs:164.

What fails: Sanitize(route, 256) cuts at 256 UTF-16 code units. Kestrel decodes a percent-encoded character outside the Basic Multilingual Plane into a surrogate pair. If the pair sits at index 255 and 256, the cut keeps only the high surrogate. Flush then calls File.AppendAllText with its default UTF-8 encoding, which throws EncoderFallbackException on a lone surrogate.

The catch at line 167 then drops the lines that Flush already dequeued. The comment there says so: "The dequeued lines are already gone." The batch holds lines from every part of the service, not only the web host. The failure latch reports only the first loss, through the Event Log, and only if the event source exists. Every later loss is silent.

Who can do it: the path must match a route, and the request must then throw. At baaa4e0 the only routes with an unconstrained string path parameter are the three /api/mute-rules/{id} routes. ReadBodyAsync (DarlingWebEndpoints.cs:883) reads the body outside the catch in the mute-rule cores. So one request is enough: PATCH /api/mute-rules/ plus 239 a characters plus %F0%9F%98%80, with Content-Type: application/json, Content-Length: 40000000 and no body.

In loopback mode any local process can send it without a token. In network mode it needs a seat that can edit, because the read-only seat check refuses PATCH. One such request in each 5-second flush window loses the lines of that window.

Repro: a standalone program, not the shipped binary. It copies Sanitize and the Flush write line for line. It runs a Kestrel app with the same backstop shape and a route shaped like the mute-rules PATCH.

The request got a 500 (the same request without the backstop got 413 Payload Too Large). The backstop caught BadHttpRequestException. The decoded path was 257 characters, with a high surrogate at index 255. The sanitized line held a lone high surrogate. File.AppendAllText threw EncoderFallbackException and wrote 0 bytes, so an unrelated line in the same batch was lost too. With new UTF8Encoding(false), the same batch wrote 495 bytes.

Fix:

• In DarlingFileLoggerProvider.Flush, pass an encoding that does not throw: File.AppendAllText(CurrentLogFile(), sb.ToString(), new UTF8Encoding(encoderShouldEmitUTF8Identifier: false)). A bad character then becomes U+FFFD, whatever its source, and one line can no longer cost a batch.
• In DarlingHttpRefusalLog.Sanitize, do not end on a high surrogate (if (take < value.Length && char.IsHighSurrogate(value[take - 1])) take--;). Also map any lone surrogate to ., as the method already does for control characters.
• Test: add a 255-character route plus one non-BMP character to the CR/LF test, and flush it through a real DarlingFileLoggerProvider in a temp directory.

2. Low: the /api/read/* 500 body carries the exception text

Where: DarlingWebEndpoints.cs:327 (the dispatcher catch) and DarlingWebEndpoints.cs:2948 (the ServerError arm of ToHttpResult), through McpHelpers.ErrorSentence (PerformanceMonitor.Common/Mcp/McpHelpers.cs:635).

What fails: the body is {"error":"Error during <tool>: <ex.Message>"} with HTTP 500. The tools' own catches take the same path, and those are the common case. A PostgresException message starts with the SQLSTATE, then the server's message text, which can name schema objects and roles. An Npgsql connection failure names the endpoint of the store (host and port).

So a statement timeout inside a tool answers 500 with 57014: canceling statement due to statement timeout. It does not get the 503 and the generic message that the backstop gives. The class comment at DarlingWebFailureLog.cs:17-22 says that the wording and the timeout/error split cannot drift between the two call sites. On the wire they do, because the dispatcher shares only Report.

Who sees it: every web seat, including read-only seats, and any local process on the loopback bind. I rate it Low because it needs a session or local access, and I found no credentials in these messages. It is older code, but the #4276 ruling ("never the exception text") applies here too.

Fix: in the dispatcher catch, answer with the same helpers as the backstop:

return Results.Json(DarlingWebFailureLog.Body(ex), statusCode: DarlingWebFailureLog.StatusCode(ex));

The tools' own catches need the same change in the ServerError arm of ToHttpResult. That arm must log the real text before it drops it, unless the tool already logs its catch. The MCP wire keeps FormatError as it is.

The same family exists in older code outside this diff. /api/compose/run answers 500 with Error running query: {ex.Message} (DarlingWebEndpoints.cs:1112) and 400 with the Postgres message text (:1108). The triage page puts ex.Message into its notes with a 200 (DarlingTriageEndpoint.cs:608 and :663).

3. Low: client protocol errors now answer 500 and write an Error line with no limit

Where: DarlingWebHostService.cs:1212-1223, and the "No throttle" reasoning at DarlingWebFailureLog.cs:62-64.

What fails: Kestrel throws BadHttpRequestException into the app for a bad request body. Examples are a body over the size limit (413), bad chunked encoding (400), or a body that arrives too slowly (408). Before this change, Kestrel answered with that status and logged nothing. Now the backstop answers 500 and writes one Error line ("Web dashboard read ... failed") for each request, at a rate that the client chooses. The "not adversary-shaped traffic" reasoning does not hold for these errors, because a client can cause them on purpose at almost no cost.

Who can do it: /api/compose/run catches only JsonException around its body read (DarlingWebEndpoints.cs:514-522). It is the one POST that DarlingWebSeat.IsRequestAllowed (Hosting/DarlingWebSeat.cs:122) lets a read-only seat send. So the least-privileged seat can do it, and so can any local process on the loopback bind. The file log has a 14-day age sweep but no size cap. For a managed store, the log directory and the store's data directory are both under %ProgramData%\PerformanceMonitorDarling, so they share a volume.

Fix: in the backstop, catch BadHttpRequestException before the generic catch. Answer its own status code, and do not log it at Error. If you want a trace, log one throttled Warning through a fold like the one in DarlingHttpRefusalLog.

catch (BadHttpRequestException bad)
{
    if (!context.Response.HasStarted)
    {
        context.Response.StatusCode = bad.StatusCode;
    }
}

4. Low: the backstop comment says that it catches gate throws, but it cannot

Where: DarlingWebHostService.cs:1195-1198.

What fails: the comment says that both gates "already handle their own exceptions", and that the backstop fires for "an UNANTICIPATED throw from a gate". The backstop is registered after both gates, so a gate throw never enters its try. The Host guard has no try/catch. The auth gate has one only around HandleAuthFlowAsync (1107-1124), and the body of that catch has no guard.

If a gate throws, Kestrel answers 500 with an empty body, or resets the connection if the response started. Nothing is logged, because the Kestrel error log goes to the providers that ClearProviders (772) removed. That is the #4276 symptom, on the surface that has no authentication.

There is one more case. The WebApplicationOptions at 703-707 do not set EnvironmentName. If the service environment sets ASPNETCORE_ENVIRONMENT or DOTNET_ENVIRONMENT to Development, WebApplication adds the developer exception page. It adds that page first in the pipeline, ahead of the Host guard. A caller with no credentials then gets the exception message and the stack trace for any throw that escapes.

No shipped config sets that variable, and I found no gate throw path today. But a developer can set that variable for the whole machine on a test box.

Fix: correct the comment. It must say that the backstop covers the routes only, and that a gate throw is not logged. Set EnvironmentName = Environments.Production in the WebApplicationOptions of the web host. If you want gate throws logged, add a log-only try/catch inside each gate body. The middleware order stays the same.

5. Low: exception.Message reaches the file log with no sanitizing

Where: DarlingWebFailureLog.cs:75-85 passes the exception object. DarlingFileLoggerProvider.cs:288 appends | {exception.GetType().Name}: {exception.Message} with no change.

What fails: the third commit sanitized the route, because CR/LF in the route can forge a log line. The same line also carries exception.Message, with no sanitizing and no length cap. An exception message can repeat request text. For example, PostgreSQL repeats a bad input value in a cast error, and KeyNotFoundException includes the key.

I found no route today where a caller's CR/LF reaches an exception that gets to Report. The tools and /api/compose/run catch their Postgres errors, and the BadHttpRequestException messages do not repeat input. So the risk is latent. But this change is what sends exceptions that a request triggers into this logger.

Fix: sanitize in FileLogger.Log, for both the formatted message and exception.Message. Map control characters to . and cap the length, as Sanitize does. That change covers every call site in the service.

Note (not a finding)

IsStatementTimeout (DarlingWebFailureLog.cs:50-53) also matches the Npgsql errors for pool exhaustion and connect timeouts. Npgsql reports both as an NpgsqlException that wraps a TimeoutException. So when the store cannot hand out a connection, the backstop answers 503 "took too long" and logs a Warning that says "timed out", not an Error.