From 1c3b1a066c6e4595efd0e2fcdd9c7201bf47a28b Mon Sep 17 00:00:00 2001 From: Charles Nykamp Date: Wed, 29 Apr 2026 13:50:57 -0500 Subject: [PATCH 01/11] feat: log start and end of api requests Co-authored-by: Copilot --- apps/api/package.json | 1 + apps/api/src/index.ts | 2 + apps/api/src/middleware/requestLogger.ts | 84 +++++++++++++ apps/api/src/test/requestLogger.test.ts | 105 ++++++++++++++++ package-lock.json | 147 ++++++++++++++++++++++- 5 files changed, 337 insertions(+), 2 deletions(-) create mode 100644 apps/api/src/middleware/requestLogger.ts create mode 100644 apps/api/src/test/requestLogger.test.ts diff --git a/apps/api/package.json b/apps/api/package.json index 9aeaeda023..a7b723c359 100644 --- a/apps/api/package.json +++ b/apps/api/package.json @@ -45,6 +45,7 @@ "passport-local": "^1.0.0", "passport-magic-link": "^2.1.1", "passport-strategy": "^1.0.0", + "pino-http": "^11.0.0", "prisma": "6.4.1", "short-uuid": "^5.2.0", "zod": "^4.0.14" diff --git a/apps/api/src/index.ts b/apps/api/src/index.ts index 4a1f0ddaaa..a85336f093 100644 --- a/apps/api/src/index.ts +++ b/apps/api/src/index.ts @@ -49,6 +49,7 @@ import { generateHandle } from "./utils/names"; import { codeRouter } from "./routes/code"; import { metricsRouter } from "./routes/metricsRoutes"; import { contentRouter } from "./routes/content.route"; +import { initRequestLogger } from "./middleware/requestLogger"; // Type assertion to work around passport type declaration issues // eslint-disable-next-line @typescript-eslint/no-explicit-any @@ -394,6 +395,7 @@ app.use( app.use(passport.initialize()); app.use(passport.session()); +app.use("/api", initRequestLogger()); const port = process.env.PORT || 3000; diff --git a/apps/api/src/middleware/requestLogger.ts b/apps/api/src/middleware/requestLogger.ts new file mode 100644 index 0000000000..944afdd147 --- /dev/null +++ b/apps/api/src/middleware/requestLogger.ts @@ -0,0 +1,84 @@ +import type { Request, Response } from "express"; +import pinoHttp from "pino-http"; + +type LoggableObject = Record; +type RequestLoggerOptions = { + stream?: NodeJS.WritableStream; +}; + +/** + * Initialize the pino-http middleware for logging API requests. + * + * The middleware logs two events per API call + * 1) a start event as soon as a request enters the API + * 2) a completion event when the response ends + * + * Each log entry includes only the metadata fields we want. No sensitive data. + */ +export function initRequestLogger(options: RequestLoggerOptions = {}) { + return pinoHttp({ + customErrorMessage() { + return "API request completed"; + }, + customErrorObject(req, res, _err, loggableObject) { + return getRequestEndObject( + req as Request, + res as Response, + loggableObject as LoggableObject, + ); + }, + customReceivedMessage() { + return "API request started"; + }, + customReceivedObject(req) { + return { + ...getRequestMetadata(req as Request), + event: "request_start", + }; + }, + customSuccessMessage() { + return "API request completed"; + }, + customSuccessObject(req, res, loggableObject) { + return getRequestEndObject( + req as Request, + res as Response, + loggableObject as LoggableObject, + ); + }, + level: process.env.LOG_LEVEL?.trim() || "info", + quietReqLogger: true, + stream: options.stream, + }); +} + +/** + * Pulls the safe request fields that we want to include in every lifecycle log. + */ +function getRequestMetadata(req: Request) { + return { + anonymous: req.user?.isAnonymous ?? false, + authenticated: req.user !== undefined, + method: req.method, + path: req.originalUrl || req.url, + }; +} + +function getDurationMs(loggableObject: LoggableObject) { + const responseTime = loggableObject.responseTime; + + return typeof responseTime === "number" ? responseTime : undefined; +} + +function getRequestEndObject( + req: Request, + res: Response, + loggableObject: LoggableObject, +) { + return { + ...getRequestMetadata(req), + durationMs: getDurationMs(loggableObject), + event: "request_end", + statusCode: res.statusCode, + }; +} diff --git a/apps/api/src/test/requestLogger.test.ts b/apps/api/src/test/requestLogger.test.ts new file mode 100644 index 0000000000..67de20dce7 --- /dev/null +++ b/apps/api/src/test/requestLogger.test.ts @@ -0,0 +1,105 @@ +import { EventEmitter } from "node:events"; +import { Writable } from "node:stream"; +import type { Request, Response } from "express"; +import { describe, expect, test } from "vitest"; +import { initRequestLogger } from "../middleware/requestLogger"; + +class MockResponse extends EventEmitter { + statusCode = 200; + writableEnded = false; +} + +function createMockRequest(overrides: Partial = {}) { + return { + method: "GET", + originalUrl: "/api/health", + url: "/api/health", + ...overrides, + } as Request; +} + +function createLogCapture() { + const lines: string[] = []; + const stream = new Writable({ + write(chunk, _encoding, callback) { + lines.push(chunk.toString()); + callback(); + }, + }); + + return { lines, stream }; +} + +function parseLogs(lines: string[]) { + return lines.map((line) => JSON.parse(line)); +} + +describe("createApiRequestLogger", () => { + test("logs request start and end for completed requests", () => { + const { lines, stream } = createLogCapture(); + const middleware = initRequestLogger({ stream }); + const req = createMockRequest(); + const mockResponse = new MockResponse(); + const res = mockResponse as unknown as Response; + + middleware(req, res, () => {}); + + mockResponse.statusCode = 204; + mockResponse.writableEnded = true; + mockResponse.emit("finish"); + + const [startLog, endLog] = parseLogs(lines); + + expect(startLog).toMatchObject({ + anonymous: false, + authenticated: false, + event: "request_start", + method: "GET", + msg: "API request started", + path: "/api/health", + }); + expect(endLog).toMatchObject({ + event: "request_end", + msg: "API request completed", + statusCode: 204, + }); + expect(endLog.durationMs).toBeGreaterThanOrEqual(0); + }); + + test("includes safe authenticated request metadata in both lifecycle logs", () => { + const { lines, stream } = createLogCapture(); + const middleware = initRequestLogger({ stream }); + const req = createMockRequest({ + method: "POST", + originalUrl: "/api/login/anonymous", + url: "/api/login/anonymous", + user: { isAnonymous: true } as Request["user"], + }); + const mockResponse = new MockResponse(); + const res = mockResponse as unknown as Response; + + middleware(req, res, () => {}); + + mockResponse.statusCode = 200; + mockResponse.writableEnded = true; + mockResponse.emit("finish"); + + const [startLog, endLog] = parseLogs(lines); + + expect(startLog).toMatchObject({ + anonymous: true, + authenticated: true, + event: "request_start", + method: "POST", + path: "/api/login/anonymous", + }); + expect(endLog).toMatchObject({ + anonymous: true, + authenticated: true, + event: "request_end", + method: "POST", + path: "/api/login/anonymous", + statusCode: 200, + }); + }); +}); diff --git a/package-lock.json b/package-lock.json index 96b8e30835..3414fe5fad 100644 --- a/package-lock.json +++ b/package-lock.json @@ -38,7 +38,7 @@ "wick-a11y": "^2.5.0" }, "engines": { - "node": "24.15" + "node": "~24.15.0" } }, "apps/api": { @@ -67,6 +67,7 @@ "passport-local": "^1.0.0", "passport-magic-link": "^2.1.1", "passport-strategy": "^1.0.0", + "pino-http": "^11.0.0", "prisma": "6.4.1", "short-uuid": "^5.2.0", "zod": "^4.0.14" @@ -4028,6 +4029,12 @@ "@noble/hashes": "^1.1.5" } }, + "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/@pkgjs/parseargs": { "version": "0.11.0", "resolved": "https://registry.npmjs.org/@pkgjs/parseargs/-/parseargs-0.11.0.tgz", @@ -7930,6 +7937,15 @@ "node": ">= 4.5.0" } }, + "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/available-typed-arrays": { "version": "1.0.7", "resolved": "https://registry.npmjs.org/available-typed-arrays/-/available-typed-arrays-1.0.7.tgz", @@ -12688,7 +12704,6 @@ "version": "2.0.5", "resolved": "https://registry.npmjs.org/get-caller-file/-/get-caller-file-2.0.5.tgz", "integrity": "sha512-DyFP3BM/3YHTQOCUL/w0OZHR0lpKeGrxotcHWcqNEdnltqFwXVfhEBQ94eIo34AfQpo0rGki4cyIiftY06h2Fg==", - "dev": true, "license": "ISC", "engines": { "node": "6.* || 8.* || >= 10.*" @@ -17612,6 +17627,15 @@ "integrity": "sha512-RdR9FQrFwNBNXAr4GixM8YaRZRJ5PUWbKYbE5eOsrwAjJW0q2REGcf79oYPsLyskQCZG1PLN+S/K1V00joZAoQ==", "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", @@ -18149,6 +18173,55 @@ "node": ">=0.10.0" } }, + "node_modules/pino": { + "version": "10.3.1", + "resolved": "https://registry.npmjs.org/pino/-/pino-10.3.1.tgz", + "integrity": "sha512-r34yH/GlQpKZbU1BvFFqOjhISRo1MNx1tWYsYvmj6KIRHSPMT2+yHOEb1SG6NMvRoHRF0a07kCOox/9yakl1vg==", + "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": "^0.2.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.0", "resolved": "https://registry.npmjs.org/pkg-types/-/pkg-types-2.3.0.tgz", @@ -18355,6 +18428,22 @@ "node": ">= 0.6.0" } }, + "node_modules/process-warning": { + "version": "5.0.0", + "resolved": "https://registry.npmjs.org/process-warning/-/process-warning-5.0.0.tgz", + "integrity": "sha512-a39t9ApHNx2L4+HBnQKqxxHNs1r7KF+Intd8Q/g1bUh6q0WIp9voPXJ/x0j+ZL45KF1pJd9+q2jLIRMfvEshkA==", + "funding": [ + { + "type": "github", + "url": "https://github.com/sponsors/fastify" + }, + { + "type": "opencollective", + "url": "https://opencollective.com/fastify" + } + ], + "license": "MIT" + }, "node_modules/prompts": { "version": "2.4.2", "resolved": "https://registry.npmjs.org/prompts/-/prompts-2.4.2.tgz", @@ -18512,6 +18601,12 @@ ], "license": "MIT" }, + "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/quick-lru": { "version": "4.0.1", "resolved": "https://registry.npmjs.org/quick-lru/-/quick-lru-4.0.1.tgz", @@ -18965,6 +19060,15 @@ "url": "https://paulmillr.com/funding/" } }, + "node_modules/real-require": { + "version": "0.2.0", + "resolved": "https://registry.npmjs.org/real-require/-/real-require-0.2.0.tgz", + "integrity": "sha512-57frrGM/OCTLqLOAh0mhVA9VBMHd+9U7Zb2THMGdBUoZVOtGbJzjxsYGDJ3A9AYYCP4hn6y1TVbaOfzWtm5GFg==", + "license": "MIT", + "engines": { + "node": ">= 12.13.0" + } + }, "node_modules/recharts": { "version": "2.15.4", "resolved": "https://registry.npmjs.org/recharts/-/recharts-2.15.4.tgz", @@ -19877,6 +19981,15 @@ "url": "https://github.com/sponsors/ljharb" } }, + "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", @@ -20541,6 +20654,15 @@ "integrity": "sha512-Tpp60P6IUJDTuOq/5Z8cdskzJujfwqfOTkrwIwj7IRISpnkJnT6SyJ4PCPnGMoFjC9ddhal5KVIYtAt97ix05A==", "license": "MIT" }, + "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/sort-keys": { "version": "2.0.0", "resolved": "https://registry.npmjs.org/sort-keys/-/sort-keys-2.0.0.tgz", @@ -20683,6 +20805,15 @@ "node": ">=0.10.0" } }, + "node_modules/split2": { + "version": "4.2.0", + "resolved": "https://registry.npmjs.org/split2/-/split2-4.2.0.tgz", + "integrity": "sha512-UcjcJOWknrNkF6PLX83qcHM6KHgVKNkV62Y8a5uYDVv9ydGQVwAHMKqHdJje1VTWpljG0WYpCDhrCdAOYH4TWg==", + "license": "ISC", + "engines": { + "node": ">= 10.x" + } + }, "node_modules/sprintf-js": { "version": "1.0.3", "resolved": "https://registry.npmjs.org/sprintf-js/-/sprintf-js-1.0.3.tgz", @@ -21195,6 +21326,18 @@ "url": "https://opencollective.com/webpack" } }, + "node_modules/thread-stream": { + "version": "4.0.0", + "resolved": "https://registry.npmjs.org/thread-stream/-/thread-stream-4.0.0.tgz", + "integrity": "sha512-4iMVL6HAINXWf1ZKZjIPcz5wYaOdPhtO8ATvZ+Xqp3BTdaqtAwQkNmKORqcIo5YkQqGXq5cwfswDwMqqQNrpJA==", + "license": "MIT", + "dependencies": { + "real-require": "^0.2.0" + }, + "engines": { + "node": ">=20" + } + }, "node_modules/throttleit": { "version": "1.0.1", "resolved": "https://registry.npmjs.org/throttleit/-/throttleit-1.0.1.tgz", From 997b95e0ae9749a55ea9aa37dc532822e09c87f5 Mon Sep 17 00:00:00 2001 From: Charles Nykamp Date: Wed, 29 Apr 2026 13:55:54 -0500 Subject: [PATCH 02/11] better log levels Co-authored-by: Copilot --- apps/api/src/middleware/requestLogger.ts | 32 +++++++++++++----------- apps/api/src/test/requestLogger.test.ts | 6 +++-- 2 files changed, 22 insertions(+), 16 deletions(-) diff --git a/apps/api/src/middleware/requestLogger.ts b/apps/api/src/middleware/requestLogger.ts index 944afdd147..ea442580d6 100644 --- a/apps/api/src/middleware/requestLogger.ts +++ b/apps/api/src/middleware/requestLogger.ts @@ -1,4 +1,4 @@ -import type { Request, Response } from "express"; +import type { NextFunction, Request, Response } from "express"; import pinoHttp from "pino-http"; type LoggableObject = Record; @@ -10,13 +10,13 @@ type RequestLoggerOptions = { * Initialize the pino-http middleware for logging API requests. * * The middleware logs two events per API call - * 1) a start event as soon as a request enters the API - * 2) a completion event when the response ends + * 1) a start event as soon as a request enters the API (level: debug) + * 2) a completion event when the response ends (level: info) * * Each log entry includes only the metadata fields we want. No sensitive data. */ export function initRequestLogger(options: RequestLoggerOptions = {}) { - return pinoHttp({ + const httpLogger = pinoHttp({ customErrorMessage() { return "API request completed"; }, @@ -27,15 +27,6 @@ export function initRequestLogger(options: RequestLoggerOptions = {}) { loggableObject as LoggableObject, ); }, - customReceivedMessage() { - return "API request started"; - }, - customReceivedObject(req) { - return { - ...getRequestMetadata(req as Request), - event: "request_start", - }; - }, customSuccessMessage() { return "API request completed"; }, @@ -46,10 +37,23 @@ export function initRequestLogger(options: RequestLoggerOptions = {}) { loggableObject as LoggableObject, ); }, - level: process.env.LOG_LEVEL?.trim() || "info", + level: "debug", quietReqLogger: true, stream: options.stream, + useLevel: "info", }); + + return (req: Request, res: Response, next: NextFunction) => { + httpLogger(req, res); + req.log.debug( + { + ...getRequestMetadata(req), + event: "request_start", + }, + "API request started", + ); + next(); + }; } /** diff --git a/apps/api/src/test/requestLogger.test.ts b/apps/api/src/test/requestLogger.test.ts index 67de20dce7..64b5af92f9 100644 --- a/apps/api/src/test/requestLogger.test.ts +++ b/apps/api/src/test/requestLogger.test.ts @@ -34,8 +34,8 @@ function parseLogs(lines: string[]) { return lines.map((line) => JSON.parse(line)); } -describe("createApiRequestLogger", () => { - test("logs request start and end for completed requests", () => { +describe("initRequestLogger", () => { + test("logs request start at debug and request end at info", () => { const { lines, stream } = createLogCapture(); const middleware = initRequestLogger({ stream }); const req = createMockRequest(); @@ -54,12 +54,14 @@ describe("createApiRequestLogger", () => { anonymous: false, authenticated: false, event: "request_start", + level: 20, method: "GET", msg: "API request started", path: "/api/health", }); expect(endLog).toMatchObject({ event: "request_end", + level: 30, msg: "API request completed", statusCode: 204, }); From 8a79b04c92277579d3ba9007df5c44957e511f8c Mon Sep 17 00:00:00 2001 From: Charles Nykamp Date: Thu, 30 Apr 2026 09:37:25 -0500 Subject: [PATCH 03/11] tweak `npm run dev` --- AGENTS.md | 2 ++ README.md | 30 +++++++++--------------------- package.json | 2 +- packages/shared/package.json | 2 +- 4 files changed, 13 insertions(+), 23 deletions(-) diff --git a/AGENTS.md b/AGENTS.md index 56d3769f84..fd76b2f91b 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -28,8 +28,10 @@ npm ci ### Dev servers ```bash +npm run dev # builds shared once, then runs api/app/web npm run dev --workspace @doenet-tools/api # Express API on port 3000 npm run dev --workspace @doenet-tools/app # Vite dev server on port 8000 (proxies /api to port 3000) +npm run watch --workspace @doenet-tools/shared # shared TypeScript watcher when needed ``` ### Build diff --git a/README.md b/README.md index 4ea46e0dd3..4ea8c8391c 100644 --- a/README.md +++ b/README.md @@ -19,28 +19,21 @@ We would love to hear from you! Join our [Discord](https://discord.gg/PUduwtKJ5h ### Steps -**1. Clone the repository** - -```bash -git clone https://github.com/Doenet/DoenetTools.git -cd DoenetTools -``` - -**2. Install dependencies** +**1. Install dependencies** ```bash npm install ``` -**3. Create the `.env` file** +**2. Create the un-tracked `.env` file** ```bash npm run setup ``` -This copies `apps/api/.env.example` to `apps/api/.env`. The defaults work for local development, but edit as needed (e.g. change `DATABASE_HOST`, `DATABASE_PORT`, or `DATABASE_PASSWORD` if your MySQL setup differs — and update `DATABASE_URL` to match). +This file (`apps/api/.env`) contains secrets like the database password and database url. -**4. Start the database** +**3. Start the database** ```bash docker compose --env-file apps/api/.env up -d @@ -48,7 +41,7 @@ docker compose --env-file apps/api/.env up -d Wait until the MySQL container shows `(healthy)` in `docker container ls` before continuing. -**5. Setup the database tables** +**4. Setup the database tables** ```bash npm run db:setup @@ -56,9 +49,9 @@ npm run db:setup This creates the required database tables and seeds them with minimal data. -**6. Start the dev servers** +**5. Start the dev servers** -All dev processes can be started together with a single command: +The main dev processes can be started together with a single command: ```bash npm run dev @@ -66,25 +59,20 @@ npm run dev This starts: -- Shared package watcher - Express API → http://localhost:3000 - React SPA → http://localhost:8000 (proxies `/api/*` to the API) - Astro site → http://localhost:4321 -This command first builds `shared` once, then starts its watch process alongside -the app, API, and web dev servers. - Alternatively, run each in a separate terminal if needed: ```bash -npm run dev --workspace @doenet-tools/shared # Shared package watcher +npm run build --workspace @doenet-tools/shared # Do this first npm run dev --workspace @doenet-tools/api # Express API npm run dev --workspace @doenet-tools/app # React SPA npm run dev --workspace @doenet-tools/web # Astro site +npm run watch --workspace @doenet-tools/shared # if making edits to this package ``` ---- - ## Repository Structure This repository is an npm workspace monorepo. Packages are organized into two directories: diff --git a/package.json b/package.json index 6b113cf3cc..4cc54bd410 100644 --- a/package.json +++ b/package.json @@ -13,7 +13,7 @@ "postinstall": "npm run prisma:generate --workspace @doenet-tools/api", "setup": "node scripts/setup.js", "db:setup": "npm run prisma:migrate-dev --workspace @doenet-tools/api && npm run prisma:seed --workspace @doenet-tools/api", - "dev": "npm run build --workspace @doenet-tools/shared -- --force && concurrently \"npm run dev --workspace @doenet-tools/shared\" \"npm run dev --workspace @doenet-tools/api\" \"npm run dev --workspace @doenet-tools/app\" \"npm run dev --workspace @doenet-tools/web\"", + "dev": "npm run build --workspace @doenet-tools/shared && concurrently \"npm run dev --workspace @doenet-tools/api\" \"npm run dev --workspace @doenet-tools/app\" \"npm run dev --workspace @doenet-tools/web\"", "format": "prettier . --write", "format:check": "prettier . --check", "lint": "npm run lint --workspaces --if-present", diff --git a/packages/shared/package.json b/packages/shared/package.json index f16876ea5b..9360eee945 100644 --- a/packages/shared/package.json +++ b/packages/shared/package.json @@ -16,7 +16,7 @@ } }, "scripts": { - "dev": "tsc --build --watch --preserveWatchOutput --force", + "watch": "tsc --build --watch --preserveWatchOutput", "lint": "eslint --fix", "lint:check": "eslint", "build": "tsc --build" From 3d16709418a5df57525fdae43ccffada4e95e545 Mon Sep 17 00:00:00 2001 From: Charles Nykamp Date: Thu, 30 Apr 2026 10:08:44 -0500 Subject: [PATCH 04/11] chore: cleaner npm run dev --- apps/api/src/index.ts | 4 +++- apps/api/src/utils/cli.ts | 28 ++++++++++++++++++++++++++++ package.json | 2 +- 3 files changed, 32 insertions(+), 2 deletions(-) create mode 100644 apps/api/src/utils/cli.ts diff --git a/apps/api/src/index.ts b/apps/api/src/index.ts index a85336f093..eeea4ab040 100644 --- a/apps/api/src/index.ts +++ b/apps/api/src/index.ts @@ -18,6 +18,7 @@ import { SESClient, SendEmailCommand } from "@aws-sdk/client-ses"; import { nanoid } from "nanoid"; import * as fs from "fs/promises"; import { fromUUID, toUUID } from "./utils/uuid"; +import { formatApiReadyMessage } from "./utils/cli"; import { UserInfo, UserInfoWithEmail } from "./types"; import { findOrCreateUser, @@ -475,5 +476,6 @@ app.post( // ); app.listen(port, () => { - console.log(`[server]: Server is running at http://localhost:${port}`); + const localUrl = `http://localhost:${port}`; + console.log(formatApiReadyMessage(localUrl)); }); diff --git a/apps/api/src/utils/cli.ts b/apps/api/src/utils/cli.ts new file mode 100644 index 0000000000..bac48894dc --- /dev/null +++ b/apps/api/src/utils/cli.ts @@ -0,0 +1,28 @@ +const ansiReset = "\x1b[0m"; +const shouldUseAnsiColors = + process.env.NO_COLOR === undefined && process.env.FORCE_COLOR !== "0"; + +const ansiStyles = { + bold: "\x1b[1m", + dim: "\x1b[2m", + green: "\x1b[32m", + cyan: "\x1b[36m", +} as const; + +function styleCli(text: string, ...codes: string[]) { + if (!shouldUseAnsiColors) { + return text; + } + + return `${codes.join("")}${text}${ansiReset}`; +} + +export function formatApiReadyMessage(localUrl: string) { + return [ + "", + ` ${styleCli("API", ansiStyles.bold, ansiStyles.green)} ${styleCli("ready", ansiStyles.dim)}`, + "", + ` ${styleCli("Local:", ansiStyles.dim)} ${styleCli(localUrl, ansiStyles.cyan)}`, + "", + ].join("\n"); +} diff --git a/package.json b/package.json index 4cc54bd410..3478214c61 100644 --- a/package.json +++ b/package.json @@ -13,7 +13,7 @@ "postinstall": "npm run prisma:generate --workspace @doenet-tools/api", "setup": "node scripts/setup.js", "db:setup": "npm run prisma:migrate-dev --workspace @doenet-tools/api && npm run prisma:seed --workspace @doenet-tools/api", - "dev": "npm run build --workspace @doenet-tools/shared && concurrently \"npm run dev --workspace @doenet-tools/api\" \"npm run dev --workspace @doenet-tools/app\" \"npm run dev --workspace @doenet-tools/web\"", + "dev": "npm run build --workspace @doenet-tools/shared && concurrently --names \"API,APP,WEB\" --prefix-colors \"auto\" \"npm run dev --workspace @doenet-tools/api\" \"npm run dev --workspace @doenet-tools/app\" \"npm run dev --workspace @doenet-tools/web\"", "format": "prettier . --write", "format:check": "prettier . --check", "lint": "npm run lint --workspaces --if-present", From 0df1046f723ab32b5e21cbd834eb2bd13cd88328 Mon Sep 17 00:00:00 2001 From: Charles Nykamp Date: Thu, 30 Apr 2026 11:03:09 -0500 Subject: [PATCH 05/11] feat: use `pino-pretty` for dev logs --- apps/api/.env.example | 4 +- apps/api/package.json | 1 + apps/api/src/logging/loggerConfig.ts | 75 ++++++++++++++ apps/api/src/middleware/requestLogger.ts | 121 ++++++++++++++++------- apps/api/src/test/requestLogger.test.ts | 109 ++++++++++++++++---- package-lock.json | 97 ++++++++++++++++++ 6 files changed, 356 insertions(+), 51 deletions(-) create mode 100644 apps/api/src/logging/loggerConfig.ts diff --git a/apps/api/.env.example b/apps/api/.env.example index f4ccf2c862..b92aeabb51 100644 --- a/apps/api/.env.example +++ b/apps/api/.env.example @@ -2,8 +2,10 @@ PORT="3000" # Base URL of the frontend app APP_URL="http://localhost:8000" +LOG_LEVEL="info" #Flags +# Dev flags (only enable for local dev, not production) ENABLE_TEST_AUTH_BYPASS="true" ENABLE_TEST_ROUTES="true" MOCK_SIGNIN_EMAIL="true" @@ -33,4 +35,4 @@ MAGIC_LINK_SECRET="mysecret" DISCOURSE_URL="https://community.example.com" DISCOURSE_SSO_SECRET="mysecret" DISCOURSE_API_KEY="mysecret" -DISCOURSE_API_USERNAME="system" \ No newline at end of file +DISCOURSE_API_USERNAME="system" diff --git a/apps/api/package.json b/apps/api/package.json index a7b723c359..bd3c6d0e02 100644 --- a/apps/api/package.json +++ b/apps/api/package.json @@ -60,6 +60,7 @@ "@types/passport-google-oauth20": "^2.0.16", "@types/passport-local": "^1.0.38", "@types/passport-strategy": "^0.2.38", + "pino-pretty": "^13.1.3", "vitest": "^3.2.4" }, "optionalDependencies": { diff --git a/apps/api/src/logging/loggerConfig.ts b/apps/api/src/logging/loggerConfig.ts new file mode 100644 index 0000000000..b183605eb6 --- /dev/null +++ b/apps/api/src/logging/loggerConfig.ts @@ -0,0 +1,75 @@ +export type LogLevel = + | "trace" + | "debug" + | "info" + | "warn" + | "error" + | "fatal" + | "silent"; + +export type LoggerConfigOptions = { + prettyIgnore?: string[]; + stream?: NodeJS.WritableStream; +}; + +/** + * Shared pino configuration for logs + */ +export function getApiLoggerOptions(options: LoggerConfigOptions = {}) { + const logLevel = getLogLevel(); + + return { + level: logLevel, + stream: options.stream, + ...(shouldUsePrettyLogs(options) + ? getPrettyTransportOptions(logLevel, options.prettyIgnore) + : {}), + }; +} + +function getLogLevel(): LogLevel { + const logLevel = process.env.LOG_LEVEL?.trim().toLowerCase(); + return isLogLevel(logLevel) ? logLevel : "info"; +} + +function isLogLevel(logLevel: string | undefined): logLevel is LogLevel { + return ( + logLevel === "trace" || + logLevel === "debug" || + logLevel === "info" || + logLevel === "warn" || + logLevel === "error" || + logLevel === "fatal" || + logLevel === "silent" + ); +} + +function shouldUsePrettyLogs(options: LoggerConfigOptions) { + if (options.stream) { + return false; + } + + return ( + process.env.NODE_ENV === "development" || + process.env.npm_lifecycle_event === "dev" + ); +} + +function getPrettyTransportOptions( + logLevel: LogLevel, + prettyIgnore: string[] | undefined, +) { + return { + transport: { + target: "pino-pretty", + options: { + colorize: true, + hideObject: true, + messageFormat: "{msg}", + translateTime: "SYS:standard", + ...(logLevel === "silent" ? {} : { minimumLevel: logLevel }), + ...(prettyIgnore?.length ? { ignore: prettyIgnore.join(",") } : {}), + }, + }, + }; +} diff --git a/apps/api/src/middleware/requestLogger.ts b/apps/api/src/middleware/requestLogger.ts index ea442580d6..32ff28ca6d 100644 --- a/apps/api/src/middleware/requestLogger.ts +++ b/apps/api/src/middleware/requestLogger.ts @@ -1,9 +1,16 @@ import type { NextFunction, Request, Response } from "express"; import pinoHttp from "pino-http"; +import { + getApiLoggerOptions, + type LoggerConfigOptions, + type LogLevel, +} from "../logging/loggerConfig"; type LoggableObject = Record; -type RequestLoggerOptions = { - stream?: NodeJS.WritableStream; +type RequestWithLogger = Request & { + log: { + debug: (object: Record, message: string) => void; + }; }; /** @@ -11,47 +18,43 @@ type RequestLoggerOptions = { * * The middleware logs two events per API call * 1) a start event as soon as a request enters the API (level: debug) - * 2) a completion event when the response ends (level: info) + * 2) a completion event when the response ends (level: info/warn/error) * * Each log entry includes only the metadata fields we want. No sensitive data. + * LOG_LEVEL controls the minimum emitted log level in both local dev and prod. */ -export function initRequestLogger(options: RequestLoggerOptions = {}) { +export function initRequestLogger(options: LoggerConfigOptions = {}) { const httpLogger = pinoHttp({ - customErrorMessage() { - return "API request completed"; - }, - customErrorObject(req, res, _err, loggableObject) { - return getRequestEndObject( - req as Request, - res as Response, - loggableObject as LoggableObject, - ); + ...getApiLoggerOptions({ + ...options, + prettyIgnore: getRequestPrettyIgnore(), + }), + customErrorMessage: getRequestCompletionMessage, + customErrorObject( + req: Request, + res: Response, + _err: Error, + loggableObject: LoggableObject, + ) { + return getRequestCompletionObject(req, res, loggableObject); }, - customSuccessMessage() { - return "API request completed"; + customSuccessMessage: getRequestCompletionMessage, + customSuccessObject( + req: Request, + res: Response, + loggableObject: LoggableObject, + ) { + return getRequestCompletionObject(req, res, loggableObject); }, - customSuccessObject(req, res, loggableObject) { - return getRequestEndObject( - req as Request, - res as Response, - loggableObject as LoggableObject, - ); + customLogLevel(_req: Request, res: Response, err?: Error) { + return getRequestCompletionLogLevel(res, err); }, - level: "debug", quietReqLogger: true, - stream: options.stream, - useLevel: "info", }); return (req: Request, res: Response, next: NextFunction) => { httpLogger(req, res); - req.log.debug( - { - ...getRequestMetadata(req), - event: "request_start", - }, - "API request started", - ); + logRequestStart(req); next(); }; } @@ -64,7 +67,7 @@ function getRequestMetadata(req: Request) { anonymous: req.user?.isAnonymous ?? false, authenticated: req.user !== undefined, method: req.method, - path: req.originalUrl || req.url, + path: getRequestPath(req), }; } @@ -74,7 +77,59 @@ function getDurationMs(loggableObject: LoggableObject) { return typeof responseTime === "number" ? responseTime : undefined; } -function getRequestEndObject( +function getRequestPath(req: Request) { + if (req.baseUrl || req.path) { + return `${req.baseUrl}${req.path}`; + } + + return (req.originalUrl || req.url).split("?")[0]; +} + +function getRequestStartMessage(req: Request) { + return `START: ${req.method} ${getRequestPath(req)}`; +} + +function getRequestCompletionMessage(req: Request, res: Response) { + return `${res.statusCode} ${req.method} ${getRequestPath(req)}`; +} + +function getRequestCompletionLogLevel(res: Response, err?: Error): LogLevel { + if (res.statusCode >= 500 || err) { + return "error"; + } + + if (res.statusCode >= 400) { + return "warn"; + } + + return "info"; +} + +function getRequestPrettyIgnore() { + return [ + "pid", + "hostname", + "event", + "method", + "path", + "statusCode", + "durationMs", + "authenticated", + "anonymous", + ]; +} + +function logRequestStart(req: Request) { + (req as RequestWithLogger).log.debug( + { + ...getRequestMetadata(req), + event: "request_start", + }, + getRequestStartMessage(req), + ); +} + +function getRequestCompletionObject( req: Request, res: Response, loggableObject: LoggableObject, diff --git a/apps/api/src/test/requestLogger.test.ts b/apps/api/src/test/requestLogger.test.ts index 64b5af92f9..e7745ea259 100644 --- a/apps/api/src/test/requestLogger.test.ts +++ b/apps/api/src/test/requestLogger.test.ts @@ -1,19 +1,24 @@ import { EventEmitter } from "node:events"; import { Writable } from "node:stream"; import type { Request, Response } from "express"; -import { describe, expect, test } from "vitest"; +import { afterEach, describe, expect, test } from "vitest"; import { initRequestLogger } from "../middleware/requestLogger"; class MockResponse extends EventEmitter { + err?: Error; statusCode = 200; writableEnded = false; } +const originalLogLevel = process.env.LOG_LEVEL; + function createMockRequest(overrides: Partial = {}) { return { + baseUrl: "/api", method: "GET", originalUrl: "/api/health", - url: "/api/health", + path: "/health", + url: "/health", ...overrides, } as Request; } @@ -35,7 +40,18 @@ function parseLogs(lines: string[]) { } describe("initRequestLogger", () => { - test("logs request start at debug and request end at info", () => { + afterEach(() => { + if (originalLogLevel === undefined) { + delete process.env.LOG_LEVEL; + return; + } + + process.env.LOG_LEVEL = originalLogLevel; + }); + + test("defaults to info and suppresses the debug start log", () => { + delete process.env.LOG_LEVEL; + const { lines, stream } = createLogCapture(); const middleware = initRequestLogger({ stream }); const req = createMockRequest(); @@ -48,33 +64,28 @@ describe("initRequestLogger", () => { mockResponse.writableEnded = true; mockResponse.emit("finish"); - const [startLog, endLog] = parseLogs(lines); + const [endLog] = parseLogs(lines); - expect(startLog).toMatchObject({ - anonymous: false, - authenticated: false, - event: "request_start", - level: 20, - method: "GET", - msg: "API request started", - path: "/api/health", - }); + expect(lines).toHaveLength(1); expect(endLog).toMatchObject({ event: "request_end", level: 30, - msg: "API request completed", + msg: "204 GET /api/health", statusCode: 204, }); expect(endLog.durationMs).toBeGreaterThanOrEqual(0); }); - test("includes safe authenticated request metadata in both lifecycle logs", () => { + test("emits the request start log when LOG_LEVEL=debug", () => { + process.env.LOG_LEVEL = "debug"; + const { lines, stream } = createLogCapture(); const middleware = initRequestLogger({ stream }); const req = createMockRequest({ method: "POST", - originalUrl: "/api/login/anonymous", - url: "/api/login/anonymous", + originalUrl: "/api/login/anonymous?token=secret", + path: "/login/anonymous", + url: "/login/anonymous?token=secret", user: { isAnonymous: true } as Request["user"], }); const mockResponse = new MockResponse(); @@ -99,9 +110,73 @@ describe("initRequestLogger", () => { anonymous: true, authenticated: true, event: "request_end", + level: 30, method: "POST", + msg: "200 POST /api/login/anonymous", path: "/api/login/anonymous", statusCode: 200, }); }); + + test("logs 4xx responses at warn", () => { + delete process.env.LOG_LEVEL; + + const { lines, stream } = createLogCapture(); + const middleware = initRequestLogger({ stream }); + const req = createMockRequest({ + originalUrl: "/api/content/not-found?token=super-secret", + path: "/content/not-found", + url: "/content/not-found?token=super-secret", + }); + const mockResponse = new MockResponse(); + const res = mockResponse as unknown as Response; + + middleware(req, res, () => {}); + + mockResponse.statusCode = 404; + mockResponse.writableEnded = true; + mockResponse.emit("finish"); + + const [endLog] = parseLogs(lines); + + expect(lines).toHaveLength(1); + expect(endLog).toMatchObject({ + event: "request_end", + level: 40, + msg: "404 GET /api/content/not-found", + path: "/api/content/not-found", + statusCode: 404, + }); + }); + + test("uses a failure-specific completion message for errored requests", () => { + delete process.env.LOG_LEVEL; + + const { lines, stream } = createLogCapture(); + const middleware = initRequestLogger({ stream }); + const req = createMockRequest({ + originalUrl: "/api/login/magic?token=super-secret", + path: "/login/magic", + url: "/login/magic?token=super-secret", + }); + const mockResponse = new MockResponse(); + const res = mockResponse as unknown as Response; + + middleware(req, res, () => {}); + + mockResponse.err = new Error("boom"); + mockResponse.statusCode = 500; + mockResponse.writableEnded = true; + mockResponse.emit("finish"); + + const [endLog] = parseLogs(lines); + + expect(endLog).toMatchObject({ + event: "request_end", + level: 50, + msg: "500 GET /api/login/magic", + path: "/api/login/magic", + statusCode: 500, + }); + }); }); diff --git a/package-lock.json b/package-lock.json index 3414fe5fad..90c29fb4cf 100644 --- a/package-lock.json +++ b/package-lock.json @@ -82,6 +82,7 @@ "@types/passport-google-oauth20": "^2.0.16", "@types/passport-local": "^1.0.38", "@types/passport-strategy": "^0.2.38", + "pino-pretty": "^13.1.3", "vitest": "^3.2.4" }, "optionalDependencies": { @@ -10284,6 +10285,16 @@ "url": "https://github.com/sponsors/ljharb" } }, + "node_modules/dateformat": { + "version": "4.6.3", + "resolved": "https://registry.npmjs.org/dateformat/-/dateformat-4.6.3.tgz", + "integrity": "sha512-2P0p0pFGzHS5EMnhdxQi7aJN+iMheud0UhG4dlE1DLAlvL8JHjJJTX/CSm4JXwV0Ka5nGk3zC5mcb5bUQUxxMA==", + "dev": true, + "license": "MIT", + "engines": { + "node": "*" + } + }, "node_modules/dayjs": { "version": "1.11.19", "resolved": "https://registry.npmjs.org/dayjs/-/dayjs-1.11.19.tgz", @@ -12052,6 +12063,13 @@ ], "license": "MIT" }, + "node_modules/fast-copy": { + "version": "4.0.3", + "resolved": "https://registry.npmjs.org/fast-copy/-/fast-copy-4.0.3.tgz", + "integrity": "sha512-58apWr0GUiDFM8+3afrO6eYwJBn9ZAhDOzG3L+/9llab/haCARS2UIfffmOurYLwbgDRs8n0rfr6qAAPEAuAQw==", + "dev": true, + "license": "MIT" + }, "node_modules/fast-deep-equal": { "version": "3.1.3", "resolved": "https://registry.npmjs.org/fast-deep-equal/-/fast-deep-equal-3.1.3.tgz", @@ -12110,6 +12128,13 @@ "dev": true, "license": "MIT" }, + "node_modules/fast-safe-stringify": { + "version": "2.1.1", + "resolved": "https://registry.npmjs.org/fast-safe-stringify/-/fast-safe-stringify-2.1.1.tgz", + "integrity": "sha512-W+KJc2dmILlPplD/H4K9l9LcAHAfPtP6BY84uVLXQ6Evcz9Lcg33Y2z1IVblT6xdY54PXYVHEv+0Wpq8Io6zkA==", + "dev": true, + "license": "MIT" + }, "node_modules/fast-uri": { "version": "3.1.0", "resolved": "https://registry.npmjs.org/fast-uri/-/fast-uri-3.1.0.tgz", @@ -13560,6 +13585,13 @@ "he": "bin/he" } }, + "node_modules/help-me": { + "version": "5.0.0", + "resolved": "https://registry.npmjs.org/help-me/-/help-me-5.0.0.tgz", + "integrity": "sha512-7xgomUX6ADmcYzFik0HzAxh/73YlKR9bmFzf51CZwR+b6YtzU2m0u49hQCqV6SvlqIqsaxovfwdvbnsw3b/zpg==", + "dev": true, + "license": "MIT" + }, "node_modules/hoist-non-react-statics": { "version": "3.3.2", "resolved": "https://registry.npmjs.org/hoist-non-react-statics/-/hoist-non-react-statics-3.3.2.tgz", @@ -14623,6 +14655,16 @@ "dev": true, "license": "MIT" }, + "node_modules/joycon": { + "version": "3.1.1", + "resolved": "https://registry.npmjs.org/joycon/-/joycon-3.1.1.tgz", + "integrity": "sha512-34wB/Y7MW7bzjKRjUKTa46I2Z7eV62Rkhva+KkopW7Qvv/OSWBqvkSY7vusOPrNuZcUG3tApvdVgNB8POj3SPw==", + "dev": true, + "license": "MIT", + "engines": { + "node": ">=10" + } + }, "node_modules/js-sha3": { "version": "0.8.0", "resolved": "https://registry.npmjs.org/js-sha3/-/js-sha3-0.8.0.tgz", @@ -18216,6 +18258,44 @@ "process-warning": "^5.0.0" } }, + "node_modules/pino-pretty": { + "version": "13.1.3", + "resolved": "https://registry.npmjs.org/pino-pretty/-/pino-pretty-13.1.3.tgz", + "integrity": "sha512-ttXRkkOz6WWC95KeY9+xxWL6AtImwbyMHrL1mSwqwW9u+vLp/WIElvHvCSDg0xO/Dzrggz1zv3rN5ovTRVowKg==", + "dev": true, + "license": "MIT", + "dependencies": { + "colorette": "^2.0.7", + "dateformat": "^4.6.3", + "fast-copy": "^4.0.0", + "fast-safe-stringify": "^2.1.1", + "help-me": "^5.0.0", + "joycon": "^3.1.1", + "minimist": "^1.2.6", + "on-exit-leak-free": "^2.1.0", + "pino-abstract-transport": "^3.0.0", + "pump": "^3.0.0", + "secure-json-parse": "^4.0.0", + "sonic-boom": "^4.0.1", + "strip-json-comments": "^5.0.2" + }, + "bin": { + "pino-pretty": "bin.js" + } + }, + "node_modules/pino-pretty/node_modules/strip-json-comments": { + "version": "5.0.3", + "resolved": "https://registry.npmjs.org/strip-json-comments/-/strip-json-comments-5.0.3.tgz", + "integrity": "sha512-1tB5mhVo7U+ETBKNf92xT4hrQa3pm0MZ0PQvuDnWgAAGHDsfp4lPSpiS6psrSiet87wyGPh9ft6wmhOMQ0hDiw==", + "dev": true, + "license": "MIT", + "engines": { + "node": ">=14.16" + }, + "funding": { + "url": "https://github.com/sponsors/sindresorhus" + } + }, "node_modules/pino-std-serializers": { "version": "7.1.0", "resolved": "https://registry.npmjs.org/pino-std-serializers/-/pino-std-serializers-7.1.0.tgz", @@ -20011,6 +20091,23 @@ "integrity": "sha512-eNv+WrVbKu1f3vbYJT/xtiF5syA5HPIMtf9IgY/nKg0sWqzAUEvqY/xm7OcZc/qafLx/iO9FgOmeSAp4v5ti/Q==", "license": "MIT" }, + "node_modules/secure-json-parse": { + "version": "4.1.0", + "resolved": "https://registry.npmjs.org/secure-json-parse/-/secure-json-parse-4.1.0.tgz", + "integrity": "sha512-l4KnYfEyqYJxDwlNVyRfO2E4NTHfMKAWdUuA8J0yve2Dz/E/PdBepY03RvyJpssIpRFwJoCD55wA+mEDs6ByWA==", + "dev": true, + "funding": [ + { + "type": "github", + "url": "https://github.com/sponsors/fastify" + }, + { + "type": "opencollective", + "url": "https://opencollective.com/fastify" + } + ], + "license": "BSD-3-Clause" + }, "node_modules/seedrandom": { "version": "3.0.5", "resolved": "https://registry.npmjs.org/seedrandom/-/seedrandom-3.0.5.tgz", From f542bf8d6390abe053882a34487b1b3cc1737969 Mon Sep 17 00:00:00 2001 From: Charles Nykamp Date: Thu, 30 Apr 2026 11:12:09 -0500 Subject: [PATCH 06/11] log userId for authenticated endpoints --- apps/api/src/middleware/requestLogger.ts | 1 + apps/api/src/test/requestLogger.test.ts | 11 ++++++++++- 2 files changed, 11 insertions(+), 1 deletion(-) diff --git a/apps/api/src/middleware/requestLogger.ts b/apps/api/src/middleware/requestLogger.ts index 32ff28ca6d..2af9f5a2c9 100644 --- a/apps/api/src/middleware/requestLogger.ts +++ b/apps/api/src/middleware/requestLogger.ts @@ -68,6 +68,7 @@ function getRequestMetadata(req: Request) { authenticated: req.user !== undefined, method: req.method, path: getRequestPath(req), + ...(req.user?.userId ? { userId: req.user.userId } : {}), }; } diff --git a/apps/api/src/test/requestLogger.test.ts b/apps/api/src/test/requestLogger.test.ts index e7745ea259..f4365fb325 100644 --- a/apps/api/src/test/requestLogger.test.ts +++ b/apps/api/src/test/requestLogger.test.ts @@ -3,6 +3,7 @@ import { Writable } from "node:stream"; import type { Request, Response } from "express"; import { afterEach, describe, expect, test } from "vitest"; import { initRequestLogger } from "../middleware/requestLogger"; +import type { Uuid } from "../types"; class MockResponse extends EventEmitter { err?: Error; @@ -86,7 +87,13 @@ describe("initRequestLogger", () => { originalUrl: "/api/login/anonymous?token=secret", path: "/login/anonymous", url: "/login/anonymous?token=secret", - user: { isAnonymous: true } as Request["user"], + user: { + email: null, + firstNames: null, + isAnonymous: true, + lastNames: "", + userId: "test-user-id-1" as unknown as Uuid, + } as Request["user"], }); const mockResponse = new MockResponse(); const res = mockResponse as unknown as Response; @@ -105,6 +112,7 @@ describe("initRequestLogger", () => { event: "request_start", method: "POST", path: "/api/login/anonymous", + userId: "test-user-id-1", }); expect(endLog).toMatchObject({ anonymous: true, @@ -115,6 +123,7 @@ describe("initRequestLogger", () => { msg: "200 POST /api/login/anonymous", path: "/api/login/anonymous", statusCode: 200, + userId: "test-user-id-1", }); }); From 6e281b50ca708998037e7a4033f1da3a9babeb6f Mon Sep 17 00:00:00 2001 From: Charles Nykamp Date: Thu, 30 Apr 2026 12:04:45 -0500 Subject: [PATCH 07/11] remove sensitive or noisy headers --- apps/api/src/logging/loggerConfig.ts | 15 ++++ apps/api/src/middleware/requestLogger.ts | 107 ++++++++++++++++++++++- apps/api/src/test/requestLogger.test.ts | 85 ++++++++++++++++-- 3 files changed, 201 insertions(+), 6 deletions(-) diff --git a/apps/api/src/logging/loggerConfig.ts b/apps/api/src/logging/loggerConfig.ts index b183605eb6..8cac2c3018 100644 --- a/apps/api/src/logging/loggerConfig.ts +++ b/apps/api/src/logging/loggerConfig.ts @@ -12,6 +12,17 @@ export type LoggerConfigOptions = { stream?: NodeJS.WritableStream; }; +const sensitiveHeaderPaths = [ + "req.headers.cookie", + "req.headers.authorization", + 'req.headers["proxy-authorization"]', + 'req.headers["x-api-key"]', + 'req.headers["x-auth-token"]', + 'req.headers["x-csrf-token"]', + 'req.headers["csrf-token"]', + 'res.headers["set-cookie"]', +]; + /** * Shared pino configuration for logs */ @@ -20,6 +31,10 @@ export function getApiLoggerOptions(options: LoggerConfigOptions = {}) { return { level: logLevel, + redact: { + paths: sensitiveHeaderPaths, + remove: true, + }, stream: options.stream, ...(shouldUsePrettyLogs(options) ? getPrettyTransportOptions(logLevel, options.prettyIgnore) diff --git a/apps/api/src/middleware/requestLogger.ts b/apps/api/src/middleware/requestLogger.ts index 2af9f5a2c9..fb193ea4a2 100644 --- a/apps/api/src/middleware/requestLogger.ts +++ b/apps/api/src/middleware/requestLogger.ts @@ -5,14 +5,34 @@ import { type LoggerConfigOptions, type LogLevel, } from "../logging/loggerConfig"; +import { fromUUID } from "../utils/uuid"; type LoggableObject = Record; +type SerializedRequest = { + headers?: Record; +} & Record; type RequestWithLogger = Request & { log: { debug: (object: Record, message: string) => void; }; }; +const noisyRequestHeaders = new Set([ + "accept", + "accept-encoding", + "accept-language", + "connection", + "dnt", + "sec-ch-ua", + "sec-ch-ua-mobile", + "sec-ch-ua-platform", + "sec-fetch-dest", + "sec-fetch-mode", + "sec-fetch-site", + "sec-gpc", + "user-agent", +]); + /** * Initialize the pino-http middleware for logging API requests. * @@ -50,6 +70,9 @@ export function initRequestLogger(options: LoggerConfigOptions = {}) { return getRequestCompletionLogLevel(res, err); }, quietReqLogger: true, + serializers: { + req: sanitizeSerializedRequest, + }, }); return (req: Request, res: Response, next: NextFunction) => { @@ -63,12 +86,15 @@ export function initRequestLogger(options: LoggerConfigOptions = {}) { * Pulls the safe request fields that we want to include in every lifecycle log. */ function getRequestMetadata(req: Request) { + const userId = getLoggedUserId(req); + return { anonymous: req.user?.isAnonymous ?? false, authenticated: req.user !== undefined, method: req.method, + route: getRequestRoute(req) ?? getRequestPath(req), path: getRequestPath(req), - ...(req.user?.userId ? { userId: req.user.userId } : {}), + ...(userId ? { userId } : {}), }; } @@ -86,6 +112,26 @@ function getRequestPath(req: Request) { return (req.originalUrl || req.url).split("?")[0]; } +function getRequestRoute(req: Request) { + if (!req.route) { + return undefined; + } + + const routePath = req.route.path; + if (typeof routePath === "string") { + return `${req.baseUrl}${routePath}`; + } + + if (Array.isArray(routePath)) { + return routePath + .filter((path): path is string => typeof path === "string") + .map((path) => `${req.baseUrl}${path}`) + .join("|"); + } + + return undefined; +} + function getRequestStartMessage(req: Request) { return `START: ${req.method} ${getRequestPath(req)}`; } @@ -120,6 +166,65 @@ function getRequestPrettyIgnore() { ]; } +function sanitizeSerializedRequest(req: SerializedRequest) { + const { + params: _params, + query: _query, + remotePort: _remotePort, + ...rest + } = req; + + return { + ...rest, + ...(req.headers ? { headers: sanitizeRequestHeaders(req.headers) } : {}), + }; +} + +function sanitizeRequestHeaders(headers: Record) { + const sanitizedHeaders: Record = {}; + + for (const [headerName, value] of Object.entries(headers)) { + if (noisyRequestHeaders.has(headerName)) { + continue; + } + + if (headerName === "referer") { + const refererOrigin = getRefererOrigin(value); + + if (refererOrigin) { + sanitizedHeaders.referer = refererOrigin; + } + continue; + } + + sanitizedHeaders[headerName] = value; + } + + return sanitizedHeaders; +} + +function getRefererOrigin(referer: string) { + if (!URL.canParse(referer)) { + return undefined; + } + + return new URL(referer).origin; +} + +function getLoggedUserId(req: Request) { + const userId = req.user?.userId; + + if (typeof userId === "string") { + return userId; + } + + if (userId instanceof Uint8Array) { + return fromUUID(userId); + } + + return undefined; +} + function logRequestStart(req: Request) { (req as RequestWithLogger).log.debug( { diff --git a/apps/api/src/test/requestLogger.test.ts b/apps/api/src/test/requestLogger.test.ts index f4365fb325..3dc59c045e 100644 --- a/apps/api/src/test/requestLogger.test.ts +++ b/apps/api/src/test/requestLogger.test.ts @@ -3,12 +3,18 @@ import { Writable } from "node:stream"; import type { Request, Response } from "express"; import { afterEach, describe, expect, test } from "vitest"; import { initRequestLogger } from "../middleware/requestLogger"; -import type { Uuid } from "../types"; +import { fromUUID, newUUID } from "../utils/uuid"; class MockResponse extends EventEmitter { err?: Error; + headers: Record = {}; + headersSent = true; statusCode = 200; writableEnded = false; + + getHeaders() { + return this.headers; + } } const originalLogLevel = process.env.LOG_LEVEL; @@ -72,6 +78,7 @@ describe("initRequestLogger", () => { event: "request_end", level: 30, msg: "204 GET /api/health", + route: "/api/health", statusCode: 204, }); expect(endLog.durationMs).toBeGreaterThanOrEqual(0); @@ -82,6 +89,7 @@ describe("initRequestLogger", () => { const { lines, stream } = createLogCapture(); const middleware = initRequestLogger({ stream }); + const userId = newUUID(); const req = createMockRequest({ method: "POST", originalUrl: "/api/login/anonymous?token=secret", @@ -92,8 +100,8 @@ describe("initRequestLogger", () => { firstNames: null, isAnonymous: true, lastNames: "", - userId: "test-user-id-1" as unknown as Uuid, - } as Request["user"], + userId, + } as unknown as Request["user"], }); const mockResponse = new MockResponse(); const res = mockResponse as unknown as Response; @@ -112,7 +120,8 @@ describe("initRequestLogger", () => { event: "request_start", method: "POST", path: "/api/login/anonymous", - userId: "test-user-id-1", + route: "/api/login/anonymous", + userId: fromUUID(userId), }); expect(endLog).toMatchObject({ anonymous: true, @@ -122,8 +131,9 @@ describe("initRequestLogger", () => { method: "POST", msg: "200 POST /api/login/anonymous", path: "/api/login/anonymous", + route: "/api/login/anonymous", statusCode: 200, - userId: "test-user-id-1", + userId: fromUUID(userId), }); }); @@ -142,6 +152,11 @@ describe("initRequestLogger", () => { middleware(req, res, () => {}); + Object.assign(req, { + baseUrl: "/api/content", + path: "/not-found", + route: { path: "/:contentId" } as Request["route"], + }); mockResponse.statusCode = 404; mockResponse.writableEnded = true; mockResponse.emit("finish"); @@ -153,6 +168,7 @@ describe("initRequestLogger", () => { event: "request_end", level: 40, msg: "404 GET /api/content/not-found", + route: "/api/content/:contentId", path: "/api/content/not-found", statusCode: 404, }); @@ -188,4 +204,63 @@ describe("initRequestLogger", () => { statusCode: 500, }); }); + + test("sanitizes request headers and redacts sensitive ones", () => { + delete process.env.LOG_LEVEL; + + const { lines, stream } = createLogCapture(); + const middleware = initRequestLogger({ stream }); + const req = createMockRequest({ + headers: { + accept: "application/json", + "accept-encoding": "gzip, br", + authorization: "Bearer secret-token", + connection: "close", + cookie: "session=top-secret", + referer: "http://localhost:8000/library?token=secret", + "sec-fetch-mode": "cors", + "user-agent": "Mozilla/5.0", + "x-api-key": "key-123", + }, + params: { ownerId: "abc123" }, + query: { parentId: "folder1" }, + // pino-http request serializer includes remotePort + socket: { + remoteAddress: "::1", + remotePort: 62051, + } as Request["socket"], + }); + const mockResponse = new MockResponse(); + mockResponse.headers = { + "content-type": "application/json", + "set-cookie": ["session=top-secret"], + }; + const res = mockResponse as unknown as Response; + + middleware(req, res, () => {}); + + mockResponse.writableEnded = true; + mockResponse.emit("finish"); + + const [endLog] = parseLogs(lines); + + expect(endLog.req.headers).toMatchObject({ + referer: "http://localhost:8000", + }); + expect(endLog.req).toMatchObject({ + remoteAddress: "::1", + }); + expect(endLog.req).not.toHaveProperty("params"); + expect(endLog.req).not.toHaveProperty("query"); + expect(endLog.req).not.toHaveProperty("remotePort"); + expect(endLog.req.headers).not.toHaveProperty("accept"); + expect(endLog.req.headers).not.toHaveProperty("accept-encoding"); + expect(endLog.req.headers).not.toHaveProperty("authorization"); + expect(endLog.req.headers).not.toHaveProperty("connection"); + expect(endLog.req.headers).not.toHaveProperty("cookie"); + expect(endLog.req.headers).not.toHaveProperty("sec-fetch-mode"); + expect(endLog.req.headers).not.toHaveProperty("user-agent"); + expect(endLog.req.headers).not.toHaveProperty("x-api-key"); + expect(endLog.res?.headers?.["set-cookie"]).toBeUndefined(); + }); }); From 4b1519d880e2118396a726f7a5fb0f4751021955 Mon Sep 17 00:00:00 2001 From: Charles Nykamp Date: Thu, 30 Apr 2026 12:37:15 -0500 Subject: [PATCH 08/11] less noisy `npm run dev` --- package.json | 2 +- scripts/dev.js | 76 ++++++++++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 77 insertions(+), 1 deletion(-) create mode 100644 scripts/dev.js diff --git a/package.json b/package.json index 3478214c61..c9ce98d5a9 100644 --- a/package.json +++ b/package.json @@ -13,7 +13,7 @@ "postinstall": "npm run prisma:generate --workspace @doenet-tools/api", "setup": "node scripts/setup.js", "db:setup": "npm run prisma:migrate-dev --workspace @doenet-tools/api && npm run prisma:seed --workspace @doenet-tools/api", - "dev": "npm run build --workspace @doenet-tools/shared && concurrently --names \"API,APP,WEB\" --prefix-colors \"auto\" \"npm run dev --workspace @doenet-tools/api\" \"npm run dev --workspace @doenet-tools/app\" \"npm run dev --workspace @doenet-tools/web\"", + "dev": "npm run build --workspace @doenet-tools/shared && node scripts/dev.js", "format": "prettier . --write", "format:check": "prettier . --check", "lint": "npm run lint --workspaces --if-present", diff --git a/scripts/dev.js b/scripts/dev.js new file mode 100644 index 0000000000..4b36be87de --- /dev/null +++ b/scripts/dev.js @@ -0,0 +1,76 @@ +/* + * This wrapper exists so the root `npm run dev` command can orchestrate the app, + * api, and web dev servers with a bit of custom behavior. It starts each workspace + * through the npm CLI, keeps the usual prefixed output from `concurrently`, and + * makes Ctrl+C shutdown less noisy without hiding real failures. + */ +/* global process */ +import concurrently, { Logger } from "concurrently"; +import path from "path"; + +const npmExecPath = process.env.npm_execpath; + +if (!npmExecPath) { + throw new Error( + "npm_execpath is not set. Run this script through `npm run dev`.", + ); +} + +function quoteCliArgument(argument) { + return JSON.stringify(argument); +} + +let interrupted = false; + +for (const signal of ["SIGINT", "SIGTERM"]) { + process.on(signal, () => { + interrupted = true; + }); +} + +class DevLogger extends Logger { + logCommandEvent(text, command) { + if ( + interrupted && + / exited with code (1|null|SIGINT|SIGTERM)$/.test(text) + ) { + return; + } + + super.logCommandEvent(text, command); + } +} + +const npmRunDevCommand = `${quoteCliArgument(process.execPath)} ${quoteCliArgument(npmExecPath)} run dev`; +const root = path.join(import.meta.dirname, ".."); + +const { result } = concurrently( + [ + { + command: npmRunDevCommand, + cwd: path.join(root, "apps", "api"), + name: "API", + }, + { + command: npmRunDevCommand, + cwd: path.join(root, "apps", "app"), + name: "APP", + }, + { + command: npmRunDevCommand, + cwd: path.join(root, "apps", "web"), + name: "WEB", + }, + ], + { + logger: new DevLogger({ prefixFormat: "name" }), + prefix: "name", + prefixColors: "auto", + }, +); + +try { + await result; +} catch { + process.exitCode = interrupted ? 0 : 1; +} From 49edc2a0aed038f834f22d9e5b318f17f1050945 Mon Sep 17 00:00:00 2001 From: Charles Nykamp Date: Thu, 30 Apr 2026 15:10:12 -0500 Subject: [PATCH 09/11] update pretty logging --- apps/api/src/logging/loggerConfig.ts | 1 + apps/api/src/middleware/requestLogger.ts | 43 +++++++++++++----------- apps/api/src/test/requestLogger.test.ts | 16 ++++++--- 3 files changed, 37 insertions(+), 23 deletions(-) diff --git a/apps/api/src/logging/loggerConfig.ts b/apps/api/src/logging/loggerConfig.ts index 8cac2c3018..1ee7be60d8 100644 --- a/apps/api/src/logging/loggerConfig.ts +++ b/apps/api/src/logging/loggerConfig.ts @@ -81,6 +81,7 @@ function getPrettyTransportOptions( colorize: true, hideObject: true, messageFormat: "{msg}", + timestampKey: "__pretty_timestamp_disabled__", translateTime: "SYS:standard", ...(logLevel === "silent" ? {} : { minimumLevel: logLevel }), ...(prettyIgnore?.length ? { ignore: prettyIgnore.join(",") } : {}), diff --git a/apps/api/src/middleware/requestLogger.ts b/apps/api/src/middleware/requestLogger.ts index fb193ea4a2..a1909e2724 100644 --- a/apps/api/src/middleware/requestLogger.ts +++ b/apps/api/src/middleware/requestLogger.ts @@ -47,9 +47,16 @@ export function initRequestLogger(options: LoggerConfigOptions = {}) { const httpLogger = pinoHttp({ ...getApiLoggerOptions({ ...options, - prettyIgnore: getRequestPrettyIgnore(), + prettyIgnore: ["pid", "hostname"], }), - customErrorMessage: getRequestCompletionMessage, + customErrorMessage( + req: Request, + res: Response, + _err: Error, + responseTime?: number, + ) { + return getRequestCompletionMessage(req, res, responseTime); + }, customErrorObject( req: Request, res: Response, @@ -58,7 +65,9 @@ export function initRequestLogger(options: LoggerConfigOptions = {}) { ) { return getRequestCompletionObject(req, res, loggableObject); }, - customSuccessMessage: getRequestCompletionMessage, + customSuccessMessage(req: Request, res: Response, responseTime?: number) { + return getRequestCompletionMessage(req, res, responseTime); + }, customSuccessObject( req: Request, res: Response, @@ -136,8 +145,18 @@ function getRequestStartMessage(req: Request) { return `START: ${req.method} ${getRequestPath(req)}`; } -function getRequestCompletionMessage(req: Request, res: Response) { - return `${res.statusCode} ${req.method} ${getRequestPath(req)}`; +function getRequestCompletionMessage( + req: Request, + res: Response, + responseTime?: number, +) { + const baseMessage = `${res.statusCode} ${req.method} ${getRequestPath(req)}`; + + if (responseTime === undefined) { + return baseMessage; + } + + return `${baseMessage} (${Math.round(responseTime)}ms)`; } function getRequestCompletionLogLevel(res: Response, err?: Error): LogLevel { @@ -152,20 +171,6 @@ function getRequestCompletionLogLevel(res: Response, err?: Error): LogLevel { return "info"; } -function getRequestPrettyIgnore() { - return [ - "pid", - "hostname", - "event", - "method", - "path", - "statusCode", - "durationMs", - "authenticated", - "anonymous", - ]; -} - function sanitizeSerializedRequest(req: SerializedRequest) { const { params: _params, diff --git a/apps/api/src/test/requestLogger.test.ts b/apps/api/src/test/requestLogger.test.ts index 3dc59c045e..f49dfbea11 100644 --- a/apps/api/src/test/requestLogger.test.ts +++ b/apps/api/src/test/requestLogger.test.ts @@ -77,11 +77,13 @@ describe("initRequestLogger", () => { expect(endLog).toMatchObject({ event: "request_end", level: 30, - msg: "204 GET /api/health", route: "/api/health", statusCode: 204, }); expect(endLog.durationMs).toBeGreaterThanOrEqual(0); + expect(endLog.msg).toBe( + `204 GET /api/health (${Math.round(endLog.durationMs)}ms)`, + ); }); test("emits the request start log when LOG_LEVEL=debug", () => { @@ -129,12 +131,14 @@ describe("initRequestLogger", () => { event: "request_end", level: 30, method: "POST", - msg: "200 POST /api/login/anonymous", path: "/api/login/anonymous", route: "/api/login/anonymous", statusCode: 200, userId: fromUUID(userId), }); + expect(endLog.msg).toBe( + `200 POST /api/login/anonymous (${Math.round(endLog.durationMs)}ms)`, + ); }); test("logs 4xx responses at warn", () => { @@ -167,11 +171,13 @@ describe("initRequestLogger", () => { expect(endLog).toMatchObject({ event: "request_end", level: 40, - msg: "404 GET /api/content/not-found", route: "/api/content/:contentId", path: "/api/content/not-found", statusCode: 404, }); + expect(endLog.msg).toBe( + `404 GET /api/content/not-found (${Math.round(endLog.durationMs)}ms)`, + ); }); test("uses a failure-specific completion message for errored requests", () => { @@ -199,10 +205,12 @@ describe("initRequestLogger", () => { expect(endLog).toMatchObject({ event: "request_end", level: 50, - msg: "500 GET /api/login/magic", path: "/api/login/magic", statusCode: 500, }); + expect(endLog.msg).toBe( + `500 GET /api/login/magic (${Math.round(endLog.durationMs)}ms)`, + ); }); test("sanitizes request headers and redacts sensitive ones", () => { From 95a07ec69aedcd89a5ef2678a1148912a0d08dbb Mon Sep 17 00:00:00 2001 From: Charles Nykamp Date: Thu, 30 Apr 2026 15:23:48 -0500 Subject: [PATCH 10/11] update env vars for prod and dev3 --- apps/api/.env.example | 18 ++++++++++++++++-- .../dev3-doenet-taskdef-includes.yml | 4 ++++ .../prod-doenet-taskdef-includes.yml | 4 ++++ 3 files changed, 24 insertions(+), 2 deletions(-) diff --git a/apps/api/.env.example b/apps/api/.env.example index b92aeabb51..1b759e5c5b 100644 --- a/apps/api/.env.example +++ b/apps/api/.env.example @@ -1,7 +1,20 @@ +# ________________________________________________________ +# +# This is an example .env setup for local development. +# You can copy this to `.env` and edit values as needed. +# _________________________________________________________ +# +# To edit values for the production site, see +# `/infra/cloudformation/prod-doenet-taskdef-includes.yml` +# +# To edit values for deployed dev site (dev3), see +# `/infra/cloudformation/dev3-doenet-taskdef-includes.yml` + + + #General PORT="3000" -# Base URL of the frontend app -APP_URL="http://localhost:8000" +APP_URL="http://localhost:8000" # Base URL of the frontend app LOG_LEVEL="info" #Flags @@ -9,6 +22,7 @@ LOG_LEVEL="info" ENABLE_TEST_AUTH_BYPASS="true" ENABLE_TEST_ROUTES="true" MOCK_SIGNIN_EMAIL="true" +PRETTY_LOGS="true" #Database # DATABASE_URL must match the individual vars below. Update both if you change any connection details. diff --git a/infra/cloudformation/dev3-doenet-taskdef-includes.yml b/infra/cloudformation/dev3-doenet-taskdef-includes.yml index ecdb49d498..0cb4d99b8e 100644 --- a/infra/cloudformation/dev3-doenet-taskdef-includes.yml +++ b/infra/cloudformation/dev3-doenet-taskdef-includes.yml @@ -3,6 +3,8 @@ Environment: Value: 3000 - Name: APP_URL Value: "https://dev3.doenet.org" + - Name: LOG_LEVEL + Value: "info" - Name: DATABASE_PORT Value: 3306 - Name: DATABASE_NAME @@ -19,6 +21,8 @@ Environment: Value: "false" - Name: MOCK_SIGNIN_EMAIL Value: "false" + - Name: PRETTY_LOGS + Value: "false" - Name: NODE_OPTIONS Value: "--max-old-space-size=1950" # - Name: DISCOURSE_API_USERNAME diff --git a/infra/cloudformation/prod-doenet-taskdef-includes.yml b/infra/cloudformation/prod-doenet-taskdef-includes.yml index 6930f5d2ba..a17dd4955c 100644 --- a/infra/cloudformation/prod-doenet-taskdef-includes.yml +++ b/infra/cloudformation/prod-doenet-taskdef-includes.yml @@ -3,6 +3,8 @@ Environment: Value: 3000 - Name: APP_URL Value: "https://beta.doenet.org" + - Name: LOG_LEVEL + Value: "info" - Name: DATABASE_PORT Value: 3306 - Name: DATABASE_NAME @@ -19,6 +21,8 @@ Environment: Value: "false" - Name: MOCK_SIGNIN_EMAIL Value: "false" + - Name: PRETTY_LOGS + Value: "false" - Name: NODE_OPTIONS Value: "--max-old-space-size=1950" - Name: DISCOURSE_API_USERNAME From fb6e4ab963c67cb4d387314b2d8664f97b056036 Mon Sep 17 00:00:00 2001 From: Charles Nykamp Date: Fri, 1 May 2026 09:00:27 -0500 Subject: [PATCH 11/11] use pretty flag explicitly --- apps/api/src/logging/loggerConfig.ts | 5 +-- apps/api/src/test/loggerConfig.test.ts | 50 ++++++++++++++++++++++++++ 2 files changed, 51 insertions(+), 4 deletions(-) create mode 100644 apps/api/src/test/loggerConfig.test.ts diff --git a/apps/api/src/logging/loggerConfig.ts b/apps/api/src/logging/loggerConfig.ts index 1ee7be60d8..0778d54508 100644 --- a/apps/api/src/logging/loggerConfig.ts +++ b/apps/api/src/logging/loggerConfig.ts @@ -64,10 +64,7 @@ function shouldUsePrettyLogs(options: LoggerConfigOptions) { return false; } - return ( - process.env.NODE_ENV === "development" || - process.env.npm_lifecycle_event === "dev" - ); + return process.env.PRETTY_LOGS?.trim().toLowerCase() === "true"; } function getPrettyTransportOptions( diff --git a/apps/api/src/test/loggerConfig.test.ts b/apps/api/src/test/loggerConfig.test.ts new file mode 100644 index 0000000000..fb200fe28b --- /dev/null +++ b/apps/api/src/test/loggerConfig.test.ts @@ -0,0 +1,50 @@ +import { afterEach, describe, expect, test } from "vitest"; +import { getApiLoggerOptions } from "../logging/loggerConfig"; + +const originalPrettyLogs = process.env.PRETTY_LOGS; + +describe("getApiLoggerOptions", () => { + afterEach(() => { + if (originalPrettyLogs === undefined) { + delete process.env.PRETTY_LOGS; + return; + } + + process.env.PRETTY_LOGS = originalPrettyLogs; + }); + + test("does not enable pretty logs by default", () => { + delete process.env.PRETTY_LOGS; + + const loggerOptions = getApiLoggerOptions(); + + expect(loggerOptions.transport).toBeUndefined(); + }); + + test("enables pretty logs only when PRETTY_LOGS=true", () => { + process.env.PRETTY_LOGS = "true"; + + const loggerOptions = getApiLoggerOptions({ + prettyIgnore: ["pid", "hostname"], + }); + + expect(loggerOptions.transport).toMatchObject({ + options: { + hideObject: true, + ignore: "pid,hostname", + messageFormat: "{msg}", + }, + target: "pino-pretty", + }); + }); + + test("keeps pretty logs disabled when a custom stream is provided", () => { + process.env.PRETTY_LOGS = "true"; + + const loggerOptions = getApiLoggerOptions({ + stream: process.stdout, + }); + + expect(loggerOptions.transport).toBeUndefined(); + }); +});