From 86e2e2e6ca1c2be36334d9220f1d8dd109cdbf38 Mon Sep 17 00:00:00 2001 From: Alan Cruikshanks Date: Wed, 21 Jun 2023 11:50:51 +0100 Subject: [PATCH] Better handle errors in Notifiers (#273) We spotted this issue when [working in another service](https://github.com/DEFRA/water-abstraction-import/pull/661) where we have copied the `app/lib/base-notifier.lib.js` and `app/lib/global-notifier.lib.js` across. At the points we wanted to log an error we were calling `global.GlobalNotifier.omfg('import.charge-versions: errored', error)`. When we got an error though, this is what we saw. In the logs, it would just be ```text 0|import | [15:44:40.837] ERROR (8616): 0|import | message: "import.charge-versions: errored" ``` Errbit would get the notification but if you tried to view it you'd get an error. The main issue with the logs was we were treating instances of `Error` as if they were just a POJO when they are not. ```javascript const myError = new Error('boom') const myObject = { ...myError } console.log(myObject) // {} ``` We also went back to the [pino docs](https://github.com/pinojs/pino/blob/master/docs/api.md#logging-method-parameters) and learnt that the log packet we were generating no longer matched what pino was expecting. Specifically, we refreshed our understanding of the [mergingObject](https://github.com/pinojs/pino/blob/master/docs/api.md#mergingobject-object) and realised that we would be better placed to keep any data that needs to be logged separately from the message. We also learnt that pino knows how to log errors, including custom ones with additional properties as long as either - the error instance is passed into the log call as the `mergingObject` - we mimic what pino does and wrap the error instance in a new object with the property `err:` For Airbrake and Errbit uncaught errors were coming through and displaying fine. It was those caught in our logic and passed through as the data argument to `omfg()`. The key difference was `app/plugins/airbrake.plugin.js` when calling `notify()` passes in the error instance as the `error:` property, not `session:`. ```javascript // When Hapi emits a request event with an error we capture the details and use Airbrake to send a request to our // Errbit instance server.events.on({ name: 'request', channels: 'error' }, (request, event, _tags) => { server.app.airbrake .notify({ error: event.error, session: { route: request.route.path, method: request.method, url: request.url.href } }) ``` If we did the same _then_ the error would always display in Errbit. We also found the grouping of errors vastly improved. All this means we are making the following changes - to ensure things are passed through to the logger and errbit correctly, formatting of the arguments for both is moved to `BaseNotifier` rather than forcing extending classes to do their own thing - callers still have the flexibility to just set a message for both `omg()` and `omfg()`. But behind the scenes we _always_ generate an [Error](https://developer.mozilla.org/en-US/docs/Web/JavaScript/Reference/Global_Objects/Error/Error) instance and pass this to the Pino and Airbrake to ensure consistency The result is this. Given the following calls to `omg()` and `omfg()` ```javascript const myError = new ErrorWithDate('Thing go pop') const myData = { thingyId: 'ece18f30-1a73-4579-b752-5ca2607671bf', status: 'snazzy' } global.GlobalNotifier.omg('Keep calm. I am an example of using omg()', myData) global.GlobalNotifier.omfg('Panic! I am an example of using omfg()', myData, myError) ``` We see the following log output (pretty-printed local version) ``` [15:57:10.672] INFO (10292): Keep calm. I am an example of using omg() thingyId: "ece18f30-1a73-4579-b752-5ca2607671bf" status: "snazzy" [15:57:10.673] ERROR (10292): Panic! I am an example of using omfg() thingyId: "ece18f30-1a73-4579-b752-5ca2607671bf" status: "snazzy" err: { "type": "ErrorWithDate", "message": "Thing go pop", "stack": Error: Thing go pop at index (/home/repos/water-abstraction-system/app/controllers/root.controller.js:16:19) at exports.Manager.execute (/home/repos/water-abstraction-system/node_modules/@hapi/hapi/lib/toolkit.js:57:29) at Object.internals.handler (/home/repos/water-abstraction-system/node_modules/@hapi/hapi/lib/handler.js:46:48) at exports.execute (/home/repos/water-abstraction-system/node_modules/@hapi/hapi/lib/handler.js:31:36) at Request._lifecycle (/home/repos/water-abstraction-system/node_modules/@hapi/hapi/lib/request.js:370:68) at processTicksAndRejections (node:internal/process/task_queues:96:5) at async Request._execute (/home/repos/water-abstraction-system/node_modules/@hapi/hapi/lib/request.js:280:9) "dateItHappened": "2023-06-20T15:57:10.672Z" } ``` In Errbit all errors are viewable. Also, it better groups the notifications. --- app/lib/base-notifier.lib.js | 89 +++++-- app/lib/boom-notifier.lib.js | 4 +- app/lib/global-notifier.lib.js | 14 - app/lib/request-notifier.lib.js | 29 +-- .../data/tear-down/tear-down.service.js | 2 +- app/services/db-export/db-export.service.js | 2 +- .../db-export/schema-export.service.js | 2 +- .../process-billing-batch.service.js | 14 +- test/lib/base-notifier.lib.test.js | 241 ++++++++++-------- test/lib/boom-notifier.lib.test.js | 17 -- test/lib/global-notifier.lib.test.js | 34 --- test/lib/request-notifier.lib.test.js | 150 ++++++++--- .../data/tear-down/tear-down.service.test.js | 5 +- .../db-export/db-export.service.test.js | 5 +- .../process-billing-batch.service.test.js | 61 ++--- 15 files changed, 375 insertions(+), 294 deletions(-) diff --git a/app/lib/base-notifier.lib.js b/app/lib/base-notifier.lib.js index 3d31ae2906..b2e8374e9d 100644 --- a/app/lib/base-notifier.lib.js +++ b/app/lib/base-notifier.lib.js @@ -17,7 +17,7 @@ const AirbrakeConfig = require('../../config/airbrake.config.js') * Errbit via {@link https://github.com/airbrake/airbrake-js|airbrake-js} available in the service. * * Most functionality is maintained in this `BaseNotifierLib` with the expectation that classes will extend it for their - * particular scenario, for example, the `RequestNotifierLib` handles including the request ID in its output. + * particular scenario, for example, the `RequestNotifierLib` adds the request ID to the log data and Airbrake session. * * > ***So, `omg()` and `omfg()`. What's that all about!?*** * > @@ -41,16 +41,19 @@ class BaseNotifierLib { * The message will be added as an `INFO` level log message. * * @param {string} message Message to add to the log (INFO) - * @param {Object} data Any params or values, for example, a bill run ID to be included with the log message + * @param {Object} [data={}] An object containing any values to be logged, for example, a bill run ID to be included with + * the log message. Defaults to an empty object */ omg (message, data = {}) { - this._logger.info(this._formatLogPacket(message, data)) + this._logger.info(this._formatLogPacket(data), message) } /** * Use to add an 'error' message to the log and send a notification to Errbit * - * Intended to be used when we want to record an error both in the logs and in Errbit. + * Intended to be used when we want to record an error both in the logs and in Errbit. You don't have to provide + * an error (you may just want to log an event in Errbit). But to help with grouping in Errbit and to keep things + * consistent it will generate a new Error using the provided message. * * ## Notifications to Errbit * @@ -72,22 +75,36 @@ class BaseNotifierLib { * ``` * * @param {string} message Message to add to the log (ERROR) - * @param {Object} data Any params or values, for example, a bill run ID to be included with the log message and sent - * with the notification to Errbit + * @param {Object} [data={}] An object containing any values to be logged and sent in the notification to Errbit, for + * example, a bill run ID. Defaults to an empty object + * @param {Error} [error=null] An instance of the error to be logged and sent to Errbit. If no error is provided one + * will be created using `message` as the error message */ - omfg (message, data = {}) { - this._logger.error(this._formatLogPacket(message, data)) + omfg (message, data = {}, error = null) { + // This deals with anyone calling omfg() with `omfg('It broke', null, error)` which would cause things to break + if (!data) { + data = {} + } + + // To keep logging consistent and to help grouping in Errbit we always work with an error. If one is not provided + // (which is fine!) we create one using the message as the error message + if (!(error instanceof Error)) { + error = new Error(message) + } + + this._logger.error(this._formatLogPacket(data, error), message) - this._notifier.notify(this._formatNotifyPacket(message, data)) - .then(notice => { + this._notifier.notify(this._formatNotifyPacket(data, error, message)) + // This section is a 'just in case' anything goes wrong when trying to send the notification to Errbit. It will + // either fail (cannot connect) or blow up entirely. If it does we log the error directly (no calls to the + // formatter) + .then((notice) => { if (!notice.id) { - this._logger.error( - this._formatLogPacket(`${this.constructor.name} - Airbrake failed`, { error: notice.error }) - ) + this._logger.error(notice.error, `${this.constructor.name} - Airbrake failed`) } }) .catch(err => { - this._logger.error(this._formatLogPacket(`${this.constructor.name} - Airbrake errored`, { error: err })) + this._logger.error(err, `${this.constructor.name} - Airbrake errored`) }) } @@ -107,21 +124,51 @@ class BaseNotifierLib { } /** - * Used to format the 'packet' of information sent to the log + * Used to format the 'mergingObject' passed to pino to be included in the log * - * **Must be overridden by extending class** + * This is a default implementation which can be overridden by notifiers which need to inject additional information. + * + * If no error is specified then it simply returns a copy of the data object passed in. If one is specified we add + * the error to copied data object as `err:`. This mimics what pino does if an error is provided as the + * `mergingObject` param to any log method. It wraps it in an object containing a property `err:`. They reason it + * provides a "unified error handling flow." + * + * By doing it this way we can _still_ pass a `data` arg to `omfg()` and include those values in our log entry along + * with the error. */ - _formatLogPacket (_message, _data) { - throw new Error("Extending class must implement '_formatLogPacket()'") + _formatLogPacket (data, error) { + const packet = { + ...data + } + + if (error instanceof Error) { + packet.err = error + } + + return packet } /** * Used to format the 'packet' of information sent to Errbit * - * **Must be overridden by extending class** + * This is a default implementation which can be overridden by notifiers which need to inject additional values. + * + * Errbit works best by recording and grouping error signatures. It also ensures that any custom errors will be + * handled by Errbit correctly. Passing the error in the `session:` property can cause Errbit to fail when rendering + * errors notified in that way. This is why we must set the `error:` property. + * + * But this means Airbrake's `message:` property becomes ignored. Errbit will set the issue title using the error's + * `message` instead. In order to see our message when a 'proper' error is passed in we include our `message` as a + * property of `session:`. */ - _formatNotifyPacket (_message, _data) { - throw new Error("Extending class must implement '_formatNotifyPacket()'") + _formatNotifyPacket (data, error, message) { + return { + error, + session: { + ...data, + message + } + } } /** diff --git a/app/lib/boom-notifier.lib.js b/app/lib/boom-notifier.lib.js index a36aaaf84d..e37c1d6458 100644 --- a/app/lib/boom-notifier.lib.js +++ b/app/lib/boom-notifier.lib.js @@ -13,11 +13,11 @@ const RequestNotifierLib = require('./request-notifier.lib.js') * A combined logging and Airbrake (Errbit) notification manager which extends RequestNotifierLib to also throw a Boom * `400` error if the .omfg method is called. * - * The use case for RequestNotifierLib is to log errors which occur in syncronous "background" tasks -- ie. where a + * The use case for RequestNotifierLib is to log errors which occur in synchronous "background" tasks -- ie. where a * controller calls a service then immediately returns a response while the service continues to run. Any errors thrown * within the background task are caught and logged using the notifier. * - * The use case for BoomNotifierLib is for when we wish to run one of these background tasks asyncronously -- for + * The use case for BoomNotifierLib is for when we wish to run one of these background tasks asynchronously -- for * example, sending a bill run would normally be done in the background but we want the 'send bill run' admin endpoint * to run it in the foreground so any errors which occur are returned straight away so we don't need to dig through the * logs. diff --git a/app/lib/global-notifier.lib.js b/app/lib/global-notifier.lib.js index 3f89df9561..73c082ce7b 100644 --- a/app/lib/global-notifier.lib.js +++ b/app/lib/global-notifier.lib.js @@ -23,20 +23,6 @@ class GlobalNotifierLib extends BaseNotifierLib { super(logger, notifier) } - - _formatLogPacket (message, data) { - return { - message, - ...data - } - } - - _formatNotifyPacket (message, data) { - return { - message, - session: data - } - } } module.exports = GlobalNotifierLib diff --git a/app/lib/request-notifier.lib.js b/app/lib/request-notifier.lib.js index 59f9a70535..a71a9cb9f5 100644 --- a/app/lib/request-notifier.lib.js +++ b/app/lib/request-notifier.lib.js @@ -36,7 +36,7 @@ class RequestNotifierLib extends BaseNotifierLib { } /** - * Used to format the 'packet' of information sent to the log + * Override the base class's _formatLogPacket to decorate the data object with the request ID * * We don't just want the log output to include the request ID. We want it to output it in the same structure as the * Hapi request is logged, for example @@ -54,21 +54,21 @@ class RequestNotifierLib extends BaseNotifierLib { * { $.req.id = "1617655289640:533c1e381364:1671:kn526tbx:10000" } * ``` */ - _formatLogPacket (message, data) { - return { - message, + _formatLogPacket (data, error) { + const dataWithRequestId = { ...data, req: { id: this._id } } + + return super._formatLogPacket(dataWithRequestId, error) } /** - * Used to format the 'packet' of information sent to Errbit + * Override the base class's _formatNotifyPacket to decorate the data object with the request ID * - * This will format the packet so that Errbit displays the information correctly. It also adds the request ID so we - * can tie it back to the original request that raised the notification + * We add the request ID so we can tie the Errbit entry back to the original request that raised the notification * * This means we can then locate the request in the log entries in AWS Cloudwatch by using * {@link https://docs.aws.amazon.com/AmazonCloudWatch/latest/logs/FilterAndPatternSyntax.html|Metric Filters} @@ -77,16 +77,15 @@ class RequestNotifierLib extends BaseNotifierLib { * { $.req.id = "1617655289640:533c1e381364:1671:kn526tbx:10000" } * ``` */ - _formatNotifyPacket (message, data) { - return { - message, - session: { - ...data, - req: { - id: this._id - } + _formatNotifyPacket (data, error, message) { + const dataWithRequestId = { + ...data, + req: { + id: this._id } } + + return super._formatNotifyPacket(dataWithRequestId, error, message) } } diff --git a/app/services/data/tear-down/tear-down.service.js b/app/services/data/tear-down/tear-down.service.js index b677cbc79f..b492cc341c 100644 --- a/app/services/data/tear-down/tear-down.service.js +++ b/app/services/data/tear-down/tear-down.service.js @@ -30,7 +30,7 @@ function _calculateAndLogTime (startTime) { const timeTakenNs = endTime - startTime const timeTakenMs = timeTakenNs / 1000000n - global.GlobalNotifier.omg(`Tear down: Time taken to process ${timeTakenMs}ms`) + global.GlobalNotifier.omg('Tear down complete', { timeTakenMs }) } module.exports = { diff --git a/app/services/db-export/db-export.service.js b/app/services/db-export/db-export.service.js index 60b915bd9c..6f4dbe8a54 100644 --- a/app/services/db-export/db-export.service.js +++ b/app/services/db-export/db-export.service.js @@ -29,7 +29,7 @@ function _calculateAndLogTime (startTime) { const timeTakenNs = endTime - startTime const timeTakenMs = timeTakenNs / 1000000n - global.GlobalNotifier.omg(`Time taken to export the db: ${timeTakenMs}ms`) + global.GlobalNotifier.omg('DB export complete', { timeTakenMs }) } module.exports = { diff --git a/app/services/db-export/schema-export.service.js b/app/services/db-export/schema-export.service.js index a76826782d..1597552ad2 100644 --- a/app/services/db-export/schema-export.service.js +++ b/app/services/db-export/schema-export.service.js @@ -35,7 +35,7 @@ async function go (schemaName) { compressedSchemaPath = await CompressSchemaFolderService.go(schemaFolderPath) await SendToS3BucketService.go(compressedSchemaPath) } catch (error) { - global.GlobalNotifier.omfg(`Error: Failed to export schema ${schemaName}`, error.message) + global.GlobalNotifier.omfg(`Error: Failed to export schema ${schemaName}`, null, error) } finally { await DeleteFilesService.go(schemaFolderPath) await DeleteFilesService.go(compressedSchemaPath) diff --git a/app/services/supplementary-billing/process-billing-batch.service.js b/app/services/supplementary-billing/process-billing-batch.service.js index 81d62c95cb..aaa8d5fed1 100644 --- a/app/services/supplementary-billing/process-billing-batch.service.js +++ b/app/services/supplementary-billing/process-billing-batch.service.js @@ -61,7 +61,7 @@ function _calculateAndLogTime (billingBatchId, startTime) { const timeTakenNs = endTime - startTime const timeTakenMs = timeTakenNs / 1000000n - global.GlobalNotifier.omg(`Time taken to process billing batch ${billingBatchId}: ${timeTakenMs}ms`) + global.GlobalNotifier.omg('Process billing batch complete', { billingBatchId, timeTakenMs }) } async function _fetchChargeVersions (billingBatch, billingPeriod) { @@ -98,17 +98,7 @@ async function _finaliseBillingBatch (billingBatch, allLicenceIds, isPopulated) } function _logError (billingBatch, error) { - global.GlobalNotifier.omfg( - 'Billing Batch process errored', - { - billingBatch, - error: { - name: error.name, - message: error.message, - stack: error.stack, - code: error.code - } - }) + global.GlobalNotifier.omfg('Billing Batch process errored', { billingBatch }, error) } async function _updateStatus (billingBatchId, status) { diff --git a/test/lib/base-notifier.lib.test.js b/test/lib/base-notifier.lib.test.js index f4417e2542..6dbb8e6d3b 100644 --- a/test/lib/base-notifier.lib.test.js +++ b/test/lib/base-notifier.lib.test.js @@ -12,6 +12,9 @@ const { expect } = Code const BaseNotifierLib = require('../../app/lib/base-notifier.lib.js') describe('BaseNotifierLib class', () => { + const id = '1234567890' + const message = 'say what test' + let airbrakeFake let pinoFake @@ -26,26 +29,27 @@ describe('BaseNotifierLib class', () => { }) describe('#omg()', () => { - const id = '1234567890' - const message = 'say what test' - beforeEach(async () => { Sinon.stub(BaseNotifierLib.prototype, '_setNotifier').returns(airbrakeFake) Sinon.stub(BaseNotifierLib.prototype, '_setLogger').returns(pinoFake) + }) + + describe('when just a message is logged', () => { + it("logs a correctly formatted 'info' level entry", () => { + const testNotifier = new BaseNotifierLib() + testNotifier.omg(message) - // Stub _formatLogPacket to simulate a child class which has provided an override - Sinon.stub(BaseNotifierLib.prototype, '_formatLogPacket').returns({ message, id }) + expect(pinoFake.info.calledOnceWith({}, message)).to.be.true() + }) }) - it("logs an 'info' message", () => { - const expectedArgs = { - message, - id - } - const testNotifier = new BaseNotifierLib() - testNotifier.omg(message, { id }) + describe('when a message and some data is to be logged', () => { + it("logs a correctly formatted 'info' level entry", () => { + const testNotifier = new BaseNotifierLib() + testNotifier.omg(message, { id }) - expect(pinoFake.info.calledOnceWith(expectedArgs)).to.be.true() + expect(pinoFake.info.calledOnceWith({ id }, message)).to.be.true() + }) }) it("does not send a notification to 'Errbit'", () => { @@ -64,14 +68,7 @@ describe('BaseNotifierLib class', () => { }) describe('#omfg()', () => { - const message = 'hell no test' - const data = { offTheChart: true } - - beforeEach(async () => { - // Stub _formatLogPacket and _formatNotifyPacket to simulate a child class which has provided the overrides - Sinon.stub(BaseNotifierLib.prototype, '_formatLogPacket').returns({ message, ...data }) - Sinon.stub(BaseNotifierLib.prototype, '_formatNotifyPacket').returns({ message, session: { ...data } }) - }) + const testError = new Error('hell no test') describe('when the Airbrake notification succeeds', () => { beforeEach(async () => { @@ -79,40 +76,107 @@ describe('BaseNotifierLib class', () => { Sinon.stub(BaseNotifierLib.prototype, '_setLogger').returns(pinoFake) }) - it("does not log an 'info' message", () => { - const testNotifier = new BaseNotifierLib() - testNotifier.omfg(message, data) + describe('and just a message is logged', () => { + it("logs a correctly formatted 'error' level entry", () => { + const testNotifier = new BaseNotifierLib() + testNotifier.omfg(message) + + const logPacketArgs = pinoFake.error.args[0] + + expect(logPacketArgs[0].err).to.be.an.error() + expect(logPacketArgs[0].err.message).to.equal(message) + expect(logPacketArgs[1]).to.equal(message) + }) + + it("sends the expected notification to 'Errbit'", () => { + const testNotifier = new BaseNotifierLib() + testNotifier.omfg(message) - expect(pinoFake.info.notCalled).to.be.true() + const { error, session } = airbrakeFake.notify.args[0][0] + + expect(error).to.be.an.error() + expect(error.message).to.equal(message) + expect(session).to.equal({ message }) + }) }) - it("sends a notification to 'Errbit'", () => { - const expectedArgs = { - message, - session: { - ...data - } - } - const testNotifier = new BaseNotifierLib() - testNotifier.omfg(message, data) + describe('and a message and some data is to be logged', () => { + it("logs a correctly formatted 'error' level entry", () => { + const testNotifier = new BaseNotifierLib() + testNotifier.omfg(message, { id }) - expect(airbrakeFake.notify.calledOnceWith(expectedArgs)).to.be.true() + const logPacketArgs = pinoFake.error.args[0] + + expect(logPacketArgs[0].err).to.be.an.error() + expect(logPacketArgs[0].err.message).to.equal(message) + expect(logPacketArgs[0].id).to.equal(id) + expect(logPacketArgs[1]).to.equal(message) + }) + + it("sends the expected notification to 'Errbit'", () => { + const testNotifier = new BaseNotifierLib() + testNotifier.omfg(message, { id }) + + const { error, session } = airbrakeFake.notify.args[0][0] + + expect(error).to.be.an.error() + expect(error.message).to.equal(message) + expect(session).to.equal({ id, message }) + }) }) - it("logs an 'error' message", () => { - const expectedArgs = { - message, - ...data - } - const testNotifier = new BaseNotifierLib() - testNotifier.omfg(message, data) + describe('and a message, some data and an error is to be logged', () => { + it("logs a correctly formatted 'error' level entry", () => { + const testNotifier = new BaseNotifierLib() + testNotifier.omfg(message, { id }, testError) + + const logPacketArgs = pinoFake.error.args[0] + + expect(logPacketArgs[0].err).to.be.an.error() + expect(logPacketArgs[0].err.message).to.equal(testError.message) + expect(logPacketArgs[0].id).to.equal(id) + expect(logPacketArgs[1]).to.equal(message) + }) + + it("sends the expected notification to 'Errbit'", () => { + const testNotifier = new BaseNotifierLib() + testNotifier.omfg(message, { id }, testError) + + const { error, session } = airbrakeFake.notify.args[0][0] + + expect(error).to.be.an.error() + expect(error.message).to.equal(testError.message) + expect(session).to.equal({ id, message }) + }) + }) + + describe('and a message, no data but an error is to be logged', () => { + it("logs a correctly formatted 'error' level entry", () => { + const testNotifier = new BaseNotifierLib() + testNotifier.omfg(message, null, testError) + + const logPacketArgs = pinoFake.error.args[0] + + expect(logPacketArgs[0].err).to.be.an.error() + expect(logPacketArgs[0].err.message).to.equal(testError.message) + expect(logPacketArgs[1]).to.equal(message) + }) - expect(pinoFake.error.calledOnceWith(expectedArgs)).to.be.true() + it("sends the expected notification to 'Errbit'", () => { + const testNotifier = new BaseNotifierLib() + testNotifier.omfg(message, null, testError) + + const { error, session } = airbrakeFake.notify.args[0][0] + + expect(error).to.be.an.error() + expect(error.message).to.equal(testError.message) + expect(session).to.equal({ message }) + }) }) }) describe('when the Airbrake notification fails', () => { - let error + const airbrakeFailure = new Error('Airbrake failure') beforeEach(async () => { // We specifically use a stub instead of a fake so we can then use Sinon's callsFake() function. See the test @@ -120,25 +184,13 @@ describe('BaseNotifierLib class', () => { pinoFake = { info: Sinon.fake(), error: Sinon.stub() } Sinon.stub(BaseNotifierLib.prototype, '_setLogger').returns(pinoFake) - error = new Error('Airbrake failed') - airbrakeFake = { notify: Sinon.fake.resolves({ error }) } + airbrakeFake = { notify: Sinon.fake.resolves({ name: 'foo', error: airbrakeFailure }) } Sinon.stub(BaseNotifierLib.prototype, '_setNotifier').returns(airbrakeFake) }) - it("does not log an 'info' message", () => { - const testNotifier = new BaseNotifierLib() - testNotifier.omfg(message, data) - - expect(pinoFake.info.notCalled).to.be.true() - }) - it("logs 2 'error' messages, the second containing details of the Airbrake failure", async () => { - const expectedArgs = [ - { message, ...data }, - { message: 'TaskNotifierLib - Airbrake failed', error } - ] const testNotifier = new BaseNotifierLib() - testNotifier.omfg(message, { data }) + testNotifier.omfg(message) // We use Sinon callsFake() here in order to test our expectations. This is because Airbrake notify() actually // returns a promise, and it is on the calling code to handle the responses back. When we test sending the @@ -146,43 +198,45 @@ describe('BaseNotifierLib class', () => { // assert pinoFake.error.secondCall.calledWith() it always fails because the promise which calls it has not yet // resolved. So, callsFake() tells Sinon to call our anonymous function below that includes our assertion only // when pinoFake.error is called i.e. the Airbrake.notify() promise has resolved. - pinoFake.error.callsFake(() => { - expect(pinoFake.error.firstCall.calledWith(expectedArgs[0])) - expect(pinoFake.error.secondCall.calledWith(expectedArgs[1])) + pinoFake.error.callsFake(async () => { + const firstCallArgs = pinoFake.error.firstCall.args + expect(firstCallArgs[0].err).to.be.an.error() + expect(firstCallArgs[0].err.message).to.equal(message) + expect(firstCallArgs[1]).to.equal(message) + + const secondCallArgs = pinoFake.error.secondCall.args + expect(secondCallArgs[0]).to.be.an.error() + expect(secondCallArgs[0].message).to.equal(airbrakeFailure.message) + expect(secondCallArgs[1]).to.equal('BaseNotifierLib - Airbrake failed') }) }) }) describe('when the Airbrake notification errors', () => { - let error + const airbrakeError = new Error('Airbrake error') beforeEach(async () => { pinoFake = { info: Sinon.fake(), error: Sinon.stub() } Sinon.stub(BaseNotifierLib.prototype, '_setLogger').returns(pinoFake) - error = new Error('Airbrake errored') - airbrakeFake = { notify: Sinon.fake.rejects({ error }) } + airbrakeFake = { notify: Sinon.fake.rejects(airbrakeError) } Sinon.stub(BaseNotifierLib.prototype, '_setNotifier').returns(airbrakeFake) }) - it("does not log an 'info' message", () => { - const testNotifier = new BaseNotifierLib() - testNotifier.omfg(message, data) - - expect(pinoFake.info.notCalled).to.be.true() - }) - it("logs 2 'error' messages, the second containing details of the Airbrake errors", async () => { - const expectedArgs = [ - { message, ...data }, - { message: 'TaskNotifierLib - Airbrake failed', error } - ] const testNotifier = new BaseNotifierLib() - testNotifier.omfg(message, { data }) - - pinoFake.error.callsFake(() => { - expect(pinoFake.error.firstCall.calledWith(expectedArgs[0])) - expect(pinoFake.error.secondCall.calledWith(expectedArgs[1])) + testNotifier.omfg(message) + + pinoFake.error.callsFake(async () => { + const firstCallArgs = pinoFake.error.firstCall.args + expect(firstCallArgs[0].err).to.be.an.error() + expect(firstCallArgs[0].err.message).to.equal(message) + expect(firstCallArgs[1]).to.equal(message) + + const secondCallArgs = pinoFake.error.secondCall.args + expect(secondCallArgs[0]).to.be.an.error() + expect(secondCallArgs[0].message).to.equal(airbrakeError.message) + expect(secondCallArgs[1]).to.equal('BaseNotifierLib - Airbrake errored') }) }) }) @@ -200,31 +254,4 @@ describe('BaseNotifierLib class', () => { expect(airbrakeFake.flush.called).to.be.true() }) }) - - describe('#_formatLogPacket()', () => { - it("throws an error if '_formatLogPacket' is not overridden", async () => { - const testNotifier = new BaseNotifierLib() - - expect(() => testNotifier.omg('Oops')).to.throw("Extending class must implement '_formatLogPacket()'") - }) - }) - - describe('#_formatNotifyPacket()', () => { - beforeEach(async () => { - Sinon.stub(BaseNotifierLib.prototype, '_setLogger').returns(pinoFake) - Sinon.stub(BaseNotifierLib.prototype, '_setNotifier').returns(airbrakeFake) - - // We need to stub _formatLogPacket in this test else we don't get to `_formatNotifyPacket()` because of the error - // `_formatLogPacket()` will throw. - Sinon.stub(BaseNotifierLib.prototype, '_formatLogPacket').callsFake(() => { - return { message: 'Boom!' } - }) - }) - - it("throws an error if '_formatNotifyPacket' is not overridden", async () => { - const testNotifier = new BaseNotifierLib() - - expect(() => testNotifier.omfg('Oops')).to.throw("Extending class must implement '_formatNotifyPacket()'") - }) - }) }) diff --git a/test/lib/boom-notifier.lib.test.js b/test/lib/boom-notifier.lib.test.js index bd911a7f17..57fc219622 100644 --- a/test/lib/boom-notifier.lib.test.js +++ b/test/lib/boom-notifier.lib.test.js @@ -29,23 +29,6 @@ describe('BoomNotifierLib class', () => { const message = 'hell no test' const data = { offTheChart: true } - it('formats it as expected', () => { - const expectedArgs = { - message, - session: { - ...data, - req: { - id - } - } - } - const testNotifier = new BoomNotifierLib(id, pinoFake, airbrakeFake) - - // We wrap the call in this assertion so the thrown error doesn't cause the test to fail - expect(() => testNotifier.omfg(message, data)).to.throw() - expect(airbrakeFake.notify.calledOnceWith(expectedArgs)).to.be.true() - }) - it('throws a Boom error with the correct message and data', async () => { const testNotifier = new BoomNotifierLib(id, pinoFake, airbrakeFake) diff --git a/test/lib/global-notifier.lib.test.js b/test/lib/global-notifier.lib.test.js index 8c5475c16e..94a440c664 100644 --- a/test/lib/global-notifier.lib.test.js +++ b/test/lib/global-notifier.lib.test.js @@ -43,38 +43,4 @@ describe('GlobalNotifierLib class', () => { }) }) }) - - describe('when a log entry is made', () => { - const id = '1234567890' - const message = 'say what test' - - it('formats it as expected', () => { - const expectedArgs = { - message, - id - } - const testNotifier = new GlobalNotifierLib(pinoFake, airbrakeFake) - testNotifier.omg(message, { id }) - - expect(pinoFake.info.calledOnceWith(expectedArgs)).to.be.true() - }) - }) - - describe('when an airbrake notification is sent', () => { - const message = 'hell no test' - const data = { offTheChart: true } - - it('formats it as expected', () => { - const expectedArgs = { - message, - session: { - ...data - } - } - const testNotifier = new GlobalNotifierLib(pinoFake, airbrakeFake) - testNotifier.omfg(message, data) - - expect(airbrakeFake.notify.calledOnceWith(expectedArgs)).to.be.true() - }) - }) }) diff --git a/test/lib/request-notifier.lib.test.js b/test/lib/request-notifier.lib.test.js index 2397c067c5..b7f152b7ff 100644 --- a/test/lib/request-notifier.lib.test.js +++ b/test/lib/request-notifier.lib.test.js @@ -13,6 +13,8 @@ const RequestNotifierLib = require('../../app/lib/request-notifier.lib.js') describe('RequestNotifierLib class', () => { const id = '1234567890' + const message = 'say what test' + let airbrakeFake let pinoFake @@ -25,41 +27,129 @@ describe('RequestNotifierLib class', () => { Sinon.restore() }) - describe('when a log entry is made', () => { - const message = 'say what test' + describe('#omg()', () => { + describe('when just a message is logged', () => { + it("logs a correctly formatted 'info' level entry", () => { + const testNotifier = new RequestNotifierLib(id, pinoFake, airbrakeFake) + testNotifier.omg(message) + + expect(pinoFake.info.calledOnceWith({ req: { id } }, message)).to.be.true() + }) + }) - it("logs an 'info' message", () => { - const expectedArgs = { - message, - req: { - id - } - } - const testNotifier = new RequestNotifierLib(id, pinoFake, airbrakeFake) - testNotifier.omg(message) + describe('when a message and some data is to be logged', () => { + it("logs a correctly formatted 'info' level entry", () => { + const testNotifier = new RequestNotifierLib(id, pinoFake, airbrakeFake) + testNotifier.omg(message, { name: 'foo' }) - expect(pinoFake.info.calledOnceWith(expectedArgs)).to.be.true() + expect(pinoFake.info.calledOnceWith({ name: 'foo', req: { id } }, message)).to.be.true() + }) }) }) - describe('when an airbrake notification is sent', () => { - const message = 'hell no test' - const data = { offTheChart: true } - - it('formats it as expected', () => { - const expectedArgs = { - message, - session: { - ...data, - req: { - id - } - } - } - const testNotifier = new RequestNotifierLib(id, pinoFake, airbrakeFake) - testNotifier.omfg(message, data) - - expect(airbrakeFake.notify.calledOnceWith(expectedArgs)).to.be.true() + describe('#omfg()', () => { + const testError = new Error('hell no test') + + describe('when just a message is logged', () => { + it("logs a correctly formatted 'error' level entry", () => { + const testNotifier = new RequestNotifierLib(id, pinoFake, airbrakeFake) + testNotifier.omfg(message) + + const logPacketArgs = pinoFake.error.args[0] + + expect(logPacketArgs[0].err).to.be.an.error() + expect(logPacketArgs[0].err.message).to.equal(message) + expect(logPacketArgs[0].req.id).to.equal(id) + expect(logPacketArgs[1]).to.equal(message) + }) + + it("sends the expected notification to 'Errbit'", () => { + const testNotifier = new RequestNotifierLib(id, pinoFake, airbrakeFake) + testNotifier.omfg(message) + + const { error, session } = airbrakeFake.notify.args[0][0] + + expect(error).to.be.an.error() + expect(error.message).to.equal(message) + expect(session).to.equal({ message, req: { id } }) + }) + }) + + describe('when a message and some data is to be logged', () => { + it("logs a correctly formatted 'error' level entry", () => { + const testNotifier = new RequestNotifierLib(id, pinoFake, airbrakeFake) + testNotifier.omfg(message, { name: 'foo' }) + + const logPacketArgs = pinoFake.error.args[0] + + expect(logPacketArgs[0].err).to.be.an.error() + expect(logPacketArgs[0].err.message).to.equal(message) + expect(logPacketArgs[0].req.id).to.equal(id) + expect(logPacketArgs[0].name).to.equal('foo') + expect(logPacketArgs[1]).to.equal(message) + }) + + it("sends the expected notification to 'Errbit'", () => { + const testNotifier = new RequestNotifierLib(id, pinoFake, airbrakeFake) + testNotifier.omfg(message, { name: 'foo' }) + + const { error, session } = airbrakeFake.notify.args[0][0] + + expect(error).to.be.an.error() + expect(error.message).to.equal(message) + expect(session).to.equal({ name: 'foo', message, req: { id } }) + }) + }) + + describe('when a message, some data and an error is to be logged', () => { + it("logs a correctly formatted 'error' level entry", () => { + const testNotifier = new RequestNotifierLib(id, pinoFake, airbrakeFake) + testNotifier.omfg(message, { name: 'foo' }, testError) + + const logPacketArgs = pinoFake.error.args[0] + + expect(logPacketArgs[0].err).to.be.an.error() + expect(logPacketArgs[0].err.message).to.equal(testError.message) + expect(logPacketArgs[0].req.id).to.equal(id) + expect(logPacketArgs[0].name).to.equal('foo') + expect(logPacketArgs[1]).to.equal(message) + }) + + it("sends the expected notification to 'Errbit'", () => { + const testNotifier = new RequestNotifierLib(id, pinoFake, airbrakeFake) + testNotifier.omfg(message, { name: 'foo' }, testError) + + const { error, session } = airbrakeFake.notify.args[0][0] + + expect(error).to.be.an.error() + expect(error.message).to.equal(testError.message) + expect(session).to.equal({ name: 'foo', message, req: { id } }) + }) + }) + + describe('when a message, no data but an error is to be logged', () => { + it("logs a correctly formatted 'error' level entry", () => { + const testNotifier = new RequestNotifierLib(id, pinoFake, airbrakeFake) + testNotifier.omfg(message, null, testError) + + const logPacketArgs = pinoFake.error.args[0] + + expect(logPacketArgs[0].err).to.be.an.error() + expect(logPacketArgs[0].err.message).to.equal(testError.message) + expect(logPacketArgs[0].req.id).to.equal(id) + expect(logPacketArgs[1]).to.equal(message) + }) + + it("sends the expected notification to 'Errbit'", () => { + const testNotifier = new RequestNotifierLib(id, pinoFake, airbrakeFake) + testNotifier.omfg(message, null, testError) + + const { error, session } = airbrakeFake.notify.args[0][0] + + expect(error).to.be.an.error() + expect(error.message).to.equal(testError.message) + expect(session).to.equal({ message, req: { id } }) + }) }) }) }) diff --git a/test/services/data/tear-down/tear-down.service.test.js b/test/services/data/tear-down/tear-down.service.test.js index b5e2390968..6c832ce94d 100644 --- a/test/services/data/tear-down/tear-down.service.test.js +++ b/test/services/data/tear-down/tear-down.service.test.js @@ -47,9 +47,10 @@ describe('Tear down service', () => { it('tears down the schemas', async () => { await TearDownService.go() - const logMessage = notifierStub.omg.firstCall.args[0] + const args = notifierStub.omg.firstCall.args - expect(logMessage).to.startWith('Tear down: Time taken to process') + expect(args[0]).to.equal('Tear down complete') + expect(args[1].timeTakenMs).to.exist() expect(waterSchemaServiceStub.called).to.be.true() expect(crmSchemaServiceStub.called).to.be.true() diff --git a/test/services/db-export/db-export.service.test.js b/test/services/db-export/db-export.service.test.js index 5c12393e2b..d52b00d014 100644 --- a/test/services/db-export/db-export.service.test.js +++ b/test/services/db-export/db-export.service.test.js @@ -44,8 +44,9 @@ describe('Db Export Service', () => { it('logs the time taken to export the db', async () => { await DbExportService.go() - const logMessage = notifierStub.omg.firstCall.args[0] + const args = notifierStub.omg.firstCall.args - expect(logMessage).to.startWith('Time taken to export the db: ') + expect(args[0]).to.equal('DB export complete') + expect(args[1].timeTakenMs).to.exist() }) }) diff --git a/test/services/supplementary-billing/process-billing-batch.service.test.js b/test/services/supplementary-billing/process-billing-batch.service.test.js index 55e8daccc2..b5bdd032ce 100644 --- a/test/services/supplementary-billing/process-billing-batch.service.test.js +++ b/test/services/supplementary-billing/process-billing-batch.service.test.js @@ -107,9 +107,11 @@ describe('Process billing batch service', () => { it('logs the time taken to process the billing batch', async () => { await ProcessBillingBatchService.go(billingBatch, billingPeriods) - const logMessage = notifierStub.omg.firstCall.args[0] + const args = notifierStub.omg.firstCall.args - expect(logMessage).to.startWith(`Time taken to process billing batch ${billingBatch.billingBatchId}:`) + expect(args[0]).to.equal('Process billing batch complete') + expect(args[1].timeTakenMs).to.exist() + expect(args[1].billingBatchId).to.equal(billingBatch.billingBatchId) }) }) @@ -134,21 +136,14 @@ describe('Process billing batch service', () => { it('logs the error', async () => { await ProcessBillingBatchService.go(billingBatch, billingPeriods) - const logDataArg = notifierStub.omfg.firstCall.args[1] - - expect(notifierStub.omfg.calledWith('Billing Batch process errored')).to.be.true() - expect(logDataArg.billingBatch).to.equal(billingBatch) - - // We can't do a direct comparison of the error object as in other tests. This is because when `thrownError` - // is caught in a try catch it is passed to a `new BillingBatchError()` call. That causes the stack trace to - // be rewritten which means they'll always differ. So, we have to skip it in the comparison - expect(logDataArg.error).to.equal({ - name: thrownError.name, - message: `Error: ${thrownError.message}`, - code: BillingBatchModel.errorCodes.failedToProcessChargeVersions - }, - { skip: 'stack' } - ) + const args = notifierStub.omfg.firstCall.args + + expect(args[0]).to.equal('Billing Batch process errored') + expect(args[1].billingBatch.billingBatchId).to.equal(billingBatch.billingBatchId) + expect(args[2]).to.be.an.error() + expect(args[2].name).to.equal(thrownError.name) + expect(args[2].message).to.equal(`Error: ${thrownError.message}`) + expect(args[2].code).to.equal(BillingBatchModel.errorCodes.failedToProcessChargeVersions) }) }) @@ -172,16 +167,14 @@ describe('Process billing batch service', () => { it('logs the error', async () => { await ProcessBillingBatchService.go(billingBatch, billingPeriods) - const logDataArg = notifierStub.omfg.firstCall.args[1] + const args = notifierStub.omfg.firstCall.args - expect(notifierStub.omfg.calledWith('Billing Batch process errored')).to.be.true() - expect(logDataArg.billingBatch).to.equal(billingBatch) - expect(logDataArg.error).to.equal({ - name: thrownError.name, - message: thrownError.message, - stack: thrownError.stack, - code: BillingBatchModel.errorCodes.failedToPrepareTransactions - }) + expect(args[0]).to.equal('Billing Batch process errored') + expect(args[1].billingBatch.billingBatchId).to.equal(billingBatch.billingBatchId) + expect(args[2]).to.be.an.error() + expect(args[2].name).to.equal(thrownError.name) + expect(args[2].message).to.equal(thrownError.message) + expect(args[2].code).to.equal(BillingBatchModel.errorCodes.failedToPrepareTransactions) }) }) }) @@ -206,16 +199,14 @@ describe('Process billing batch service', () => { it('logs the error', async () => { await ProcessBillingBatchService.go(billingBatch, billingPeriods) - const logDataArg = notifierStub.omfg.firstCall.args[1] + const args = notifierStub.omfg.firstCall.args - expect(notifierStub.omfg.calledWith('Billing Batch process errored')).to.be.true() - expect(logDataArg.billingBatch).to.equal(billingBatch) - expect(logDataArg.error).to.equal({ - name: thrownError.name, - message: thrownError.message, - stack: thrownError.stack, - code: undefined - }) + expect(args[0]).to.equal('Billing Batch process errored') + expect(args[1].billingBatch.billingBatchId).to.equal(billingBatch.billingBatchId) + expect(args[2]).to.be.an.error() + expect(args[2].name).to.equal(thrownError.name) + expect(args[2].message).to.equal(thrownError.message) + expect(args[2].code).to.be.undefined() }) }) })