Repository navigation
Say which gate turned a request away, without letting a scanner fill the log (#2479) - #2486
Conversation
…the log (#2479) A 401, 403 or 400 on either listener left nothing in the service log. All five refusal sites across the MCP and web hosts were a bare `StatusCode = ...; return;`, so "is my token wrong, or my CIDR wrong?" was answerable only from the client - which sees one opaque status code and cannot tell a Host-allowlist 400 from a malformed request, or a CIDR 403 from anything else. The person who can fix either of those is on the server, and the server said nothing. Each gate now reports once per refusal, naming itself and the config key that governs it: the Host header allowlist, the access token, or network.allowFrom. The web host's ShowLogin path is included even though it answers 200 rather than 401, but ONLY when a token was actually presented and did not match - that is the state an operator asks about when a ?token= they pasted did not work, while a first visit with no token is the normal route to the login page and logging it would make every bookmark a warning. The rate limit is the load-bearing half. These ports are LAN-exposed on purpose and an exposed port meets a scanner eventually, so an unthrottled line per refusal makes the service log a denial-of-service target: the file an operator debugs from fills up exactly when it matters. Tuned the other way it is worthless - if a tester's own first refusal waits out a window, nothing shipped. So the key is (gate, source address) and the FIRST sighting of one always logs immediately. Only repeats fold, for ten minutes, which costs nothing because a second identical refusal from the same address through the same gate carries no information the first did not - and a tester who fixes their token and now fails the CIDR check trips a different key, which logs at once. The number folded rides out on the next line that does emit, so the volume is visible without being written. Per SOURCE rather than per gate alone, because per-gate is a smaller key set and it is wrong: one scanner's line would win the window and hide the tester's refusal completely, which is this defect reintroduced by the fix for it. That makes the map unbounded by construction, so past sixteen distinct sources in a window further sources fold into one per-gate aggregate that SAYS so - bounding memory and volume to (cap + gate count) entries and one line per gate per window. Measured: 108,000 refused requests over an hour from a few hundred sources produce 100 lines and 19 tracked entries. The accepted cost is that a tester arriving mid-scan lands in the aggregate; that is visible rather than silent, and if the port is being scanned, that is the more urgent thing to know. Eviction is keyed on last SEEN, not last logged. Keyed on last logged, a source still being refused every second would be dropped at the two-window horizon and re-log as a fresh first sighting - turning the rate limit into a rate multiplier, which is worse than no limit because it looks like one is working. The token, any prefix of it and its length are never logged; a line may say whether a credential was PRESENTED and nothing about its value, which is pinned per call site rather than trusted. The Host header is the one request-derived value echoed, and it goes through a sanitizer first: a log file is a text file, and a header carrying CR/LF would otherwise forge whole entries. The budget belongs to the started server rather than the process, so a rebind starts clean instead of inheriting the previous listener's scan and swallowing the new one's first refusals. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
| refusals.Report( | ||
| _logger, "MCP", DarlingRefusalGate.Token, StatusCodes.Status401Unauthorized, | ||
| context.Connection.RemoteIpAddress, | ||
| ExtractBearerToken(context.Request.Headers.Authorization.ToString()) is null |
There was a problem hiding this comment.
Minor/non-blocking: ExtractBearerToken is now called twice on this refusal path — once inside IsBearerTokenAuthorized above, once here to decide the "presented vs. mismatched" wording. Only reached on an already-refused request, so no real perf concern, but if IsBearerTokenAuthorized were changed to return the extracted token (or a small result type) this duplicate parse would go away for free.
Review summaryThis is a well-scoped, well-tested change — no correctness bugs found in Specifically checked and found solid:
Lite/Darling parity note (non-blocking)Lite's Minor nit (left inline)
No T-SQL in this PR, so the collector/style conventions (OPTION(RECOMPILE), AS aliasing, etc.) don't apply here. |
Review catch: ExtractBearerToken was being handed a second StringValues.ToString() of the same header, purely to tell "no credential" from "wrong credential" in the refusal line. Hoisted to a local, so the header is materialized once and both readers share it. Not taken: having IsBearerTokenAuthorized return what it parsed. Its signature is pinned by DarlingMcpHostTests and DarlingHostBindingTests, and threading a result type through it to save one parse on an already-refused request is not a trade worth making - the comment now says so, so the next reader does not re-open it. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
|
Good catch — fixed in 2a857dc by hoisting the header to a local, so I did not take the fuller version (having |
|
|
||
| return string.Format( | ||
| CultureInfo.InvariantCulture, | ||
| " {0} further refusal(s) from this source were not logged in the last {1} minute(s).", |
There was a problem hiding this comment.
DescribeSuppression always renders "N further refusal(s) from this source were not logged...", but this text is also used for aggregate entries (decision.Aggregated == true), where the folded refusals came from multiple different source addresses once the per-source cap (16) was exceeded, not from one source.
Concretely: with the per-source budget full, gate Token keeps getting hit by many different overflow IPs within the same 10-minute window. The first overflow logs with Aggregated: true and creates the _perGate[Token] entry; every subsequent overflow (from any other IP) folds into it via Fold(aggregate, ..., aggregated: true), incrementing Suppressed. When the window elapses and the next overflow logs, the line will combine the "(speaking for several sources …)" scope suffix with "N further refusal(s) from this source were not logged" — actively misleading, since those N refusals were spread across many different addresses, not repeats from one. That directly undercuts the PR's stated goal of giving the operator an accurate answer, and isn't covered by PastTheCap_TheLineSaysItSpeaksForSeveralSources (which only exercises a single overflow, before any folding/suppression happens on the aggregate).
Suggest branching the wording on decision.Aggregated (e.g. "…were not logged from other sources sharing this gate's aggregate…") or otherwise not implying a single source when the aggregate bucket is speaking for the cap overflow.
|
Reviewed the diff ( Overall: the rate-limiting design is sound and well-tested (first-sighting-always-logs, per-(gate,source) folding, eviction on last-seen not last-logged, capped memory with an announced aggregate fallback). Left one inline finding on a wording bug in the suppression message when it applies to an aggregated (multi-source) bucket rather than a single source — see the inline comment on Lite/Darling parity check: this only touches the Darling service host. I checked Security: the token-value redaction (present/absent or match/mismatch only, never the value/prefix/length) and the CR/LF-stripping Performance: No missing-index DMV comments applicable — no T-SQL in this PR. |
Review catch. The two buckets fold different things: a per-source entry folds repeats from ONE address, while the aggregate entry folds the cap overflow, which is by definition many DIFFERENT addresses through one gate. Both rendered "N further refusal(s) from this source were not logged", which is false on the aggregate - and false in the direction that costs most. An operator reading "399 further refusals from this source" goes looking for one busy client; what is actually happening is a broad scan, which is precisely what the aggregate bucket exists to tell them. A line whose whole job is to be an accurate answer must not be inaccurate here. The wording now branches on Decision.Aggregated. PastTheCap_TheLineSaysItSpeaksForSeveralSources only exercised the FIRST overflow, before any folding had happened on the aggregate, so the clause that ships with the folded count was never rendered by a test. The new case fills the budget, pushes 400 distinct overflow addresses through one gate, crosses the window, and asserts the clause reports 399 and says "from other sources" - and, in the same test, that a per-source entry still says "from this source", because the fix must not flatten both into one hedge. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
|
Right, and the analysis is exact — the aggregate bucket folds many different addresses through one gate, so "from this source" is false there, and false in the direction that costs most: it sends the operator looking for one busy client when what is happening is a broad scan, which is the very thing the aggregate bucket exists to tell them. Fixed in 84086e4. The clause now branches on
Your point about the coverage gap was the useful half — |
| ExtractBearerToken(authorization) is null | ||
| ? "no 'Authorization: Bearer <token>' header was presented" | ||
| : "the presented bearer token does not match mcp.network.encryptedToken", |
There was a problem hiding this comment.
ExtractBearerToken(authorization) is null collapses two different client states into one message. It returns null not only when the Authorization header is absent, but also when it's present with the wrong scheme (e.g. Authorization: Basic xxx) or Bearer with a blank/whitespace-only token (see ExtractBearerToken below, lines 921-937).
In those malformed-but-present cases, the operator sees "no 'Authorization: Bearer ' header was presented" even though a header was sent — just not in the expected shape. Given this whole feature exists so operators can tell "client never configured" from "client configured wrong" at a glance, that's exactly the ambiguity it's meant to resolve. Consider distinguishing "header absent" (authorizationHeaderValue is null) from "header present but not a valid Bearer token" (ExtractBearerToken(...) is null but header non-null) so a malformed scheme doesn't get reported as "not presented".
|
Reviewed. The core Lite/Darling parity note (not a blocker, flagging per review scope): No correctness bugs found beyond the inline note. No T-SQL touched by this PR, so the collector-style conventions in CONTRIBUTING.md don't apply here. |
Review catch. ExtractBearerToken answers null for BOTH "no header" and "a
header that is not a well-formed Bearer", so a refusal line built on it
alone told an operator that nothing was presented while their client was
sending Authorization: Basic ... every second - collapsing precisely the
ambiguity this feature exists to resolve, in the message that exists to
resolve it.
Each state is a different next step:
no header -> a client that was never configured with a token
header, not a Bearer -> a client configured wrong (Basic, a bare token,
an empty "Bearer ") - it IS sending something
a Bearer that misses -> a token that does not match this endpoint's
Split into a pure DescribeBearerRefusal so all three are pinned by a table
rather than by reading a lambda, and so the "never the value" property is
structural: it reads the header's SHAPE and has nothing else to leak. The
table covers the wrong scheme, a bare token with no scheme, "Bearer " with
an empty and a blank token, and the case-insensitive scheme forms that must
still reach the third state.
Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
|
Correct, and it is the same defect this PR exists to fix, sitting inside the fix. Fixed in 4bae26d. Three states now, because each is a different next step:
Pulled out into a pure |
| if (!string.IsNullOrEmpty(presentedToken)) | ||
| { | ||
| refusals.Report( | ||
| _logger, "Web dashboard", DarlingRefusalGate.Token, StatusCodes.Status200OK, |
There was a problem hiding this comment.
Minor wording nit: DarlingHttpRefusalLog.Report's message template is fixed as "{Surface} refused a request from {Source} with {Status}: the {Gate} gate rejected it — {Reason}...". Passing Status200OK here produces a line like:
Web dashboard refused a request from 10.0.0.5 with 200: the access token gate rejected it — the presented ?token= does not match web.network.encryptedToken, so the login page was served instead.
"refused ... with 200" reads as self-contradictory (200 = success), which could trip up anyone grepping the log for actual denials (e.g. filtering on status >= 400) or just reading it cold. The PR description explains why this 200 case is intentionally included, but that reasoning doesn't reach the log line itself. Worth either rewording the shared template to not always say "refused", or giving this call site a distinct phrasing (e.g. "declined a stale ?token= and served the login page instead" rather than "refused ... with 200").
|
Reviewed the diff ( Two things worth a look, both left as inline suggestions/notes where I could anchor them:
No correctness bugs found in the rate-limiter logic itself, and the test file's structural pins (every 4xx site reports, no forbidden token identifiers, budget is per-started-server) look sound. |
…2479) Review catch. Not every gate rejection ends in a 4xx: the web dashboard answers an in-CIDR request carrying a WRONG ?token= with a 200 and the login page, deliberately, and that is exactly the state an operator asks about when a token they pasted did not work - which is why this PR logs it at all. But the shared template said "refused" unconditionally, so the line read "refused a request from 10.0.0.5 with 200", which is self-contradictory on its face and misleads anyone reading the log cold or filtering it for denials on status. The verb is now derived from the status and the code is stated as HTTP N: MCP refused a request from 10.0.0.5 (HTTP 401): the access token gate ... Web dashboard did not authorize a request from 10.0.0.5 (HTTP 200): ... The reasoning for including the 200 case was in the PR description, which is not where the person reading the log is standing. Kept as a pure DescribeOutcome so the boundary is pinned rather than asserted about, and so the structured template keeps its named placeholders instead of being concatenated into one opaque string. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
|
Agreed — and it is worse than a nit, because a log line that says "refused … with 200" argues with itself and would mislead anyone filtering for denials on status. The reasoning for including the 200 case was in the PR description, which is not where the person reading the log is standing. Fixed in df057b6. The verb is derived from the status and the code is stated as Kept as a pure |
| : string.Empty; | ||
|
|
||
| logger.LogWarning( | ||
| "{Surface} {Outcome} a request from {Source} (HTTP {Status}): the {Gate} gate rejected it — {Reason}.{Suppressed}{Scope}", |
There was a problem hiding this comment.
DescribeOutcome exists specifically so a 200/302 refusal isn't logged as "refused" (see the docstring above it, and TheOutcomeVerb_AgreesWithTheStatusCode). But this format string hardcodes the {Gate} gate rejected it regardless of outcome. For the web host's ShowLogin path (200, wrong ?token=), the rendered line is:
Web dashboard did not authorize a request from 10.0.0.5 (HTTP 200): the access token gate rejected it — the presented ?token= does not match web.network.encryptedToken, so the login page was served instead.
"did not authorize ... HTTP 200 ... gate rejected it" reintroduces the exact self-contradiction DescribeOutcome was added to eliminate — no test currently checks the fully-rendered message, only DescribeOutcome in isolation. Worth making the middle clause outcome-aware too (or rephrasing it to something outcome-neutral, e.g. "because of the {Gate} gate").
| internal static readonly TimeSpan DefaultWindow = TimeSpan.FromMinutes(10); | ||
|
|
||
| /// <summary>Distinct sources tracked before new ones fold into the per-gate aggregate.</summary> | ||
| internal const int DefaultMaxTrackedSources = 16; |
There was a problem hiding this comment.
Minor: this is documented (here and in the class-level doc above) as bounding "distinct sources," but the dictionary key built at Observe (gate.ToString() + "|" + source) is actually keyed on (gate, source), not source alone. A single address that trips more than one gate over time (fix the Host header, then get refused on the token, then on the CIDR — exactly the iterating-tester scenario this feature is designed around) consumes one slot per gate it trips, not one slot total. With 3 gates and a cap of 16, worst case only ~5 truly distinct addresses get individual treatment before others start folding into the per-gate aggregate, despite the docs implying room for 16 sources. Not a safety issue (the aggregate path still bounds memory/log volume correctly), but the doc/constant name overstates the effective per-address budget.
|
Reviewed. This is C# only (no T-SQL), so the CONTRIBUTING.md style checklist mostly doesn't apply here. Lite/Darling parity: no drift. Lite's Design: the rate-limit shape (first-sighting-always-logs, per-(gate,source) folding, capped-then-aggregated overflow, last-seen eviction) is sound and the test suite exercises the tricky parts (noisy-neighbour, overflow wording, eviction-vs-multiplier) well. Security: token value/prefix/length are never logged, confirmed by both the redaction tests and the Left two inline notes:
Nothing else stood out as a correctness, security, or performance regression. |
|
Both fixed in 3041b73, and both were narrower statements than they sounded. The sentence. You are right that Your observation that nothing tested the full message is the part that mattered — that is exactly how the contradiction survived the first fix. The budget. Also right, and the doc overstated it by ~3x. Renamed to Re-measured the ceiling with the larger cap: 108,000 refused requests over an hour now produce 258 lines and 51 tracked keys, against 100 and 19 before. Still a hard ceiling. |
Item 5 of #2479.
The gap
All five refusal sites across the two listeners were a bare
StatusCode = …; return;:mcp.network.allowFrom)web.network.allowFrom)So "is my token wrong, or my CIDR wrong?" was answerable only from the client — which sees one opaque status code and cannot tell a Host-allowlist 400 from a malformed request, or a CIDR 403 from anything else. The person who can fix either is on the server, and the server said nothing.
Each gate now emits a WARN naming itself and the config key that governs it.
The web host's
ShowLoginpath is included too, even though it answers 200 rather than 401 — but only when a token was actually presented and did not match. That is precisely the state an operator asks about when a?token=they pasted did not work, and the status code hides it. A first visit with no token is the normal route to the login page, so logging that would make every bookmark a warning.Out of scope on purpose:
DarlingWebEndpoints' validation 400s and the CSRF 415 already return a body that explains itself to the client. This is about the gates that refuse silently, before any handler.The rate limit, and why it is shaped this way
This is the load-bearing half, so it is measured rather than asserted about.
cap + gate countentries and one line per gate per window.Measured ceiling: 108,000 refused requests over an hour (30/s across three gates from a few hundred sources) produce 100 log lines and 19 tracked entries.
What is never logged
The token, any prefix of it, and its length. A line may say whether a credential was presented — an absent
Authorizationheader is a client that was never configured; a wrong one is a token that does not matchmcp.network.encryptedToken, and each points at a different next step — and nothing about its value. Pinned per call site rather than trusted.The Host header is the only request-derived value echoed, and it goes through a sanitizer first. A log file is a text file: a header carrying
\r\nwould otherwise forge whole log entries.Verification
DarlingHttpRefusalLog.cs—<Compile Include>'d into a throwawaynet10.0console harness, sinceDarling.Testsisnet10.0-windowsand cannot run on macOS. 26/26 assertions pass, including the 108,000-request scan ceiling, the first-sighting-is-immediate guarantee, the noisy-neighbour case, the cap announcement, the last-seen eviction invariant, and the log-injection cases.Reportcalls total, no forbidden token identifier in any argument list.HostHeaderGuardTestsassertions against the edited files —FirstMiddlewareAfterBuildstill findsIsAllowedHost(context.Request.Host.HostandStatus400BadRequestin the first middleware, and the guard still precedesif (networkMode)andMapMcp. Adding lines inside that lambda was the one thing that could have broken them.Darling.Testsboth build clean, 0 errors.devthe whole test class fails to compile —DarlingHttpRefusalLogdoes not exist there.mcp.networkexposed,curl -H "Authorization: Bearer wrong" http://<ip>:5152/should produce one WARN naming the access-token gate, and a second identical curl within ten minutes should produce none.Onboarding
Makes
docs/uat-onboarding.md§4.4 "When it says enabled and still will not connect" substantially unnecessary — the section exists because the server-side answer had to be reconstructed from the client's status code. The tell it teaches (401 = token, 403 = CIDR, 400 = Host) is now stated in the service log at the moment it happens, naming the config key. §5's "the things that will actually bite you" entry on the same subject can go the same way. The gate list is still worth keeping as a reference table; the "you can only tell from the client" framing is what stops being true.Co-Authored-By: Claude Opus 5 noreply@anthropic.com