Skip to content

Commit

Permalink
feat: span statistics -- ensure dropped span objects are still created (
Browse files Browse the repository at this point in the history
#2694)

feat: span statistics -- ensure dropped span objects are still created

Part of: #2302
  • Loading branch information
astorm authored May 20, 2022
1 parent 4019c99 commit 3c4e18d
Show file tree
Hide file tree
Showing 9 changed files with 130 additions and 146 deletions.
4 changes: 4 additions & 0 deletions lib/instrumentation/index.js
Original file line number Diff line number Diff line change
Expand Up @@ -356,6 +356,10 @@ Instrumentation.prototype.addEndedSpan = function (span) {
return
}

if (!span.isRecorded()) {
return
}

if (!this._agent._conf.spanCompressionEnabled) {
this._encodeAndSendSpan(span)
} else {
Expand Down
8 changes: 8 additions & 0 deletions lib/instrumentation/span.js
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
16 changes: 9 additions & 7 deletions lib/instrumentation/transaction.js
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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
Expand All @@ -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
Expand All @@ -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
Expand Down
6 changes: 3 additions & 3 deletions lib/opentelemetry-bridge/OTelTracer.js
Original file line number Diff line number Diff line change
Expand Up @@ -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))
}
Expand Down
4 changes: 4 additions & 0 deletions lib/tracecontext/index.js
Original file line number Diff line number Diff line change
Expand Up @@ -97,6 +97,10 @@ class TraceContext {
setRecorded () {
return this.traceparent.setRecorded()
}

isRecorded () {
return this.traceparent.recorded
}
}

TraceContext.FLAGS = TraceParent.FLAGS
Expand Down
2 changes: 1 addition & 1 deletion test/instrumentation/transaction.test.js
Original file line number Diff line number Diff line change
Expand Up @@ -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()
Expand Down
76 changes: 20 additions & 56 deletions test/opentelemetry-bridge/fixtures.test.js
Original file line number Diff line number Diff line change
Expand Up @@ -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')
}
},

Expand Down
81 changes: 81 additions & 0 deletions test/opentelemetry-bridge/fixtures/createSpan-returns-null.js
Original file line number Diff line number Diff line change
@@ -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()
})
})
79 changes: 0 additions & 79 deletions test/opentelemetry-bridge/fixtures/hit-transaction-max-spans.js

This file was deleted.

0 comments on commit 3c4e18d

Please sign in to comment.