fix: usage of 'base' option to pino constructor (elastic#63)

trentm · web-flow · commit d0331a7115c5 · 2021-03-17T14:18:51.000-07:00
The 'base' option to pino allows one to change (or null out) the
default "bindings". ecs-format-pino wasn't handling (a) a changed
base, nor (b) `base: null` which results in `formatters.bindings()`
not being called by pino at all -- which broke addition of
"ecs.version", "service.name", and "event.dataset".
diff --git a/loggers/pino/CHANGELOG.md b/loggers/pino/CHANGELOG.md
@@ -2,6 +2,22 @@
 
 ## Unreleased
 
+- Fix handling when the [`base`](https://getpino.io/#/docs/api?id=base-object)
+  option is used to the pino constructor.
+
+  Before this change, using, for example:
+        const log = pino({base: {foo: "bar"}, ...ecsFormat()})
+  would result in two issues:
+  1. The log records would not include the "foo" field.
+  2. The log records would include `"process": {}, "host": {}` for the
+     expected process.pid and os.hostname.
+
+  Further, if the following is used:
+        const log = pino({base: null, ...ecsFormat()})
+  pino does not call `formatters.bindings()` at all, resulting in log
+  records that were missing "ecs.version" (making them invalid ecs-logging
+  records) and part of the APM integration.
+
 - 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))
diff --git a/loggers/pino/index.js b/loggers/pino/index.js
@@ -67,130 +67,173 @@ function createEcsPinoOptions (opts) {
   }
 
   let apm = null
+  let apmServiceName = null
   if (apmIntegration && elasticApm && elasticApm.isStarted && elasticApm.isStarted()) {
     apm = elasticApm
+    // Elastic APM v3.11.0 added getServiceName(). Fallback to private `apm._conf`.
+    // istanbul ignore next
+    apmServiceName = apm.getServiceName
+      ? apm.getServiceName()
+      : apm._conf.serviceName
   }
 
+  let isServiceNameInBindings = false
+  let isEventDatasetInBindings = false
+
   const ecsPinoOptions = {
+    messageKey: 'message',
+    timestamp: () => `,"@timestamp":"${new Date().toISOString()}"`,
     formatters: {
       level (label, number) {
         return { 'log.level': label }
       },
 
-      // Add the following ECS fields:
-      // - https://www.elastic.co/guide/en/ecs/current/ecs-process.html#field-process-pid
-      // - https://www.elastic.co/guide/en/ecs/current/ecs-host.html#field-host-hostname
-      // - https://www.elastic.co/guide/en/ecs/current/ecs-log.html#field-log-logger
-      //
-      // This is called once at logger creation, and for each child logger creation.
       bindings (bindings) {
         const {
-          // We assume the default `pid` and `hostname` bindings
-          // (https://getpino.io/#/docs/api?id=bindings) will be always be
-          // defined because currently one cannot use this package *and*
-          // pass a custom `formatters` to a pino logger.
+          // `pid` and `hostname` are default bindings, unless overriden by
+          // a `base: {...}` passed to logger creation.
           pid,
           hostname,
           // name is defined if `log = pino({name: 'my name', ...})`
-          name
+          name,
+          // Warning: silently drop any "ecs" value from `base`. See
+          // "ecs.version" comment below.
+          ecs,
+          ...ecsBindings
         } = bindings
 
-        const ecsBindings = {
-          ecs: {
-            version
-          },
-          process: {
-            pid: pid
-          },
-          host: {
-            hostname: hostname
-          }
+        if (pid !== undefined) {
+          // https://www.elastic.co/guide/en/ecs/current/ecs-process.html#field-process-pid
+          ecsBindings.process = { pid: pid }
+        }
+        if (hostname !== undefined) {
+          // https://www.elastic.co/guide/en/ecs/current/ecs-host.html#field-host-hostname
+          ecsBindings.host = { hostname: hostname }
         }
         if (name !== undefined) {
+          // https://www.elastic.co/guide/en/ecs/current/ecs-log.html#field-log-logger
           ecsBindings.log = { logger: name }
         }
 
+        // Note if service.name & event.dataset are set, to not do so again below.
+        if (bindings.service && bindings.service.name) {
+          isServiceNameInBindings = true
+        }
+        if (bindings.event && bindings.event.dataset) {
+          isEventDatasetInBindings = true
+        }
+
+        return ecsBindings
+      },
+
+      log (obj) {
+        const {
+          req,
+          res,
+          err,
+          ...ecsObj
+        } = obj
+
+        // https://www.elastic.co/guide/en/ecs/current/ecs-ecs.html
+        // For "ecs.version" we take a heavier-handed approach, because it is
+        // a require ecs-logging field: overwrite any possible "ecs" value from
+        // the log statement. This means we don't need to spend the time
+        // guarding against "ecs" being null, Array, Buffer, Date, etc.
+        ecsObj.ecs = { version }
+
         if (apm) {
-          // https://github.com/elastic/apm-agent-nodejs/pull/1949 is adding
-          // getServiceName() in v3.11.0. Fallback to private `apm._conf`.
-          // istanbul ignore next
-          const serviceName = apm.getServiceName
-            ? apm.getServiceName()
-            : apm._conf.serviceName
           // A mis-configured APM Agent can be "started" but not have a
           // "serviceName".
-          if (serviceName) {
-            ecsBindings.service = { name: serviceName }
-            ecsBindings.event = { dataset: serviceName + '.log' }
+          if (apmServiceName) {
+            // Per https://github.com/elastic/ecs-logging/blob/master/spec/spec.json
+            // "service.name" and "event.dataset" should be automatically set
+            // if not already by the user.
+            if (!isServiceNameInBindings) {
+              const service = ecsObj.service
+              if (service === undefined) {
+                ecsObj.service = { name: apmServiceName }
+              } else if (!isVanillaObject(service)) {
+                // Warning: "service" type conflicts with ECS spec. Overwriting.
+                ecsObj.service = { name: apmServiceName }
+              } else if (typeof service.name !== 'string') {
+                ecsObj.service.name = apmServiceName
+              }
+            }
+            if (!isEventDatasetInBindings) {
+              const event = ecsObj.event
+              if (event === undefined) {
+                ecsObj.event = { dataset: apmServiceName + '.log' }
+              } else if (!isVanillaObject(event)) {
+                // Warning: "event" type conflicts with ECS spec. Overwriting.
+                ecsObj.event = { dataset: apmServiceName + '.log' }
+              } else if (typeof event.dataset !== 'string') {
+                ecsObj.event.dataset = apmServiceName + '.log'
+              }
+            }
           }
-        }
-
-        return ecsBindings
-      }
-    },
-    messageKey: 'message',
-    timestamp: () => `,"@timestamp":"${new Date().toISOString()}"`
-  }
 
-  // For performance, avoid adding the `formatters.log` pino option unless we
-  // know we'll do some processing in it.
-  if (convertErr || convertReqRes || apm) {
-    ecsPinoOptions.formatters.log = function (obj) {
-      const {
-        req,
-        res,
-        err,
-        ...ecsObj
-      } = obj
-
-      // istanbul ignore else
-      if (apm) {
-        // https://www.elastic.co/guide/en/ecs/current/ecs-tracing.html
-        const tx = apm.currentTransaction
-        if (tx) {
-          ecsObj.trace = ecsObj.trace || {}
-          ecsObj.trace.id = tx.traceId
-          ecsObj.transaction = ecsObj.transaction || {}
-          ecsObj.transaction.id = tx.id
-          const span = apm.currentSpan
-          // istanbul ignore else
-          if (span) {
-            ecsObj.span = ecsObj.span || {}
-            ecsObj.span.id = span.id
+          // https://www.elastic.co/guide/en/ecs/current/ecs-tracing.html
+          const tx = apm.currentTransaction
+          if (tx) {
+            ecsObj.trace = ecsObj.trace || {}
+            ecsObj.trace.id = tx.traceId
+            ecsObj.transaction = ecsObj.transaction || {}
+            ecsObj.transaction.id = tx.id
+            const span = apm.currentSpan
+            // istanbul ignore else
+            if (span) {
+              ecsObj.span = ecsObj.span || {}
+              ecsObj.span.id = span.id
+            }
           }
         }
-      }
 
-      // https://www.elastic.co/guide/en/ecs/current/ecs-http.html
-      if (err !== undefined) {
-        if (!convertErr) {
-          ecsObj.err = err
-        } else {
-          formatError(ecsObj, err)
+        // https://www.elastic.co/guide/en/ecs/current/ecs-http.html
+        if (err !== undefined) {
+          if (!convertErr) {
+            ecsObj.err = err
+          } else {
+            formatError(ecsObj, err)
+          }
         }
-      }
 
-      // https://www.elastic.co/guide/en/ecs/current/ecs-http.html
-      if (req !== undefined) {
-        if (!convertReqRes) {
-          ecsObj.req = req
-        } else {
-          formatHttpRequest(ecsObj, req)
+        // https://www.elastic.co/guide/en/ecs/current/ecs-http.html
+        if (req !== undefined) {
+          if (!convertReqRes) {
+            ecsObj.req = req
+          } else {
+            formatHttpRequest(ecsObj, req)
+          }
         }
-      }
-      if (res !== undefined) {
-        if (!convertReqRes) {
-          ecsObj.res = res
-        } else {
-          formatHttpResponse(ecsObj, res)
+        if (res !== undefined) {
+          if (!convertReqRes) {
+            ecsObj.res = res
+          } else {
+            formatHttpResponse(ecsObj, res)
+          }
         }
-      }
 
-      return ecsObj
+        return ecsObj
+      }
     }
   }
 
   return ecsPinoOptions
 }
 
+// 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 = createEcsPinoOptions
diff --git a/loggers/pino/test/apm.test.js b/loggers/pino/test/apm.test.js
@@ -331,8 +331,36 @@ 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-pino-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()
+  })
+})
+
+test('can override service.name, event.dataset in base arg to constructor', t => {
+  execFile(process.execPath, [
+    path.join(__dirname, 'use-apm-override-service-name.js'),
+    'test-apm', // apm "serviceName"
+    'mybindingname' // pino logger "service.name" value for `base` arg
+  ], {
+    timeout: 5000
+  }, function (err, stdout, stderr) {
+    t.ifErr(err)
+    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[3].service.name, 'mybindingname')
+    t.equal(recs[3].event.dataset, 'mybindingname')
     t.end()
   })
 })
