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;