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

…rt log

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')
     }
 
@@ -166,14 +166,13 @@ async function register (server, options) {
         const childBindings = getChildBindings(request)
         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.
       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: (info.completed !== undefined ? info.completed : info.responded) - info.received
         },

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', () => {