fix: ensure correct run context for 'graphql' instrumentation

Refs: #2430

examples/trace-graphql.js

@@ -0,0 +1,41 @@
+// A small example showing Elastic APM tracing of a script using `graphql`.
+// Adapted from https://graphql.org/graphql-js/#writing-code
+
+const apm = require('../').start({ // elastic-apm-node
+  serviceName: 'example-trace-graphql'
+})
+var { graphql, buildSchema } = require('graphql')
+
+// Construct a schema, using GraphQL schema language
+var schema = buildSchema(`
+  type Query {
+    hello: String
+    bye: String
+  }
+`)
+
+// The root provides a resolver function for each API endpoint
+var root = {
+  hello: () => {
+    return 'Hello world!'
+  },
+  bye: () => {
+    return 'Farewell!'
+  }
+}
+
+// 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')
+
+// Run the GraphQL query '{ hello }' and print out the response
+graphql(schema, '{ hello }', root).then((response) => {
+  console.log('hello response:', response)
+})
+graphql(schema, '{ bye }', root).then((response) => {
+  console.log('bye response:', response)
+  t1.end()
+})

lib/instrumentation/modules/graphql.js

@@ -17,6 +17,8 @@ module.exports = function (graphql, agent, { version, enabled }) {
     return graphql
   }
 
