Skip to content

fix(auth): a rejected token's log line says whether the row was absent or unreadable, and a supersede names the rows (#5074) - #5198

Merged
rbuergi merged 3 commits into
mainfrom
fix/5074-oauth-supersede-and-unreadable-row-diagnostics
Sep 22, 2026
Merged

rbuergi merged 3 commits into
mainfrom
fix/5074-oauth-supersede-and-unreadable-row-diagnostics

Conversation

@rbuergi

@rbuergi rbuergi commented Sep 22, 2026

Copy link
Copy Markdown
Contributor

Summary

Diagnostics for #5074, so the next occurrence of a "working token answers 401" is attributable inside the log window — plus the doc page the MCP OAuth flow was missing.

The title's mechanism ("MCP OAuth state is per-process") is refuted, re-measured this session on main and the live control instance: the authorization code and the bearer token are written to and read from the shared store on every replica (the deployed IStorageAdapter is the decorated Postgres adapter; the mesh-routed proxy has zero callers), /mcp authenticates through ApiTokenAuthenticationHandler → ApiTokenService.Validate (never the mesh-routed ValidateTokenViaHub, which only serves endpoints without a policy), the MCP transport is Stateless = true, and the data-protection keys are shared. Both replica-hop regression tests already exist and are green on main, so the two-sided test "an exchange arriving on a process that did not start it" cannot be written — the unfixed code passes it. What remains (a client that shares one client_id across processes evicts its own siblings under the one-live-credential rule) is a policy decision, recorded on the issue with its options; this PR does not pick one.

