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

- 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.

Refs: #2430
  • Loading branch information
trentm committed Nov 19, 2021
1 parent 3b0b9d1 commit ccdd35b
Show file tree
Hide file tree
Showing 3 changed files with 103 additions and 70 deletions.
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()
96 changes: 38 additions & 58 deletions lib/instrumentation/modules/ioredis.js
Original file line number Diff line number Diff line change
@@ -1,81 +1,61 @@
'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'

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 (span && command) {
// store span on command to it can be accessed by callback in initPromise
command[spanSym] = span

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)
}
}
if (!command || !command.name || !command.promise) {
// Doesn't look like an ioredis.Command, skip instrumenting.
return origSendCommand.apply(this, arguments)
}

span.name = String(command.name).toUpperCase()
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)
}

return original.apply(this, arguments)
const options = this.options || {} // `this` is the `Redis` client.
span.setDestinationContext(getDBDestination(span, options.host, options.port))

command.promise.then(
() => {
span.end()
},
(err) => {
span._setOutcomeFromErrorCapture(constants.OUTCOME_FAILURE)
agent.captureError(err, { skipOutcome: true })
span.end()
}
)
const spanRunContext = ins.currRunContext().enterSpan(span)
return ins.withRunContext(spanRunContext, origSendCommand, this, ...arguments)
}
}
}
28 changes: 16 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 Down Expand Up @@ -98,7 +97,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 +109,16 @@ test('rejections_handled', function (t) {
process.removeListener('unhandledRejection', onUnhandledRejection)
})
agent._instrumentation.testReset()
agent._transport = mockClient(3, function () {
agent._transport = mockClient(4, function (data) {
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')

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 +155,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 +173,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 ccdd35b

Please sign in to comment.