From 3c4e18d151845d3582f05352e4f6fcc4431c4ba5 Mon Sep 17 00:00:00 2001 From: Alan Storm Date: Fri, 20 May 2022 10:06:36 -0700 Subject: [PATCH] feat: span statistics -- ensure dropped span objects are still created (#2694) feat: span statistics -- ensure dropped span objects are still created Part of: https://github.com/elastic/apm-agent-nodejs/issues/2302 --- lib/instrumentation/index.js | 4 + lib/instrumentation/span.js | 8 ++ lib/instrumentation/transaction.js | 16 ++-- lib/opentelemetry-bridge/OTelTracer.js | 6 +- lib/tracecontext/index.js | 4 + test/instrumentation/transaction.test.js | 2 +- test/opentelemetry-bridge/fixtures.test.js | 76 +++++------------ .../fixtures/createSpan-returns-null.js | 81 +++++++++++++++++++ .../fixtures/hit-transaction-max-spans.js | 79 ------------------ 9 files changed, 130 insertions(+), 146 deletions(-) create mode 100644 test/opentelemetry-bridge/fixtures/createSpan-returns-null.js delete mode 100644 test/opentelemetry-bridge/fixtures/hit-transaction-max-spans.js diff --git a/lib/instrumentation/index.js b/lib/instrumentation/index.js index b8de8cfd75..d3475d9947 100644 --- a/lib/instrumentation/index.js +++ b/lib/instrumentation/index.js @@ -356,6 +356,10 @@ Instrumentation.prototype.addEndedSpan = function (span) { return } + if (!span.isRecorded()) { + return + } + if (!this._agent._conf.spanCompressionEnabled) { this._encodeAndSendSpan(span) } else { diff --git a/lib/instrumentation/span.js b/lib/instrumentation/span.js index e9c1791e9d..9dc47a3dc2 100644 --- a/lib/instrumentation/span.js +++ b/lib/instrumentation/span.js @@ -305,6 +305,14 @@ Span.prototype.tryToCompress = function (spanToCompress) { return this._compression.tryToCompress(this, spanToCompress) } +Span.prototype.isRecorded = function () { + return this._context.isRecorded() +} + +Span.prototype.setRecorded = function (value) { + return this._context.setRecorded(value) +} + function filterCallSite (callsite) { var filename = callsite.getFileName() return filename ? filename.indexOf('/node_modules/elastic-apm-node/') === -1 : true diff --git a/lib/instrumentation/transaction.js b/lib/instrumentation/transaction.js index 5da16d67f5..3d341292f8 100644 --- a/lib/instrumentation/transaction.js +++ b/lib/instrumentation/transaction.js @@ -186,10 +186,6 @@ Transaction.prototype.createSpan = function (...args) { if (!this.sampled) { return null } - if (this._builtSpans >= this._agent._conf.transactionMaxSpans) { - this._droppedSpans++ - return null - } // Exit spans must not have child spans (unless of the same type and subtype). // https://github.com/elastic/apm/blob/master/specs/agents/tracing-spans.md#child-spans-of-exit-spans @@ -206,8 +202,15 @@ Transaction.prototype.createSpan = function (...args) { return null } + const span = new Span(this, ...args, opts) + + if (this._builtSpans >= this._agent._conf.transactionMaxSpans) { + this._droppedSpans++ + span.setRecorded(false) + } + this._builtSpans++ - return new Span(this, ...args, opts) + return span } // Note that this only returns a complete result when called *during* the call @@ -225,7 +228,7 @@ Transaction.prototype.toJSON = function () { sampled: this.sampled, context: undefined, span_count: { - started: this._builtSpans + started: this._builtSpans - this._droppedSpans }, outcome: this.outcome, faas: this._faas @@ -244,7 +247,6 @@ Transaction.prototype.toJSON = function () { cloud: this._cloud || {}, message: this._message || {} } - // Only include dropped count when spans have been dropped. if (this._droppedSpans > 0) { payload.span_count.dropped = this._droppedSpans diff --git a/lib/opentelemetry-bridge/OTelTracer.js b/lib/opentelemetry-bridge/OTelTracer.js index f8af35529b..5ab40beefd 100644 --- a/lib/opentelemetry-bridge/OTelTracer.js +++ b/lib/opentelemetry-bridge/OTelTracer.js @@ -80,9 +80,9 @@ class OTelTracer { } newTransOrSpan = trans.createSpan(name, createOpts) - // There might be no span, e.g. if transactionMaxSpans was hit. We have - // to return some OTelSpan, and we also want to propagate the parent's - // trace-context, if any. + // There might be no span, e.g. if the span is a child of an exit span. We + // have to return some OTelSpan, and we also want to propagate the + // parent's trace-context, if any. if (!newTransOrSpan) { return otel.trace.wrapSpanContext(otelSpanContextFromTraceContext(parentGenericSpan._context)) } diff --git a/lib/tracecontext/index.js b/lib/tracecontext/index.js index 34fe44cf03..8394e5d69e 100644 --- a/lib/tracecontext/index.js +++ b/lib/tracecontext/index.js @@ -97,6 +97,10 @@ class TraceContext { setRecorded () { return this.traceparent.setRecorded() } + + isRecorded () { + return this.traceparent.recorded + } } TraceContext.FLAGS = TraceParent.FLAGS diff --git a/test/instrumentation/transaction.test.js b/test/instrumentation/transaction.test.js index c227726f7c..8b1c608c2d 100644 --- a/test/instrumentation/transaction.test.js +++ b/test/instrumentation/transaction.test.js @@ -500,7 +500,7 @@ test('#_encode() - dropped spans', function (t) { var span0 = trans.startSpan('s0', 'type0') trans.startSpan('s1', 'type1') var span2 = trans.startSpan() - if (span2) { + if (span2.isRecorded()) { t.fail('should have dropped the span') } span0.end() diff --git a/test/opentelemetry-bridge/fixtures.test.js b/test/opentelemetry-bridge/fixtures.test.js index ca0320ea01..f89e0d9baf 100644 --- a/test/opentelemetry-bridge/fixtures.test.js +++ b/test/opentelemetry-bridge/fixtures.test.js @@ -161,74 +161,38 @@ const cases = [ { // Expected trace: - // trace $traceId - // `- transaction $myTransId "myTrans" - // `- span "s0" - // `- span "GET localhost:$port" (http) + // trace $traceId + // `- transaction "aTrans" + // `- span "anExitSpan" // `- transaction "GET unknown route" - // `- span "s1" // This is the 3rd (max) span. - // `- transaction "GET unknown route" - // `- transaction "GET unknown route" - // `- transaction "GET unknown route" - // `- transaction "GET unknown route" - script: 'hit-transaction-max-spans.js', - testOpts: { - // - This fixture fails with node.js [10.0, 10.4) due to an async context - // issue. See https://github.com/nodejs/node/issues/20274 - // - This fixture hits a limitation/bug with asyncHooks=false. - // See https://github.com/elastic/apm-agent-nodejs/issues/2679 - skip: (semver.satisfies(process.version, '>=10.0.0 <10.4') || - process.env.ELASTIC_APM_ASYNC_HOOKS === 'false') - }, - env: { - ELASTIC_APM_TRANSACTION_MAX_SPANS: '3' - }, + script: 'createSpan-returns-null.js', check: (t, events) => { - t.equal(events.length, 10, 'exactly 10 events') + t.equal(events.length, 4, 'exactly 4 events') t.ok(events[0].metadata, 'APM server got event metadata object') - function assertIncomingHttpTrans (trans, parentId) { - t.equal(trans.name, 'GET unknown route', 'incoming http transaction.name') - t.equal(trans.parent_id, parentId, 'incoming http transaction.parent_id') - t.ok(trans.context.request.headers.traceparent, 'incoming http "traceparent" header') - t.ok(trans.context.request.headers['elastic-apm-traceparent'], 'incoming http "elastic-apm-traceparent" header') - t.ok((trans.context.request.headers.tracestate || '').indexOf('es=s:1') !== -1, - 'incoming http "tracestate" header has expected "es=" section') - } - // All the transactions and spans, in order of creation. const tas = events.slice(1) .sort((a, b) => (a.transaction || a.span).timestamp > (b.transaction || b.span).timestamp ? 1 : -1) - // trace $traceId + // trace $traceId const traceId = tas[0].transaction.trace_id tas.forEach(s => { t.equal((s.transaction || s.span).trace_id, traceId, 'traceId') }) - // `- transaction $myTransId "myTrans" - const myTrans = tas[0].transaction - t.equal(myTrans.name, 'myTrans', 'myTrans.name') - t.deepEqual(myTrans.span_count, { started: 3, dropped: 4 }, 'myTrans.span_count') - // `- span "s0" - const s0 = tas[1].span - t.equal(s0.name, 's0', 's0') - t.equal(s0.parent_id, myTrans.id, 's0.parent_id') - // `- span "GET localhost:$port" (http) - t.equal(tas[2].span.subtype, 'http', 'http span.subtype') - t.equal(tas[2].span.parent_id, s0.id, 'http span.parent_id') + // `- transaction "aTrans" + const aTrans = tas[0].transaction + t.equal(aTrans.name, 'aTrans', 'aTrans.name') + // `- span "anExitSpan" + const anExitSpan = tas[1].span + t.equal(anExitSpan.name, 'anExitSpan', 'anExitSpan') + t.equal(anExitSpan.parent_id, aTrans.id, 'anExitSpan.parent_id') // `- transaction "GET unknown route" - assertIncomingHttpTrans(tas[3].transaction, tas[2].span.id) - // `- span "s1" // This is the 3rd (max) span. - const s1 = tas[4].span - t.equal(s1.name, 's1', 's1') - t.equal(s1.parent_id, myTrans.id, 's1.parent_id') - // `- transaction "GET unknown route" - assertIncomingHttpTrans(tas[5].transaction, tas[4].span.id) - // `- transaction "GET unknown route" - // `- transaction "GET unknown route" - // `- transaction "GET unknown route" - for (let i = 6; i < 9; i++) { - assertIncomingHttpTrans(tas[i].transaction, myTrans.id) - } + const trans = tas[2].transaction + t.equal(trans.name, 'GET unknown route', 'incoming http transaction.name') + t.equal(trans.parent_id, anExitSpan.id, 'incoming http transaction.parent_id') + t.ok(trans.context.request.headers.traceparent, 'incoming http "traceparent" header') + t.ok(trans.context.request.headers['elastic-apm-traceparent'], 'incoming http "elastic-apm-traceparent" header') + t.ok((trans.context.request.headers.tracestate || '').indexOf('es=s:1') !== -1, + 'incoming http "tracestate" header has expected "es=" section') } }, diff --git a/test/opentelemetry-bridge/fixtures/createSpan-returns-null.js b/test/opentelemetry-bridge/fixtures/createSpan-returns-null.js new file mode 100644 index 0000000000..bf9744dd3b --- /dev/null +++ b/test/opentelemetry-bridge/fixtures/createSpan-returns-null.js @@ -0,0 +1,81 @@ +'use strict' + +// This tests the OTel Bridge for the case when `tracer.startSpan()` calls +// the internal API `transaction.createSpan()` **and that returns null**. +// Currently that can happen when attempting to create a child of an exit +// span (a contrived case). +// +// The OTel Bridge needs to: +// - return a non-recording span, because it needs to return something that +// implements interface Span; and +// - propagate W3C trace-context for possible subsequent outgoing HTTP requests +// +// Usage: +// ELASTIC_APM_OPENTELEMETRY_BRIDGE_ENABLED=true \ +// node -r ../../../start.js createSpan-returns-null.js +// +// Expected trace: +// trace $traceId +// `- transaction "aTrans" +// `- span "anExitSpan" +// `- transaction "GET unknown route" + +const apm = require('../../..') +const assert = require('assert') +const http = require('http') +const otel = require('@opentelemetry/api') + +const tracer = otel.trace.getTracer('test-createSpan-returns-null') + +const server = http.createServer(function onRequest (req, res) { + console.log('server request: %s %s %s', req.method, req.url, req.headers) + req.resume() + req.on('end', function () { + const resBody = JSON.stringify({ ping: 'pong' }) + res.writeHead(200, { + 'content-type': 'application/json', + 'content-length': Buffer.byteLength(resBody) + }) + res.end(resBody) + }) +}) + +async function makeAClientRequest (port) { + return new Promise(resolve => { + http.get({ + host: 'localhost', + port: port, + path: '/ping' + }, (cRes) => { + console.log('client response status:', cRes.statusCode) + console.log('client response headers:', cRes.headers) + const body = [] + cRes.on('data', (chunk) => body.push(chunk)) + cRes.on('end', () => { + console.log('client response body:', body.toString()) + resolve() + }) + }) + }) +} + +server.listen(async () => { + const port = server.address().port + + // 1. Create an APM transaction. + tracer.startActiveSpan('aTrans', async (aTrans) => { + // 2. Use the Elastic API to create an *exit* span. + const anExitSpan = apm.startSpan('anExitSpan', 'myType', 'mySubtype', { exitSpan: true }) + // 3. Attempt to create a child span of that exit span. This triggers the + // code path where `Transaction#createSpan()` returns null. + await tracer.startActiveSpan('theSpan', async (theSpan) => { + assert.strictEqual(theSpan.isRecording(), false, 'theSpan is not recording') + assert.strictEqual(theSpan.spanContext().spanId, anExitSpan.id, 'theSpan is carrying the trace-context of its parent (anExitSpan)') + await makeAClientRequest(port) + theSpan.end() + }) + anExitSpan.end() + aTrans.end() + server.close() + }) +}) diff --git a/test/opentelemetry-bridge/fixtures/hit-transaction-max-spans.js b/test/opentelemetry-bridge/fixtures/hit-transaction-max-spans.js deleted file mode 100644 index 8f4a9bf766..0000000000 --- a/test/opentelemetry-bridge/fixtures/hit-transaction-max-spans.js +++ /dev/null @@ -1,79 +0,0 @@ -'use strict' - -// This tests the OTel Bridge for the case when `transactionMaxSpans` is hit. -// -// This results in `.createSpan(...)` returning null. The OTel -// Bridge needs to cope by returning a non-recording span. It *also* needs -// to propagate W3C trace-context for outgoing HTTP requests. -// -// Usage: -// ELASTIC_APM_TRANSACTION_MAX_SPANS=3 \ -// ELASTIC_APM_OPENTELEMETRY_BRIDGE_ENABLED=true \ -// node -r ../../../start.js hit-transaction-max-spans.js -// -// Expected trace: -// trace $traceId -// `- transaction $myTransId "myTrans" -// `- span "s0" -// `- span "GET localhost:$port" (http) -// `- transaction "GET unknown route" -// `- span "s1" // This is the 3rd (max) span. -// `- transaction "GET unknown route" -// `- transaction "GET unknown route" -// `- transaction "GET unknown route" -// `- transaction "GET unknown route" - -const http = require('http') - -const otel = require('@opentelemetry/api') -const tracer = otel.trace.getTracer('test-hit-transaction-max-spans') - -const server = http.createServer(function onRequest (req, res) { - console.log('server request: %s %s %s', req.method, req.url, req.headers) - req.resume() - req.on('end', function () { - const resBody = JSON.stringify({ ping: 'pong' }) - res.writeHead(200, { - 'content-type': 'application/json', - 'content-length': Buffer.byteLength(resBody) - }) - res.end(resBody) - }) -}) - -async function makeAClientRequest (i, port) { - console.log('\n-- make client request %d', i) - await tracer.startActiveSpan(`s${i}`, async (s) => { - return new Promise(resolve => { - http.get({ - host: 'localhost', - port: port, - path: `/ping-${i}` - }, (cRes) => { - console.log('client response status:', cRes.statusCode) - console.log('client response headers:', cRes.headers) - const body = [] - cRes.on('data', (chunk) => body.push(chunk)) - cRes.on('end', () => { - console.log('client response body:', body.toString()) - s.end() - resolve() - }) - }) - }) - }) -} - -server.listen(async () => { - const port = server.address().port - tracer.startActiveSpan('myTrans', async (myTrans) => { - // Make 5 client requests to `server` in sequence. Each of those requests - // involves two spans (a manual `s${i}` span and the auto-instrumented - // http.get() span). We expect to hit the `transactionMaxSpans` limit. - for (let i = 0; i < 5; i++) { - await makeAClientRequest(i, port) - } - myTrans.end() - server.close() - }) -})