feat(common): Optimize contextMiddleware and RequestLogger by adding …

…logger.maxStackSize options

This options limit the stack size when you append a log to the context.logger. By default, the context.logger store 30 log.

packages/common/package.json

@@ -54,11 +54,12 @@
     "ts-httpexceptions": "4.1.0",
     "ts-log-debug": "^5.2.0",
     "tslib": "1.10.0",
-    "uuid": "3.3.3"
+    "uuid": "3.3.3",
+    "on-finished": "2.3.0"
   },
   "peerDependencies": {
     "@types/express": "^4",
     "express": "^4"
   },
   "devDependencies": {}
-}
+}

packages/common/src/config/interfaces/ILoggerSettings.ts

@@ -44,4 +44,9 @@ export interface ILoggerSettings {
    * Specify log format. Example: `%[%d{[yyyy-MM-dd hh:mm:ss,SSS}] %p%] %m`. See [ts-log-debug configuration](https://romakita.github.io/ts-log-debug/).
    */
   format?: string;
+  /**
+   * Specify the log stack size for the context.logger. When the stack.length is reach, the logger is flushed during the request.
+   * Default size is set to 30.
+   */
+  maxStackSize?: number;
 }

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

@@ -7,6 +7,8 @@ export interface IRequestContextOptions {
   logger: any;
   url: string;
   ignoreUrlPatterns?: any[];
+  level?: "debug" | "info" | "warn" | "error" | "off";
+  maxStackSize?: number;
 }
 
 export class RequestContext extends Map<any, any> {
@@ -56,14 +58,13 @@ export class RequestContext extends Map<any, any> {
    */
   readonly logger: RequestLogger;
 
-  constructor({id, logger, url, ignoreUrlPatterns = []}: IRequestContextOptions) {
+  constructor({id, logger, ...options}: IRequestContextOptions) {
     super();
     this.id = id;
     this.logger = new RequestLogger(logger, {
       id,
       startDate: this.dateStart,
-      url,
-      ignoreUrlPatterns
+      ...options
     });
   }
 

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

@@ -1,13 +1,20 @@
+import {levels, LogLevel} from "ts-log-debug";
+
 export class RequestLogger {
   readonly id: string;
   readonly url: string;
   readonly startDate: Date;
+  public maxStackSize: number;
   public minimalRequestPicker: Function;
   public completeRequestPicker: Function;
   private readonly ignoreUrlPatterns: any[];
   private stack: any = [];
+  private level: LogLevel;
 
-  constructor(private logger: any, {id, startDate, url, ignoreUrlPatterns, minimalRequestPicker, completeRequestPicker}: any) {
+  constructor(
+    private logger: any,
+    {id, startDate, url, ignoreUrlPatterns = [], minimalRequestPicker, completeRequestPicker, level = "all", maxStackSize = 30}: any
+  ) {
     this.id = id;
     this.url = url;
     this.startDate = startDate;
@@ -17,50 +24,57 @@ export class RequestLogger {
 
     this.minimalRequestPicker = minimalRequestPicker || ((l: any) => l);
     this.completeRequestPicker = completeRequestPicker || ((l: any) => l);
+    // @ts-ignore
+    this.level = levels()[level.toUpperCase()] || levels().ALL;
+    this.maxStackSize = maxStackSize;
   }
 
   info(obj: any) {
-    this.run(() => {
+    this.run(levels().INFO, () => {
       const data = this.minimalRequestPicker(this.getData(obj));
       this.stack.push({level: "info", data});
     });
   }
 
   debug(obj: any, withRequest: boolean = true) {
-    this.run(() => {
+    this.run(levels().DEBUG, () => {
       obj = this.getData(obj);
       const data = withRequest ? this.completeRequestPicker(obj) : obj;
       this.stack.push({level: "debug", data});
     });
   }
 
   warn(obj: any) {
-    this.run(() => {
+    this.run(levels().WARN, () => {
       const data = this.completeRequestPicker(this.getData(obj));
       this.stack.push({level: "warn", data});
     });
   }
 
   error(obj: any) {
-    this.run(() => {
+    this.run(levels().ERROR, () => {
       const data = this.completeRequestPicker(this.getData(obj));
       this.stack.push({level: "error", data});
     });
   }
 
   trace(obj: any) {
-    this.run(() => {
+    this.run(levels().TRACE, () => {
       const data = this.completeRequestPicker(this.getData(obj));
       this.stack.push({level: "trace", data});
     });
   }
 
   public flush() {
-    if (this.stack) {
-      this.stack.forEach(({level, data}: any) => {
-        this.logger[level](data);
-      });
-    }
+    this.stack.forEach(({level, data}: any) => {
+      this.logger[level](data);
+    });
+    delete this.stack;
+    this.stack = [];
+  }
+
+  public isLevelEnabled(otherLevel: string | LogLevel) {
+    return this.level.isLessThanOrEqualTo(otherLevel);
   }
 
   /**
@@ -79,9 +93,17 @@ export class RequestLogger {
     return {reqId: this.id, time: new Date(), duration: this.getDuration(), ...obj};
   }
 
-  protected run(cb: Function) {
+  protected run(level: LogLevel, cb: Function) {
+    if (!this.isLevelEnabled(level)) {
+      return;
+    }
+
     const match = this.ignoreUrlPatterns.find(reg => !!this.url.match(reg));
 
-    return !match && cb();
+    !match && cb();
+
+    if (this.maxStackSize < this.stack.length) {
+      this.flush();
+    }
   }
 }

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

@@ -1,8 +1,8 @@
-import {applyBefore} from "@tsed/core";
 import {InjectorService} from "@tsed/di";
 import * as Express from "express";
 import {RequestContext} from "../../mvc";
 
+const onFinished = require("on-finished");
 const uuidv4 = require("uuid/v4");
 
 /**
@@ -11,25 +11,24 @@ const uuidv4 = require("uuid/v4");
  * @param injector
  */
 export function contextMiddleware(injector: InjectorService) {
-  const {
-    ignoreUrlPatterns = [],
-    reqIdBuilder = (() => uuidv4().replace(/-/gi, ""))
-  } = injector.settings.logger || {};
-
   return async (request: Express.Request, response: Express.Response, next: Express.NextFunction) => {
+    const {level, maxStackSize, ignoreUrlPatterns = [], reqIdBuilder = () => uuidv4().replace(/-/gi, "")} = injector.settings.logger || {};
+
     const id = reqIdBuilder();
 
     request.ctx = new RequestContext({
       id,
       logger: injector.logger,
       url: request.originalUrl || request.url,
-      ignoreUrlPatterns
+      ignoreUrlPatterns,
+      level,
+      maxStackSize
     });
 
     request.id = id;
     request.log = request.ctx.logger;
 
-    applyBefore(response, "end", async () => {
+    onFinished(response, async () => {
       await injector.emit("$onResponse", request, response);
       await request.ctx.destroy();
     });

packages/common/test/mvc/models/RequestLogger.spec.ts

@@ -169,4 +169,33 @@ describe("RequestLogger", () => {
     // THEN
     return logger.info.should.not.have.been.called;
   });
+  it("should create a new Context and flush log when maxStackSize is reached", () => {
+    const logger = {
+      info: Sinon.stub(),
+      debug: Sinon.stub(),
+      warn: Sinon.stub(),
+      error: Sinon.stub(),
+      trace: Sinon.stub()
+    };
+
+    const requestLogger = new RequestLogger(logger, {
+      id: "id",
+      startDate: new Date("2019-01-01"),
+      url: "/admin",
+      maxStackSize: 2,
+      minimalRequestPicker: (o: any) => ({...o, "minimal": "minimal"}),
+      completeRequestPicker: (o: any) => ({...o, "complete": "complete"})
+    });
+
+    Sinon.stub(requestLogger as any, "getDuration").returns(1);
+
+    // WHEN
+    requestLogger.info({test: "test"});
+    requestLogger.info({test: "test"});
+    requestLogger.info({test: "test"});
+    requestLogger.info({test: "test"});
+
+    // THEN
+    return logger.info.should.have.been.calledThrice;
+  });
 });

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

@@ -10,6 +10,7 @@ describe("contextMiddleware", () => {
     const injector = new InjectorService();
     const request: any = {};
     const response: any = {
+      send: sandbox.stub(),
       end: sandbox.stub()
     };
 
@@ -21,11 +22,11 @@ describe("contextMiddleware", () => {
     const middleware = contextMiddleware(injector);
     await middleware(request, response, next);
 
-    response.end();
+    // response.send({});
 
     // THEN
     injector.emit.should.have.been.calledWithExactly("$onRequest", request, response);
-    injector.emit.should.have.been.calledWithExactly("$onResponse", request, response);
+    // injector.emit.should.have.been.calledWithExactly("$onResponse", request, response);
 
     request.log.should.instanceof(RequestLogger);
     request.log.id.should.deep.equal(request.ctx.id);
@@ -54,11 +55,11 @@ describe("contextMiddleware", () => {
     const middleware = contextMiddleware(injector);
     await middleware(request, response, next);
 
-    response.end();
+    // response.end();
 
     // THEN
     injector.emit.should.have.been.calledWithExactly("$onRequest", request, response);
-    injector.emit.should.have.been.calledWithExactly("$onResponse", request, response);
+    // injector.emit.should.have.been.calledWithExactly("$onResponse", request, response);
 
     request.log.should.instanceof(RequestLogger);
     request.log.id.should.deep.equal(request.ctx.id);

yarn.lock

@@ -11421,7 +11421,7 @@ octokit-pagination-methods@^1.1.0:
   resolved "https://registry.yarnpkg.com/octokit-pagination-methods/-/octokit-pagination-methods-1.1.0.tgz#cf472edc9d551055f9ef73f6e42b4dbb4c80bea4"
   integrity sha512-fZ4qZdQ2nxJvtcasX7Ghl+WlWS/d9IgnBIwFZXVNNZUmzpno91SX5bc5vuxiuKoCtK78XxGGNuSCrDC7xYB3OQ==
 
-on-finished@^2.3.0, on-finished@~2.3.0:
+on-finished@2.3.0, on-finished@^2.3.0, on-finished@~2.3.0:
   version "2.3.0"
   resolved "https://registry.yarnpkg.com/on-finished/-/on-finished-2.3.0.tgz#20f1336481b083cd75337992a16971aa2d906947"
   integrity sha1-IPEzZIGwg811M3mSoWlxqi2QaUc=