Repository: pinojs/hapi-pino
Pull request #90 (2019-10-28 19:33:33)

Feat: add options.logRequestComplete, allow function syntax for options.logRequestStart
Stacked on top of https://github.com/pinojs/hapi-pino/pull/89 for formatting improvements to the README

This PR:

 - adds the ability to specify the existing `options.logRequestStart` using a function syntax: `(Request) => boolean`, which selectively enables/disables the logging on requestStart for the given request

 - adds the same functionality for the "request complete" event, letting you pass in either a boolean or a function of the same style.

 - keeps the current behavior / defaults, namely:
     - `request start` events are _not_ logged
     - `request completed` events _are_ logged


coveralls: 
[![Coverage Status](https://coveralls.io/builds/26600353/badge)](https://coveralls.io/builds/26600353)

Coverage increased (+0.1%) to 99.146% when pulling **bbdb9b9dab7001e011a98acec5517c280fdf335c on devshackio:feat-logRequestStart-logRequestComplete** into **02ce38b6d4a6107071ca4d223e685e9764a99422 on pinojs:master**.

mcollina: Would you mind to rebase against master? It currently has a conflict.
BlooJeans: > Would you mind to rebase against master? It currently has a conflict.

Rebased

Patch:
diff --git a/README.md b/README.md
index d1beea1..479c559 100644
--- a/README.md
+++ b/README.md
@@ -107,13 +107,26 @@ events"](#hapievents) section.
 
   When enabled, add the request route tags (as configured in hapi `route.options.tags`) `tags` to the `response` event log.
 
-### `options.logRequestStart: boolean`
+### `options.logRequestStart: boolean | (Request) => boolean`
 
   **Default**: false
 
-  When enabled, add a log.info() at the beginning of Hapi requests.
+  Whether hapi-pino should add a `log.info()` at the beginning of Hapi requests for the given Request.
 
-  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.
+  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
+  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.
+
+### `options.logRequestComplete: boolean | (Request) => Boolean`
+
+  **Default**: true
+
+  Whether hapi-pino should add a `log.info()` at the completion of Hapi requests for the given Request.
+
+  For convenience, you can pass in `true` to always log `request complete` events, or `false` to disable logging `request complete` events
 
 ### `options.stream` Pino.DestinationStream
 
@@ -129,9 +142,10 @@ events"](#hapievents) section.
 
 ### `options.tags: ({ [key in pino.Level]?: string })`
 
-  A map to specify pairs of Hapi log tags and levels.
+  **Default**: exposed via `hapi-pino.levelTags`
 
-  The tags `trace`, `debug`, `info`, `warn`, and `error` map to their corresponding level. Any mappings you supply take precedence over the default mappings. The default level tags are exposed via `hapi-pino.levelTags`.
+  A map to specify pairs of Hapi log tags and levels.  The tags `trace`, `debug`, `info`, `warn`, and `error` map to their corresponding level.
+  Any mappings you supply take precedence over the default mappings.
 
 ### `options.allTags: pino.Level`
 
diff --git a/index.js b/index.js
index 690b878..337995b 100644
--- a/index.js
+++ b/index.js
@@ -68,7 +68,16 @@ async function register (server, options) {
 
   const mergeHapiLogData = options.mergeHapiLogData
   const getChildBindings = options.getChildBindings ? options.getChildBindings : (request) => ({ req: request })
-  const logRequestStart = options.logRequestStart
+  const shouldLogRequestStart = typeof options.logRequestStart === 'function'
+    ? (request) => options.logRequestStart(request)
+    : typeof options.logRequestStart === 'boolean'
+      ? () => !!options.logRequestStart
+      : () => false
+  const shouldLogRequestComplete = typeof options.logRequestComplete === 'function'
+    ? (request) => options.logRequestComplete(request)
+    : typeof options.logRequestComplete === 'boolean'
+      ? () => !!options.logRequestComplete
+      : () => true
 
   // expose logger as 'server.logger()'
   server.decorate('server', 'logger', () => logger)
@@ -83,7 +92,7 @@ async function register (server, options) {
     const childBindings = getChildBindings(request)
     request.logger = logger.child(childBindings)
 
-    if (logRequestStart) {
+    if (shouldLogRequestStart(request)) {
       request.logger.info({
         req: request
       }, 'request start')
@@ -130,25 +139,25 @@ async function register (server, options) {
       return
     }
 
-    const info = request.info
-
-    if (!request.logger) {
-      const childBindings = getChildBindings(request)
-      request.logger = logger.child(childBindings)
+    if (shouldLogRequestComplete(request)) {
+      const info = request.info
+      if (!request.logger) {
+        const childBindings = getChildBindings(request)
+        request.logger = logger.child(childBindings)
+      }
+      request.logger.info(
+        {
+          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: shouldLogRequestStart(request) ? undefined : request,
+          res: request.raw.res,
+          responseTime: (info.completed !== undefined ? info.completed : info.responded) - info.received
+        },
+        'request completed'
+      )
     }
-
-    request.logger.info(
-      {
-        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
-      },
-      'request completed'
-    )
   })
 
   tryAddEvent(server, options, 'ext', 'onPostStart', async function (s) {


Test patch:
diff --git a/test.js b/test.js
index 724fe2f..b5e46b0 100644
--- a/test.js
+++ b/test.js
@@ -858,7 +858,34 @@ 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 () => {
+  test('when options.logRequestStart is is default/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 false, only response events are logged, containing both the req and res', async () => {
     const server = getServer()
     let done
     const finish = new Promise(function (resolve, reject) {
@@ -911,6 +938,69 @@ experiment('options.logRequestStart', () => {
     await finish
   })
 
+  test('when options.logRequestStart is a function, log an event at the beginning of each request if the function resolves to true for that request', async () => {
+    const server = getServer()
+    server.route({
+      path: '/ignored',
+      method: 'GET',
+      handler: (req, h) => {
+        return 'ignored'
+      }
+    })
+
+    server.route({
+      path: '/foo',
+      method: 'GET',
+      handler: (req, h) => {
+        return 'foo'
+      }
+    })
+
+    let done
+    const finish = new Promise((resolve, reject) => {
+      done = resolve
+    })
+    let count = 0
+    const stream = sink((data, enc, cb) => {
+      if (count === 0) {
+        expect(data.req.url).to.endWith('/ignored')
+        expect(data.msg).to.equal('request completed')
+      } else if (count === 1) {
+        expect(data.req.url).to.endWith('/foo')
+        expect(data.msg).to.equal('request start')
+      } else {
+        expect(data.req.url).to.endWith('/foo')
+        expect(data.msg).to.equal('request completed')
+        done()
+      }
+      count++
+      cb()
+    })
+    const logger = require('pino')(stream)
+    const plugin = {
+      plugin: Pino,
+      options: {
+        instance: logger,
+        logRequestStart: (request) => {
+          return request.url.pathname !== '/ignored'
+        }
+      }
+    }
+
+    await server.register(plugin)
+
+    await server.inject({
+      method: 'GET',
+      url: '/ignored'
+    })
+
+    await server.inject({
+      method: 'GET',
+      url: '/foo'
+    })
+    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
@@ -985,6 +1075,149 @@ experiment('options.logRequestStart', () => {
   })
 })
 
+experiment('options.logRequestComplete', () => {
+  test('when options.logRequestComplete is default/omitted; 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.logRequestComplete is true; 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',
+        logRequestComplete: true
+      }
+    }
+
+    await server.register(plugin)
+    await server.inject('/something')
+    await finish
+  })
+
+  test('when options.logRequestComplete is false; response events are not logged', 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')
+      } else {
+        expect(data.msg).to.equal('request start')
+        done()
+      }
+      count++
+      cb()
+    })
+    const plugin = {
+      plugin: Pino,
+      options: {
+        stream: stream,
+        level: 'info',
+        logRequestStart: true,
+        logRequestComplete: false
+      }
+    }
+
+    await server.register(plugin)
+    await server.inject('/something')
+    await server.inject('/something')
+    await finish
+  })
+
+  test('when options.logRequestComplete is a function, log an event at the completion of each request if the function resolves to true for that request', async () => {
+    const server = getServer()
+    server.route({
+      path: '/ignored',
+      method: 'GET',
+      handler: (req, h) => {
+        return 'ignored'
+      }
+    })
+
+    server.route({
+      path: '/foo',
+      method: 'GET',
+      handler: (req, h) => {
+        return 'foo'
+      }
+    })
+
+    let done
+    const finish = new Promise((resolve, reject) => {
+      done = resolve
+    })
+    const stream = sink((data, enc, cb) => {
+      expect(data.req.url).to.endWith('/foo')
+      expect(data.msg).to.equal('request completed')
+      done()
+    })
+    const logger = require('pino')(stream)
+    const plugin = {
+      plugin: Pino,
+      options: {
+        instance: logger,
+        logRequestComplete: (request) => {
+          return request.url.pathname !== '/ignored'
+        }
+      }
+    }
+
+    await server.register(plugin)
+
+    await server.inject({
+      method: 'GET',
+      url: '/ignored'
+    })
+
+    await server.inject({
+      method: 'GET',
+      url: '/foo'
+    })
+    await finish
+  })
+})
+
 experiment('logging with mergeHapiLogData option enabled', () => {
   test("log event data is merged into pino's log object", async () => {
     const server = getServer()