@@ -351,8 +379,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()
   })
 })
diff --git a/loggers/pino/test/basic.test.js b/loggers/pino/test/basic.test.js
@@ -100,6 +100,37 @@ test('ecsPinoFormat cases', suite => {
         req: { id: 42 },
         res: { status: 'OK' }
       }
+    },
+    {
+      name: '`base: {}` should avoid "process" and "host" fields',
+      pinoOpts: { base: {}, ...ecsFormat() },
+      loggingFn: (log) => {
+        log.info('hi')
+      },
+      rec: {
+        'log.level': 'info',
+        ecs: { version: ecsVersion },
+        message: 'hi'
+      }
+    },
+    {
+      // The pino docs suggest:
+      // > `base`
+      // > Set to `null` to avoid adding `pid`, `hostname` and `name` properties to each log.
+      //
+      // This results in a given `formatters.bindings` **not getting called** at
+      // all. In earlier versions of this package, that `formatters.bindings`
+      // was used to add fields like "ecs.version".
+      name: '`base: null` should not break ecs-logging format',
+      pinoOpts: { base: null, ...ecsFormat() },
+      loggingFn: (log) => {
+        log.info('hi')
+      },
+      rec: {
+        'log.level': 'info',
+        ecs: { version: ecsVersion },
+        message: 'hi'
+      }
     }
   ]
 
diff --git a/loggers/pino/test/use-apm-override-service-name.js b/loggers/pino/test/use-apm-override-service-name.js
@@ -26,6 +26,7 @@
 // - flush APM and exit
 
 const serviceName = process.argv[2] || ''
+const pinoServiceName = process.argv[3] || ''
 /* eslint-disable-next-line no-unused-vars */
 const apm = require('elastic-apm-node').start({
   // Use default serverUrl (fire and forget)
@@ -38,10 +39,12 @@ const apm = require('elastic-apm-node').start({
 const ecsFormat = require('../') // @elastic/ecs-pino-format
 const pino = require('pino')
 
-const log = pino({ ...ecsFormat() })
-log.info({
-  foo: 'bar',
-  service: { name: 'myname' },
-  event: { dataset: 'mydataset' }
-}, 'hi')
-log.info({ foo: 'bar' }, 'bye')
+const pinoOpts = ecsFormat()
+if (pinoServiceName) {
+  pinoOpts.base = { service: { name: pinoServiceName }, event: { dataset: pinoServiceName } }
+}
+const log = pino(pinoOpts)
+log.info({ service: { name: 'myname' }, event: { dataset: 'mydataset' } }, 'override values')
+log.info({ service: { name: 42 }, event: { dataset: 42 } }, 'override values with nums')
+log.info({ service: 'myname', event: 'myevent' }, 'override top-level keys with invalid ECS type')
+log.info('bye')
