Nex.js from zero to one series (four) : Build a logging system using middleware, interceptors and filters

preface

The previous article covered single sign-on using JWT, but now we’ll refine some of the basics of a back-end project.

First, a good server should have a good log collection function, so that in the event of an exception in the production environment, you can retrieve the log to find the Bug.

Second, exceptions thrown in the project are categorized and reflected in the interface or log.

Finally, the parameters of the request interface should also be logged for statistical analysis (mainly for big data and malicious attack analysis).

GitHub project address, welcome everyone Star.

1. Log system

Here we use log4JS, formerly log4j, which will be familiar to anyone who has written Java.

The use of log4js has already been summarized by the big guy, so I will not repeat it:

Node.js log4JS Completely explained

1. The configuration

Install the dependency packages first

$ yarn add log4js stacktrace-js -S
Copy the code

Create a new file log4js.ts in the config directory to write the configuration file:

// config/log4js.ts

import * as path from 'path';
const baseLogPath = path.resolve(__dirname, '.. /.. /logs'); // Which directory to write logs to

const log4jsConfig = {
  appenders: {
    console: {
      type: 'console'.// Prints to the console
    },
    access: {
      type: 'dateFile'.// Files are written and sorted by date
      filename: `${baseLogPath}/access/access.log`.// The log file name is access.20200320.log
      alwaysIncludePattern: true,
      pattern: 'yyyyMMdd',
      daysToKeep: 60,
      numBackups: 3,
      category: 'http',
      keepFileExt: true.// Whether to retain the file suffix
    },
    app: {
      type: 'dateFile',
      filename: `${baseLogPath}/app-out/app.log`,
      alwaysIncludePattern: true,
      layout: {
        type: 'pattern',
        pattern: '{"date":"%d","level":"%p","category":"%c","host":"%h","pid":"%z","data":\'%m\'}',},// Log files are cut by date (day)
      pattern: 'yyyyMMdd',
      daysToKeep: 60.// maxLogSize: 10485760,
      numBackups: 3,
      keepFileExt: true,
    },
    errorFile: {
      type: 'dateFile',
      filename: `${baseLogPath}/errors/error.log`,
      alwaysIncludePattern: true,
      layout: {
        type: 'pattern',
        pattern: '{"date":"%d","level":"%p","category":"%c","host":"%h","pid":"%z","data":\'%m\'}',},// Log files are cut by date (day)
      pattern: 'yyyyMMdd',
      daysToKeep: 60.// maxLogSize: 10485760,
      numBackups: 3,
      keepFileExt: true,
    },
    errors: {
      type: 'logLevelFilter',
      level: 'ERROR',
      appender: 'errorFile',
    },
  },
  categories: {
    default: {
      appenders: ['console'.'app'.'errors'],
      level: 'DEBUG',
    },
    info: { appenders: ['console'.'app'.'errors'], level: 'info' },
    access: { appenders: ['console'.'app'.'errors'], level: 'info' },
    http: { appenders: ['access'], level: 'DEBUG' },
  },
  pm2: true.// Open when using PM2 to manage projects
  pm2InstanceVar: 'INSTANCE_ID'.// The ids assigned by pM2 are distinguished to avoid log writing conflicts between processes
};

export default log4jsConfig;
Copy the code

My configuration is posted above with some simple notes to accompany the log4JS Tutorial on Node.js.

2. The instantiation

With the configuration in place, you’re ready to start writing log4JS instances and some utility functions.

Create log4js.ts under SRC /utils:

// src/utils/log4js.ts
import * as Path from 'path';
import * as Log4js from 'log4js';
import * as Util from 'util';
import * as Moment from 'moment'; // A tool for processing time
import * as StackTrace from 'stacktrace-js';
import Chalk from 'chalk';
import config from '.. /.. /config/log4js';

// Log level
export enum LoggerLevel {
  ALL = 'ALL',
  MARK = 'MARK',
  TRACE = 'TRACE',
  DEBUG = 'DEBUG',
  INFO = 'INFO',
  WARN = 'WARN',
  ERROR = 'ERROR',
  FATAL = 'FATAL',
  OFF = 'OFF',}// Content tracking class
