Merge pull request #556 from Cooldude2606/feature/http-logging

Add logging for express requests and errors

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",

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();
 		});

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<winston.Logger,
-	"error" | "warn" | "help" | "data" | "info" | "debug" | "prompt" | "http" | "verbose" | "input" | "silly" |
+	"error" | "warn" | "help" | "data" | "info" | "debug" | "prompt" | "verbose" | "input" | "silly" |
 	"emerg" | "alert" | "crit" | "warning" | "notice" |
 	"child"
 > & {
@@ -172,6 +174,7 @@ export type Logger = Omit<winston.Logger,
 	warn: winston.LeveledLogMethod,
 	audit: winston.LeveledLogMethod,
 	info: winston.LeveledLogMethod,
+	http: winston.LeveledLogMethod,
 	server: winston.LeveledLogMethod,
 	verbose: winston.LeveledLogMethod,
 	child(options: object): Logger,