What changes

  1. ApiTokenService.ReadValidationNode — {stage}-not-found ("no row at {Path}") was printed for two different facts: a row the store does not have, and a row it has whose content is not readable as a token record. The second is now {stage}-unreadable, naming the row's version and the content's runtime type and saying the token was NOT deleted. -not-found is emitted only when the store answered "no row" — which is the meaning MCP OAuth state is per-process — on a two-replica deployment the token exchange reaches the wrong replica about half the time #5074's inference (-not-found ⇒ the row was deleted ⇒ supersession) needs it to have. Verdict unchanged: Invalid in both cases; Unavailable/503 stays reserved for a store that could not be read. The stale XML doc on IndexHashVerdict (promising a re-poll on a null verdict the code stopped doing) now matches the code.
  2. OAuthConnectController.SupersedePreviousTokens — the Information line now names the removed paths and the kept path. The removed path ends in the hash prefix the superseded holder's 401 is logged under, so one search for the prefix ties the removal to the 401 it caused.
  3. Doc/AI/McpAuthentication — the page documented only manual tokens although the topic map described it as the OAuth flow. It now carries: the endpoints; what each record stores, where, for how long, and who can read it (checked against Access Control's Admin-partition rule); why a multi-replica portal needs no affinity; the one-live-credential rule and its consequence for a client that shares its client_id; the stage table for reading a rejection (401 vs 503); and the positive post-roll verification read.

No public surface changes (ApiTokenService is internal; the controller's changed method is private). No catalog key changes. Nothing served by a per-node hub changes, so no address needs a recycle after the roll — the new lines are live on any pod running this build.

Controls on both sides

Same test files, same commands (dotnet <Project>.dll -class … on the Release build):

Build TokenValidationNegativeStagesTest ×2 + OAuthSupersedeLineNamesTheRowsTest ×1 Related existing suites
product change reverted, tests kept 2 failed of 3 — the unreadable row printed index-not-found; the supersede line lacked the path (both failure messages quote the old line). The absent-row control passed. —
product change applied 3 of 3 26 of 26 across the new tests, OAuthCodeStoreTest, TokenMintedOnOneReplicaValidatesOnAnotherTest, OAuthAuthorizeReturnUrlIsLocalTest, DeleteTokenReportsWhatItRemovedTest

DocumentationLinkIntegrityTest: 1 of 1 on the rebuilt Documentation assembly (the new page text confirmed embedded). dotnet build -c Release -warnaserror on Memex.Portal.Shared.Test and MeshWeaver.Documentation.Test: 0 Warning(s), 0 Error(s), each with fresh assembly timestamps.

Issue

Refs #5074 — stays OPEN: sev:H closes on the post-roll verification read named on the issue and on the doc page, never on this merge.

🤖 Generated with Claude Code

…t or unreadable, and a supersede names the rows (#5074)

Two links in the #5074 investigation's inference chain (401 → definitive
negative → "-not-found" → the row was deleted → supersession) were weaker
than they read, and both were in the LOG LINES the inference reads:

1. ApiTokenService.ReadValidationNode printed `{stage}-not-found: no row at
   {Path}` for two different facts — a row the store does not have, and a row
   it has whose content is not readable as a token record. The second is now
   its own stage, `{stage}-unreadable`, naming the row's version and the
   content's runtime type and saying the token was NOT deleted. `-not-found`
   is emitted only when the store answered "no row". The verdict is unchanged
   (Invalid in both cases; Unavailable/503 stays reserved for a store that
   could not be read), and the stale doc on IndexHashVerdict that still
   promised a re-poll on a null verdict now describes what the code does.

2. The /token supersede line said "superseding N previous token(s) for user U,
   client label L" — true and uncorrelatable with the 401 it causes. It now
   names the removed paths and the kept path; the removed path ends in the
   hash prefix the superseded holder's 401 is logged under, so one search for
   the prefix ties the two.

Controls on both sides (same files, same commands): with the product change
reverted the new tests read 2 failed of 3 — the unreadable row printed
`index-not-found`, the supersede line lacked the path — and the absent-row
control passed; with the change, 26 of 26 across the new tests and the
existing OAuth/token suites.

Doc/AI/McpAuthentication now carries the OAuth flow itself: the endpoints,
what each record stores and where and for how long and who can read it, why
a multi-replica portal needs no affinity (every record is read from the
shared store on every replica; the MCP transport is stateless; the
protection keys are shared), the one-live-credential rule and its consequence
for a client that shares one client_id across processes, the stage table for
reading a rejection, and the positive post-roll verification read.

Not a fix for the title's mechanism, which is refuted: nothing in this flow
is per-process. Not a fix for the remaining supersession collision either —
that is a policy decision recorded on the issue.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>

Copilot AI left a comment

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Copilot review overview

🟡 Changes recommended

Unresolved moderate findings affect deletion-log accuracy and token-row semantics.

Get a fresh assessment by requesting another Copilot review.

Review effort: Lite
Findings: 1 Medium severity · 1 Low severity

Open (2)
What changed in this PR

Improves MCP OAuth/token diagnostics and documents the OAuth flow, storage model, and rejection stages.

Changes:

  • Distinguishes absent and unreadable token rows in validation logs.
  • Adds superseded and retained paths to OAuth logging with regression tests.
  • Expands MCP authentication documentation.
File Summary and review notes
test/​Memex.Portal.Shared.Test/​TokenValidationNegativeStagesTest.cs Tests absent versus unreadable validation rows.
test/​Memex.Portal.Shared.Test/​OAuthSupersedeLineNamesTheRowsTest.cs Tests supersession log correlation.
test/​Memex.Portal.Shared.Test/​CapturingLogger.cs Captures formatted log entries for tests.
src/​MeshWeaver.Documentation/​Data/​AI/​McpAuthentication.md Documents OAuth behavior and diagnostics; includes nit findings about deletion wording, lifetime text, discovery-chain accuracy, and format-rejection logging.
memex/​Memex.Portal.Shared/​Authentication/​OAuthConnectController.cs Names superseded and retained paths; moderate finding that logging occurs before successful deletion is known.
memex/​Memex.Portal.Shared/​Authentication/​ApiTokenService.cs Logs unreadable rows distinctly; moderate finding about index-row wording and nit regarding unreadable-row contract documentation.

💡 Configure MCP servers for context-aware, tailored reviews. Learn more in the docs.

Comment on lines 445 to +449
logger.LogInformation(
"OAuth: superseding {Count} previous token(s) for user {UserId}, client label {Label} — "
"OAuth: superseding {Count} previous token(s) for user {UserId}, client label {Label}: "
+ "{SupersededPaths} replaced by {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);

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Agreed — the line ran ahead of the fact. DeleteToken answers false for a path that was already gone and faults on a refusal (the per-path catch keeps that token live), so "replaced by" was a claim about an outcome not yet known.

Fixing it in the next push as you suggest, split in two: the pre-line stays as the candidate set ("superseding N previous token(s) … candidates {paths}, keeping {kept}"), and a second Information line after the Concat completes reports what was actually removed — "superseded R of N … removed {paths}; kept {kept}" — collected from each delete's own bool (a caught fault counts as not removed). The test now asserts on the removal line, and it still fails on the pre-change code, which has neither.

|---|---|---|---|---|
| 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 | The token's | Written and deleted under the System identity; the `ApiToken` partition is separately gated and ordinary users hold no grant on it |

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Right — a dangling cell. Changing it to "Follows its token row: written with it, deleted with it (revocation, expiry sweep, supersede)" in the next push.

@github-actions

github-actions Bot commented Sep 22, 2026 •

Copy link
Copy Markdown
Contributor

Test Results (shard 0)

  1 files  ±0    1 suites  ±0   2m 23s ⏱️ -27s
318 tests ±0  318 ✅ ±0  0 💤 ±0  0 ❌ ±0 
322 runs  ±0  322 ✅ ±0  0 💤 ±0  0 ❌ ±0 

Results for commit 36170a6. ± Comparison against base commit bc7fe79.

♻️ This comment has been updated with latest results.

@github-actions

github-actions Bot commented Sep 22, 2026 •

Copy link
Copy Markdown
Contributor

Test Results (shard 3)

443 tests  ±0   443 ✅ ±0   54s ⏱️ +7s
  3 suites ±0     0 💤 ±0 
  3 files   ±0     0 ❌ ±0 

Results for commit 36170a6. ± Comparison against base commit bc7fe79.

♻️ This comment has been updated with latest results.

@github-actions

github-actions Bot commented Sep 22, 2026 •

Copy link
Copy Markdown
Contributor

Test Results (shard 1)

1 590 tests  ±0   1 590 ✅ ±0   3m 11s ⏱️ -1s
    2 suites ±0       0 💤 ±0 
    2 files   ±0       0 ❌ ±0 

Results for commit 36170a6. ± Comparison against base commit bc7fe79.

♻️ This comment has been updated with latest results.

…oved set comes from the deletes' own answers (review)

Review on #5198: the "superseding … replaced by" line ran ahead of the
fact. DeleteToken answers false for a path already gone and faults on a
refusal (the per-path catch keeps that token live), so the line could
claim a removal this exchange never made.

Two lines now. Before any delete: "superseding N previous token(s) … —
candidates {paths}, keeping {kept}" (intent). After the Concat completes:
"superseded R of N … — removed {paths}; kept {kept}" (outcome), where
`removed` holds only the paths whose delete returned true; a caught fault
counts as not removed. The test asserts on the outcome line, which the
pre-change code does not emit either — control re-measured against
origin/main's product: 2 failed of 3 (the absent-row control passed);
with the change 26 of 26. The doc's token-index lifetime cell, left
dangling, now reads "Follows its token row: written with it, deleted
with it", and the supersede paragraph describes both lines.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
@github-actions

github-actions Bot commented Sep 22, 2026 •

Copy link
Copy Markdown
Contributor

Test Results (shard 2)

726 tests  ±0   534 ✅ ±0   5m 53s ⏱️ ±0s
  3 suites ±0   192 💤 ±0 
  3 files   ±0     0 ❌ ±0 

Results for commit 36170a6. ± Comparison against base commit bc7fe79.

♻️ This comment has been updated with latest results.

@github-actions

github-actions Bot commented Sep 22, 2026 •

Copy link
Copy Markdown
Contributor

Test Results (shard 4)

    3 files  ±0      3 suites  ±0   5m 35s ⏱️ -31s
1 956 tests ±0  1 956 ✅ ±0  0 💤 ±0  0 ❌ ±0 
1 957 runs  ±0  1 957 ✅ ±0  0 💤 ±0  0 ❌ ±0 

Results for commit 36170a6. ± Comparison against base commit bc7fe79.

♻️ This comment has been updated with latest results.

@github-actions

github-actions Bot commented Sep 22, 2026 •

Copy link
Copy Markdown
Contributor

Test Results (shard 5)

    5 files  ±0      5 suites  ±0   15m 7s ⏱️ -24s
3 958 tests +3  3 956 ✅ +3  2 💤 ±0  0 ❌ ±0 
3 962 runs  +3  3 960 ✅ +3  2 💤 ±0  0 ❌ ±0 

Results for commit 36170a6. ± Comparison against base commit bc7fe79.

♻️ This comment has been updated with latest results.

@github-actions

github-actions Bot commented Sep 22, 2026 •

Copy link
Copy Markdown
Contributor

Test Results

   17 files  ±0     17 suites  ±0   33m 6s ⏱️ - 1m 15s
8 991 tests +3  8 797 ✅ +3  194 💤 ±0  0 ❌ ±0 
9 000 runs  +3  8 806 ✅ +3  194 💤 ±0  0 ❌ ±0 

Results for commit 36170a6. ± Comparison against base commit bc7fe79.

♻️ This comment has been updated with latest results.

…e, not a literal 30 s

TestTimeoutLiteralRatchetGuard held the count at 380 and the six new
`Within(30.Seconds())` sites took it to 386 (CI shard 5 on #5198). A
literal 30 s is the framework's own write bound, so a wait on it gives
up one second before the framework can say why; the ratchet exists to
keep new sites off it. Converted; the guard reads 380 again locally and
the three tests still pass (3 of 3).

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
@rbuergi
rbuergi added this pull request to the merge queue Sep 22, 2026
Merged via the queue into main with commit 5d28773 Sep 22, 2026
37 checks passed
@rbuergi rbuergi mentioned this pull request Sep 22, 2026
6 of 26 tasks
@rbuergi
rbuergi deleted the fix/5074-oauth-supersede-and-unreadable-row-diagnostics branch October 10, 2026 13:10
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

2 participants