diff --git a/apps/api/src/app.ts b/apps/api/src/app.ts index b57a5ad..4a5c86d 100644 --- a/apps/api/src/app.ts +++ b/apps/api/src/app.ts @@ -1,8 +1,10 @@ import { errorHandlerService } from "@batch-cooking/error-tools"; -import { ExpressServer, createErrorMiddleware } from "@batch-cooking/express-tools"; +import { createErrorMiddleware, ExpressServer } from "@batch-cooking/express-tools"; import { ErrorCode } from "@batch-cooking/shared"; import type { Express, Request, Response } from "express"; import { env } from "./config/env.js"; +import { errorLogger } from "./middlewares/error-logger.js"; +import { requestLogger } from "./middlewares/request-logger.js"; import { authRouter } from "./modules/auth/auth.routes.js"; import { houseRouter } from "./modules/house/house.routes.js"; import { planningRouter } from "./modules/planning/planning.routes.js"; @@ -22,6 +24,12 @@ import { sourcesRouter } from "./modules/sources/sources.routes.js"; */ export function createServer(): ExpressServer { const server = new ExpressServer(); + // First middleware registered, before even setupCore's own (CORS/JSON + // body parsing/cookies) — it only reads `req`/`res`, so it doesn't need + // to run after them, and mounting it first means it wraps the *whole* + // pipeline (its "finish" listener still fires for a request that never + // makes it past CORS/body-parsing, not just ones that reach a route). + server.addMiddleware(requestLogger); server.setupCore({ corsOrigin: env.CORS_ORIGIN }); server.addRoute("get", "/health", (_req: Request, res: Response) => { @@ -52,10 +60,12 @@ export function createServer(): ExpressServer { res.status(404).json({ code: ErrorCode.NOT_FOUND, message: "Not found" }); }); - // Final error-handling middleware: every thrown/`next(err)`-ed error in - // the app ends up here. All the "what status/body does this error map - // to" logic lives in ErrorHandlerService, from @batch-cooking/error-tools - // — this stays a thin adapter. + // Two error-handling middlewares in a row (Express runs them in + // registration order, same as regular middleware) — errorLogger logs the + // error, then hands it on (`next(err)`) to the real one: all the "what + // status/body does this error map to" logic lives in ErrorHandlerService, + // from @batch-cooking/error-tools — this stays a thin adapter. + server.setErrorHandler(errorLogger); server.setErrorHandler(createErrorMiddleware(errorHandlerService)); return server; diff --git a/apps/api/src/lib/logger.service.ts b/apps/api/src/lib/logger.service.ts new file mode 100644 index 0000000..a8685ae --- /dev/null +++ b/apps/api/src/lib/logger.service.ts @@ -0,0 +1,102 @@ +import { env } from "../config/env.js"; + +/** + * Server-side operational logging — the one place in this codebase allowed + * to call `console.*` directly (see `biome.json`'s `noConsole`, which bans + * bare `console.log` everywhere else: every log line here goes through a + * named level instead, `logger.info(...)`/`logger.error(...)`, never an + * unlabeled dump of text). Everything else (the request logger, `server.ts`'s + * startup line, the error middleware) goes through this instead of touching + * `console` itself, so there's exactly one place that decides the log + * *shape* (structured JSON lines — one object per line, trivially + * grep/parse-able by `docker logs`/Portainer or any log aggregator, unlike + * free-form `console.log` text). + * + * A class, not a plain object literal — same convention as + * `ErrorHandlerService` (`packages/error-tools`): `public` methods are the + * actual API, `private` ones are internals a caller never touches directly. + * `export const logger = new LoggerService()` below is the single shared + * instance every caller imports — there's exactly one log stream for the + * whole process, nothing to parameterize per call site, so nobody + * constructs their own. + */ + +/** Ascending severity — mirrors the standard `debug < info < warn < error` convention. */ +export type LogLevel = "debug" | "info" | "warn" | "error"; + +/** Arbitrary structured context attached to a log line (a request id, a duration, an error's own fields, …) — merged into the emitted JSON object, never interpolated into the message string itself. */ +export type LogMeta = Record; + +const LEVEL_SEVERITY: Record = { + debug: 0, + info: 1, + warn: 2, + error: 3, +}; + +/** + * Lines below this level are dropped rather than emitted — keeps `debug` + * out of production (verbose, meant for local troubleshooting only) and + * out of the test suite's own output (Mocha's reporter is noisy enough + * already), while `pnpm dev:api` sees everything. A free function, not a + * method — exported (unlike the rest of this module's internals) purely so + * `logger.service.test.ts` can exercise the three `NODE_ENV` cases + * directly, without needing a `LoggerService` instance at all. + */ +export function minLevelFor(nodeEnv: typeof env.NODE_ENV): LogLevel { + if (nodeEnv === "production") return "info"; + if (nodeEnv === "test") return "warn"; + return "debug"; +} + +/** Console method each level writes through — `error`/`warn` go to stderr (their own native behavior), `debug`/`info` to stdout, the usual split log aggregators expect. */ +const CONSOLE_METHOD: Record = { + debug: "debug", + info: "info", + warn: "warn", + error: "error", +}; + +/** Server-side operational logger — see the module doc comment for why this exists and what it's for. */ +export class LoggerService { + /** Computed once at construction from `env.NODE_ENV` — see {@link minLevelFor}. */ + private readonly minSeverity: number; + + public constructor(nodeEnv: typeof env.NODE_ENV = env.NODE_ENV) { + this.minSeverity = LEVEL_SEVERITY[minLevelFor(nodeEnv)]; + } + + public debug(message: string, meta?: LogMeta): void { + this.emit("debug", message, meta); + } + + public info(message: string, meta?: LogMeta): void { + this.emit("info", message, meta); + } + + public warn(message: string, meta?: LogMeta): void { + this.emit("warn", message, meta); + } + + public error(message: string, meta?: LogMeta): void { + this.emit("error", message, meta); + } + + private emit(level: LogLevel, message: string, meta?: LogMeta): void { + if (LEVEL_SEVERITY[level] < this.minSeverity) return; + + // `meta` spread first so a caller accidentally passing e.g. `{ message: + // ... }` in it can never shadow the line's own core fields. + const line = { + ...meta, + timestamp: new Date().toISOString(), + level, + message, + }; + // biome-ignore lint/suspicious/noConsole: this is the one place allowed to — see the class doc comment above. + console[CONSOLE_METHOD[level]](JSON.stringify(line)); + } +} + +/** Single shared instance — this service has no per-call-site state to isolate, same reasoning as `errorHandlerService`. */ +export const logger = new LoggerService(); diff --git a/apps/api/src/middlewares/error-logger.ts b/apps/api/src/middlewares/error-logger.ts new file mode 100644 index 0000000..9764008 --- /dev/null +++ b/apps/api/src/middlewares/error-logger.ts @@ -0,0 +1,40 @@ +import { errorHandlerService } from "@batch-cooking/error-tools"; +import type { NextFunction, Request, Response } from "express"; +import { logger } from "../lib/logger.service.js"; + +/** + * Logs every error that reaches Express's error-handling chain, then + * passes it straight on (`next(err)`) to the real error-to-response + * middleware (`createErrorMiddleware`, `@batch-cooking/express-tools`) — + * mounted immediately after this one in `app.ts`. Reuses + * `errorHandlerService.handle()` (`@batch-cooking/error-tools`) just to + * classify the error for logging purposes (its `status`/`body.code`) — + * `.handle()` is pure/stateless, so calling it here and then again in + * `createErrorMiddleware` right after is harmless, and it's the one place + * that already knows a bare `ZodError` maps to `400 VALIDATION_ERROR`, an + * `HttpError` maps to its own `status`/`code`, and anything else is a + * `500`. Doesn't build the actual response itself — that's still + * `createErrorMiddleware`'s job. + * + * A resulting `4xx` is routine, expected operation (a validation failure, + * a 404, an unauthenticated request) — logged at `warn`, not `error`, so a + * genuine `5xx` (an unhandled exception, a bug) stands out instead of + * being buried under normal client mistakes. + */ +export function errorLogger(err: unknown, req: Request, _res: Response, next: NextFunction): void { + const meta = { method: req.method, path: req.originalUrl }; + const { status, body } = errorHandlerService.handle(err); + + if (status >= 500) { + logger.error(err instanceof Error ? err.message : body.message, { + ...meta, + status, + code: body.code, + stack: err instanceof Error ? err.stack : undefined, + }); + } else { + logger.warn(body.message, { ...meta, status, code: body.code }); + } + + next(err); +} diff --git a/apps/api/src/middlewares/request-logger.ts b/apps/api/src/middlewares/request-logger.ts new file mode 100644 index 0000000..bb3c49e --- /dev/null +++ b/apps/api/src/middlewares/request-logger.ts @@ -0,0 +1,45 @@ +import type { NextFunction, Request, Response } from "express"; +import { logger } from "../lib/logger.service.js"; + +/** + * Logs one line per request once it finishes — method, path, status code, + * and duration. Mounted first in `app.ts` (before every route, and before + * the error handler) so it wraps the whole request/response cycle, + * including requests that end in a 404 or an error response. + * + * Listens on `res`'s `"finish"` event rather than wrapping `next()` in a + * `try`/`finally`: this middleware calls `next()` immediately and returns, + * so it never itself sits on the stack waiting for the rest of the + * pipeline to resolve — `"finish"` fires once Express has actually flushed + * the response, whichever handler (or the error middleware) produced it. + * + * `4xx`/`5xx` responses log at `warn`/`error` respectively (status alone + * decides the level — this middleware has no idea *why* a request failed, + * just that it did); everything else logs at `info`. A route's own + * handler/the error middleware may log more detail about *why* separately + * (see `error-middleware` wiring in `app.ts`) — this line is just the + * "a request happened, here's the outcome" operational trace. + */ +export function requestLogger(req: Request, res: Response, next: NextFunction): void { + const startedAt = process.hrtime.bigint(); + + res.on("finish", () => { + const durationMs = Number(process.hrtime.bigint() - startedAt) / 1_000_000; + const meta = { + method: req.method, + path: req.originalUrl, + status: res.statusCode, + durationMs: Math.round(durationMs * 100) / 100, + }; + + if (res.statusCode >= 500) { + logger.error("Request completed", meta); + } else if (res.statusCode >= 400) { + logger.warn("Request completed", meta); + } else { + logger.info("Request completed", meta); + } + }); + + next(); +} diff --git a/apps/api/src/server.ts b/apps/api/src/server.ts index 388c3a8..85f2cf9 100644 --- a/apps/api/src/server.ts +++ b/apps/api/src/server.ts @@ -1,5 +1,6 @@ import { createServer } from "./app.js"; import { env } from "./config/env.js"; +import { logger } from "./lib/logger.service.js"; import { registerAllRecipeSources } from "./sources/index.js"; // Populates the recipe-source registry (recipe-source-registry.ts) before @@ -10,5 +11,5 @@ registerAllRecipeSources(); const server = createServer(); server.listen(env.PORT, () => { - console.log(`API listening on http://localhost:${env.PORT}`); + logger.info("API listening", { port: env.PORT, nodeEnv: env.NODE_ENV }); }); diff --git a/apps/api/test/logger.service.test.ts b/apps/api/test/logger.service.test.ts new file mode 100644 index 0000000..c5ed333 --- /dev/null +++ b/apps/api/test/logger.service.test.ts @@ -0,0 +1,105 @@ +import { expect } from "chai"; +import { LoggerService, logger, minLevelFor } from "../src/lib/logger.service.js"; + +/** + * Stubs one `console` method for one test, capturing every call instead of + * actually writing to stdout/stderr — same "stub the one thing that + * touches the outside world" approach `the-meal-db.test.ts` uses for + * `fetch`. Restored by the caller (`afterEach` below) regardless of which + * test used it. + */ +function stubConsoleMethod(method: "debug" | "info" | "warn" | "error") { + const calls: unknown[][] = []; + // biome-ignore lint/suspicious/noConsole: this *is* the console-stubbing helper — it has to read the real method to be able to restore it. Never calls it for real. + const original = console[method]; + console[method] = (...args: unknown[]) => { + calls.push(args); + }; + return { + calls, + restore: () => (console[method] = original), + }; +} + +describe("logger.service", () => { + describe("minLevelFor", () => { + it("only lets warn/error through in test — Mocha's own output shouldn't get any noisier", () => { + expect(minLevelFor("test")).to.equal("warn"); + }); + + it("only lets info/warn/error through in production — debug is too verbose to ship", () => { + expect(minLevelFor("production")).to.equal("info"); + }); + + it("lets everything through, including debug, in development", () => { + expect(minLevelFor("development")).to.equal("debug"); + }); + }); + + describe("logger", () => { + let stub: ReturnType; + + afterEach(() => { + stub?.restore(); + }); + + it("emits a warn line as a single JSON object via console.warn, with a timestamp/level/message and any extra meta merged in", () => { + stub = stubConsoleMethod("warn"); + + logger.warn("Something routine failed", { status: 404, code: 4049 }); + + expect(stub.calls).to.have.length(1); + const [line] = stub.calls[0]; + const parsed = JSON.parse(line as string); + expect(parsed.level).to.equal("warn"); + expect(parsed.message).to.equal("Something routine failed"); + expect(parsed.status).to.equal(404); + expect(parsed.code).to.equal(4049); + expect(new Date(parsed.timestamp).toString()).to.not.equal("Invalid Date"); + }); + + it("emits an error line via console.error", () => { + stub = stubConsoleMethod("error"); + + logger.error("Something broke"); + + expect(stub.calls).to.have.length(1); + const parsed = JSON.parse(stub.calls[0][0] as string); + expect(parsed.level).to.equal("error"); + }); + + it('drops debug/info under the test suite\'s own NODE_ENV=test (minLevelFor("test") === "warn")', () => { + const debugStub = stubConsoleMethod("debug"); + const infoStub = stubConsoleMethod("info"); + + logger.debug("Should not appear"); + logger.info("Should not appear either"); + + expect(debugStub.calls).to.have.length(0); + expect(infoStub.calls).to.have.length(0); + debugStub.restore(); + infoStub.restore(); + }); + + it("never lets meta override the line's own timestamp/level/message keys", () => { + stub = stubConsoleMethod("warn"); + + logger.warn("Real message", { message: "spoofed", level: "spoofed", timestamp: "spoofed" }); + + const parsed = JSON.parse(stub.calls[0][0] as string); + expect(parsed.message).to.equal("Real message"); + expect(parsed.level).to.equal("warn"); + expect(new Date(parsed.timestamp).toString()).to.not.equal("Invalid Date"); + }); + + it('a separate instance constructed with nodeEnv="development" lets debug through, independently of the shared logger\'s own NODE_ENV=test threshold', () => { + const debugStub = stubConsoleMethod("debug"); + const devLogger = new LoggerService("development"); + + devLogger.debug("Visible in dev"); + + expect(debugStub.calls).to.have.length(1); + debugStub.restore(); + }); + }); +}); diff --git a/packages/error-tools/src/error-handler.service.ts b/packages/error-tools/src/error-handler.service.ts index a4f0b6e..c04f403 100644 --- a/packages/error-tools/src/error-handler.service.ts +++ b/packages/error-tools/src/error-handler.service.ts @@ -60,11 +60,15 @@ export class ErrorHandlerService { } /** - * Anything unrecognized: logged server-side (so it's still diagnosable) - * but never leaks internal details to the client — always a generic 500. + * Anything unrecognized: never leaks internal details to the client — + * always a generic 500. Doesn't log the error itself — this class only + * maps an error to `{ status, body }` (see the class doc comment); a + * caller wanting this logged server-side does so on its own before/ + * around calling `handle()` (see `apps/api`'s `errorLogger` middleware, + * which sees every error — including this exact "unrecognized" case — + * before it ever reaches here). */ - private fromUnknownError(error: unknown): ErrorHandlingResult { - console.error(error); + private fromUnknownError(_error: unknown): ErrorHandlingResult { return { status: 500, body: { code: ErrorCode.INTERNAL_ERROR, message: "Internal server error" },