From 7a2a3121d417cb84a6c206b76d4020d7f60972c3 Mon Sep 17 00:00:00 2001 From: Trent Mick Date: Tue, 4 Jan 2022 15:37:08 -0800 Subject: [PATCH] fix: ensure correct run context for 'graphql' instrumentation (#2509) Refs: #2430 --- CHANGELOG.asciidoc | 3 ++ examples/trace-graphql.js | 41 ++++++++++++++++++++ lib/instrumentation/modules/graphql.js | 38 ++++++++---------- test/instrumentation/modules/graphql.test.js | 17 +++++++- 4 files changed, 75 insertions(+), 24 deletions(-) create mode 100644 examples/trace-graphql.js diff --git a/CHANGELOG.asciidoc b/CHANGELOG.asciidoc index 625b72763c..ae40217d28 100644 --- a/CHANGELOG.asciidoc +++ b/CHANGELOG.asciidoc @@ -39,6 +39,9 @@ Notes: [float] ===== Bug fixes +* Fixes for run context handling for 'graphql' instrumentation. + ({issues}2430[#2430]) + * Fixes for run context handling for DynamoDB instrumentation ('aws-sdk' package) so that a span created after an AWS client command (in the same tick, in the command callback, or promise) is not a child of the automatic diff --git a/examples/trace-graphql.js b/examples/trace-graphql.js new file mode 100644 index 0000000000..4beb74ed34 --- /dev/null +++ b/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() +}) diff --git a/lib/instrumentation/modules/graphql.js b/lib/instrumentation/modules/graphql.js index 4c5c015316..ce0ac45a3a 100644 --- a/lib/instrumentation/modules/graphql.js +++ b/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,15 +80,9 @@ 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) } @@ -100,8 +90,11 @@ module.exports = function (graphql, agent, { version, enabled }) { 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() diff --git a/test/instrumentation/modules/graphql.test.js b/test/instrumentation/modules/graphql.test.js index 4a964df2b1..9aa3e51adf 100644 --- a/test/instrumentation/modules/graphql.test.js +++ b/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!' } })