feat(api): ajoute un log service pour les logs de fonctionnement côté serveur
Jusqu'ici, rien ne journalisait quoi que ce soit côté serveur : aucune trace au démarrage à part un console.log ad hoc, et surtout aucune trace des requêtes ni des erreurs gérées par ErrorHandlerService — un 500 en production n'aurait laissé aucune trace exploitable. - LoggerService (apps/api/src/lib/logger.service.ts) — classe (public debug/info/warn/error, private emit), même convention que ErrorHandlerService (packages/error-tools) : instance unique partagée exportée (`export const logger = new LoggerService()`). Émet une ligne JSON structurée par appel (timestamp/level/message + meta), filtrée par seuil selon NODE_ENV (debug complet en dev, warn+ pendant les tests pour ne pas alourdir la sortie de Mocha, info+ en production). Seul endroit du code autorisé à toucher `console` directement (biome-ignore justifié), toujours via une méthode nommée — jamais un console.log nu. - requestLogger (middlewares/request-logger.ts) — une ligne par requête terminée (méthode/chemin/statut/durée), montée en tout premier dans app.ts, avant même setupCore (CORS/JSON/cookies), pour englober tout le pipeline. Niveau déduit du statut (info/warn/error). - errorLogger (middlewares/error-logger.ts) — monté juste avant createErrorMiddleware : réutilise errorHandlerService.handle() (pur/ sans effet de bord) pour classifier l'erreur avant que la vraie réponse ne soit construite, log en warn les 4xx routiniers (validation, 404, 401...) et en error les 5xx/exceptions non prévues (avec la stack). - error-handler.service.ts : retire le `console.error(error)` ad hoc de fromUnknownError — errorLogger voit désormais chaque erreur avant que ce service ne la mappe, donc ce console.error faisait doublon (et loggait en texte brut, pas en JSON structuré). - server.ts : le console.log de démarrage passe par logger.info. Vérifié : pnpm --filter api test (303/303, dont 8 nouveaux tests sur LoggerService), pnpm lint/build clean, testé en live (pnpm dev:api + curl) — logs JSON corrects pour un 200, un 404, un 401. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
This commit is contained in:
parent
37a044a267
commit
22582536a6
7 changed files with 317 additions and 10 deletions
|
|
@ -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;
|
||||
|
|
|
|||
102
apps/api/src/lib/logger.service.ts
Normal file
102
apps/api/src/lib/logger.service.ts
Normal file
|
|
@ -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<string, unknown>;
|
||||
|
||||
const LEVEL_SEVERITY: Record<LogLevel, number> = {
|
||||
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<LogLevel, "debug" | "info" | "warn" | "error"> = {
|
||||
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();
|
||||
40
apps/api/src/middlewares/error-logger.ts
Normal file
40
apps/api/src/middlewares/error-logger.ts
Normal file
|
|
@ -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);
|
||||
}
|
||||
45
apps/api/src/middlewares/request-logger.ts
Normal file
45
apps/api/src/middlewares/request-logger.ts
Normal file
|
|
@ -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();
|
||||
}
|
||||
|
|
@ -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 });
|
||||
});
|
||||
|
|
|
|||
105
apps/api/test/logger.service.test.ts
Normal file
105
apps/api/test/logger.service.test.ts
Normal file
|
|
@ -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<typeof stubConsoleMethod>;
|
||||
|
||||
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();
|
||||
});
|
||||
});
|
||||
});
|
||||
|
|
@ -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" },
|
||||
|
|
|
|||
Loading…
Reference in a new issue