Filter asset requests from Hapi-pino logs (#16)

Our current hapi-pino configuration is based on what we needed for the [sroc-charging-module-api](https://github.com/DEFRA/sroc-charging-module-api). But as an API it never had to worry about assets and requests from the browser for them.

As we use this app, we're seeing multiple log entries per page. This is because it's logging both the main request plus one for each asset used by the page. Below is an example of what we see. Bear in mind that we have only listed the top-level entry. Each one is 41 lines long (when working locally) because the logger details both the request and response.

```text
[09:41:06.763] INFO (17542): [response] get /service-status 200 (1138ms)
[09:41:06.871] INFO (17542): [response] get /assets/stylesheets/application.css 200 (72ms)
[09:41:06.873] INFO (17542): [response] get /assets/all.js 200 (64ms)
[09:41:06.893] INFO (17542): [response] get /assets/images/govuk-crest.png 200 (8ms)
[09:41:06.926] INFO (17542): [response] get /assets/fonts/light-94a07e06a1-v2.woff2 200 (19ms)
[09:41:06.928] INFO (17542): [response] get /assets/fonts/bold-b542beb274-v2.woff2 200 (18ms)
[09:41:07.032] INFO (17542): [response] get /assets/images/favicon.ico 200 (6ms)
```

Our primary reason for using hapi-pino is to reduce the noise in our logs so we can find and focus on what's important. This change updates the hapi-pino filtering so we only log the main requests. It will include an option to switch back on asset logging, just in case we ever have issues and need that extra detail.

** Notes

- Rename test config

We needed somewhere to put our config for whether to include asset requests in the log. We already have a setting to control whether the log should record anything when running in `test`. So, putting these together made the most sense.

Having done that, we concluded this wasn't really test config anymore, but log config. Hence we renamed the file.

.env.example

@@ -14,7 +14,8 @@ POSTGRES_DB_TEST=sroc_charge_test
 # Server config
 PORT=3000
 
-# Test config
+# Log config
+LOG_ASSET_REQUESTS=false
 LOG_IN_TEST=false
 
 # External services

app/plugins/hapi_pino.plugin.js

@@ -9,8 +9,11 @@
  *
  * @module HapiPinoPlugin
  */
+
 const HapiPino = require('hapi-pino')
 
+const HapiPinoIgnoreRequestService = require('../services/plugins/hapi_pino_ignore_request.service.js')
+
 /**
  * Return test configuration options for the logger
  *
@@ -48,8 +51,10 @@ const HapiPinoPlugin = logInTest => {
       transport: process.env.NODE_ENV !== 'production' ? { target: 'pino-pretty', options: { colorize: true } } : undefined,
       // Redact Authorization headers, see https://getpino.io/#/docs/redaction
       redact: ['req.headers.authorization'],
-      // We don't want logs outputting for our 'health' routes
-      ignorePaths: ['/', '/status']
+      // We want our logs to focus on the main requests and not become full of 'noise' from requests for /assets or
+      // pings from the AWS load balancer to /status. We pass this function to hapi-pino to control what gets filtered
+      // https://github.com/pinojs/hapi-pino#optionsignorefunc-options-request--boolean
+      ignoreFunc: HapiPinoIgnoreRequestService.go
     }
   }
 }

app/server.js

@@ -3,7 +3,7 @@
 const Hapi = require('@hapi/hapi')
 
 const ServerConfig = require('../config/server.config.js')
-const TestConfig = require('../config/test.config.js')
+const LogConfig = require('../config/log.config.js')
 
 const AirbrakePlugin = require('./plugins/airbrake.plugin.js')
 const BlippPlugin = require('./plugins/blipp.plugin.js')
@@ -19,7 +19,7 @@ const registerPlugins = async (server) => {
   await server.register(StopPlugin)
   await server.register(require('@hapi/inert'))
   await server.register(RouterPlugin)
-  await server.register(HapiPinoPlugin(TestConfig.logInTest))
+  await server.register(HapiPinoPlugin(LogConfig.logInTest))
   await server.register(AirbrakePlugin)
   await server.register(ErrorPagesPlugin)
   await server.register(RequestNotifierPlugin)

app/services/plugins/hapi_pino_ignore_request.service.js

@@ -0,0 +1,59 @@
+'use strict'
+
+/**
+ * @module HapiPinoIgnoreRequestService
+ */
+
+const LogConfig = require('../../../config/log.config.js')
+
+class HapiPinoIgnoreRequestService {
+  /**
+   * Returns true or false whether a request should be loged
+   *
+   * Used by `app/plugins/hapi_pino.plugin.js` to control what does and doesn't get added to our log output. We built
+   * `/status` to support AWS load balancer health checks which fire approximately every 500ms. If we logged these
+   * requests our log would be too noisy to prove useful. (`/` and `/status` go to the same place hence both are
+   * listed).
+   *
+   * When a view is requested, a number of assets will be requested along with it. So, a single request for a page will
+   * result in the following log entries
+   *
+   * ```text
+   * [09:41:06.763] INFO (17542): [response] get /service-status 200 (1138ms)
+   * [09:41:06.871] INFO (17542): [response] get /assets/stylesheets/application.css 200 (72ms)
+   * [09:41:06.873] INFO (17542): [response] get /assets/all.js 200 (64ms)
+   * [09:41:06.893] INFO (17542): [response] get /assets/images/govuk-crest.png 200 (8ms)
+   * [09:41:06.926] INFO (17542): [response] get /assets/fonts/light-94a07e06a1-v2.woff2 200 (19ms)
+   * [09:41:06.928] INFO (17542): [response] get /assets/fonts/bold-b542beb274-v2.woff2 200 (18ms)
+   * [09:41:07.032] INFO (17542): [response] get /assets/images/favicon.ico 200 (6ms)
+   * ```
+   *
+   * And these are just the first line from each entry. Because we log both the request and response details when
+   * viewed locally each entry is 41 lines long!
+   *
+   * So, we also do not log any requests to `/assets/*`.
+   *
+   * @param {Object} _options The options passed to the HapiPino plugin
+   * @param {request} request Hapi request object created internally for each incoming request
+   *
+   * @returns {boolean} true if the request should be ignored, else false
+   */
+  static go (_options, request) {
+    const staticPaths = ['/', '/status']
+
+    // If request is a known path ignore it
+    if (staticPaths.includes(request.path)) {
+      return true
+    }
+
+    // If logging asset requests is disabled and the request is for an asset ignore it
+    if (!LogConfig.logAssetRequests && request.path.startsWith('/assets')) {
+      return true
+    }
+
+    // Do not ignore all other requests
+    return false
+  }
+}
+
+module.exports = HapiPinoIgnoreRequestService

config/test.config.js → config/log.config.js

@@ -3,6 +3,7 @@
 const config = {
   // Credit to https://stackoverflow.com/a/323546/6117745 for how to handle
   // converting the env var to a boolean
+  logAssetRequests: (String(process.env.LOG_ASSET_REQUESTS) === 'true') || false,
   logInTest: (String(process.env.LOG_IN_TEST) === 'true') || false
 }
 

test/services/plugins/hapi_pino_ignore_request.service.test.js

@@ -0,0 +1,73 @@
+'use strict'
+
+// Test framework dependencies
+const Lab = require('@hapi/lab')
+const Code = require('@hapi/code')
+const Sinon = require('sinon')
+
+const { describe, it, beforeEach, afterEach } = exports.lab = Lab.script()
+const { expect } = Code
+
+// Things we need to stub
+const LogConfig = require('../../../config/log.config')
+
+// Thing under test
+const HapiPinoIgnoreRequestService = require('../../../app/services/plugins/hapi_pino_ignore_request.service.js')
+
+describe('Hapi Pino Ignore Request service', () => {
+  const _options = {}
+
+  afterEach(() => {
+    Sinon.restore()
+  })
+
+  describe("when the request is for the root '/'", () => {
+    it('returns true', () => {
+      const result = HapiPinoIgnoreRequestService.go(_options, { path: '/' })
+
+      expect(result).to.be.true()
+    })
+  })
+
+  describe("when the request is for '/status'", () => {
+    it('returns true', () => {
+      const result = HapiPinoIgnoreRequestService.go(_options, { path: '/status' })
+
+      expect(result).to.be.true()
+    })
+  })
+
+  describe('when the request is for an asset', () => {
+    describe('and LOG_ASSET_REQUESTS is false', () => {
+      beforeEach(() => {
+        Sinon.replace(LogConfig, 'logAssetRequests', false)
+      })
+
+      it('returns true', () => {
+        const result = HapiPinoIgnoreRequestService.go(_options, { path: '/assets/stylesheets/application.css' })
+
+        expect(result).to.be.true()
+      })
+    })
+
+    describe('and LOG_ASSET_REQUESTS is true', () => {
+      beforeEach(() => {
+        Sinon.replace(LogConfig, 'logAssetRequests', true)
+      })
+
+      it('returns false', () => {
+        const result = HapiPinoIgnoreRequestService.go(_options, { path: '/assets/stylesheets/application.css' })
+
+        expect(result).to.be.false()
+      })
+    })
+  })
+
+  describe("when the request is not for '/status' or an asset", () => {
+    it('returns false', () => {
+      const result = HapiPinoIgnoreRequestService.go(_options, { path: '/bill-run/stuff' })
+
+      expect(result).to.be.false()
+    })
+  })
+})