fix missing req in "request complete" event when using getChildBindin…

…gs and options.logRequestStart feature (#88)

* fix: req field should be included in the response log event, even if omitted via child bindings

* feat: options.logRequestStart to separate requests and responses and link via a custom binding

* refactor: extract options.logRequestStart to higher scope

README.md

@@ -96,6 +96,8 @@ events"](#hapievents) section.
 ### Options
 - `[logPayload]` – when enabled, add the request payload as `payload` to the `response` event log. Defaults to `false`.
 - `[logRouteTags]` – when enabled, add the request route tags (as configured in hapi `route.options.tags`) `tags` to the `response` event log. Defaults to `false`.
+- `[logRequestStart]` - when enabled, add a log.info() at the beginning of Hapi requests.   Defaults to `false`
+  Note: when `logRequestStart` is enabled and `getChildBindings` is configured to omit the `req` field, then the `req` field will be omitted from the "request complete" log event. 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 complete" only logs the response and the requestId.
 - `[stream]` - the binary stream to write stuff to, defaults to
   `process.stdout`.
 - `[prettyPrint]` - pretty print the logs (same as `node server |

index.js

@@ -68,6 +68,7 @@ async function register (server, options) {
 
   const mergeHapiLogData = options.mergeHapiLogData
   const getChildBindings = options.getChildBindings ? options.getChildBindings : (request) => ({ req: request })
+  const logRequestStart = options.logRequestStart
 
   // expose logger as 'server.logger()'
   server.decorate('server', 'logger', () => logger)
@@ -82,6 +83,12 @@ async function register (server, options) {
     const childBindings = getChildBindings(request)
     request.logger = logger.child(childBindings)
 
+    if (logRequestStart) {
+      request.logger.info({
+        req: request
+      }, 'request start')
+    }
+
     return h.continue
   })
 
@@ -126,6 +133,9 @@ async function register (server, options) {
       {
         payload: options.logPayload ? request.payload : 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: logRequestStart ? undefined : request,
         res: request.raw.res,
         responseTime: (info.completed !== undefined ? info.completed : info.responded) - info.received
       },

test.js

@@ -810,7 +810,7 @@ experiment('request.logger.child() bindings', () => {
       done = resolve
     })
     const stream = sink(data => {
-      expect(data.req).to.be.undefined()
+      expect(data.req).to.not.be.undefined()
       expect(data.custom).to.not.be.undefined()
       done()
     })
@@ -829,6 +829,134 @@ experiment('request.logger.child() bindings', () => {
   })
 })
 
+experiment('options.logRequestStart', () => {
+  test('is default/false/omitted; only response events are logged, containing both the req and res', async () => {
+    const server = getServer()
+    let done
+    const finish = new Promise(function (resolve, reject) {
+      done = resolve
+    })
+
+    const stream = sink(data => {
+      expect(data.msg).to.equal('request completed')
+      expect(data.req).to.be.an.object()
+      expect(data.req.id).to.exists()
+      expect(data.res).to.be.an.object()
+      done()
+    })
+    const plugin = {
+      plugin: Pino,
+      options: {
+        stream: stream,
+        level: 'info'
+      }
+    }
+
+    await server.register(plugin)
+    await server.inject('/something')
+    await finish
+  })
+
+  test('when options.logRequestStart is true, log an event at the beginning of each request', async () => {
+    const server = getServer()
+    let done
+    const finish = new Promise(function (resolve, reject) {
+      done = resolve
+    })
+    const stream = sink(data => {
+      expect(data.msg).to.equal('request start')
+      expect(data.req).to.be.an.object()
+      expect(data.req.id).to.be.a.string()
+      done()
+    })
+    const plugin = {
+      plugin: Pino,
+      options: {
+        stream: stream,
+        level: 'info',
+        logRequestStart: true
+      }
+    }
+
+    await server.register(plugin)
+    await server.inject('/something')
+    await finish
+  })
+
+  test('when options.logRequestStart is true and options.getChildBindings does not omit req field, the onRequestComplete log event includes the req field', async () => {
+    const server = getServer()
+    let done
+    const finish = new Promise(function (resolve, reject) {
+      done = resolve
+    })
+    let count = 0
+    const stream = sink((data, enc, cb) => {
+      if (count === 0) {
+        expect(data.msg).to.equal('request start')
+        expect(data.req).to.be.an.object()
+        expect(data.res).to.be.undefined()
+      } else {
+        expect(data.msg).to.equal('request completed')
+        expect(data.req).to.be.an.object()
+        expect(data.res).to.be.an.object()
+        done()
+      }
+      count++
+      cb()
+    })
+    const plugin = {
+      plugin: Pino,
+      options: {
+        stream: stream,
+        level: 'info',
+        logRequestStart: true
+      }
+    }
+
+    await server.register(plugin)
+    await server.inject('/something')
+    await finish
+  })
+
+  test('when options.logRequestStart is true and options.getChildBindings omits the req field, the onRequestComplete log event omits the req field', async () => {
+    const server = getServer()
+    let done
+    const finish = new Promise(function (resolve, reject) {
+      done = resolve
+    })
+    let count = 0
+    const stream = sink((data, enc, cb) => {
+      if (count === 0) {
+        expect(data.msg).to.equal('request start')
+        expect(data.req).to.be.an.object()
+        expect(data.res).to.be.undefined()
+        expect(data.requestId).to.equal('request1234')
+      } else {
+        expect(data.msg).to.equal('request completed')
+        expect(data.req).to.be.undefined()
+        expect(data.res).to.be.an.object()
+        expect(data.requestId).to.equal('request1234')
+        done()
+      }
+      count++
+      cb()
+    })
+    const plugin = {
+      plugin: Pino,
+      options: {
+        stream: stream,
+        level: 'info',
+        getChildBindings: (req) => ({ requestId: 'request1234' }),
+        logRequestStart: true
+      }
+    }
+
+    await server.register(plugin)
+    await server.inject('/something')
+    await finish
+  })
+})
+
 experiment('logging with mergeHapiLogData option enabled', () => {
   test("log event data is merged into pino's log object", async () => {
     const server = getServer()