Feature: Improve logging to contain additional properties (#38)

.gitattributes

@@ -0,0 +1 @@
+swagger-spec.json eol=lf

src/app.ts

@@ -3,11 +3,11 @@ import { DocumentBuilder, SwaggerModule } from "@nestjs/swagger";
 import helmet from "helmet";
 
 import { AppModule } from "./app.module";
-import { LoggerService } from "./core";
+import { NestLogger } from "./core/logger/nest-logger";
 
 export async function createApp() {
   const app = await NestFactory.create(AppModule, {
-    logger: new LoggerService(),
+    logger: new NestLogger(),
   });
   app.enableCors();
   app.use(helmet());

src/core/logger/logger.ts

@@ -1,88 +1,42 @@
-import chalk from "chalk";
-import jsonStringify from "fast-safe-stringify";
-import { MESSAGE } from "triple-beam";
-import winston, { LoggerOptions, format } from "winston";
-import winstonDailyFile from "winston-daily-rotate-file";
+import winston from "winston";
 
-import { Configuration } from "../../config";
+import { WINSTON_LOGGER } from "./winston-logger";
 
-const consoleTransport: winston.transports.ConsoleTransportOptions = {
-  handleExceptions: true,
-  level: "info",
-};
-
-const customFormat = format(info => {
-  const { message, level, timestamp, context, trace, ...others } = info;
-  const stringifiedRest = jsonStringify(others);
-
-  const padding = (info.padding && info.padding[level]) || "";
-  const coloredTime = chalk.dim.yellow.bold(timestamp);
-  const coloredContext = chalk.grey(context);
-  let coloredMessage = `${level}:${padding} ${coloredTime} | [${coloredContext}] ${message}`;
-  if (stringifiedRest !== "{}") {
-    coloredMessage = `${coloredMessage} ${stringifiedRest}`;
-  }
-  if (trace) {
-    coloredMessage = `${coloredMessage}\n${trace}`;
-  }
-  info[MESSAGE] = coloredMessage;
-  return info;
-});
-
-const config = new Configuration();
-// Production depends on the default JSON serialized logs to be uploaded to Geneva.
-if (config.env === "development") {
-  consoleTransport.format = winston.format.combine(
-    winston.format.timestamp({
-      format: "YYYY-MM-DD HH:mm:ss",
-    }),
-    winston.format.colorize(),
-    customFormat(),
-  );
-} else {
-  consoleTransport.format = winston.format.combine(winston.format.timestamp(), winston.format.json());
+export interface LogMetadata {
+  context?: string;
+  [key: string]: any;
 }
 
-export class LoggerService {
-  public static loggerOptions: LoggerOptions = {
-    transports: [
-      new winston.transports.Console(consoleTransport),
-      new winstonDailyFile({
-        filename: `%DATE%.log`,
-        datePattern: "YYYY-MM-DD-HH",
-        level: "debug",
-        dirname: "logs",
-        handleExceptions: true,
-      }),
-    ],
-  };
-
+export class Logger {
   private logger: winston.Logger;
-
-  constructor() {
-    this.logger = winston.createLogger(LoggerService.loggerOptions);
+  constructor(private context: string) {
+    this.logger = WINSTON_LOGGER;
   }
 
-  public log(message: string, context?: string) {
-    this.logger.info(message, { context });
+  public info(message: string, meta?: LogMetadata) {
+    this.logger.info(message, this.processMetadata(meta));
   }
 
-  public error(message: string, trace?: string, context?: string) {
-    this.logger.error(message, {
-      trace,
-      context,
-    });
+  public debug(message: string, meta?: LogMetadata) {
+    this.logger.debug(message, this.processMetadata(meta));
   }
 
-  public warn(message: string, context?: string) {
-    this.logger.warn(message, { context });
+  public warning(message: string, meta?: LogMetadata) {
+    this.logger.warning(message, this.processMetadata(meta));
   }
 
-  public debug(message: string, context?: string) {
-    this.logger.debug(message, { context });
+  public error(message: string | Error, meta?: LogMetadata) {
+    if (message instanceof Error) {
+      this.logger.error(message.message, this.processMetadata({ ...meta, stack: message.stack }));
+    } else {
+      this.logger.error(message, this.processMetadata(meta));
+    }
   }
 
-  public verbose(message: string, context?: string) {
-    this.logger.verbose(message, { context });
+  private processMetadata(meta: LogMetadata | undefined) {
+    return {
+      context: this.context,
+      ...meta,
+    };
   }
 }

src/core/logger/nest-logger.ts

@@ -0,0 +1,39 @@
+import { LoggerService } from "@nestjs/common";
+import winston from "winston";
+
+import { WINSTON_LOGGER } from "./winston-logger";
+
+/**
+ * Class to handle logs from nest.
+ * This shouldn't be used directly this is just to route nest logs to winston
+ */
+export class NestLogger implements LoggerService {
+  private logger: winston.Logger;
+
+  constructor() {
+    this.logger = WINSTON_LOGGER;
+  }
+
+  public log(message: string, context?: string) {
+    this.logger.info(message, { context });
+  }
+
+  public error(message: string, trace?: string, context?: string) {
+    this.logger.error(message, {
+      trace,
+      context,
+    });
+  }
+
+  public warn(message: string, context?: string) {
+    this.logger.warn(message, { context });
+  }
+
+  public debug(message: string, context?: string) {
+    this.logger.debug(message, { context });
+  }
+
+  public verbose(message: string, context?: string) {
+    this.logger.verbose(message, { context });
+  }
+}

src/core/logger/winston-logger.ts

@@ -0,0 +1,63 @@
+import chalk from "chalk";
+import jsonStringify from "fast-safe-stringify";
+import { MESSAGE } from "triple-beam";
+import winston, { LoggerOptions, format } from "winston";
+import winstonDailyFile from "winston-daily-rotate-file";
+
+import { Configuration } from "../../config";
+
+const consoleTransport: winston.transports.ConsoleTransportOptions = {
+  handleExceptions: true,
+  level: "info",
+};
+
+const customFormat = format(info => {
+  const { message, level, timestamp, context, trace, ...others } = info;
+  const stringifiedRest = jsonStringify(others);
+
+  const padding = (info.padding && info.padding[level]) || "";
+  const coloredTime = chalk.dim.yellow.bold(timestamp);
+  const coloredContext = chalk.grey(context);
+  let coloredMessage = `${level}:${padding} ${coloredTime} | [${coloredContext}] ${message}`;
+  if (stringifiedRest !== "{}") {
+    coloredMessage = `${coloredMessage} ${stringifiedRest}`;
+  }
+  if (trace) {
+    coloredMessage = `${coloredMessage}\n${trace}`;
+  }
+  info[MESSAGE] = coloredMessage;
+  return info;
+});
+
+const config = new Configuration();
+
+// In development only we want to have the logs printed nicely. For production we want json log lines that can be parsed easily
+if (config.env === "development") {
+  consoleTransport.format = winston.format.combine(
+    winston.format.timestamp({
+      format: "YYYY-MM-DD HH:mm:ss",
+    }),
+    winston.format.colorize(),
+    customFormat(),
+  );
+} else {
+  consoleTransport.format = winston.format.combine(winston.format.timestamp(), winston.format.json());
+}
+
+export const WINSTON_LOGGER_OPTIONS: LoggerOptions = {
+  transports: [
+    new winston.transports.Console(consoleTransport),
+    new winstonDailyFile({
+      filename: `%DATE%.log`,
+      datePattern: "YYYY-MM-DD-HH",
+      level: "debug",
+      dirname: "logs",
+      handleExceptions: true,
+    }),
+  ],
+};
+
+/**
+ * DO NOT import this one directly
+ */
+export const WINSTON_LOGGER = winston.createLogger(WINSTON_LOGGER_OPTIONS);

src/middlewares/logger-interceptor.ts

@@ -1,32 +1,62 @@
-import { CallHandler, ExecutionContext, HttpException, Injectable, Logger, NestInterceptor } from "@nestjs/common";
+import { CallHandler, ExecutionContext, HttpException, Injectable, NestInterceptor } from "@nestjs/common";
 import { Observable, throwError } from "rxjs";
 import { catchError, tap } from "rxjs/operators";
 
+import { Configuration } from "../config";
+import { LogMetadata, Logger } from "../core";
+
 @Injectable()
 export class LoggingInterceptor implements NestInterceptor {
   private logger = new Logger("Request");
 
+  constructor(private config: Configuration) {}
+
   public intercept(context: ExecutionContext, next: CallHandler): Observable<any> {
     const now = Date.now();
     const req = context.switchToHttp().getRequest();
+
+    const commonProperties = {
+      url: req.originalUrl,
+      method: req.method,
+    };
+
     return next.handle().pipe(
       tap(() => {
         const response = context.switchToHttp().getResponse();
         const duration = Date.now() - now;
-        this.logger.log(`${req.method} ${response.statusCode} ${req.originalUrl} (${duration}ms)`);
+
+        const properties = {
+          ...commonProperties,
+          duration,
+          statusCode: response.statusCode,
+        };
+
+        this.logger.info(
+          `${req.method} ${response.statusCode} ${req.originalUrl} (${duration}ms)`,
+          this.clean(properties),
+        );
       }),
       catchError((error: Error | HttpException) => {
         const statusCode = error instanceof HttpException ? error.getStatus() : 500;
         const duration = Date.now() - now;
         const message = `${req.method} ${statusCode} ${req.originalUrl} (${duration}ms)`;
 
+        const properties = {
+          duration,
+          statusCode,
+        };
+
         if (statusCode >= 500) {
-          this.logger.error(message);
+          this.logger.error(message, this.clean(properties));
         } else {
-          this.logger.log(message);
+          this.logger.info(message, this.clean(properties));
         }
         return throwError(error);
       }),
     );
   }
+
+  private clean(meta: LogMetadata) {
+    return this.config.env === "development" ? {} : meta;
+  }
 }