export class ContextTrace {
  constructor(
    public readonly context: string.publicreadonly path? :string.publicreadonly lineNumber? :number.publicreadonly columnNumber? :number.) {}
}

Log4js.addLayout('Awesome-nest'.(logConfig: any) = > {
  return (logEvent: Log4js.LoggingEvent): string= > {
    let moduleName: string = ' ';
    let position: string = ' ';

    // Log assembly
    const messageList: string[] = [];
    logEvent.data.forEach((value: any) = > {
      if (value instanceof ContextTrace) {
        moduleName = value.context;
        // Display the coordinates of the trigger log (row, column)
        if (value.lineNumber && value.columnNumber) {
          position = `${value.lineNumber}.${value.columnNumber}`;
        }
        return;
      }

      if (typeofvalue ! = ='string') {
        value = Util.inspect(value, false.3.true);
      }

      messageList.push(value);
    });

    // Log component
    const messageOutput: string = messageList.join(' ');
    const positionOutput: string = position ? ` [${position}] ` : ' ';
    const typeOutput: string = ` [${logConfig.type}] ${logEvent.pid.toString()}   - `;
    const dateOutput: string = `${Moment(logEvent.startTime).format('YYYY-MM-DD HH:mm:ss')}`;
    const moduleOutput: string = moduleName ? ` [${moduleName}] ` : '[LoggerService] ';
    let levelOutput: string = ` [${logEvent.level}] ${messageOutput}`;

    // Use different colors according to the log level
    switch (logEvent.level.toString()) {
      case LoggerLevel.DEBUG:
        levelOutput = Chalk.green(levelOutput);
        break;
      case LoggerLevel.INFO:
        levelOutput = Chalk.cyan(levelOutput);
        break;
      case LoggerLevel.WARN:
        levelOutput = Chalk.yellow(levelOutput);
        break;
      case LoggerLevel.ERROR:
        levelOutput = Chalk.red(levelOutput);
        break;
      case LoggerLevel.FATAL:
        levelOutput = Chalk.hex('#DD4C35')(levelOutput);
        break;
      default:
        levelOutput = Chalk.grey(levelOutput);
        break;
    }

    return `${Chalk.green(typeOutput)}${dateOutput}  ${Chalk.yellow(moduleOutput)}${levelOutput}${positionOutput}`;
  };
});

// Inject the configuration
Log4js.configure(config);

/ / instantiate
const logger = Log4js.getLogger();
logger.level = LoggerLevel.TRACE;

export class Logger {
  statictrace(... args) { logger.trace(Logger.getStackTrace(), ... args); }staticdebug(... args) { logger.debug(Logger.getStackTrace(), ... args); }staticlog(... args) { logger.info(Logger.getStackTrace(), ... args); }staticinfo(... args) { logger.info(Logger.getStackTrace(), ... args); }staticwarn(... args) { logger.warn(Logger.getStackTrace(), ... args); }staticwarning(... args) { logger.warn(Logger.getStackTrace(), ... args); }staticerror(... args) { logger.error(Logger.getStackTrace(), ... args); }staticfatal(... args) { logger.fatal(Logger.getStackTrace(), ... args); }staticaccess(... args) {const loggerCustom = Log4js.getLogger('http'); loggerCustom.info(Logger.getStackTrace(), ... args); }// Log trace, can trace to which file, which row and which column
  static getStackTrace(deep: number = 2) :string {
    const stackList: StackTrace.StackFrame[] = StackTrace.getSync();
    const stackInfo: StackTrace.StackFrame = stackList[deep];

    const lineNumber: number = stackInfo.lineNumber;
    const columnNumber: number = stackInfo.columnNumber;
    const fileName: string = stackInfo.fileName;
    const basename: string = Path.basename(fileName);
    return `${basename}(line: ${lineNumber}, column: ${columnNumber}): \n`; }}Copy the code

