From ac6732b66580fc24cdb015c4b6a61af6b68e323d Mon Sep 17 00:00:00 2001 From: Jack Zhuang <50353452+hotlong@users.noreply.github.com> Date: Thu, 3 Sep 2026 00:57:45 +0800 Subject: [PATCH 1/3] fix(observability,runtime,rest): log every 5xx at `error` level instead of answering it silently MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit A 500 that leaves no server-side line is diagnosed from the browser or not at all. Measured on `main` @ ca48cf377, through the real plugin and the real route handlers: a plain `Error` thrown out of a dispatcher route answered `500 INTERNAL_ERROR` with zero log records at any level. The reporting that existed was not a substitute: `ErrorReporter` defaults to `NoopErrorReporter` (so a dev server captured nothing), and it is fed by `res.__obsRecordedError`, which only the THROWN exit sets — a route that catches its own fault and RETURNS a 5xx envelope recorded nothing at all. `logServerFault` (new, `@objectstack/observability`) is the one definition of the rule, emitting exactly one `error`-level record with method, path, request id, message and stack. It is wired at each transport's own single exit so a fault costs one line and never two. 4xx stays quiet, decided inside the helper. Co-Authored-By: Claude Fable 5.1 --- .changeset/log-every-5xx-server-fault.md | 61 +++++ .../src/__tests__/server-fault-log.test.ts | 138 +++++++++++ packages/observability/src/index.ts | 14 ++ .../observability/src/server-fault-log.ts | 214 ++++++++++++++++++ packages/rest/src/package-routes.ts | 25 ++ .../src/dispatcher-5xx-always-logged.test.ts | 201 ++++++++++++++++ packages/runtime/src/dispatcher-plugin.ts | 103 ++++++++- .../runtime/src/observability/instrument.ts | 18 ++ 8 files changed, 767 insertions(+), 7 deletions(-) create mode 100644 .changeset/log-every-5xx-server-fault.md create mode 100644 packages/observability/src/__tests__/server-fault-log.test.ts create mode 100644 packages/observability/src/server-fault-log.ts create mode 100644 packages/runtime/src/dispatcher-5xx-always-logged.test.ts diff --git a/.changeset/log-every-5xx-server-fault.md b/.changeset/log-every-5xx-server-fault.md new file mode 100644 index 0000000000..0a96d4d534 --- /dev/null +++ b/.changeset/log-every-5xx-server-fault.md @@ -0,0 +1,61 @@ +--- +"@objectstack/observability": patch +"@objectstack/runtime": patch +"@objectstack/rest": patch +--- + +fix(observability,runtime,rest): log every 5xx at `error` level instead of answering it silently (#14310) + +A 500 that leaves no server-side line is diagnosed from the browser or not at +all. Measured on `main`, through the real plugin and the real route handlers: a +plain `Error` thrown out of a dispatcher route answered `500 INTERNAL_ERROR` +with **zero** log records at any level — the only evidence was the client's +console and the response body. That is AGENTS.md "Route & surface ownership §3 +— absence must be loud" inverted, and it is why a `/api/v1/packages` regression +stayed invisible for a week. + +The reporting that already existed was not a substitute, for two independent +reasons: + +- `ErrorReporter.captureException` defaults to `NoopErrorReporter`. A dev + server — the surface an operator actually watches — wires no APM, so the + capture was a no-op every time. A log line is the operator's floor; APM is + opt-in telemetry on top of it. +- It is fed by `res.__obsRecordedError`, which only the THROWN exit sets. A + route that catches its own fault and RETURNS a 5xx envelope — how every + `/packages` handler answers, via `deps.errorFromThrown` — recorded nothing, + so even a wired reporter never saw those. + +**The rule now has one definition.** `logServerFault` (new, in +`@objectstack/observability`, which owns the operator-facing `Logger` / +`ErrorReporter` channel and is already a dependency of both consumers) emits +exactly one `error`-level record carrying method, path, request id, the +message and — where the door still holds the throw — the stack. It could not +live in either consumer: `@objectstack/runtime` depends on `@objectstack/rest`, +so an import could only ever point one way — the same argument that put +`resolveThrownHttpError` in `@objectstack/types` rather than in one of its two +doors. + +Wired at each transport's own single exit, so a fault costs one line and never +two: the dispatcher's thrown exit (`errorResponseBase`) and returned exit +(`sendResultBase`), the AI-route mount that writes its own result, and the REST +direct-mount package registrar's `sendThrownError` plus its two reported +driver faults. `packages/rest`'s `/data` doors were already loud +(`logUnexpectedRouteError`) and are untouched. + +`error` level is load-bearing: the CLI's default is `warn` and `error` (40) +outranks `warn` (30), so the record clears `--log-level`'s default without +bypassing the level system. `--log-level silent` still silences it, which is a +deliberate instruction rather than the default this fixes. + +**4xx stays quiet**, decided once inside the helper rather than at each call +site — client mistakes are already explained by the response, and logging them +is how a `?state=draft` probe once printed 45 stack traces in one browsing +session. + +⚠️ Behaviour change worth knowing before upgrading: a deployment that answers +a *declared* 5xx on a polled route — `501 NOT_IMPLEMENTED` from an uninstalled +optional service, say — now prints one `error` line per request where it +previously printed none. The band is the one the issue specifies ("4xx may stay +quiet; 5xx never"); narrowing it for declared capability-absence would be a +separate contract decision. diff --git a/packages/observability/src/__tests__/server-fault-log.test.ts b/packages/observability/src/__tests__/server-fault-log.test.ts new file mode 100644 index 0000000000..39e0b32dee --- /dev/null +++ b/packages/observability/src/__tests__/server-fault-log.test.ts @@ -0,0 +1,138 @@ +// Copyright (c) 2026 ObjectStack. Licensed under the Apache-2.0 license. + +/** + * [#14310] The shared "a 5xx is never silent" rule, pinned on its own. + * + * The transports each pin the rule from their own side + * (`packages/runtime/src/dispatcher-5xx-always-logged.test.ts`); this file + * pins the rule itself, so a door that starts disagreeing with it turns red + * here rather than in one consumer's suite only. + * + * The band boundary is the assertion that matters most. "4xx may stay quiet; + * 5xx never" is a contract sentence, and 499/500 is where a refactor would + * silently move it. + */ + +import { describe, it, expect, vi } from 'vitest'; + +import { + logServerFault, + isServerFault, + serverFaultLogMessage, + serverFaultLogMeta, + describeFaultRequest, + SERVER_FAULT_LOG_PREFIX, +} from '../server-fault-log.js'; + +const spyLogger = () => ({ + debug: vi.fn(), + info: vi.fn(), + warn: vi.fn(), + error: vi.fn(), + fatal: vi.fn(), + child: vi.fn(), +}); + +describe('isServerFault — the band', () => { + it('is exactly "at or above 500"', () => { + expect(isServerFault(499)).toBe(false); + expect(isServerFault(500)).toBe(true); + expect(isServerFault(503)).toBe(true); + expect(isServerFault(200)).toBe(false); + }); +}); + +describe('logServerFault', () => { + it('emits nothing for a 4xx, and says so in its return value', () => { + const logger = spyLogger(); + expect(logServerFault({ status: 404, error: new Error('nope') }, logger)).toBe(false); + expect(logger.error).not.toHaveBeenCalled(); + expect(logger.warn).not.toHaveBeenCalled(); + expect(logger.info).not.toHaveBeenCalled(); + }); + + it('emits exactly one record, at ERROR level, for a 5xx', () => { + const logger = spyLogger(); + expect(logServerFault({ status: 500, error: new Error('kaboom') }, logger)).toBe(true); + + expect(logger.error).toHaveBeenCalledTimes(1); + // ⛔ Never `warn`/`info`: the level is what makes the line survive + // `--log-level`'s `warn` default. + expect(logger.warn).not.toHaveBeenCalled(); + expect(logger.info).not.toHaveBeenCalled(); + + const [message, error, meta] = logger.error.mock.calls[0]; + expect(String(message)).toContain('kaboom'); + expect((error as Error).stack).toBeTruthy(); + expect(meta).toMatchObject({ status: 500 }); + }); + + it('carries method, path and request id when the door knows them', () => { + const logger = spyLogger(); + logServerFault( + { + status: 500, + error: new Error('driver down'), + code: 'INTERNAL_ERROR', + request: { method: 'GET', path: '/api/v1/packages', requestId: 'req_1' }, + }, + logger, + ); + + const [message, , meta] = logger.error.mock.calls[0]; + expect(String(message)).toBe(`${SERVER_FAULT_LOG_PREFIX} 500 GET /api/v1/packages — driver down`); + expect(meta).toEqual({ + status: 500, + code: 'INTERNAL_ERROR', + method: 'GET', + path: '/api/v1/packages', + requestId: 'req_1', + }); + }); + + it('survives a producer that threw a non-Error, rather than losing the line', () => { + const logger = spyLogger(); + expect(logServerFault({ status: 500, error: 'a bare string' }, logger)).toBe(true); + expect(String(logger.error.mock.calls[0][0])).toContain('a bare string'); + }); + + it('falls back to the envelope message for a declared fault that never threw', () => { + const logger = spyLogger(); + logServerFault({ status: 503, message: 'Package service not available', code: 'SERVICE_UNAVAILABLE' }, logger); + const [message, error] = logger.error.mock.calls[0]; + expect(String(message)).toContain('Package service not available'); + // No throw happened, so no synthetic stack is invented for one. + expect(error).toBeUndefined(); + }); + + it('never throws when the logger does — a logging failure must not become a second fault', () => { + const logger = spyLogger(); + logger.error.mockImplementation(() => { throw new Error('sink is down'); }); + expect(() => logServerFault({ status: 500, error: new Error('x') }, logger)).not.toThrow(); + }); +}); + +describe('serverFaultLogMessage / serverFaultLogMeta', () => { + it('degrade to status alone when the door knows nothing else', () => { + expect(serverFaultLogMessage({ status: 500 })).toBe(`${SERVER_FAULT_LOG_PREFIX} 500 — Unhandled server fault`); + expect(serverFaultLogMeta({ status: 500 })).toEqual({ status: 500 }); + }); +}); + +describe('describeFaultRequest', () => { + it('reads the spellings adapters actually use', () => { + expect(describeFaultRequest({ method: 'GET', path: '/a', requestId: 'r1' })) + .toEqual({ method: 'GET', path: '/a', requestId: 'r1' }); + // `url` and `originalUrl` are the other two spellings in the wild. + expect(describeFaultRequest({ method: 'POST', url: '/b' })).toEqual({ method: 'POST', path: '/b' }); + expect(describeFaultRequest({ originalUrl: '/c' })).toEqual({ path: '/c' }); + // The id may only be on the incoming header. + expect(describeFaultRequest({ headers: { 'x-request-id': 'r2' } })).toEqual({ requestId: 'r2' }); + }); + + it('answers an empty description rather than throwing on a missing request', () => { + expect(describeFaultRequest(undefined)).toEqual({}); + expect(describeFaultRequest(null)).toEqual({}); + expect(describeFaultRequest('not an object')).toEqual({}); + }); +}); diff --git a/packages/observability/src/index.ts b/packages/observability/src/index.ts index 1deb7fb20f..9080bdda13 100644 --- a/packages/observability/src/index.ts +++ b/packages/observability/src/index.ts @@ -42,6 +42,20 @@ export { ConsoleErrorReporter, } from './error-exporters.js'; +// [#14310] The shared "a 5xx is never silent" rule, read by every transport +// that turns a fault into an HTTP envelope (REST's direct-mount doors and the +// runtime dispatcher's two exits). +export { + logServerFault, + isServerFault, + serverFaultLogMessage, + serverFaultLogMeta, + describeFaultRequest, + SERVER_FAULT_LOG_PREFIX, + type ServerFaultLogInput, + type ServerFaultRequest, +} from './server-fault-log.js'; + // Loggers export { NoopLogger, diff --git a/packages/observability/src/server-fault-log.ts b/packages/observability/src/server-fault-log.ts new file mode 100644 index 0000000000..4f36d22bab --- /dev/null +++ b/packages/observability/src/server-fault-log.ts @@ -0,0 +1,214 @@ +// Copyright (c) 2026 ObjectStack. Licensed under the Apache-2.0 license. + +/** + * [#14310] The one rule for "a 5xx must never be silent", shared by every + * transport that turns a fault into an HTTP envelope. + * + * ## The hole this closes + * + * A 500 that leaves no server-side line is diagnosed from the browser or not + * at all. Measured on `main`: a plain `Error` thrown out of a dispatcher route + * answered `500 INTERNAL_ERROR` with **zero** log records at any level — the + * only evidence was the client's console and the response body. The failure + * that motivated this had been reachable for a week and nobody saw it, which + * is AGENTS.md "Route & surface ownership §3 — absence must be loud" inverted. + * + * The reporting that DID exist was not a substitute, in two independent ways: + * + * 1. `ErrorReporter.captureException` is an APM channel and defaults to + * `NoopErrorReporter`. A dev server — the surface an operator actually + * watches — wires no reporter, so the capture was a no-op every time. + * 2. It is fed by `res.__obsRecordedError`, which only the THROWN exit sets. + * A dispatcher route that catches its own fault and RETURNS a 5xx envelope + * (`deps.errorFromThrown`, which is how every `/packages` handler answers) + * records nothing, so even a wired reporter never saw those. + * + * This module is the log half, and it is deliberately not the reporter half: + * an APM capture is opt-in telemetry, a log line is the operator's floor. + * + * ## Why it lives here + * + * `@objectstack/rest` and `@objectstack/runtime` both emit 5xx envelopes and + * both already depend on this package, which owns the operator-facing channel + * (`Logger`, `LOG_LEVELS`, `ErrorReporter`). The rule cannot live in either + * consumer: `runtime` depends on `rest`, so an import could only ever point + * one way — the same argument that put `resolveThrownHttpError` in + * `@objectstack/types` rather than in one of its two doors. Centralising it + * is also what keeps the two doors serving `/api/v1/packages` from printing + * two lines for one fault: each door logs at its own single exit, and the + * predicate that decides "is this worth a line" has one definition. + * + * ## `error` level, and why that clears the default + * + * The requirement is that the line survives `--log-level`'s DEFAULT. The CLI + * default is `warn` (`packages/cli/src/utils/log-level.ts`) and `error` (40) + * outranks `warn` (30) in `LEVEL_PRIORITY`, so an `error` record passes the + * default threshold without any bypass of the level system. An operator who + * asks for `--log-level silent` still gets silence: that is a deliberate + * instruction, not the default this issue is about. + * + * ## 5xx only + * + * 4xx stays quiet, deliberately and at this one gate rather than at each call + * site. A client error is the caller's mistake and the response already + * explains it; logging them is how the `/meta` `?state=draft` probe once + * printed 45 stack traces in one browsing session. `isServerFault` is the + * whole rule: at or above 500. + */ + +import type { Logger } from './contracts.js'; + +/** The request coordinates an operator needs to find the failing call. */ +export interface ServerFaultRequest { + /** HTTP method, e.g. `GET`. */ + method?: string; + /** Request path as served, e.g. `/api/v1/packages`. */ + path?: string; + /** Correlation id — the `X-Request-Id` echoed on the response. */ + requestId?: string; +} + +/** One fault, as the emitting door knows it. */ +export interface ServerFaultLogInput { + /** The HTTP status about to be written. Below 500 nothing is logged. */ + status: number; + /** + * The original thrown value, when the door still holds it. Carries the + * stack; the wire body never does, because a 5xx message is withheld. + */ + error?: unknown; + /** The envelope's `code`, when the door resolved one. */ + code?: string; + /** + * The message to print when {@link ServerFaultLogInput.error} carries + * none — a declared fault built from a string rather than a throw. + */ + message?: string; + /** Where the call came in. */ + request?: ServerFaultRequest; +} + +/** The prefix every fault line carries, so an operator can grep one token. */ +export const SERVER_FAULT_LOG_PREFIX = '[5xx]'; + +/** + * THE predicate. A response is a server fault worth a line exactly when its + * status is 5xx. Exported so a door can decide without restating `>= 500`. + */ +export function isServerFault(status: number): boolean { + return typeof status === 'number' && status >= 500; +} + +/** + * Normalize a thrown value to an `Error`, because `Logger.error`'s second + * parameter is typed to one and a `throw 'string'` must not cost the line. + * Returns `undefined` when there was no throw at all (a declared fault), so + * the logger is not handed an empty synthetic stack. + */ +function toError(thrown: unknown): Error | undefined { + if (thrown === undefined || thrown === null) return undefined; + if (thrown instanceof Error) return thrown; + const wrapped = new Error(typeof thrown === 'string' ? thrown : safeStringify(thrown)); + // The synthetic stack points at THIS file and would mislead; the value's + // own text is the whole of what the producer gave us. + wrapped.stack = undefined; + return wrapped; +} + +function safeStringify(value: unknown): string { + try { + return JSON.stringify(value) ?? String(value); + } catch { + return String(value); + } +} + +/** + * The human half of the line: `[5xx] 500 GET /api/v1/packages — `. + * Split out so both the emitted record and a test can name the same string. + */ +export function serverFaultLogMessage(input: ServerFaultLogInput): string { + const err = toError(input.error); + const text = err?.message || input.message || 'Unhandled server fault'; + const where = [input.request?.method, input.request?.path].filter(Boolean).join(' '); + return `${SERVER_FAULT_LOG_PREFIX} ${input.status}${where ? ` ${where}` : ''} — ${text}`; +} + +/** + * The structured half. `status`/`code`/`requestId` are what a log search keys + * on; `method`/`path` repeat the message's coordinates because a JSON sink + * indexes fields, not prose. + */ +export function serverFaultLogMeta(input: ServerFaultLogInput): Record { + return { + status: input.status, + ...(input.code !== undefined ? { code: input.code } : {}), + ...(input.request?.method !== undefined ? { method: input.request.method } : {}), + ...(input.request?.path !== undefined ? { path: input.request.path } : {}), + ...(input.request?.requestId !== undefined ? { requestId: input.request.requestId } : {}), + }; +} + +/** + * Emit EXACTLY ONE `error`-level record for a 5xx, or nothing at all. + * + * Returns whether a record was emitted, so a caller that must not double-log + * can branch on the answer rather than re-deriving the 5xx test. + * + * `logger` is optional: a door with no injected logger falls back to + * `console.error`, because the point of this function is that the line exists + * even on a surface nobody configured. Emission never throws — a logging + * failure must not become a second fault on top of the one being reported. + */ +export function logServerFault( + input: ServerFaultLogInput, + logger?: Logger, +): boolean { + if (!isServerFault(input.status)) return false; + const message = serverFaultLogMessage(input); + const meta = serverFaultLogMeta(input); + const err = toError(input.error); + try { + if (logger) { + logger.error(message, err, meta); + return true; + } + const sink = (globalThis as { console?: { error?: (...args: unknown[]) => void } }).console; + sink?.error?.(message, { ...meta, ...(err?.stack ? { stack: err.stack } : {}) }); + return true; + } catch { + // Log emission must never throw — the original fault is still answered. + return false; + } +} + +/** + * Read request coordinates off whatever request object the transport hands + * the door. Adapters disagree on the spelling (`path` / `url` / + * `originalUrl`), and the request id may be on the object (set by + * `instrumentRouteHandler`) or only on the incoming header — so both are + * read here, once, instead of at each call site. + */ +export function describeFaultRequest(req: unknown): ServerFaultRequest { + const r = req as { + method?: unknown; + path?: unknown; + url?: unknown; + originalUrl?: unknown; + requestId?: unknown; + headers?: Record; + } | undefined | null; + if (!r || typeof r !== 'object') return {}; + const str = (v: unknown): string | undefined => (typeof v === 'string' && v ? v : undefined); + const headerId = r.headers + ? str(r.headers['x-request-id']) ?? str(r.headers['X-Request-Id']) + : undefined; + const method = str(r.method); + const path = str(r.path) ?? str(r.url) ?? str(r.originalUrl); + const requestId = str(r.requestId) ?? headerId; + return { + ...(method !== undefined ? { method } : {}), + ...(path !== undefined ? { path } : {}), + ...(requestId !== undefined ? { requestId } : {}), + }; +} diff --git a/packages/rest/src/package-routes.ts b/packages/rest/src/package-routes.ts index 079ebd21bb..f68062c291 100644 --- a/packages/rest/src/package-routes.ts +++ b/packages/rest/src/package-routes.ts @@ -7,6 +7,7 @@ import { IHttpServer, shouldDenyAnonymous, ANONYMOUS_DENY_STATUS, ANONYMOUS_DENY // gate's cohort was ruled separately (#7033 / #7023) and pins write-only callers // OUT. Same value it read before — no re-ruling by side effect. import { OBJECT_SCHEMA_READ_ONLY_EXEMPT_CAPABILITIES } from '@objectstack/metadata-core'; +import { logServerFault } from '@objectstack/observability'; import type { PackageService } from '@objectstack/service-package'; // The declared envelope is written in ONE place for the whole platform (#3973), // and so (#8016) is the rule that reads an HTTP answer off a THROWN error. @@ -265,6 +266,16 @@ function sendThrownError(res: any, error: unknown): void { ...(declaredCode !== undefined ? { declaredCode } : {}), ...(thrown.userMessage !== undefined ? { userMessage: thrown.userMessage } : {}), }; + // [#14310] This registrar's 5xx were silent, and it is the door that mounts + // FIRST in the production stack — so for `/api/v1/packages` the silent + // answer was the live one, which is how the fault this card was filed on + // stayed invisible for a week. `logServerFault` owns the 5xx test, so the + // coded 4xx refusals this exit exists to carry (#8016's `409 + // DESTRUCTIVE_CHANGE`, the `[tenant_scope_required]` 400) still cost no + // line. It logs the UNSANITISED `error`: the withhold above is scoped to + // what the CLIENT reads, and an operator losing the driver text to the same + // rule would trade a leak for the blind spot #5437 already refused. + logServerFault({ status: thrown.status, error, code: thrown.code }); sendError( res, thrown.status, @@ -636,6 +647,14 @@ export function registerPackageRoutes( // for a `PackageService` implementation that reports failure without // saying why, which is the one thing the old `error?: string` could not // distinguish from a driver dump. + // [#14310] A REPORTED driver fault never passes through + // {@link sendThrownError} — nothing was thrown — so it owes its own + // line, or this 5xx stays as silent as the thrown ones were. + logServerFault({ + status: 500, + code: 'PACKAGE_PUBLISH_FAILED', + message: result.driverFault?.message ?? `Failed to publish ${manifest.id}.`, + }); sendError( res, 500, @@ -995,6 +1014,12 @@ export function registerPackageRoutes( // producer returns a bare flag with no message channel at all // (`PackageDeleteResult`), which is what keeps that true — this route is // a status-classification defect only, never a disclosure. + // [#14310] Same shape as the publish fault above: reported, not thrown. + logServerFault({ + status: 500, + code: 'PACKAGE_DELETE_FAILED', + message: `Failed to delete ${packageId}${version ? `@${version}` : ''}.`, + }); sendError( res, 500, diff --git a/packages/runtime/src/dispatcher-5xx-always-logged.test.ts b/packages/runtime/src/dispatcher-5xx-always-logged.test.ts new file mode 100644 index 0000000000..4eea79656c --- /dev/null +++ b/packages/runtime/src/dispatcher-5xx-always-logged.test.ts @@ -0,0 +1,201 @@ +// Copyright (c) 2026 ObjectStack. Licensed under the Apache-2.0 license. + +/** + * [#14310] Every 5xx this dispatcher answers leaves an `error`-level record. + * + * ## What went wrong + * + * Measured on `main` @ ca48cf377, through the real plugin and the real route + * handlers: a plain `Error` thrown out of a dispatcher route answered + * `500 INTERNAL_ERROR` with **zero** log records at any level. The only + * evidence a fault had happened was the client's console and the response + * body, which is why the `/packages` regression this card was filed beside + * stayed invisible for a week. + * + * Two independent reasons the existing machinery did not cover it, both + * pinned below: + * + * 1. `errorReporter.captureException` defaults to `NoopErrorReporter`, so on + * any surface nobody wired an APM into — a dev server, above all — the + * capture was a no-op. A log line is the operator's floor; APM is opt-in + * telemetry on top. + * 2. The reporter is fed by `res.__obsRecordedError`, which only the THROWN + * exit sets. A route that catches its own fault and RETURNS a 5xx + * envelope — which is how every `/packages` handler answers + * (`deps.errorFromThrown`) — recorded nothing at all. + * + * ## Why the assertions are shaped this way + * + * The logger is INJECTED (`ctx.logger`, the kernel logger the plugin already + * receives) and spied. ⛔ Not a `console` mock: what this card is about is a + * record reaching the operator's configured sink at a level that survives + * `--log-level`'s default, and a console spy would pass just as green if the + * line bypassed the level system entirely. + * + * `error` level is the load-bearing choice: the CLI's default is `warn` + * (`packages/cli/src/utils/log-level.ts`, `DEFAULT_LOG_LEVEL`) and `error` + * (40) outranks `warn` (30) in `LEVEL_PRIORITY`, so the record clears the + * default threshold without any bypass. Asserting the LEVEL rather than "some + * output happened" is what keeps that true. + * + * The counts are exact (`toHaveLength(1)`), not `toBeGreaterThan(0)`. Two + * doors serve `/api/v1/packages` and the whole point of centralising the rule + * was that a fault produces ONE line rather than one per exit it passes. + */ + +import { describe, it, expect, vi } from 'vitest'; + +import { createDispatcherPlugin } from './dispatcher-plugin.js'; + +function makeFakeServer() { + const handlers: Record any> = {}; + const rec = (verb: string) => (path: string, handler: any) => { + handlers[`${verb} ${path}`] = handler; + }; + return { + handlers, + server: { + get: rec('GET'), + post: rec('POST'), + put: rec('PUT'), + delete: rec('DELETE'), + patch: rec('PATCH'), + }, + }; +} + +function makeRes() { + const res: any = { + statusCode: undefined as number | undefined, + body: undefined as any, + status(c: number) { res.statusCode = c; return res; }, + header() { return res; }, + json(b: any) { res.body = b; return res; }, + }; + return res; +} + +/** Boot the real plugin over a fake transport, with a spied kernel logger. */ +async function boot(services: Record) { + const logger = { info: vi.fn(), warn: vi.fn(), error: vi.fn(), debug: vi.fn() }; + const kernel = { + getService: (n: string) => services[n], + getServiceAsync: async (n: string) => services[n], + }; + const { server, handlers } = makeFakeServer(); + const ctx: any = { + getKernel: () => kernel, + getService: (n: string) => (n === 'http.server' ? server : undefined), + environmentId: undefined, + logger, + hook: () => { }, + on: () => { }, + }; + const plugin = createDispatcherPlugin({ prefix: '/api/v1', securityHeaders: false }); + await plugin.start?.(ctx); + return { handlers, logger }; +} + +/** Only the records this card is about — boot-time chatter is not a fault. */ +function faultRecords(logger: { error: { mock: { calls: any[][] } } }) { + return logger.error.mock.calls.filter((c) => String(c[0]).startsWith('[5xx]')); +} + +describe('#14310 — a 5xx is never silent', () => { + it('a handler throwing a plain Error yields a 500 AND one error-level record carrying the message', async () => { + const { handlers, logger } = await boot({ + analytics: { + query: async () => { throw new Error('boom-plain-error'); }, + getMeta: async () => ({ cubes: [] }), + generateSql: async () => ({ sql: null }), + }, + }); + + const res = makeRes(); + await handlers['POST /api/v1/analytics/query']( + { body: { cube: 'x', measures: ['count'] }, query: {} }, + res, + ); + + expect(res.statusCode).toBe(500); + + const records = faultRecords(logger); + expect(records, 'exactly one fault line per fault').toHaveLength(1); + + // The message the card names. The client no longer reads a 5xx's own + // words (#5437) — the operator must, so this is the assertion that + // makes the line worth printing. + expect(String(records[0][0])).toContain('boom-plain-error'); + + // …and the stack, via `Logger.error`'s error parameter, which both + // shipped loggers fold into the record as `error` + `stack`. + expect((records[0][1] as Error)?.stack).toContain('boom-plain-error'); + + // Method, path and request id — the coordinates that turn a line into + // a diagnosis. They ride `res.__obsRequest`, parked by + // `instrumentRouteHandler`. + expect(records[0][2]).toMatchObject({ + status: 500, + method: 'POST', + path: '/api/v1/analytics/query', + }); + expect(String((records[0][2] as any).requestId)).not.toHaveLength(0); + }); + + it('still hands the same error to the observability side-channel — the log does not replace APM', async () => { + const original = new Error('UNIQUE constraint failed: sys_user.email'); + const { handlers, logger } = await boot({ + analytics: { + query: async () => { throw original; }, + getMeta: async () => ({ cubes: [] }), + generateSql: async () => ({ sql: null }), + }, + }); + + const res = makeRes(); + await handlers['POST /api/v1/analytics/query']( + { body: { cube: 'x', measures: ['count'] }, query: {} }, + res, + ); + + expect((res as any).__obsRecordedError).toBe(original); + // The withheld prose reaches the operator through BOTH channels: the + // body says `Internal server error`, the log says what happened. + expect(res.body.error.message).toBe('Internal server error'); + expect(String(faultRecords(logger)[0][0])).toContain('UNIQUE constraint failed'); + }); + + it('a RETURNED 5xx envelope logs too — the path that leaves no throw to catch', async () => { + // `/notifications` with no messaging service answers through + // `deps.error(...)`: nothing is thrown, so `errorResponseBase` is never + // reached and `__obsRecordedError` is never set. This is the shape + // every `/packages` handler answers with, and the one that was + // completely untraceable before this change. + const { handlers, logger } = await boot({}); + + const res = makeRes(); + await handlers['GET /api/v1/notifications']({ body: {}, query: {}, headers: {}, params: {} }, res); + + expect(res.statusCode).toBeGreaterThanOrEqual(500); + expect((res as any).__obsRecordedError).toBeUndefined(); + + const records = faultRecords(logger); + expect(records, 'the returned exit owes exactly one line too').toHaveLength(1); + expect(records[0][2]).toMatchObject({ status: res.statusCode }); + }); + + it('a 4xx stays quiet — the predicate must not turn client mistakes into fault noise', async () => { + // An anonymous caller on an auth-gated route: a deliberate 401, the + // caller's own business. Logging these is how a `?state=draft` probe + // once printed 45 stack traces in one browsing session. + const pkgSvc = { list: async () => [] }; + const { handlers, logger } = await boot({ package: pkgSvc, packages: pkgSvc }); + + const res = makeRes(); + await handlers['GET /api/v1/packages']({ body: {}, query: {}, headers: {}, params: {} }, res); + + expect(res.statusCode).toBeGreaterThanOrEqual(400); + expect(res.statusCode).toBeLessThan(500); + expect(faultRecords(logger)).toHaveLength(0); + }); +}); diff --git a/packages/runtime/src/dispatcher-plugin.ts b/packages/runtime/src/dispatcher-plugin.ts index 8c9f07c4ed..2796c1fd12 100644 --- a/packages/runtime/src/dispatcher-plugin.ts +++ b/packages/runtime/src/dispatcher-plugin.ts @@ -20,6 +20,11 @@ import { } from './security/index.js'; import { resolveSessionData, resolveSessionPrincipalId } from './security/resolve-session-principal.js'; import { buildActorUser } from './security/actor-user.js'; +import { + logServerFault, + describeFaultRequest, + type Logger, +} from '@objectstack/observability'; import { NoopMetricsRegistry, NoopErrorReporter, @@ -183,6 +188,23 @@ interface RouteDefinition { handler: (req: any) => Promise; } +/** + * [#14310] What the two response exits need in order to make a 5xx loud: the + * kernel logger to write to, and the request whose coordinates the line + * carries. + * + * Threaded as one optional bag rather than two positional parameters because + * both exits are called from ~50 route handlers through the locally-shadowed + * `sendResult` / `errorResponse` wrappers — the bag lets those wrappers bind + * the logger once at `start()` and add only the per-request half at the call + * site. Optional throughout: a caller that supplies nothing still gets the + * line, on `console.error`, which is the property this issue is about. + */ +interface DispatcherFaultLogContext { + logger?: Logger; + req?: unknown; +} + /** * Register a single RouteDefinition on the HTTP server. * Returns true if the route was successfully registered. @@ -193,6 +215,7 @@ function mountRouteOnServer( routePath: string, securityHeaders?: Record, resolveUser?: (headers: Record) => Promise, + faultLogger?: Logger, ): boolean { const handler = async (req: any, res: any) => { try { @@ -293,6 +316,23 @@ function mountRouteOnServer( res.send(buffered); } } else { + // [#14310] This family writes its own result rather than going + // through `sendResultBase`, so it owes the same 5xx line. A + // declared fault here carries no throw — the envelope's own + // message is what there is to print. + logServerFault( + { + status: result.status, + ...(typeof result.body?.error?.message === 'string' + ? { message: result.body.error.message } + : {}), + ...(typeof result.body?.error?.code === 'string' + ? { code: result.body.error.code } + : {}), + request: describeFaultRequest(req), + }, + faultLogger, + ); res.status(result.status); if (securityHeaders) { for (const [k, v] of Object.entries(securityHeaders)) { @@ -306,7 +346,7 @@ function mountRouteOnServer( } } } catch (err: any) { - errorResponseBase(err, res, securityHeaders); + errorResponseBase(err, res, securityHeaders, { logger: faultLogger, req }); } }; @@ -339,7 +379,33 @@ function sendResultBase( result: HttpDispatcherResult, res: any, securityHeaders?: Record, + fault?: DispatcherFaultLogContext, ): void { + // [#14310] The RETURNED exit's half. This is the path the card was filed + // on: every `/packages` handler catches its own fault and answers + // `deps.errorFromThrown(e, 500)`, so nothing is ever thrown past here — + // `errorResponseBase` is not reached, `__obsRecordedError` is never set, + // and the 500 left no trace of any kind. + // + // The original throw is already unwound by the time the envelope arrives, + // so this line carries the envelope's own `code` and `message` rather than + // a stack. That is not a shortfall to fix by threading the error down: a + // 5xx message is withheld from the WIRE (#3867), not from this process, so + // `deps.error`'s pre-sanitisation text is what the door resolved and the + // code is what a search keys on. The stack-bearing line is the thrown + // exit's, one function up. + if (result.handled && result.response) { + const body = result.response.body as { error?: { code?: unknown; message?: unknown } } | undefined; + logServerFault( + { + status: result.response.status, + ...(typeof body?.error?.code === 'string' ? { code: body.error.code } : {}), + ...(typeof body?.error?.message === 'string' ? { message: body.error.message } : {}), + request: describeFaultRequest(fault?.req ?? (res as any)?.__obsRequest), + }, + fault?.logger, + ); + } const applySecurityHeaders = () => { if (!securityHeaders) return; for (const [k, v] of Object.entries(securityHeaders)) { @@ -575,12 +641,31 @@ function sendResultBase( * asserts the code at `error.code` against a real `AnalyticsService` on a real * mounted route. */ -function errorResponseBase(err: any, res: any, securityHeaders?: Record): void { +function errorResponseBase( + err: any, + res: any, + securityHeaders?: Record, + fault?: DispatcherFaultLogContext, +): void { const validation = validationFailureDetails(err); const httpStatus = (typeof err?.status === 'number' ? err.status : undefined) ?? (typeof err?.statusCode === 'number' ? err.statusCode : undefined) ?? (validation ? VALIDATION_FAILED_STATUS : 500); + // [#14310] The THROWN exit's half of "a 5xx is never silent". The + // `__obsRecordedError` side-channel below hands the same error to + // `errorReporter`, which is NOT a substitute: it defaults to + // `NoopErrorReporter`, so on a dev server — the surface an operator + // actually watches — the fault reached nobody. `logServerFault` owns the + // 5xx test, so a 4xx refusal answered here still costs no line. + logServerFault( + { + status: httpStatus, + error: err, + request: describeFaultRequest(fault?.req ?? (res as any)?.__obsRequest), + }, + fault?.logger, + ); res.status(httpStatus); if (securityHeaders) { for (const [k, v] of Object.entries(securityHeaders)) { @@ -820,10 +905,14 @@ export function createDispatcherPlugin(config: DispatcherPluginConfig = {}): Plu // `errorResponse(...)` call below picks these up via lexical // scope, so the 50+ route handlers don't need to thread the // security headers through manually. + // [#14310] The fault logger is bound ONCE here, so every route's + // `sendResult(...)` / `errorResponse(...)` call is unchanged and + // still gets a loud 5xx. The per-request half rides the + // `res.__obsRequest` side-channel the instrument wrapper parks. const sendResult = (result: HttpDispatcherResult, res: any) => - sendResultBase(result, res, securityHeaders); + sendResultBase(result, res, securityHeaders, { logger: ctx.logger }); const errorResponse = (err: any, res: any) => - errorResponseBase(err, res, securityHeaders); + errorResponseBase(err, res, securityHeaders, { logger: ctx.logger }); // ── Observability ────────────────────────────────────────── // Noop defaults; production hosts inject real adapters. @@ -1909,11 +1998,11 @@ export function createDispatcherPlugin(config: DispatcherPluginConfig = {}): Plu let count = 0; if (enableProjectScoping && projectResolution === 'required') { - if (mountRouteOnServer(route, server, toScopedPath(routePath), securityHeaders, resolveRequestUser)) count++; + if (mountRouteOnServer(route, server, toScopedPath(routePath), securityHeaders, resolveRequestUser, ctx.logger)) count++; } else { - if (mountRouteOnServer(route, server, routePath, securityHeaders, resolveRequestUser)) count++; + if (mountRouteOnServer(route, server, routePath, securityHeaders, resolveRequestUser, ctx.logger)) count++; if (enableProjectScoping) { - if (mountRouteOnServer(route, server, toScopedPath(routePath), securityHeaders, resolveRequestUser)) count++; + if (mountRouteOnServer(route, server, toScopedPath(routePath), securityHeaders, resolveRequestUser, ctx.logger)) count++; } } return count; diff --git a/packages/runtime/src/observability/instrument.ts b/packages/runtime/src/observability/instrument.ts index d472fa0a11..3b0570978b 100644 --- a/packages/runtime/src/observability/instrument.ts +++ b/packages/runtime/src/observability/instrument.ts @@ -120,6 +120,24 @@ export function instrumentRouteHandler( } } + // [#14310] Side-channel: the request coordinates a 5xx log line needs, + // parked where the RESPONSE exits can reach them. + // + // `sendResultBase` / `errorResponseBase` are called as `(result, res)` + // from ~50 route handlers through locally-shadowed wrappers, so they + // never see `req`. Threading a third argument through every one of + // those call sites would be a fifty-file diff whose only content is + // passing a parameter — and the one place that already holds the + // method, the route PATTERN (lower cardinality than a raw path, the + // same string the metrics labels use) and the resolved request id is + // right here. Same shape and same lifetime as `__obsRecordedError`, + // which the error exit has parked on `res` since #3867. + try { + (res as any).__obsRequest = { method, path: route, requestId }; + } catch { + // frozen / proxy res — the log line degrades to status + code + } + // Capture the final status. We start at 200 (the adapter default // when no status() is called) and override on status() calls via // a tiny proxy. From b31868383f8b78c6873094f0825bf9af781a0b98 Mon Sep 17 00:00:00 2001 From: Jack Zhuang <50353452+hotlong@users.noreply.github.com> Date: Thu, 3 Sep 2026 01:02:14 +0800 Subject: [PATCH 2/3] chore(docs): re-anchor the system-context census after the package-routes import `check:check-system-context-census` went red on pure line rot: the `logServerFault` import added one line to `packages/rest/src/package-routes.ts`, shifting both anchored elevation reads by one (97 -> 98, 102 -> 103). Repaired with the gate's own `--fix`; no prose changed and no row added or removed. Co-Authored-By: Claude Fable 5.1 --- content/docs/permissions/system-context.mdx | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/content/docs/permissions/system-context.mdx b/content/docs/permissions/system-context.mdx index 211a566390..0cb3553b52 100644 --- a/content/docs/permissions/system-context.mdx +++ b/content/docs/permissions/system-context.mdx @@ -160,9 +160,9 @@ The largest single consumer — **20 of the 109 sites**. | 49 | Action `requiredPermissions` bypassed | runtime | Get: engine self-invocation runs any action | `action-execution.ts:399` | | 50 | `manage_metadata` bypassed on metadata writes | runtime, rest | Get: schema writes without the capability | `domains/meta.ts:471`, `:874`, `rest-server.ts:4716`, `:6079`, `:6327`, `:6758`, `:6951` | | 51 | The shared metadata-write verdict itself returns `allowed` | metadata-core | Get: the one function all of row 50's doors consult answers yes before any capability is examined | `meta-write-capability.ts:134` | -| 52 | Anonymous-deny seam satisfied on the domain dispatchers and the package/federation routes | runtime, rest | Get: passes with no `userId` | `domains/actions.ts:411`, `domains/ai.ts:60`, `domains/automation.ts:989`, `domains/meta.ts:232`, `domains/security.ts:78`, `domains/packages.ts:276`, `external-datasource-routes.ts:302`, `package-routes.ts:97` | +| 52 | Anonymous-deny seam satisfied on the domain dispatchers and the package/federation routes | runtime, rest | Get: passes with no `userId` | `domains/actions.ts:411`, `domains/ai.ts:60`, `domains/automation.ts:989`, `domains/meta.ts:232`, `domains/security.ts:78`, `domains/packages.ts:276`, `external-datasource-routes.ts:302`, `package-routes.ts:98` | | 53 | MCP principal check satisfied | runtime | Get: MCP surface reachable with no user | `domains/mcp.ts:61` | -| 54 | Package REST route capability gate bypassed | rest | Get: package read/write over REST without `manage_metadata` / `studio.access` / `setup.access` | `package-routes.ts:102` | +| 54 | Package REST route capability gate bypassed | rest | Get: package read/write over REST without `manage_metadata` / `studio.access` / `setup.access` | `package-routes.ts:103` | | 55 | Package domain capability gates bypassed | runtime | Get: package management and package-inventory reads without the capability | `domains/packages.ts:95`, `:128` | | 56 | Activation write / authoring refusals do not fire | runtime | Get: activation artifacts writable and authorable without the activation-authoring capability | `activation-gate.ts:139`, `:190` | | 57 | Automation run-state read, flow-authoring write and unrelated-screen read all pass | runtime | Get: run state, flow writes and screen reads with no grant | `domains/automation.ts:254`, `:545`, `:635` | From b4bc2ab473e5f8b9d95326e9a191f4ded2ac98e5 Mon Sep 17 00:00:00 2001 From: Jack Zhuang <50353452+hotlong@users.noreply.github.com> Date: Thu, 3 Sep 2026 01:11:57 +0800 Subject: [PATCH 3/3] refactor(types): move the 5xx fault-log rule to @objectstack/types and land it on sendError MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Re-homed under the domain seat's serial fence: `packages/rest/src/package-routes.ts` is held by the open PR #14499, so this no longer edits that file. The REST direct-mount doors are covered from the producer side instead. `sendError` (`@objectstack/types`) is the single writer for every nested-envelope error in the repo, and every catch in the package registrar ends there — so wiring the rule at that one exit covers those doors with no per-door call, and covers any door added later by construction. That also puts the helper in the same package as `resolveThrownHttpError`, on the same argument: a rule two doors must agree on cannot live inside one of them. `@objectstack/observability` and `packages/rest` are back to origin/main byte-for-byte, as is the system-context census page (its line rot was caused by the package-routes import this drops). Co-Authored-By: Claude Fable 5.1 --- .changeset/log-every-5xx-server-fault.md | 41 ++++++------ content/docs/permissions/system-context.mdx | 4 +- packages/observability/src/index.ts | 14 ---- packages/rest/src/package-routes.ts | 25 ------- packages/runtime/src/dispatcher-plugin.ts | 9 +-- packages/types/src/index.ts | 4 ++ packages/types/src/response-envelope.ts | 18 +++++ .../src}/server-fault-log.test.ts | 67 ++++++++++++++++++- .../src/server-fault-log.ts | 23 ++++--- 9 files changed, 127 insertions(+), 78 deletions(-) rename packages/{observability/src/__tests__ => types/src}/server-fault-log.test.ts (65%) rename packages/{observability => types}/src/server-fault-log.ts (90%) diff --git a/.changeset/log-every-5xx-server-fault.md b/.changeset/log-every-5xx-server-fault.md index 0a96d4d534..3564759c89 100644 --- a/.changeset/log-every-5xx-server-fault.md +++ b/.changeset/log-every-5xx-server-fault.md @@ -1,10 +1,9 @@ --- -"@objectstack/observability": patch +"@objectstack/types": patch "@objectstack/runtime": patch -"@objectstack/rest": patch --- -fix(observability,runtime,rest): log every 5xx at `error` level instead of answering it silently (#14310) +fix(types,runtime): log every 5xx at `error` level instead of answering it silently (#14310) A 500 that leaves no server-side line is diagnosed from the browser or not at all. Measured on `main`, through the real plugin and the real route handlers: a @@ -27,21 +26,24 @@ reasons: so even a wired reporter never saw those. **The rule now has one definition.** `logServerFault` (new, in -`@objectstack/observability`, which owns the operator-facing `Logger` / -`ErrorReporter` channel and is already a dependency of both consumers) emits -exactly one `error`-level record carrying method, path, request id, the -message and — where the door still holds the throw — the stack. It could not -live in either consumer: `@objectstack/runtime` depends on `@objectstack/rest`, -so an import could only ever point one way — the same argument that put -`resolveThrownHttpError` in `@objectstack/types` rather than in one of its two -doors. - -Wired at each transport's own single exit, so a fault costs one line and never -two: the dispatcher's thrown exit (`errorResponseBase`) and returned exit -(`sendResultBase`), the AI-route mount that writes its own result, and the REST -direct-mount package registrar's `sendThrownError` plus its two reported -driver faults. `packages/rest`'s `/data` doors were already loud -(`logUnexpectedRouteError`) and are untouched. +`@objectstack/types`) emits exactly one `error`-level record carrying method, +path, request id, the message and — where the door still holds the throw — the +stack. It shares a home with `resolveThrownHttpError` for the same reason that +rule was moved there in #8016: a rule two doors must agree on cannot live +inside one of them, because `@objectstack/runtime` depends on +`@objectstack/rest` and an import could only ever point one way. + +Wired at each transport's single exit, so a fault costs one line and never two: + +- `sendError` — the one writer for every nested-envelope error in the repo. The + REST direct-mount registrars (the `/api/v1/packages` door that mounts first + in production) become loud through it with no per-door call, so a door added + later cannot forget one. +- The dispatcher's thrown exit (`errorResponseBase`), its returned exit + (`sendResultBase`) and the AI-route mount that writes its own result. + +`packages/rest`'s `/data` doors were already loud via `logUnexpectedRouteError` +and are untouched. `error` level is load-bearing: the CLI's default is `warn` and `error` (40) outranks `warn` (30), so the record clears `--log-level`'s default without @@ -51,7 +53,8 @@ deliberate instruction rather than the default this fixes. **4xx stays quiet**, decided once inside the helper rather than at each call site — client mistakes are already explained by the response, and logging them is how a `?state=draft` probe once printed 45 stack traces in one browsing -session. +session. The wire body is byte-identical at every door: this adds a side +effect, never a field. ⚠️ Behaviour change worth knowing before upgrading: a deployment that answers a *declared* 5xx on a polled route — `501 NOT_IMPLEMENTED` from an uninstalled diff --git a/content/docs/permissions/system-context.mdx b/content/docs/permissions/system-context.mdx index 0cb3553b52..211a566390 100644 --- a/content/docs/permissions/system-context.mdx +++ b/content/docs/permissions/system-context.mdx @@ -160,9 +160,9 @@ The largest single consumer — **20 of the 109 sites**. | 49 | Action `requiredPermissions` bypassed | runtime | Get: engine self-invocation runs any action | `action-execution.ts:399` | | 50 | `manage_metadata` bypassed on metadata writes | runtime, rest | Get: schema writes without the capability | `domains/meta.ts:471`, `:874`, `rest-server.ts:4716`, `:6079`, `:6327`, `:6758`, `:6951` | | 51 | The shared metadata-write verdict itself returns `allowed` | metadata-core | Get: the one function all of row 50's doors consult answers yes before any capability is examined | `meta-write-capability.ts:134` | -| 52 | Anonymous-deny seam satisfied on the domain dispatchers and the package/federation routes | runtime, rest | Get: passes with no `userId` | `domains/actions.ts:411`, `domains/ai.ts:60`, `domains/automation.ts:989`, `domains/meta.ts:232`, `domains/security.ts:78`, `domains/packages.ts:276`, `external-datasource-routes.ts:302`, `package-routes.ts:98` | +| 52 | Anonymous-deny seam satisfied on the domain dispatchers and the package/federation routes | runtime, rest | Get: passes with no `userId` | `domains/actions.ts:411`, `domains/ai.ts:60`, `domains/automation.ts:989`, `domains/meta.ts:232`, `domains/security.ts:78`, `domains/packages.ts:276`, `external-datasource-routes.ts:302`, `package-routes.ts:97` | | 53 | MCP principal check satisfied | runtime | Get: MCP surface reachable with no user | `domains/mcp.ts:61` | -| 54 | Package REST route capability gate bypassed | rest | Get: package read/write over REST without `manage_metadata` / `studio.access` / `setup.access` | `package-routes.ts:103` | +| 54 | Package REST route capability gate bypassed | rest | Get: package read/write over REST without `manage_metadata` / `studio.access` / `setup.access` | `package-routes.ts:102` | | 55 | Package domain capability gates bypassed | runtime | Get: package management and package-inventory reads without the capability | `domains/packages.ts:95`, `:128` | | 56 | Activation write / authoring refusals do not fire | runtime | Get: activation artifacts writable and authorable without the activation-authoring capability | `activation-gate.ts:139`, `:190` | | 57 | Automation run-state read, flow-authoring write and unrelated-screen read all pass | runtime | Get: run state, flow writes and screen reads with no grant | `domains/automation.ts:254`, `:545`, `:635` | diff --git a/packages/observability/src/index.ts b/packages/observability/src/index.ts index 9080bdda13..1deb7fb20f 100644 --- a/packages/observability/src/index.ts +++ b/packages/observability/src/index.ts @@ -42,20 +42,6 @@ export { ConsoleErrorReporter, } from './error-exporters.js'; -// [#14310] The shared "a 5xx is never silent" rule, read by every transport -// that turns a fault into an HTTP envelope (REST's direct-mount doors and the -// runtime dispatcher's two exits). -export { - logServerFault, - isServerFault, - serverFaultLogMessage, - serverFaultLogMeta, - describeFaultRequest, - SERVER_FAULT_LOG_PREFIX, - type ServerFaultLogInput, - type ServerFaultRequest, -} from './server-fault-log.js'; - // Loggers export { NoopLogger, diff --git a/packages/rest/src/package-routes.ts b/packages/rest/src/package-routes.ts index f68062c291..079ebd21bb 100644 --- a/packages/rest/src/package-routes.ts +++ b/packages/rest/src/package-routes.ts @@ -7,7 +7,6 @@ import { IHttpServer, shouldDenyAnonymous, ANONYMOUS_DENY_STATUS, ANONYMOUS_DENY // gate's cohort was ruled separately (#7033 / #7023) and pins write-only callers // OUT. Same value it read before — no re-ruling by side effect. import { OBJECT_SCHEMA_READ_ONLY_EXEMPT_CAPABILITIES } from '@objectstack/metadata-core'; -import { logServerFault } from '@objectstack/observability'; import type { PackageService } from '@objectstack/service-package'; // The declared envelope is written in ONE place for the whole platform (#3973), // and so (#8016) is the rule that reads an HTTP answer off a THROWN error. @@ -266,16 +265,6 @@ function sendThrownError(res: any, error: unknown): void { ...(declaredCode !== undefined ? { declaredCode } : {}), ...(thrown.userMessage !== undefined ? { userMessage: thrown.userMessage } : {}), }; - // [#14310] This registrar's 5xx were silent, and it is the door that mounts - // FIRST in the production stack — so for `/api/v1/packages` the silent - // answer was the live one, which is how the fault this card was filed on - // stayed invisible for a week. `logServerFault` owns the 5xx test, so the - // coded 4xx refusals this exit exists to carry (#8016's `409 - // DESTRUCTIVE_CHANGE`, the `[tenant_scope_required]` 400) still cost no - // line. It logs the UNSANITISED `error`: the withhold above is scoped to - // what the CLIENT reads, and an operator losing the driver text to the same - // rule would trade a leak for the blind spot #5437 already refused. - logServerFault({ status: thrown.status, error, code: thrown.code }); sendError( res, thrown.status, @@ -647,14 +636,6 @@ export function registerPackageRoutes( // for a `PackageService` implementation that reports failure without // saying why, which is the one thing the old `error?: string` could not // distinguish from a driver dump. - // [#14310] A REPORTED driver fault never passes through - // {@link sendThrownError} — nothing was thrown — so it owes its own - // line, or this 5xx stays as silent as the thrown ones were. - logServerFault({ - status: 500, - code: 'PACKAGE_PUBLISH_FAILED', - message: result.driverFault?.message ?? `Failed to publish ${manifest.id}.`, - }); sendError( res, 500, @@ -1014,12 +995,6 @@ export function registerPackageRoutes( // producer returns a bare flag with no message channel at all // (`PackageDeleteResult`), which is what keeps that true — this route is // a status-classification defect only, never a disclosure. - // [#14310] Same shape as the publish fault above: reported, not thrown. - logServerFault({ - status: 500, - code: 'PACKAGE_DELETE_FAILED', - message: `Failed to delete ${packageId}${version ? `@${version}` : ''}.`, - }); sendError( res, 500, diff --git a/packages/runtime/src/dispatcher-plugin.ts b/packages/runtime/src/dispatcher-plugin.ts index 2796c1fd12..5b79d6cdf4 100644 --- a/packages/runtime/src/dispatcher-plugin.ts +++ b/packages/runtime/src/dispatcher-plugin.ts @@ -1,9 +1,9 @@ // Copyright (c) 2025 ObjectStack. Licensed under the Apache-2.0 license. import { Plugin, PluginContext, IHttpServer, ANONYMOUS_DENY_BODY, ANONYMOUS_DENY_STATUS } from '@objectstack/core'; -import { looksLikeInternalErrorLeak, INTERNAL_ERROR_MESSAGE, resolveThrownHttpError, serverFaultProvenance, demotedDeclaredCode } from '@objectstack/types'; +import { looksLikeInternalErrorLeak, INTERNAL_ERROR_MESSAGE, resolveThrownHttpError, serverFaultProvenance, demotedDeclaredCode, logServerFault, describeFaultRequest } from '@objectstack/types'; import { DispatcherErrorCode } from '@objectstack/spec/api'; -import type { IAuthService, IMetadataService } from '@objectstack/spec/contracts'; +import type { IAuthService, IMetadataService, Logger } from '@objectstack/spec/contracts'; import type { CounterStore } from '@objectstack/plugin-auth/rate-limit-storage'; import { HttpDispatcher, HttpDispatcherResult, type HttpProtocolContext } from './http-dispatcher.js'; import { isServiceServeable } from './service-serveable.js'; @@ -20,11 +20,6 @@ import { } from './security/index.js'; import { resolveSessionData, resolveSessionPrincipalId } from './security/resolve-session-principal.js'; import { buildActorUser } from './security/actor-user.js'; -import { - logServerFault, - describeFaultRequest, - type Logger, -} from '@objectstack/observability'; import { NoopMetricsRegistry, NoopErrorReporter, diff --git a/packages/types/src/index.ts b/packages/types/src/index.ts index a36698a4bd..cba1459dbf 100644 --- a/packages/types/src/index.ts +++ b/packages/types/src/index.ts @@ -18,6 +18,10 @@ export * from './response-envelope.js'; // direct-mount REST registrar, which used to answer 500 INTERNAL_ERROR for a // coded 4xx the dispatcher mapped correctly. export * from './thrown-http-error.js'; +// [#14310] The sibling rule to the one above, for the same two doors: "is this +// answer worth an operator's attention?". `resolveThrownHttpError` decides what +// the CLIENT is told; this decides what the LOG says — 5xx always, 4xx never. +export * from './server-fault-log.js'; export * from './validation-failure.js'; // [#6615] The one home for Postgres' `«sub-object» "x" of relation "y"` phrase, // whose missing-COLUMN spelling contains a legal missing-TABLE phrase as a diff --git a/packages/types/src/response-envelope.ts b/packages/types/src/response-envelope.ts index 0302d9a0d0..6838a6a014 100644 --- a/packages/types/src/response-envelope.ts +++ b/packages/types/src/response-envelope.ts @@ -51,6 +51,7 @@ */ import type { ApiError, ErrorCode } from '@objectstack/spec/api'; +import { logServerFault } from './server-fault-log.js'; /** * The only thing an envelope builder needs from a response object. @@ -207,5 +208,22 @@ export function sendError( message: string, extra?: Pick, ): void { + // [#14310] A 5xx is never silent. This writer is the single exit for every + // nested-envelope error in the repo, so the rule is applied ONCE here rather + // than at each registrar's catch block — a per-door call is a thing a new + // door can forget, and the `/api/v1/packages` 500 that motivated the card + // went unlogged for a week through exactly such a door. + // + // ⛔ Not a second opinion about the answer: `logServerFault` reads the same + // `status` this call is about to write, and its own 5xx gate keeps every + // deliberate 4xx refusal — the coded `409 DESTRUCTIVE_CHANGE`, the + // `403 FORBIDDEN` capability denials above it — as quiet as they were. + // + // The thrown value is not available here (callers resolve it into `message` + // before arriving), so this line carries the message and code rather than a + // stack. A door still holding the throw can call `logServerFault` itself for + // the stack-bearing line; none does today, and the transports that DO hold + // it log at their own exits instead. + logServerFault({ status, code, message, ...(extra?.requestId ? { request: { requestId: extra.requestId } } : {}) }); res.status(status).json({ success: false, error: { code, message, ...extra } }); } diff --git a/packages/observability/src/__tests__/server-fault-log.test.ts b/packages/types/src/server-fault-log.test.ts similarity index 65% rename from packages/observability/src/__tests__/server-fault-log.test.ts rename to packages/types/src/server-fault-log.test.ts index 39e0b32dee..71e3cd37ef 100644 --- a/packages/observability/src/__tests__/server-fault-log.test.ts +++ b/packages/types/src/server-fault-log.test.ts @@ -22,7 +22,8 @@ import { serverFaultLogMeta, describeFaultRequest, SERVER_FAULT_LOG_PREFIX, -} from '../server-fault-log.js'; +} from './server-fault-log.js'; +import { sendError } from './response-envelope.js'; const spyLogger = () => ({ debug: vi.fn(), @@ -119,6 +120,70 @@ describe('serverFaultLogMessage / serverFaultLogMeta', () => { }); }); +describe('sendError — the funnel every nested-envelope 5xx exits through', () => { + /** + * This is the half that makes the REST direct-mount registrars loud + * without any per-door call: `packages/rest`'s package routes end every + * catch in `sendError`, so wiring the rule HERE covers them (and any door + * added later) by construction rather than by remembering. + * + * The sink is `console.error` because `sendError` takes no logger — it is + * a pure envelope writer reached from ~50 sites that have no logger to + * pass. Spying it is the only way to observe this seam, and it is done + * ONLY here: the behavioural pins that matter (level, exact count, the + * message and stack) assert against an INJECTED logger above and in + * `packages/runtime/src/dispatcher-5xx-always-logged.test.ts`, where a + * console spy would have been the weaker instrument. + */ + const makeRes = () => { + const res: any = { + statusCode: undefined as number | undefined, + body: undefined as any, + status(c: number) { res.statusCode = c; return res; }, + json(b: any) { res.body = b; return res; }, + }; + return res; + }; + + it('logs a 5xx', () => { + const spy = vi.spyOn(console, 'error').mockImplementation(() => { }); + try { + sendError(makeRes(), 500, 'INTERNAL_ERROR', 'the driver fell over'); + const lines = spy.mock.calls.filter((c) => String(c[0]).startsWith(SERVER_FAULT_LOG_PREFIX)); + expect(lines).toHaveLength(1); + expect(String(lines[0][0])).toContain('the driver fell over'); + } finally { + spy.mockRestore(); + } + }); + + it('stays quiet on a 4xx — the coded refusals this door exists to carry', () => { + const spy = vi.spyOn(console, 'error').mockImplementation(() => { }); + try { + sendError(makeRes(), 409, 'DESTRUCTIVE_CHANGE', 'that change drops a column'); + sendError(makeRes(), 403, 'FORBIDDEN', 'Managing packages requires `manage_metadata`.'); + expect(spy.mock.calls.filter((c) => String(c[0]).startsWith(SERVER_FAULT_LOG_PREFIX))).toHaveLength(0); + } finally { + spy.mockRestore(); + } + }); + + it('leaves the wire body byte-identical — this change adds a side effect, not a field', () => { + const spy = vi.spyOn(console, 'error').mockImplementation(() => { }); + try { + const res = makeRes(); + sendError(res, 500, 'INTERNAL_ERROR', 'boom', { details: { a: 1 } }); + expect(res.statusCode).toBe(500); + expect(res.body).toEqual({ + success: false, + error: { code: 'INTERNAL_ERROR', message: 'boom', details: { a: 1 } }, + }); + } finally { + spy.mockRestore(); + } + }); +}); + describe('describeFaultRequest', () => { it('reads the spellings adapters actually use', () => { expect(describeFaultRequest({ method: 'GET', path: '/a', requestId: 'r1' })) diff --git a/packages/observability/src/server-fault-log.ts b/packages/types/src/server-fault-log.ts similarity index 90% rename from packages/observability/src/server-fault-log.ts rename to packages/types/src/server-fault-log.ts index 4f36d22bab..451590dbd0 100644 --- a/packages/observability/src/server-fault-log.ts +++ b/packages/types/src/server-fault-log.ts @@ -28,15 +28,18 @@ * * ## Why it lives here * - * `@objectstack/rest` and `@objectstack/runtime` both emit 5xx envelopes and - * both already depend on this package, which owns the operator-facing channel - * (`Logger`, `LOG_LEVELS`, `ErrorReporter`). The rule cannot live in either - * consumer: `runtime` depends on `rest`, so an import could only ever point - * one way — the same argument that put `resolveThrownHttpError` in - * `@objectstack/types` rather than in one of its two doors. Centralising it - * is also what keeps the two doors serving `/api/v1/packages` from printing - * two lines for one fault: each door logs at its own single exit, and the - * predicate that decides "is this worth a line" has one definition. + * Same argument, and the same package, as `resolveThrownHttpError` one file + * over: a rule two doors must agree on cannot live inside one of them. + * `@objectstack/runtime` depends on `@objectstack/rest`, so an import between + * the two doors could only ever point one way — which is exactly why the + * "what status does this throw mean" rule was moved here in #8016. "Is this + * answer worth an operator's attention" is the same kind of rule, read by the + * same two doors, so it gets the same home rather than a second one. + * + * Living beside {@link sendError} is what makes the REST side automatic: that + * writer is the single exit for every nested-envelope 5xx, so the direct-mount + * registrars need no per-door call and cannot forget one. Each transport logs + * at its own single exit, so a fault costs one line and never two. * * ## `error` level, and why that clears the default * @@ -56,7 +59,7 @@ * whole rule: at or above 500. */ -import type { Logger } from './contracts.js'; +import type { Logger } from '@objectstack/spec/contracts'; /** The request coordinates an operator needs to find the failing call. */ export interface ServerFaultRequest {