Repository: pinojs/pino-http
Pull request #177 (2021-11-17 18:58:02)

Add request received event (customReceivedMessage)
Change:

* add request received event (customReceivedMessage)
* add yarn.lock to .gitignore
* add t.end() to some test

Please review and merge to upstream.


Patch:
diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml
index 0e87e47..aea443d 100644
--- a/.github/workflows/ci.yml
+++ b/.github/workflows/ci.yml
@@ -37,6 +37,6 @@ jobs:
     needs: build
     runs-on: ubuntu-latest
     steps:
-      - uses: fastify/github-action-merge-dependabot@v2.5.0
+      - uses: fastify/github-action-merge-dependabot@v2.6.0
         with:
           github-token: ${{ secrets.GITHUB_TOKEN }}
diff --git a/.gitignore b/.gitignore
index 7829623..602a593 100644
--- a/.gitignore
+++ b/.gitignore
@@ -43,3 +43,4 @@ profile*
 
 # lockfile
 package-lock.json
+yarn.lock
diff --git a/README.md b/README.md
index 990605d..a4a31d4 100644
--- a/README.md
+++ b/README.md
@@ -96,12 +96,13 @@ $ node example.js | pino-pretty
 * `logger`: parent pino instance for a child logger instance, which will be used by `pino-http`. To refer to this child instance, use [pinoHttp.logger](#pinohttplogger-plogger)
 * `genReqId`: you can pass a function which gets used to generate a request id. The first argument is the request itself. As fallback `pino-http` is just using an integer. This default might not be the desired behavior if you're running multiple instances of the app
 * `useLevel`: the logger level `pino-http` is using to log out the response. default: `info`
-* `customLogLevel`: set to a `function (res, err) => { /* returns level name string */ }`. This function will be invoked to determine the level at which the log should be issued. This option is mutually exclusive with the `useLevel` option. The first argument is the HTTP response. The second argument is an error object if an error has occurred in the request.
+* `customLogLevel`: set to a `function (res, err, req) => { /* returns level name string */ }`. This function will be invoked to determine the level at which the log should be issued. This option is mutually exclusive with the `useLevel` option. The first argument is the HTTP response. The second argument is an error object if an error has occurred in the request.
 * `autoLogging`: set to `false`, to disable the automatic "request completed" and "request errored" logging. Defaults to `true`. If set to an object, you can provide more options.
 * `autoLogging.ignore`: set to a `function (req) => { /* returns boolean */ }`. Useful for defining logic based on req properties (such as a user-agent header) to ignore successful requests.
 * `autoLogging.ignorePaths`: array that holds one or many paths that should not autolog on completion. Paths will be matched exactly to the url path `req.url` (using Node class `URL.pathname`). This is useful for ignoring e.g. health check paths that get called every X seconds, and would fill out the logs unnecessarily. If the path matches and succeeds (http 200), it will not log any text. If it fails, it will log the error (as with any other path).
 * `autoLogging.getPath`: set to a `function (req) => { /* returns path string */ }`. This function will be invoked to return the current path as a string. This is useful for checking `autoLogging.ignorePaths` against a path other than the default `req.url`. e.g. An express server where `req.originalUrl` is preferred.
 * `stream`: same as the second parameter
+* `customReceivedMessage`: set to a `function (req, res) => { /* returns message string */ }` This function will be invoked at each request received, setting "msg" property to returned string. If not set, nothing value will be used.
 * `customSuccessMessage`: set to a `function (res) => { /* returns message string */ }` This function will be invoked at each successful response, setting "msg" property to returned string. If not set, default value will be used.
 * `customErrorMessage`: set to a `function (err, res) => { /* returns message string */ }` This function will be invoked at each failed response, setting "msg" property to returned string. If not set, default value will be used.
 * `customAttributeKeys`: allows the log object attributes added by `pino-http` to be given custom keys. Accepts an object of format `{ [original]: [override] }`. Attributes available for override are `req`, `res`, `err`, `responseTime` and, when using quietReqLogger, `reqId`.
@@ -159,6 +160,11 @@ const logger = require('pino-http')({
     return 'request completed'
   },
 
+  // Define a custom receive message
+  customReceivedMessage: function (req, _res) {
+    return 'request received: ' + req.method
+  },
+
   // Define a custom error message
   customErrorMessage: function (error, res) {
     return 'request errored with status code: ' + res.statusCode
diff --git a/index.d.ts b/index.d.ts
new file mode 100644
index 0000000..37b5549
--- /dev/null
+++ b/index.d.ts
@@ -0,0 +1,69 @@
+// Type definitions for pino-http 6.0
+// Project: https://github.com/pinojs/pino-http#readme
+// Definitions by: Christian Rackerseder <https://github.com/screendriver>
+//                 Jeremy Forsythe <https://github.com/jdforsythe>
+//                 Griffin Yourick <https://github.com/tough-griff>
+//                 Jorge Barnaby <https://github.com/yorch>
+//                 Jose Ramirez <https://github.com/jarcodallo>
+// Definitions: https://github.com/DefinitelyTyped/DefinitelyTyped
+// TypeScript Version: 4.0
+/// <reference types="node"/>
+
+import { IncomingMessage, ServerResponse } from 'http';
+import pino from 'pino';
+import { SerializedError, SerializedRequest, SerializedResponse } from 'pino-std-serializers';
+
+declare function pinoHttp(opts?: Options, stream?: pino.DestinationStream): HttpLogger;
+
+declare function pinoHttp(stream?: pino.DestinationStream): HttpLogger;
+
+interface HttpLogger {
+    (req: IncomingMessage, res: ServerResponse, next?: () => void): void;
+    logger: pino.Logger;
+}
+type ReqId = number | string | object;
+
+interface Options extends pino.LoggerOptions {
+    logger?: pino.Logger | undefined;
+    genReqId?: GenReqId | undefined;
+    useLevel?: pino.Level | undefined;
+    stream?: pino.DestinationStream | undefined;
+    autoLogging?: boolean | AutoLoggingOptions | undefined;
+    customLogLevel?: ((res: ServerResponse, error: Error) => pino.Level) | undefined;
+    customSuccessMessage?: ((res: ServerResponse) => string) | undefined;
+    customErrorMessage?: ((error: Error, res: ServerResponse) => string) | undefined;
+    customAttributeKeys?: CustomAttributeKeys | undefined;
+    wrapSerializers?: boolean | undefined;
+    reqCustomProps?: ((req: IncomingMessage, res: ServerResponse) => object) | undefined;
+    quietReqLogger?: boolean | undefined;
+}
+
+interface GenReqId {
+    (req: IncomingMessage): ReqId;
+}
+
+interface AutoLoggingOptions {
+    ignore?: ((req: IncomingMessage) => boolean);
+    ignorePaths?: Array<string | RegExp> | undefined;
+    getPath?: ((req: IncomingMessage) => string | undefined) | undefined;
+}
+
+interface CustomAttributeKeys {
+    req?: string | undefined;
+    res?: string | undefined;
+    err?: string | undefined;
+    reqId?: string | undefined;
+    responseTime?: string | undefined;
+}
+
+interface StdSerializers {
+    err: SerializedError;
+    req: SerializedRequest;
+    res: SerializedResponse;
+}
+
+export default pinoHttp;
+
+export const startTime: unique symbol;
+
+export const stdSerializers: StdSerializers;
\ No newline at end of file
diff --git a/logger.js b/logger.js
index d16e685..8230f31 100644
--- a/logger.js
+++ b/logger.js
@@ -40,7 +40,22 @@ function pinoLogger (opts, stream) {
     throw new Error("You can't pass 'useLevel' and 'customLogLevel' together")
   }
 
-  const useLevel = opts.useLevel || 'info'
+  const LOG_LEVEL_STRS = ['trace', 'debug', 'info', 'warn', 'error', 'fatal', 'silent']
+  function getValidLogLevel (level, defaultValue = 'info') {
+    if (level && typeof level === 'string') {
+      const logLevel = level.trim().toLowerCase()
+      if (LOG_LEVEL_STRS.includes(logLevel) === true) {
+        return logLevel
+      }
+    }
+    return defaultValue
+  }
+
+  function getLogLevelFromCustomLogLevel (customLogLevel, useLevel, res, err, req) {
+    return customLogLevel ? getValidLogLevel(customLogLevel(res, err, req), useLevel) : useLevel
+  }
+
+  const useLevel = getValidLogLevel(opts.useLevel)
   const customLogLevel = opts.customLogLevel
   delete opts.useLevel
   delete opts.customLogLevel
@@ -54,6 +69,7 @@ function pinoLogger (opts, stream) {
   const autoLoggingGetPath = opts.autoLogging && opts.autoLogging.getPath ? opts.autoLogging.getPath : null
   delete opts.autoLogging
 
+  const receivedMessage = opts.customReceivedMessage && typeof opts.customReceivedMessage === 'function' ? opts.customReceivedMessage : undefined
   const successMessage = opts.customSuccessMessage || function () { return 'request completed' }
   const errorMessage = opts.customErrorMessage || function () { return 'request errored' }
   delete opts.customSuccessfulMessage
@@ -72,7 +88,7 @@ function pinoLogger (opts, stream) {
 
     const log = this.log
     const responseTime = Date.now() - this[startTime]
-    const level = customLogLevel ? customLogLevel(this, err) : useLevel
+    const level = getLogLevelFromCustomLogLevel(customLogLevel, useLevel, this, err)
 
     if (err || this.err || this.statusCode >= 500) {
       const error = err || this.err || new Error('failed with status code ' + this.statusCode)
@@ -133,6 +149,11 @@ function pinoLogger (opts, stream) {
       }
 
       if (shouldLogSuccess) {
+        if (receivedMessage !== undefined) {
+          const level = getLogLevelFromCustomLogLevel(customLogLevel, useLevel, res, undefined, req)
+          log[level]({}, receivedMessage(req, res))
+        }
+
         res.on('finish', onResFinished)
       }
 
diff --git a/package.json b/package.json
index 54b8263..c99f004 100644
--- a/package.json
+++ b/package.json
@@ -1,8 +1,9 @@
 {
   "name": "pino-http",
-  "version": "6.0.0",
+  "version": "6.1.0",
   "description": "High-speed HTTP logger for Node.js",
   "main": "logger.js",
+  "types": "index.d.ts",
   "dependencies": {
     "fast-url-parser": "^1.1.3",
     "get-caller-file": "^2.0.5",
@@ -10,18 +11,24 @@
     "pino-std-serializers": "^4.0.0"
   },
   "devDependencies": {
+    "@types/node": "^16.11.0",
     "autocannon": "^7.3.0",
     "coveralls": "^3.0.0",
     "http-ndjson": "^3.1.0",
+    "pino-pretty": "^7.1.0",
     "pre-commit": "^1.1.2",
     "split2": "^4.0.0",
     "standard": "^16.0.3",
-    "tap": "^15.0.0"
+    "tap": "^15.0.0",
+    "ts-node": "^10.3.0",
+    "tsd": "^0.19.0",
+    "typescript": "^4.4.4"
   },
   "scripts": {
     "benchmark": "bash ./scripts/benchmark-all",
-    "test": "standard && tap test.js",
-    "fix": "standard --fix"
+    "test": "standard && tap test.js && npm run test-types",
+    "fix": "standard --fix",
+    "test-types": "tsc && tsd && ts-node index.test-d.ts"
   },
   "author": "David Mark Clements",
   "contributors": [
diff --git a/tsconfig.json b/tsconfig.json
new file mode 100644
index 0000000..6e66603
--- /dev/null
+++ b/tsconfig.json
@@ -0,0 +1,15 @@
+{
+  "compilerOptions": {
+    "target": "es6",
+    "esModuleInterop": true,
+    "lib": [ "es2015" ],
+    "module": "commonjs",
+    "noEmit": true,
+    "strict": true,
+    "moduleResolution": "node",
+  },
+  "include": [
+    "./*.test-d.ts",
+    "./*.d.ts"
+  ]
+}
\ No newline at end of file


Test patch:
diff --git a/index.test-d.ts b/index.test-d.ts
new file mode 100644
index 0000000..7a041c8
--- /dev/null
+++ b/index.test-d.ts
@@ -0,0 +1,35 @@
+
+/// <reference path="./index.d.ts"/>
+
+import { Writable } from 'stream';
+import { IncomingMessage, ServerResponse } from 'http';
+import pino from 'pino';
+import pinoHttp from './';
+
+const logger = pino();
+
+pinoHttp({ logger });
+pinoHttp({ logger }).logger = logger;
+pinoHttp({ genReqId: (req: IncomingMessage) => req.statusCode || 200 });
+pinoHttp({ genReqId: (req: IncomingMessage) => 'foo' });
+pinoHttp({ genReqId: (req: IncomingMessage) => Buffer.allocUnsafe(16) });
+pinoHttp({ useLevel: 'error' });
+pinoHttp({ prettyPrint: true }); // deprecated but still present in pino.
+pinoHttp({ transport: { target: 'pino-pretty', options: { colorize: true } } });
+pinoHttp({ autoLogging: false });
+pinoHttp({ autoLogging: { ignore: (req: IncomingMessage) => req.headers['user-agent'] === 'ELB-HealthChecker/2.0' } });
+pinoHttp({ autoLogging: { ignorePaths: ['/health'] } });
+pinoHttp({ autoLogging: { ignorePaths: [/\/health/] } });
+pinoHttp({ autoLogging: { ignorePaths: ['/health'], getPath: (req: IncomingMessage) => req.url } });
+pinoHttp({ customSuccessMessage: (req: ServerResponse) => 'Success' });
+pinoHttp({ customErrorMessage: (error: Error, res: ServerResponse) => `Error - ${error}` });
+pinoHttp({ customAttributeKeys: { req: 'req' } });
+pinoHttp({ customAttributeKeys: { res: 'res' } });
+pinoHttp({ customAttributeKeys: { err: 'err' } });
+pinoHttp({ customAttributeKeys: { responseTime: 'responseTime' } });
+pinoHttp({ customAttributeKeys: { req: 'req', res: 'res', err: 'err', responseTime: 'responseTime' } });
+pinoHttp({ customLogLevel: (res: ServerResponse, error: Error) => 'info' });
+pinoHttp({ reqCustomProps: (req: IncomingMessage, res: ServerResponse) => ({ key1: 'value1', 'x-key-2': 'value2' }) });
+pinoHttp({ wrapSerializers: false });
+pinoHttp(new Writable());
+pinoHttp({ quietReqLogger: true, customAttributeKeys: { reqId: 'reqId' }});
diff --git a/test.js b/test.js
index 3a66e1c..4871a4c 100644
--- a/test.js
+++ b/test.js
@@ -10,6 +10,10 @@ const { join } = require('path')
 const ERROR_URL = '/make-error'
 const noop = function () {}
 
+const DEFAULT_REQUEST_RECEIVED_MSG = 'request received'
+const DEFAULT_REQUEST_COMPLETED_MSG = 'request completed'
+const DEFAULT_REQUEST_ERROR_MSG = 'request errored'
+
 function setup (t, logger, cb, handler, next) {
   const server = http.createServer(handler || function (req, res) {
     logger(req, res, next)
@@ -54,7 +58,7 @@ test('default settings', function (t) {
   dest.on('data', function (line) {
     t.ok(line.req, 'req is defined')
     t.ok(line.res, 'res is defined')
-    t.equal(line.msg, 'request completed', 'message is set')
+    t.equal(line.msg, DEFAULT_REQUEST_COMPLETED_MSG, 'message is set')
     t.equal(line.req.method, 'GET', 'method is get')
     t.equal(line.res.statusCode, 200, 'statusCode is 200')
     t.end()
@@ -73,7 +77,7 @@ test('stream in options', function (t) {
   dest.on('data', function (line) {
     t.ok(line.req, 'req is defined')
     t.ok(line.res, 'res is defined')
-    t.equal(line.msg, 'request completed', 'message is set')
+    t.equal(line.msg, DEFAULT_REQUEST_COMPLETED_MSG, 'message is set')
     t.equal(line.req.method, 'GET', 'method is get')
     t.equal(line.res.statusCode, 200, 'statusCode is 200')
     t.end()
@@ -94,6 +98,7 @@ test('add transport.caller information when missing', function (t) {
   const logger = pinoHttp(options)
   logger.logger.info('hello world')
   t.equal(options.transport.caller, join(__dirname, 'logger.js'), 'caller is set')
+  t.end()
 })
 
 test('exposes the internal pino', function (t) {
@@ -104,6 +109,7 @@ test('exposes the internal pino', function (t) {
 
   dest.on('data', function (line) {
     t.equal(line.msg, 'hello world')
+    t.end()
   })
 
   logger.logger.info('hello world')
@@ -128,7 +134,7 @@ test('uses the log level passed in as an option', function (t) {
 test('uses the custom log level passed in as an option', function (t) {
   const dest = split(JSON.parse)
   const logger = pinoHttp({
-    customLogLevel: function (res, err) {
+    customLogLevel: function (_res, _err, _req) {
       return 'warn'
     }
   }, dest)
@@ -145,12 +151,32 @@ test('uses the custom log level passed in as an option', function (t) {
   })
 })
 
+test('uses the custom invalid log level passed in as an option', function (t) {
+  const dest = split(JSON.parse)
+  const logger = pinoHttp({
+    customLogLevel: function (_res, _err, _req) {
+      return 'error-log-level'
+    }
+  }, dest)
+
+  setup(t, logger, function (err, server) {
+    t.error(err)
+    doGet(server)
+  })
+
+  dest.on('data', function (line) {
+    t.equal(line.level, 30, 'level')
+    t.notOk(line.customLogLevel, 'customLogLevel not forwarded')
+    t.end()
+  })
+})
+
 test('throw error if custom log level and log level passed in together', function (t) {
   const dest = split(JSON.parse)
   const throwFunction = function () {
     pinoHttp({
       useLevel: 'info',
-      customLogLevel: function (res, err) {
+      customLogLevel: function (_res, _err, _req) {
         return 'warn'
       }
     }, dest)
@@ -199,6 +225,7 @@ test('uses a custom genReqId function', function (t) {
   dest.on('data', function (line) {
     t.equal(typeof line.req.id, 'string')
     t.equal(line.req.id, idToTest)
+    t.end()
   })
 })
 
@@ -221,6 +248,7 @@ test('reuses existing req.id if present', function (t) {
 
   dest.on('data', function (line) {
     t.equal(line.req.id, someId)
+    t.end()
   })
 })
 
@@ -274,7 +302,7 @@ test('responseTime for errored request', function (t) {
 
   dest.on('data', function (line) {
     t.ok(line.responseTime >= 0, 'responseTime is defined')
-    t.equal(line.msg, 'request errored', 'message is set')
+    t.equal(line.msg, DEFAULT_REQUEST_ERROR_MSG, 'message is set')
     t.end()
   })
 })
@@ -460,7 +488,7 @@ test('support a custom instance', function (t) {
   dest.on('data', function (line) {
     t.ok(line.req, 'req is defined')
     t.ok(line.res, 'res is defined')
-    t.equal(line.msg, 'request completed', 'message is set')
+    t.equal(line.msg, DEFAULT_REQUEST_COMPLETED_MSG, 'message is set')
     t.equal(line.req.method, 'GET', 'method is get')
     t.equal(line.res.statusCode, 200, 'statusCode is 200')
     t.end()
@@ -491,7 +519,7 @@ test('support a custom instance with custom genReqId function', function (t) {
     t.ok(line.req, 'req is defined')
     t.ok(line.res, 'res is defined')
     t.notOk(line.genReqId)
-    t.equal(line.msg, 'request completed', 'message is set')
+    t.equal(line.msg, DEFAULT_REQUEST_COMPLETED_MSG, 'message is set')
     t.equal(line.req.method, 'GET', 'method is get')
     t.equal(line.res.statusCode, 200, 'statusCode is 200')
     t.end()
@@ -547,6 +575,7 @@ test('does not return excessively long object', function (t) {
 
   dest.on('data', function (obj) {
     t.equal(Object.keys(obj.req).length, 6)
+    t.end()
   })
 })
 
@@ -559,6 +588,7 @@ test('err.raw is available to custom serializers', function (t) {
     serializers: {
       err (err) {
         t.equal(err.raw, error)
+        t.end()
       }
     }
   })
@@ -609,6 +639,7 @@ test('res.raw is available to custom serializers', function (t) {
       res: function (res) {
         t.ok(res.raw)
         t.ok(res.raw.statusCode)
+        t.end()
         return res
       }
     }
@@ -634,6 +665,7 @@ test('res.raw is not enumerable', function (t) {
     serializers: {
       res: function (res) {
         t.equal(Object.prototype.propertyIsEnumerable.call(res, 'raw'), false)
+        t.end()
         return res
       }
     }
@@ -698,6 +730,7 @@ test('req.id has a non-function value', function (t) {
     serializers: {
       req: function (req) {
         t.equal(typeof req.id === 'function', false)
+        t.end()
         return req
       }
     }
@@ -735,6 +768,51 @@ test('uses the custom successMessage callback if passed in as an option', functi
   })
 })
 
+test('uses the custom receivedMessage callback if passed in as an option', function (t) {
+  const dest = split(JSON.parse)
+  const message = DEFAULT_REQUEST_RECEIVED_MSG
+  const logger = pinoHttp({
+    customReceivedMessage: function (_req, _res) {
+      return message
+    }
+  }, dest)
+
+  setup(t, logger, function (err, server) {
+    t.error(err)
+    doGet(server)
+  })
+
+  dest.on('data', function (line) {
+    if (line.msg === DEFAULT_REQUEST_COMPLETED_MSG) {
+      return
+    }
+    t.equal(line.msg, message)
+    t.end()
+  })
+})
+
+test('receve receivedMessage before successMessage', function (t) {
+  t.plan(3)
+  const dest = split(JSON.parse)
+  const message = DEFAULT_REQUEST_RECEIVED_MSG
+  const logger = pinoHttp({
+    customReceivedMessage: function (_req, _res) {
+      return message
+    }
+  }, dest)
+
+  setup(t, logger, function (err, server) {
+    t.error(err)
+    doGet(server, null, function () {
+      t.equal(dest.read().msg, DEFAULT_REQUEST_RECEIVED_MSG)
+
+      t.equal(dest.read().msg, DEFAULT_REQUEST_COMPLETED_MSG)
+
+      t.end()
+    })
+  })
+})
+
 test('uses the custom errorMessage callback if passed in as an option', function (t) {
   const dest = split(JSON.parse)
   const customErrorMessage = 'Custom error message'
@@ -755,6 +833,28 @@ test('uses the custom errorMessage callback if passed in as an option', function
   })
 })
 
+test('receve receivedMessage before errorMessage', function (t) {
+  t.plan(3)
+  const dest = split(JSON.parse)
+  const message = DEFAULT_REQUEST_RECEIVED_MSG
+  const logger = pinoHttp({
+    customReceivedMessage: function (_req, _res) {
+      return message
+    }
+  }, dest)
+
+  setup(t, logger, function (err, server) {
+    t.error(err)
+    doGet(server, ERROR_URL, function () {
+      t.equal(dest.read().msg, DEFAULT_REQUEST_RECEIVED_MSG)
+
+      t.equal(dest.read().msg, DEFAULT_REQUEST_ERROR_MSG)
+
+      t.end()
+    })
+  })
+})
+
 test('uses custom log object attribute keys when provided, successful request', function (t) {
   const dest = split(JSON.parse)
   const logger = pinoHttp({
@@ -905,7 +1005,9 @@ test('auto logging and next callback', function (t) {
     t.error(err)
     doGet(server, null, function () {
       const line = dest.read()
-      t.equal(line.msg, 'request completed')
+      t.equal(line.msg, DEFAULT_REQUEST_COMPLETED_MSG)
+
+      t.end()
     })
   }, function (req, res) {
     logger(req, res, function () {
@@ -937,9 +1039,11 @@ test('quiet request logging', function (t) {
       t.notOk(quietLine.req)
 
       const responseLine = dest.read()
-      t.equal(responseLine.msg, 'request completed')
+      t.equal(responseLine.msg, DEFAULT_REQUEST_COMPLETED_MSG)
       t.equal(responseLine.reqId, 'testId')
       t.ok(responseLine.req)
+
+      t.end()
     })
   }, handler)
 })
@@ -966,9 +1070,11 @@ test('quiet request logging - custom request id key', function (t) {
       t.equal(quietLine.customRequestId, 'testId')
 
       const responseLine = dest.read()
-      t.equal(responseLine.msg, 'request completed')
+      t.equal(responseLine.msg, DEFAULT_REQUEST_COMPLETED_MSG)
       t.equal(responseLine.customRequestId, 'testId')
       t.ok(responseLine.req)
+
+      t.end()
     })
   }, handler)
 })