Posted above is my process for instantiating Log4JS, which deals with the components of the log (including time, type, call file, and call coordinates) and can be displayed in different colors on the console depending on the level of the log.

This file, not only can be called alone, can also be used as middleware.

3. Create middleware

We want to automatically record the requested route, IP, parameters, etc., every time a user requests an interface. It would be silly to write every route, so we need middleware to implement this.

Nest middleware is essentially equivalent to Express middleware.

Middleware functions can perform the following tasks:

• Execute any code;
• Make changes to the request and response objects;
• End the request-response cycle;
• Call the next middleware function in the stack;
• If the current middleware function does not have an end request or response period, it must be callednext()Pass control to the next middleware function. Otherwise, the request will be suspended;

Create the middleware file by executing the following command:

$ nest g middleware logger middleware
Copy the code

SRC creates logger.middleware.ts, and Nest’s default middleware template looks something like this:

// src/middleware/logger.middleware.ts
import { Injectable, NestMiddleware } from '@nestjs/common';

@Injectable(a)export class LoggerMiddleware implements NestMiddleware {
  use(req: any, res: any, next: (a)= > void) { next(); }}Copy the code

The NestMiddleware interface is just implemented, and it takes three parameters:

• Req: Request for information.
• Res: Response information.
• Next: Passes control to the next middleware, which should be familiar to anyone who has written Vue or Koa;

Next, we write the logging functionality to the middleware:

// src/middleware/logger.middleware.ts
import { Injectable, NestMiddleware } from '@nestjs/common';
import { Request, Response } from 'express';
import { Logger } from '.. /utils/log4js';

@Injectable(a)export class LoggerMiddleware implements NestMiddleware {
  use(req: Request, res: Response, next: (a)= > void) {
    const code = res.statusCode; // Response status code
    next();
    // Assemble log information
    const logFormat = `Method: ${req.method} \n Request original url: ${req.originalUrl} \n IP: ${req.ip} \n Status code: ${code} \n`;
    // Log types are distinguished according to the status code
    if (code >= 500) {
      Logger.error(logFormat);
    } else if (code >= 400) {
      Logger.warn(logFormat);
    } else{ Logger.access(logFormat); Logger.log(logFormat); }}}Copy the code

At the same time, Nest also supports [functional middleware]. Let’s implement the above functions functionally:

// src/middleware/logger.middleware.ts import { Injectable, NestMiddleware } from '@nestjs/common'; import { Request, Response } from 'express'; import { Logger } from '.. /utils/log4js'; @Injectable() export class LoggerMiddleware implements NestMiddleware { ... } // Export function Logger (req: Request, res: Response, next: () => any) {const code = res.statuscode; // Response status code next(); / / assembly log information const logFormat = ` > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > > Request the original url: ${req.originalUrl} Method: ${req.method} IP: ${req.ip} Status code: ${code} Parmas: ${JSON.stringify(req.params)} Query: ${JSON.stringify(req.query)} Body: ${JSON.stringify(req.body)} \n >>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>>> `; If (code >= 500) {logger. error(logFormat); } else if (code >= 400) { Logger.warn(logFormat); } else { Logger.access(logFormat); Logger.log(logFormat); }}Copy the code

Some changes have been made to the log format above, mainly for ease of viewing.

Whether to use Nest or functional middleware depends on your needs. Of course, Nest’s native middleware has more advanced gameplay.

Application middleware

Once the middleware is ready, we just need to introduce the middleware to main.ts:

// src/main.ts
import { NestFactory } from '@nestjs/core';
import { AppModule } from './app.module';

import { logger } from './middleware/logger.middleware';

async function bootstrap() {
  const app = await NestFactory.create(AppModule);
  // Listen for all request routes and print logs
  app.use(logger);
  app.setGlobalPrefix('nest-zero-to-one');
  await app.listen(3000);
}
bootstrap();
Copy the code

After saving the code, you will find that there are several more files in the project directory:

This is the result of the previous configuration in config/log4js.ts

Next, let’s try requesting the login interface:

Found that although it is printed, but no request parameter information.

So, we need to do one more operation to handle the request parameters:

// src/main.ts
import { NestFactory } from '@nestjs/core';
import { AppModule } from './app.module';
import * as express from 'express';
import { logger } from './middleware/logger.middleware';

async function bootstrap() {
  const app = await NestFactory.create(AppModule);
  app.use(express.json()); // For parsing application/json
  app.use(express.urlencoded({ extended: true })); // For parsing application/x-www-form-urlencoded
  // Listen for all request routes and print logs
  app.use(logger);
  app.setGlobalPrefix('nest-zero-to-one');
  await app.listen(3000);
}
bootstrap();
Copy the code

Request again, find the parameter is already out:

The IP is ::1 because I run all my stuff locally. Normally, it prints the IP of the other party.

Look again under logs/ :

Above you can see that the log has been written to the file.

5. Preliminary interceptor

The previous example has shown how to print input parameters, but without input information, it will not work, otherwise how to locate the Bug.

Nest provides an Interceptors, which you can think of as a checkpoint. Unless you encounter guan Yu, all parameters will be processed here.

The details of how to use it will be explained in a later tutorial, but here is just an overview of how to use it:

Create the transform file by executing the following instructions

$ nest g interceptor transform interceptor
Copy the code

The intercept takes two arguments, the current context and the transfer function. It also uses pipe to pass the response data:

// src/interceptor/transform.interceptor.ts
import { CallHandler, ExecutionContext, Injectable, NestInterceptor } from '@nestjs/common';
import { Observable } from 'rxjs';
import { map } from 'rxjs/operators';
import { Logger } from '.. /utils/log4js';

@Injectable(a)export class TransformInterceptor implements NestInterceptor {
  intercept(context: ExecutionContext, next: CallHandler): Observable<any> {
    const req = context.getArgByIndex(1).req;
    return next.handle().pipe(
      map(data= > {
        const logFormat = ` <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
    Request original url: ${req.originalUrl}
    Method: ${req.method}
    IP: ${req.ip}
    User: ${JSON.stringify(req.user)}
    Response data:\n ${JSON.stringify(data.data)}< < < < < < < < < < < < < < < < < < < < < < < < < < < < < < < < < < < < < < < < < < < < < < < < < < < < < < < < < < < < < < < < `;
        Logger.info(logFormat);
        Logger.access(logFormat);
        returndata; })); }}Copy the code

Use useGlobalInterceptors to call the global interceptor:

import { NestFactory } from '@nestjs/core';
import { AppModule } from './app.module';
import * as express from 'express';
import { logger } from './middleware/logger.middleware';
import { TransformInterceptor } from './interceptor/transform.interceptor';

async function bootstrap() {
  const app = await NestFactory.create(AppModule);
  app.use(express.json()); // For parsing application/json
  app.use(express.urlencoded({ extended: true})); // For parsing application/x-www-form-urlencoded // Monitor all request routes, and print the log app.use(logger); // Parsing application/x-www-form-urlencoded // Monitor all request routes, and print the log app.use(logger); / / use global interceptor to print out and app. UseGlobalInterceptors (new TransformInterceptor ()); app.setGlobalPrefix('nest-zero-to-one');
  await app.listen(3000);
}
bootstrap();
Copy the code

Let’s try the login interface again:

If @useGuards (AuthGuard(‘ JWT ‘)) is added to the route, the User information is bound to the REQ. Please refer to the previous tutorial for details.

Second, exception handling

In the process of development, it is inevitable to write a variety of “eight brother”, or programmers will be unemployed. A caring programmer should create 3 jobs (manual dog heads) while exporting code.

Getting back to the point, it’s not enough to log in and out arguments. Exceptions caught and thrown need to be logged as well.

Let’s see what the console prints:

As shown, only input parameters and console default error messages are logged, and default error messages are not written to the log file.

Look again at the returned data from the request:

