fix(common): Refactoring contextMiddleware to fix memory leaks

packages/common/src/mvc/models/RequestContext.ts

@@ -58,27 +58,31 @@ export class RequestContext extends Map<any, any> {
    * Logger attached to the context request.
    */
   public logger: RequestLogger;
-  /**
-   *
-   */
+
   public injector: InjectorService;
 
   constructor({id, injector, logger, ...options}: IRequestContextOptions) {
     super();
     this.id = id;
+
+    injector && (this.injector = injector);
+
     this.logger = new RequestLogger(logger, {
       id,
       startDate: this.dateStart,
       ...options
     });
-    // @ts-ignore
-    this.injector = injector;
   }
 
   async destroy() {
     await this.container.destroy();
+    this.logger.destroy();
     delete this.container;
     delete this.logger;
     delete this.injector;
   }
+
+  async emit(eventName: string, ...args: any[]) {
+    return this.injector && this.injector.emit(eventName, args);
+  }
 }

packages/common/src/mvc/models/RequestLogger.ts

@@ -66,17 +66,27 @@ export class RequestLogger {
   }
 
   public flush() {
-    this.stack.forEach(({level, data}: any) => {
-      this.logger[level](data);
-    });
-    delete this.stack;
-    this.stack = [];
+    if (this.stack.length) {
+      this.stack.forEach(({level, data}: any) => {
+        this.logger[level](data);
+      });
+
+      this.stack = [];
+    }
   }
 
   public isLevelEnabled(otherLevel: string | LogLevel) {
     return this.level.isLessThanOrEqualTo(otherLevel);
   }
 
