feat: add 'apmIntegration: false' option to disable Elastic APM integration (#62)

Refs: #60

Author: trentm

docs/morgan.asciidoc

@@ -134,9 +134,10 @@ const app = require('express')()
 const morgan = require('morgan')
 const ecsFormat = require('@elastic/ecs-morgan-format')
 
-app.use(morgan(ecsFormat('tiny'))) <1>
+app.use(morgan(ecsFormat({ format: 'tiny' }))) <1>
 // ...
 ----
+<1> If "format" is the only option you are using, you may pass it as `ecsFormat('tiny')`.
 
 [float]
 [[morgan-log-level]]
@@ -194,3 +195,11 @@ For example, running https://github.com/elastic/ecs-logging-nodejs/blob/master/l
 ----
 
 These IDs match trace data reported by the APM agent.
+
+Integration with Elastic APM can be explicitly disabled via the
+`apmIntegration: false` option, for example:
+
+[source,js]
+----
+app.use(morgan(ecsFormat({ apmIntegration: false })))
+----

docs/pino.asciidoc

@@ -240,6 +240,14 @@ For example, running https://github.com/elastic/ecs-logging-nodejs/blob/master/l
 
 These IDs match trace data reported by the APM agent.
 
+Integration with Elastic APM can be explicitly disabled via the
+`apmIntegration: false` option, for example:
+
+[source,js]
+----
+const log = pino(ecsFormat({ apmIntegration: false }))
+----
+
 
 [float]
 [[pino-considerations]]

docs/winston.asciidoc

@@ -254,3 +254,14 @@ For example, running https://github.com/elastic/ecs-logging-nodejs/blob/master/l
 ----
 
 These IDs match trace data reported by the APM agent.
+
+Integration with Elastic APM can be explicitly disabled via the
+`apmIntegration: false` option, for example:
+
+[source,js]
+----
+const logger = winston.createLogger({
+  format: ecsFormat({ apmIntegration: false }),
+  // ...
+})
+----

loggers/morgan/CHANGELOG.md

@@ -2,6 +2,10 @@
 
 ## Unreleased
 
+- 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))
+
 - Fix "elasticApm.isStarted is not a function" crash on startup.
   ([#60](https://github.com/elastic/ecs-logging-nodejs/issues/60))
 

loggers/morgan/index.js

@@ -33,17 +33,55 @@ try {
   // Silently ignore.
 }
 
-function ecsFormat (format = morgan.combined) {
-  // `format` is a format *name* (e.g. 'combined'), format function (e.g.
-  // `morgan.combined`), or a format string (e.g. ':method :url :status')
-  // Resolve this to a format function a la morgan's own `getFormatFunction`.
+// Return a Morgan formatter function for ecs-logging output.
+//
+// @param {Object} opts - Optional.
+//    - {String || Function} opts.format - A format *name* (e.g. 'combined'),
+//      format function (e.g. `morgan.combined`), or a format string
+//      (e.g. ':method :url :status'). This is used to format the "message"
+//      field. Defaults to `morgan.combined`.
+//    - {Boolean} opts.apmIntegration - Whether to automatically integrate with
+//      Elastic APM (https://github.com/elastic/apm-agent-nodejs). If a started
+//      APM agent is detected, then log records will include the following
+//      fields:
+//        - "service.name" - the configured serviceName in the agent
+//        - "event.dataset" - set to "$serviceName.log" for correlation in Kibana
+//        - "trace.id", "transaction.id", and "span.id" - if there is a current
+//          active trace when the log call is made
+//      Default true.
+//
+// For backwards compatibility, the first argument can be a String or Function
+// to specify `opts.format`. For example, the following are equivalent:
+//    ecsFormat({format: 'combined'})
+//    ecsFormat('combined')
+// The former allows specifying other options.
+function ecsFormat (opts) {
+  let format = morgan.combined
+  let apmIntegration = true
+  if (opts && typeof opts === 'object') {
+    // Usage: ecsFormat({ /* opts */ })
+    if (hasOwnProperty.call(opts, 'format')) {
+      format = opts.format
+    }
+    if (hasOwnProperty.call(opts, 'apmIntegration')) {
+      apmIntegration = opts.apmIntegration
+    }
+  } else if (opts) {
+    // Usage: ecsFormat(format)
+    format = opts
+  }
+
+  // Resolve to a format function a la morgan's own `getFormatFunction`.
   let fmt = morgan[format] || format
   if (typeof fmt !== 'function') {
     fmt = morgan.compile(fmt)
   }
 
-  // If there is a *started* APM agent, then use it.
-  const apm = elasticApm && elasticApm.isStarted && elasticApm.isStarted() ? elasticApm : null
+  let apm = null
+  if (apmIntegration && elasticApm && elasticApm.isStarted && elasticApm.isStarted()) {
+    apm = elasticApm
+  }
+
   let serviceField
   let eventField
   if (apm) {

loggers/morgan/test/apm.test.js

@@ -179,3 +179,148 @@ test('tracing integration works', t => {
     })
   })
 })
+
+// This is the same as the previous test, but sets `apmIntegration=false`
+// and asserts tracing fields are *not* added to log records.
+test('apmIntegration=false disables tracing integration', t => {
+  let apmServer
+  let app
+  let appIsClosed = false
+  const traceObjs = []
+  const logObjs = []
+  let stderr = ''
+
+  // 1. Setup a mock APM server to accept trace data. Callback when listening.
+  //    Pass intake data to `collectTracesLogsAndCheck()`.
+  function step1StartMockApmServer (cb) {
+    apmServer = http.createServer(function apmServerReq (req, res) {
+      t.equal(req.method, 'POST')
+      t.equal(req.url, '/intake/v2/events')
+      let instream = req
+      if (req.headers['content-encoding'] === 'gzip') {
+        instream = req.pipe(zlib.createGunzip())
+      } else {
+        instream.setEncoding('utf8')
+      }
+      instream.pipe(split(JSON.parse)).on('data', function (traceObj) {
+        collectTracesLogsAndCheck(traceObj, null)
+      })
+      req.on('end', function () {
+        res.end('ok')
+      })
+    })
+    apmServer.listen(0, function () {
+      cb(null, 'http://localhost:' + apmServer.address().port)
+    })
+  }
+
+  // 2. Start a test app that uses APM and our mock APM Server.
+  //    Callback on first log line, which includes the app's HTTP address.
+  //    Pass parsed JSON log records to `collectTracesLogsAndCheck()`.
+  function step2StartApp (apmServerUrl, cb) {
+    app = spawn(
+      process.execPath,
+      [
+        path.join(__dirname, 'serve-one-http-req-with-apm.js'),
+        apmServerUrl,
+        'true' // disableApmIntegration argument
+      ]
+    )
+    let handledFirstLogLine = false
+    app.stdout.pipe(split(JSON.parse)).on('data', function (logObj) {
+      if (!handledFirstLogLine) {
+        handledFirstLogLine = true
+        t.equal(logObj.message, 'listening')
+        t.ok(logObj.address, 'first listening log line has "address"')
+        cb(null, logObj.address)
+      } else {
+        collectTracesLogsAndCheck(null, logObj)
+      }
+    })
+    app.stderr.on('data', function (chunk) {
+      stderr += chunk
+    })
+    app.on('close', function (code) {
+      t.equal(stderr, '', 'empty stderr from app')
+      t.equal(code, 0, 'app exited 0')
+      appIsClosed = true
+    })
+  }
+
+  // 3. Call the test app to generate a trace.
+  function step3CallApp (appUrl, cb) {
+    const req = http.request(appUrl + '/', function (res) {
+      res.on('data', function () {})
+      res.on('end', cb)
+    })
+    req.on('error', cb)
+    req.end()
+  }
+
+  // 4. Collect trace data from the APM Server, log data from the app, and when
+  // all the expected data is collected, then test it: assert matching tracing
+  // IDs.
+  function collectTracesLogsAndCheck (traceObj, logObj) {
+    if (traceObj) {
+      traceObjs.push(traceObj)
+    }
+    if (logObj) {
+      t.ok(validate(logObj), 'logObj is ECS valid')
+      t.equal(ecsLoggingValidate(logObj), null)
+      logObjs.push(logObj)
+    }
+    // Unlike the equivalent apm.test.js for other logging frameworks, we are
+    // not testing for a custom span and `$logRecord.span.id` because the way
+    // morgan logs (on the HTTP Response "finished" event), a custom span in
+    // the request handler is no longer active.
+    if (traceObjs.length >= 2 && logObjs.length >= 1) {
+      t.ok(traceObjs[0].metadata, 'traceObjs[0] is metadata')
+      t.ok(traceObjs[1].transaction, 'traceObjs[1] is transaction')
+      t.notOk(logObjs[0].trace, 'log record does *not* have "trace" object')
+      t.notOk(logObjs[0].transaction, 'log record does *not* have "transaction" object')
+      t.notOk(logObjs[0].span, 'log record does *not* have "span" object')
+      t.notOk(logObjs[0].service, 'log record does *not* have "service" object')
+      t.notOk(logObjs[0].event, 'log record does *not* have "event" object')
+      finish()
+    }
+  }
+
+  function finish () {
+    if (appIsClosed) {
+      apmServer.close(function () {
+        t.end()
+      })
+    } else {
+      app.on('close', function () {
+        apmServer.close(function () {
+          t.end()
+        })
+      })
+    }
+  }
+
+  step1StartMockApmServer(function onListening (apmServerErr, apmServerUrl) {
+    t.ifErr(apmServerErr)
+    if (apmServerErr) {
+      finish()
+      return
+    }
+    t.ok(apmServerUrl, 'apmServerUrl: ' + apmServerUrl)
+
+    step2StartApp(apmServerUrl, function onReady (appErr, appUrl) {
+      t.ifErr(appErr)
+      if (appErr) {
+        finish()
+        return
+      }
+      t.ok(appUrl, 'appUrl: ' + appUrl)
+
+      step3CallApp(appUrl, function (clientErr) {
+        t.ifErr(clientErr)
+
+        // The thread of control now is expected to be in
+        // `collectTracesLogsAndCheck()`.
+      })
+    })
+  })
+})

loggers/morgan/test/basic.test.js

@@ -159,6 +159,25 @@ test('"format" argument - format function', t => {
   })
 })
 
