elastic-apm-node - npm Package Compare versions

Comparing version 3.21.1 to 3.22.0

index.d.ts

@@ -148,2 +148,6 @@ /// <reference types="node" />
     result: string | number;
+    ids: {
+      'trace.id': string;
+      'transaction.id': string;
+    }
 
@@ -195,2 +199,6 @@ setType (type?: string | null, subtype?: string | null, action?: string | null): void;
     outcome: Outcome;
+    ids: {
+      'trace.id': string;
+      'span.id': string;
+    }
 
@@ -329,2 +337,3 @@ setType (type?: string | null, subtype?: string | null, action?: string | null): void;
   export interface SpanOptions {
+    startTime?: number;
     childOf?: Transaction | Span | string;
@@ -331,0 +340,0 @@ }

lib/agent.js

@@ -13,2 +13,3 @@ 'use strict'
 var errors = require('./errors')
+const { InflightEventSet } = require('./InflightEventSet')
 var Instrumentation = require('./instrumentation')
@@ -40,2 +41,3 @@ var { elasticApmAwsLambda } = require('./lambda')
 
+  this._inflightEvents = new InflightEventSet()
   this._instrumentation = new Instrumentation(this)
@@ -389,3 +391,4 @@ this._metrics = new Metrics(this)
 //   - `opts.handled` - Boolean indicating if this exception was handled by
-//     application code.
+//     application code. Default true. Setting to `false` also results in the
+//     error being flushed to APM server as soon as it is processed.
 //   - `opts.captureAttributes` - Boolean. Default true. Set to false to *not*
@@ -395,3 +398,5 @@ //     include properties of `err` as attributes on the APM error event.
 //     this captured error set `<currentSpan>.outcome = failure`.
