From d0f35e1af68fffb811cd0a1701fa9095ea864a1f Mon Sep 17 00:00:00 2001 From: Joshua Schnabel Date: Fri, 25 Mar 2022 13:49:06 +0100 Subject: [PATCH] Add Logger --- .eslintrc.json | 10 +- package.json | 1 + src/framework/logger/fastifyLogger.ts | 155 ++++++++++++++++++++++++++ src/framework/logger/logger.ts | 33 +++++- src/server.ts | 48 +++----- tsconfig.json | 3 +- yarn.lock | 2 +- 7 files changed, 207 insertions(+), 45 deletions(-) create mode 100644 src/framework/logger/fastifyLogger.ts diff --git a/.eslintrc.json b/.eslintrc.json index c05893e..ee89ffc 100644 --- a/.eslintrc.json +++ b/.eslintrc.json @@ -100,12 +100,6 @@ "@typescript-eslint/no-require-imports":"error", "@typescript-eslint/no-this-alias":"error", "@typescript-eslint/no-throw-literal":"error", - "@typescript-eslint/no-type-alias":[ - "error", - { - "allowAliases":"always" - } - ], "@typescript-eslint/no-unsafe-call":"error", "@typescript-eslint/no-unsafe-member-access":"error", "@typescript-eslint/no-unsafe-return":"error", @@ -159,8 +153,9 @@ } ], "no-unused-vars":"off", + "unused-imports/no-unused-vars": "off", "unused-imports/no-unused-imports":"error", - "unused-imports/no-unused-vars":[ + "@typescript-eslint/no-unused-vars":[ "warn", { "vars":"all", @@ -171,5 +166,6 @@ ], "indent": "off", "@typescript-eslint/indent": ["error", 2], + "import/no-unresolved": ["off"] } } \ No newline at end of file diff --git a/package.json b/package.json index 902101b..bcd97ef 100644 --- a/package.json +++ b/package.json @@ -25,6 +25,7 @@ "dependencies": { "@gquittet/graceful-server": "^2.5.2", "fastify": "^3.25.3", + "fastify-plugin": "^3.0.0", "fastify-sensible": "^3.1.2", "winston": "^3.4.0" }, diff --git a/src/framework/logger/fastifyLogger.ts b/src/framework/logger/fastifyLogger.ts new file mode 100644 index 0000000..a32ce26 --- /dev/null +++ b/src/framework/logger/fastifyLogger.ts @@ -0,0 +1,155 @@ +/* eslint-disable @typescript-eslint/require-await */ +import { FastifyLogFn, FastifyLoggerInstance, FastifyPluginAsync, FastifyRequest} from "fastify"; +import fastifyPlugin from "fastify-plugin"; +import { Bindings } from "fastify/types/logger"; +import getlogger from "./logger"; +import chalk from "chalk"; + +const logger = getlogger("fastify"); +const customLogger: FastifyLoggerInstance = { + info: function (obj: unknown, msg?: string, ...args: unknown[]): void { + if(typeof obj === "string") + logger.info(obj, msg, ...args); + else if(msg) + logger.info(msg, obj, ...args); + } as FastifyLogFn, + warn: function (obj: unknown, msg?: string, ...args: unknown[]): void { + if(typeof obj === "string") + logger.warning(obj, msg, ...args); + else if(msg) + logger.warning(msg, obj, ...args); + } as FastifyLogFn, + error: function (obj: unknown, msg?: string, ...args: unknown[]): void { + if(typeof obj === "string") + logger.error(obj, msg, ...args); + else if(msg) + logger.error(msg, obj, ...args); + } as FastifyLogFn, + fatal: function (obj: unknown, msg?: string, ...args: unknown[]): void { + if(typeof obj === "string") + logger.fatal(obj, msg, ...args); + else if(msg) + logger.fatal(msg, obj, ...args); + } as FastifyLogFn, + trace: function (obj: unknown, msg?: string, ...args: unknown[]): void { + if(typeof obj === "string") + logger.trace(obj, msg, ...args); + else if(msg) + logger.trace(msg, obj, ...args); + } as FastifyLogFn, + debug: function (obj: unknown, msg?: string, ...args: unknown[]): void { + if(typeof obj === "string") + logger.debug(obj, msg, ...args); + else if(msg) + logger.debug(msg, obj, ...args); + } as FastifyLogFn, + child: function (_bindings: Bindings): FastifyLoggerInstance { + return customLogger; + }, + setBindings: function (_bindings: Bindings): void { + // OK + } +}; + +export type FastifyRequestLoggerOptions = { + logBody?: boolean; + ignoredPaths?: Array; +}; + +export const plugin: FastifyPluginAsync = async (fastify, options = {}): Promise => { + const { + logBody = true, + ignoredPaths = [], + } = options; + + const isIgnoredRequest = (request: FastifyRequest): boolean => { + const { routerPath } = request; + if (ignoredPaths.includes(routerPath)) { + return true; + } + return false; + }; + + fastify.addHook("onRequest", async (request) => { + if (isIgnoredRequest(request)) { + return; + } + const id = request.id; + const method = request.method; + const referrer = (request.headers["Referer"] ?? (request.headers["referer"]) ?? request.headers["Refferer"]) ?? request.headers["refferer"]; + const remoteAddr = request.ip; + const remoteUser = "???"; + const url = request.url; + const httpVersion = request.raw.httpVersion; + const userAgent = request.headers["User-Agents"]; + const contentLength = request.headers["content-length"]; + + request.log.info(`${chalk.bold.yellow("→")} ${chalk.yellow(method)} ${chalk.green(url)} HTTP/${httpVersion} - ${chalk.blue(remoteAddr)} ${remoteUser} - ${referrer} - ${contentLength} bytes [${id}]`); + request.log.trace(`${chalk.bold.yellow("→")} ${chalk.yellow(method)} ${chalk.green(url)} ${userAgent} [${id}]`); + request.log.info( + `${chalk.bold.yellow("←")}${chalk.yellow(request.method)}:${chalk.green( + request.url + )} request from ip ${chalk.blue(request.ip)}${ + contentLength ? ` with a ${chalk.yellow(contentLength)}-length body` : "" + }` + ); + request.log.trace("Request trace %s", JSON.stringify({header: request.headers, body: request.body})); + }); + + fastify.addHook("preHandler", async (request) => { + if (isIgnoredRequest(request)) { + return; + } + const id = request.id; + const method = request.method; + // const referrer = (request.headers["Referer"] ?? (request.headers["referer"]) ?? request.headers["Refferer"]) ?? request.headers["refferer"]; + const remoteAddr = request.ip; + const remoteUser = "???"; + const url = request.url; + const httpVersion = request.raw.httpVersion; + const userAgent = request.headers["User-Agents"]; + if (request.body && logBody) { + request.log.debug("Request body: %s", {body: request.body }); + } + }); + + fastify.addHook("onResponse", async (request, reply) => { + if (isIgnoredRequest(request)) { + return; + } + const id = request.id; + const method = request.method; + const remoteAddr = request.ip; + const remoteUser = "???"; + const responseTime = Math.ceil(reply.getResponseTime()); + const status = reply.statusCode + ""; + const url = request.url; + const httpVersion = request.raw.httpVersion; + const contentLength = reply.getHeaders()["content-length"] ?? -1; + const statusColor = function (status: string): string { + if(status.startsWith("2")) + return chalk.green(status); + if(status.startsWith("3")) + return chalk.blue(status); + if(status.startsWith("4")) + return chalk.yellow(status); + if(status.startsWith("5")) + return chalk.red(status); + return status; + }; + request.log.info(`${chalk.bold.yellow("→")} ${chalk.yellow(method)} ${chalk.green(url)} ${statusColor(status)} HTTP/${httpVersion} - ${chalk.blue(remoteAddr)} ${remoteUser} - ${contentLength} bytes ${responseTime} ms [${id}]`); + }); +}; + +declare module "fastify" { + interface FastifyLoggerInstance { + setBindings(bindings: Bindings): void; + } +} + +export const fastifyRequestLogger = fastifyPlugin(plugin, { + fastify: "3.x", + name: "fastify-request-logger", +}); + +export const fastifyLogger = customLogger; diff --git a/src/framework/logger/logger.ts b/src/framework/logger/logger.ts index 5163891..8f1ac62 100644 --- a/src/framework/logger/logger.ts +++ b/src/framework/logger/logger.ts @@ -5,9 +5,32 @@ const { combine, timestamp, label, printf, errors, splat } = format; // Custom logging format const customFormat = printf(({ level, message, label, timestamp, stack }) => { - return `${timestamp} [${label || "-"}] ${level}: ${message} ${stack || ""}`; + return `${level}\t ${timestamp} · ${label || "-"}: ${message} ${stack || ""}`; }); +const myCustomLevels = { + levels: { + alert: 0, + fatal: 1, + error: 2, + warning: 3, + verbose: 4, + info: 5, + debug: 6, + trace: 7 + }, + colors: { + alert: "magentaBG white", + fatal: "redBG white", + error: "red", + warning: "yellow", + verbose: "green", + info: "blue", + debug: "cyan", + trace: "cyanBG black" + } +}; + // Custom combined logging format: const customCombinedFormat = (module: string): Format => combine( @@ -25,15 +48,19 @@ const customTransports = (): Transport[] => [new transports.Console()]; // Container to provide different pre-configured loggers const logContainer = new winston.Container(); +winston.addColors(myCustomLevels.colors); + // Default logger for modules: -const getLogger = (module: string): Logger => { +const getLogger = (module: string): Logger & Record => { if (!logContainer.has(module)) { logContainer.add(module, { + level: "trace", + levels: myCustomLevels.levels, format: customCombinedFormat(module), transports: customTransports() }); } - return logContainer.get(module); + return logContainer.get(module) as Logger & Record; }; export default getLogger; diff --git a/src/server.ts b/src/server.ts index e3febcf..333011d 100644 --- a/src/server.ts +++ b/src/server.ts @@ -1,63 +1,45 @@ import Fastify from "fastify"; import fastifySensible from "fastify-sensible"; import GracefulServer from "@gquittet/graceful-server"; -import getlogger, {defaultLogger} from "@logger"; +import getlogger from "@logger"; +import {fastifyLogger, fastifyRequestLogger} from "@logger/fastifyLogger"; const fastify = Fastify({ - logger: true + logger: fastifyLogger, + disableRequestLogging: true }); -fastify.register(fastifySensible); +await fastify.register(fastifyRequestLogger, {logBody: true}); +await fastify.register(fastifySensible); const gracefulServer = GracefulServer(fastify.server); gracefulServer.on(GracefulServer.READY, () => { - console.log("Server is ready"); + getlogger("server").info("Server is ready"); }); gracefulServer.on(GracefulServer.SHUTTING_DOWN, () => { - console.log("Server is shutting down"); + getlogger("server").info("Server is shutting down"); }); -gracefulServer.on(GracefulServer.SHUTDOWN, error => { - console.log("Server is down because of", error.message); +gracefulServer.on(GracefulServer.SHUTDOWN, (error: {message: string}) => { + getlogger("server").info("Server is down because of", error.message); process.exit(); }); // Declare a route fastify.get("/", function (request, reply) { - reply.send({ hello: "world" }); + void reply.send({ hello: "world" }); }); // Run the server! -const start = async () => { +const start = async (): Promise => { try { - await fastify.listen(3000); + const port = 3000; + await fastify.listen(port); gracefulServer.setReady(); } catch (err) { fastify.log.error(err); process.exit(1); } }; -start(); - -const c = function (): void { - const v = function (): void { - throw new Error("Oh no!"); - }; - return v(); -}; - -const abc = getlogger("abc"); -abc.info("Ich bin ein Test!"); -abc.warn("Ich bin ein Test!"); -try { - c(); -} -catch (e) { - abc.warn(e); -} -const xyz = getlogger("xyz"); -xyz.error("Ich bin ein Test!"); -xyz.error("Ich bin ein '%s' Test!", "test"); - -defaultLogger.error("Ich bin ein Test!"); \ No newline at end of file +await start(); \ No newline at end of file diff --git a/tsconfig.json b/tsconfig.json index db8e2af..b2ac068 100644 --- a/tsconfig.json +++ b/tsconfig.json @@ -10,7 +10,8 @@ "baseUrl": "./src/", "paths": { "@abc/*": ["abc/*"], - "@logger": ["framework/logger/logger"] + "@logger": ["framework/logger/logger"], + "@logger/*": ["framework/logger/*"] } }, "include": ["src/**/*.ts"], diff --git a/yarn.lock b/yarn.lock index 32f76dd..ea765c8 100644 --- a/yarn.lock +++ b/yarn.lock @@ -771,7 +771,7 @@ fastify-error@^0.3.0: fastify-plugin@^3.0.0: version "3.0.0" - resolved "https://registry.npmjs.org/fastify-plugin/-/fastify-plugin-3.0.0.tgz" + resolved "https://registry.yarnpkg.com/fastify-plugin/-/fastify-plugin-3.0.0.tgz#cf1b8c8098e3b5a7c8c30e6aeb06903370c054ca" integrity sha512-ZdCvKEEd92DNLps5n0v231Bha8bkz1DjnPP/aEz37rz/q42Z5JVLmgnqR4DYuNn3NXAO3IDCPyRvgvxtJ4Ym4w== fastify-sensible@^3.1.2: