From 9bcbc1e7f3a5185eed2146f4f3502542b0bebd01 Mon Sep 17 00:00:00 2001 From: Cooldude2606 <25043174+Cooldude2606@users.noreply.github.com> Date: Thu, 18 Jan 2024 15:49:01 +0000 Subject: [PATCH 1/4] Add http logging for express --- packages/controller/package.json | 1 + packages/controller/src/Controller.ts | 8 ++++++++ packages/lib/src/logging.ts | 7 +++++-- 3 files changed, 14 insertions(+), 2 deletions(-) diff --git a/packages/controller/package.json b/packages/controller/package.json index 042a53ad..1a1e6365 100644 --- a/packages/controller/package.json +++ b/packages/controller/package.json @@ -30,6 +30,7 @@ "set-blocking": "^2.0.0", "webpack-cli": "^5.1.4", "winston": "^3.10.0", + "express-winston": "^4.2.0", "winston-daily-rotate-file": "^4.7.1", "ws": "^8.13.0", "yargs": "^17.7.2" diff --git a/packages/controller/src/Controller.ts b/packages/controller/src/Controller.ts index 89214e0f..2b5b67f2 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 * as expressWinston from "express-winston"; import compression from "compression"; import events, { EventEmitter } from "events"; @@ -164,6 +165,10 @@ export default class Controller { this.app = express(); this.app.locals.controller = this; this.app.locals.streams = new Map(); + this.app.use(expressWinston.logger({ + winstonInstance: this.clusterLogger, + level: "http", + })); this.trustedProxies = this.parseTrustedProxies(); this.wsServer = new WsServer(this); @@ -283,6 +288,9 @@ export default class Controller { // Load plugins await this.loadPlugins(); + this.app.use(expressWinston.errorLogger({ + winstonInstance: this.clusterLogger, + })); this.wsServer = new WsServer(this); diff --git a/packages/lib/src/logging.ts b/packages/lib/src/logging.ts index c673f98e..d8502c2d 100644 --- a/packages/lib/src/logging.ts +++ b/packages/lib/src/logging.ts @@ -9,7 +9,8 @@ export const levels = Object.freeze({ audit: 3, info: 4, server: 5, - verbose: 6, + http: 6, + verbose: 7, }); export const colors = { @@ -19,6 +20,7 @@ export const colors = { audit: "bold brightGreen", info: "bold brightBlue", server: "bold", + http: "bold grey", verbose: "bold grey", } as const; winston.addColors(colors); @@ -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 & { @@ -173,6 +175,7 @@ export type Logger = Omit Date: Thu, 18 Jan 2024 18:05:27 +0000 Subject: [PATCH 2/4] Remove insecure and bloated module --- packages/controller/package.json | 1 - packages/controller/src/Controller.ts | 51 ++++++++++++++++++++++----- packages/lib/src/logging.ts | 8 ++--- 3 files changed, 47 insertions(+), 13 deletions(-) diff --git a/packages/controller/package.json b/packages/controller/package.json index 1a1e6365..042a53ad 100644 --- a/packages/controller/package.json +++ b/packages/controller/package.json @@ -30,7 +30,6 @@ "set-blocking": "^2.0.0", "webpack-cli": "^5.1.4", "winston": "^3.10.0", - "express-winston": "^4.2.0", "winston-daily-rotate-file": "^4.7.1", "ws": "^8.13.0", "yargs": "^17.7.2" diff --git a/packages/controller/src/Controller.ts b/packages/controller/src/Controller.ts index 2b5b67f2..42c93d2d 100644 --- a/packages/controller/src/Controller.ts +++ b/packages/controller/src/Controller.ts @@ -3,7 +3,6 @@ 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 * as expressWinston from "express-winston"; import compression from "compression"; import events, { EventEmitter } from "events"; @@ -165,10 +164,31 @@ export default class Controller { this.app = express(); this.app.locals.controller = this; this.app.locals.streams = new Map(); - this.app.use(expressWinston.logger({ - winstonInstance: this.clusterLogger, - level: "http", - })); + + // Log all requests made to express + this.app.use((req, res, next) => { + const startNs = process.hrtime.bigint(); + res.once("finish", () => { + const endNs = process.hrtime.bigint(); + const durationMs = (Number(endNs - startNs) / 1e6); + 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(); + }); this.trustedProxies = this.parseTrustedProxies(); this.wsServer = new WsServer(this); @@ -288,9 +308,24 @@ export default class Controller { // Load plugins await this.loadPlugins(); - this.app.use(expressWinston.errorLogger({ - winstonInstance: this.clusterLogger, - })); + + // 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, + }, + }); + + next(); + }); this.wsServer = new WsServer(this); diff --git a/packages/lib/src/logging.ts b/packages/lib/src/logging.ts index d8502c2d..c78dea30 100644 --- a/packages/lib/src/logging.ts +++ b/packages/lib/src/logging.ts @@ -8,8 +8,8 @@ export const levels = Object.freeze({ warn: 2, audit: 3, info: 4, - server: 5, - http: 6, + http: 5, + server: 6, verbose: 7, }); @@ -19,8 +19,8 @@ export const colors = { warn: "bold brightYellow", audit: "bold brightGreen", info: "bold brightBlue", + http: "bold", server: "bold", - http: "bold grey", verbose: "bold grey", } as const; winston.addColors(colors); @@ -174,8 +174,8 @@ export type Logger = Omit Date: Thu, 18 Jan 2024 18:45:01 +0000 Subject: [PATCH 3/4] Clean up the request correctly --- packages/controller/package.json | 2 ++ packages/controller/src/Controller.ts | 7 +++++-- 2 files changed, 7 insertions(+), 2 deletions(-) diff --git a/packages/controller/package.json b/packages/controller/package.json index 042a53ad..4af76e17 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", @@ -39,6 +40,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 42c93d2d..f89753c3 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"; @@ -173,7 +174,7 @@ export default class Controller { const durationMs = (Number(endNs - startNs) / 1e6); logger.log({ level: "http", - message: `HTTP ${req.httpVersion} ${req.method} ${req.originalUrl}` + + message: `HTTP${req.httpVersion} ${req.method} ${req.originalUrl}` + ` (Status ${res.statusCode} in ${durationMs}ms)`, meta: { method: req.method, @@ -324,7 +325,9 @@ export default class Controller { }, }); - next(); + // 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); From 0b2fcdcec471a5ba029a0f2b017ba8e35d44174b Mon Sep 17 00:00:00 2001 From: Cooldude2606 <25043174+Cooldude2606@users.noreply.github.com> Date: Wed, 14 Feb 2024 22:37:48 +0000 Subject: [PATCH 4/4] Merged redundant middleware --- packages/controller/src/Controller.ts | 46 +++++++++++---------------- 1 file changed, 18 insertions(+), 28 deletions(-) diff --git a/packages/controller/src/Controller.ts b/packages/controller/src/Controller.ts index f89753c3..78f42436 100644 --- a/packages/controller/src/Controller.ts +++ b/packages/controller/src/Controller.ts @@ -166,31 +166,6 @@ export default class Controller { this.app.locals.controller = this; this.app.locals.streams = new Map(); - // Log all requests made to express - this.app.use((req, res, next) => { - const startNs = process.hrtime.bigint(); - res.once("finish", () => { - const endNs = process.hrtime.bigint(); - const durationMs = (Number(endNs - startNs) / 1e6); - 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(); - }); - this.trustedProxies = this.parseTrustedProxies(); this.wsServer = new WsServer(this); @@ -765,14 +740,29 @@ export default class Controller { static addAppRoutes(app: Application, pluginInfos: any[]) { app.use((req: Request, res: Response, next) => { - let start = 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 end = process.hrtime.bigint(); - endpointDurationSummary.labels(routePath).observe(Number(end - start) / 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(); });