-// - `cb` is a callback `function (captureErr, apmErrorIdString)`
+// - `cb` is a callback `function (captureErr, apmErrorIdString)`. If provided,
+//   the error will be flushed to APM server as soon as it is processed, and
+//   `cb` will be called when that send is complete.
 Agent.prototype.captureError = function (err, opts, cb) {
@@ -405,6 +410,8 @@ if (typeof opts === 'function') {
 
+  const id = errors.generateErrorId()
+
   // Quick out if disableSend=true, no point in the processing time.
   if (this._conf.disableSend) {
     if (cb) {
-      process.nextTick(cb, null, errors.generateErrorId())
+      process.nextTick(cb, null, id)
     }
@@ -441,2 +448,6 @@ return
 
+  // Note this error as an "inflight" event. See Agent#flush().
+  const inflightEvents = this._inflightEvents
+  inflightEvents.add(id)
+
   // Move the remaining captureError processing to a later tick because:
@@ -486,2 +497,3 @@ // 1. This allows the calling code to continue processing. For example, for
       log: agent.logger,
+      id: id,
       exception: errIsError ? err : null,
@@ -501,3 +513,2 @@ logMessage: errIsError ? null : err,
       // _err is always null from createAPMError.
-      const id = apmError.id
 
@@ -507,2 +518,3 @@ apmError = agent._errorFilters.process(apmError)
         agent.logger.debug('error ignored by filter %o', { id })
+        inflightEvents.delete(id)
         if (cb) {
@@ -516,3 +528,8 @@ cb(null, id)
         agent.logger.info('Sending error to Elastic APM: %o', { id })
-        agent._transport.sendError(apmError, function () {
+        agent._transport.sendError(apmError)
+        inflightEvents.delete(id)
+        if (!handled || cb) {
+          // Immediately flush *unhandled* errors -- those from
+          // `uncaughtException` -- on the assumption that the process may
+          // soon crash. Also flush when a `cb` is provided.
           agent.flush(function (flushErr) {
@@ -523,6 +540,9 @@ if (cb) {
           })
-        })
-      } else if (cb) {
-        // TODO: Swallow this error just as it's done in agent.flush()?
-        cb(new Error('cannot capture error before agent is started'), id)
+        }
+      } else {
+        inflightEvents.delete(id)
+        if (cb) {
+          // TODO: Swallow this error just as it's done in agent.flush()?
+          cb(new Error('cannot capture error before agent is started'), id)
+        }
       }
@@ -561,12 +581,74 @@ })
 
+// Flush all ended APM events (transactions, spans, errors, metricsets) to APM
+// server as soon as possible. If the optional `cb` is given, it will be called
+// `cb(flushErr)` when this is complete.
+//
+// Encoding and passing event data to the agent's transport is *asynchronous*
+// for some event types: spans and errors. This flush will make a *best effort*
+// attempt to wait for those "inflight" events to finish processing before
+// flushing data to APM server. To avoid `.flush()` hanging, this times out
+// after one second.
+//
+// If flush is called while still waiting for inflight events in an earlier
+// flush call, then the more recent flush will only wait for events that were
+// newly inflight *since the last .flush()* call. I.e. the second flush does
+// *not* wait for the set of events the first flush is waiting on. This makes
+// the semantics of flush less than ideal (one cannot blindly call .flush() to
+// flush *everything* that has come before). However it handles the common use
+// case of flushing synchronously after ending a span or capturing an error:
+//    mySpan.end()
+//    apm.flush(function () { ... })
+// and it simplifies the implementation.
+//
+// # Dev Notes
+//
+// To support the implementation, agent code that creates an inflight event
+// must do the following:
+// - Take a reference to the current set of inflight events:
+//      const inflightEvents = agent._inflightEvents
+// - Add a unique ID for the event to the set:
+//      inflightEvents.add(id)
+// - Delete the ID from the set when sent to the transport (`.sendSpan(...)` et
+//   al) or when dropping the event (e.g. because of a filter):
+//      inflightEvents.delete(id)
 Agent.prototype.flush = function (cb) {
-  if (this._transport) {
-    // TODO: Only bind the callback if the transport can't use AsyncResource from async hooks
-    this._transport.flush(cb && this._instrumentation.bindFunction(cb))
-  } else {
+  if (!this._transport) {
     // Log an *err* to provide a stack for the user.
     const err = new Error('cannot flush agent before it is started')
     this.logger.warn({ err }, err.message)
-    if (cb) process.nextTick(cb)
+    if (cb) {
+      process.nextTick(cb)
+    }
+    return
   }
+
+  // This 1s timeout is a subjective balance between "long enough for spans
+  // and errors to reasonably encode" and "short enough to not block data
+  // being reported to APM server".
+  const INS_FLUSH_TIMEOUT_MS = 1000
+  const boundCb = cb && this._instrumentation.bindFunction(cb)
+
+  // If there are no inflight events then avoid creating additional objects.
+  if (this._inflightEvents.size === 0) {
+    this._transport.flush(boundCb)
+    return
+  }
+
+  // Otherwise, there are inflight events to wait for.  Setup a handler to
+  // callback when the current set of inflight events complete.
+  const flushingInflightEvents = this._inflightEvents
+  flushingInflightEvents.setDrainHandler((drainErr) => {
+    // The only possible drainErr is a timeout. This is best effort, so we only
+    // log this and move on.
+    this.logger.debug({
+      numRemainingInflightEvents: flushingInflightEvents.size,
+      err: drainErr
+    }, 'flush: drained inflight events')
+
+    // Then, flush the intake request to APM server.
+    this._transport.flush(boundCb)
+  }, INS_FLUSH_TIMEOUT_MS)
+
+  // Create a new empty set to collect subsequent inflight events.
+  this._inflightEvents = new InflightEventSet()
 }
@@ -573,0 +655,0 @@

lib/config.js

@@ -10,2 +10,3 @@ 'use strict'
 
+const REDACTED = require('./constants').REDACTED
 var logging = require('./logging')
@@ -201,7 +202,10 @@ var version = require('../package').version
 
-var TIME_OPTS = [
+var POSITIVE_TIME_OPTS = [
   'abortedErrorThreshold',
   'apiRequestTime',
   'metricsInterval',
-  'serverTimeout',
+  'serverTimeout'
+]
+// Time options allowing negative values.
+var TIME_OPTS = [
   'spanFramesMinDuration'
@@ -274,2 +278,8 @@ ]
 
+    if (isLambdaExecutionEnviornment() && this.metricsInterval !== 0) {
+      // Disable APM agent metrics in Lambda per current APM spec.
+      this.logger.trace('disable metricsInterval (%d -> 0) in lambda environment', this.metricsInterval)
+      this.metricsInterval = 0
+    }
+
     if (this.disableSend) {
@@ -364,2 +374,8 @@ this.transport = function createNoopTransport (conf, agent) {
     }
+    const REDACT_FIELDS = {
+      apiKey: true,
+      secretToken: true,
+      serverUrl: true,
+      serverHost: true
+    }
     const NICE_REGEXPS_FIELDS = {
@@ -376,2 +392,4 @@ ignoreUrlRegExp: true,
         // pass
+      } else if (REDACT_FIELDS[k]) {
+        loggable[k] = REDACTED
       } else if (NICE_REGEXPS_FIELDS[k] && Array.isArray(this[k])) {
@@ -408,2 +426,3 @@ // JSON.stringify() on a RegExp is "{}", which isn't very helpful.
   normalizeArrays(opts)
+  normalizePositiveTime(opts, logger)
   normalizeTime(opts)
@@ -521,5 +540,20 @@ normalizeBools(opts, logger)
 
+function normalizePositiveTime (opts, logger) {
+  for (const key of POSITIVE_TIME_OPTS) {
+    if (key in opts) {
+      let val = secondsFromTimeStr(String(opts[key]))
+      if (val === null) {
+        const def = DEFAULTS[key]
+        logger.warn('invalid time value "%s" for "%s" config option: using default "%s"',
+          opts[key], key, def)
+        val = secondsFromTimeStr(def)
+      }
+      opts[key] = val
+    }
+  }
+}
+
 function normalizeTime (opts) {
   for (const key of TIME_OPTS) {
-    if (key in opts) opts[key] = toSeconds(String(opts[key]))
+    if (key in opts) opts[key] = secondsFromTimeStr(String(opts[key]), true)
   }
@@ -604,10 +638,15 @@ }
 
-function toSeconds (value) {
-  var matches = /^(-)?(\d+)(m|ms|s)?$/.exec(value)
-  if (!matches) return null
+function secondsFromTimeStr (value, allowNegative) {
+  let matches
+  if (allowNegative) {
+    matches = /^(-?\d+)(m|ms|s)?$/.exec(value)
+  } else {
+    matches = /^(\d+)(m|ms|s)?$/.exec(value)
+  }
+  if (!matches) {
+    return null
+  }
 
-  var negate = matches[1]
-  var amount = Number(matches[2])
-  if (negate) amount = -amount
-  var scale = matches[3]
+  var amount = Number(matches[1])
+  var scale = matches[2]
 
@@ -749,2 +788,5 @@ if (scale === 'm') {
 module.exports.CAPTURE_ERROR_LOG_STACK_TRACES_ALWAYS = CAPTURE_ERROR_LOG_STACK_TRACES_ALWAYS
+
+// The following are exported for tests.
 module.exports.DEFAULTS = DEFAULTS
+module.exports.secondsFromTimeStr = secondsFromTimeStr

lib/errors.js

@@ -112,2 +112,4 @@ 'use strict'
 //   which will be formated with `util.format()`.
+// - `args.id` - An ID for the error. It should be created with
+//   `errors.generateErrorId()`.
 // - `args.log` {Logger}
@@ -138,3 +140,3 @@ // - `args.shouldCaptureAttributes` {Boolean}
   const error = {
-    id: generateErrorId(),
+    id: args.id,
     timestamp: args.timestampUs
@@ -141,0 +143,0 @@ }

lib/instrumentation/async-hooks.js

@@ -95,10 +95,2 @@ 'use strict'
   function before (asyncId) {
-    const span = activeSpans.get(asyncId)
-    if (span && !span.ended) {
-      span.sync = false
-    }
-    const transaction = span ? span.transaction : activeTransactions.get(asyncId)
-    if (transaction && !transaction.ended) {
-      transaction.sync = false
-    }
     ins.bindingSpan = null
@@ -105,0 +97,0 @@ }

lib/instrumentation/generic-span.js

@@ -26,3 +26,2 @@ 'use strict'
   this.ended = false
-  this.sync = true
 
@@ -29,0 +28,0 @@ this.outcome = constants.OUTCOME_UNKNOWN

lib/instrumentation/index.js

@@ -253,2 +253,6 @@ 'use strict'
   } else if (this._started) {
+    // Note this error as an "inflight" event. See Agent#flush().
+    const inflightEvents = agent._inflightEvents
+    inflightEvents.add(span.id)
+
     agent.logger.debug('encoding span %o', { span: span.id, parent: span.parentId, trace: span.traceId, name: span.name, type: span.type })
@@ -258,14 +262,14 @@ span._encode(function (err, payload) {
         agent.logger.error('error encoding span %o', { span: span.id, parent: span.parentId, trace: span.traceId, name: span.name, type: span.type, error: err.message })
-        return
+      } else {
+        payload = agent._spanFilters.process(payload)
+        if (!payload) {
+          agent.logger.debug('span ignored by filter %o', { span: span.id, parent: span.parentId, trace: span.traceId, name: span.name, type: span.type })
+        } else {
+          agent.logger.debug('sending span %o', { span: span.id, parent: span.parentId, trace: span.traceId, name: span.name, type: span.type })
+          if (agent._transport) {
+            agent._transport.sendSpan(payload)
+          }
+        }
       }
-
-      payload = agent._spanFilters.process(payload)
-
-      if (!payload) {
-        agent.logger.debug('span ignored by filter %o', { span: span.id, parent: span.parentId, trace: span.traceId, name: span.name, type: span.type })
-        return
-      }
-
-      agent.logger.debug('sending span %o', { span: span.id, parent: span.parentId, trace: span.traceId, name: span.name, type: span.type })
-      if (agent._transport) agent._transport.sendSpan(payload)
+      inflightEvents.delete(span.id)
     })
@@ -358,7 +362,3 @@ } else {
 // The instrumentation programmer is still responsible for starting a span,
-// and ending a span.  Additionally, this function will set a span's sync
-// property to `false` -- it's up to the instrumentation programmer to ensure
-// that the callback they're binding is really async.  If bindFunction is
-// passed a callback that the wrapped function executes synchronously, it will
-// still mark the span's `async` property as `false`.
+// and ending a span.
 //
@@ -385,4 +385,2 @@ // @param {function} original
     ins.activeSpan = span
-    if (trans) trans.sync = false
-    if (span) span.sync = false
     var result = original.apply(this, arguments)
@@ -389,0 +387,0 @@ ins.currentTransaction = prevTrans

lib/instrumentation/modules/aws-sdk/dynamodb.js

@@ -103,9 +103,2 @@ 'use strict'
 
-    // Workaround a bug in the agent's handling of `span.sync`.
-    //
-    // The bug: Currently this span.sync is not set `false` because there is
-    // an HTTP span created (for this S3 request) in the same async op. That
-    // HTTP span becomes the "active span" for this async op, and *it* gets
-    // marked as sync=false in `before()` in async-hooks.js.
-    span.sync = false
     span.end()
@@ -112,0 +105,0 @@ })

lib/instrumentation/modules/aws-sdk/s3.js

@@ -112,10 +112,2 @@ 'use strict'
 
-      // Workaround a bug in the agent's handling of `span.sync`.
-      //
-      // The bug: Currently this span.sync is not set `false` because there is
-      // an HTTP span created (for this S3 request) in the same async op. That
-      // HTTP span becomes the "active span" for this async op, and *it* gets
-      // marked as sync=false in `before()` in async-hooks.js.
-      span.sync = false
-
       span.end()
@@ -122,0 +114,0 @@ })

lib/instrumentation/modules/aws-sdk/sns.js

@@ -134,5 +134,2 @@ const constants = require('../../../constants')
 
-    // we'll need to manually mark this span as async.  The actual async hop
-    // is captured by the agent's async hooks instrumentation
-    span.sync = false
     span.end()
@@ -139,0 +136,0 @@ })

lib/instrumentation/modules/aws-sdk/sqs.js

@@ -95,2 +95,5 @@ 'use strict'
     const collector = agent._metrics.createQueueMetricsCollector(queueName)
+    if (!collector) {
+      return
+    }
     queueMetrics.set(queueName, collector)
@@ -167,5 +170,2 @@ }
 
-    // we'll need to manually mark this span as async.  The actual async hop
-    // is captured by the agent's async hooks instrumentation
-    span.sync = false
     span.end()
@@ -172,0 +172,0 @@

lib/instrumentation/modules/mongodb.js

@@ -6,4 +6,5 @@ 'use strict'
 
-// Match expected `<hostname>:<port>`.
-const HOSTNAME_PORT_RE = /^([^:]+):(\d+)$/
+// Match expected `<hostname>:<port>`, e.g. "mongo:27017", "::1:27017",
+// "127.0.0.1:27017".
+const HOSTNAME_PORT_RE = /^(.+):(\d+)$/
 
@@ -10,0 +11,0 @@ module.exports = (mongodb, agent, { version, enabled }) => {

lib/instrumentation/span.js

 'use strict'
 
+const { executionAsyncId } = require('async_hooks')
 var util = require('util')
@@ -37,2 +38,4 @@
   this._capturedStackTrace = null
+  this.sync = true
+  this._startXid = executionAsyncId()
 
@@ -75,2 +78,5 @@ this.transaction = transaction
   this._timer.end(endTime)
+  if (executionAsyncId() !== this._startXid) {
+    this.sync = false
+  }
 
@@ -77,0 +83,0 @@ this._setOutcomeFromSpanEnd()

lib/instrumentation/transaction.js

@@ -132,3 +132,2 @@ 'use strict'
     context: undefined,
-    sync: this.sync,
     span_count: {
@@ -135,0 +134,0 @@ started: this._builtSpans

lib/lambda.js

 'use strict'
 
+const constants = require('./constants')
 const shimmer = require('./instrumentation/shimmer')
 
 function elasticApmAwsLambda (agent) {
+  const log = agent.logger
+
   function captureContext (trans, payload, context, result) {
@@ -35,5 +38,11 @@ trans.setCustomContext({
       return function wrappedFail (err) {
+        // Capture the error before trans.end() so it associates with the
+        // current trans.  `skipOutcome` to avoid setting outcome on a possible
+        // currentSpan, because this error applies to the transaction, not any
+        // sub-span.
+        agent.captureError(err, { skipOutcome: true })
+        trans.setOutcome(constants.OUTCOME_FAILURE)
         const bound = fail.bind(this, err)
-        const done = captureAndMakeCompleter(trans, payload, context, undefined, bound)
-        agent.captureError(err, done)
+        const finish = captureAndMakeCompleter(trans, payload, context, undefined, bound)
+        finish()
       }
@@ -47,3 +56,4 @@ })
 
-  function captureAndMakeCompleter (trans, payload, context, result, callback) {
+  function captureAndMakeCompleter (trans, payload, context, result, boundCallback) {
+    log.trace({ awsRequestId: context && context.awsRequestId }, 'lambda: fn end')
     captureContext(trans, payload, context, result)
@@ -53,4 +63,8 @@ trans.end()
       agent.flush((err) => {
-        if (err) agent.logger.error('Flush error: %s', err.message)
-        callback()
+        if (err) {
+          log.error({ err, awsRequestId: context && context.awsRequestId }, 'lambda: flush error')
+        } else {
+          log.trace({ awsRequestId: context && context.awsRequestId }, 'lambda: flushed')
+        }
+        boundCallback()
       })
@@ -62,9 +76,13 @@ }
     return function wrappedLambdaCallback (err, result) {
-      const bound = callback.bind(this, err, result)
-      const done = captureAndMakeCompleter(trans, payload, context, result, bound)
       if (err) {
-        agent.captureError(err, done)
-      } else {
-        done()
+        // Capture the error before trans.end() so it associates with the
+        // current trans.  `skipOutcome` to avoid setting outcome on a possible
+        // currentSpan, because this error applies to the transaction, not any
+        // sub-span.
+        agent.captureError(err, { skipOutcome: true })
+        trans.setOutcome(constants.OUTCOME_FAILURE)
       }
+      const bound = callback.bind(this, err, result)
+      const finish = captureAndMakeCompleter(trans, payload, context, result, bound)
+      finish()
     }
@@ -78,4 +96,9 @@ }
     }
+    if (!agent._conf.active) {
+      // Manual usage of `apm.lambda(...)` should be a no-op when not active.
+      return fn
+    }
 
     return function wrappedLambda (payload, context, callback) {
+      log.trace({ awsRequestId: context && context.awsRequestId }, 'lambda: fn start')
       let parentId
@@ -105,3 +128,7 @@ let tracestate
 
-      return fn.call(this, payload, context, callback)
+      try {
+        return fn.call(this, payload, context, callback)
+      } catch (handlerErr) {
+        callback(handlerErr)
+      }
     }
@@ -108,0 +135,0 @@ }

lib/metrics/index.js

@@ -27,10 +27,12 @@ 'use strict'
     const enabled = metricsInterval !== 0 && !this[agentSymbol]._conf.disableSend
-    this[registrySymbol] = new MetricsRegistry(this[agentSymbol], {
-      reporterOptions: {
-        defaultReportingIntervalInSeconds: metricsInterval,
-        enabled: enabled,
-        unrefTimers: !refTimers,
-        logger: new NoopLogger()
-      }
-    })
+    if (enabled) {
+      this[registrySymbol] = new MetricsRegistry(this[agentSymbol], {
+        reporterOptions: {
+          defaultReportingIntervalInSeconds: metricsInterval,
+          enabled: enabled,
+          unrefTimers: !refTimers,
+          logger: new NoopLogger()
+        }
+      })
+    }
   }
@@ -37,0 +39,0 @@

package.json

 {
   "name": "elastic-apm-node",
-  "version": "3.21.1",
+  "version": "3.22.0",
   "description": "The official Elastic APM agent for Node.js",
@@ -46,3 +46,3 @@ "main": "index.js",
   "engines": {
-    "node": "^8.6.0 || 10 || 12 || 14 || 15 || 16"
+    "node": "^8.6.0 || 10 || 12 || 14 || 15 || 16 || 17"
   },
@@ -91,3 +91,3 @@ "keywords": [
     "core-util-is": "^1.0.2",
-    "elastic-apm-http-client": "^10.0.0",
+    "elastic-apm-http-client": "^10.1.0",
     "end-of-stream": "^1.4.4",
@@ -167,2 +167,3 @@ "error-callsites": "^2.0.4",
     "mkdirp": "^0.5.1",
+    "module-details-from-path": "^1.0.3",
     "mongodb": "^4.1.0",
@@ -169,0 +170,0 @@ "mongodb-core": "^3.2.7",

New alerts

License Policy Violation

License

This package is not allowed per your license policy. Review the package's license to ensure compliance.

Found 1 instance in 1 package

Fixed alerts

License Policy Violation

License

This package is not allowed per your license policy. Review the package's license to ensure compliance.

Found 1 instance in 1 package

Improved metrics

Total package byte prevSize

425912

increased by2.11%

Number of package files

103

increased by0.98%

Lines of code

10278

increased by1.74%

Worsened metrics

Dev dependency count

75

increased by1.35%

Number of low supply chain risk alerts

20

increased by5.26%

Dependency changes

• Updatedelastic-apm-http-client@^10.1.0