Skip to content

Commit

Permalink
fix: rewrite ioredis instrumentation: run-context, add destination co…
Browse files Browse the repository at this point in the history
…ntext, captureError (#2460)

- This fixes run-context handling for proper parent/child relationships.
  The run-context in code in the same tick and the optional callback are
  no longer changed.
- Add destination context, so ioredis usage shows redis on the Service Map.
- Capture an error and set the span outcome to "failure" if the command
  errors.
- No longer double-instrument queued ioredis commands
- Limit the number of ioredis versions tested, it is one of the 
  top 5 longest to run.

Fixes: #2459
Refs: #2430
  • Loading branch information
trentm authored Nov 24, 2021
1 parent 832c285 commit 1ed110e
Show file tree
Hide file tree
Showing 6 changed files with 146 additions and 73 deletions.
12 changes: 10 additions & 2 deletions .tav.yml
Original file line number Diff line number Diff line change
Expand Up @@ -42,15 +42,23 @@ mysql2-new:
redis:
versions: '>=2.0.0 <4.0.0'
commands: node test/instrumentation/modules/redis.test.js

# We want these version ranges:
# # v3.1.3 is broken in older versions of Node because of https://github.com/luin/ioredis/commit/d5867f7c7f03a770a8c0ca5680fdcbfcaf8488e7
# versions: '>=2 <3.1.3 || >3.1.3 <4'
# versions: '^4.0.0'
# However, there are a *lot* of ioredis releases, so we statically list a
# subset (the first, plus then the latest in each major.minor).
ioredis-old:
name: ioredis
versions: '>=2 <3.1.3 || >3.1.3 <4' # v3.1.3 is broken in older versions of Node because of https://github.com/luin/ioredis/commit/d5867f7c7f03a770a8c0ca5680fdcbfcaf8488e7
versions: '2.0.0 || 2.0.1 || 2.1.0 || 2.2.0 || 2.3.1 || 2.4.3 || 2.5.0 || 3.0.0 || 3.1.4 || 3.2.2 || >3.2.2 <4'
commands: node test/instrumentation/modules/ioredis.test.js
ioredis-new:
name: ioredis
versions: '^4.0.0'
versions: '4.0.0 || 4.0.2 || 4.1.0 || 4.2.3 || 4.3.1 || 4.4.0 || 4.5.1 || 4.6.3 || 4.7.0 || 4.8.0 || 4.9.0 || 4.9.5 || 4.10.4 || 4.11.2 || 4.12.2 || 4.13.1 || 4.14.4 || 4.15.1 || 4.16.3 || 4.17.3 || 4.18.0 || 4.19.4 || 4.20.0 || 4.21.0 || 4.22.0 || 4.23.1 || 4.24.6 || 4.25.0 || 4.26.0 || 4.27.11 || ^4.28.0'
node: '>=6'
commands: node test/instrumentation/modules/ioredis.test.js

pg-old-node:
name: pg
# We want this version range:
Expand Down
23 changes: 22 additions & 1 deletion CHANGELOG.asciidoc
Original file line number Diff line number Diff line change
Expand Up @@ -28,14 +28,35 @@ Notes:
[[release-notes-3.x]]
=== Node.js Agent version 3.x
==== Unreleased
[float]
===== Breaking changes
[float]
===== Features
[float]
===== Bug fixes
* Fixes for 'ioredis' instrumentation ({pull}2460[#2460]):
+
** Fix run-context so that a span created in the same tick as an ioredis
client command will no longer be a child of the redis span.
** Capture an APM error and correctly set span.outcome to "failure" when
a redis client command calls back with an error.
** Avoid a rare possible double-instrumentation of redis commands
internally-queued before the RedisClient is "ready". ({issues}2459[#2459])
** Add destination context so Redis shows up on the Service Map.
[[release-notes-3.25.0]]
==== 3.25.0 2021/11/24
[float]
===== Bug fixes
* Fixes for 'redis' instrumentations:
* Fixes for 'redis' instrumentation:
+
** Fix run-context so that a span created in the same tick as a redis client
command will no longer be a child of the redis span. ({issues}2430[#2430])
Expand Down
49 changes: 49 additions & 0 deletions examples/trace-ioredis.js
Original file line number Diff line number Diff line change
@@ -0,0 +1,49 @@
#!/usr/bin/env node --unhandled-rejections=strict

// A small example showing Elastic APM tracing the 'ioredis' package.
//
// This assumes a Redis server running on localhost. You can use:
// npm run docker:start
// to start an Redis docker container (and other containers used for
// testing of this project). Then `npm run docker:stop` to stop them.

const apm = require('../').start({ // elastic-apm-node
serviceName: 'example-trace-ioredis'
})

const Redis = require('ioredis')
const redis = new Redis()

// Convenience printer for redis client callbacks.
function printerCb (name) {
return function (err, results) {
console.log('%s: %o', name, err ? `${err.name}: ${err.message}` : results)
}
}

// For tracing spans to be created, there must be an active transaction.
// Typically, a transaction is automatically started for incoming HTTP
// requests to a Node.js server. However, because this script is not running
// an HTTP server, we manually start a transaction. More details at:
// https://www.elastic.co/guide/en/apm/agent/nodejs/current/custom-transactions.html
const t1 = apm.startTransaction('t1')

redis.set('foo', 'bar')
redis.get('foo', printerCb('GET foo'))
redis.get('foo').then(function (result) {
console.log('GET foo (with promise):', result)
})

// Transactions.
redis
.multi()
.set('foo', 'bar', printerCb('SET in MULTI'))
.get('foo')
.exec(printerCb('EXEC'))

// Error capture.
redis.hset('a', 'b', 'c')
redis.get('a', printerCb('GET a (wrong type)'))

t1.end()
redis.quit()
102 changes: 45 additions & 57 deletions lib/instrumentation/modules/ioredis.js
Original file line number Diff line number Diff line change
@@ -1,81 +1,69 @@
'use strict'

var semver = require('semver')
// Instrumentation of the 'ioredis' package:
// https://github.com/luin/ioredis
// https://github.com/luin/ioredis/blob/master/API.md

var shimmer = require('../shimmer')
const semver = require('semver')

var spanSym = Symbol('elasticAPMSpan')
const constants = require('../../constants')
const { getDBDestination } = require('../context')
const shimmer = require('../shimmer')

const TYPE = 'cache'
const SUBTYPE = 'redis'
const hasIoredisSpanSym = Symbol('ElasticAPMHasIoredisSpan')

module.exports = function (ioredis, agent, { version, enabled }) {
if (!enabled) {
return ioredis
}
if (!semver.satisfies(version, '>=2.0.0 <5.0.0')) {
agent.logger.debug('ioredis version %s not supported - aborting...', version)
return ioredis
}

agent.logger.debug('shimming ioredis.Command.prototype.initPromise')
shimmer.wrap(ioredis.Command && ioredis.Command.prototype, 'initPromise', wrapInitPromise)

if (!enabled) return ioredis
const ins = agent._instrumentation

agent.logger.debug('shimming ioredis.prototype.sendCommand')
shimmer.wrap(ioredis.prototype, 'sendCommand', wrapSendCommand)

return ioredis

// wrap initPromise to allow us to get notified when the callback to a
// command is called. If we don't do this we will still get notified because
// we register a callback with command.promise.finally the
// wrappedSendCommand, but the finally call will not get fired until the tick
// after the command.callback have fired, so if the transaction is ended in
// the same tick as the call to command.callback, we'll lose the last span
// as it hasn't yet ended.
function wrapInitPromise (original) {
return function wrappedInitPromise () {
var command = this
var cb = this.callback

if (typeof cb === 'function') {
this.callback = agent._instrumentation.bindFunction(function wrappedCallback () {
var span = command[spanSym]
if (span && !span.ended) span.end()
return cb.apply(this, arguments)
})
}

return original.apply(this, arguments)
}
}

function wrapSendCommand (original) {
function wrapSendCommand (origSendCommand) {
return function wrappedSendCommand (command) {
var span = agent.startSpan(null, 'cache', 'redis')
var id = span && span.transaction.id

agent.logger.debug('intercepted call to ioredis.prototype.sendCommand %o', { id: id, command: command && command.name })
if (!command || !command.name || !command.promise) {
// Doesn't look like an ioredis.Command, skip instrumenting.
return origSendCommand.apply(this, arguments)
}
if (command[hasIoredisSpanSym]) {
// Avoid double-instrumenting a command when ioredis *re*-calls
// sendCommand for queued commands when "ready".
return origSendCommand.apply(this, arguments)
}

if (span && command) {
// store span on command to it can be accessed by callback in initPromise
command[spanSym] = span
agent.logger.debug({ command: command.name }, 'intercepted call to ioredis.prototype.sendCommand')
const span = ins.createSpan(command.name.toUpperCase(), TYPE, SUBTYPE)
if (!span) {
return origSendCommand.apply(this, arguments)
}

if (typeof command.resolve === 'function') {
command.resolve = agent._instrumentation.bindFunction(command.resolve)
}
if (typeof command.reject === 'function') {
command.reject = agent._instrumentation.bindFunction(command.reject)
}
if (command.promise) {
const endSpan = function () {
if (!span.ended) span.end()
}
if (typeof command.promise.then === 'function') {
command.promise.then(endSpan).catch(endSpan)
}
}
command[hasIoredisSpanSym] = true

span.name = String(command.name).toUpperCase()
}
const options = this.options || {} // `this` is the `Redis` client.
span.setDestinationContext(getDBDestination(span, options.host, options.port))

return original.apply(this, arguments)
const spanRunContext = ins.currRunContext().enterSpan(span)
command.promise.then(
() => {
span.end()
},
ins.bindFunctionToRunContext(spanRunContext, (err) => {
span._setOutcomeFromErrorCapture(constants.OUTCOME_FAILURE)
agent.captureError(err, { skipOutcome: true })
span.end()
})
)
return ins.withRunContext(spanRunContext, origSendCommand, this, ...arguments)
}
}
}
2 changes: 1 addition & 1 deletion package.json
Original file line number Diff line number Diff line change
Expand Up @@ -151,7 +151,7 @@
"handlebars": "^4.7.3",
"hapi": "^18.1.0",
"https-pem": "^2.0.0",
"ioredis": "^4.16.0",
"ioredis": "^4.28.0",
"jade": "^1.11.0",
"knex": "^0.21.2",
"koa": "^2.11.0",
Expand Down
31 changes: 19 additions & 12 deletions test/instrumentation/modules/ioredis.test.js
Original file line number Diff line number Diff line change
@@ -1,8 +1,7 @@
'use strict'

var agent = require('../../..').start({
serviceName: 'test',
secretToken: 'test',
serviceName: 'test-ioredis',
captureExceptions: false,
metricsInterval: 0,
centralConfig: false,
Expand All @@ -12,6 +11,7 @@ var agent = require('../../..').start({
var Redis = require('ioredis')
var test = require('tape')

var findObjInArray = require('../../_utils').findObjInArray
var mockClient = require('../../_mock_http_client')

test('not nested', function (t) {
Expand Down Expand Up @@ -98,7 +98,7 @@ test('nested', function (t) {
})
})

test('rejections_handled', function (t) {
test('error capture, no unhandledRejection on command error is introduced', function (t) {
// Make sure there are no unhandled promise rejections
// introduced by our promise handling. See #1518.
let unhandledRejection = false
Expand All @@ -110,13 +110,18 @@ test('rejections_handled', function (t) {
process.removeListener('unhandledRejection', onUnhandledRejection)
})
agent._instrumentation.testReset()
agent._transport = mockClient(3, function () {
agent._transport = mockClient(4, function (data) {
const getSpan = findObjInArray(data.spans, 'name', 'GET')
t.equal(data.errors.length, 1, 'captured 1 error')
t.equal(data.errors[0].exception.type, 'ReplyError', 'exception.type')
t.equal(data.errors[0].transaction_id, data.transactions[0].id, 'error.transaction_id')
t.equal(data.errors[0].parent_id, getSpan.id, 'error.parent_id, the error is a child of the erroring span')

setTimeout(function () {
t.notOk(unhandledRejection)
t.end()
}, 0)
})
agent.captureError = function (err) { throw err }

var redis = new Redis(process.env.REDIS_HOST)
const trans = agent.startTransaction('foo', 'bar')
Expand Down Expand Up @@ -153,12 +158,15 @@ function done (t) {

groups.forEach(function (name, i) {
const span = data.spans[i]
t.strictEqual(span.name, name)
t.strictEqual(span.type, 'cache')
t.strictEqual(span.subtype, 'redis')

var offset = span.timestamp - trans.timestamp
t.ok(offset + span.duration * 1000 < trans.duration * 1000)
t.strictEqual(span.name, name, 'span.name')
t.strictEqual(span.type, 'cache', 'span.type')
t.strictEqual(span.subtype, 'redis', 'span.subtype')
t.deepEqual(span.context.destination, {
service: { name: 'redis', resource: 'redis', type: 'cache' },
address: process.env.REDIS_HOST || 'localhost',
port: 6379
}, 'span.context.destination')
t.strictEqual(span.parent_id, trans.id, 'span is a child of the transaction')
})

t.end()
Expand All @@ -168,5 +176,4 @@ function done (t) {
function resetAgent (cb) {
agent._instrumentation.testReset()
agent._transport = mockClient(9, cb)
agent.captureError = function (err) { throw err }
}

0 comments on commit 1ed110e

Please sign in to comment.