Repository: pinojs/pino-http
Pull request #156 (2021-09-16 15:56:23)

feature: quietReqLogger option for a quieter child logger available on the request object
Hi, I've recently started using this for our logging as we migrated from bunyan to pino.

A behaviour we used to have in the bunyan-land was that our request logging middleware would similarly provide a request-context aware child logger (available at `req.log`) however it would only contain the request id that you could use to filter logs on and see logs for the entire request transaction (including the one message with the full request serialized).

Instead of just requesting this feature, I took a stab at a PR instead - please let me know if this is something you'd consider.

Some things that I'm on the fence/unsure about:

1) the name of the option `quietReqLogger` :man_shrugging: 
2) the top-level request id being only populated when the quietReqLogger is enabled with no granular control
3) `res.log` and `req.log` are diverging with this option enabled, is there any downstream issues with this?
4) typescript definitions - not sure who manages these



Patch:
diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml
index c0e8042..59f4afe 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.4.0
+      - uses: fastify/github-action-merge-dependabot@v2.5.0
         with:
           github-token: ${{ secrets.GITHUB_TOKEN }}
diff --git a/README.md b/README.md
index 2ca1aad..bd894d8 100644
--- a/README.md
+++ b/README.md
@@ -104,9 +104,10 @@ $ node example.js | pino-pretty
 * `stream`: same as the second parameter
 * `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`, and `responseTime`.
+* `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`.
 * `wrapSerializers`: when `false`, custom serializers will be passed the raw value directly. Defaults to `true`.
 * `customProps`: set to a `function (req,res) => { /* returns on object */ }` or `{ /* returns on object */ }` This function will be invoked for each request with `req` and `res` where we could pass additional properties that needs to be logged outside the `req`.
+* `quietReqLogger`: when `true`, the child logger available on `req.log` will no longer contain the full bindings and will now only have the request id bound at `reqId` (note: the autoLogging messages and the logger available on `res.log` will remain the same except they will also have the additional `reqId` property). default: `false`
 
 `stream`: the destination stream. Could be passed in as an option too.
 
diff --git a/logger.js b/logger.js
index 8b3723b..6277103 100644
--- a/logger.js
+++ b/logger.js
@@ -17,6 +17,7 @@ function pinoLogger (opts, stream) {
   var reqKey = opts.customAttributeKeys.req || 'req'
   var resKey = opts.customAttributeKeys.res || 'res'
   var errKey = opts.customAttributeKeys.err || 'err'
+  var requestIdKey = opts.customAttributeKeys.reqId || 'reqId'
   var responseTimeKey = opts.customAttributeKeys.responseTime || 'responseTime'
   delete opts.customAttributeKeys
 
@@ -57,6 +58,8 @@ function pinoLogger (opts, stream) {
   delete opts.customSuccessfulMessage
   delete opts.customErroredMessage
 
+  var quietReqLogger = !!opts.quietReqLogger
+
   var logger = wrapChild(opts, theStream)
   var genReqId = reqIdGenFactory(opts.genReqId)
   loggingMiddleware.logger = logger
@@ -92,11 +95,14 @@ function pinoLogger (opts, stream) {
 
     req.id = genReqId(req)
 
-    var log = logger.child({ [reqKey]: req })
+    var log = quietReqLogger ? logger.child({ [requestIdKey]: req.id }) : logger
 
+    var fullReqLogger = log.child({ [reqKey]: req })
     var customPropBindings = (typeof customProps === 'function') ? customProps(req, res) : customProps
-    log = log.child(customPropBindings)
-    req.log = res.log = log
+    fullReqLogger = fullReqLogger.child(customPropBindings)
+
+    res.log = fullReqLogger
+    req.log = quietReqLogger ? log : fullReqLogger
 
     res[startTime] = res[startTime] || Date.now()
 


Test patch:
diff --git a/test.js b/test.js
index 9c2e627..55f2906 100644
--- a/test.js
+++ b/test.js
@@ -897,3 +897,61 @@ test('auto logging and next callback', function (t) {
     })
   })
 })
+
+test('quiet request logging', function (t) {
+  t.plan(8)
+  var dest = split(JSON.parse)
+  var logger = pinoHttp({ quietReqLogger: true }, dest)
+
+  function handler (req, res) {
+    t.pass('called')
+    req.id = 'testId'
+    logger(req, res)
+    req.log.info('quiet message')
+    res.end('hello world')
+  }
+
+  setup(t, logger, function (err, server) {
+    t.error(err)
+    doGet(server, null, function () {
+      var quietLine = dest.read()
+      t.equal(quietLine.msg, 'quiet message')
+      t.equal(quietLine.reqId, 'testId')
+      t.notOk(quietLine.req)
+
+      var responseLine = dest.read()
+      t.equal(responseLine.msg, 'request completed')
+      t.equal(responseLine.reqId, 'testId')
+      t.ok(responseLine.req)
+    })
+  }, handler)
+})
+
+test('quiet request logging - custom request id key', function (t) {
+  t.plan(8)
+  var dest = split(JSON.parse)
+  var logger = pinoHttp({ quietReqLogger: true, customAttributeKeys: { reqId: 'customRequestId' } }, dest)
+
+  function handler (req, res) {
+    t.pass('called')
+    req.id = 'testId'
+    logger(req, res)
+    req.log.info('quiet message')
+    res.end('hello world')
+  }
+
+  setup(t, logger, function (err, server) {
+    t.error(err)
+    doGet(server, null, function () {
+      var quietLine = dest.read()
+      t.equal(quietLine.msg, 'quiet message')
+      t.notOk(quietLine.req)
+      t.equal(quietLine.customRequestId, 'testId')
+
+      var responseLine = dest.read()
+      t.equal(responseLine.msg, 'request completed')
+      t.equal(responseLine.customRequestId, 'testId')
+      t.ok(responseLine.req)
+    })
+  }, handler)
+})