+  const ins = agent._instrumentation
+
   return clone({}, graphql, {
     graphql (descriptor) {
       const getter = descriptor.get
@@ -40,16 +42,9 @@ module.exports = function (graphql, agent, { version, enabled }) {
 
   function wrapGraphql (orig) {
     return function wrappedGraphql (schema, requestString, rootValue, contextValue, variableValues, operationName) {
-      var trans = agent._instrumentation.currTransaction()
-      var span = agent.startSpan('GraphQL: Unknown Query', 'db', 'graphql', 'execute')
-      var id = span && span.transaction.id
-      agent.logger.debug('intercepted call to graphql.graphql %o', { id: id })
-
-      // As of now, the only reason why there might be a transaction but no
-      // span is if the transaction have ended. But just to be sure this
-      // doesn't break in the future we add the extra `!span` guard as well
-      if (!trans || trans.ended || !span) {
-        agent.logger.debug('no active transaction found - skipping graphql tracing')
+      agent.logger.debug('intercepted call to graphql.graphql')
+      const span = ins.createSpan('GraphQL: Unknown Query', 'db', 'graphql', 'execute')
+      if (!span) {
         return orig.apply(this, arguments)
       }
 
@@ -74,7 +69,8 @@ module.exports = function (graphql, agent, { version, enabled }) {
         agent.logger.debug('graphql.Source(query) failed - skipping graphql query extraction')
       }
 
-      var p = orig.apply(this, arguments)
+      const spanRunContext = ins.currRunContext().enterSpan(span)
+      const p = ins.withRunContext(spanRunContext, orig, this, ...arguments)
       p.then(function () {
         span.end()
       })
@@ -84,24 +80,21 @@ module.exports = function (graphql, agent, { version, enabled }) {
 
   function wrapExecute (orig) {
     function wrappedExecuteImpl (schema, document, rootValue, contextValue, variableValues, operationName) {
-      var trans = agent._instrumentation.currTransaction()
-      var span = agent.startSpan('GraphQL: Unknown Query', 'db', 'graphql', 'execute')
-      var id = span && span.transaction.id
-      agent.logger.debug('intercepted call to graphql.execute %o', { id: id })
-
-      // As of now, the only reason why there might be a transaction but no
-      // span is if the transaction have ended. But just to be sure this
-      // doesn't break in the future we add the extra `!span` guard as well
-      if (!trans || trans.ended || !span) {
+      agent.logger.debug('intercepted call to graphql.execute')
+      const span = ins.createSpan('GraphQL: Unknown Query', 'db', 'graphql', 'execute')
+      if (!span) {
         agent.logger.debug('no active transaction found - skipping graphql tracing')
         return orig.apply(this, arguments)
       }
 
       var details = extractDetails(document, operationName)
       var queries = details.queries
       operationName = operationName || (details.operation && details.operation.name && details.operation.name.value)
-      if (queries.length > 0) span.name = 'GraphQL: ' + (operationName ? operationName + ' ' : '') + queries.join(', ')
+      if (queries.length > 0) {
+        span.name = 'GraphQL: ' + (operationName ? operationName + ' ' : '') + queries.join(', ')
+      }
 
+      const trans = span.transaction
       if (trans._graphqlRoute) {
         var name = queries.length > 0 ? queries.join(', ') : 'Unknown GraphQL query'
         if (trans.req) var path = getPathFromRequest(trans.req, true)
@@ -112,7 +105,8 @@ module.exports = function (graphql, agent, { version, enabled }) {
         trans.type = 'graphql'
       }
 
-      var p = orig.apply(this, arguments)
+      const spanRunContext = ins.currRunContext().enterSpan(span)
+      const p = ins.withRunContext(spanRunContext, orig, this, ...arguments)
       if (typeof p.then === 'function') {
         p.then(function () {
           span.end()

test/instrumentation/modules/graphql.test.js

@@ -29,10 +29,12 @@ test('graphql.graphql', function (t) {
   agent.startTransaction('foo')
 
   graphql.graphql(schema, query, root).then(function (response) {
+    t.ok(agent.currentSpan === null, 'no currentSpan .graphql().then(...)')
     agent.endTransaction()
     t.deepLooseEqual(response, { data: { hello: 'Hello world!' } })
     agent.flush()
   })
+  t.ok(agent.currentSpan === null, 'no currentSpan in sync code after .graphql(...)')
 })
 
 test('graphql.graphql - invalid query', function (t) {
@@ -49,16 +51,18 @@ test('graphql.graphql - invalid query', function (t) {
   agent.startTransaction('foo')
 
   graphql.graphql(schema, query, root).then(function (response) {
+    t.ok(agent.currentSpan === null, 'no currentSpan .graphql().then(...)')
     agent.endTransaction()
     t.deepEqual(Object.keys(response), ['errors'])
     t.strictEqual(response.errors.length, 1, 'should have one error')
     t.ok(response.errors[0].message.indexOf('Syntax Error') !== -1, 'should return a sytax error')
     agent.flush()
   })
+  t.ok(agent.currentSpan === null, 'no currentSpan in sync code after .graphql(...)')
 })
 
 test('graphql.graphql - transaction ended', function (t) {
-  t.plan(5)
+  t.plan(7)
 
   resetAgent(1, function (data) {
     t.strictEqual(data.transactions.length, 1)
@@ -81,8 +85,10 @@ test('graphql.graphql - transaction ended', function (t) {
   agent.startTransaction('foo').end()
 
   graphql.graphql(schema, query, root).then(function (response) {
+    t.ok(agent.currentSpan === null, 'no currentSpan .graphql().then(...)')
     t.deepLooseEqual(response, { data: { hello: 'Hello world!' } })
   })
+  t.ok(agent.currentSpan === null, 'no currentSpan in sync code after .graphql(...)')
 })
 
 test('graphql.execute', function (t) {
@@ -101,14 +107,16 @@ test('graphql.execute', function (t) {
   agent.startTransaction('foo')
 
   graphql.execute(schema, documentAST, root).then(function (response) {
+    t.ok(agent.currentSpan === null, 'no currentSpan .execute().then(...)')
     agent.endTransaction()
     t.deepLooseEqual(response, { data: { hello: 'Hello world!' } })
     agent.flush()
   })
+  t.ok(agent.currentSpan === null, 'no currentSpan in sync code after .execute(...)')
 })
 
 test('graphql.execute - transaction ended', function (t) {
-  t.plan(5)
+  t.plan(7)
 
   resetAgent(1, function (data) {
     t.strictEqual(data.transactions.length, 1)
@@ -133,8 +141,10 @@ test('graphql.execute - transaction ended', function (t) {
   agent.startTransaction('foo').end()
 
   graphql.execute(schema, documentAST, root).then(function (response) {
+    t.ok(agent.currentSpan === null, 'no currentSpan .execute().then(...)')
     t.deepLooseEqual(response, { data: { hello: 'Hello world!' } })
   })
+  t.ok(agent.currentSpan === null, 'no currentSpan in sync code after .execute(...)')
 })
 
 test('graphql.execute args object', function (t) {
@@ -158,10 +168,12 @@ test('graphql.execute args object', function (t) {
   agent.startTransaction('foo')
 
   graphql.execute(args).then(function (response) {
+    t.ok(agent.currentSpan === null, 'no currentSpan .execute().then(...)')
     agent.endTransaction()
     t.deepLooseEqual(response, { data: { hello: 'Hello world!' } })
     agent.flush()
   })
+  t.ok(agent.currentSpan === null, 'no currentSpan in sync code after .execute(...)')
 })
 
 if (semver.satisfies(pkg.version, '>=0.12')) {
@@ -181,6 +193,7 @@ if (semver.satisfies(pkg.version, '>=0.12')) {
     agent.startTransaction('foo')
 
     var response = graphql.execute(schema, documentAST, root)
+    t.ok(agent.currentSpan === null, 'no currentSpan in sync code after .execute(...)')
 
     agent.endTransaction()
     t.deepLooseEqual(response, { data: { hello: 'Hello world!' } })