diff --git a/memex/Memex.Portal.Shared/Authentication/ApiTokenService.cs b/memex/Memex.Portal.Shared/Authentication/ApiTokenService.cs index 9f4224630d..9c9869bfab 100644 --- a/memex/Memex.Portal.Shared/Authentication/ApiTokenService.cs +++ b/memex/Memex.Portal.Shared/Authentication/ApiTokenService.cs @@ -478,8 +478,10 @@ public IObservable Validate(string rawToken) /// true = expected content present with the MATCHING hash (emit the node); /// false = content present but a DIFFERENT hash — someone else's token /// colliding on the 12-char prefix / tampering — a TERMINAL mismatch that must - /// fail fast, never spin the poll; null = content not (yet) extractable — - /// transient (mid-create, sync lag), keep polling until the timeout. + /// fail fast, never spin the poll; null = the row is there but its content is not + /// readable as a token record — also TERMINAL (the store answered; nothing a re-read would + /// change), logged under its own -unreadable stage by + /// so it is never mistaken for an absent row. /// private bool? IndexHashVerdict(MeshNode node, string hash) { @@ -546,6 +548,18 @@ private IObservable ReadValidationNode( // storage-direct cutover) — a leftover from the cross-silo mesh read whose // lag no longer exists. Only a THROWN storage error (connection blip) // re-polls, bounded by ValidationReadTimeout. + // + // 🚨 Three negatives, three DIFFERENT log stages — never fold them. `{stage}-not-found` + // is the line a 401 investigation reads as "the row was deleted" (#5074 rested its whole + // supersession inference on it), so it must be emitted ONLY when the store answered that + // no row exists. A row that IS there but whose content cannot be read as the expected + // record is a different fact — the token was not deleted, this replica could not TYPE + // the row — and used to print as "no row at {Path}", which sent the reader hunting for a + // delete that never happened. It logs as `{stage}-unreadable`, naming the row's version + // and the content's runtime type, so the next occurrence is attributable inside the log + // window. The verdict stays a definitive negative either way: the store WAS read, and a + // row that carries no token record authenticates nobody — Unavailable is reserved for a + // store that could not be read at all. IObservable Attempt() => storage.Read(path, hub.JsonSerializerOptions) .Select(node => @@ -557,10 +571,15 @@ IObservable Attempt() => logger.LogWarning( "API token validation failed at {Stage} for hash prefix {HashPrefix} after {ElapsedMs} ms: node at {Path} exists but carries a different token hash", stage + "-hash-mismatch", hashPrefix, elapsed.ElapsedMilliseconds, path); - else + else if (node is null) logger.LogWarning( "API token validation failed at {Stage} for hash prefix {HashPrefix} after {ElapsedMs} ms: no row at {Path} (unknown or deleted token)", stage + "-not-found", hashPrefix, elapsed.ElapsedMilliseconds, path); + else + logger.LogWarning( + "API token validation failed at {Stage} for hash prefix {HashPrefix} after {ElapsedMs} ms: row at {Path} exists (version {Version}) but its content is {ContentType}, not a readable token record — the token was NOT deleted; this replica could not type the row", + stage + "-unreadable", hashPrefix, elapsed.ElapsedMilliseconds, path, + node.Version, node.Content?.GetType().Name ?? "null"); return new ValidationReadOutcome(null, null); }) // A transient storage ERROR (not absence) re-polls — the outer diff --git a/memex/Memex.Portal.Shared/Authentication/OAuthConnectController.cs b/memex/Memex.Portal.Shared/Authentication/OAuthConnectController.cs index a7847706a9..a687a7343e 100644 --- a/memex/Memex.Portal.Shared/Authentication/OAuthConnectController.cs +++ b/memex/Memex.Portal.Shared/Authentication/OAuthConnectController.cs @@ -436,22 +436,50 @@ public Task ExchangeToken([FromForm] TokenRequest request, Cancel if (superseded.Length == 0) return Observable.Return(System.Reactive.Unit.Default); + // 🚨 Name the rows — twice, and the two lines say different things. The 401 a + // superseded holder gets is logged by the validator under the token's HASH + // PREFIX, which is the last segment of these paths, so a path here and that + // warning correlate on one string. Without the paths, "superseding 1 previous + // token(s)" cannot be tied to the 401 it caused, and the alternation #5074 reports + // (two processes of one installation sharing a client_id and evicting each + // other's credential) is unattributable inside the log window. + // + // This first line is INTENT: the candidate set, before any delete has run. + // DeleteToken answers false for a path that was already gone (a concurrent + // exchange got there first) and faults on a refusal (the per-path catch below + // keeps that token live), so what was actually removed is known only after the + // Concat completes — the second line, below, reports that. A reader tying a 401 + // to a removal uses the second line; the first says what this exchange set out + // to do, which is what a refusal is measured against. logger.LogInformation( "OAuth: superseding {Count} previous token(s) for user {UserId}, client label {Label} — " + + "candidates {SupersededPaths}, keeping {KeptPath}; " + "a re-authorization replaces the client's credential rather than adding one", - superseded.Length, userId, label); + superseded.Length, userId, label, string.Join(", ", superseded), keepPath); // Self-paced (Concat, never Merge): one delete at a time, the same shape the expiry - // sweep uses, so a client that re-authorized many times drains gently. + // sweep uses, so a client that re-authorized many times drains gently. Each + // delete's own bool is what it REMOVED (true) or found already absent (false); + // a fault is caught per path and counts as not removed. return Observable.Concat(superseded.Select(path => tokens.DeleteToken(path) - .Catch(ex => + .Select(removed => (Path: path, Removed: removed)) + .Catch<(string Path, bool Removed), Exception>(ex => { logger.LogWarning(ex, "OAuth: could not supersede previous token {Path} — it stays live until " + "the next authorization or its expiry", path); - return Observable.Return(false); + return Observable.Return((Path: path, Removed: false)); }))) - .LastOrDefaultAsync() + .ToList() + .Do(outcomes => + { + var removed = outcomes.Where(o => o.Removed).Select(o => o.Path).ToArray(); + logger.LogInformation( + "OAuth: superseded {RemovedCount} of {Count} previous token(s) for user {UserId}, " + + "client label {Label} — removed {RemovedPaths}; kept {KeptPath}", + removed.Length, outcomes.Count, userId, label, + removed.Length == 0 ? "(none)" : string.Join(", ", removed), keepPath); + }) .Select(_ => System.Reactive.Unit.Default); }) .Catch(ex => diff --git a/src/MeshWeaver.Documentation/Data/AI/McpAuthentication.md b/src/MeshWeaver.Documentation/Data/AI/McpAuthentication.md index 92d4e44cc2..45310ee732 100644 --- a/src/MeshWeaver.Documentation/Data/AI/McpAuthentication.md +++ b/src/MeshWeaver.Documentation/Data/AI/McpAuthentication.md @@ -1,7 +1,7 @@ --- NodeType: Markdown Name: "MCP Authentication" -Abstract: "How to generate API tokens and configure MCP clients like Claude Code to securely access the MeshWeaver MCP endpoint with bearer token authentication." +Abstract: "How MCP clients authenticate against the MeshWeaver MCP endpoint: personal API tokens, the OAuth flow OAuth-capable clients run instead, what each flow stores and for how long, why a multi-replica portal needs no affinity, and how to read a rejected token's log line." Icon: "" Thumbnail: "images/agenticai.svg" Authors: @@ -132,7 +132,67 @@ curl -X POST https://your-portal.com/api/mcp \ -d '{"jsonrpc":"2.0","method":"initialize","params":{},"id":1}' ``` -A successful JSON-RPC response confirms authentication is working. A `401` means the token is missing, invalid, expired, or revoked. +A successful JSON-RPC response confirms authentication is working. A `401` means the token is missing, invalid, expired, or revoked — and a `503` with `Retry-After` means the token could **not be checked** right now and must be kept (see *Reading a rejection* below). + +--- + +## OAuth for MCP clients + +A client that speaks OAuth — claude.ai connectors, Claude Desktop, Claude Code's `claude mcp add --transport http` — never sees the token page. It discovers the portal as an authorization server and ends up holding the same `mw_` token a manual flow would have produced. The whole flow is served by `OAuthConnectController` in `Memex.Portal.Shared`: + +| Step | Endpoint | What happens | +|---|---|---| +| Discovery | `GET /.well-known/oauth-protected-resource`, `GET /.well-known/oauth-authorization-server` | The `401` challenge on `/mcp` names the first; it names the second. Only `authorization_code` with PKCE `S256` is advertised — there is no `refresh_token` grant. | +| Registration | `POST /register` (RFC 7591) | The client sends its name and redirect URIs and receives a `client_id`. **Nothing is persisted.** The id is *derived* — a hash of this portal's origin, the client name and the sorted redirect URIs — so a client that registers again receives the same id and is recognised as the same application. | +| Authorization | `GET /authorize` | The user must hold a portal session. Without one the request is sent to `/login` with a **local** return target (`/authorize?…`) and comes back here after sign-in; with one, an authorization code is minted and the browser is redirected to the client's `redirect_uri`. No consent screen is shown: a signed-in user is authorized for their own identity. | +| Exchange | `POST /token` | The client presents the code, its `client_id`, the same `redirect_uri` and the PKCE verifier. The code is consumed (single use, first delete wins), an `mw_` token is minted for the code's user, and the client's *previous* token for the same `client_id` is removed. | +| Use | `POST /mcp` with `Authorization: Bearer mw_…` | Exactly the manual-token path from here on. | + +### What is stored, where, for how long, and who can read it + +| Record | Path | Contents | Lifetime | Readable by | +|---|---|---|---|---| +| Authorization code | `Admin/OAuthCode/{hashPrefix}` | The SHA-256 hash of the code (never the code), the user's id/name/email, `client_id`, `redirect_uri`, the PKCE challenge, the creation time | 5 minutes, and deleted the moment it is exchanged; expired rows are swept on the next `/authorize` | System-managed rows in the `Admin` partition — a platform admin's grant, nobody else's (see [Access Control → The Admin partition](/Doc/Architecture/AccessControl)). Excluded from search, create menus and autocomplete. | +| Access token | `{userId}/ApiToken/{hashPrefix}` | The SHA-256 hash of the token (never the token), owner identity, the label `OAuth: {client_id}`, created/expires/last-used stamps, a diagnostic copy of the roles at mint time | 1 year, or until revoked, deleted, or superseded | The owner, in their own partition — the same row the API Tokens settings tab lists | +| Token index | `ApiToken/{hashPrefix}` | The hash and the path of the token row | Follows its token row: written with it, deleted with it (revocation, expiry sweep, supersede) | Written and deleted under the System identity; the `ApiToken` partition is separately gated and ordinary users hold no grant on it | +| Client registration | — | nothing | — | — | + +Two things are deliberately **not** stored: the raw code and the raw token exist only in the client's hands, and no consent or registration record is kept, so there is nothing for a stable `client_id` to be stable *for* on the server — its value is that the client keys its own token cache on it. + +### Nothing is per-process — a multi-replica portal needs no affinity + +Every record above is written to and read from the shared store directly, on every replica: `/authorize` on one pod and `/token` on the other exchange the same code, and a token minted by one pod validates on the other on the first request. The MCP transport itself is stateless (no per-pod session table), and the cookie-protection keys are shared across replicas, so a two-replica deployment needs no sticky routing for `/token`, `/register` or `/mcp`. The regression controls for both halves are two-instance tests over one store: `OAuthCodeStoreTest.TwoStoreInstances_GenerateOnOne_ExchangeOnOther` and `TokenMintedOnOneReplicaValidatesOnAnotherTest`. + +### One live credential per client — and what that means for a client that shares its `client_id` + +A re-authorization **replaces** the client's credential rather than adding one: after minting, `/token` deletes every token with the same label `OAuth: {client_id}` that is strictly older. This is what keeps a reinstall, a new device or a reconnected integration from leaving year-long keys behind — the state the rule was introduced to end was 86 live token rows on one portal. + +The key is the `client_id`, and the `client_id` is derived from the client's name and redirect URIs. So which installations share a credential slot is decided by the **client**: + +- A client that binds a fresh callback port per registration gets a fresh `client_id` per registration — two such installations never collide, and neither do their re-authorizations (which also means the one-live-credential rule never fires for them). +- A client that presents the same `client_id` from more than one process — Claude Code keeps one registration per server per machine in its credential store, reuses its callback port when it is free, and every Claude Code process on that machine reads the same entry — shares ONE slot across those processes. When one of them re-authorizes, the others hold a token that has just been removed: their next call answers `401`, and they must re-authorize too. With a live portal session that re-authorization completes without any interaction (`/authorize` redirects straight back with a code), so it shows as a brief hop rather than a failure; with a lapsed session it is a sign-in. + +Nothing the exchange receives distinguishes two processes of one installation — `client_id`, `redirect_uri` and `client_name` are identical by construction, and the code and verifier are per attempt — so the portal cannot mint per-process credentials without changing the identity the client keys its cache on. Whether the rule should stay one-per-client, allow a bounded number of live tokens per client, or key on something process-distinct if the protocol ever offers one, is a maintainer decision and is tracked on [#5074](https://github.com/Systemorph/MeshWeaver/issues/5074); the log lines below are what make either choice measurable. + +### Reading a rejection + +Every rejected bearer token produces a warning on the portal naming the token's **hash prefix** (the first 12 characters of the hash — also the last path segment of its rows) and the failing **stage**. The stage is the whole diagnosis: + +| Stage | Meaning | HTTP answer | +|---|---|---| +| `index-not-found`, `token-not-found` | The store answered that **no row** exists at the path. The token was never minted here, or its row was deleted (revocation from the settings tab, the expiry sweep, or the one-live-credential supersede). | `401` | +| `index-unreadable`, `token-unreadable` | The row **exists** but its content is not a readable token record; the line names the row's version and the content's runtime type. The token was **not** deleted — this replica could not type the row. | `401` | +| `index-hash-mismatch`, `token-hash-mismatch` | A row exists at the prefix but carries a different hash. | `401` | +| `revoked`, `expired` | The row was read and says so. | `401` | +| `index-read-timeout`, `token-read-timeout` | The store could **not** be read within the validation window. No verdict was reached. | `503` + `Retry-After` — the body says the token was **not** rejected and must be kept | + +A supersede is logged at Information twice, and the two lines say different things: `OAuth: superseding N previous token(s) for user U, client label L — candidates {paths}, keeping {kept path}` is the **intent**, written before any delete has run; `OAuth: superseded R of N previous token(s) … — removed {paths}; kept {kept path}` is the **outcome**, written after every delete has answered (a path a concurrent exchange had already removed, or one whose delete was refused, is not in `removed`). A removed path ends in the same hash prefix the superseded holder's `-not-found` line will name, so one search for the prefix ties the removal to the `401` it caused — read the outcome line for that, never the intent. + +To read these on a deployed portal, use the control instance's `Logs` action rather than the cluster (see [Operating from the Portal](/Doc/Architecture/OperatingFromThePortal)): a `Hosting/InstanceAction` node with `requestedAction: "Logs"`, `deployment` naming the instance, `query: "API token validation"` (or `"OAuth: superseding"`, or the hash prefix itself) and a `sinceMinutes` that covers the moment — the entries land under `Ops/Logs`. The window the instrument answers for is bounded, so a reading is taken while the event is recent, not reconstructed afterwards. + +### Verifying the flow on a deployed portal — a positive read + +A silent log is not evidence of a working flow; the read must be a line that only a *completed* flow produces. After a roll, have an MCP client whose portal session has lapsed re-authorize, then query `OAuth /authorize` and `Issued OAuth` over the minutes around it. The sequence that proves the login hop returns to the flow is, for one `client_id`: `OAuth /authorize: … authenticated=False` → `redirecting unauthenticated caller to /login?returnUrl=%2Fauthorize%3F…` (a **local** target — an absolute `https://…` target here is the shape that [never came back](/Doc/Architecture/RedirectTargetContract)) → `Issued OAuth authorization code for user …, client {ClientId}` → `Issued OAuth access token for user …, client {ClientId}`. A client whose previous token was superseded then shows exactly that sequence with `authenticated=True` and no `/login` hop, which is the silent re-authorization the one-live-credential rule relies on. --- diff --git a/test/Memex.Portal.Shared.Test/CapturingLogger.cs b/test/Memex.Portal.Shared.Test/CapturingLogger.cs new file mode 100644 index 0000000000..b85a595148 --- /dev/null +++ b/test/Memex.Portal.Shared.Test/CapturingLogger.cs @@ -0,0 +1,35 @@ +using System; +using System.Collections.Concurrent; +using System.Collections.Generic; +using System.Linq; +using Microsoft.Extensions.Logging; + +namespace Memex.Portal.Shared.Test; + +/// +/// An that keeps every formatted line, for tests whose +/// SUBJECT is a log line — the stage a validation failure is logged under, the rows a supersede +/// names. Thread-safe: the services under test log from Rx continuations, never from the test's +/// thread. +/// +/// The category the logger is injected as. +internal sealed class CapturingLogger : ILogger +{ + private readonly ConcurrentQueue<(LogLevel Level, string Text)> entries = new(); + + /// Every line logged so far, in arrival order. + public IReadOnlyList<(LogLevel Level, string Text)> Entries => entries.ToArray(); + + /// The text of every line at . + public IReadOnlyList Lines(LogLevel level) => + entries.Where(e => e.Level == level).Select(e => e.Text).ToArray(); + + 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((logLevel, formatter(state, exception))); +} diff --git a/test/Memex.Portal.Shared.Test/OAuthSupersedeLineNamesTheRowsTest.cs b/test/Memex.Portal.Shared.Test/OAuthSupersedeLineNamesTheRowsTest.cs new file mode 100644 index 0000000000..d464110a4a --- /dev/null +++ b/test/Memex.Portal.Shared.Test/OAuthSupersedeLineNamesTheRowsTest.cs @@ -0,0 +1,186 @@ +using System; +using System.Linq; +using System.Reactive.Linq; +using System.Reactive.Threading.Tasks; +using System.Security.Claims; +using System.Security.Cryptography; +using System.Text; +using System.Threading.Tasks; +using Memex.Portal.Shared.Authentication; +using MeshWeaver.Fixture; +using MeshWeaver.Hosting.Monolith.TestBase; +using MeshWeaver.Mesh; +using MeshWeaver.Mesh.Services; +using Microsoft.AspNetCore.Http; +using Microsoft.AspNetCore.Mvc; +using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.Logging; +using Xunit; + +namespace Memex.Portal.Shared.Test; + +/// +/// The /token supersede line names the row it removed and the row that replaced it. +/// +/// Why a log line is worth a test. One live credential per (user, client_id) +/// is deliberate (#1493): a re-authorization DELETES the client's previous token. The holder of +/// that previous token then gets a 401, which the validator logs under the token's HASH PREFIX +/// — and that prefix is the last segment of the token row's path. The supersede line used to say +/// only "superseding 1 previous token(s) for user U, client label L": true, and useless +/// for tying it to the 401 it caused. #5074's alternation — two processes of one installation +/// sharing a client_id and evicting each other's credential — is attributable inside a log +/// window only if the supersede names the path whose prefix the 401 names. +/// +/// SHOULD-FAIL-IF the paths leave the line again. The control on the other side is +/// the FIRST exchange, which has nothing to supersede and must log no supersede line at all — an +/// implementation that printed the line on every exchange would fail that half. +/// +public class OAuthSupersedeLineNamesTheRowsTest(ITestOutputHelper output) : MonolithMeshTestBase(output) +{ + private const string RedirectUri = "https://claude.ai/cb"; + private const string UserEmail = "dora@example.com"; + + /// The mesh user id the controller resolves from the claims (email local part). + private const string UserId = "dora"; + + protected override MeshBuilder ConfigureMesh(MeshBuilder builder) + // Same registration the portal wires in ConfigureMemexMesh — the OAuthCode + // NodeType + AuthorizationCode content type the code store persists. + => base.ConfigureMesh(builder).AddOAuthCodeType(); + + private CapturingLogger Log { get; } = new(); + + private IStorageAdapter Storage => Mesh.ServiceProvider.GetRequiredService(); + + private ApiTokenService TokenService() => new( + Mesh.ServiceProvider.GetRequiredService(), + Mesh, + Storage, + Mesh.ServiceProvider.GetRequiredService>()); + + private OAuthConnectController Controller() + { + // The controller resolves its two collaborators lazily from the request's provider; the + // portal registers both as root singletons over the mesh's storage adapter, and so does + // this. + var services = new ServiceCollection(); + services.AddSingleton(new OAuthCodeStore( + Storage, Mesh, Mesh.ServiceProvider.GetRequiredService>())); + services.AddSingleton(TokenService()); + var provider = services.BuildServiceProvider(); + + var identity = new ClaimsIdentity( + [ + new Claim(ClaimTypes.Email, UserEmail), + new Claim(ClaimTypes.Name, "Dora"), + new Claim("preferred_username", UserEmail), + ], + authenticationType: "Test"); + + return new OAuthConnectController(provider, Log) + { + ControllerContext = new ControllerContext + { + HttpContext = new DefaultHttpContext + { + User = new ClaimsPrincipal(identity), + Request = { Scheme = "https", Host = new HostString("memex.test") }, + }, + }, + }; + } + + private static string TokenPath(string rawToken) => + $"{UserId}/ApiToken/{ApiTokenService.HashToken(rawToken)[..12]}"; + + /// One full authorization: /authorize → code → /token → raw token. + private static async Task AuthorizeAndExchange(OAuthConnectController controller, string clientId) + { + var verifier = Convert.ToBase64String(RandomNumberGenerator.GetBytes(32)) + .Replace("+", "-").Replace("/", "_").TrimEnd('='); + var challenge = Convert.ToBase64String(SHA256.HashData(Encoding.ASCII.GetBytes(verifier))) + .Replace("+", "-").Replace("/", "_").TrimEnd('='); + + var redirect = await controller.Authorize( + response_type: "code", + client_id: clientId, + redirect_uri: RedirectUri, + state: "s", + scope: "mcp", + code_challenge: challenge, + code_challenge_method: "S256", + ct: TestContext.Current.CancellationToken) + .ToObservable() + .Should().Within(TestTimeouts.Convergence).Emit(cancellationToken: TestContext.Current.CancellationToken); + + var url = ((RedirectResult)redirect).Url; + var code = Uri.UnescapeDataString(url[(RedirectUri + "?code=").Length..url.IndexOf("&state=", StringComparison.Ordinal)]); + + var result = await controller.ExchangeToken(new TokenRequest + { + grant_type = "authorization_code", + code = code, + client_id = clientId, + redirect_uri = RedirectUri, + code_verifier = verifier, + }, TestContext.Current.CancellationToken) + .ToObservable() + .Should().Within(TestTimeouts.Convergence).Emit(cancellationToken: TestContext.Current.CancellationToken); + + var body = ((OkObjectResult)result).Value!; + return (string)body.GetType().GetProperty("access_token")!.GetValue(body)!; + } + + [Fact] + public async Task TheSupersedeLineNamesTheRowItRemovedAndTheRowThatReplacedIt() + { + var controller = Controller(); + var clientId = "one-installation-" + Guid.NewGuid().ToString("N")[..8]; + var label = $"OAuth: {clientId}"; + + var first = await AuthorizeAndExchange(controller, clientId); + + Log.Lines(LogLevel.Information).Should().NotContain( + l => l.Contains("superseding"), + "the first authorization has nothing to supersede — a line here would be noise, " + + "and the control that the line is tied to an actual removal"); + + // The supersede reads the user's token listing through the synced query, which trails the + // mint. Wait for the FIRST token to be listed before authorizing again, so the second + // exchange's listing is guaranteed to see it — waiting on the actual condition, not a delay. + var listing = TokenService(); + await Observable.Interval(TimeSpan.FromMilliseconds(50)).StartWith(0L) + .SelectMany(_ => listing.GetTokensForUser(UserId).Take(1)) + .Should().Within(TestTimeouts.Convergence) + .Match(all => all.Any(t => t.Label == label && t.NodePath == TokenPath(first)), + cancellationToken: TestContext.Current.CancellationToken); + + var second = await AuthorizeAndExchange(controller, clientId); + second.Should().NotBe(first, "each authorization mints its own credential"); + + // Two lines, two facts. The first is INTENT (the candidate set before any delete ran); + // the second is the OUTCOME (what each delete actually removed). A reader tying a 401 to + // a removal reads the second, so that is the one the paths are asserted on. + var intent = Log.Lines(LogLevel.Information).Where(l => l.Contains("superseding ")).ToArray(); + intent.Should().ContainSingle( + "the second authorization sets out to retire exactly the first credential, once"); + intent.Single().Should() + .Contain("superseding 1 previous token(s)") + .And.Contain(label) + .And.Contain($"candidates {TokenPath(first)}") + .And.Contain($"keeping {TokenPath(second)}"); + + var outcome = Log.Lines(LogLevel.Information).Where(l => l.Contains("superseded ")).ToArray(); + outcome.Should().ContainSingle( + "one removal report per supersede, emitted after every delete has answered"); + outcome.Single().Should() + .Contain("superseded 1 of 1 previous token(s)", + "the count is what the deletes RETURNED, not what was attempted") + .And.Contain(label) + .And.Contain($"removed {TokenPath(first)}", + "the removed row's path carries the hash prefix the holder's 401 will be logged under — " + + "without it the supersede and the 401 it caused cannot be tied together") + .And.Contain($"kept {TokenPath(second)}", + "the replacement is the other half of the same event"); + } +} diff --git a/test/Memex.Portal.Shared.Test/TokenValidationNegativeStagesTest.cs b/test/Memex.Portal.Shared.Test/TokenValidationNegativeStagesTest.cs new file mode 100644 index 0000000000..45facf9c99 --- /dev/null +++ b/test/Memex.Portal.Shared.Test/TokenValidationNegativeStagesTest.cs @@ -0,0 +1,122 @@ +using System; +using System.Linq; +using System.Security.Cryptography; +using System.Threading.Tasks; +using Memex.Portal.Shared.Authentication; +using MeshWeaver.Fixture; +using MeshWeaver.Hosting.Monolith.TestBase; +using MeshWeaver.Mesh; +using MeshWeaver.Mesh.Services; +using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.Logging; +using Xunit; + +namespace Memex.Portal.Shared.Test; + +/// +/// The stage a rejected bearer token is logged under tells the truth about the ROW. +/// +/// Why the log line is the subject. A 401 from the bearer path is a definitive +/// verdict, and the investigation of #5074 rested its whole inference on the stage the validator +/// logs: index-not-found / token-not-found were read as "the row was deleted", which +/// in the OAuth path can only be the one-credential-per-client supersede. That reading is sound +/// ONLY if -not-found is emitted exclusively when the store answered that no row exists. +/// It was not: a row that IS there but whose content cannot be read as a token record took the +/// same branch and printed "no row at {Path}" — sending the reader after a delete that +/// never happened. The two facts now carry two stages, -not-found and -unreadable. +/// +/// What does NOT change. Both are definitive negatives — the store was read, and a row +/// carrying no token record authenticates nobody — so the verdict stays +/// in both cases; +/// remains reserved for a store that could not be read at all. The assertions pin that too. +/// +/// SHOULD-FAIL-IF the two negatives fold back into one line: +/// goes red on +/// the pre-change code (it printed index-not-found for that row), while +/// is the control in the other +/// direction — an implementation that stamped every negative -unreadable would pass the +/// first and fail this one, so no constant satisfies the pair. +/// +public class TokenValidationNegativeStagesTest(ITestOutputHelper output) : MonolithMeshTestBase(output) +{ + private CapturingLogger Log { get; } = new(); + + private IStorageAdapter Storage => Mesh.ServiceProvider.GetRequiredService(); + + private ApiTokenService Service() => new( + Mesh.ServiceProvider.GetRequiredService(), + Mesh, + Storage, + Log); + + /// A raw token nobody minted, in the wire shape the validator accepts. + private static string UnmintedRawToken() => + "mw_" + Convert.ToBase64String(RandomNumberGenerator.GetBytes(32)) + .Replace("+", "-").Replace("/", "_").TrimEnd('='); + + [Fact] + public async Task ARowThatExistsButCarriesNoTokenRecord_IsLoggedUnreadable_NotNotFound() + { + var rawToken = UnmintedRawToken(); + var prefix = ApiTokenService.HashToken(rawToken)[..12]; + var indexPath = $"ApiToken/{prefix}"; + + // The index row EXISTS at the address the validator reads first, but nothing in it is a + // token record: neither an ApiTokenIndex nor a legacy ApiToken, typed or as JSON. + var written = await Storage + .Write(new MeshNode(prefix, "ApiToken") + { + Name = "not a token record", + NodeType = "ApiToken", + State = MeshNodeState.Active, + Content = "not a token record", + }, Mesh.JsonSerializerOptions) + .Should().Within(TestTimeouts.Convergence).Emit(cancellationToken: TestContext.Current.CancellationToken); + written.Should().NotBeNull("the row must be in the store before validation reads it"); + + var verdict = await Service().Validate(rawToken) + .Should().Within(TestTimeouts.Convergence).Emit(cancellationToken: TestContext.Current.CancellationToken); + + verdict.Status.Should().Be( + TokenValidationStatus.Invalid, + "the store WAS read and the row carries no token record — a definitive negative, never Unavailable"); + + var warnings = Log.Lines(LogLevel.Warning); + var forThisToken = warnings.Where(l => l.Contains(prefix)).ToArray(); + forThisToken.Should().ContainSingle( + l => l.Contains("index-unreadable"), + "a row that exists but cannot be typed is its own fact, logged under its own stage"); + forThisToken.Single(l => l.Contains("index-unreadable")).Should() + .Contain($"row at {indexPath} exists") + .And.Contain("was NOT deleted", + "the line must say the opposite of what -not-found says, because the opposite is what happened") + .And.Contain("String", + "naming the content's runtime type is what makes the next occurrence attributable"); + forThisToken.Should().NotContain( + l => l.Contains("-not-found") || l.Contains("no row at"), + "'no row' is the claim an investigation reads as 'the row was deleted', and here the row is there"); + } + + [Fact] + public async Task AnAbsentRow_IsLoggedNotFound_NeverUnreadable() + { + var rawToken = UnmintedRawToken(); + var prefix = ApiTokenService.HashToken(rawToken)[..12]; + + var verdict = await Service().Validate(rawToken) + .Should().Within(TestTimeouts.Convergence).Emit(cancellationToken: TestContext.Current.CancellationToken); + + verdict.Status.Should().Be( + TokenValidationStatus.Invalid, + "an absent row is a verdict, not a failure to reach one"); + + var forThisToken = Log.Lines(LogLevel.Warning).Where(l => l.Contains(prefix)).ToArray(); + forThisToken.Should().ContainSingle( + l => l.Contains("index-not-found") && l.Contains($"no row at ApiToken/{prefix}"), + "an absent row keeps the stage every investigation already knows how to read"); + forThisToken.Should().NotContain( + l => l.Contains("-unreadable"), + "the unreadable stage is reserved for a row that exists — stamping it on absence would " + + "make the split meaningless"); + } +}