From 2de0ec8423a6fe730980017f6b0ca91a34cc604e Mon Sep 17 00:00:00 2001 From: Alan Cruikshanks Date: Fri, 4 Nov 2022 09:39:53 +0000 Subject: [PATCH 1/7] Filter asset requests from Hapi-pino logs 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. From 2d35ae9e80d1f60d3226241ccbffc34225b1878f Mon Sep 17 00:00:00 2001 From: Alan Cruikshanks Date: Fri, 4 Nov 2022 11:39:49 +0000 Subject: [PATCH 2/7] Working implentation This all works and gives us the outcome we want. Next we'll look at refactoring it to match our conventions and make it easier to test. --- app/plugins/hapi_pino.plugin.js | 14 ++++++++++++-- 1 file changed, 12 insertions(+), 2 deletions(-) diff --git a/app/plugins/hapi_pino.plugin.js b/app/plugins/hapi_pino.plugin.js index 0cf1490608..f23c3f9495 100644 --- a/app/plugins/hapi_pino.plugin.js +++ b/app/plugins/hapi_pino.plugin.js @@ -37,6 +37,14 @@ const testOptions = logInTest => { } } +const ignoreRequest = (_options, request) => { + const staticPaths = ['/', '/status'] + + const result = staticPaths.includes(request.path) || request.path.startsWith('/assets') + + return result +} + const HapiPinoPlugin = logInTest => { return { plugin: HapiPino, @@ -48,8 +56,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: ignoreRequest } } } From d9e9169e6151c8a2352e5d1e70fed104cbc5345f Mon Sep 17 00:00:00 2001 From: Alan Cruikshanks Date: Fri, 4 Nov 2022 12:48:56 +0000 Subject: [PATCH 3/7] Refactor the logic into a service This makes it easier to test and makes the plugin code clearer. --- app/plugins/hapi_pino.plugin.js | 13 ++--- .../hapi_pino_ignore_request.service.js | 48 +++++++++++++++++++ .../hapi_pino_ignore_request.service.test.js | 47 ++++++++++++++++++ 3 files changed, 99 insertions(+), 9 deletions(-) create mode 100644 app/services/plugins/hapi_pino_ignore_request.service.js create mode 100644 test/services/plugins/hapi_pino_ignore_request.service.test.js diff --git a/app/plugins/hapi_pino.plugin.js b/app/plugins/hapi_pino.plugin.js index f23c3f9495..62ac37c3d7 100644 --- a/app/plugins/hapi_pino.plugin.js +++ b/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 * @@ -37,14 +40,6 @@ const testOptions = logInTest => { } } -const ignoreRequest = (_options, request) => { - const staticPaths = ['/', '/status'] - - const result = staticPaths.includes(request.path) || request.path.startsWith('/assets') - - return result -} - const HapiPinoPlugin = logInTest => { return { plugin: HapiPino, @@ -59,7 +54,7 @@ const HapiPinoPlugin = logInTest => { // 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: ignoreRequest + ignoreFunc: HapiPinoIgnoreRequestService.go } } } diff --git a/app/services/plugins/hapi_pino_ignore_request.service.js b/app/services/plugins/hapi_pino_ignore_request.service.js new file mode 100644 index 0000000000..efd6f81368 --- /dev/null +++ b/app/services/plugins/hapi_pino_ignore_request.service.js @@ -0,0 +1,48 @@ +'use strict' + +/** + * @module HapiPinoIgnoreRequestService + */ + +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'] + + const result = staticPaths.includes(request.path) || request.path.startsWith('/assets') + + return result + } +} + +module.exports = HapiPinoIgnoreRequestService diff --git a/test/services/plugins/hapi_pino_ignore_request.service.test.js b/test/services/plugins/hapi_pino_ignore_request.service.test.js new file mode 100644 index 0000000000..7d629085de --- /dev/null +++ b/test/services/plugins/hapi_pino_ignore_request.service.test.js @@ -0,0 +1,47 @@ +'use strict' + +// Test framework dependencies +const Lab = require('@hapi/lab') +const Code = require('@hapi/code') + +const { describe, it } = exports.lab = Lab.script() +const { expect } = Code + +// Thing under test +const HapiPinoIgnoreRequestService = require('../../../app/services/plugins/hapi_pino_ignore_request.service.js') + +describe('Hapi Pino Ignore Request service', () => { + const options = {} + + 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', () => { + it('returns true', () => { + const result = HapiPinoIgnoreRequestService.go(options, { path: '/assets/stylesheets/application.css' }) + + expect(result).to.be.true() + }) + }) + + 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() + }) + }) +}) From e2c79e87302fc53385eb85c939840b746b0c1309 Mon Sep 17 00:00:00 2001 From: Alan Cruikshanks Date: Fri, 4 Nov 2022 12:56:06 +0000 Subject: [PATCH 4/7] Rename test config We need 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 makes the most sense. Having done then, we concluded this isn't really test config, but log config hence we have renamed the file. --- app/server.js | 4 ++-- config/{test.config.js => log.config.js} | 0 2 files changed, 2 insertions(+), 2 deletions(-) rename config/{test.config.js => log.config.js} (100%) diff --git a/app/server.js b/app/server.js index 909b6286e9..0880a62ee4 100644 --- a/app/server.js +++ b/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) diff --git a/config/test.config.js b/config/log.config.js similarity index 100% rename from config/test.config.js rename to config/log.config.js From 5405e481fb7dd720b657d8781019c8aca48e8781 Mon Sep 17 00:00:00 2001 From: Alan Cruikshanks Date: Sun, 6 Nov 2022 23:34:36 +0000 Subject: [PATCH 5/7] Make asset logging configurable There is a possiblity we need to investigate an issue with assets in the future, for which logging will be incredibly useful. So, we add a config option that allows us to quick configure the repo to start logging asset requests again. --- .../hapi_pino_ignore_request.service.js | 15 ++++++- config/log.config.js | 3 +- .../hapi_pino_ignore_request.service.test.js | 42 +++++++++++++++---- 3 files changed, 49 insertions(+), 11 deletions(-) diff --git a/app/services/plugins/hapi_pino_ignore_request.service.js b/app/services/plugins/hapi_pino_ignore_request.service.js index efd6f81368..a6852c8c71 100644 --- a/app/services/plugins/hapi_pino_ignore_request.service.js +++ b/app/services/plugins/hapi_pino_ignore_request.service.js @@ -4,6 +4,8 @@ * @module HapiPinoIgnoreRequestService */ +const LogConfig = require('../../../config/log.config.js') + class HapiPinoIgnoreRequestService { /** * Returns true or false whether a request should be loged @@ -39,9 +41,18 @@ class HapiPinoIgnoreRequestService { static go(_options, request) { const staticPaths = ['/', '/status'] - const result = staticPaths.includes(request.path) || request.path.startsWith('/assets') + // 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 + } - return result + // Do not ignore all other requests + return false } } diff --git a/config/log.config.js b/config/log.config.js index f0d0b49fd9..a37546a34c 100644 --- a/config/log.config.js +++ b/config/log.config.js @@ -3,7 +3,8 @@ const config = { // Credit to https://stackoverflow.com/a/323546/6117745 for how to handle // converting the env var to a boolean - logInTest: (String(process.env.LOG_IN_TEST) === 'true') || false + logInTest: (String(process.env.LOG_IN_TEST) === 'true') || false, + logAssetRequests: (String(process.env.LOG_ASSET_REQUESTS) === 'true') || false } module.exports = config diff --git a/test/services/plugins/hapi_pino_ignore_request.service.test.js b/test/services/plugins/hapi_pino_ignore_request.service.test.js index 7d629085de..f5950a7552 100644 --- a/test/services/plugins/hapi_pino_ignore_request.service.test.js +++ b/test/services/plugins/hapi_pino_ignore_request.service.test.js @@ -3,19 +3,27 @@ // Test framework dependencies const Lab = require('@hapi/lab') const Code = require('@hapi/code') +const Sinon = require('sinon') -const { describe, it } = exports.lab = Lab.script() +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 = {} + const _options = {} + + afterEach(() => { + Sinon.restore() + }) describe("when the request is for the root '/'", () => { it('returns true', () => { - const result = HapiPinoIgnoreRequestService.go(options, { path: '/' }) + const result = HapiPinoIgnoreRequestService.go(_options, { path: '/' }) expect(result).to.be.true() }) @@ -23,23 +31,41 @@ describe('Hapi Pino Ignore Request service', () => { describe("when the request is for '/status'", () => { it('returns true', () => { - const result = HapiPinoIgnoreRequestService.go(options, { path: '/status' }) + const result = HapiPinoIgnoreRequestService.go(_options, { path: '/status' }) expect(result).to.be.true() }) }) describe('when the request is for an asset', () => { - it('returns true', () => { - const result = HapiPinoIgnoreRequestService.go(options, { path: '/assets/stylesheets/application.css' }) + describe('and LOG_ASSET_REQUESTS is false', () => { + beforeEach(() => { + Sinon.replace(LogConfig, 'logAssetRequests', false) + }) - expect(result).to.be.true() + 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' }) + const result = HapiPinoIgnoreRequestService.go(_options, { path: '/bill-run/stuff' }) expect(result).to.be.false() }) From 894abfb42da021d9cd3dbb17fe825c98b220489c Mon Sep 17 00:00:00 2001 From: Alan Cruikshanks Date: Sun, 6 Nov 2022 23:37:16 +0000 Subject: [PATCH 6/7] Update .env.example and put in alpha order --- .env.example | 3 ++- config/log.config.js | 4 ++-- 2 files changed, 4 insertions(+), 3 deletions(-) diff --git a/.env.example b/.env.example index cbdb396daa..92664cf3bb 100644 --- a/.env.example +++ b/.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 diff --git a/config/log.config.js b/config/log.config.js index a37546a34c..4a22338b2a 100644 --- a/config/log.config.js +++ b/config/log.config.js @@ -3,8 +3,8 @@ const config = { // Credit to https://stackoverflow.com/a/323546/6117745 for how to handle // converting the env var to a boolean - logInTest: (String(process.env.LOG_IN_TEST) === 'true') || false, - logAssetRequests: (String(process.env.LOG_ASSET_REQUESTS) === 'true') || false + logAssetRequests: (String(process.env.LOG_ASSET_REQUESTS) === 'true') || false, + logInTest: (String(process.env.LOG_IN_TEST) === 'true') || false } module.exports = config From 7d322699ffa64fcf2aab97372fe947f460540df0 Mon Sep 17 00:00:00 2001 From: Alan Cruikshanks Date: Sun, 6 Nov 2022 23:41:14 +0000 Subject: [PATCH 7/7] Standardjs fixes --- app/services/plugins/hapi_pino_ignore_request.service.js | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/app/services/plugins/hapi_pino_ignore_request.service.js b/app/services/plugins/hapi_pino_ignore_request.service.js index a6852c8c71..70b0e3b657 100644 --- a/app/services/plugins/hapi_pino_ignore_request.service.js +++ b/app/services/plugins/hapi_pino_ignore_request.service.js @@ -38,8 +38,8 @@ class HapiPinoIgnoreRequestService { * * @returns {boolean} true if the request should be ignored, else false */ - static go(_options, request) { - const staticPaths = ['/', '/status'] + static go (_options, request) { + const staticPaths = ['/', '/status'] // If request is a known path ignore it if (staticPaths.includes(request.path)) {