diff --git a/hub/.env.example b/hub/.env.example index 35e842d8..ed8cba81 100644 --- a/hub/.env.example +++ b/hub/.env.example @@ -1,6 +1,9 @@ # Optional API port. The Vite development proxy expects the default. PORT=3001 +# API logging threshold: trace, debug, info, warn, error, fatal, or silent. +LOG_LEVEL=info + # Local development only. The devcontainer supplies its own database hostname. DATABASE_URL=postgresql://replica:replica@127.0.0.1:5432/replica diff --git a/hub/.prettierignore b/hub/.prettierignore index 53393922..5c018a01 100644 --- a/hub/.prettierignore +++ b/hub/.prettierignore @@ -1,4 +1,4 @@ -log +/log .local .npm .storybook/instances diff --git a/hub/app/javascript/application/prototype-canvas/tests/improvement-notes.test.tsx b/hub/app/javascript/application/prototype-canvas/tests/improvement-notes.test.tsx index 0dadbac5..f0ece573 100644 --- a/hub/app/javascript/application/prototype-canvas/tests/improvement-notes.test.tsx +++ b/hub/app/javascript/application/prototype-canvas/tests/improvement-notes.test.tsx @@ -469,11 +469,13 @@ describe("App()", () => { await waitFor(() => expect(annotate).toBeEnabled()) const post = vi.spyOn(frame.contentWindow!, "postMessage") fireEvent.click(annotate) - await waitFor(() => expect(annotate).toHaveAttribute("aria-pressed", "true")) - expect(post).toHaveBeenCalledWith( - { type: "replica:canvas:select", nonce, mode: "improvement" }, - previewOrigin, + await waitFor(() => + expect(post).toHaveBeenCalledWith( + { type: "replica:canvas:select", nonce, mode: "improvement" }, + previewOrigin, + ), ) + expect(annotate).toHaveAttribute("aria-pressed", "true") expect(screen.queryByRole("complementary", { name: copy.notes })).not.toBeInTheDocument() receive(frame, { type: "replica:canvas:selected", anchor }, "https://unrelated.example") diff --git a/hub/docs/README.md b/hub/docs/README.md index a844c507..ec3bd8fe 100644 --- a/hub/docs/README.md +++ b/hub/docs/README.md @@ -7,6 +7,7 @@ Hub is being rebuilt. The [Hub overview](../README.md) describes what the baseli - [Coding conventions](coding-conventions.md): frontend layers and interface rules. - [Development](development.md): local API and frontend setup. - [Database](database.md): Prisma schema conventions, migrations, and the shared client. +- [Logging](logging.md): application events, automatic request records, and payload safety. - [Testing and operations](testing-and-operations.md): baseline checks and their limits. - [Storybook](storybook.md): retained presentation, fixtures, and screenshot evidence. - [Prototype canvas](prototype-canvas.md): the separately retained extension. diff --git a/hub/docs/architecture.md b/hub/docs/architecture.md index de76ecfe..eb7d24c5 100644 --- a/hub/docs/architecture.md +++ b/hub/docs/architecture.md @@ -14,10 +14,12 @@ Contributors can use PostgreSQL and Prisma locally or in the devcontainer. The d API code lives under `server/`. As features are added, route handlers will read requests, call domains, and return responses. The [code conventions](backend-architecture.md) explain repositories, integrations, utilities, domains, and which layers may import others. Put these directories under `server/` when they are needed; do not add empty implementations. -The only route is `GET /api/health`, which returns `{ "status": "ok" }`. Every other path returns a JSON 404 response. `createApp()` builds the Express app without starting a server. `server/index.ts` starts it at a local address. +The only route is `GET /api/health`, which returns `{ "status": "ok" }`. Unknown paths return a JSON 404 response; invalid JSON is rejected before routing. `createApp()` builds the Express app without starting a server. `server/index.ts` starts it at a local address. The [database guide](database.md) defines the multi-file Prisma schema and shared client in integrations. The health route remains a process check, not a database readiness check. +The [Pino integration](logging.md) writes structured application and HTTP logs to stdout. `createApp()` installs request logging and JSON parsing before routes, so new endpoints inherit completion records and server-generated request IDs without explicit logging calls. + ## Frontend ```mermaid diff --git a/hub/docs/backend-architecture.md b/hub/docs/backend-architecture.md index 46cc8f0b..60976740 100644 --- a/hub/docs/backend-architecture.md +++ b/hub/docs/backend-architecture.md @@ -1,9 +1,10 @@ # Code architecture conventions -Organize backend functions into repositories, integrations, utilities, and domains. Each layer has a clear job and rules for which other layers it may use. +Organize backend functions into routes, repositories, integrations, utilities, and domains. Each layer has a clear job and rules for which other layers it may use. | Layer | Responsibility | Directory example | | --- | --- | --- | +| Routes | Parse HTTP requests, call backend functions, and send responses. Directories follow URL paths and HTTP methods. | `routes/api/health/get/index.ts` | | Repositories | Functions that interact with the database. Each repository directory represents one RESTful resource. | `repositories/user/get-user/index.ts` | | Integrations | Functions that interact with an API or SDK. Each integration directory represents one API or SDK service. | `integrations/github/get-user/index.ts` | | Utilities | General functions reusable elsewhere in the codebase. | `utils/format-timestamp/index.ts` | @@ -13,6 +14,10 @@ Organize backend functions into repositories, integrations, utilities, and domai ```mermaid flowchart LR + Routes --> Domains + Routes --> Repositories + Routes --> Integrations + Routes --> Utilities Domains --> Repositories Domains --> Integrations Domains --> Utilities @@ -20,7 +25,7 @@ flowchart LR Integrations --> Utilities ``` -Repositories and integrations may import only utilities from elsewhere in the backend. Utilities may import only other utilities. Domains may import any of these layers, including other domains. Each layer may also use built-in libraries and npm packages. +Routes may import domains, repositories, integrations, and utilities. Repositories and integrations may import only utilities from elsewhere in the backend. Utilities may import only other utilities. Domains may import any of these backend layers, including other domains, but not routes. Each layer may also use built-in libraries and npm packages. These rules apply to imported types as well as functions. A repository must not call another repository or an integration. An integration must not call a repository. Keep business decisions in domains rather than moving them into utilities to get around these rules. @@ -28,6 +33,8 @@ These rules apply to imported types as well as functions. A repository must not Put each function in a directory named with lowercase words and hyphens, such as `get-user`. Keep `index.ts`, its tests, and its types together. Group repository functions by resource and integration functions by API or SDK service, as shown above. Import from each function's directory, not from a shared file that re-exports its neighbors. +Export route handlers by HTTP method, such as `get()`, and alias them to descriptive `handle*` names in `routes/index.ts`. Its `routes()` function registers endpoints; `createApp()` installs shared middleware and error handling. Express-specific helpers belong in `integrations/express`, not utilities. + Add directories when their functions are needed. Do not add empty implementations just to fill out the structure. ## Database access diff --git a/hub/docs/logging.md b/hub/docs/logging.md new file mode 100644 index 00000000..a32eb149 --- /dev/null +++ b/hub/docs/logging.md @@ -0,0 +1,47 @@ +# API logging + +Hub writes one JSON object per line to stdout through `server/integrations/pino/index.ts`. `LOG_LEVEL` sets the minimum severity: `trace`, `debug`, `info` (default), `warn`, `error`, `fatal`, or `silent`. Invalid values prevent startup. + +Logs can still contain private information after redaction. Operators must restrict access and configure collection and retention separately. + +## Application events + +Use `log()` for application events: + +```ts +import { log } from "../integrations/pino/log/index.ts" + +log("info", "Build imported", { buildId }) +``` + +Keep messages short and static. Pass data as structured fields, not message text. Redaction matches keys; it cannot detect secrets in free text, including messages and stacks. + +In handlers, use `request.log.info({ buildId }, "Build imported")` to include the request ID, or pass `request.log` as the fourth argument to `log()`. + +Follow the [import boundaries](backend-architecture.md#import-boundaries). Repositories and other integrations must receive a logger rather than import Pino's shared instance. Never put payloads in `logger.child()` or `setBindings()`: those fields bypass sanitization. + +## Automatic HTTP records + +`createApp()` installs request logging before JSON parsing and routes. Every endpoint inherits it. Each request gets a server-generated UUID in the `X-Request-Id` response header; incoming IDs are ignored. + +Each request produces one final record with `reqId`, `method`, `route`, `statusCode`, `responseTime` (milliseconds), and `outcome`. Responses below 400 use `info`, 4xx use `warn`, and 5xx or connection errors use `error`. Interrupted responses have `outcome: "aborted"` and `statusCode: null`. + +`route` is the handler's template, such as `/builds/:id`, or `null` when unmatched. Mounted routers use a relative template to avoid exposing actual mount values. Sanitized parameters, query fields, and parsed JSON bodies are copied when headers are sent, before Express clears route data. + +Automatic records exclude raw URLs, headers, cookies, uploads, response bodies, and error details. JSON parsing uses Express's default 100 KiB limit; rejected bodies are not logged. The Express error handler returns generic JSON errors, or closes the connection if headers were sent, without exposing raw errors. + +For private free text or other sensitive payloads, exclude all payload fields before sending a response: + +```ts +response.locals.omitLogPayload = true +``` + +This omits `params`, `query`, and `body` while keeping request metadata. + +## Structured-field safety + +Application fields, `request.log` fields, and automatic payloads share the same sanitizer. It copies data without changing the request or invoking getters or custom serialization methods. + +Keys containing password, passwd, passphrase, secret, token, authorization, cookie, API key, private key, or session ID become `[REDACTED]`. Matching ignores case and punctuation and includes nested objects and arrays. Exclude payloads whose sensitive fields do not match these rules. + +Structured fields have [size, depth, and entry limits](../server/utils/logging/sanitize-log-value/constants.ts). Markers replace truncated data, cycles, getters, and unsupported values. These limits do not apply to messages or custom bindings and do not replace endpoint validation or privacy decisions. diff --git a/hub/package-lock.json b/hub/package-lock.json index e7a1d8e7..6594c6db 100644 --- a/hub/package-lock.json +++ b/hub/package-lock.json @@ -15,6 +15,8 @@ "@prisma/client": "7.10.1", "dotenv": "18.0.8", "express": "5.3.0", + "pino": "10.4.0", + "pino-http": "11.0.0", "react": "19.3.0", "react-dom": "19.3.0", "zod": "4.6.5" @@ -2565,6 +2567,12 @@ "win32" ] }, + "node_modules/@pinojs/redact": { + "version": "0.4.0", + "resolved": "https://registry.npmjs.org/@pinojs/redact/-/redact-0.4.0.tgz", + "integrity": "sha512-k2ENnmBugE/rzQfEcdWHcCY+/FM3VLzH9cYEsbdsoqrvzAKRhUZeRNhAZvB8OitQJ1TBed3yqWtdjzS6wJKBwg==", + "license": "MIT" + }, "node_modules/@primer/behaviors": { "version": "1.10.3", "resolved": "https://registry.npmjs.org/@primer/behaviors/-/behaviors-1.10.3.tgz", @@ -4998,6 +5006,15 @@ "node": ">=4" } }, + "node_modules/atomic-sleep": { + "version": "1.0.0", + "resolved": "https://registry.npmjs.org/atomic-sleep/-/atomic-sleep-1.0.0.tgz", + "integrity": "sha512-kNOjDqAh7px0XWNI+4QbzoiR/nTkHAWNud2uvnJquD1/x5a7EQZMJT0AczqK0Qn67oY/TTQ1LbUKajZpp3I9tQ==", + "license": "MIT", + "engines": { + "node": ">=8.0.0" + } + }, "node_modules/aws-ssl-profiles": { "version": "1.1.2", "resolved": "https://registry.npmjs.org/aws-ssl-profiles/-/aws-ssl-profiles-1.1.2.tgz", @@ -6525,6 +6542,15 @@ "node": ">=6.9.0" } }, + "node_modules/get-caller-file": { + "version": "2.0.5", + "resolved": "https://registry.npmjs.org/get-caller-file/-/get-caller-file-2.0.5.tgz", + "integrity": "sha512-DyFP3BM/3YHTQOCUL/w0OZHR0lpKeGrxotcHWcqNEdnltqFwXVfhEBQ94eIo34AfQpo0rGki4cyIiftY06h2Fg==", + "license": "ISC", + "engines": { + "node": "6.* || 8.* || >= 10.*" + } + }, "node_modules/get-intrinsic": { "version": "1.3.0", "resolved": "https://registry.npmjs.org/get-intrinsic/-/get-intrinsic-1.3.0.tgz", @@ -7701,6 +7727,15 @@ "devOptional": true, "license": "MIT" }, + "node_modules/on-exit-leak-free": { + "version": "2.1.2", + "resolved": "https://registry.npmjs.org/on-exit-leak-free/-/on-exit-leak-free-2.1.2.tgz", + "integrity": "sha512-0eJJY6hXLGf1udHwfNftBqH+g73EU4B504nZeKpz1sYRKafAghwxEJunB2O7rDZkL4PGfsMVnTXZ2EjibbqcsA==", + "license": "MIT", + "engines": { + "node": ">=14.0.0" + } + }, "node_modules/on-finished": { "version": "2.4.1", "resolved": "https://registry.npmjs.org/on-finished/-/on-finished-2.4.1.tgz", @@ -8088,6 +8123,55 @@ "url": "https://github.com/sponsors/jonschlinkert" } }, + "node_modules/pino": { + "version": "10.4.0", + "resolved": "https://registry.npmjs.org/pino/-/pino-10.4.0.tgz", + "integrity": "sha512-bk1ZMTwG/Vymx+zPoa28MhNzucFvXJWp3csrSuxuHPSMeUettaCoQ5Jvg07mtC4JGNpcfTwz41oVCnNgBK9+vA==", + "license": "MIT", + "dependencies": { + "@pinojs/redact": "^0.4.0", + "atomic-sleep": "^1.0.0", + "on-exit-leak-free": "^2.1.0", + "pino-abstract-transport": "^3.0.0", + "pino-std-serializers": "^7.0.0", + "process-warning": "^5.0.0", + "quick-format-unescaped": "^4.0.3", + "real-require": "^1.0.0", + "safe-stable-stringify": "^2.3.1", + "sonic-boom": "^4.0.1", + "thread-stream": "^4.0.0" + }, + "bin": { + "pino": "bin.js" + } + }, + "node_modules/pino-abstract-transport": { + "version": "3.0.0", + "resolved": "https://registry.npmjs.org/pino-abstract-transport/-/pino-abstract-transport-3.0.0.tgz", + "integrity": "sha512-wlfUczU+n7Hy/Ha5j9a/gZNy7We5+cXp8YL+X+PG8S0KXxw7n/JXA3c46Y0zQznIJ83URJiwy7Lh56WLokNuxg==", + "license": "MIT", + "dependencies": { + "split2": "^4.0.0" + } + }, + "node_modules/pino-http": { + "version": "11.0.0", + "resolved": "https://registry.npmjs.org/pino-http/-/pino-http-11.0.0.tgz", + "integrity": "sha512-wqg5XIAGRRIWtTk8qPGxkbrfiwEWz1lgedVLvhLALudKXvg1/L2lTFgTGPJ4Z2e3qcRmxoFxDuSdMdMGNM6I1g==", + "license": "MIT", + "dependencies": { + "get-caller-file": "^2.0.5", + "pino": "^10.0.0", + "pino-std-serializers": "^7.0.0", + "process-warning": "^5.0.0" + } + }, + "node_modules/pino-std-serializers": { + "version": "7.1.0", + "resolved": "https://registry.npmjs.org/pino-std-serializers/-/pino-std-serializers-7.1.0.tgz", + "integrity": "sha512-BndPH67/JxGExRgiX1dX0w1FvZck5Wa4aal9198SrRhZjH3GxKQUKIBnYJTdj2HDN3UQAS06HlfcSbQj2OHmaw==", + "license": "MIT" + }, "node_modules/pkg-types": { "version": "2.3.3", "resolved": "https://registry.npmjs.org/pkg-types/-/pkg-types-2.3.3.tgz", @@ -8271,6 +8355,22 @@ } } }, + "node_modules/process-warning": { + "version": "5.1.1", + "resolved": "https://registry.npmjs.org/process-warning/-/process-warning-5.1.1.tgz", + "integrity": "sha512-oCkNVj4OKnKEcocVBcDfiIugN1/cE6rgfT3nCtzeqZPA8+rIxMaQ0xXzIkGP8Gj2qUaP1UR7uhJ1VD8lUCpzCg==", + "funding": [ + { + "type": "github", + "url": "https://github.com/sponsors/fastify" + }, + { + "type": "opencollective", + "url": "https://opencollective.com/fastify" + } + ], + "license": "MIT" + }, "node_modules/proper-lockfile": { "version": "4.1.2", "resolved": "https://registry.npmjs.org/proper-lockfile/-/proper-lockfile-4.1.2.tgz", @@ -8370,6 +8470,12 @@ "url": "https://github.com/sponsors/ljharb" } }, + "node_modules/quick-format-unescaped": { + "version": "4.0.4", + "resolved": "https://registry.npmjs.org/quick-format-unescaped/-/quick-format-unescaped-4.0.4.tgz", + "integrity": "sha512-tYC1Q1hgyRuHgloV/YXs2w15unPVh8qfu/qCTfhTYamaw7fyhumKa2yGpdSo87vY32rIclj+4fWYQXUMs9EHvg==", + "license": "MIT" + }, "node_modules/range-parser": { "version": "1.3.0", "resolved": "https://registry.npmjs.org/range-parser/-/range-parser-1.3.0.tgz", @@ -8476,6 +8582,12 @@ "url": "https://paulmillr.com/funding/" } }, + "node_modules/real-require": { + "version": "1.0.0", + "resolved": "https://registry.npmjs.org/real-require/-/real-require-1.0.0.tgz", + "integrity": "sha512-P4nbQYQfePJxRSmY+v/KINxVucm4NF3p3s7pJveMTtom52FR4YGltUQLB8idDXwDDWW+eYrWDFbuzUnjoWHF7g==", + "license": "MIT" + }, "node_modules/recast": { "version": "0.23.21", "resolved": "https://registry.npmjs.org/recast/-/recast-0.23.21.tgz", @@ -8685,6 +8797,15 @@ "safe-regex2": "bin/safe-regex2.js" } }, + "node_modules/safe-stable-stringify": { + "version": "2.5.0", + "resolved": "https://registry.npmjs.org/safe-stable-stringify/-/safe-stable-stringify-2.5.0.tgz", + "integrity": "sha512-b3rppTKm9T+PsVCBEOUR46GWI7fdOs00VKZ1+9c1EWDaDMvjQc6tUwuFyIprgGgTcWoVHSKrU8H31ZHA2e0RHA==", + "license": "MIT", + "engines": { + "node": ">=10" + } + }, "node_modules/safer-buffer": { "version": "2.1.2", "resolved": "https://registry.npmjs.org/safer-buffer/-/safer-buffer-2.1.2.tgz", @@ -8879,6 +9000,15 @@ "url": "https://github.com/sponsors/isaacs" } }, + "node_modules/sonic-boom": { + "version": "4.2.1", + "resolved": "https://registry.npmjs.org/sonic-boom/-/sonic-boom-4.2.1.tgz", + "integrity": "sha512-w6AxtubXa2wTXAUsZMMWERrsIRAdrK0Sc+FUytWvYAhBJLyuI4llrMIC1DtlNSdI99EI86KZum2MMq3EAZlF9Q==", + "license": "MIT", + "dependencies": { + "atomic-sleep": "^1.0.0" + } + }, "node_modules/source-map": { "version": "0.6.1", "resolved": "https://registry.npmjs.org/source-map/-/source-map-0.6.1.tgz", @@ -9065,6 +9195,18 @@ "url": "https://github.com/sponsors/ljharb" } }, + "node_modules/thread-stream": { + "version": "4.2.0", + "resolved": "https://registry.npmjs.org/thread-stream/-/thread-stream-4.2.0.tgz", + "integrity": "sha512-e2zZ96wSChazBsbENf/Pcm/4swHt2cEKQ92rhUjkL9GCKiTDJIaTBenjE/m9DXi0QBmTMDkFDdOomUy20A1tDQ==", + "license": "MIT", + "dependencies": { + "real-require": "^1.0.0" + }, + "engines": { + "node": ">=20" + } + }, "node_modules/tiny-invariant": { "version": "1.3.3", "resolved": "https://registry.npmjs.org/tiny-invariant/-/tiny-invariant-1.3.3.tgz", diff --git a/hub/package.json b/hub/package.json index ba09fc60..f24effed 100644 --- a/hub/package.json +++ b/hub/package.json @@ -44,6 +44,8 @@ "@primer/react-brand": "0.78.0", "dotenv": "18.0.8", "express": "5.3.0", + "pino": "10.4.0", + "pino-http": "11.0.0", "react": "19.3.0", "react-dom": "19.3.0", "zod": "4.6.5" diff --git a/hub/server/create-app/index.test.ts b/hub/server/create-app/index.test.ts index 28339a1c..c9453fb5 100644 --- a/hub/server/create-app/index.test.ts +++ b/hub/server/create-app/index.test.ts @@ -1,24 +1,68 @@ import { once } from "node:events" import { createServer } from "node:http" import type { AddressInfo } from "node:net" -import { describe, expect, it } from "vitest" +import { describe, expect, it, vi } from "vitest" + +import { createLogger } from "../integrations/pino/create-logger" import { createApp } from "." +function isRecord(value: unknown): value is Record { + return value !== null && typeof value === "object" && !Array.isArray(value) +} + +function parseRecord(line: string) { + const value: unknown = JSON.parse(line) + if (!isRecord(value)) throw new Error("Expected a JSON log object") + return value +} + describe("createApp()", () => { - it("returns the health status as JSON", async () => { - const server = createServer(createApp()) + it("automatically logs health and not-found responses with the injected logger", async () => { + const records: Record[] = [] + const logger = createLogger({ + destination: { write: (line) => records.push(parseRecord(line)) }, + }) + const server = createServer(createApp({ logger })) try { server.listen(0, "127.0.0.1") await once(server, "listening") const { port } = server.address() as AddressInfo - const response = await fetch(`http://127.0.0.1:${port}/api/health`) + const headers = { "x-request-id": "untrusted-request-id" } + const health = await fetch(`http://127.0.0.1:${port}/api/health`, { headers }) + expect(health.status).toBe(200) + expect(health.headers.get("content-type")).toMatch(/^application\/json\b/) + expect(await health.json()).toEqual({ status: "ok" }) + const missing = await fetch( + `http://127.0.0.1:${port}/api/missing-private-path?token=query-secret`, + { headers }, + ) + expect(missing.status).toBe(404) + expect(missing.headers.get("content-type")).toMatch(/^application\/json\b/) + expect(await missing.json()).toEqual({ error: "Not found" }) + expect(health.headers.get("x-request-id")).not.toBe(missing.headers.get("x-request-id")) - expect(response.status).toBe(200) - expect(response.headers.get("content-type")).toMatch(/^application\/json\b/) - expect(await response.json()).toEqual({ status: "ok" }) + await vi.waitFor(() => expect(records).toHaveLength(2)) + expect(records[0]).toMatchObject({ + reqId: health.headers.get("x-request-id"), + method: "GET", + route: "/api/health", + statusCode: 200, + level: 30, + outcome: "completed", + }) + expect(records[1]).toMatchObject({ + reqId: missing.headers.get("x-request-id"), + route: null, + statusCode: 404, + level: 40, + outcome: "completed", + }) + expect(JSON.stringify(records)).not.toMatch( + /missing-private-path|query-secret|untrusted-request-id/, + ) } finally { await new Promise((resolve, reject) => { server.close((error) => (error ? reject(error) : resolve())) @@ -26,19 +70,44 @@ describe("createApp()", () => { } }) - it("returns a JSON not-found error for an unknown API route", async () => { - const server = createServer(createApp()) + it.each([ + { name: "malformed", body: '{"password":"malformed-body-secret"', statusCode: 400 }, + { name: "oversized", body: JSON.stringify({ text: "x".repeat(1024 * 1024) }), statusCode: 413 }, + ])("logs $name JSON safely before routing", async ({ body, statusCode }) => { + const records: Record[] = [] + const logger = createLogger({ + destination: { write: (line) => records.push(parseRecord(line)) }, + }) + const server = createServer(createApp({ logger })) + const stderr = vi.spyOn(process.stderr, "write").mockImplementation(() => true) try { server.listen(0, "127.0.0.1") await once(server, "listening") const { port } = server.address() as AddressInfo - const response = await fetch(`http://127.0.0.1:${port}/api/not-a-route`) + const response = await fetch(`http://127.0.0.1:${port}/api/health`, { + method: "POST", + headers: { "content-type": "application/json" }, + body, + }) - expect(response.status).toBe(404) + expect(response.status).toBe(statusCode) expect(response.headers.get("content-type")).toMatch(/^application\/json\b/) - expect(await response.json()).toEqual({ error: "Not found" }) + expect(await response.json()).toEqual({ error: "Invalid request" }) + await vi.waitFor(() => expect(records).toHaveLength(1)) + expect(records[0]).toMatchObject({ + reqId: response.headers.get("x-request-id"), + statusCode, + level: 40, + outcome: "completed", + }) + expect(records[0]).not.toHaveProperty("body") + expect(records[0]).not.toHaveProperty("err") + expect(records[0]).not.toHaveProperty("req") + expect(records[0]).not.toHaveProperty("res") + expect(JSON.stringify(records)).not.toContain("malformed-body-secret") + expect(stderr).not.toHaveBeenCalled() } finally { await new Promise((resolve, reject) => { server.close((error) => (error ? reject(error) : resolve())) diff --git a/hub/server/create-app/index.ts b/hub/server/create-app/index.ts index 06d3bc09..a3954deb 100644 --- a/hub/server/create-app/index.ts +++ b/hub/server/create-app/index.ts @@ -1,16 +1,21 @@ import express from "express" +import type { Logger } from "pino" -export function createApp() { +import { handleError } from "../integrations/express/handle-error/index.ts" +import { respondNotFound } from "../integrations/express/respond-not-found/index.ts" +import { createRequestLogger } from "../integrations/pino/create-request-logger/index.ts" +import { routes } from "../routes/index.ts" + +/** Give every endpoint the same request logging and safe error responses. */ +export function createApp({ logger }: { logger?: Logger } = {}) { const app = express() app.disable("x-powered-by") + app.use(createRequestLogger(logger)) + app.use(express.json()) - app.get("/api/health", (_request, response) => { - response.json({ status: "ok" }) - }) - - app.use((_request, response) => { - response.status(404).json({ error: "Not found" }) - }) + routes(app) + app.use(respondNotFound) + app.use(handleError) return app } diff --git a/hub/server/index.ts b/hub/server/index.ts index e6de88b0..64bafe13 100644 --- a/hub/server/index.ts +++ b/hub/server/index.ts @@ -1,6 +1,7 @@ import "dotenv/config" import { createApp } from "./create-app/index.ts" +import { log } from "./integrations/pino/log/index.ts" const port = Number(process.env.PORT ?? 3001) if (!Number.isInteger(port) || port < 1 || port > 65535) { @@ -8,5 +9,5 @@ if (!Number.isInteger(port) || port < 1 || port > 65535) { } createApp().listen(port, "127.0.0.1", () => { - console.info(`Hub API listening at http://127.0.0.1:${port}`) + log("info", "Hub API listening", { host: "127.0.0.1", port }) }) diff --git a/hub/server/integrations/express/handle-error/constants.ts b/hub/server/integrations/express/handle-error/constants.ts new file mode 100644 index 00000000..a45e0ed1 --- /dev/null +++ b/hub/server/integrations/express/handle-error/constants.ts @@ -0,0 +1,3 @@ +import { z } from "zod" + +export const httpErrorSchema = z.object({ status: z.int().min(400).max(599) }) diff --git a/hub/server/integrations/express/handle-error/index.test.ts b/hub/server/integrations/express/handle-error/index.test.ts new file mode 100644 index 00000000..0d7eae81 --- /dev/null +++ b/hub/server/integrations/express/handle-error/index.test.ts @@ -0,0 +1,79 @@ +import { once } from "node:events" +import type { AddressInfo } from "node:net" +import express from "express" +import { describe, expect, it, onTestFinished, vi } from "vitest" + +import { handleError } from "." + +describe("handleError()", () => { + it.each([ + { name: "an unknown error", status: undefined, expectedStatus: 500 }, + { name: "an explicit server error", status: 503, expectedStatus: 503 }, + { name: "an invalid success status", status: 200, expectedStatus: 500 }, + ])("returns a generic JSON failure for $name", async ({ status, expectedStatus }) => { + vi.stubEnv("NODE_ENV", "development") + const app = express() + const error = Object.assign(new Error("private-error-message"), { status }) + error.stack = "private-error-stack" + app.get("/failure", () => { + throw error + }) + app.use(handleError) + const stderr = vi.spyOn(process.stderr, "write").mockImplementation(() => true) + const server = app.listen(0, "127.0.0.1") + onTestFinished( + () => + new Promise((resolve, reject) => { + server.closeAllConnections() + server.close((error) => (error ? reject(error) : resolve())) + }), + ) + await once(server, "listening") + const { port } = server.address() as AddressInfo + + const response = await fetch(`http://127.0.0.1:${port}/failure`) + + expect(response.status).toBe(expectedStatus) + expect(response.headers.get("content-type")).toMatch(/^application\/json\b/) + expect(await response.json()).toEqual({ error: "Internal server error" }) + expect(stderr).not.toHaveBeenCalled() + }) + + it("closes a started response without reporting the raw error", async () => { + vi.stubEnv("NODE_ENV", "development") + let failResponse: (() => void) | undefined + const failure = new Promise((resolve) => { + failResponse = resolve + }) + const app = express() + app.get("/stream", async (_request, response) => { + response.write("safe-stream-content") + await failure + throw new Error("private-stream-error") + }) + app.use(handleError) + const stderr = vi.spyOn(process.stderr, "write").mockImplementation(() => true) + const server = app.listen(0, "127.0.0.1") + onTestFinished( + () => + new Promise((resolve, reject) => { + server.closeAllConnections() + server.close((error) => (error ? reject(error) : resolve())) + }), + ) + await once(server, "listening") + const { port } = server.address() as AddressInfo + const response = await fetch(`http://127.0.0.1:${port}/stream`) + if (!response.body) throw new Error("Expected a streaming response") + const reader = response.body.getReader() + + expect(response.status).toBe(200) + const first = await reader.read() + expect(new TextDecoder().decode(first.value)).toBe("safe-stream-content") + if (!failResponse) throw new Error("Expected a response failure trigger") + failResponse() + + await expect(reader.read()).rejects.toThrow() + expect(stderr).not.toHaveBeenCalled() + }) +}) diff --git a/hub/server/integrations/express/handle-error/index.ts b/hub/server/integrations/express/handle-error/index.ts new file mode 100644 index 00000000..265e562e --- /dev/null +++ b/hub/server/integrations/express/handle-error/index.ts @@ -0,0 +1,24 @@ +import type { NextFunction, Request, Response } from "express" + +import { httpErrorSchema } from "./constants.ts" + +/** Keep raw request data and error details out of responses and Express's reporter. */ +export function handleError( + error: unknown, + _request: Request, + response: Response, + // Express identifies error handlers by their four-argument signature. + // eslint-disable-next-line @typescript-eslint/no-unused-vars + _next: NextFunction, +): void { + if (response.headersSent) { + response.destroy() + return + } + + const parsed = httpErrorSchema.safeParse(error) + const status = parsed.success ? parsed.data.status : 500 + response.status(status).json({ + error: status >= 500 ? "Internal server error" : "Invalid request", + }) +} diff --git a/hub/server/integrations/express/respond-not-found/index.ts b/hub/server/integrations/express/respond-not-found/index.ts new file mode 100644 index 00000000..3256dffb --- /dev/null +++ b/hub/server/integrations/express/respond-not-found/index.ts @@ -0,0 +1,6 @@ +import type { Request, Response } from "express" + +/** Return the API's JSON error rather than Express's HTML fallback. */ +export function respondNotFound(_request: Request, response: Response): void { + response.status(404).json({ error: "Not found" }) +} diff --git a/hub/server/integrations/pino/constants.ts b/hub/server/integrations/pino/constants.ts new file mode 100644 index 00000000..594034ca --- /dev/null +++ b/hub/server/integrations/pino/constants.ts @@ -0,0 +1 @@ +export const logLevels = ["trace", "debug", "info", "warn", "error", "fatal", "silent"] as const diff --git a/hub/server/integrations/pino/create-logger/index.test.ts b/hub/server/integrations/pino/create-logger/index.test.ts new file mode 100644 index 00000000..41c34c1c --- /dev/null +++ b/hub/server/integrations/pino/create-logger/index.test.ts @@ -0,0 +1,98 @@ +import { describe, expect, it } from "vitest" + +import { createLogger } from "." + +function isRecord(value: unknown): value is Record { + return value !== null && typeof value === "object" && !Array.isArray(value) +} + +function parseRecord(line: string) { + const value: unknown = JSON.parse(line) + if (!isRecord(value)) throw new Error("Expected a JSON log object") + return value +} + +describe("createLogger()", () => { + it("writes real JSON records and applies the configured level", () => { + const lines: string[] = [] + const logger = createLogger({ + level: "warn", + destination: { write: (line) => lines.push(line) }, + }) + + logger.info("Not emitted") + logger.warn({ count: 2 }, "Needs attention") + + expect(lines).toHaveLength(1) + const record = parseRecord(lines.join("")) + expect(record).toMatchObject({ + level: 40, + msg: "Needs attention", + count: 2, + }) + expect(record).toHaveProperty("time", expect.any(Number)) + expect(record).toHaveProperty("name", expect.any(String)) + }) + + it("sanitizes structured fields from direct and child logger calls", () => { + const lines: string[] = [] + const logger = createLogger({ destination: { write: (line) => lines.push(line) } }) + const input = { nested: [{ password: "direct-secret", visible: true }] } + + logger.info(input, "Direct") + logger + .child({ component: "worker" }) + .info( + { access_token: "child-token-secret", data: { "client-secret": "child-secret" } }, + "Child", + ) + + expect(lines.map((line) => parseRecord(line))).toMatchObject([ + { + nested: [{ password: "[REDACTED]", visible: true }], + msg: "Direct", + }, + { + access_token: "[REDACTED]", + component: "worker", + data: { "client-secret": "[REDACTED]" }, + msg: "Child", + }, + ]) + expect(lines.join("")).not.toMatch(/direct-secret|child-token-secret|child-secret/) + expect(input.nested[0]?.password).toBe("direct-secret") + }) + + it("serializes an Error without leaking its sensitive enumerable fields", () => { + const lines: string[] = [] + const logger = createLogger({ destination: { write: (line) => lines.push(line) } }) + const error = Object.assign(new Error("Operation failed"), { + password: "error-secret", + context: { access_token: "nested-error-secret" }, + }) + + logger.error({ err: error }, "Failed") + + expect(lines).toHaveLength(1) + expect(parseRecord(lines.join(""))).toMatchObject({ + level: 50, + err: { message: "Operation failed" }, + }) + expect(lines[0]).not.toMatch(/error-secret|nested-error-secret/) + expect(error.password).toBe("error-secret") + }) + + it("bounds each structured field without dropping unrelated fields or the message", () => { + const lines: string[] = [] + const logger = createLogger({ destination: { write: (line) => lines.push(line) } }) + const oversized = Array.from({ length: 6 }, () => "\u754c".repeat(1800)) + + logger.info({ oversized, task: "rebuild" }, "Task started") + + expect(lines).toHaveLength(1) + const record = parseRecord(lines.join("")) + expect(record).toMatchObject({ task: "rebuild", msg: "Task started" }) + expect(record).toHaveProperty("oversized") + expect(Buffer.byteLength(JSON.stringify(record.oversized), "utf8")).toBeLessThanOrEqual(8192) + }) +}) diff --git a/hub/server/integrations/pino/create-logger/index.ts b/hub/server/integrations/pino/create-logger/index.ts new file mode 100644 index 00000000..57fe3a5b --- /dev/null +++ b/hub/server/integrations/pino/create-logger/index.ts @@ -0,0 +1,18 @@ +import pino from "pino" + +import { formatLogFields } from "../format-log-fields/index.ts" +import type { LoggerOptions } from "./types.ts" + +/** Apply one output and privacy policy to application and request logs. */ +export function createLogger({ level = "info", destination }: LoggerOptions = {}) { + return pino( + { + name: "replica-hub", + level, + formatters: { + log: formatLogFields, + }, + }, + destination, + ) +} diff --git a/hub/server/integrations/pino/create-logger/types.ts b/hub/server/integrations/pino/create-logger/types.ts new file mode 100644 index 00000000..4ec3ff7b --- /dev/null +++ b/hub/server/integrations/pino/create-logger/types.ts @@ -0,0 +1,6 @@ +import type { DestinationStream, LevelWithSilent } from "pino" + +export interface LoggerOptions { + level?: LevelWithSilent + destination?: DestinationStream +} diff --git a/hub/server/integrations/pino/create-request-logger/index.test.ts b/hub/server/integrations/pino/create-request-logger/index.test.ts new file mode 100644 index 00000000..9c78c3a4 --- /dev/null +++ b/hub/server/integrations/pino/create-request-logger/index.test.ts @@ -0,0 +1,239 @@ +import { once } from "node:events" +import { createServer, IncomingMessage, request } from "node:http" +import type { AddressInfo } from "node:net" +import express from "express" +import { describe, expect, it, onTestFinished, vi } from "vitest" + +import { createLogger } from "../create-logger" + +import { createRequestLogger } from "." + +function isRecord(value: unknown): value is Record { + return value !== null && typeof value === "object" && !Array.isArray(value) +} + +function parseRecord(line: string) { + const value: unknown = JSON.parse(line) + if (!isRecord(value)) throw new Error("Expected a JSON log object") + return value +} + +async function listen(app: express.Express) { + const server = createServer(app) + onTestFinished( + () => + new Promise((resolve, reject) => { + server.close((error) => (error ? reject(error) : resolve())) + }), + ) + server.listen(0, "127.0.0.1") + await once(server, "listening") + const { port } = server.address() as AddressInfo + return `http://127.0.0.1:${port}` +} + +describe("createRequestLogger()", () => { + it("retains mounted route data after next without changing the request payload", async () => { + const records: Record[] = [] + const logger = createLogger({ + destination: { write: (line) => records.push(parseRecord(line)) }, + }) + const app = express() + app.use(createRequestLogger(logger)) + app.use(express.json()) + const router = express.Router({ mergeParams: true }) + router.post("/widgets/:password", (req, res, next) => { + const body: unknown = req.body + res.json({ params: req.params, query: req.query, body }) + next() + }) + app.use("/teams/:teamId", router) + const baseUrl = await listen(app) + const body = { title: "Example", nested: [{ access_token: "body-secret" }] } + + const response = await fetch( + `${baseUrl}/teams/design/widgets/param-secret?tag=one&tag=two&password=query-secret`, + { + method: "POST", + headers: { + "content-type": "application/json", + "x-request-id": "untrusted-request-id", + "x-private-header": "header-secret", + authorization: "header-authorization-secret", + }, + body: JSON.stringify(body), + }, + ) + + expect(await response.json()).toEqual({ + params: { teamId: "design", password: "param-secret" }, + query: { tag: ["one", "two"], password: "query-secret" }, + body, + }) + await vi.waitFor(() => expect(records).toHaveLength(1)) + const reqId = response.headers.get("x-request-id") + expect(reqId).toMatch(/^[0-9a-f]{8}-[0-9a-f]{4}-4[0-9a-f]{3}-[89ab][0-9a-f]{3}-[0-9a-f]{12}$/i) + expect(records[0]).toMatchObject({ + reqId, + level: 30, + method: "POST", + route: "/widgets/:password", + statusCode: 200, + outcome: "completed", + params: { teamId: "design", password: "[REDACTED]" }, + query: { tag: ["one", "two"], password: "[REDACTED]" }, + body: { title: "Example", nested: [{ access_token: "[REDACTED]" }] }, + }) + expect(records[0]).toHaveProperty("responseTime", expect.any(Number)) + expect(records[0]?.responseTime).toBeGreaterThanOrEqual(0) + expect(records[0]).not.toHaveProperty("req") + expect(records[0]).not.toHaveProperty("res") + expect(records[0]).not.toHaveProperty("url") + expect(JSON.stringify(records)).not.toMatch( + /param-secret|query-secret|body-secret|header-secret|header-authorization-secret|untrusted-request-id/, + ) + }) + + it("logs a server error once at error level", async () => { + const records: Record[] = [] + const logger = createLogger({ + destination: { write: (line) => records.push(parseRecord(line)) }, + }) + const app = express() + app.use(createRequestLogger(logger)) + app.get("/status", (_req, res) => res.status(500).end()) + const baseUrl = await listen(app) + + const response = await fetch(`${baseUrl}/status`) + await response.arrayBuffer() + + await vi.waitFor(() => expect(records).toHaveLength(1)) + expect(records[0]).toMatchObject({ level: 50, statusCode: 500, outcome: "completed" }) + }) + + it("lets an endpoint omit all payload fields without suppressing completion metadata", async () => { + const records: Record[] = [] + const logger = createLogger({ + destination: { write: (line) => records.push(parseRecord(line)) }, + }) + const app = express() + app.use(createRequestLogger(logger)) + app.use(express.json()) + app.post("/private/:id", (_req, res) => { + res.locals.omitLogPayload = true + res.json({ private: "response-secret" }) + }) + const baseUrl = await listen(app) + + const response = await fetch(`${baseUrl}/private/param-secret?search=query-secret`, { + method: "POST", + headers: { "content-type": "application/json" }, + body: JSON.stringify({ text: "body-secret" }), + }) + await response.arrayBuffer() + + await vi.waitFor(() => expect(records).toHaveLength(1)) + expect(records[0]).toMatchObject({ + method: "POST", + route: "/private/:id", + statusCode: 200, + outcome: "completed", + }) + for (const field of ["params", "query", "body", "req", "res"]) { + expect(records[0]).not.toHaveProperty(field) + } + expect(JSON.stringify(records)).not.toMatch( + /param-secret|query-secret|body-secret|response-secret/, + ) + }) + + it("does not log parsed binary uploads or response content", async () => { + const records: Record[] = [] + const logger = createLogger({ + destination: { write: (line) => records.push(parseRecord(line)) }, + }) + const app = express() + app.use(createRequestLogger(logger)) + app.use(express.raw({ type: "application/octet-stream" })) + app.post("/upload", (req, res) => { + expect(Buffer.isBuffer(req.body)).toBe(true) + res.send("response-secret") + }) + const baseUrl = await listen(app) + + const response = await fetch(`${baseUrl}/upload`, { + method: "POST", + headers: { "content-type": "application/octet-stream" }, + body: "upload-secret", + }) + await response.arrayBuffer() + + await vi.waitFor(() => expect(records).toHaveLength(1)) + expect(records[0]).not.toHaveProperty("body") + expect(JSON.stringify(records)).not.toMatch(/upload-secret|response-secret/) + }) + + it("exposes a sanitized request logger correlated with the automatic record", async () => { + const records: Record[] = [] + const logger = createLogger({ + destination: { write: (line) => records.push(parseRecord(line)) }, + }) + const app = express() + app.use(createRequestLogger(logger)) + app.get("/work", (req, res) => { + req.log.info({ nested: { password: "request-log-secret" } }, "Work started") + res.end() + }) + const baseUrl = await listen(app) + + const response = await fetch(`${baseUrl}/work`) + await response.arrayBuffer() + + await vi.waitFor(() => expect(records).toHaveLength(2)) + expect(records.find((record) => record.msg === "Work started")).toMatchObject({ + reqId: response.headers.get("x-request-id"), + nested: { password: "[REDACTED]" }, + }) + expect(records.filter((record) => record.outcome === "completed")).toHaveLength(1) + expect(JSON.stringify(records)).not.toContain("request-log-secret") + }) + + it("emits one distinct error record when a streaming response is aborted", async () => { + const records: Record[] = [] + const logger = createLogger({ + destination: { write: (line) => records.push(parseRecord(line)) }, + }) + const app = express() + app.use(createRequestLogger(logger)) + app.get("/stream", (_req, res) => { + res.write("private-stream-content") + }) + const baseUrl = await listen(app) + const client = request(`${baseUrl}/stream`) + onTestFinished(() => { + client.destroy() + }) + client.end() + const responseEvent: unknown[] = await once(client, "response") + const response = responseEvent[0] + if (!(response instanceof IncomingMessage)) throw new Error("Expected an HTTP response") + await once(response, "data") + + response.destroy() + client.destroy() + + await vi.waitFor(() => expect(records).toHaveLength(1)) + expect(records[0]).toMatchObject({ + level: 50, + method: "GET", + route: "/stream", + statusCode: null, + outcome: "aborted", + }) + expect(records[0]).toHaveProperty("responseTime", expect.any(Number)) + expect(records[0]).not.toHaveProperty("err") + expect(records[0]).not.toHaveProperty("req") + expect(records[0]).not.toHaveProperty("res") + expect(JSON.stringify(records)).not.toContain("private-stream-content") + }) +}) diff --git a/hub/server/integrations/pino/create-request-logger/index.ts b/hub/server/integrations/pino/create-request-logger/index.ts new file mode 100644 index 00000000..13cada56 --- /dev/null +++ b/hub/server/integrations/pino/create-request-logger/index.ts @@ -0,0 +1,71 @@ +import { randomUUID } from "node:crypto" +import type { OutgoingHttpHeader, OutgoingHttpHeaders } from "node:http" +import type { Request, RequestHandler, Response } from "express" +import type { Logger } from "pino" +import { pinoHttp } from "pino-http" + +import { createRequestRecord } from "../create-request-record/index.ts" +import { logger } from "../index.ts" +import { snapshotRequest } from "../snapshot-request/index.ts" +import type { RequestSnapshot } from "../snapshot-request/types.ts" + +/** Log each request once, including parser failures and interrupted responses. */ +export function createRequestLogger(target: Logger = logger): RequestHandler { + const snapshots = new WeakMap() + + const middleware = pinoHttp({ + logger: target, + quietReqLogger: true, + quietResLogger: true, + wrapSerializers: false, + serializers: { + req: () => undefined, + res: () => undefined, + err: () => undefined, + }, + genReqId(_request, response) { + const id = randomUUID() + response.setHeader("X-Request-Id", id) + return id + }, + customLogLevel(request, response, error) { + if ( + error || + !response.writableFinished || + request.readableAborted || + response.statusCode >= 500 + ) { + return "error" + } + return response.statusCode >= 400 ? "warn" : "info" + }, + customSuccessObject(request, response, value: { responseTime: number }) { + return createRequestRecord(request, response, value.responseTime, snapshots.get(response)) + }, + customErrorObject(request, response, _error, value: { responseTime: number }) { + return createRequestRecord(request, response, value.responseTime, snapshots.get(response)) + }, + customSuccessMessage(request, response) { + return response.writableFinished && !request.readableAborted + ? "Request completed" + : "Request aborted" + }, + customErrorMessage: () => "Request failed", + }) + + return (request, response, next) => { + // Capture before Express restores mounted router parameters after sending a response. + const writeHead = response.writeHead.bind(response) + response.writeHead = function ( + statusCode: number, + statusMessageOrHeaders?: string | OutgoingHttpHeaders | OutgoingHttpHeader[], + headers?: OutgoingHttpHeaders | OutgoingHttpHeader[], + ) { + snapshots.set(response, snapshotRequest(request)) + return typeof statusMessageOrHeaders === "string" + ? writeHead(statusCode, statusMessageOrHeaders, headers) + : writeHead(statusCode, statusMessageOrHeaders) + } + middleware(request, response, next) + } +} diff --git a/hub/server/integrations/pino/create-request-record/index.ts b/hub/server/integrations/pino/create-request-record/index.ts new file mode 100644 index 00000000..68ac75a9 --- /dev/null +++ b/hub/server/integrations/pino/create-request-record/index.ts @@ -0,0 +1,23 @@ +import type { Request, Response } from "express" + +import { snapshotRequest } from "../snapshot-request/index.ts" +import type { RequestSnapshot } from "../snapshot-request/types.ts" + +/** Keep completion metadata even when an endpoint excludes its payload. */ +export function createRequestRecord( + request: Request, + response: Response, + responseTime: number, + captured: RequestSnapshot = snapshotRequest(request), +) { + const completed = response.writableFinished && !request.readableAborted + const { route, ...payload } = captured + return { + method: request.method, + route, + statusCode: completed ? response.statusCode : null, + responseTime, + outcome: completed ? "completed" : "aborted", + ...(response.locals.omitLogPayload === true ? {} : payload), + } +} diff --git a/hub/server/integrations/pino/format-log-fields/index.ts b/hub/server/integrations/pino/format-log-fields/index.ts new file mode 100644 index 00000000..4527a3a1 --- /dev/null +++ b/hub/server/integrations/pino/format-log-fields/index.ts @@ -0,0 +1,18 @@ +import { maxLogKeyLength } from "../../../utils/logging/sanitize-log-value/constants.ts" +import { sanitizeLogValue } from "../../../utils/logging/sanitize-log-value/index.ts" + +/** Bound fields independently so a large payload cannot hide useful metadata. */ +export function formatLogFields(fields: Record): Record { + const result = Object.create(null) as Record + for (const key of Object.keys(fields)) { + const descriptor = Object.getOwnPropertyDescriptor(fields, key) + const value: unknown = descriptor && "value" in descriptor ? descriptor.value : "[UNAVAILABLE]" + const safe = sanitizeLogValue({ [key]: value }) + if (safe !== null && typeof safe === "object" && !Array.isArray(safe)) { + Object.assign(result, safe) + } else { + result[key.slice(0, maxLogKeyLength)] = safe + } + } + return result +} diff --git a/hub/server/integrations/pino/index.ts b/hub/server/integrations/pino/index.ts new file mode 100644 index 00000000..37f7f657 --- /dev/null +++ b/hub/server/integrations/pino/index.ts @@ -0,0 +1,11 @@ +import "dotenv/config" + +import { logLevels } from "./constants.ts" +import { createLogger } from "./create-logger/index.ts" + +const level = logLevels.find((candidate) => candidate === (process.env.LOG_LEVEL ?? "info")) +if (!level) { + throw new Error("LOG_LEVEL must be trace, debug, info, warn, error, fatal, or silent.") +} + +export const logger = createLogger({ level }) diff --git a/hub/server/integrations/pino/log/index.test.ts b/hub/server/integrations/pino/log/index.test.ts new file mode 100644 index 00000000..c9f43f52 --- /dev/null +++ b/hub/server/integrations/pino/log/index.test.ts @@ -0,0 +1,25 @@ +import { describe, expect, it } from "vitest" + +import { createLogger } from "../create-logger" + +import { log } from "." + +describe("log()", () => { + it("writes the selected level, message, and sanitized fields to the supplied logger", () => { + const lines: string[] = [] + const logger = createLogger({ destination: { write: (line) => lines.push(line) } }) + const fields = { task: "rebuild", nested: { password: "helper-secret" } } + + log("warn", "Rebuild delayed", fields, logger) + + expect(lines).toHaveLength(1) + const record: unknown = JSON.parse(lines.join("")) + expect(record).toMatchObject({ + level: 40, + msg: "Rebuild delayed", + task: "rebuild", + nested: { password: "[REDACTED]" }, + }) + expect(fields.nested.password).toBe("helper-secret") + }) +}) diff --git a/hub/server/integrations/pino/log/index.ts b/hub/server/integrations/pino/log/index.ts new file mode 100644 index 00000000..77118f97 --- /dev/null +++ b/hub/server/integrations/pino/log/index.ts @@ -0,0 +1,13 @@ +import type { Level, Logger } from "pino" + +import { logger } from "../index.ts" + +/** Use the shared logging policy, with an optional request-scoped logger. */ +export function log( + level: Level, + message: string, + fields: Record = {}, + target: Logger = logger, +) { + target[level](fields, message) +} diff --git a/hub/server/integrations/pino/snapshot-request/index.ts b/hub/server/integrations/pino/snapshot-request/index.ts new file mode 100644 index 00000000..8a1b9d15 --- /dev/null +++ b/hub/server/integrations/pino/snapshot-request/index.ts @@ -0,0 +1,20 @@ +import type { Request } from "express" + +import { sanitizeLogValue } from "../../../utils/logging/sanitize-log-value/index.ts" + +import type { RequestSnapshot } from "./types.ts" + +/** Retain safe route data before Express restores a mounted router's parameters. */ +export function snapshotRequest(request: Request): RequestSnapshot { + const route: unknown = request.route + const path = + route !== null && typeof route === "object" && "path" in route ? route.path : undefined + return { + route: typeof path === "string" ? path : null, + params: sanitizeLogValue(request.params), + query: sanitizeLogValue(request.query), + ...(request.is("application/json") && request.body !== undefined + ? { body: sanitizeLogValue(request.body) } + : {}), + } +} diff --git a/hub/server/integrations/pino/snapshot-request/types.ts b/hub/server/integrations/pino/snapshot-request/types.ts new file mode 100644 index 00000000..d86d170e --- /dev/null +++ b/hub/server/integrations/pino/snapshot-request/types.ts @@ -0,0 +1,8 @@ +import type { LogValue } from "../../../utils/logging/sanitize-log-value/types.ts" + +export interface RequestSnapshot { + route: string | null + params: LogValue + query: LogValue + body?: LogValue +} diff --git a/hub/server/routes/api/health/get/index.ts b/hub/server/routes/api/health/get/index.ts new file mode 100644 index 00000000..8026f06a --- /dev/null +++ b/hub/server/routes/api/health/get/index.ts @@ -0,0 +1,6 @@ +import type { Request, Response } from "express" + +/** Check that the API responds without requiring a database connection. */ +export function get(_request: Request, response: Response): void { + response.json({ status: "ok" }) +} diff --git a/hub/server/routes/index.ts b/hub/server/routes/index.ts new file mode 100644 index 00000000..e5216064 --- /dev/null +++ b/hub/server/routes/index.ts @@ -0,0 +1,8 @@ +import type { Express } from "express" + +import { get as handleApiHealthGet } from "./api/health/get/index.ts" + +/** Keep endpoint registration separate from the app's shared middleware. */ +export function routes(app: Express): void { + app.get("/api/health", handleApiHealthGet) +} diff --git a/hub/server/utils/logging/sanitize-log-value/constants.ts b/hub/server/utils/logging/sanitize-log-value/constants.ts new file mode 100644 index 00000000..d15e3596 --- /dev/null +++ b/hub/server/utils/logging/sanitize-log-value/constants.ts @@ -0,0 +1,8 @@ +export const maxLogBytes = 8192 +export const maxLogDepth = 6 +export const maxLogEntries = 100 +export const maxLogStringLength = 2048 +export const maxLogKeyLength = 128 +export const truncationMarker = "[TRUNCATED]" +export const sensitiveLogKeyPattern = + /(password|passwd|passphrase|secret|token|authorization|cookie|apikey|privatekey|sessionid)/ diff --git a/hub/server/utils/logging/sanitize-log-value/index.test.ts b/hub/server/utils/logging/sanitize-log-value/index.test.ts new file mode 100644 index 00000000..ecb60b54 --- /dev/null +++ b/hub/server/utils/logging/sanitize-log-value/index.test.ts @@ -0,0 +1,111 @@ +import { describe, expect, it, vi } from "vitest" + +import { sanitizeLogValue } from "." + +describe("sanitizeLogValue()", () => { + it("redacts sensitive naming variants recursively without changing the input", () => { + const input = { + title: "Public title", + PASSWORD: "password-value", + nested: [ + { access_token: "token-value", "client-secret": "secret-value", count: 2 }, + { authorization: "authorization-value", cookie: "cookie-value" }, + ], + } + const original = structuredClone(input) + + expect(sanitizeLogValue(input)).toEqual({ + title: "Public title", + PASSWORD: "[REDACTED]", + nested: [ + { access_token: "[REDACTED]", "client-secret": "[REDACTED]", count: 2 }, + { authorization: "[REDACTED]", cookie: "[REDACTED]" }, + ], + }) + expect(input).toEqual(original) + }) + + it("makes cycles and non-JSON primitives safe to serialize", () => { + const input: Record = { + title: "Keep this", + bigint: 1n, + missing: undefined, + infinite: Infinity, + symbol: Symbol("private-symbol"), + callback: () => "private-function", + } + input.self = input + + const result = sanitizeLogValue(input) + + expect(() => JSON.stringify(result)).not.toThrow() + expect(JSON.parse(JSON.stringify(result))).toMatchObject({ title: "Keep this" }) + expect(input.self).toBe(input) + }) + + it("does not execute getters or serialization hooks on unsupported instances", () => { + const getter = vi.fn(() => "getter-secret") + const toJSON = vi.fn(() => ({ exposed: "serialization-secret" })) + class Upload { + toJSON = toJSON + } + const input = { + safe: "Keep this", + upload: new Upload(), + buffer: Buffer.from("upload-secret"), + get computed() { + return getter() + }, + } + + const result = JSON.stringify(sanitizeLogValue(input)) + + expect(getter).not.toHaveBeenCalled() + expect(toJSON).not.toHaveBeenCalled() + expect(result).toContain("Keep this") + expect(result).not.toMatch(/getter-secret|serialization-secret|upload-secret/) + }) + + it("omits values deeper than six levels while retaining shallow data", () => { + const input = { + safe: "Keep this", + nested: { a: { b: { c: { d: { e: { f: { g: "too-deep" } } } } } } }, + } + + const result = JSON.stringify(sanitizeLogValue(input)) + + expect(result).toContain("Keep this") + expect(result).not.toContain("too-deep") + }) + + it("limits total visited entries rather than only limiting each container", () => { + const input = Array.from({ length: 12 }, (_, group) => + Array.from({ length: 10 }, (_, entry) => `entry-${group}-${entry}`), + ) + + const result = JSON.stringify(sanitizeLogValue(input)) + + expect(result).toContain("entry-0-0") + expect(result).not.toContain("entry-11-9") + }) + + it("limits an individual string to 2048 characters", () => { + const input = "a".repeat(2048) + "past-string-limit" + + const result = sanitizeLogValue(input) + + expect(typeof result).toBe("string") + expect((result as string).length).toBeLessThanOrEqual(2048) + expect(result).not.toContain("past-string-limit") + expect(input).toHaveLength(2065) + }) + + it("keeps the final serialized value within 8192 bytes for multibyte text", () => { + const input = Array.from({ length: 6 }, () => "\u754c".repeat(1800)) + + const result = JSON.stringify(sanitizeLogValue(input)) + + expect(Buffer.byteLength(result, "utf8")).toBeLessThanOrEqual(8192) + expect(input[0]).toHaveLength(1800) + }) +}) diff --git a/hub/server/utils/logging/sanitize-log-value/index.ts b/hub/server/utils/logging/sanitize-log-value/index.ts new file mode 100644 index 00000000..fd81e426 --- /dev/null +++ b/hub/server/utils/logging/sanitize-log-value/index.ts @@ -0,0 +1,12 @@ +import { Buffer } from "node:buffer" + +import { visitLogValue } from "../visit-log-value/index.ts" + +import { maxLogBytes } from "./constants.ts" +import type { LogValue } from "./types.ts" + +/** Copy structured data with secret-key redaction and bounded JSON output. */ +export function sanitizeLogValue(value: unknown): LogValue { + const result = visitLogValue(value, 0, { ancestors: new WeakSet(), entries: 0 }) + return Buffer.byteLength(JSON.stringify(result)) <= maxLogBytes ? result : "[OMITTED: MAX BYTES]" +} diff --git a/hub/server/utils/logging/sanitize-log-value/types.ts b/hub/server/utils/logging/sanitize-log-value/types.ts new file mode 100644 index 00000000..eee7766f --- /dev/null +++ b/hub/server/utils/logging/sanitize-log-value/types.ts @@ -0,0 +1 @@ +export type LogValue = null | boolean | number | string | LogValue[] | { [key: string]: LogValue } diff --git a/hub/server/utils/logging/visit-log-value/index.ts b/hub/server/utils/logging/visit-log-value/index.ts new file mode 100644 index 00000000..247eb881 --- /dev/null +++ b/hub/server/utils/logging/visit-log-value/index.ts @@ -0,0 +1,65 @@ +import { + maxLogDepth, + maxLogEntries, + maxLogKeyLength, + maxLogStringLength, + sensitiveLogKeyPattern, + truncationMarker, +} from "../sanitize-log-value/constants.ts" +import type { LogValue } from "../sanitize-log-value/types.ts" + +import type { LogTraversal } from "./types.ts" + +/** Share traversal limits across containers without invoking getters or toJSON(). */ +export function visitLogValue(input: unknown, depth: number, traversal: LogTraversal): LogValue { + if (typeof input === "string") { + return input.length > maxLogStringLength + ? `${input.slice(0, maxLogStringLength - truncationMarker.length)}${truncationMarker}` + : input + } + if (input === null || typeof input === "boolean") return input + if (typeof input === "number") return Number.isFinite(input) ? input : "[NON-FINITE]" + if (typeof input !== "object") return "[UNSUPPORTED]" + if (traversal.ancestors.has(input)) return "[CIRCULAR]" + if (depth >= maxLogDepth) return "[MAX DEPTH]" + if ( + !Array.isArray(input) && + !(input instanceof Error) && + Object.getPrototypeOf(input) !== Object.prototype && + Object.getPrototypeOf(input) !== null + ) { + return "[UNSUPPORTED OBJECT]" + } + + traversal.ancestors.add(input) + const output = Object.create(null) as Record + const array: LogValue[] = [] + if (input instanceof Error) output.type = "Error" + const keys = input instanceof Error ? ["name", "message", "stack", "code"] : Object.keys(input) + for (const key of keys) { + if (++traversal.entries > maxLogEntries) { + if (Array.isArray(input)) array.push("[MAX ENTRIES]") + else output[truncationMarker] = "[MAX ENTRIES]" + break + } + const descriptor = Object.getOwnPropertyDescriptor(input, key) + if (!descriptor) continue + let result: LogValue + if (sensitiveLogKeyPattern.test(key.toLowerCase().replace(/[^a-z0-9]/g, ""))) { + result = "[REDACTED]" + } else if ("value" in descriptor) { + result = visitLogValue(descriptor.value, depth + 1, traversal) + } else { + result = "[UNAVAILABLE]" + } + if (Array.isArray(input)) array.push(result) + else + output[ + key.length > maxLogKeyLength + ? `${key.slice(0, maxLogKeyLength - truncationMarker.length)}${truncationMarker}` + : key + ] = result + } + traversal.ancestors.delete(input) + return Array.isArray(input) ? array : output +} diff --git a/hub/server/utils/logging/visit-log-value/types.ts b/hub/server/utils/logging/visit-log-value/types.ts new file mode 100644 index 00000000..9446a8f0 --- /dev/null +++ b/hub/server/utils/logging/visit-log-value/types.ts @@ -0,0 +1,4 @@ +export interface LogTraversal { + ancestors: WeakSet + entries: number +}