+test('"opts.format" argument', t => {
+  t.plan(2)
+
+  // Example:
+  //  POST /?foo=bar 200 - - 0.073 ms
+  const format = 'tiny' // https://github.com/expressjs/morgan#tiny
+  const msgRe = /^POST \/\?foo=bar 200 - - \d+\.\d+ ms$/
+  const stream = split().on('data', line => {
+    const rec = JSON.parse(line)
+    t.match(rec.message, msgRe, 'rec.message')
+  })
+  const logger = morgan(ecsFormat({ format: format }), { stream })
+
+  makeExpressServerAndRequest(logger, '/?foo=bar', { method: 'POST' }, 'hi', function (err) {
+    t.ifErr(err)
+    t.end()
+  })
+})
+
 test('"log.level" for successful response is "info"', t => {
   t.plan(2)
 

loggers/morgan/test/serve-one-http-req-with-apm.js

@@ -29,6 +29,7 @@
 // - exit
 
 const serverUrl = process.argv[2]
+const disableApmIntegration = process.argv[3] === 'true'
 /* eslint-disable-next-line no-unused-vars */
 const apm = require('elastic-apm-node').start({
   serverUrl,
@@ -43,7 +44,11 @@ const http = require('http')
 const morgan = require('morgan')
 const ecsFormat = require('../') // @elastic/ecs-morgan-format
 
-app.use(morgan(ecsFormat()))
+const ecsOpts = {}
+if (disableApmIntegration) {
+  ecsOpts.apmIntegration = false
+}
+app.use(morgan(ecsFormat(ecsOpts)))
 
 app.get('/', function (req, res) {
   res.once('finish', function apmFlushAndExit () {

loggers/pino/CHANGELOG.md

@@ -2,6 +2,10 @@
 
 ## Unreleased
 
+- 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))
+
 - Fix "elasticApm.isStarted is not a function" crash on startup.
   ([#60](https://github.com/elastic/ecs-logging-nodejs/issues/60))
 

loggers/pino/index.js

@@ -32,27 +32,44 @@ try {
   // Silently ignore.
 }
 
+// Create options for `pino(...)` that configure it for ecs-logging output.
+//
+// @param {Object} opts - Optional.
+//    - {Boolean} opts.convertErr - Whether to convert a logged `err` field
+//      to ECS error fields. Default true, to match Pino's default of having
+//      an `err` serializer.
+//    - {Boolean} opts.convertReqRes - Whether to convert logged `req` and `res`
+//      HTTP request and response fields to ECS HTTP, User agent, and URL
+//      fields. Default false.
+//    - {Boolean} opts.apmIntegration - Whether to automatically integrate with
+//      Elastic APM (https://github.com/elastic/apm-agent-nodejs). If a started
+//      APM agent is detected, then log records will include the following
+//      fields:
+//        - "service.name" - the configured serviceName in the agent
+//        - "event.dataset" - set to "$serviceName.log" for correlation in Kibana
+//        - "trace.id", "transaction.id", and "span.id" - if there is a current
+//          active trace when the log call is made
+//      Default true.
 function createEcsPinoOptions (opts) {
-  // Boolean options for whether to specially handle some logged field names:
-  //  - `err` to ECS Error fields
-  //  - `req` and `res` to ECS HTTP, User agent, etc. fields
-  // These intentionally match the common serializers
-  // (https://getpino.io/#/docs/api?id=serializers-object). If enabled,
-  // this ECS conversion will take precedence over a serializer for the same
-  // field name.
   let convertErr = true
   let convertReqRes = false
+  let apmIntegration = true
   if (opts) {
     if (hasOwnProperty.call(opts, 'convertErr')) {
       convertErr = opts.convertErr
     }
     if (hasOwnProperty.call(opts, 'convertReqRes')) {
       convertReqRes = opts.convertReqRes
     }
+    if (hasOwnProperty.call(opts, 'apmIntegration')) {
+      apmIntegration = opts.apmIntegration
+    }
   }
 
-  // If there is a *started* APM agent, then use it.
-  const apm = elasticApm && elasticApm.isStarted && elasticApm.isStarted() ? elasticApm : null
+  let apm = null
+  if (apmIntegration && elasticApm && elasticApm.isStarted && elasticApm.isStarted()) {
+    apm = elasticApm
+  }
 
   const ecsPinoOptions = {
     formatters: {