fix: more reliable span.sync determination, drop unused transaction.sync (#2326)

trentm · web-flow · commit c9e4ca2459ed · 2021-09-20T11:36:44.000-07:00
Currently `span.sync` is tracked via: - the "before" async hook setting it false on the "active" span, and - Instrumentation#bindFunction's wrapper setting it false, on the fair assumption that all usages of bindFunction are for async callbacks. The former has issues when there are multiple active spans within a single async task -- as is the case with Elasticsearch instrumentation (issue #1996) and the aws-sdk instrumentations (which have manual workarounds). This changes to set sync=false if the executionAsyncId() at end-time is different than at start-time. This decouples from async context management, so works for whatever value of the `asyncHooks` config var. This also drops the `transaction.sync` field which was never used. Fixes: #1996 Fixes: #2292
diff --git a/CHANGELOG.asciidoc b/CHANGELOG.asciidoc
@@ -40,6 +40,12 @@ Notes:
 [float]
 ===== Bug fixes
 
+* Improve `span.sync` determination (fixes {issue}1996[#1996]) and stop
+  reporting `transaction.sync` which was never used ({issue}2292[#2292]).
+  A minor semantic change is that `span.sync` is not set to a final value
+  until `span.end()` is called. Before `span.end()` the value will always
+  by `true`.
+
 * Guard against a negative value of `metricsInterval`, which can lead to
   high CPU usage as metrics are collected as fast as possible. Also ensure
   no metrics collection can happen if `metricsInterval="0s"` as intended.
diff --git a/lib/instrumentation/async-hooks.js b/lib/instrumentation/async-hooks.js
@@ -92,14 +92,6 @@ module.exports = function (ins) {
   }
 
   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
   }
 
diff --git a/lib/instrumentation/generic-span.js b/lib/instrumentation/generic-span.js
@@ -23,7 +23,6 @@ function GenericSpan (agent, ...args) {
 
   this.timestamp = this._timer.start
   this.ended = false
-  this.sync = true
 
   this.outcome = constants.OUTCOME_UNKNOWN
 
diff --git a/lib/instrumentation/index.js b/lib/instrumentation/index.js
@@ -353,11 +353,7 @@ var wrapped = Symbol('elastic-apm-wrapped-function')
 // the callback function gets instrument on "the right" transaction and span.
 //
 // 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.
 //
 // @param {function} original
 Instrumentation.prototype.bindFunction = function (original) {
@@ -379,8 +375,6 @@ Instrumentation.prototype.bindFunction = function (original) {
     ins.currentTransaction = trans
     ins.bindingSpan = null
     ins.activeSpan = span
-    if (trans) trans.sync = false
-    if (span) span.sync = false
     var result = original.apply(this, arguments)
     ins.currentTransaction = prevTrans
     return result
diff --git a/lib/instrumentation/modules/aws-sdk/dynamodb.js b/lib/instrumentation/modules/aws-sdk/dynamodb.js
@@ -100,13 +100,6 @@ function instrumentationDynamoDb (orig, origArguments, request, AWS, agent, { ve
       span._setOutcomeFromErrorCapture(constants.OUTCOME_FAILURE)
     }
 
-    // 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()
   })
 
diff --git a/lib/instrumentation/modules/aws-sdk/s3.js b/lib/instrumentation/modules/aws-sdk/s3.js
@@ -109,14 +109,6 @@ function instrumentationS3 (orig, origArguments, request, AWS, agent, { version,
         }
       }
 
-      // 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()
     })
   }
diff --git a/lib/instrumentation/modules/aws-sdk/sns.js b/lib/instrumentation/modules/aws-sdk/sns.js
@@ -131,9 +131,6 @@ function instrumentationSns (orig, origArguments, request, AWS, agent, { version
       span._setOutcomeFromErrorCapture(constants.OUTCOME_FAILURE)
     }
 
-    // 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()
   })
 
diff --git a/lib/instrumentation/modules/aws-sdk/sqs.js b/lib/instrumentation/modules/aws-sdk/sqs.js
@@ -166,9 +166,6 @@ function instrumentationSqs (orig, origArguments, request, AWS, agent, { version
       span._setOutcomeFromErrorCapture(constants.OUTCOME_FAILURE)
     }
 
-    // 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()
 
     if (request.operation === 'receiveMessage' && response && response.data) {
diff --git a/lib/instrumentation/span.js b/lib/instrumentation/span.js
@@ -1,5 +1,6 @@
 'use strict'
 
+const { executionAsyncId } = require('async_hooks')
 var util = require('util')
 
 var Value = require('async-value-promise')
@@ -34,6 +35,8 @@ function Span (transaction, name, ...args) {
   this._message = null
   this._stackObj = null
   this._capturedStackTrace = null
+  this.sync = true
+  this._startXid = executionAsyncId()
 
   this.transaction = transaction
   this.name = name || 'unnamed'
@@ -71,6 +74,9 @@ Span.prototype.end = function (endTime) {
   }
 
   this._timer.end(endTime)
+  if (executionAsyncId() !== this._startXid) {
+    this.sync = false
+  }
 
   this._setOutcomeFromSpanEnd()
 
diff --git a/lib/instrumentation/transaction.js b/lib/instrumentation/transaction.js
@@ -129,7 +129,6 @@ Transaction.prototype.toJSON = function () {
     result: String(this.result),
     sampled: this.sampled,
     context: undefined,
-    sync: this.sync,
     span_count: {
       started: this._builtSpans
     },
diff --git a/test/instrumentation/async-hooks.test.js b/test/instrumentation/async-hooks.test.js
@@ -121,43 +121,6 @@ test('post-defined, post-resolved promise', function (t) {
   })
 })
 
-test('sync/async tracking: span ended in same function is sync', function (t) {
-  var trans = agent.startTransaction()
-  t.strictEqual(trans.sync, true)
-
-  var span1 = agent.startSpan()
-  t.strictEqual(span1.sync, true)
-
-  // This span will be *ended* synchronously. It should stay `span.sync=true`.
-  var span2 = agent.startSpan()
-  t.strictEqual(span2.sync, true, 'span2.sync=true immediately after creation')
-  span2.end()
-  t.strictEqual(span2.sync, true, 'span2.sync=true immediately after end')
-
-  setImmediate(() => {
-    t.strictEqual(trans.sync, false)
-    t.strictEqual(span2.sync, true,
-      'span2.sync=true later after having ended sync')
-    t.end()
-  })
-})
-
-test('sync/async tracking: span ended across async boundary is not sync', function (t) {
-  var trans = agent.startTransaction()
-  t.strictEqual(trans.sync, true)
-
-  var span1 = agent.startSpan()
-  t.strictEqual(span1.sync, true)
-
-  setImmediate(() => {
-    span1.end()
-    t.strictEqual(trans.sync, false)
-    t.strictEqual(span1.sync, false,
-      'span1.sync=true after having ended sync')
-    t.end()
-  })
-})
-
 function twice (fn) {
   setImmediate(fn)
   setImmediate(fn)
diff --git a/test/instrumentation/modules/@elastic/elasticsearch.test.js b/test/instrumentation/modules/@elastic/elasticsearch.test.js
@@ -586,12 +586,14 @@ function checkDataAndEnd (t, method, path, dbStatement) {
     t.strictEqual(esSpan.type, 'db')
     t.strictEqual(esSpan.subtype, 'elasticsearch')
     t.strictEqual(esSpan.action, 'request')
+    t.strictEqual(esSpan.sync, false, 'span.sync=false')
 
     const httpSpan = findObjInArray(data.spans, 'subtype', 'http')
     t.ok(httpSpan, 'have an http span')
     t.strictEqual(httpSpan.type, 'external')
     t.strictEqual(httpSpan.subtype, 'http')
     t.strictEqual(httpSpan.action, method)
+    t.strictEqual(httpSpan.sync, false, 'span.sync=false')
 
     t.equal(httpSpan.name, method + ' ' + host, 'http span should have expected name')
     t.equal(esSpan.name, 'Elasticsearch: ' + method + ' ' + path, 'elasticsearch span should have expected name')
diff --git a/test/instrumentation/modules/aws-sdk/sns.test.js b/test/instrumentation/modules/aws-sdk/sns.test.js
@@ -243,6 +243,7 @@ tape.test('AWS SNS: End to End Test', function (test) {
         t.equals(span.type, 'messaging', 'span type correctly set')
         t.equals(span.subtype, 'sns', 'span subtype set correctly')
         t.equals(span.action, 'publish', 'span action set correctly')
+        t.equals(span.sync, false, 'span.sync is false')
         t.equals(span.context.message.queue.name, 'topic-name')
         t.equals(span.context.destination.service.resource, 'sns/topic-name')
         t.equals(span.context.destination.service.type, 'messaging')
diff --git a/test/instrumentation/span.test.js b/test/instrumentation/span.test.js
@@ -161,12 +161,24 @@ test('#addLabels', function (t) {
   t.end()
 })
 
-test('sync/async tracking', function (t) {
-  var trans = new Transaction(agent)
-  var span = new Span(trans)
-  t.strictEqual(span.sync, true)
+test('span.sync', function (t) {
+  var trans = agent.startTransaction()
+
+  var span1 = agent.startSpan('span1')
+  t.strictEqual(span1.sync, true)
+
+  // This span will be *ended* synchronously. It should stay `span.sync=true`.
+  var span2 = agent.startSpan('span2')
+  t.strictEqual(span2.sync, true, 'span2.sync=true immediately after creation')
+  span2.end()
+  t.strictEqual(span2.sync, true, 'span2.sync=true immediately after end')
+
   setImmediate(() => {
-    t.strictEqual(span.sync, false)
+    span1.end()
+    t.strictEqual(span1.sync, false, 'span1.sync=false immediately after end')
+    trans.end()
+    t.strictEqual(span2.sync, true,
+      'span2.sync=true later after having ended sync')
     t.end()
   })
 })
diff --git a/test/instrumentation/transaction.test.js b/test/instrumentation/transaction.test.js

Original file line number	Diff line number	Diff line change
`@@ -92,14 +92,6 @@ module.exports = function (ins) {`
`92`	`92`	`}`
`93`	`93`
`94`	`94`	`function before (asyncId) {`
`95`		`- const span = activeSpans.get(asyncId)`
`96`		`- if (span && !span.ended) {`
`97`		`- span.sync = false`
`98`		`- }`
`99`		`- const transaction = span ? span.transaction : activeTransactions.get(asyncId)`
`100`		`- if (transaction && !transaction.ended) {`
`101`		`- transaction.sync = false`
`102`		`- }`
`103`	`95`	`ins.bindingSpan = null`
`104`	`96`	`}`
`105`	`97`
Original file line number	Diff line number	Diff line change
`@@ -109,14 +109,6 @@ function instrumentationS3 (orig, origArguments, request, AWS, agent, { version,`
`109`	`109`	`}`
`110`	`110`	`}`
`111`	`111`
`112`		- // Workaround a bug in the agent's handling of `span.sync`.
`113`		`- //`
`114`		- // The bug: Currently this span.sync is not set `false` because there is
`115`		`- // an HTTP span created (for this S3 request) in the same async op. That`
`116`		`- // HTTP span becomes the "active span" for this async op, and it gets`
`117`		- // marked as sync=false in `before()` in async-hooks.js.
`118`		`- span.sync = false`
`119`		`-`
`120`	`112`	`span.end()`
`121`	`113`	`})`
`122`	`114`	`}`
Original file line number	Diff line number	Diff line change
`@@ -131,9 +131,6 @@ function instrumentationSns (orig, origArguments, request, AWS, agent, { version`
`131`	`131`	`span._setOutcomeFromErrorCapture(constants.OUTCOME_FAILURE)`
`132`	`132`	`}`
`133`	`133`
`134`		`- // we'll need to manually mark this span as async. The actual async hop`
`135`		`- // is captured by the agent's async hooks instrumentation`
`136`		`- span.sync = false`
`137`	`134`	`span.end()`
`138`	`135`	`})`
`139`	`136`
Original file line number	Diff line number	Diff line change
`@@ -166,9 +166,6 @@ function instrumentationSqs (orig, origArguments, request, AWS, agent, { version`
`166`	`166`	`span._setOutcomeFromErrorCapture(constants.OUTCOME_FAILURE)`
`167`	`167`	`}`
`168`	`168`
`169`		`- // we'll need to manually mark this span as async. The actual async hop`
`170`		`- // is captured by the agent's async hooks instrumentation`
`171`		`- span.sync = false`
`172`	`169`	`span.end()`
`173`	`170`
`174`	`171`	`if (request.operation === 'receiveMessage' && response && response.data) {`