+  destroy() {
+    this.flush();
+    delete this.logger;
+    delete this.stack;
+    delete this.minimalRequestPicker;
+    delete this.completeRequestPicker;
+  }
+
   /**
    * Return the duration between the time when LogIncomingRequest has handle the request and now.
    * @returns {number}

packages/common/src/server/components/LogIncomingRequestMiddleware.ts

@@ -8,12 +8,17 @@ import {IMiddleware, Middleware, Req, Res} from "../../mvc";
 @Middleware()
 export class LogIncomingRequestMiddleware implements IMiddleware {
   protected static DEFAULT_FIELDS = ["reqId", "method", "url", "duration"];
+  $onResponse: any;
   protected settings: ILoggerSettings;
 
   // tslint:disable-next-line: no-unused-variable
-  constructor(protected injector: InjectorService) {
+  constructor(injector: InjectorService) {
     this.settings = injector.settings.logger || {};
     this.settings.requestFields = this.settings.requestFields || LogIncomingRequestMiddleware.DEFAULT_FIELDS;
+
+    if (this.settings.level !== "off") {
+      this.$onResponse = this.onLogEnd;
+    }
   }
 
   /**
@@ -25,10 +30,6 @@ export class LogIncomingRequestMiddleware implements IMiddleware {
     this.onLogStart(request);
   }
 
-  $onResponse(request: Req, response: Res) {
-    this.onLogEnd(request, response);
-  }
-
   /**
    * The separate onLogStart() function will allow developer to overwrite the initial request log.
    * @param {e.Request} request
@@ -55,7 +56,7 @@ export class LogIncomingRequestMiddleware implements IMiddleware {
    * @param response
    */
   protected onLogEnd(request: Req, response: Res) {
-    const {debug, logRequest, logEnd} = this.injector.settings.logger;
+    const {debug, logRequest, logEnd} = this.settings;
 
     if (logEnd !== false) {
       if (debug) {
@@ -108,9 +109,10 @@ export class LogIncomingRequestMiddleware implements IMiddleware {
    * @returns {Object}
    */
   protected minimalRequestPicker(request: Req): any {
+    const {requestFields} = this.settings;
     const info = this.requestToObject(request);
 
-    return this.settings.requestFields!.reduce((acc: any, key: string) => {
+    return requestFields!.reduce((acc: any, key: string) => {
       acc[key] = info[key];
 
       return acc;

packages/common/src/server/components/ServerLoader.ts

@@ -417,7 +417,7 @@ export abstract class ServerLoader implements IServerLifecycle {
   protected async loadMiddlewares(): Promise<any> {
     this.injector.logger.debug("Mount middlewares");
     this.use(contextMiddleware(this.injector));
-    this.use(LogIncomingRequestMiddleware); // FIXME will be deprecated
+    this.settings.logger.level !== "off" && this.use(LogIncomingRequestMiddleware); // FIXME will be deprecated
 
     await this.callHook("$onMountingMiddlewares");
     await this.callHook("$beforeRoutesInit"); // deprecated
@@ -447,6 +447,7 @@ export abstract class ServerLoader implements IServerLifecycle {
 
     this.routes = providers.filter(provider => !!provider.route).map(({route, token}) => ({route, token}));
   }
+
   /**
    * Create a new server from settings parameters.
    * @param http

packages/common/src/server/utils/contextMiddleware.ts

@@ -1,47 +1,70 @@
 import {InjectorService} from "@tsed/di";
-import * as Express from "express";
 import {RequestContext} from "../../mvc";
 
 const onFinished = require("on-finished");
 const uuidv4 = require("uuid/v4");
 
-const whenFinished = (request: any, response: any) => async () => {
-  const {injector} = request.ctx;
+const defaultReqIdBuilder = () => uuidv4().replace(/-/gi, "");
 
-  await injector.emit("$onResponse", request, response);
-  await request.ctx.destroy();
-  delete request.ctx;
-  delete request.log;
-};
+export class ContextMiddleware {
+  level: "debug" | "info" | "warn" | "error" | "off" | undefined;
+  maxStackSize: number;
+  ignoreUrlPatterns: string[];
+  reqIdBuilder: any;
 
-/**
- * Bind request and create a new context to store information during the request lifecycle. See @@RequestContext@@ for more details.
- *
- * @param injector
- */
-export function contextMiddleware(injector: InjectorService) {
-  const {level, maxStackSize, ignoreUrlPatterns = [], reqIdBuilder = () => uuidv4().replace(/-/gi, "")} = injector.settings.logger || {};
+  constructor(private injector: InjectorService) {
+    const {level, maxStackSize, ignoreUrlPatterns = [], reqIdBuilder = defaultReqIdBuilder} = injector.settings.logger || {};
+
+    this.level = level;
+    this.maxStackSize = maxStackSize!;
+    this.ignoreUrlPatterns = ignoreUrlPatterns;
+    this.reqIdBuilder = reqIdBuilder;
+  }
+
+  async use(request: any, response: any, next: any) {
+    const {level, ignoreUrlPatterns, maxStackSize} = this;
+
+    const id = this.reqIdBuilder();
 
-  return async (request: Express.Request, response: Express.Response, next: Express.NextFunction) => {
-    const id = reqIdBuilder();
     request.ctx = new RequestContext({
       id,
-      logger: injector.logger,
+      logger: this.injector.logger,
       url: request.originalUrl || request.url,
       ignoreUrlPatterns,
       level,
       maxStackSize,
-      injector
+      injector: this.injector
     });
 
-    request.id = id;
     // deprecated
     request.log = request.ctx.logger;
 
-    onFinished(response, whenFinished(request, response));
+    onFinished(response, ContextMiddleware.onClose);
 
-    await injector.emit("$onRequest", request, response);
+    await this.injector.emit("$onRequest", request, response);
 
     next();
-  };
+  }
+
+  static async onClose(err: any, response: any) {
+    const {req: request} = response;
+    try {
+      await request.ctx.emit("$onResponse", request, response);
+      await request.ctx.destroy();
+    } catch (er) {}
+
+    delete request.ctx;
+    delete request.log;
+  }
+}
+
+/**
+ * Bind request and create a new context to store information during the request lifecycle. See @@RequestContext@@ for more details.
+ *
+ * @param injector
+ */
+export function contextMiddleware(injector: InjectorService) {
+  const middleware = new ContextMiddleware(injector);
+
+  return middleware.use.bind(middleware);
 }

packages/common/test/server/utils/contextMiddleware.spec.ts

@@ -11,7 +11,8 @@ describe("contextMiddleware", () => {
     const request: any = {};
     const response: any = {
       send: sandbox.stub(),
-      end: sandbox.stub()
+      end: sandbox.stub(),
+      req: request
     };
 
     const next = sandbox.stub();
@@ -37,7 +38,8 @@ describe("contextMiddleware", () => {
     const injector = new InjectorService();
     const request: any = {};
     const response: any = {
-      end: sandbox.stub()
+      end: sandbox.stub(),
+      req: request
     };
 
     const next = sandbox.stub();

packages/test-artillery/.gitignore

@@ -0,0 +1,2 @@
+stats.json
+.tmp

packages/test-artillery/Dockerfile

@@ -0,0 +1,30 @@
+###############################################################################
+###############################################################################
+##                      _______ _____ ______ _____                           ##
+##                     |__   __/ ____|  ____|  __ \                          ##
+##                        | | | (___ | |__  | |  | |                         ##
+##                        | |  \___ \|  __| | |  | |                         ##
+##                        | |  ____) | |____| |__| |                         ##
+##                        |_| |_____/|______|_____/                          ##
+##                                                                           ##
+## description     : Dockerfile for TsED Application                         ##
+## author          : TsED team                                               ##
+## date            : 20190820                                                ##
+## version         : 1.0                                                     ##
+###############################################################################
+###############################################################################
+FROM node:12.13.0-alpine
+
+RUN apk update && apk add build-base git python
+
+COPY package.json .
+COPY ./src ./src
+COPY ./lib ./lib
+
+RUN yarn install --production
+
+EXPOSE 8081
+ENV PORT 8081
+ENV NODE_ENV production
+
+CMD ["yarn", "start:prod"]

packages/test-artillery/docker-compose.yml

@@ -0,0 +1,17 @@
+version: '3.3'
+services:
+  server:
+    build:
+      context: ./
+      dockerfile: Dockerfile
+      args:
+        - http_proxy
+        - https_proxy
+        - no_proxy
+    image: tsed/test-artillery:latest
+    ports:
+      - "3000:3000"
+      - "9229:9229"
+    stdin_open: true  # -i
+    tty: true         # -t
+

packages/test-artillery/package.json

@@ -0,0 +1,48 @@
+{
+  "name": "@tsed/test-artillery",
+  "version": "5.42.1",
+  "description": "Artillery test packages",
+  "main": "./lib/index.js",
+  "typings": "./lib/index.d.ts",
+  "scripts": {
+    "start": "node --expose-gc -r ts-node/register -r tsconfig-paths/register src/index.ts",
+    "start:express": "node --inspect --expose-gc test/server/express.js",
+    "start:prod": "node --expose-gc lib/index.js",
+    "build": "tsc --build tsconfig.compile.json",
+    "test:artillery": "artillery run test/test.yml",
+    "docker:build": "docker-compose build",
+    "docker:upd": "docker-compose up -d",
+    "docker:up": "docker-compose up",
+    "docker:down": "docker-compose down",
+    "plot": "yarn start && python plot.py",
+    "plot:express": "yarn start:express && python plot.py"
+  },
+  "dependencies": {
+    "@tsed/ajv": "5.42.1",
+    "@tsed/common": "5.42.1",
+    "@tsed/core": "5.42.1",
+    "@tsed/di": "5.42.1",
+    "@tsed/graphql": "5.42.1",
+    "@tsed/mongoose": "5.42.1",
+    "@tsed/multipartfiles": "5.42.1",
+    "@tsed/passport": "5.42.1",
+    "@tsed/seq": "5.42.1",
+    "@tsed/servestatic": "5.42.1",
+    "@tsed/swagger": "5.42.1",
+    "@tsed/testing": "5.42.1",
+    "@tsed/typeorm": "5.42.1",
+    "express": "4.17.1",
+    "compression": "1.7.4",
+    "body-parser": "1.19.0",
+    "cookie-parser": "1.4.4",
+    "method-override": "3.0.0"
+  },
+  "devDependencies": {
+    "@types/compression": "1.7.0",
+    "@types/body-parser": "1.19.0",
+    "@types/method-override": "0.0.31",
+    "artillery": "^1.6.0-29",
+    "heapdump": "0.3.15"
+  },
+  "private": true
+}

packages/test-artillery/plot.py

@@ -0,0 +1,16 @@
+#!/usr/bin/env python
+
+import matplotlib.pyplot as plt
+import json
+
+statsFile = open('.tmp/stats.json', 'r')
+stats = json.load(statsFile)
+heapSizes = stats[1]
+timestamps = stats[0]
+
+print('Plotting %s' % ', '.join(map(str, heapSizes)))
+
+plt.plot(timestamps, heapSizes)
+plt.ylabel('Heap Size')
+plt.xlabel('timestamp (ms)')
+plt.show()