diff --git a/packages/controller/package.json b/packages/controller/package.json index 588b39c0..61a728e4 100644 --- a/packages/controller/package.json +++ b/packages/controller/package.json @@ -24,6 +24,7 @@ "busboy": "^1.6.0", "compression": "^1.7.4", "express": "^4.18.2", + "finalhandler": "^1.2.0", "fs-extra": "^11.1.1", "jsonwebtoken": "^9.0.1", "jszip": "^3.10.1", @@ -40,6 +41,7 @@ "@types/busboy": "^1.5.0", "@types/compression": "^1.7.2", "@types/express": "^4.17.17", + "@types/finalhandler": "^1.2.0", "@types/fs-extra": "^11.0.1", "@types/jsonwebtoken": "^9.0.2", "@types/node": "^20.4.5", diff --git a/packages/controller/src/Controller.ts b/packages/controller/src/Controller.ts index 4c98efc3..e1e53293 100644 --- a/packages/controller/src/Controller.ts +++ b/packages/controller/src/Controller.ts @@ -3,6 +3,7 @@ import { BlockList, type AddressInfo, isIPv4, isIPv6 } from "net"; import type { ControllerArgs } from "../controller"; import express, { type Request, type Response, type NextFunction, type Application } from "express"; import type { Static } from "@sinclair/typebox"; +import finalhandler from "finalhandler"; import compression from "compression"; import events, { EventEmitter } from "events"; @@ -286,6 +287,26 @@ export default class Controller { // Load plugins await this.loadPlugins(); + // Log all express errors from middleware or routes (app.use is missing the type overload) + this.app.use((err: Error, req: express.Request, res: express.Response, next: express.NextFunction): void => { + logger.log({ + level: "error", + message: "Error while handling HTTP" + + `${req.httpVersion} ${req.method} ${req.originalUrl}:\n${err.stack}`, + meta: { + method: req.method, + url: req.originalUrl, + httpVersion: req.httpVersion, + headers: req.headers, + query: req.query, + }, + }); + + // Create and call the final handler, this is the same method used by express + // This is used instead of next(err) to stop express from logging the error to the console + finalhandler(req, res, { env: this.app.get("env") })(err); + }); + this.wsServer = new WsServer(this); // Only start listening for connections after all plugins have loaded @@ -721,14 +742,29 @@ export default class Controller { static addAppRoutes(app: Application, pluginInfos: any[]) { app.use((req: Request, res: Response, next) => { - let startNs = process.hrtime.bigint(); + const startNs = process.hrtime.bigint(); stream.finished(res, () => { let routePath = "static"; if (req.route && req.route.path) { routePath = req.route.path; } - let endNs = process.hrtime.bigint(); - endpointDurationSummary.labels(routePath).observe(Number(endNs - startNs) / 1e9); + const endNs = process.hrtime.bigint(); + const durationMs = (Number(endNs - startNs) / 1e6); + endpointDurationSummary.labels(routePath).observe(durationMs / 1e3); + logger.log({ + level: "http", + message: `HTTP${req.httpVersion} ${req.method} ${req.originalUrl}` + + ` (Status ${res.statusCode} in ${durationMs}ms)`, + meta: { + method: req.method, + url: req.originalUrl, + statusCode: res.statusCode, + responseTime: durationMs, + httpVersion: req.httpVersion, + headers: req.headers, + query: req.query, + }, + }); }); next(); }); diff --git a/packages/lib/src/logging.ts b/packages/lib/src/logging.ts index d9ce0c56..38b66278 100644 --- a/packages/lib/src/logging.ts +++ b/packages/lib/src/logging.ts @@ -8,8 +8,9 @@ export const levels = Object.freeze({ warn: 2, audit: 3, info: 4, - server: 5, - verbose: 6, + http: 5, + server: 6, + verbose: 7, }); export const colors = { @@ -18,6 +19,7 @@ export const colors = { warn: "bold brightYellow", audit: "bold brightGreen", info: "bold brightBlue", + http: "bold", server: "bold", verbose: "bold grey", } as const; @@ -163,7 +165,7 @@ export const logger = winston.createLogger({ // Who in their right mind thought that log levels should be hard coded // into the type when you can define custom levels you want to support? export type Logger = Omit & { @@ -172,6 +174,7 @@ export type Logger = Omit