From 521affe6c64c7d6f1d0d9bdbf305800c62806c75 Mon Sep 17 00:00:00 2001 From: Claude Date: Fri, 28 Aug 2026 17:33:09 +0000 Subject: [PATCH] Log the refusal we didn't send on a StackNotFoundError 404 Since #79, a verified requester denied read access gets the same StackNotFoundError/404 as a genuinely missing record, per the anti-oracle rule. That's correct for the client but leaves the operator with no way to tell a subtly-wrong grant apart from a bad record ID or a write that never landed. errorMiddleware now probes existence with the unscoped Stack (one extra read, only on a path that's already failing) and logs the requester DID, record ID, and whether the record existed. The refusing check is always logged as 'read': ScopedStack's denialFor() and get() both collapse into StackNotFoundError exactly when canRead() is false, so there's no second gate to name. Logged at debug rather than warn, since this is the sharing graph written down and shouldn't ship to a general-purpose aggregator by default. Co-Authored-By: Claude Sonnet 5 Claude-Session: https://claude.ai/code/session_0152A7WX2PwCTVr2zgzkS7LZ --- src/app.ts | 2 +- src/middleware/errors.ts | 44 +++++++++++++++-- tests/middleware/errors.test.ts | 85 +++++++++++++++++++++++++++++++-- 3 files changed, 123 insertions(+), 8 deletions(-) diff --git a/src/app.ts b/src/app.ts index 5c53c9f..7f7b100 100644 --- a/src/app.ts +++ b/src/app.ts @@ -44,7 +44,7 @@ export function createApp(ctx: StackContext, config: Config, logger: Logger): Ho exposeHeaders: ['X-Request-Id', 'Content-Disposition'], }), ); - app.onError(errorMiddleware(logger)); + app.onError(errorMiddleware(logger, ctx.stack)); app.use(authMiddleware(config.ownerToken, ctx)); // Cap request body size globally — not per-prefix, so a route added later diff --git a/src/middleware/errors.ts b/src/middleware/errors.ts index b3b4bc0..3ecb09f 100644 --- a/src/middleware/errors.ts +++ b/src/middleware/errors.ts @@ -1,7 +1,7 @@ import type { ErrorHandler } from 'hono'; import type { ContentfulStatusCode } from 'hono/utils/http-status'; import type { Logger } from 'pino'; -import { StackPermissionError } from '@haverstack/core'; +import { StackPermissionError, StackNotFoundError, type Stack } from '@haverstack/core'; import type { AppEnv } from '../types.js'; import { serializeError } from '@haverstack/wire-types'; @@ -11,9 +11,13 @@ import { serializeError } from '@haverstack/wire-types'; * the wire-format's typed `{ error: { code, message } }` body. Anything * else is an unanticipated bug: log it and return a bodyless 500 rather * than guessing at a taxonomy it doesn't belong to. + * + * `stack` is the unscoped root Stack, used only to probe existence for the + * refusal log below — never to read content or bypass a permission check + * for the response itself. */ -export function errorMiddleware(logger: Logger): ErrorHandler { - return (err, c) => { +export function errorMiddleware(logger: Logger, stack: Stack): ErrorHandler { + return async (err, c) => { const wire = serializeError(err); if (wire) { // A permission denial with a resolved auth means the requester's DID @@ -33,6 +37,40 @@ export function errorMiddleware(logger: Logger): ErrorHandler { 'Denied a verified requester', ); } + // A StackNotFoundError for a verified requester is deliberately + // indistinguishable, on the wire, from a genuinely missing record + // (docs/spec/wire-format.md § Server implementation checklist, + // "Log the refusal you didn't send") — that's the anti-oracle rule + // #79 adopted. But the operator is not the adversary: an unscoped + // existence probe here (one extra read, only on a path that's + // already failing) recovers the distinction for the log without + // ever surfacing it to the client. `check` is always 'read' because + // ScopedStack's denialFor()/get() both collapse into + // StackNotFoundError exactly when canRead() is false, regardless of + // which verb (update/delete/etc.) the request asked for — there's no + // second gate to name here. + // + // Logged at debug, not warn: unlike the denial line above, this one + // is "who asked after what, and was refused" — the sharing graph, + // written down — and the spec asks that it not ship to a + // general-purpose aggregator by default (default LOG_LEVEL is info). + if (err instanceof StackNotFoundError && auth) { + const recordId = c.req.param('id'); + if (recordId) { + const existing = await stack.get(recordId); + logger.debug( + { + requestId: c.get('requestId'), + principalId: auth.principalId, + subjectId: auth.subjectId, + recordId, + existed: existing !== null, + check: 'read', + }, + 'Refused a verified requester a 404', + ); + } + } // An anonymous requester gets the same 404 for a private record as for // a missing one (docs/spec/wire-format.md § Server implementation // checklist): a bare 403 or 401 here would confirm the record exists diff --git a/tests/middleware/errors.test.ts b/tests/middleware/errors.test.ts index c9b62df..5a59f74 100644 --- a/tests/middleware/errors.test.ts +++ b/tests/middleware/errors.test.ts @@ -13,10 +13,16 @@ import type { StackContext } from '../../src/stack.js'; import { rm } from 'node:fs/promises'; import { dirname } from 'node:path'; -function spyLogger(): Logger & { warn: ReturnType } { - return { warn: vi.fn(), error: vi.fn(), info: vi.fn() } as unknown as Logger & { - warn: ReturnType; - }; +function spyLogger(): Logger & { + warn: ReturnType; + debug: ReturnType; +} { + return { + warn: vi.fn(), + error: vi.fn(), + info: vi.fn(), + debug: vi.fn(), + } as unknown as Logger & { warn: ReturnType; debug: ReturnType }; } describe('errorMiddleware — denied-but-verified logging', () => { @@ -67,6 +73,77 @@ describe('errorMiddleware — denied-but-verified logging', () => { }); }); +const NOTE_TYPE_ID = 'com.example.test/note@1'; + +describe('errorMiddleware — refusal logging (StackNotFoundError)', () => { + let dbPath: string; + let ctx: StackContext; + + beforeEach(async () => { + dbPath = tempDbPath(); + ctx = await createTestContext(dbPath); + await ctx.stack.defineType(NOTE_TYPE_ID, 'Note', { + body: { kind: 'text' as const, required: true as const }, + }); + }); + + afterEach(async () => { + await ctx.queryWorker.close(); + await ctx.stack.close(); + await ctx.tokens.close(); + await rm(dirname(dbPath), { recursive: true, force: true }).catch(() => {}); + }); + + it('logs existed: true for a verified requester denied read on an existing record', async () => { + const record = await ctx.stack.create(NOTE_TYPE_ID, { body: 'private' }); + const { token } = await ctx.adapter.createToken(OTHER_ENTITY_ID); + const debug = spyLogger(); + const app = createApp(ctx, testConfig(dbPath), debug); + + const { status } = await req(app, 'GET', `/records/${record.id}`, { token }); + expect(status).toBe(404); + expect(debug.debug).toHaveBeenCalledWith( + expect.objectContaining({ + principalId: OTHER_ENTITY_ID, + subjectId: OTHER_ENTITY_ID, + recordId: record.id, + existed: true, + check: 'read', + }), + expect.stringMatching(/refus/i), + ); + }); + + it('logs existed: false for a verified requester on a genuinely missing record', async () => { + const { token } = await ctx.adapter.createToken(OTHER_ENTITY_ID); + const debug = spyLogger(); + const app = createApp(ctx, testConfig(dbPath), debug); + + const { status } = await req(app, 'GET', '/records/nonexistent', { token }); + expect(status).toBe(404); + expect(debug.debug).toHaveBeenCalledWith( + expect.objectContaining({ + principalId: OTHER_ENTITY_ID, + subjectId: OTHER_ENTITY_ID, + recordId: 'nonexistent', + existed: false, + check: 'read', + }), + expect.stringMatching(/refus/i), + ); + }); + + it('does not log for an anonymous 404 on a private record', async () => { + const record = await ctx.stack.create(NOTE_TYPE_ID, { body: 'private' }); + const debug = spyLogger(); + const app = createApp(ctx, testConfig(dbPath), debug); + + const { status } = await req(app, 'GET', `/records/${record.id}`); + expect(status).toBe(404); + expect(debug.debug).not.toHaveBeenCalled(); + }); +}); + describe('errorMiddleware — malformed JSON bodies', () => { let dbPath: string; let ctx: StackContext;