Skip to content

Commit

Permalink
fix: more reliable span.sync determination
Browse files Browse the repository at this point in the history
Current `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 works for whatever `asyncHooks`
config var value.

Fixes: #1996
  • Loading branch information
trentm committed Sep 15, 2021
1 parent c29b236 commit 079d802
Show file tree
Hide file tree
Showing 7 changed files with 11 additions and 33 deletions.
8 changes: 0 additions & 8 deletions lib/instrumentation/async-hooks.js
Original file line number Diff line number Diff line change
Expand Up @@ -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
}

Expand Down
8 changes: 1 addition & 7 deletions lib/instrumentation/index.js
Original file line number Diff line number Diff line change
Expand Up @@ -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) {
Expand All @@ -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
Expand Down
7 changes: 0 additions & 7 deletions lib/instrumentation/modules/aws-sdk/dynamodb.js
Original file line number Diff line number Diff line change
Expand Up @@ -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()
})

Expand Down
8 changes: 0 additions & 8 deletions lib/instrumentation/modules/aws-sdk/s3.js
Original file line number Diff line number Diff line change
Expand Up @@ -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()
})
}
Expand Down
3 changes: 0 additions & 3 deletions lib/instrumentation/modules/aws-sdk/sqs.js
Original file line number Diff line number Diff line change
Expand Up @@ -163,9 +163,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) {
Expand Down
5 changes: 5 additions & 0 deletions lib/instrumentation/span.js
Original file line number Diff line number Diff line change
@@ -1,5 +1,6 @@
'use strict'

const { executionAsyncId } = require('async_hooks')
var util = require('util')

var Value = require('async-value-promise')
Expand Down Expand Up @@ -34,6 +35,7 @@ function Span (transaction, name, ...args) {
this._message = null
this._stackObj = null
this._capturedStackTrace = null
this._startXid = executionAsyncId()

this.transaction = transaction
this.name = name || 'unnamed'
Expand Down Expand Up @@ -71,6 +73,9 @@ Span.prototype.end = function (endTime) {
}

this._timer.end(endTime)
if (executionAsyncId() !== this._startXid) {
this.sync = false
}

this._setOutcomeFromSpanEnd()

Expand Down
5 changes: 5 additions & 0 deletions lib/instrumentation/transaction.js
Original file line number Diff line number Diff line change
@@ -1,5 +1,6 @@
'use strict'

const { executionAsyncId } = require('async_hooks')
var util = require('util')

var ObjectIdentityMap = require('object-identity-map')
Expand Down Expand Up @@ -35,6 +36,7 @@ function Transaction (agent, name, ...args) {
this._contextLost = false // TODO: Send this up to the server some how
this._abortTime = 0
this._breakdownTimings = new ObjectIdentityMap()
this._startXid = executionAsyncId()

this.outcome = constants.OUTCOME_UNKNOWN
}
Expand Down Expand Up @@ -232,6 +234,9 @@ Transaction.prototype.end = function (result, endTime) {
this._timer.end(endTime)
this._captureBreakdown(this)
this.ended = true
if (executionAsyncId() !== this._startXid) {
this.sync = false
}

var trans = this._agent._instrumentation.currentTransaction

Expand Down

0 comments on commit 079d802

Please sign in to comment.