fix!: prevent req being added twice to the response and request sta…

…rt log (#157)

There is no way to know in the response log event handling if the request was already added through the child bindings in `onRequest`.
And there was no way as a user to fix this behaviour properly.

So now `req` will be added once but you need to make sure that you pass it in `childBindings` for the response.
Request start event will have it regardless but also only once.

This is a breaking change as some people will have removed the `req` from the `childBindings` to get around this issue.

Fixes #91

README.md

@@ -116,7 +116,7 @@ events"](#hapievents) section.
   For convenience, you can pass in `true` to always log `request start` events, or `false` to disable logging `request start` events
 
   Note: when `logRequestStart` is enabled and `getChildBindings` is configured to omit the `req` field, then the `req` field will be
-  omitted from the `request completed` log event. This behavior is useful if you want to separate requests from responses and link the
+  omitted from the `request completed` log event but the `req` field will always be there for the start log. This behavior is useful if you want to separate requests from responses and link the
   two via requestId (frequently done via `headers['x-request-id']`) , where "request start" only logs the request and a requestId,
   and `request completed` only logs the response and the requestId.
 
@@ -159,7 +159,8 @@ events"](#hapievents) section.
 
  **Example**:  
  To redact the authorization header in the logs:
-  ```
+
+  ```js
   {
     req: require('pino-noir')(['req.headers.authorization']).req
     res: ...
@@ -206,6 +207,8 @@ events"](#hapievents) section.
 
   Takes a function with the request as an input, and returns the object that will be passed into pinoLogger.child().
 
+  Note: Omitting `req` from the child bindings will omit it from all logs, most notably the response log, except "request start".
+
 ### `options.ignorePaths: string[]`
   Takes an array of string routes and disables logging for each.  Useful for health checks or any route that does not need logging.
 
@@ -247,7 +250,7 @@ events"](#hapievents) section.
 
   **Default**: `{ log: '*', request: '*' }`, Logs all the events emitted by server.log and request.log without filtering event tags
 
-  **Example**: 
+  **Example**:
   Do not log the events for DEBUG and TEST tag
   ```js
   ignoredEventTags: { log: ['DEBUG', 'TEST'], request: ['DEBUG', 'TEST'] }
@@ -258,7 +261,7 @@ events"](#hapievents) section.
 ### `options.level: Pino.Level`
   **Default**: `'info'`
 
-  Set the minumum level that Pino should log out. See [Level](https://github.com/pinojs/pino/blob/master/docs/api.md#level).
+  Set the minimum level that Pino should log out. See [Level](https://github.com/pinojs/pino/blob/master/docs/api.md#level).
 
   **Example**:  
   Configure Pino to output all `debug` or higher events:
@@ -281,19 +284,19 @@ events"](#hapievents) section.
 
 **hapi-pino** decorates the Hapi request with:
 
-* `request.logger`, which is an instance of [pino][pino] bound to the current request, so you can trace all the logs of a given request. See [pino][pino] doc for the way to actual log.
+- `request.logger`, which is an instance of [pino][pino] bound to the current request, so you can trace all the logs of a given request. See [pino][pino] doc for the way to actual log.
 
 <a name="hapievents"></a>
 ### Hapi Events
 
 **hapi-pino** listens to some Hapi events:
 
-* `'onRequest'`, to create a request-specific child logger
-* `'response'`, to log at `'info'` level when a request is completed
-* `'request'`, to support logging via the Hapi `request.log()` method and to log at `'warn'` level when a request errors or when request received contains an invalid `accept-encoding` header, see `tags` and `allTags` options.
-* `'log'`, to support logging via the Hapi `server.log()` method and to log in case of an internal server event, see `tags` and `allTags` options.
-* `'onPostStart'`, to log when the server is started
-* `'onPostStop'`, to log when the server is stopped
+- `'onRequest'`, to create a request-specific child logger
+- `'response'`, to log at `'info'` level when a request is completed
+- `'request'`, to support logging via the Hapi `request.log()` method and to log at `'warn'` level when a request errors or when request received contains an invalid `accept-encoding` header, see `tags` and `allTags` options.
+- `'log'`, to support logging via the Hapi `server.log()` method and to log in case of an internal server event, see `tags` and `allTags` options.
+- `'onPostStart'`, to log when the server is started
+- `'onPostStop'`, to log when the server is stopped
 
 ## Acknowledgements
 

index.js

@@ -109,7 +109,7 @@ async function register (server, options) {
 
     if (shouldLogRequestStart(request)) {
       request.logger.info({
-        req: request
+        req: childBindings.req ? undefined : request
       }, 'request start')
     }
 
@@ -167,16 +167,13 @@ async function register (server, options) {
         request.logger = logger.child(childBindings)
       }
 
+      // If you want `req` to be added either use the default `getChildBindings` or make sure `req` is passed in your custom bindings.
       const responseTime = (info.completed !== undefined ? info.completed : info.responded) - info.received
-
       request.logger.info(
         {
           payload: options.logPayload ? request.payload : undefined,
           queryParams: options.logQueryParams ? request.query : undefined,
           tags: options.logRouteTags ? request.route.settings.tags : undefined,
-          // note: pino doesnt support unsetting a key, so this next line
-          // has the effect of setting it or "leaving it as it was" if it was already added via child bindings
-          req: shouldLogRequestStart(request) ? undefined : request,
           res: request.raw.res,
           responseTime
         },

test.js

@@ -165,6 +165,36 @@ experiment('logs each request', () => {
     await finish
   })
 
+  test('without duplicate req data', async () => {
+    const server = getServer()
+    let done
+
+    const finish = new Promise(function (resolve, reject) {
+      done = resolve
+    })
+
+    // We do a manual setup here compared to other tests
+    // as the `JSON.parse` in the `sink` function hides the double key from us.
+    const stream = split()
+    stream.pipe(writeStream.obj((data) => {
+      expect(data.match(/"req":/g).length).to.equal(1)
+
+      done()
+    }))
+
+    const plugin = {
+      plugin: Pino,
+      options: {
+        stream: stream,
+        level: 'info'
+      }
+    }
+
+    await server.register(plugin)
+    await server.inject('/something')
+    await finish
+  })
+
   test('track responseTime', async () => {
     const server = getServer()
 
@@ -584,6 +614,7 @@ experiment('logs through request.log', () => {
       (data, enc, cb) => {
         if (data.tags) {
           expect(data.data).to.equal('hello logger')
+          expect(data.req).to.not.be.undefined()
           resolver()
         }
         cb()
@@ -907,7 +938,7 @@ experiment('request.logger.child() bindings', () => {
       done = resolve
     })
     const stream = sink(data => {
-      expect(data.req).to.not.be.undefined()
+      expect(data.req).to.be.undefined()
       expect(data.custom).to.not.be.undefined()
       done()
     })
@@ -1142,6 +1173,42 @@ experiment('options.logRequestStart', () => {
     await server.inject('/something')
     await finish
   })
+
+  test('when options.logRequestStart is true, don\'t log req twice ', async () => {
+    const server = getServer()
+    let done
+
+    const finish = new Promise(function (resolve, reject) {
+      done = resolve
+    })
+
+    // We do a manual setup here compared to other tests
+    // as the `JSON.parse` in the `sink` function hides the double key from us.
+    const stream = split()
+    stream.pipe(writeStream.obj((data, enc, cb) => {
+      expect(data.match(/"req":/g).length).to.equal(1)
+
+      // If we get to the response log we're done
+      if (data.includes('"responseTime":')) {
+        done()
+      }
+
+      cb()
+    }))
+
+    const plugin = {
+      plugin: Pino,
+      options: {
+        stream: stream,
+        level: 'info',
+        logRequestStart: true
+      }
+    }
+
+    await server.register(plugin)
+    await server.inject('/something')
+    await finish
+  })
 })
 
 experiment('options.logRequestComplete', () => {