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

lib/instrumentation/index.js

@@ -385,6 +385,10 @@ Instrumentation.prototype.addEndedSpan = function (span) {
 }
 
 Instrumentation.prototype._encodeAndSendSpan = function (span) {
+  if (!span.isRecorded()) {
+    return
+  }
+
   const agent = this._agent
   // Note this error as an "inflight" event. See Agent#flush().
   const inflightEvents = agent._inflightEvents

lib/instrumentation/span.js

@@ -301,6 +301,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

lib/instrumentation/transaction.js

@@ -133,10 +133,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
@@ -153,8 +149,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
@@ -172,7 +175,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
@@ -191,7 +194,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

lib/opentelemetry-bridge/OTelTracer.js

@@ -74,9 +74,9 @@ class OTelTracer {
       }
       newTransOrSpan = trans.createSpan(name, spanOpts)
 
-      // 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))
       }

lib/tracecontext/index.js

@@ -86,6 +86,10 @@ class TraceContext {
   setRecorded () {
     return this.traceparent.setRecorded()
   }
+
+  isRecorded () {
+    return this.traceparent.recorded
+  }
 }
 
 TraceContext.FLAGS = TraceParent.FLAGS

test/instrumentation/transaction.test.js

@@ -449,7 +449,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()

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

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