new "run context" management to fix numerous span hierarchy issues

.tav.yml

@@ -3,7 +3,9 @@ generic-pool:
   commands: node test/instrumentation/modules/generic-pool.test.js
 mimic-response:
   versions: ^1.0.0
-  commands: node test/instrumentation/modules/mimic-response.test.js
+  commands:
+    - node test/instrumentation/modules/mimic-response.test.js
+    - node test/instrumentation/modules/http/github-179.test.js
 got-very-old:
   name: got
   versions: '>=4.0.0 <9.0.0'

CHANGELOG.asciidoc

@@ -28,6 +28,33 @@ Notes:
 [[release-notes-3.x]]
 === Node.js Agent version 3.x
 
+==== Unreleased
+
+[float]
+===== Breaking changes
+
+[float]
+===== Features
+
+[float]
+===== Bug fixes
+
+* A significant change was made to internal run context tracking (a.k.a. async
+  context tracking). There are no configuration changes or API changes for
+  custom instrumentation. ({pull}2181[#2181])
++
+One behavior change is that multiple spans created synchronously (in the same
+async task) will form parent/child relationships; before this change they would
+all be siblings. This fixes HTTP child spans of Elasticsearch and aws-sdk
+automatic spans to properly be children. ({issues}1889[#1889])
++
+Another behavior change is that a span B started after having ended span A in
+the same async task will *no longer* be a child of span A. ({pull}1964[#1964])
++
+This fixes an issue with context binding of EventEmitters, where
+`removeListener` would fail to actually remove if the same handler function was
+added to multiple events.
+
 
 [[release-notes-3.23.0]]
 ==== 3.23.0 2021/10/25

DEVELOPMENT.md

@@ -38,24 +38,24 @@ environment variables:
 
 ## debug logging of `async_hooks` usage
 
-The following patch to the agent's async-hooks.js can be helpful to learn
-how its async hook tracks relationships between async operations:
+When using the `AsyncHooksRunContextManager` the following debug printf in
+the `init` async hook can be helpful to learn how its async hook tracks
+relationships between async operations:
 
 ```diff
-diff --git a/lib/instrumentation/async-hooks.js b/lib/instrumentation/async-hooks.js
-index 1dd168f..f35877d 100644
---- a/lib/instrumentation/async-hooks.js
-+++ b/lib/instrumentation/async-hooks.js
-@@ -71,6 +71,9 @@ module.exports = function (ins) {
-     // type, which will init for each scheduled timer.
-     if (type === 'TIMERWRAP') return
-
-+    const indent = ' '.repeat(triggerAsyncId % 80)
-+    process._rawDebug(`${indent}${type}(${asyncId}): triggerAsyncId=${triggerAsyncId} executionAsyncId=${asyncHooks.executionAsyncId()}`);
+diff --git a/lib/instrumentation/run-context/AsyncHooksRunContextManager.js b/lib/instrumentation/run-context/AsyncHooksRunContextManager.js
+index 94376188..571539aa 100644
+--- a/lib/instrumentation/run-context/AsyncHooksRunContextManager.js
++++ b/lib/instrumentation/run-context/AsyncHooksRunContextManager.js
+@@ -60,6 +60,8 @@ class AsyncHooksRunContextManager extends BasicRunContextManager {
+       return
+     }
+
++    process._rawDebug(`${' '.repeat(triggerAsyncId % 80)}${type}(${asyncId}): triggerAsyncId=${triggerAsyncId} executionAsyncId=${asyncHooks.executionAsyncId()}`);
 +
-     const transaction = ins.currentTransaction
-     if (!transaction) return
-
+     const context = this._stack[this._stack.length - 1]
+     if (context !== undefined) {
+       this._runContextFromAsyncId.set(asyncId, context)
 ```
 
 

NOTICE.md

@@ -1,3 +1,6 @@
+apm-agent-nodejs
+Copyright 2011-2021 Elasticsearch B.V.
+
 # Notice
 
 This project contains several dependencies which have been vendored in
@@ -95,3 +98,14 @@ AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER
 LIABILITY, WHETHER IN AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM,
 OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN
 THE SOFTWARE.
+
+## opentelemetry-js
+
+- **path:** [lib/instrumentation/run-context/](lib/instrumentation/run-context/)
+- **author:** OpenTelemetry Authors
+- **project url:** https://github.com/open-telemetry/opentelemetry-js
+- **original file:** https://github.com/open-telemetry/opentelemetry-js/tree/main/packages/opentelemetry-context-async-hooks/src
+- **license:** Apache License 2.0, https://github.com/open-telemetry/opentelemetry-js/blob/main/packages/opentelemetry-context-async-hooks/LICENSE
+
+Parts of "lib/instrumentation/run-context" have been adapted from or influenced
+by TypeScript code in `@opentelemetry/context-async-hooks`.

lib/agent.js

@@ -50,26 +50,26 @@ function Agent () {
 
 Object.defineProperty(Agent.prototype, 'currentTransaction', {
   get () {
-    return this._instrumentation.currentTransaction
+    return this._instrumentation.currTransaction()
   }
 })
 
 Object.defineProperty(Agent.prototype, 'currentSpan', {
   get () {
-    return this._instrumentation.currentSpan
+    return this._instrumentation.currSpan()
   }
 })
 
 Object.defineProperty(Agent.prototype, 'currentTraceparent', {
   get () {
-    const current = this.currentSpan || this.currentTransaction
+    const current = this._instrumentation.currSpan() || this._instrumentation.currTransaction()
     return current ? current.traceparent : null
   }
 })
 
 Object.defineProperty(Agent.prototype, 'currentTraceIds', {
   get () {
-    return this._instrumentation.ids
+    return this._instrumentation.ids()
   }
 })
 
@@ -86,6 +86,9 @@ Object.defineProperty(Agent.prototype, 'currentTraceIds', {
 // - There may be in-flight tasks (in ins.addEndedSpan() and
 //   agent.captureError() for example) that will complete after this destroy
 //   completes. They should have no impact other than CPU/resource use.
+// - The patching of core node functions when `asyncHooks=false` is *not*
+//   undone. This means run context tracking for `asyncHooks=false` is broken
+//   with in-process multiple-Agent use.
 Agent.prototype.destroy = function () {
   if (this._transport && this._transport.destroy) {
     this._transport.destroy()
@@ -275,27 +278,27 @@ Agent.prototype.setFramework = function ({ name, version, overwrite = true }) {
 }
 
 Agent.prototype.setUserContext = function (context) {
-  var trans = this.currentTransaction
+  var trans = this._instrumentation.currTransaction()
   if (!trans) return false
   trans.setUserContext(context)
   return true
 }
 
 Agent.prototype.setCustomContext = function (context) {
-  var trans = this.currentTransaction
+  var trans = this._instrumentation.currTransaction()
   if (!trans) return false
   trans.setCustomContext(context)
   return true
 }
 
 Agent.prototype.setLabel = function (key, value, stringify) {
-  var trans = this.currentTransaction
+  var trans = this._instrumentation.currTransaction()
   if (!trans) return false
   return trans.setLabel(key, value, stringify)
 }
 
 Agent.prototype.addLabels = function (labels, stringify) {
-  var trans = this.currentTransaction
+  var trans = this._instrumentation.currTransaction()
   if (!trans) return false
   return trans.addLabels(labels, stringify)
 }
@@ -419,11 +422,11 @@ Agent.prototype.captureError = function (err, opts, cb) {
   const handled = opts.handled !== false // default true
   const shouldCaptureAttributes = opts.captureAttributes !== false // default true
   const skipOutcome = Boolean(opts.skipOutcome)
-  const span = this.currentSpan
+  const span = this._instrumentation.currSpan()
   const timestampUs = (opts.timestamp
     ? Math.floor(opts.timestamp * 1000)
     : Date.now() * 1000)
-  const trans = this.currentTransaction
+  const trans = this._instrumentation.currTransaction()
   const traceContext = (span || trans || {})._context
 
   // As an added feature, for *some* cases, we capture a stacktrace at the point

lib/instrumentation/http-shared.js

@@ -18,8 +18,8 @@ exports.instrumentRequest = function (agent, moduleName) {
 
         if (isRequestBlacklisted(agent, req)) {
           agent.logger.debug('ignoring blacklisted request to %s', req.url)
-          // don't leak previous transaction
-          agent._instrumentation.currentTransaction = null
+          // Don't leak previous transaction.
+          agent._instrumentation.supersedeWithEmptyRunContext()
         } else {
           var traceparent = req.headers.traceparent || req.headers['elastic-apm-traceparent']
           var tracestate = req.headers.tracestate
@@ -152,7 +152,7 @@ exports.traceOutgoingRequest = function (agent, moduleName, method) {
       // however a traceparent header must still be propagated
       // to indicate requested services should not be sampled.
       // Use the transaction context as the parent, in this case.
-      var parent = span || agent.currentTransaction
+      var parent = span || ins.currTransaction()
       if (parent && parent._context) {
         const headerValue = parent._context.toTraceParentString()
         const traceStateValue = parent._context.toTraceStateString()
@@ -181,7 +181,7 @@ exports.traceOutgoingRequest = function (agent, moduleName, method) {
       // Or if it's somehow preferable to listen for when a `response` listener
       // is added instead of when `response` is emitted.
       const emit = req.emit
-      req.emit = function (type, res) {
+      req.emit = function wrappedEmit (type, res) {
         if (type === 'response') onresponse(res)
         if (type === 'abort') onAbort(type)
         return emit.apply(req, arguments)
@@ -228,17 +228,11 @@ exports.traceOutgoingRequest = function (agent, moduleName, method) {
       }
 
       function onresponse (res) {
-        // Work around async_hooks bug in Node.js 12.0 - 12.2 (https://github.com/nodejs/node/pull/27477)
-        ins._recoverTransaction(span.transaction)
-
         agent.logger.debug('intercepted http.ClientRequest response event %o', { id: id })
         ins.bindEmitter(res)
-
         statusCode = res.statusCode
-
         res.prependListener('end', function () {
           agent.logger.debug('intercepted http.IncomingMessage end event %o', { id: id })
-
           onEnd()
         })
       }