As shown, you’ll see “Internal Server error” and nothing else.

There will be a hidden danger, the user in the process of using the error, but the log does not record the cause of the error, can not count the impact range, if it is a simple error, good, if it involves a variety of database transactions or concurrency problems, it is difficult to track the location, always can not always look at the console.

Therefore, we need to catch the exceptions that are not caught in the code and record logs in logs/errors, so that we can log in to the online server and filter and check the error logs.

1. Primary filter

Nest provides not only interceptors but also filters, which are similar in code structure to interceptors.

The built-in exception layer is responsible for handling all exceptions thrown throughout the application. When an unhandled exception is caught, the end user receives a friendly response.

Let’s create a new http-exception.filter:

$ nest g filter http-exception filter
Copy the code

To open the file, the default code looks like this:

// src/filter/http-exception.filter.ts
import { ArgumentsHost, Catch, ExceptionFilter } from '@nestjs/common';

@Catch(a)export class HttpExceptionFilter<T> implements ExceptionFilter {
  catch(exception: T, host: ArgumentsHost) {}
}
Copy the code

As you can see, the interceptor structure is much the same as that of the interceptor. It accepts two arguments, but is decorated with @catch ().

2. HTTP error capture

Nest provides a built-in HttpException class that is imported from the @nestjs/common package. For a typical APPLICATION based on the HTTP REST/GraphQL API, the best practice is to send a standard HTTP response object when some error condition occurs.

The HttpException constructor takes two necessary parameters to determine the response:

• The response parameter defines the body of the JSON response. It can be a String or object, as described below.
• The status parameter defines the HTTP status code.

By default, the JSON response body contains two properties:

• StatusCode: The HTTP status code provided by default in the status parameter
• Message: A short description of a state-based HTTP error

Let’s start by writing the logic to capture print:

// src/filter/http-exception.filter.ts
import { ExceptionFilter, Catch, ArgumentsHost, HttpException } from '@nestjs/common';
import { Request, Response } from 'express';
import { Logger } from '.. /utils/log4js';

@Catch(HttpException)
export class HttpExceptionFilter implements ExceptionFilter {
  catch(exception: HttpException, host: ArgumentsHost) {
    const ctx = host.switchToHttp();
    const response = ctx.getResponse<Response>();
    const request = ctx.getRequest<Request>();
    const status = exception.getStatus();

    const logFormat = ` <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
    Request original url: ${request.originalUrl}
    Method: ${request.method}
    IP: ${request.ip}
    Status code: ${status}
    Response: ${exception.toString()} \n  <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
    `;
    Logger.info(logFormat);
    response.status(status).json({
      statusCode: status,
      error: exception.message,
      msg: `${status >= 500 ? 'Service Error' : 'Client Error'}`}); }}Copy the code

The code above shows how to catch HTTP exceptions and assemble them into a more user-friendly message to return to the user.

Delete the Token from the registered interface and request:

Above is the result of a request without a filter.

We introduce http-exception in main.ts:

// src/main.ts
import { NestFactory } from '@nestjs/core';
import { AppModule } from './app.module';
import * as express from 'express';
import { logger } from './middleware/logger.middleware';
import { TransformInterceptor } from './interceptor/transform.interceptor';
import { HttpExceptionFilter } from './filter/http-exception.filter';

async function bootstrap() {
  const app = await NestFactory.create(AppModule);
  app.use(express.json()); // For parsing application/json
  app.use(express.urlencoded({ extended: true })); // For parsing application/x-www-form-urlencoded
  // Listen for all request routes and print logs
  app.use(logger);
  // Print parameters using interceptors
  app.useGlobalInterceptors(new TransformInterceptor());
  app.setGlobalPrefix('nest-zero-to-one');
  // Filter HTTP exceptions
  app.useGlobalFilters(new HttpExceptionFilter());
  await app.listen(3000);
}
bootstrap();
Copy the code

Call http-exception with useGlobalFilters and request:

Look at the console print again:

