From 374d044a56aad7daf52bfa0820cc10a6fd11e4ff Mon Sep 17 00:00:00 2001 From: Nick Ruest <127058086+nicholas-ruest@users.noreply.github.com> Date: Tue, 28 Jul 2026 05:39:00 +0000 Subject: [PATCH] Serialize errors logged under the "error" key instead of dropping them MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Pino applies serializers by property name. The logger registered pino.stdSerializers.err under the key `err`, but this codebase logs caught values under `error` at 62 call sites (and `reason` for unhandled rejections). Error.prototype.message/.stack/.name are non-enumerable, so those Errors fell through to default JSON serialization and rendered as `{}` — including every startup-hardening path. Cloud Run revision ruvvector-service-00052-dxg crash-looped with `{"error":{}}` as its entire diagnostic payload. Register `error` and `reason` alongside `err` rather than editing 62 call sites. pino 9's `errorKey` option configures exactly this, but this service is on pino 8.21.0 and an incident fix should not carry a major version bump. Separately, RUVVECTOR_EMBEDDING_DIM hard-crashes assertEmbeddingDimension() when unset but was absent from REQUIRED_ENV_VARS_PRODUCTION, so the first assertion reported "missing":0 while the service was already doomed. Adding it makes that count mean what it says. The variable keeps no default — the value fixes vectors.embedding's width and cannot be changed without rewriting the table, so it must be supplied explicitly at deploy time, not guessed in code. Verified by rebuilding and running with the variable unset: before, the fatal record is `{"error":{}}` after `"present":5,"missing":0`; after, it names RUVVECTOR_EMBEDDING_DIM with a full type/message/stack. Implements ADR-0003: fix swallowed startup error logging --- ...003-fix-swallowed-startup-error-logging.md | 429 ++++++++++++++++++ src/startup/assertions.ts | 3 + src/utils/logger.ts | 31 +- tests/unit/logger-serialization.test.ts | 88 ++++ 4 files changed, 541 insertions(+), 10 deletions(-) create mode 100644 docs/adr/ADR-0003-fix-swallowed-startup-error-logging.md create mode 100644 tests/unit/logger-serialization.test.ts diff --git a/docs/adr/ADR-0003-fix-swallowed-startup-error-logging.md b/docs/adr/ADR-0003-fix-swallowed-startup-error-logging.md new file mode 100644 index 0000000..7e7eb0d --- /dev/null +++ b/docs/adr/ADR-0003-fix-swallowed-startup-error-logging.md @@ -0,0 +1,429 @@ +# ADR-0003: Fix Swallowed Startup Error Logging (and the `RUVVECTOR_EMBEDDING_DIM` Gap It Hid) + +**Status:** Implemented (source changes only — steps 1-4; steps 5-8 remain open, see below) +**Date:** 2026-07-27 + +## Context + +Redeploying `ruvvector-service` from the newly-merged `main` — which implements real +pgvector persistence per [ADR-0001](./ADR-0001-implement-vector-client-persistence.md) +instead of the previously stubbed `VectorClient` — produced revision +`ruvvector-service-00052-dxg`, which crash-loops on startup. There is no outage: +`ruvvector-service-00051-gwp` remains `latestReadyRevisionName` and serves 100% of +traffic. Cloud Run reports `HealthCheckContainerError`. + +### The logs say almost nothing + +Real logs from the failed revision (`gcloud logging read ... --order=asc`), one full +crash cycle: + +``` +2026-07-27T21:02:15.954Z Starting ruvvector-service info +2026-07-27T21:02:15.956Z Running startup assertions... info +2026-07-27T21:02:15.956Z Optional environment variables using defaults info +2026-07-27T21:02:15.956Z Environment variable assertion complete info {"present":5,"missing":0} +2026-07-27T21:02:15.956Z Performance budget configured info +2026-07-27T21:02:15.957Z Failed to start server fatal {"error":{}} +2026-07-27T21:02:16.480Z Container called exit(1). +``` + +This cycle repeated identically six-plus times. `"error":{}` is the entire diagnostic +payload for a fatal crash. + +### Why the error is empty + +Two facts combine. + +`src/index.ts:634-636` — the top-level catch logs the caught value under the key +`error`: + +```ts + } catch (error) { + logger.fatal({ error }, 'Failed to start server'); + process.exit(1); + } +``` + +`src/utils/logger.ts:29-34` — the pino instance (pino 8.21.0) registers an `Error` +serializer, but binds it to the key `err`: + +```ts + serializers: { + req: (req) => ({ method: req.method, url: req.url }), + res: (res) => ({ statusCode: res.statusCode }), + err: pino.stdSerializers.err, + }, +``` + +Pino applies serializers **by property name**. The logged key is `error`; the +registered serializer is `err`; they never meet. The `Error` instance therefore falls +through to pino's default JSON serialization, and `Error.prototype.message`, `.stack`, +and `.name` are **non-enumerable own properties** — `JSON.stringify(new Error('boom'))` +is `'{}'`. Hence `"error":{}`. + +This is not isolated to one call site. Repo-wide there are **62** `logger.*` calls that +pass a caught value under the key `error` (or `error: err`), including every +startup-hardening path that would otherwise explain a failure: + +| Site | Line | +|---|---| +| `src/index.ts` | `532` `'VectorClient connection failed'`, `599` graceful shutdown, `609` `'Uncaught exception'`, `635` `'Failed to start server'` | +| `src/startup/healthCheck.ts` | `76`, `103`, `130`, `161` — connectivity, table, index, append-only checks | +| `src/clients/DatabaseClient.ts` | `55`, `162` migration check, `465` `'Failed to initialize database'`, `582`, `601` | +| `src/guards/immutability.ts` | `156` integrity check | + +Every one of these emits `{}` for an `Error`. The service is, in effect, undebuggable +at startup — precisely where it is designed to crash hard. + +`src/index.ts:614` has a related variant: `logger.fatal({ reason, promise }, 'Unhandled +promise rejection')` — `reason` is conventionally an `Error` and is likewise unserialized. + +### What actually failed + +Even with `{}`, the surviving log sequence pins the failure to a single statement. + +`src/startup/assertions.ts:213-231` runs the assertions in a fixed order, each logging +on success: + +```ts + logger.info('Running startup assertions...'); // :217 ← seen + const envResult = assertRequiredEnvVars(); // :223 ← seen (":106") + const maxLatencyMs = assertPerformanceBudget(); // :224 ← seen (":135") + assertEmbeddingDimension(); // :225 ← NO log emitted + assertExecutionAuthority(); // :226 + assertMemoryLayerRole(); // :227 + logger.info('All startup assertions passed'); // :229 +``` + +`'Performance budget configured'` (`:135`) is present. `'Embedding dimension asserted'` +(`:186`) is absent. The throw is inside `assertEmbeddingDimension()`. + +`src/startup/assertions.ts:173-188`: + +```ts +export function assertEmbeddingDimension(): number { + const dimension = config.ruvVector.embeddingDimension; + + if (!dimension) { + throw new Error( + 'FATAL: RUVVECTOR_EMBEDDING_DIM is required. ' + ... + ); + } + assertValidDimension(dimension); + logger.info({ dimension }, 'Embedding dimension asserted'); +``` + +`src/config/index.ts:136` supplies the sentinel that makes this throw: + +```ts + embeddingDimension: getEnvNumber('RUVVECTOR_EMBEDDING_DIM', 0), +``` + +`0` is falsy, so an unset variable takes the `!dimension` branch. And the variable **is** +unset on the failed revision. Verified against live infrastructure: + +``` +$ gcloud run revisions describe ruvvector-service-00052-dxg --region=us-central1 \ + --project=agentics-dev --format='value(spec.containers[0].env[].name)' +NODE_ENV;LOG_LEVEL;MAX_LATENCY_MS;RUVVECTOR_DB_SSL;RUVVECTOR_DB_HOST; +RUVVECTOR_DB_PORT;RUVVECTOR_DB_NAME;RUVVECTOR_DB_USER;RUVVECTOR_DB_PASSWORD; +EXECUTION_HMAC_SECRET +``` + +No `RUVVECTOR_EMBEDDING_DIM`. The env list of the healthy `00051` is byte-identical: +the redeploy inherited the previous revision's environment, and the old stubbed code +never required a dimension, so the gap was invisible until this release introduced the +assertion. + +Three further facts corroborate this and rule out the database: + +1. **`"present":5,"missing":0` is structurally incapable of catching this.** + `REQUIRED_ENV_VARS_PRODUCTION` (`src/startup/assertions.ts:15-21`) contains exactly + five entries — `RUVVECTOR_DB_HOST`, `RUVVECTOR_DB_NAME`, `RUVVECTOR_DB_USER`, + `RUVVECTOR_DB_PASSWORD`, `EXECUTION_HMAC_SECRET` — and `RUVVECTOR_EMBEDDING_DIM` is + not among them. The count of 5 confirms the list was checked in full and that the + dimension was never part of it. Two different notions of "required" coexist in the + codebase and disagree. + +2. **Timing rules out all I/O.** `15.956Z` → `15.957Z` is roughly one millisecond + between the last assertion and the fatal. No TCP connect, TLS handshake, Cloud SQL + dial, `CREATE EXTENSION`, or HNSW index build occurred. Everything database-related + lives *after* the assertions — `new DatabaseClient(...)` / `await + dbClient.initialize()` at `src/index.ts:479-494`, `verifyStorageHealth` at `:501`, + `assertHistoricalDataIntegrity` at `:506`, `vectorClient.connect()` at `:529`. None + of it ran. The Cloud SQL instance, the `cloudsql-instances` annotation, and the + pgvector/HNSW migration are **not** implicated in this failure. + +3. **The repo's own deploy script sets the variable; this deploy bypassed it.** + `scripts/deploy-cloudrun.sh:23` hard-fails without it + (`${RUVVECTOR_EMBEDDING_DIM:?Set RUVVECTOR_EMBEDDING_DIM ...}`) and passes it at + `:61`. The service metadata instead shows + `run.googleapis.com/build-source-location: gs://run-sources-agentics-dev-us-central1/ + services/ruvvector-service/1785185733...zip` — an ad-hoc `gcloud run deploy --source`, + which never executed the guard. + +**Confidence: very high (~97%).** The remaining ~3% is the one alternative consistent +with the same log window: `assertValidDimension()` (`src/clients/vectorSchema.ts:32-39`) +rejecting a *malformed* value. That would require the variable to be set, which +`gcloud run revisions describe` contradicts. Only the real error message closes the gap +completely — which is exactly what part (a) exists to produce. + +### Downstream state (not the cause of this crash; relevant to the next one) + +- The Cloud SQL instance is stock **`POSTGRES_15`**, `RUNNABLE`, `db-f1-micro`, no + database flags — *not* the `ruvnet/ruvector-postgres:latest` image ADR-0001's plan + assumed. The `ruvector` extension is not installable on managed Cloud SQL. This is + already handled: `DatabaseClient.ts:530-545` iterates `SUPPORTED_VECTOR_TYPES = + ['ruvector', 'vector']` (`src/clients/vectorSchema.ts:21`), tolerates the failed + `CREATE EXTENSION ruvector`, and falls back to stock pgvector, which Cloud SQL PG15 + provides. ADR-0001's open question — "the pgvector fallback must be verified to cover + us" — is answered in the affirmative *by construction*, though still unverified at + runtime. +- **The dimension value itself is an unresolved, one-way decision.** ADR-0001's + implementation plan item 1 says explicitly: *"Everything below is blocked on this + number; do not guess it."* The only evidenced producer value in the workspace is + `copilot-agent/.env.example:114` → `EMBEDDING_DIMENSIONS=1536`. This ADR treats 1536 + as a *candidate requiring confirmation*, not a decision, because + `VectorClient.connect()` (`src/clients/VectorClient.ts:151-157`) refuses to start on + any mismatch against the live column, and correcting a wrong choice means a table + rewrite. +- The `cloudsql-instances` annotation is present, yet `RUVVECTOR_DB_HOST` comes from a + secret with `RUVVECTOR_DB_SSL=true`, which suggests a TCP path to a public IP rather + than the `/cloudsql/...` unix socket. Unverified — secret values were deliberately not + read. If it is TCP, the annotation is inert and harmless. + +## Decision + +Two decisions, at different confidence levels. They ship together but stand +independently. + +### (a) Startup errors must be logged with their real message, name, and stack + +An unhandled startup failure must never again be reduced to `{}`. This is not +negotiable for a service whose stated design is to *crash hard* on misconfiguration: +a hard crash is only a safety property if the operator can read why. + +The fix is **one line in the serializer map**, not 62 edits at the call sites: + +```ts + serializers: { + req: (req) => ({ method: req.method, url: req.url }), + res: (res) => ({ statusCode: res.statusCode }), + err: pino.stdSerializers.err, + error: pino.stdSerializers.err, // ← the key this codebase actually uses + }, +``` + +Rationale for the serializer over per-site rewrites: + +- It repairs all 62 sites atomically, including the four startup-hardening paths that + matter most, with no chance of missing one. +- `pino.stdSerializers.err` emits `type`, `message`, `stack`, and walks `cause` chains + and any custom enumerable properties — strictly more than a hand-rolled + `{ message, stack, name }` triple, and it correctly passes non-`Error` values through. +- It cannot regress the existing `err` key, which is retained. + +Explicitly rejected: pino's `errorKey: 'error'` option, which configures exactly this +behavior but was introduced in **pino 9.0**. This repo is on **8.21.0** +(`node_modules/pino/package.json`), so it is unavailable without a major-version bump +that this ADR does not want to couple to an incident fix. + +Also in scope: `src/index.ts:614` gains `reason` handling so unhandled rejections are +legible too. + +### (b) The underlying failure is an unset `RUVVECTOR_EMBEDDING_DIM`, and the two "required" lists must be reconciled + +The crash is `assertEmbeddingDimension()` throwing `FATAL: RUVVECTOR_EMBEDDING_DIM is +required`, because the variable is absent from the revision's environment +(evidence above, ~97% confidence). + +Beyond setting the variable, the *structural* defect is that +`REQUIRED_ENV_VARS_PRODUCTION` and the individual `assert*` functions encode two +disagreeing definitions of "required". A variable that hard-crashes startup must appear +in the list whose job is to report missing required variables — otherwise the +`"missing":0` log actively misleads the operator, as it did here. `RUVVECTOR_EMBEDDING_DIM` +is added to that list so the failure is named in the first assertion rather than +discovered two steps later. + +Deployment configuration is likewise not something to re-derive by hand per release: +the redeploy must go through `scripts/deploy-cloudrun.sh`, or the variable must be set +on the service so it is inherited by every subsequent revision. + +## Consequences + +**Positive** + +- Startup failures become self-diagnosing. The next bad deploy costs one log read + instead of a live investigation across `gcloud`, source, and log archaeology. +- All 62 error-logging sites are fixed by one change; no site-by-site audit debt. +- `"missing":N` becomes trustworthy — it will name every variable that can crash startup. +- The environment gap that this incident exposed is closed at both the config layer and + the deploy layer. + +**Negative / accepted** + +- **Log volume and content change.** `stdSerializers.err` emits full stack traces where + `{}` was emitted before. Log size grows and stacks may include file paths. This is the + intended trade: a stack in a log is worth far more than the bytes it costs. +- **Error logs may now expose values that were previously invisible.** Error messages in + this codebase interpolate configuration — e.g. `VectorClient.ts:153-155` prints the + configured dimension, and `DatabaseClient.ts:548-549` prints extension failure text. + None of the audited startup messages interpolate credentials, and `EXECUTION_HMAC_SECRET` + is only ever logged by length (`assertions.ts:155-163`). Worth re-checking whenever a + new `throw` interpolates config, and worth reading alongside + [ADR-0002](./ADR-0002-secrets-management-and-credential-exposure.md). +- **Setting the dimension is effectively irreversible.** Once `vector(N)` is created and + rows are written, changing `N` means a table rewrite and a backfill. Confirming the + producer's true dimension is therefore a blocking prerequisite, not a follow-up. +- **Fixing the logging will very likely reveal further failures.** Steps 2-4 of + `startServer()` (`src/index.ts:494-535`) have never executed against this Cloud SQL + instance with real persistence. Expect the *next* revision to surface a genuine + database or schema error — that is the logging fix working, not a new regression. +- The plaintext database password at `scripts/deploy-cloudrun.sh:18` remains a live + secret leak. It is out of scope here (ADR-0002 owns it) but the script is on this + ADR's recommended path, so it should be remediated before the script is adopted as the + standard deploy route. + +**Neutral** + +- No change to runtime behavior, request handling, or the crash-on-misconfiguration + posture. This ADR changes what gets *written down* when the service crashes, and one + environment variable. + +## Implementation Plan + +Steps 1-4 are **done** (source-only). Steps 5-8 are **open** and require an operator +decision; nothing in this repo performs them. + +1. **Fix the serializer.** In `src/utils/logger.ts:29-34`, add + `error: pino.stdSerializers.err` alongside the existing `err` entry. Do not modify + the 62 call sites. + +2. **Fix the rejection handler.** In `src/index.ts:613-616`, serialize `reason` — either + log it under a serialized key or pass it through `pino.stdSerializers.err` — so + unhandled rejections carry a message and stack. + +3. **Add a regression test.** Assert that `logger.fatal({ error: new Error('boom') }, + 'x')` produces a record whose `error.message` is `'boom'` and whose `error.stack` is + non-empty. Capture output with a pino destination stream. This test is the guard that + keeps the incident from recurring silently. + +4. **Reconcile the required-variable lists.** Add `RUVVECTOR_EMBEDDING_DIM` to + `REQUIRED_ENV_VARS_PRODUCTION` (`src/startup/assertions.ts:15-21`). Keep + `assertEmbeddingDimension()` — it additionally range-validates — but the missing-variable + case should now be named by the first assertion. Update + `tests/unit/config.test.ts` and `tests/setup.ts:13` if the expected count of 5 is + asserted anywhere. + +5. **Confirm the embedding dimension — STILL OPEN, blocking, do not guess.** Resolve + ADR-0001 plan item 1: audit what `copilot-agent` and `platform-agents/src/index.ts` + actually POST to `/v1/vectors/store`. + + The **only** candidate value evidenced anywhere in this workspace is **1536**, from + `copilot-agent/.env.example:114` (`EMBEDDING_DIMENSIONS=1536`). That is an example + file, not a confirmed producer configuration, and it is therefore a *candidate*, not + a decision. + + Setting this value is a **ONE-WAY DOOR**. `vector(N)` fixes N in the table + definition; `VectorClient.connect()` (`src/clients/VectorClient.ts:151-157`) refuses + to start on any mismatch against the live column, and correcting a wrong choice + after rows exist means a table rewrite plus a full backfill. + + Consequently `RUVVECTOR_EMBEDDING_DIM` **must not be given a default in code**, and + in particular must not be silently defaulted to 1536. It stays a required env var + with no default (`src/config/index.ts:136` supplies the falsy sentinel `0` precisely + so that an unset value crashes rather than guesses). The real value is supplied at + deploy time by a human who has confirmed it against the live producer. + +6. **Set the variable on the service** (a separate, operator-approved action — **not** + part of this ADR's authorship, and not to be performed while `00051` is serving + without sign-off). Either run `RUVVECTOR_EMBEDDING_DIM= ./scripts/deploy-cloudrun.sh`, + or set it on the service so all future revisions inherit it: + `gcloud run services update ruvvector-service --region=us-central1 + --update-env-vars RUVVECTOR_EMBEDDING_DIM=`. + +7. **Redeploy with steps 1-6 in place** and read the resulting logs. Deploy with + `--no-traffic` and promote only once healthy, so `00051` keeps serving throughout. + +8. **Address the follow-on failure, if any,** using the now-real error message. Expect it + to come from `dbClient.initialize()`, `verifyStorageHealth()`, or + `vectorClient.connect()`. + +## Verification + +**Part (a) — the logging fix.** Verifiable locally, no deployment required: + +- Unit test from step 3 passes: a logged `Error` yields a non-empty `message` and `stack`. +- Manual check: run the built image with `RUVVECTOR_EMBEDDING_DIM` deliberately unset and + confirm the fatal record contains + `"error":{"type":"Error","message":"FATAL: RUVVECTOR_EMBEDDING_DIM is required...","stack":"..."}` + instead of `"error":{}`. + +### Verification results (recorded 2026-07-28, local, no deployment) + +Both parts were reproduced locally by running the built image with every required +variable set *except* `RUVVECTOR_EMBEDDING_DIM` — the exact environment of revision +`ruvvector-service-00052-dxg`. + +**Before** (clean `main`) — reproduces the production incident exactly, including the +misleading `"missing":0`: + +``` +{"level":"info","present":5,"missing":0,"msg":"Environment variable assertion complete"} +{"level":"info","maxLatency":2000,"msg":"Performance budget configured"} +{"level":"fatal","error":{},"msg":"Failed to start server"} +exit=1 +``` + +**After** (this ADR's changes) — the variable is now named by the *first* assertion, and +the fatal record carries type, message, and stack: + +``` +{"level":"error","missing":["RUVVECTOR_EMBEDDING_DIM"],"isProduction":true, + "msg":"STARTUP ASSERTION FAILED: Required environment variables missing"} +{"level":"fatal","error":{"type":"Error","message":"FATAL: Required environment variables + missing: RUVVECTOR_EMBEDDING_DIM. Service cannot start safely without these values. + DO NOT allow partial operation.","stack":"Error: ...\n at assertRequiredEnvVars + (dist/startup/assertions.js:92:15)\n at runStartupAssertions ..."},"msg":"Failed to start server"} +exit=1 +``` + +This **confirms part (b)'s root-cause hypothesis** and closes the ADR's residual ~3% +(`assertValidDimension()` rejecting a malformed value): with the variable genuinely +absent, the missing-variable branch is the one taken. + +Note that step 4 deliberately moves detection earlier, so the message quoted in the +prediction below is no longer the one emitted for the *unset* case. That message remains +reachable for a set-but-falsy value, and both `assertEmbeddingDimension()` paths were +verified to log real errors under the fix: + +``` +RUVVECTOR_EMBEDDING_DIM=0 → error.message = "FATAL: RUVVECTOR_EMBEDDING_DIM is required. ..." +RUVVECTOR_EMBEDDING_DIM=99999 → error.message = "Embedding dimension must be an integer between 1 and 16000, got: 99999" +``` + +**Part (b) — the root-cause hypothesis.** The prediction is falsifiable and precise. With +step 1 landed and the variable *still* unset, the fatal record must read: + +``` +FATAL: RUVVECTOR_EMBEDDING_DIM is required. It fixes the dimension of the +vectors.embedding column and cannot be changed without rewriting the table, so it +must match the platform embedding model exactly. DO NOT allow partial operation +without a declared embedding dimension. +``` + +If it does, part (b) is confirmed and step 6 is the fix. If a *different* message +appears, part (b) is wrong, part (a) is still correct and valuable, and the real message +supersedes this analysis — amend this ADR rather than debugging blind. + +**Success criteria for the redeploy:** + +- Logs show `'Embedding dimension asserted'` with the configured dimension, followed by + `'All startup assertions passed'` and `'Server started successfully'`. +- The new revision reaches `Ready=True`; `latestReadyRevisionName` advances past + `ruvvector-service-00051-gwp`. +- `GET /ready` returns 200. +- Throughout, `00051` continues serving until traffic is explicitly promoted. + +**Guardrail:** no step in this plan modifies the running service without explicit +operator approval. Steps 1-5 are source changes only. diff --git a/src/startup/assertions.ts b/src/startup/assertions.ts index ec19d21..be1da68 100644 --- a/src/startup/assertions.ts +++ b/src/startup/assertions.ts @@ -18,6 +18,9 @@ const REQUIRED_ENV_VARS_PRODUCTION = [ 'RUVVECTOR_DB_USER', 'RUVVECTOR_DB_PASSWORD', 'EXECUTION_HMAC_SECRET', + // Has no default and hard-crashes assertEmbeddingDimension() when unset; listing it + // here is what makes the reported "missing" count reflect what can actually crash startup. + 'RUVVECTOR_EMBEDDING_DIM', ] as const; /** diff --git a/src/utils/logger.ts b/src/utils/logger.ts index 54fd8bd..7da55d1 100644 --- a/src/utils/logger.ts +++ b/src/utils/logger.ts @@ -1,6 +1,26 @@ import pino from 'pino'; import { config } from '../config'; +/** + * Pino applies serializers by property name. `Error.prototype.message`/`.stack`/`.name` + * are non-enumerable, so any Error logged under a key without a registered serializer + * renders as `{}`. This codebase logs caught values under `error` (62 call sites) and + * `reason` (unhandled rejections), so both must be registered alongside `err`. + * pino 9's `errorKey` option would cover this; this service is on pino 8. + */ +export const loggerSerializers = { + req: (req: { method: string; url: string }) => ({ + method: req.method, + url: req.url, + }), + res: (res: { statusCode: number }) => ({ + statusCode: res.statusCode, + }), + err: pino.stdSerializers.err, + error: pino.stdSerializers.err, + reason: pino.stdSerializers.err, +}; + /** * Structured logger - SPARC compliant * @@ -23,16 +43,7 @@ export const logger = pino({ }, }, timestamp: pino.stdTimeFunctions.isoTime, - serializers: { - req: (req) => ({ - method: req.method, - url: req.url, - }), - res: (res) => ({ - statusCode: res.statusCode, - }), - err: pino.stdSerializers.err, - }, + serializers: loggerSerializers, }); export default logger; diff --git a/tests/unit/logger-serialization.test.ts b/tests/unit/logger-serialization.test.ts new file mode 100644 index 0000000..149bcee --- /dev/null +++ b/tests/unit/logger-serialization.test.ts @@ -0,0 +1,88 @@ +import pino from 'pino'; +import { loggerSerializers } from '../../src/utils/logger'; + +function captureRecords(serializers: pino.LoggerOptions['serializers']): { + log: pino.Logger; + records: Record[]; +} { + const records: Record[] = []; + const destination = { + write(chunk: string) { + records.push(JSON.parse(chunk)); + }, + }; + return { log: pino({ level: 'fatal', serializers }, destination), records }; +} + +describe('logger error serialization', () => { + it('serializes an Error logged under the "error" key', () => { + const { log, records } = captureRecords(loggerSerializers); + + log.fatal({ error: new Error('boom') }, 'Failed to start server'); + + expect(records).toHaveLength(1); + expect(records[0].error).toEqual( + expect.objectContaining({ + type: 'Error', + message: 'boom', + }) + ); + expect(records[0].error.stack).toMatch(/logger-serialization\.test\.ts/); + }); + + it('reports the concrete error class rather than a bare "Error"', () => { + class DimensionError extends Error {} + const { log, records } = captureRecords(loggerSerializers); + + log.fatal({ error: new DimensionError('FATAL: RUVVECTOR_EMBEDDING_DIM is required') }, 'x'); + + expect(records[0].error.type).toBe('DimensionError'); + expect(records[0].error.message).toBe('FATAL: RUVVECTOR_EMBEDDING_DIM is required'); + }); + + it('serializes an Error logged under the "reason" key', () => { + const { log, records } = captureRecords(loggerSerializers); + + log.fatal({ reason: new Error('rejected') }, 'Unhandled promise rejection'); + + expect(records[0].reason.message).toBe('rejected'); + expect(records[0].reason.stack).toBeTruthy(); + }); + + it('walks the cause chain', () => { + const { log, records } = captureRecords(loggerSerializers); + + log.fatal({ error: new Error('outer', { cause: new Error('inner') }) }, 'x'); + + expect(records[0].error.message).toContain('inner'); + }); + + it('passes non-Error values through untouched', () => { + const { log, records } = captureRecords(loggerSerializers); + + log.fatal({ error: 'plain string' }, 'x'); + log.fatal({ error: { code: 'ENOENT' } }, 'x'); + + expect(records[0].error).toBe('plain string'); + expect(records[1].error).toEqual({ code: 'ENOENT' }); + }); + + it('still serializes the "err" key', () => { + const { log, records } = captureRecords(loggerSerializers); + + log.fatal({ err: new Error('legacy key') }, 'x'); + + expect(records[0].err.message).toBe('legacy key'); + }); + + // Pins the exact defect this test file exists to prevent: an Error logged under a key + // with no registered serializer renders as `{}`, because message/stack/name are + // non-enumerable. This is what shipped to production as `{"error":{}}`. + it('demonstrates the swallowed-error bug when "error" is not registered', () => { + const { log, records } = captureRecords({ err: pino.stdSerializers.err }); + + log.fatal({ error: new Error('boom') }, 'Failed to start server'); + + expect(records[0].error).toEqual({}); + }); +});