fix(winston, pino): a few crashes with req, res, event, and service fields (#71)

Fix a couple crashes with convertReqRes:true and logging a req/res that
isn't an HTTP request or response object -- via update to ecs-helpers v1.1.0.
Also fix some conflicts with logging top-level "event" and "service"
fields with the winston formatter.

Fixes: #58
Fixes: #59

Author: trentm

loggers/morgan/CHANGELOG.md

@@ -2,6 +2,9 @@
 
 ## Unreleased
 
+- Update @elastic/ecs-helpers@1.1.0 to get more robust HTTP req and res
+  formatting.
+
 - Add `apmIntegration: false` option to all ecs-logging formatters to
   enable explicitly disabling Elastic APM integration.
   ([#62](https://github.com/elastic/ecs-logging-nodejs/pull/62))

loggers/morgan/package.json

@@ -35,7 +35,7 @@
     "node": ">=10"
   },
   "dependencies": {
-    "@elastic/ecs-helpers": "^1.0.0"
+    "@elastic/ecs-helpers": "^1.1.0"
   },
   "devDependencies": {
     "ajv": "^7.0.3",

loggers/pino/CHANGELOG.md

@@ -2,6 +2,10 @@
 
 ## Unreleased
 
+- Fix a "TypeError: Cannot read property 'host' of undefined" crash when using
+  `convertReqRes: true` and logging a `req` field that is not an HTTP request
+  object.
+
 - Set the "message" to the empty string for logger calls that provide no
   message, e.g. `log.info({foo: 'bar'})`. In this case pino will not add a
   message field, which breaks ecs-logging spec.

loggers/pino/package.json

@@ -34,7 +34,7 @@
     "node": ">=10"
   },
   "dependencies": {
-    "@elastic/ecs-helpers": "^1.0.0"
+    "@elastic/ecs-helpers": "^1.1.0"
   },
   "devDependencies": {
     "ajv": "^7.0.3",

loggers/winston/CHANGELOG.md

@@ -2,6 +2,18 @@
 
 ## Unreleased
 
+- Fix a crash ([#58](https://github.com/elastic/ecs-logging-nodejs/issues/58))
+  when using APM integration and logging a record with an "event" or
+  "service" top-level field that isn't an object. The "fix" here is to
+  silently discard that "event" or "service" field because a non-object
+  conflicts with the ECS spec for those fields. (See
+  [#68](https://github.com/elastic/ecs-logging-nodejs/issues/68) for a
+  discussion of the general ECS type conflict issue.)
+
+- Fix a crash ([#59](https://github.com/elastic/ecs-logging-nodejs/issues/59))
+  when using `convertReqRes: true` and logging a `res` field that is not an
+  HTTP response object.
+
 - Add `apmIntegration: false` option to all ecs-logging formatters to
   enable explicitly disabling Elastic APM integration.
   ([#62](https://github.com/elastic/ecs-logging-nodejs/pull/62))

loggers/winston/index.js

@@ -103,7 +103,9 @@ function ecsTransform (info, opts) {
   // istanbul ignore else
   if (apm) {
     // Set "service.name" and "event.dataset" from APM conf, if not already set.
-    let serviceName = ecsFields.service && ecsFields.service.name
+    let serviceName = (ecsFields.service && ecsFields.service.name && typeof ecsFields.service.name === 'string'
+      ? ecsFields.service.name
+      : undefined)
     if (!serviceName) {
       // https://github.com/elastic/apm-agent-nodejs/pull/1949 is adding
       // getServiceName() in v3.11.0. Fallback to private `apm._conf`.
@@ -114,13 +116,27 @@ function ecsTransform (info, opts) {
       // A mis-configured APM Agent can be "started" but not have a
       // "serviceName".
       if (serviceName) {
-        ecsFields.service = ecsFields.service || {}
-        ecsFields.service.name = serviceName
+        if (ecsFields.service === undefined) {
+          ecsFields.service = { name: serviceName }
+        } else if (!isVanillaObject(ecsFields.service)) {
+          // Warning: "service" type conflicts with ECS spec. Overwriting.
+          ecsFields.service = { name: serviceName }
+        } else {
+          ecsFields.service.name = serviceName
+        }
       }
     }
-    if (serviceName && !(ecsFields.event && ecsFields.event.dataset)) {
-      ecsFields.event = ecsFields.event || {}
-      ecsFields.event.dataset = serviceName + '.log'
+    if (serviceName &&
+        !(ecsFields.event && ecsFields.event.dataset &&
+          typeof ecsFields.event.dataset === 'string')) {
+      if (ecsFields.event === undefined) {
+        ecsFields.event = { dataset: serviceName + '.log' }
+      } else if (!isVanillaObject(ecsFields.event)) {
+        // Warning: "event" type conflicts with ECS spec. Overwriting.
+        ecsFields.event = { dataset: serviceName + '.log' }
+      } else {
+        ecsFields.event.dataset = serviceName + '.log'
+      }
     }
 
     // https://www.elastic.co/guide/en/ecs/current/ecs-tracing.html
@@ -168,4 +184,19 @@ function ecsTransform (info, opts) {
   return info
 }
 
+// Return true if the given arg is a "vanilla" object. Roughly the intent is
+// whether this is basic mapping of string keys to values that will serialize
+// as a JSON object.
+//
+// Currently, it excludes Map. The uses above don't really expect a user to:
+//     service = new Map([["foo", "bar"]])
+//     log.info({ service }, '...')
+//
+// There are many ways tackle this. See some attempts and benchmarks at:
+// https://gist.github.com/trentm/34131a92eede80fd2109f8febaa56f5a
+function isVanillaObject (o) {
+  return (typeof o === 'object' &&
+    (!o.constructor || o.constructor.name === 'Object'))
+}
+
 module.exports = format(ecsTransform)

loggers/winston/package.json

@@ -35,7 +35,7 @@
     "node": ">=10"
   },
   "dependencies": {
-    "@elastic/ecs-helpers": "^1.0.0"
+    "@elastic/ecs-helpers": "^1.1.0"
   },
   "devDependencies": {
     "ajv": "^7.0.3",

loggers/winston/test/apm.test.js

@@ -335,8 +335,17 @@ test('can override service.name, event.dataset', t => {
     const recs = stdout.trim().split(/\n/g).map(JSON.parse)
     t.equal(recs[0].service.name, 'myname')
     t.equal(recs[0].event.dataset, 'mydataset')
+
+    // If integrating with APM and the log record sets "service.name" to a
+    // non-string or "service" to a non-object, then ecs-winston-format will
+    // overwrite it because it conflicts with the ECS specified type.
     t.equal(recs[1].service.name, 'test-apm')
     t.equal(recs[1].event.dataset, 'test-apm.log')
+    t.equal(recs[2].service.name, 'test-apm')
+    t.equal(recs[2].event.dataset, 'test-apm.log')
+
+    t.equal(recs[3].service.name, 'test-apm')
+    t.equal(recs[3].event.dataset, 'test-apm.log')
     t.end()
   })
 })
@@ -355,8 +364,8 @@ test('unset APM serviceName does not set service.name, event.dataset, but also d
     const recs = stdout.trim().split(/\n/g).map(JSON.parse)
     t.equal(recs[0].service.name, 'myname')
     t.equal(recs[0].event.dataset, 'mydataset')
-    t.equal(recs[1].service, undefined)
-    t.equal(recs[1].event, undefined)
+    t.equal(recs[3].service, undefined)
+    t.equal(recs[3].event, undefined)
     t.end()
   })
 })

loggers/winston/test/use-apm-override-service-name.js

@@ -45,9 +45,10 @@ const log = winston.createLogger({
   ]
 })
 
-log.info('hi', {
-  foo: 'bar',
-  service: { name: 'myname' },
-  event: { dataset: 'mydataset' }
-})
-log.info('bye', { foo: 'bar' })
+log.info('override values',
+  { service: { name: 'myname' }, event: { dataset: 'mydataset' } })
+log.info('override values with nums',
+  { service: { name: 42 }, event: { dataset: 42 } })
+log.info('override top-level keys with invalid ECS type',
+  { service: 'myname', event: 'myevent' })
+log.info('bye')