diff --git a/compose.yaml b/compose.yaml index 2062cb7..d8d787e 100644 --- a/compose.yaml +++ b/compose.yaml @@ -11,7 +11,13 @@ services: environment: PORT: "3000" CHOKIDAR_USEPOLLING: "true" + LOG_LEVEL: "${LOG_LEVEL:-info}" init: true + logging: + driver: json-file + options: + max-size: "20m" + max-file: "10" ports: - "3000:3000" volumes: @@ -45,7 +51,13 @@ services: API_INTERNAL_URL: http://api:3000 WATCHPACK_POLLING: "true" NEXT_TELEMETRY_DISABLED: "1" + LOG_LEVEL: "${LOG_LEVEL:-info}" init: true + logging: + driver: json-file + options: + max-size: "20m" + max-file: "10" depends_on: api: condition: service_healthy diff --git a/docs/deployment.md b/docs/deployment.md index 44c7dd5..5458a69 100644 --- a/docs/deployment.md +++ b/docs/deployment.md @@ -26,10 +26,39 @@ Verwendete Umgebungsvariablen: - `NEXT_TELEMETRY_DISABLED=1` - `CHOKIDAR_USEPOLLING=true` und `WATCHPACK_POLLING=true` für lokale Dateibeobachtung in Docker +- `LOG_LEVEL` – steuert für beide Dienste die Ausgabestufe des strukturierten + JSON-Loggers (`error`, `warn`, `info`, `verbose`, `debug`), Standard `info`. + Setzbar über eine `.env`-Datei neben `compose.yaml` oder + `LOG_LEVEL=verbose docker compose up`. Beim API-Start laufen zuerst `npm run db:migrate` und `npm run db:verify:circuit-schema`. +## Logging + +Beide Dienste schreiben strukturierte, einzeilige JSON-Log-Zeilen nach +stdout/stderr (`docker compose logs --follow`). Jede Zeile enthält +`timestamp`, `level`, `scope` und `message`. `compose.yaml` konfiguriert für +beide Dienste den `json-file`-Treiber mit Rotation (`max-size: 20m`, +`max-file: 10`, also bis zu 200 MB je Dienst); ohne diese Einstellung würde +Docker mit der Standardkonfiguration unbegrenzt in eine einzelne Datei unter +`/var/lib/docker/containers//` schreiben. Die Logs überleben +einen Container-Neustart (`docker compose restart`), aber nicht das Entfernen +des Containers (`docker compose down` gefolgt von `up` erzeugt neue +Container und damit neue, leere Logdateien); für ein echtes Langzeitarchiv +über Rebuilds hinweg müssten die Zeilen zusätzlich in eine Datei im +gemounteten `./data`-Verzeichnis oder an ein externes Log-System geschrieben +werden. Die Express-API protokolliert +jede abgeschlossene Anfrage (Methode, Pfad, Status, Dauer; `/health` wird +nicht mitgeloggt) sowie unbehandelte Exceptions/Promise-Rejections. Das +Next.js-Frontend protokolliert Seitenanfragen (Navigation) über +`src/proxy.ts` und unbehandelte Fehler über `src/instrumentation.ts`. +Beide Prozesse schreiben zusätzlich alle fünf Minuten einen `verbose`-Heartbeat +mit Laufzeit und Speicherverbrauch – nützlich, um Speicherlecks oder Hänger vor +einem 502 über einen längeren Zeitraum nachzuvollziehen. Für die Detailsuche +`LOG_LEVEL=debug` setzen; das protokolliert zusätzlich den Start jeder +API-Anfrage und macht damit hängende (nie abgeschlossene) Requests sichtbar. + ## Voraussetzungen für ein späteres Produktionssetup Vor einer produktiven Installation werden mindestens benötigt: diff --git a/src/instrumentation-node.ts b/src/instrumentation-node.ts new file mode 100644 index 0000000..0549375 --- /dev/null +++ b/src/instrumentation-node.ts @@ -0,0 +1,25 @@ +import { createLogger, toErrorMeta } from "./shared/logging/logger"; + +export function registerNodeInstrumentation() { + const logger = createLogger("web"); + const heartbeatIntervalMs = 5 * 60 * 1000; + + logger.info("web server starting", { pid: process.pid }); + + process.on("uncaughtException", (error) => { + logger.error("uncaught exception", toErrorMeta(error)); + }); + + process.on("unhandledRejection", (reason) => { + logger.error("unhandled rejection", toErrorMeta(reason)); + }); + + setInterval(() => { + const memory = process.memoryUsage(); + logger.verbose("heartbeat", { + uptimeSeconds: Math.round(process.uptime()), + rssMb: Math.round(memory.rss / 1024 / 1024), + heapUsedMb: Math.round(memory.heapUsed / 1024 / 1024), + }); + }, heartbeatIntervalMs).unref(); +} diff --git a/src/instrumentation.ts b/src/instrumentation.ts new file mode 100644 index 0000000..7812ea2 --- /dev/null +++ b/src/instrumentation.ts @@ -0,0 +1,8 @@ +export async function register() { + if (process.env.NEXT_RUNTIME !== "nodejs") { + return; + } + + const { registerNodeInstrumentation } = await import("./instrumentation-node"); + registerNodeInstrumentation(); +} diff --git a/src/proxy.ts b/src/proxy.ts new file mode 100644 index 0000000..9b301d8 --- /dev/null +++ b/src/proxy.ts @@ -0,0 +1,17 @@ +import { NextResponse } from "next/server"; +import type { NextRequest } from "next/server"; +import { createLogger } from "./shared/logging/logger"; + +const logger = createLogger("web:navigation"); + +export function proxy(request: NextRequest) { + logger.info("page request", { + method: request.method, + path: request.nextUrl.pathname, + }); + return NextResponse.next(); +} + +export const config = { + matcher: ["/((?!_next/static|_next/image|favicon.ico|api).*)"], +}; diff --git a/src/server/index.ts b/src/server/index.ts index e951a07..851276a 100644 --- a/src/server/index.ts +++ b/src/server/index.ts @@ -4,12 +4,36 @@ import { globalDeviceRouter } from "./routes/global-device.routes.js"; import { projectDeviceRouter } from "./routes/project-device.routes.js"; import { projectRouter } from "./routes/project.routes.js"; import { errorMiddleware } from "./middleware/error.middleware.js"; +import { createLogger, toErrorMeta } from "../shared/logging/logger.js"; +const logger = createLogger("api"); const app = express(); const port = Number(process.env.PORT || 3000); +const heartbeatIntervalMs = 5 * 60 * 1000; app.use(express.json({ limit: "25mb" })); +app.use((req, res, next) => { + if (req.path === "/health") { + next(); + return; + } + const startedAt = Date.now(); + logger.debug("request started", { method: req.method, path: req.originalUrl }); + res.on("finish", () => { + const meta = { + method: req.method, + path: req.originalUrl, + status: res.statusCode, + durationMs: Date.now() - startedAt, + }; + 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(); +}); + app.get("/health", (_req, res) => { res.json({ ok: true }); }); @@ -21,6 +45,26 @@ app.use("/api/project-devices", projectDeviceRouter); app.use(errorMiddleware); -app.listen(port, () => { - console.log(`Server running on http://localhost:${port}`); +process.on("uncaughtException", (error) => { + logger.error("uncaught exception", toErrorMeta(error)); +}); + +process.on("unhandledRejection", (reason) => { + logger.error("unhandled rejection", toErrorMeta(reason)); +}); + +process.on("SIGTERM", () => logger.info("received SIGTERM")); +process.on("SIGINT", () => logger.info("received SIGINT")); + +setInterval(() => { + const memory = process.memoryUsage(); + logger.verbose("heartbeat", { + uptimeSeconds: Math.round(process.uptime()), + rssMb: Math.round(memory.rss / 1024 / 1024), + heapUsedMb: Math.round(memory.heapUsed / 1024 / 1024), + }); +}, heartbeatIntervalMs).unref(); + +app.listen(port, () => { + logger.info("server started", { port }); }); diff --git a/src/server/middleware/error.middleware.ts b/src/server/middleware/error.middleware.ts index 33ff083..65b2df4 100644 --- a/src/server/middleware/error.middleware.ts +++ b/src/server/middleware/error.middleware.ts @@ -1,12 +1,19 @@ import type { NextFunction, Request, Response } from "express"; +import { createLogger, toErrorMeta } from "../../shared/logging/logger.js"; + +const logger = createLogger("api"); export function errorMiddleware( error: unknown, - _req: Request, + req: Request, res: Response, _next: NextFunction ) { - console.error(error); + logger.error("request handler threw", { + method: req.method, + path: req.originalUrl, + ...toErrorMeta(error), + }); res.status(500).json({ error: "Internal Server Error" }); } diff --git a/src/shared/logging/logger.ts b/src/shared/logging/logger.ts new file mode 100644 index 0000000..423a7ad --- /dev/null +++ b/src/shared/logging/logger.ts @@ -0,0 +1,71 @@ +export type LogLevel = "error" | "warn" | "info" | "verbose" | "debug"; + +const LEVEL_SEVERITY: Record = { + error: 0, + warn: 1, + info: 2, + verbose: 3, + debug: 4, +}; + +const DEFAULT_LEVEL: LogLevel = "info"; + +export function resolveLogLevel(raw: string | undefined): LogLevel { + const candidate = raw?.trim().toLowerCase(); + if (candidate && candidate in LEVEL_SEVERITY) { + return candidate as LogLevel; + } + return DEFAULT_LEVEL; +} + +export function toErrorMeta(error: unknown): Record { + if (error instanceof Error) { + return { + errorName: error.name, + errorMessage: error.message, + stack: error.stack, + }; + } + return { error: typeof error === "string" ? error : JSON.stringify(error) }; +} + +export interface Logger { + error(message: string, meta?: Record): void; + warn(message: string, meta?: Record): void; + info(message: string, meta?: Record): void; + verbose(message: string, meta?: Record): void; + debug(message: string, meta?: Record): void; +} + +export function createLogger( + scope: string, + options?: { level?: LogLevel } +): Logger { + const threshold = options?.level ?? resolveLogLevel(process.env.LOG_LEVEL); + + const write = (level: LogLevel, message: string, meta?: Record) => { + if (LEVEL_SEVERITY[level] > LEVEL_SEVERITY[threshold]) { + return; + } + const line = JSON.stringify({ + timestamp: new Date().toISOString(), + level, + scope, + message, + ...meta, + }); + if (level === "error" || level === "warn") { + console.error(line); + } else { + console.log(line); + } + }; + + return { + error: (message, meta) => write("error", message, meta), + warn: (message, meta) => write("warn", message, meta), + info: (message, meta) => write("info", message, meta), + verbose: (message, meta) => write("verbose", message, meta), + debug: (message, meta) => write("debug", message, meta), + }; +} diff --git a/tests/logger.test.ts b/tests/logger.test.ts new file mode 100644 index 0000000..35ee720 --- /dev/null +++ b/tests/logger.test.ts @@ -0,0 +1,83 @@ +import assert from "node:assert/strict"; +import { describe, it } from "node:test"; +import { createLogger, resolveLogLevel } from "../src/shared/logging/logger.js"; + +describe("resolveLogLevel", () => { + it("defaults to info for missing or unknown values", () => { + assert.equal(resolveLogLevel(undefined), "info"); + assert.equal(resolveLogLevel(""), "info"); + assert.equal(resolveLogLevel("nonsense"), "info"); + }); + + it("accepts known levels case-insensitively", () => { + assert.equal(resolveLogLevel("DEBUG"), "debug"); + assert.equal(resolveLogLevel(" verbose "), "verbose"); + assert.equal(resolveLogLevel("warn"), "warn"); + }); +}); + +describe("createLogger", () => { + it("suppresses levels below the configured threshold", () => { + const infoLines: string[] = []; + const originalLog = console.log; + console.log = (line: string) => { + infoLines.push(line); + }; + try { + const logger = createLogger("test", { level: "warn" }); + logger.info("should not appear"); + logger.debug("should not appear"); + logger.verbose("should not appear"); + } finally { + console.log = originalLog; + } + assert.equal(infoLines.length, 0); + }); + + it("emits enabled levels as structured JSON with scope and meta", () => { + const errorLines: string[] = []; + const originalError = console.error; + console.error = (line: string) => { + errorLines.push(line); + }; + try { + const logger = createLogger("test", { level: "warn" }); + logger.warn("something happened", { code: 42 }); + } finally { + console.error = originalError; + } + assert.equal(errorLines.length, 1); + const parsed = JSON.parse(errorLines[0]); + assert.equal(parsed.level, "warn"); + assert.equal(parsed.scope, "test"); + assert.equal(parsed.message, "something happened"); + assert.equal(parsed.code, 42); + assert.equal(typeof parsed.timestamp, "string"); + }); + + it("routes debug/verbose/info to console.log and error/warn to console.error", () => { + const logLines: string[] = []; + const errorLines: string[] = []; + const originalLog = console.log; + const originalError = console.error; + console.log = (line: string) => { + logLines.push(line); + }; + console.error = (line: string) => { + errorLines.push(line); + }; + try { + const logger = createLogger("test", { level: "debug" }); + logger.debug("d"); + logger.verbose("v"); + logger.info("i"); + logger.warn("w"); + logger.error("e"); + } finally { + console.log = originalLog; + console.error = originalError; + } + assert.equal(logLines.length, 3); + assert.equal(errorLines.length, 2); + }); +}); diff --git a/tsconfig.json b/tsconfig.json index 0f910df..9761c37 100644 --- a/tsconfig.json +++ b/tsconfig.json @@ -11,5 +11,11 @@ "resolveJsonModule": true }, "include": ["src/**/*.ts"], - "exclude": ["node_modules", "dist"] + "exclude": [ + "node_modules", + "dist", + "src/proxy.ts", + "src/instrumentation.ts", + "src/instrumentation-node.ts" + ] } diff --git a/tsconfig.next.json b/tsconfig.next.json index b91ebfd..d54dc0c 100644 --- a/tsconfig.next.json +++ b/tsconfig.next.json @@ -18,6 +18,9 @@ "src/app/**/*.tsx", "src/frontend/**/*.ts", "src/frontend/**/*.tsx", + "src/proxy.ts", + "src/instrumentation.ts", + "src/instrumentation-node.ts", ".next/types/**/*.ts" ], "exclude": ["node_modules", "dist"] diff --git a/tsconfig.scripts.json b/tsconfig.scripts.json index ea4c56f..6facc56 100644 --- a/tsconfig.scripts.json +++ b/tsconfig.scripts.json @@ -5,5 +5,11 @@ "rootDir": "." }, "include": ["scripts/**/*.ts", "src/**/*.ts"], - "exclude": ["node_modules", "dist"] + "exclude": [ + "node_modules", + "dist", + "src/proxy.ts", + "src/instrumentation.ts", + "src/instrumentation-node.ts" + ] }