In this way, you can see the result of the request without Token, and the specific information can be assembled and modified according to personal preference.

3. A built-in HTTP exception occurs

To reduce boilerplate code, Nest provides a series of available exceptions that inherit from the core HttpException. All of this can be found in the @nestjs/common package:

• BadRequestException
• UnauthorizedException
• NotFoundException
• ForbiddenException
• NotAcceptableException
• RequestTimeoutException
• ConflictException
• GoneException
• PayloadTooLargeException
• UnsupportedMediaTypeException
• UnprocessableException
• InternalServerErrorException
• NotImplementedException
• BadGatewayException
• ServiceUnavailableException
• GatewayTimeoutException

Combined with this, you can customize the types of exceptions that are thrown, such as ForbiddenException, when later tutorials talk about permission management.

4. Catch of other errors

In addition to http-related exceptions, we can also catch all exceptions that occur in the project. We create a new any-exception.filter:

$ nest g filter any-exception filter
Copy the code

Same routine:

// src/filter/any-exception.filter.ts
/** * catch all exceptions */
import { ExceptionFilter, Catch, ArgumentsHost, HttpException, HttpStatus } from '@nestjs/common';
import { Logger } from '.. /utils/log4js';

@Catch(a)export class AllExceptionsFilter implements ExceptionFilter {
  catch(exception: unknown, host: ArgumentsHost) {
    const ctx = host.switchToHttp();
    const response = ctx.getResponse();
    const request = ctx.getRequest();

    const status = exception instanceof HttpException ? exception.getStatus() : HttpStatus.INTERNAL_SERVER_ERROR;

    const logFormat = ` <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
    Request original url: ${request.originalUrl}
    Method: ${request.method}
    IP: ${request.ip}
    Status code: ${status}
    Response: ${exception} \n  <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
    `;
    Logger.error(logFormat);
    response.status(status).json({
      statusCode: status,
      msg: `Service Error: ${exception}`}); }}Copy the code

The only difference from http-Exception is that exception is of unknown type

We introduce any-exception to main.ts:

// src/main.ts
import { NestFactory } from '@nestjs/core';
import { AppModule } from './app.module';
import * as express from 'express';
import { logger } from './middleware/logger.middleware';
import { TransformInterceptor } from './interceptor/transform.interceptor';
import { HttpExceptionFilter } from './filter/http-exception.filter';
import { AllExceptionsFilter } from './filter/any-exception.filter';

async function bootstrap() {
  const app = await NestFactory.create(AppModule);
  app.use(express.json()); // For parsing application/json
  app.use(express.urlencoded({ extended: true })); // For parsing application/x-www-form-urlencoded
  // Listen for all request routes and print logs
  app.use(logger);
  // Print parameters using interceptors
  app.useGlobalInterceptors(new TransformInterceptor());
  app.setGlobalPrefix('nest-zero-to-one');
  app.useGlobalFilters(new AllExceptionsFilter());
  app.useGlobalFilters(new HttpExceptionFilter());
  await app.listen(3000);
}
bootstrap();
Copy the code

AllExceptionsFilter must be above HttpExceptionFilter, otherwise HttpExceptionFilter will not be effective, all will be captured by AllExceptionsFilter.

Then, we take the Token (to skip the 401 error) and ask again:

Look at the console again:

Having made the obvious difference, look at errors.log, which is also included in the log:

In this way, uncaught errors in the code can be retrieved from the log.

conclusion

This article showed you how to use Log4JS to manage logging, build middleware and interceptors to log incoming and outgoing parameters, and use filters to handle exceptions.

The print format of the log can be typeset according to your preferences, not necessarily limited to this.

Good log management allows us to quickly fix bugs, cut down on overtime, avoid being a slave to capitalists, and focus our limited energy on limitless possibilities.

The next article will show you how to use Dtos to validate parameters and disentangle various if-else.

This article is included in the NestJS practical tutorial, more articles please pay attention to.

References:

Nest.js official documentation

Nest.js Chinese document

Node.js log4JS Completely explained

`