Better handle errors in Notifiers (#273)

We spotted this issue when [working in another service](DEFRA/water-abstraction-import#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

@@ -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
+      }
+    }
   }
 
   /**

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.

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

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)
   }
 }
 

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 = {

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 = {

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)

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) {