fix: ensure run-context for mysql span does not spill into user code (#…

…2463)

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

CHANGELOG.asciidoc

@@ -59,6 +59,10 @@ Notes:
   arguments. In the next major version these two fields will be removed.
   ({issues}2356[#2356])
 
+* Fix run-context handling for 'mysql' instrumentation to avoid accidental
+  creation of *child* spans of the automatic 'mysql' spans.
+  ({issues}2430[#2430]})
+
 
 [[release-notes-3.24.0]]
 ==== 3.24.0 2021/11/09

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

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)
       }
 

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()
   })