feat(winston): improve serialization of Error instances (#158)

This handles the various ways an Error instance can be passed
to a Winston logger, and serializes those Errors to 'error.*'
fields.

Closes: #128

Author: trentm

packages/ecs-winston-format/CHANGELOG.md

@@ -2,6 +2,40 @@
 
 ## Unreleased
 
+- Fix/improve serialization of error details to `error.*` fields for the
+  various ways a Winston logger handles `Error` instances.
+
+    ```js
+    const aCause = new Error('the cause');
+    const anErr = new Error('boom', {cause: aCause});
+    anErr.code = 42;
+
+    log.debug("some message", anErr); // Form 1
+    log.info(anErr, {foo: "bar"}); // Form 2
+    log.warn("some message", {err: anErr, foo: "bar"}); // Form 3
+    ```
+
+  1. Winston will add a `stack` field for an error passed this way.
+  2. If the `logform.errors(...)` format is configured, Winston will serialize
+     `anErr` passed this way.
+  3. Passing an error via the `err` meta field is specific to
+     `@elastic/ecs-winston-format` and is discouraged. If possible, use style 1.
+     It will remain for now for backward compatibility.
+
+  With this change, all three cases above will result in `anErr` details being
+  serialized to [ECS `error.*` fields](https://www.elastic.co/guide/en/ecs/current/ecs-error.html),
+  as well as [`error.cause`](https://developer.mozilla.org/en-US/docs/Web/JavaScript/Reference/Global_Objects/Error/cause)
+  and other properties on the error instance. Forms 2 and 3 are enabled via
+  the `convertErr: true` configuration option.
+  See [examples/basic.js](./examples/basic.js).
+
+  In addition, if your Winston logger is configured to handle `uncaughtException`
+  and/or `unhandledRejection` (https://github.com/winstonjs/winston#exceptions),
+  then the Error instance included in this log record will be serialized to
+  `error.*` fields. See [test/uncaught-exception.js](./test/uncaught-exception.js)
+  and [test/unhandled-rejection.js](./test/unhandled-rejection.js) for examples.
+  (https://github.com/elastic/ecs-logging-nodejs/issues/128)
+
 - Switch to `safe-stable-stringify` for JSON serialization. This library
   protects against circular references and bigints.
   (https://github.com/elastic/ecs-logging-nodejs/pull/155)

packages/ecs-winston-format/examples/basic.js

@@ -23,10 +23,22 @@ const ecsFormat = require('../') // @elastic/ecs-winston-format
 const logger = winston.createLogger({
   level: 'info',
   format: ecsFormat(),
+  // Compare to:
+  // format: winston.format.combine(
+  //   winston.format.errors({stack: true, cause: true}),
+  //   winston.format.json()
+  // ),
   transports: [
-    new winston.transports.Console()
+    new winston.transports.Console({
+      handleExceptions: true,
+      handleRejections: true
+    })
   ]
 })
 
 logger.info('hi')
-logger.error('oops there is a problem', { foo: 'bar' })
+logger.warn('look out', { foo: 'bar' })
+
+const err = new Error('boom', { cause: new Error('the cause') })
+err.code = 42
+logger.error('here is an exception', err)

packages/ecs-winston-format/index.js

@@ -17,11 +17,10 @@
 
 'use strict'
 
-const { MESSAGE } = require('triple-beam')
+const { MESSAGE, SPLAT } = require('triple-beam')
 const safeStableStringify = require('safe-stable-stringify')
 const {
   version,
-  formatError,
   formatHttpRequest,
   formatHttpResponse
 } = require('@elastic/ecs-helpers')
@@ -48,11 +47,11 @@ try {
 const stringify = safeStableStringify.configure({ deterministic: false })
 
 const reservedFields = {
+  '@timestamp': true,
+  error: true,
   level: true,
   'log.level': true,
-  ecs: true,
-  '@timestamp': true,
-  err: true,
+  message: true,
   req: true,
   res: true
 }
@@ -82,6 +81,117 @@ class EcsWinstonTransform {
       'ecs.version': version
     }
 
+    // Error handling. Winston has a number of ways that it does something with
+    // `Error` instances passed to a logger.
+    //
+    // 1. `log.warn('a message', new Error('boom'))`
+    //    If `info[SPLAT][0] instanceof Error`, then convert it to `error.*` fields
+    //    in place of `info.stack`.
+    //
+    // 2. Winston logger configured to handle uncaughtException and/or unhandledRejection.
+    //    If `info.exception: true` and level is "error" and `info.trace` is an
+    //    Array and `info.message` starts with "uncaughtException:" or
+    //    "unhandledRejection:", then convert to `error.*` fields. These
+    //    conditions are to infer the `info` shape returned by Winston's
+    //    `ExceptionHandler` and `RejectionHandler`.
+    //    In this case the redundant `stack`, `trace`, `date` fields are dropped
+    //    and error details are moved to the `error.*` fields.
+    //
+    // If `opts.convertErr === true` (the default), then the next two forms are
+    // considered as well.
+    //
+    // 3. `log.warn(new Error('boom'))`
+    //    `log.warn(new Error(''))`
+    //    `log.warn(new Error('boom'), {foo: 'bar'})`
+    //    If `info instanceof Error` or `info.message instanceof Error`, then
+    //    convert it to `error.*` fields. The latter two are a little strange, but
+    //    Winston's logger will transform that to `{ message: new Error(...) }`
+    //    and "logform/errors.js" will handle that.
+    //
+    // 4. `log.warn('a message', { err: new Error('boom') })`
+    //    If `info.err instanceof Error`, then convert to `error.*` fields.
+    //    Note: This feature doesn't really belong because it extends error
+    //    handling beyond what is typical in Winston. It remains for backward
+    //    compatibility.
+    let err
+    let delErrorLevel = false
+    const splat0 = SPLAT && info[SPLAT] && info[SPLAT][0]
+    if (splat0 instanceof Error) { // case 1
+      // Undo the addition of this error's enumerable properties to the
+      // top-level info object.
+      err = splat0
+      delete info.stack
+      for (const propName in err) {
+        delete info[propName]
+      }
+    } else if (info.exception === true &&
+      info.level === 'error' &&
+      Array.isArray(info.trace) &&
+      (info.message.startsWith('uncaughtException:') ||
+        info.message.startsWith('unhandledRejection:'))) { // case 2
+      // The 'stack', 'trace', and trace in the 'message' are redundant.
+      // 'date' is also redundant with '@timestamp'.
+      delete info.stack
+      delete info.trace
+      delete info.date
+      ecsFields.message = info.message.split(/\n/, 1)[0]
+      // istanbul ignore else
+      if (info.error instanceof Error) {
+        err = info.error
+      } else {
+        ecsFields.error = {
+          message: info.error.toString()
+        }
+      }
+      delete info.error
+      // Dev Note: We *could* translate some of the process and os fields, but
+      // we don't currently.
+      //    https://www.elastic.co/guide/en/ecs/current/ecs-process.html
+      //    https://www.elastic.co/guide/en/ecs/current/ecs-host.html
+    } else if (convertErr) { // cases 3 and 4
+      if (info instanceof Error) {
+        // With `log.info(err)`, Winston incorrectly uses `err` as the info
+        // object -- (a) mutating it and (b) resulting in not being able to
+        // differentiate `defaultMeta` and `err` properties.
+        // The best we can do is, at least, not serialize `error.level` using
+        // the incorrectly added `level` field.
+        err = info
+        delErrorLevel = true
+      } else if (info.message instanceof Error) {
+        // `log.info(err, {...})` or `log.info(new Error(''))` with empty message.
+        err = info.message
+        ecsFields.message = err.message
+      } else if (info.err instanceof Error) {
+        err = info.err
+        delete info.err
+      }
+    }
+
+    // If we have an Error instance, then serialize it to `error.*` fields.
+    if (err) {
+      // First we add err's enumerable fields, as `logform.errors()` does.
+      ecsFields.error = Object.assign({}, err)
+      if (delErrorLevel) {
+        delete ecsFields.error.level
+      }
+      // Then add standard ECS error fields (https://www.elastic.co/guide/en/ecs/current/ecs-error.html).
+      // istanbul ignore next
+      ecsFields.error.type = toString.call(err.constructor) === '[object Function]'
+        ? err.constructor.name
+        : err.name
+      ecsFields.error.message = err.message
+      ecsFields.error.stack_trace = err.stack
+      // The add some additional fields. `cause` is handled by
+      // `logform.errors({cause: true})`.  This implementation ensures it is
+      // always a string to avoid its type varying depending on the value.
+      // istanbul ignore next -- so coverage works for Node.js <16.9.0
+      if (err.cause) {
+        ecsFields.error.cause = err.cause instanceof Error
+          ? err.cause.stack
+          : err.cause.toString()
+      }
+    }
+
     // Add all unreserved fields.
     const keys = Object.keys(info)
     for (let i = 0, len = keys.length; i < len; i++) {
@@ -165,15 +275,6 @@ class EcsWinstonTransform {
       }
     }
 
-    // https://www.elastic.co/guide/en/ecs/current/ecs-error.html
-    if (info.err !== undefined) {
-      if (convertErr) {
-        formatError(ecsFields, info.err)
-      } else {
-        ecsFields.err = info.err
-      }
-    }
-
     // https://www.elastic.co/guide/en/ecs/current/ecs-http.html
     if (info.req !== undefined) {
       if (convertReqRes) {

packages/ecs-winston-format/package.json

@@ -49,6 +49,7 @@
     "autocannon": "^7.0.1",
     "elastic-apm-node": "^3.23.0",
     "express": "^4.17.1",
+    "semver": "^7.5.4",
     "split2": "^3.2.2",
     "standard": "16.x",
     "tap": "^15.0.10",

packages/ecs-winston-format/test/basic.test.js

@@ -20,38 +20,12 @@
 const http = require('http')
 const test = require('tap').test
 const winston = require('winston')
-const Transport = require('winston-transport')
 const { MESSAGE } = require('triple-beam')
-const addFormats = require('ajv-formats').default
-const Ajv = require('ajv').default
 const { version } = require('@elastic/ecs-helpers')
 
 const ecsFormat = require('../')
 const { ecsLoggingValidate } = require('../../../utils/lib/ecs-logging-validate')
-
-const ajv = new Ajv({
-  allErrors: true,
-  verbose: true
-})
-addFormats(ajv)
-const validate = ajv.compile(require('../../../utils/schema.json'))
-
-// Winston transport to capture logged records. Parsed JSON records are on
-// `.records`. Raw records (what Winston calls `info` objects) are on `.infos`.
-class CaptureTransport extends Transport {
-  constructor () {
-    super()
-    this.records = []
-    this.infos = []
-  }
-
-  log (info, callback) {
-    this.infos.push(info)
-    const record = JSON.parse(info[MESSAGE])
-    this.records.push(record)
-    callback()
-  }
-}
+const { validate, CaptureTransport } = require('./utils')
 
 test('Should produce valid ecs logs', t => {
   t.plan(4)
@@ -300,19 +274,3 @@ test('can configure correlation fields', t => {
   t.equal(rec['event.dataset'], 'override-eventDataset')
   t.end()
 })
-
-test('can handle circular refs', t => {
-  const cap = new CaptureTransport()
-  const logger = winston.createLogger({
-    format: ecsFormat(),
-    transports: [cap]
-  })
-
-  const obj = { foo: 'bar' }
-  obj.self = obj
-  logger.info('hi', { obj })
-
-  const rec = cap.records[0]
-  t.strictSame(rec.obj, { foo: 'bar', self: '[Circular]' })
-  t.end()
-})