From 7b528e9df4272a2554288a2fbf20488c3537fd59 Mon Sep 17 00:00:00 2001 From: Trent Mick Date: Mon, 22 Nov 2021 16:49:57 -0800 Subject: [PATCH] fix: ensure run-context for mysql span does not spill into user code This fixes the 'mysql' instrumentation to not have the mysql span context be active in user code. This ensures that user code cannot create a child span of the mysql span, which would (a) be misleading and (b) cause problems for coming exit span and compressed span work. Refs: #2430 --- examples/trace-mysql.js | 4 +- lib/instrumentation/modules/mysql.js | 90 ++++++++++--------- .../modules/mysql/mysql.test.js | 19 ++++ 3 files changed, 67 insertions(+), 46 deletions(-) diff --git a/examples/trace-mysql.js b/examples/trace-mysql.js index 40dc1c27fe..cbc13e3178 100755 --- a/examples/trace-mysql.js +++ b/examples/trace-mysql.js @@ -26,14 +26,14 @@ client.connect(function (err) { // 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 -apm.startTransaction('t1') +const t1 = apm.startTransaction('t1') client.query('SELECT 1 + 1 AS solution', (err, res) => { if (err) { console.log('[t1] Failure: err is', err) } else { console.log('[t1] Success: solution is %s', res[0].solution) } - apm.endTransaction() + t1.end() }) // 2. Event emitter style diff --git a/lib/instrumentation/modules/mysql.js b/lib/instrumentation/modules/mysql.js index d473883033..9890da2f32 100644 --- a/lib/instrumentation/modules/mysql.js +++ b/lib/instrumentation/modules/mysql.js @@ -98,59 +98,61 @@ function wrapQueryable (connection, objType, agent) { function wrapQuery (original) { return function wrappedQuery (sql, values, cb) { - var span = agent.startSpan(null, 'db', 'mysql', 'query') - var id = span && span.transaction.id + agent.logger.debug('intercepted call to mysql %s.query', objType) + + var span = ins.createSpan(null, 'db', 'mysql', 'query') + if (!span) { + return original.apply(this, arguments) + } + var hasCallback = false var sqlStr - agent.logger.debug('intercepted call to mysql %s.query %o', objType, { id: id }) - - if (span) { - if (this[symbols.knexStackObj]) { - span.customStackTrace(this[symbols.knexStackObj]) - this[symbols.knexStackObj] = null - } + if (this[symbols.knexStackObj]) { + span.customStackTrace(this[symbols.knexStackObj]) + this[symbols.knexStackObj] = null + } - const wrapCallback = function (origCallback) { - hasCallback = true - return ins.bindFunction(function wrappedCallback (_err) { - span.end() - return origCallback.apply(this, arguments) - }) - } + const wrapCallback = function (origCallback) { + hasCallback = true + return ins.bindFunction(function wrappedCallback (_err) { + span.end() + return origCallback.apply(this, arguments) + }) + } - switch (typeof sql) { - case 'string': - sqlStr = sql - break - case 'object': - if (typeof sql._callback === 'function') { - sql._callback = wrapCallback(sql._callback) - } - sqlStr = sql.sql - break - case 'function': - arguments[0] = wrapCallback(sql) - break - } + switch (typeof sql) { + case 'string': + sqlStr = sql + break + case 'object': + if (typeof sql._callback === 'function') { + sql._callback = wrapCallback(sql._callback) + } + sqlStr = sql.sql + break + case 'function': + arguments[0] = wrapCallback(sql) + break + } - if (sqlStr) { - agent.logger.debug('extracted sql from mysql query %o', { id: id, sql: sqlStr }) - span.setDbContext({ statement: sqlStr, type: 'sql' }) - span.name = sqlSummary(sqlStr) - } - span.setDestinationContext(getDBDestination(span, host, port)) + if (sqlStr) { + agent.logger.debug({ sql: sqlStr }, 'extracted sql from mysql query') + span.setDbContext({ statement: sqlStr, type: 'sql' }) + span.name = sqlSummary(sqlStr) + } + span.setDestinationContext(getDBDestination(span, host, port)) - if (typeof values === 'function') { - arguments[1] = wrapCallback(values) - } else if (typeof cb === 'function') { - arguments[2] = wrapCallback(cb) - } + if (typeof values === 'function') { + arguments[1] = wrapCallback(values) + } else if (typeof cb === 'function') { + arguments[2] = wrapCallback(cb) } - var result = original.apply(this, arguments) + const spanRunContext = ins.currRunContext().enterSpan(span) + const result = ins.withRunContext(spanRunContext, original, this, ...arguments) - if (span && !hasCallback && result instanceof EventEmitter) { + if (!hasCallback && result instanceof EventEmitter) { // Wrap `result.emit` instead of `result.once('error', ...)` to avoid // changing app behaviour by possibly setting the only 'error' handler. shimmer.wrap(result, 'emit', function (origEmit) { @@ -166,7 +168,7 @@ function wrapQueryable (connection, objType, agent) { return origEmit.apply(this, arguments) } }) - // Ensure event handlers execute in this run context. + // Ensure event handlers execute in the caller run context. ins.bindEmitter(result) } diff --git a/test/instrumentation/modules/mysql/mysql.test.js b/test/instrumentation/modules/mysql/mysql.test.js index 1258a79d82..26c9367f7b 100644 --- a/test/instrumentation/modules/mysql/mysql.test.js +++ b/test/instrumentation/modules/mysql/mysql.test.js @@ -51,6 +51,7 @@ factories.forEach(function (f) { factory(function () { agent.startTransaction('foo') queryable.query(sql, basicQueryCallback(t)) + t.equal(agent.currentSpan, null, 'mysql span should not bleed into calling code') }) }) @@ -63,6 +64,7 @@ factories.forEach(function (f) { factory(function () { agent.startTransaction('foo') queryable.query(sql, [1], basicQueryCallback(t)) + t.equal(agent.currentSpan, null, 'mysql span should not bleed into calling code') }) }) @@ -75,6 +77,7 @@ factories.forEach(function (f) { factory(function () { agent.startTransaction('foo') queryable.query({ sql: sql }, basicQueryCallback(t)) + t.equal(agent.currentSpan, null, 'mysql span should not bleed into calling code') }) }) @@ -87,6 +90,7 @@ factories.forEach(function (f) { factory(function () { agent.startTransaction('foo') queryable.query({ sql: sql }, [1], basicQueryCallback(t)) + t.equal(agent.currentSpan, null, 'mysql span should not bleed into calling code') }) }) @@ -100,6 +104,7 @@ factories.forEach(function (f) { agent.startTransaction('foo') var query = mysql.createQuery(sql, basicQueryCallback(t)) queryable.query(query) + t.equal(agent.currentSpan, null, 'mysql span should not bleed into calling code') }) }) @@ -113,6 +118,7 @@ factories.forEach(function (f) { agent.startTransaction('foo') var query = mysql.createQuery(sql, [1], basicQueryCallback(t)) queryable.query(query) + t.equal(agent.currentSpan, null, 'mysql span should not bleed into calling code') }) }) @@ -127,6 +133,7 @@ factories.forEach(function (f) { factory(function () { var trans = agent.startTransaction('foo') queryable.query(sql) + t.equal(agent.currentSpan, null, 'mysql span should not bleed into calling code') setTimeout(function () { trans.end() }, 250) @@ -146,6 +153,7 @@ factories.forEach(function (f) { factory(function () { agent.startTransaction('foo') var stream = queryable.query(sql) + t.equal(agent.currentSpan, null, 'mysql span should not bleed into calling code') basicQueryStream(stream, t) }) }) @@ -159,6 +167,7 @@ factories.forEach(function (f) { factory(function () { agent.startTransaction('foo') var stream = queryable.query(sql, [1]) + t.equal(agent.currentSpan, null, 'mysql span should not bleed into calling code') basicQueryStream(stream, t) }) }) @@ -172,6 +181,7 @@ factories.forEach(function (f) { factory(function () { agent.startTransaction('foo') var stream = queryable.query({ sql: sql }) + t.equal(agent.currentSpan, null, 'mysql span should not bleed into calling code') basicQueryStream(stream, t) }) }) @@ -185,6 +195,7 @@ factories.forEach(function (f) { factory(function () { agent.startTransaction('foo') var stream = queryable.query({ sql: sql }, [1]) + t.equal(agent.currentSpan, null, 'mysql span should not bleed into calling code') basicQueryStream(stream, t) }) }) @@ -199,6 +210,7 @@ factories.forEach(function (f) { agent.startTransaction('foo') var query = mysql.createQuery(sql) var stream = queryable.query(query) + t.equal(agent.currentSpan, null, 'mysql span should not bleed into calling code') basicQueryStream(stream, t) }) }) @@ -213,6 +225,7 @@ factories.forEach(function (f) { agent.startTransaction('foo') var query = mysql.createQuery(sql, [1]) var stream = queryable.query(query) + t.equal(agent.currentSpan, null, 'mysql span should not bleed into calling code') basicQueryStream(stream, t) }) }) @@ -230,6 +243,7 @@ factories.forEach(function (f) { data.spans.forEach(function (span) { assertSpan(t, span, sql) + t.equal(span.parent_id, trans.id, 'each mysql span is a child of the transaction') }) t.end() @@ -274,6 +288,7 @@ factories.forEach(function (f) { data.spans.forEach(function (span) { assertSpan(t, span, sql) + t.equal(span.parent_id, trans.id, 'each mysql span is a child of the transaction') }) t.end() @@ -397,6 +412,7 @@ factories.forEach(function (f) { function basicQueryCallback (t) { return function (err, rows, fields) { + t.equal(agent.currentSpan, null, 'mysql span should not bleed into user callback') t.error(err) t.strictEqual(rows[0].solution, 2) agent.endTransaction() @@ -406,13 +422,16 @@ function basicQueryCallback (t) { function basicQueryStream (stream, t) { var results = 0 stream.on('error', function (err) { + t.equal(agent.currentSpan, null, 'mysql span should not be active in user code') t.error(err) }) stream.on('result', function (row) { + t.equal(agent.currentSpan, null, 'mysql span should not be active in user code') results++ t.strictEqual(row.solution, 2) }) stream.on('end', function () { + t.equal(agent.currentSpan, null, 'mysql span should not be active in user code') t.strictEqual(results, 1) agent.endTransaction() })