Repository: pinojs/hapi-pino
Pull request #93 (2019-11-25 08:16:56)

feat: ignored by tags
Usually we wants to group multiple routes in tags, however ignoring these routes one by one seems to be a tedious process. It would make more sense to support such a case by just ignoring through the tags instead, hence this PR.

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

Coverage decreased (-0.03%) to 98.989% when pulling **2ea7cf7a9cbafa838cd4a371328cefe34153264a on spywhere:feature/tag-based-logging** into **9b84037e3140c5d642774480a5d596c8addc21db on pinojs:master**.

mcollina: It seems code coverage is slightly dropping with this feature, would you mind adding the missing tests?
spywhere: Actually tests are already been added. Seems to cover all the changes I made though...

![Screen Shot 2019-11-25 at 16 42 21](https://user-images.githubusercontent.com/1087399/69529315-9a88da00-0fa2-11ea-8866-98788097719c.png)


Patch:
diff --git a/.travis.yml b/.travis.yml
index 7d86635..3433997 100644
--- a/.travis.yml
+++ b/.travis.yml
@@ -3,9 +3,17 @@ sudo: false
 node_js:
   - "8"
   - "10"
+  - "12"
 env:
   - HAPI=hapi@17
-  - HAPI=hapi@18
+  - HAPI=@hapi/hapi@18
+  - HAPI=@hapi/hapi@19
+matrix:
+  exclude:
+  - node_js: 8
+    env: HAPI=@hapi/hapi@19
+  - node_js: 10
+    env: HAPI=@hapi/hapi@19
 before_script:
   - npm install --save-dev $HAPI
 after_script:
diff --git a/README.md b/README.md
index d1beea1..7e02daa 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`
 
@@ -201,6 +215,15 @@ events"](#hapievents) section.
   ignorePaths: ['/health']
   ```
 
+### `options.ignoreTags: string[]`
+  Takes an array of string tags and disables logging for each.  Useful for health checks or any route that does not need logging.
+
+  **Example**:  
+  Do not log for route with `healthcheck` tag
+  ```js
+  ignoreTags: ['healthcheck']
+  ```
+
 ### `options.level: Pino.Level`
   **Default**: `'info'`
 
diff --git a/index.js b/index.js
index da08fb7..1d349d6 100644
--- a/index.js
+++ b/index.js
@@ -68,14 +68,23 @@ 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)
 
   // set a logger for each request
   server.ext('onRequest', (request, h) => {
-    if (options.ignorePaths && ignoreTable[request.url.pathname]) {
+    if (isLoggingIgnored(options, request)) {
       request.logger = nullLogger
       return h.continue
     }
@@ -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')
@@ -103,12 +112,17 @@ async function register (server, options) {
   // log via `request.log()` and optionally when an internal `accept-encoding`
   // error occurs or request completes with an error
   server.events.on('request', function (request, event, tags) {
-    if (event.channel === 'internal' && !tags['accept-encoding']) {
+    if (
+      (event.channel === 'internal' && !tags['accept-encoding']) ||
+      isLoggingIgnored(options, request)
+    ) {
       return
     }
 
-    const childBindings = getChildBindings(request)
-    request.logger = request.logger || logger.child(childBindings)
+    if (!request.logger) {
+      const childBindings = getChildBindings(request)
+      request.logger = logger.child(childBindings)
+    }
 
     if (event.error && isEnabledLogEvent(options, 'request-error')) {
       request.logger.error(
@@ -124,23 +138,29 @@ async function register (server, options) {
 
   // log when a request completes
   tryAddEvent(server, options, 'on', 'response', function (request) {
-    if (options.ignorePaths && ignoreTable[request.url.pathname]) {
+    if (isLoggingIgnored(options, request)) {
       return
     }
 
-    const info = request.info
-    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'
-    )
+    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'
+      )
+    }
   })
 
   tryAddEvent(server, options, 'ext', 'onPostStart', async function (s) {
@@ -151,6 +171,27 @@ async function register (server, options) {
     logger.info(server.info, 'server stopped')
   })
 
+  function isLoggingIgnored (options, request) {
+    if (options.ignorePaths && ignoreTable[request.url.pathname]) {
+      return true
+    }
+
+    const ignoreTags = options.ignoreTags
+    const routeTags = request.route.settings.tags
+
+    if (!ignoreTags || !routeTags) {
+      return false
+    }
+
+    for (var index = ignoreTags.length; index >= 0; index--) {
+      if (routeTags.includes(ignoreTags[index])) {
+        return true
+      }
+    }
+
+    return false
+  }
+
   function isEnabledLogEvent (options, name) {
     return options.logEvents && options.logEvents.indexOf(name) !== -1
   }
diff --git a/package.json b/package.json
index 7426c37..0d5c33e 100644
--- a/package.json
+++ b/package.json
@@ -1,6 +1,6 @@
 {
   "name": "hapi-pino",
-  "version": "6.3.0",
+  "version": "6.4.0",
   "description": "Hapi plugin for the Pino logger ",
   "main": "index.js",
   "scripts": {


Test patch:
diff --git a/test.js b/test.js
index b3b032a..57c14d3 100644
--- a/test.js
+++ b/test.js
@@ -356,6 +356,34 @@ experiment('logs each request', () => {
 
     expect(options).to.equal(optionsClone)
   })
+
+  test('handles removed request.logger', async () => {
+    const server = getServer()
+
+    let done
+
+    const finish = new Promise(function (resolve, reject) {
+      done = resolve
+    })
+
+    server.route({
+      path: '/',
+      method: 'GET',
+      handler: async (req, h) => {
+        req.logger = undefined
+        return 'hello world'
+      }
+    })
+
+    await registerWithSink(server, 'info', data => {
+      expect(data.res.statusCode).to.equal(200)
+      expect(data.msg).to.equal('request completed')
+      done()
+    })
+
+    await server.inject('/')
+    await finish
+  })
 })
 
 experiment('logs through server.log', () => {
@@ -830,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) {
@@ -883,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
@@ -957,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()
@@ -1232,6 +1493,41 @@ experiment('ignore request logs for paths in ignorePaths', () => {
   })
 })
 
+experiment('ignore request logs for tags in ignoreTags', () => {
+  test('when tag matches entry in ignoreTags, nothing should be logged', async () => {
+    const server = getServer()
+    let resolver
+    const done = new Promise((resolve, reject) => {
+      resolver = resolve
+    })
+    const stream = sink(data => {
+      expect(data.req.url).to.endWith('/foo')
+      resolver()
+    })
+    const logger = require('pino')(stream)
+    const plugin = {
+      plugin: Pino,
+      options: {
+        instance: logger,
+        ignoreTags: ['foo']
+      }
+    }
+
+    await server.register(plugin)
+
+    await server.inject({
+      method: 'GET',
+      url: '/something'
+    })
+
+    await server.inject({
+      method: 'PUT',
+      url: '/foo'
+    })
+    await done
+  })
+})
+
 experiment('ignore response logs for paths in ignorePaths', () => {
   test('when path matches entry in ignorePaths, nothing should be logged', async () => {
     const server = getServer()
@@ -1269,6 +1565,43 @@ experiment('ignore response logs for paths in ignorePaths', () => {
   })
 })
 
+experiment('ignore response logs for tags in ignoreTags', () => {
+  test('when tag matches entry in ignoreTags, nothing should be logged', async () => {
+    const server = getServer()
+    let resolver
+    const done = new Promise((resolve, reject) => {
+      resolver = resolve
+    })
+    const stream = sink(data => {
+      expect(data.req.url).to.endWith('/foo')
+      expect(data.msg).to.equal('request completed')
+      resolver()
+    })
+    const logger = require('pino')(stream)
+    const plugin = {
+      plugin: Pino,
+      options: {
+        instance: logger,
+        logEvents: ['response'],
+        ignoreTags: ['foo']
+      }
+    }
+
+    await server.register(plugin)
+
+    await server.inject({
+      method: 'GET',
+      url: '/something'
+    })
+
+    await server.inject({
+      method: 'PUT',
+      url: '/foo'
+    })
+    await done
+  })
+})
+
 experiment('ignore request.log logs for paths in ignorePaths', () => {
   test('when path matches entry in ignorePaths, nothing should be logged', async () => {
     const level = 'info'
@@ -1326,6 +1659,66 @@ experiment('ignore request.log logs for paths in ignorePaths', () => {
   })
 })
 
+experiment('ignore request.log logs for tags in ignoreTags', () => {
+  test('when tag matches entry in ignoreTags, nothing should be logged', async () => {
+    const level = 'info'
+    const server = getServer()
+    server.route({
+      method: 'GET',
+      path: '/ignored',
+      options: {
+        tags: ['foo']
+      },
+      handler: (req, h) => {
+        req.log([level], 'hello logger')
+        return 'hello world'
+      }
+    })
+
+    server.route({
+      path: '/foo',
+      method: 'GET',
+      handler: (req, h) => {
+        req.log([level], 'foo')
+        return 'foo'
+      }
+    })
+
+    let resolver
+    const done = new Promise((resolve, reject) => {
+      resolver = resolve
+    })
+    const stream = sink(data => {
+      expect(data.req.url).to.endWith('/foo')
+      expect(data.tags).to.equal([level])
+      expect(data.data).to.equal('foo')
+      resolver()
+    })
+    const logger = require('pino')(stream)
+    const plugin = {
+      plugin: Pino,
+      options: {
+        instance: logger,
+        logEvents: ['request-error'],
+        ignoreTags: ['foo']
+      }
+    }
+
+    await server.register(plugin)
+
+    await server.inject({
+      method: 'GET',
+      url: '/ignored'
+    })
+
+    await server.inject({
+      method: 'GET',
+      url: '/foo'
+    })
+    await done
+  })
+})
+
 experiment('logging with logRouteTags option enabled', () => {
   test('when logRouteTags is true, tags are part of the logged object', async () => {
     const server = getServer()