diff --git a/.changeset/hono-adapter-handler-throw-logging.md b/.changeset/hono-adapter-handler-throw-logging.md new file mode 100644 index 0000000000..a800c16cf2 --- /dev/null +++ b/.changeset/hono-adapter-handler-throw-logging.md @@ -0,0 +1,17 @@ +--- +'@objectstack/plugin-hono-server': patch +--- + +修复:逃出路由 handler 的抛出不再被静默丢弃 —— 适配器接缝现在有诊断出口 + +`HonoHttpServer.runHandler()` 的兜底 `.catch` 此前把 rejection 显式丢弃(参数名就是 `_err`),`wrap()` 随后回一个 `{ error: 'No response from handler' }` 的 500。净效果是:**任何**逃出 handler 的抛出,在以本适配器为 transport 的 host 上都表现为一个不带原因的裸 500,而且**任何地方都没有日志** —— 连 stack 都没有。 + +现在该接缝会按 `Logger` 契约打一条 `error` 记录,带上原始 `message` / `stack` 与定位所需的请求上下文(`method` + `path`)。 + +- **`Error` 走契约的 `error` 形参槽**,不塞进结构化 meta。`Error` 的 `message` / `stack` 是 non-enumerable,直接进 meta 会序列化成 `{}` —— 那比没有日志更糟,因为它会报告成功。跨 realm 的 `Error`(`instanceof` 不成立)会按 `name`/`message`/`stack` 重建;`throw 'boom'` 这类非 `Error` 抛出会被描述进 message 而不是丢掉。 +- **请求体不入日志** —— 只有 `method` 和 `path`。 +- **默认就有日志出口。** 未接线时适配器用 `createLogger()`,而不是静默:直接内嵌 `HonoHttpServer` 的 host(serverless 入口)正是本问题的生产现场,静默默认会对它们原样复现该 bug。`HonoServerPlugin.init()` 会用 `ctx.logger` 替换掉默认值;要静默须显式传 `NoopLogger`。 + +新增 `HonoHttpServer.setLogger(logger)`(纯新增,不改 `IHttpServer` 契约)。 + +⚠️ **响应形状一字未改**:兜底 body 仍是 `{ error: 'No response from handler' }` + 500,已加测试钉住。把它收成声明信封会改变线上响应形状,属另一项尚未裁决的契约决策,不随本次改动附带。 diff --git a/packages/plugins/plugin-hono-server/src/adapter.ts b/packages/plugins/plugin-hono-server/src/adapter.ts index 232608cd5e..b8e654721a 100644 --- a/packages/plugins/plugin-hono-server/src/adapter.ts +++ b/packages/plugins/plugin-hono-server/src/adapter.ts @@ -6,8 +6,10 @@ export * from '@objectstack/core'; import { IHttpServer, RouteHandler, - Middleware + Middleware, + createLogger, } from '@objectstack/core'; +import type { Logger } from '@objectstack/spec/contracts'; import type { Context } from 'hono'; import { currentPerfTiming } from '@objectstack/observability'; import { Hono } from 'hono'; @@ -99,6 +101,57 @@ function readRemoteAddress(c: any): string | undefined { } } +/** + * Any thrown value, as a real `Error` whose `message` and `stack` survive + * structured logging. + * + * ## The trap this exists for + * + * `Error.prototype.message` and `.stack` are **non-enumerable**. A rejection + * handed straight to a structured logger's *meta* slot — `{ err }`, + * `{ ...err }`, `JSON.stringify(err)` — therefore serializes to `{}`: the + * record is emitted, the reader sees a log line, and the one thing they needed + * is not in it. That is strictly worse than no log at all, because it reports + * success. (cloud's `objectos-runtime/src/safe-log.ts` header documents the + * same hazard from the other side of the wire.) + * + * The `Logger` contract's `error(message, error?: Error, meta?)` has a + * dedicated `Error` slot precisely so implementations can lift those two + * fields out by name, and all three in-repo implementations do + * (`ObjectLogger`, `ConsoleLogger`, `JsonLogger`). So the adapter's job is + * only to make sure what reaches that slot really is an `Error`: + * + * - a genuine `Error` passes through untouched — original stack preserved; + * - an **error-like** object that fails `instanceof` (a cross-realm `Error` + * from a `vm` context or a worker, the shape a bare spread would flatten to + * `{}`) is rebuilt, carrying its own `name`/`message`/`stack` across; + * - anything else (`throw 'boom'`, `throw { code: 1 }`, `throw undefined`) is + * described in the message rather than dropped, and labelled as a non-Error + * throw so the synthesized stack is not mistaken for the thrower's. + */ +function toLoggableError(thrown: unknown): Error { + if (thrown instanceof Error) return thrown; + + if (thrown !== null && typeof thrown === 'object') { + const like = thrown as { name?: unknown; message?: unknown; stack?: unknown }; + if (typeof like.message === 'string') { + const rebuilt = new Error(like.message); + if (typeof like.name === 'string') rebuilt.name = like.name; + if (typeof like.stack === 'string') rebuilt.stack = like.stack; + return rebuilt; + } + } + + let described: string; + try { + described = typeof thrown === 'string' ? thrown : JSON.stringify(thrown) ?? String(thrown); + } catch { + // Circular / throwing `toJSON` — `String()` still yields something. + described = String(thrown); + } + return new Error(`Non-Error value thrown: ${described}`); +} + /** * The matched route's path parameters, or `{}` when there is no matched route. * @@ -144,6 +197,11 @@ export class HonoHttpServer implements IHttpServer { private fallbackHandler: RouteHandler | undefined; /** Whether the Hono `notFound` hook that runs {@link unmatchedResponse} is mounted. */ private notFoundSeamInstalled = false; + /** + * Where {@link reportHandlerFailure} writes. See {@link setLogger} for why + * the default is a REAL logger and not a no-op. + */ + private logger: Logger = createLogger({ name: 'hono' }); constructor( private port: number = 3000, @@ -362,9 +420,15 @@ export class HonoHttpServer implements IHttpServer { closeStream(); resolve({ response: null, failed: false }); } - }).catch((_err) => { + }).catch((err) => { _endHandler?.(); closeStream(); + // The ONE place an escaping throw is reported (#5848). Both + // callers turn `failed: true` into a 500 that says nothing + // about the cause — `wrap`'s `No response from handler` and + // the `notFound` seam's `Fallback handler failed` — so if the + // diagnosis is not emitted here it does not exist anywhere. + this.reportHandlerFailure(c, err); resolve({ response: null, failed: true }); }); }); @@ -376,6 +440,67 @@ export class HonoHttpServer implements IHttpServer { }; } + /** + * Point this adapter's diagnostics at the host's logger. Called by + * `HonoServerPlugin.init()` with `ctx.logger`; a host that embeds + * `HonoHttpServer` directly (cloud's serverless entrypoints, tests) may + * call it itself, at any time. + * + * ## Why the default is a real logger, not a no-op (#5848) + * + * The failure this reports is one nobody can see any other way: a throw + * that escapes a route handler produces a 500 carrying no cause, so a + * silent default reproduces exactly the bug — bare 5xx, zero log — for + * every host that forgets to wire this. That is not hypothetical: the + * production report behind #5848 came from a control plane built on the + * BARE adapter, i.e. the path that never sees `ctx.logger`, and its only + * remedy was to re-wrap every route in its own try/catch (cloud#1144) — + * paying off this seam's debt one route at a time, which is the tax + * #4264 already described and did not remove. + * + * So the default is `createLogger()`: level `info` (an `error` always + * passes), secrets redacted by field name, and `message`/`stack` lifted + * out of the `Error` slot by name. Wiring a host logger REPLACES it; + * silencing is a deliberate act (pass a `NoopLogger`), never the default. + */ + setLogger(logger: Logger): void { + this.logger = logger; + } + + /** + * Report a throw that escaped a {@link RouteHandler} — the diagnostic exit + * that did not exist before #5848. + * + * Deliberately at `error`, not `warn`: per AGENTS.md "Degradation log + * levels", the third legal answer — "the failure was handed to the CALLER" + * — does NOT apply here. What the caller gets is a bare 500 whose body + * names no cause, no code and no message; they were told that something + * broke, not what, and nothing downstream can reconstruct it. Nor is this + * a validation path that could fire once per malformed keystroke: an + * unhandled throw out of a handler is a server-side defect, and one + * `error` per occurrence is the correct volume. + * + * Method and path only. The request body is NOT logged — it is the most + * likely place for credentials and PII to sit, and `message` + `stack` + * already locate the failure in the code. + */ + private reportHandlerFailure(c: any, thrown: unknown): void { + try { + const method = typeof c?.req?.method === 'string' ? c.req.method : undefined; + const path = typeof c?.req?.path === 'string' ? c.req.path : undefined; + this.logger.error( + '[hono] route handler threw — request answered 500 with no cause in the body', + toLoggableError(thrown), + { method, path }, + ); + } catch { + // Reporting the failure must never become a second failure: a + // host logger that throws (or a partial one missing `error`) + // would otherwise reject `runHandler`'s own promise and turn a + // clean 500 into Hono's opaque error page. + } + } + get(path: string, handler: RouteHandler) { this.registeredRoutes.push({ method: 'GET', pattern: path }); this.app.get(path, this.wrap(handler)); diff --git a/packages/plugins/plugin-hono-server/src/handler-throw-logging.test.ts b/packages/plugins/plugin-hono-server/src/handler-throw-logging.test.ts new file mode 100644 index 0000000000..5bf7a6c2c6 --- /dev/null +++ b/packages/plugins/plugin-hono-server/src/handler-throw-logging.test.ts @@ -0,0 +1,302 @@ +// Copyright (c) 2026 ObjectStack. Licensed under the Apache-2.0 license. + +/** + * A throw that ESCAPES a `RouteHandler` must leave a diagnosis behind (#5848), + * exercised through the real Hono app (`app.fetch`), never a mock. + * + * ## What was wrong + * + * `runHandler()`'s rejection path read `.catch((_err) => …)` — the parameter + * name says it: the error was explicitly discarded. `wrap()` then answered + * `c.json({ error: 'No response from handler' }, 500)`. Net effect on every + * host using this adapter as its transport: a bare 500 whose body names no + * cause, and **no log anywhere** — not even a stack. + * + * #4264 diagnosed exactly this code and its wording still holds, but its fix + * added a `catch` to three datasource ROUTES; the seam itself was untouched, + * so every route added since had to remember to re-wrap. `check-route-envelope.mjs` + * structurally cannot see this class — it audits response WRITE points, and an + * uncaught throw never writes one. + * + * ## What this file pins + * + * 1. the diagnosis exists, at `error`, once per escaped throw; + * 2. it carries the ORIGINAL `message` and `stack` — the non-enumerable trap + * that turns a naively-serialized `Error` into `{}` (see `toLoggableError`); + * 3. it carries enough request context (method + path) to locate the failure, + * and NOTHING from the body; + * 4. the response is **byte-identical** to before. Folding the fallback body + * into a declared envelope is a separate, undecided contract question and + * was explicitly ruled OUT of #5848 — so the old bytes are pinned here, on + * purpose, to keep that decision from drifting in as a rider; + * 5. a successful handler adds no log noise at all. + */ + +import { describe, it, expect, vi } from 'vitest'; +import type { Logger } from '@objectstack/spec/contracts'; + +import { HonoHttpServer } from './adapter'; + +/** One captured log call, with the contract's `error` slot kept separate. */ +interface LogRecord { + level: 'debug' | 'info' | 'warn' | 'error' | 'fatal'; + message: string; + error?: unknown; + meta?: Record; +} + +/** + * A `Logger` that records instead of writing, keeping the `error(message, + * error, meta)` slots distinct — the whole point is to prove the `Error` is + * handed to the slot built for it rather than flattened into `meta`. + */ +function recordingLogger() { + const records: LogRecord[] = []; + const plain = (level: 'debug' | 'info' | 'warn') => + (message: string, meta?: Record) => { records.push({ level, message, meta }); }; + const withError = (level: 'error' | 'fatal') => + (message: string, error?: unknown, meta?: Record) => { + records.push({ level, message, error, meta }); + }; + const logger: Logger = { + debug: plain('debug'), + info: plain('info'), + warn: plain('warn'), + error: withError('error'), + fatal: withError('fatal'), + }; + return { logger, records, errors: () => records.filter((r) => r.level === 'error') }; +} + +function serverWithLogger() { + const server = new HonoHttpServer(0); + const rec = recordingLogger(); + server.setLogger(rec.logger); + return { server, ...rec }; +} + +const call = (server: HonoHttpServer, path: string, init?: RequestInit) => + server.getRawApp().fetch(new Request(`http://localhost${path}`, init)); + +/** The exact bytes `wrap()` answers when a handler produced no response. */ +const FALLBACK_BODY = '{"error":"No response from handler"}'; + +describe('an escaped handler throw is reported', () => { + it('logs the original Error — message AND stack — for an async rejection', async () => { + const { server, errors } = serverWithLogger(); + const boom = new Error('datasource exploded'); + server.get('/api/v1/boom', async () => { throw boom; }); + + const res = await call(server, '/api/v1/boom'); + expect(res.status).toBe(500); + + const [record, ...rest] = errors(); + expect(record, 'an escaped throw produced no error log').toBeDefined(); + expect(rest, 'the same throw was reported more than once').toEqual([]); + + // Handed to the contract's `Error` slot, not flattened into meta. + expect(record!.error).toBe(boom); + expect((record!.error as Error).message).toBe('datasource exploded'); + expect((record!.error as Error).stack).toContain('datasource exploded'); + + // WHY that slot exists, demonstrated on this very error: `message` and + // `stack` are non-enumerable, so an `Error` put in a structured meta + // field serializes to `{}` — a log line that reports success and + // carries nothing. + expect(JSON.stringify({ err: boom })).toBe('{"err":{}}'); + }); + + it('logs a SYNCHRONOUS throw the same way', async () => { + // `runHandler` is `Promise.try`-shaped precisely so a sync throw and an + // async rejection land on one path; the diagnosis must not depend on + // whether the handler happened to be `async`. + const { server, errors } = serverWithLogger(); + server.get('/api/v1/sync-boom', () => { throw new Error('sync exploded'); }); + + expect((await call(server, '/api/v1/sync-boom')).status).toBe(500); + expect((errors()[0]?.error as Error)?.message).toBe('sync exploded'); + }); + + it('logs at `error`, never `warn`', async () => { + // AGENTS.md "Degradation log levels": the "failure handed to the + // CALLER" answer does not apply — the caller gets a 500 naming no + // cause, no code and no message, so the log IS the only record. + const { server, records } = serverWithLogger(); + server.get('/api/v1/level', async () => { throw new Error('x'); }); + + await call(server, '/api/v1/level'); + expect(records.map((r) => r.level)).toEqual(['error']); + }); + + it('carries method + path, and nothing from the request body', async () => { + const { server, errors } = serverWithLogger(); + server.post('/api/v1/records', async () => { throw new Error('write failed'); }); + + await call(server, '/api/v1/records', { + method: 'POST', + headers: { 'content-type': 'application/json' }, + body: JSON.stringify({ password: 'hunter2', ssn: '123-45-6789' }), + }); + + const meta = errors()[0]!.meta!; + expect(meta).toEqual({ method: 'POST', path: '/api/v1/records' }); + // Not merely "redacted" — the body never reaches the record at all. + expect(JSON.stringify(meta)).not.toContain('hunter2'); + expect(JSON.stringify(meta)).not.toContain('123-45-6789'); + }); +}); + +describe('non-Error throws keep their information', () => { + it('describes a primitive throw instead of dropping it', async () => { + const { server, errors } = serverWithLogger(); + server.get('/api/v1/string-throw', async () => { throw 'plain string boom'; }); + + expect((await call(server, '/api/v1/string-throw')).status).toBe(500); + const err = errors()[0]!.error as Error; + expect(err).toBeInstanceOf(Error); + expect(err.message).toContain('plain string boom'); + // Labelled, so the synthesized stack is not read as the thrower's. + expect(err.message).toContain('Non-Error value thrown'); + }); + + it('rebuilds an error-like object that fails `instanceof` (cross-realm Error)', async () => { + // This is the shape the trap actually bites on: an `Error` from another + // realm (a `vm` context, a worker) is not `instanceof Error` here, and + // its `message`/`stack` are still non-enumerable — spread it and you + // get `{}` while believing you logged the cause. + const { server, errors } = serverWithLogger(); + const crossRealm = Object.create(null) as Record; + Object.defineProperty(crossRealm, 'name', { value: 'TypeError', enumerable: false }); + Object.defineProperty(crossRealm, 'message', { value: 'x is not a function', enumerable: false }); + Object.defineProperty(crossRealm, 'stack', { value: 'TypeError: x is not a function\n at foo (bar.js:1:1)', enumerable: false }); + expect(JSON.stringify(crossRealm), 'fixture is not the trap it claims to be').toBe('{}'); + + server.get('/api/v1/cross-realm', async () => { throw crossRealm; }); + await call(server, '/api/v1/cross-realm'); + + const err = errors()[0]!.error as Error; + expect(err).toBeInstanceOf(Error); + expect(err.name).toBe('TypeError'); + expect(err.message).toBe('x is not a function'); + expect(err.stack).toContain('at foo (bar.js:1:1)'); + }); + + it('survives a throw that cannot be JSON-serialized', async () => { + const { server, errors } = serverWithLogger(); + const circular: any = { code: 1 }; + circular.self = circular; + + server.get('/api/v1/circular', async () => { throw circular; }); + expect((await call(server, '/api/v1/circular')).status).toBe(500); + expect(errors()[0]!.error).toBeInstanceOf(Error); + }); +}); + +describe('the fallback (notFound) seam reports too', () => { + it('logs a throwing fallback handler', async () => { + // Same seam, second caller: `installNotFoundSeam` answers a failed + // fallback with its own 500, which likewise names no cause. + const { server, errors } = serverWithLogger(); + server.setFallbackHandler(() => { throw new Error('fallback exploded'); }); + + const res = await call(server, '/nothing/here'); + expect(res.status).toBe(500); + expect(await res.text()).toBe('{"error":"Fallback handler failed"}'); + expect((errors()[0]!.error as Error).message).toBe('fallback exploded'); + expect(errors()[0]!.meta).toEqual({ method: 'GET', path: '/nothing/here' }); + }); +}); + +describe('the response shape is unchanged (explicitly OUT of scope for #5848)', () => { + it('still answers the byte-identical bare 500 body', async () => { + // Folding this into a declared envelope would change a live response + // shape and is an undecided contract question. Pinned so it cannot + // arrive as a rider on the logging fix. + const { server } = serverWithLogger(); + server.get('/api/v1/shape', async () => { throw new Error('boom'); }); + + const res = await call(server, '/api/v1/shape'); + expect(res.status).toBe(500); + expect(await res.text()).toBe(FALLBACK_BODY); + }); + + it('a handler that simply writes nothing is unaffected', async () => { + // Not a throw — the OTHER way to reach the same fallback body. It has + // no error to report, so it must stay silent. + const { server, records } = serverWithLogger(); + server.get('/api/v1/silent', async () => { /* writes nothing */ }); + + const res = await call(server, '/api/v1/silent'); + expect(res.status).toBe(500); + expect(await res.text()).toBe(FALLBACK_BODY); + expect(records).toEqual([]); + }); +}); + +describe('no new noise on the happy path', () => { + it('logs nothing at all when handlers succeed', async () => { + const { server, records } = serverWithLogger(); + server.get('/api/v1/ok', (_req, res) => { res.status(200); res.json({ ok: true }); }); + server.post('/api/v1/ok', (_req, res) => { res.status(201); res.json({ created: true }); }); + + expect(await (await call(server, '/api/v1/ok')).json()).toEqual({ ok: true }); + await call(server, '/api/v1/ok', { + method: 'POST', + headers: { 'content-type': 'application/json' }, + body: JSON.stringify({ a: 1 }), + }); + + expect(records).toEqual([]); + }); + + it('stays silent for a 404 and a 405', async () => { + const { server, records } = serverWithLogger(); + server.put('/api/v1/only-put', (_req, res) => { res.status(200); res.json({ ok: true }); }); + server.installNotFoundSeam(); + + expect((await call(server, '/api/v1/missing')).status).toBe(404); + expect((await call(server, '/api/v1/only-put')).status).toBe(405); + expect(records).toEqual([]); + }); +}); + +describe('a host that wires nothing is still not silent', () => { + it('reports through the default logger (the bare-adapter path)', async () => { + // The motivating production report came from a control plane built on + // the BARE adapter — no plugin, so no `ctx.logger`. A no-op default + // would have reproduced #5848 exactly for that host. + const server = new HonoHttpServer(0); + server.get('/api/v1/bare', async () => { throw new Error('bare adapter boom'); }); + + const written: string[] = []; + const spy = vi.spyOn(process.stderr, 'write').mockImplementation((chunk: any) => { + written.push(String(chunk)); + return true; + }); + try { + expect((await call(server, '/api/v1/bare')).status).toBe(500); + } finally { + spy.mockRestore(); + } + + const output = written.join(''); + expect(output).toContain('bare adapter boom'); + expect(output).toContain('ERROR'); + // The stack, not just the message — that is the half that disappears + // when an `Error` is serialized naively. + expect(output).toContain('handler-throw-logging.test.ts'); + }); + + it('a logger that itself throws cannot turn the 500 into something worse', async () => { + const server = new HonoHttpServer(0); + server.setLogger({ + debug() {}, info() {}, warn() {}, + error() { throw new Error('log sink is down'); }, + } as Logger); + server.get('/api/v1/bad-logger', async () => { throw new Error('boom'); }); + + const res = await call(server, '/api/v1/bad-logger'); + expect(res.status).toBe(500); + expect(await res.text()).toBe(FALLBACK_BODY); + }); +}); diff --git a/packages/plugins/plugin-hono-server/src/hono-plugin.test.ts b/packages/plugins/plugin-hono-server/src/hono-plugin.test.ts index 7af5186de4..ad516cf71a 100644 --- a/packages/plugins/plugin-hono-server/src/hono-plugin.test.ts +++ b/packages/plugins/plugin-hono-server/src/hono-plugin.test.ts @@ -41,6 +41,11 @@ vi.mock('./adapter', async (importOriginal) => ({ // against the REAL adapter in `notfound-405.test.ts` and // `fallback-seam.test.ts`; here it only has to exist. installNotFoundSeam: vi.fn(), + // [#5848] init() hands the adapter `ctx.logger` so a throw escaping + // a route handler lands in the HOST's log pipeline. What the + // adapter then does with it is covered against the REAL adapter in + // `handler-throw-logging.test.ts`; here only the wiring is pinned. + setLogger: vi.fn(), getRawApp: vi.fn().mockReturnValue({ get: vi.fn(), use: vi.fn(), @@ -95,6 +100,17 @@ describe('HonoServerPlugin', () => { expect(HonoHttpServer).toHaveBeenCalled(); }); + it('hands the adapter the host logger on init (#5848)', async () => { + // Without this wiring the adapter falls back to its own default + // logger, and an escaped handler throw is reported outside whatever + // pipeline the host actually reads. + const plugin = new HonoServerPlugin(); + await plugin.init(context as PluginContext); + + const server = (HonoHttpServer as unknown as ReturnType).mock.results[0]!.value; + expect(server.setLogger).toHaveBeenCalledWith(logger); + }); + it('should register IHttpServer service on init', async () => { const plugin = new HonoServerPlugin(); await plugin.init(context as PluginContext); diff --git a/packages/plugins/plugin-hono-server/src/hono-plugin.ts b/packages/plugins/plugin-hono-server/src/hono-plugin.ts index ee0484b285..12f2d5ca29 100644 --- a/packages/plugins/plugin-hono-server/src/hono-plugin.ts +++ b/packages/plugins/plugin-hono-server/src/hono-plugin.ts @@ -228,6 +228,13 @@ export class HonoServerPlugin implements Plugin { * Init phase - Setup HTTP server and register as service */ init = async (ctx: PluginContext) => { + // Hand the adapter the host's logger BEFORE the server is reachable as + // a service — that is the earliest point `ctx` exists (the adapter is + // constructed in this plugin's constructor, which has no context), and + // it is what routes an escaped handler throw into the host's log + // pipeline instead of the adapter's own default (#5848). + this.server.setLogger(ctx.logger); + ctx.logger.debug('Initializing Hono server plugin', { port: this.options.port, staticRoot: this.options.staticRoot