fix: span compression bug where a buffered span would not be sent whe…

…n an incompressible sibling ended (#3076)

https://github.com/elastic/apm/blob/main/specs/agents/handling-huge-traces/tracing-spans-compress.md#span-buffering says:
> A buffered span gets reported when
>  1. its parent ends
>  2. a non-compressible sibling ends

Before this change, case 2 was not being handled. Further, a possibly
buffered span on the ending sibling would incorrectly get sent *twice*.
The scenario is as follows:

   trans t0
     span s1: _bufferdSpan=s2
       span s2: ended, compressible -> buffered on s1
       span s3: incompressible, _bufferdSpan=s4
         span s4: ended, compressible -> buffered on s3

What happens when s3 ends? We expect:
- s4 is encoded and sent
- s2 is encoded and sent
- s3 is encoded and sent

Before this change the agent would send: s4, s4, s3

Refs: https://discuss.elastic.co/t/apm-agent-send-duplicate-record-in-mysql/321440

.eslintrc.json

@@ -11,6 +11,7 @@
     "license-header/header": [ "error", "./dev-utils/license-header.js" ]
   },
   "ignorePatterns": [
+    "/*.example.js", // a pattern for uncommited local dev files to avoid linting
     "/.nyc_output",
     "/build",
     "node_modules",

CHANGELOG.asciidoc

@@ -32,6 +32,25 @@ Notes:
 === Node.js Agent version 3.x
 
 
+==== Unreleased
+
+[float]
+===== Breaking changes
+
+[float]
+===== Features
+
+[float]
+===== Bug fixes
+
+* Fix a bug in span compression with sending spans that were buffered for
+  possible compression. Before this fix a compressible span could be sent
+  *twice* or not sent at all. ({pull}3076[#3076])
+
+[float]
+===== Chores
+
+
 [[release-notes-3.41.0]]
 ==== 3.41.0 2022/12/12
 

lib/instrumentation/index.js

@@ -414,24 +414,26 @@ Instrumentation.prototype.addEndedSpan = function (span) {
     // if I have ended and I have something buffered, send that buffered thing
     if (span.getBufferedSpan()) {
       this._encodeAndSendSpan(span.getBufferedSpan())
+      span.setBufferedSpan(null)
     }
 
-    if (!span.isCompressionEligible() || span.getParentSpan().ended) {
-      const buffered = span.getBufferedSpan()
+    const parentSpan = span.getParentSpan()
+    if ((parentSpan && parentSpan.ended) || !span.isCompressionEligible()) {
+      const buffered = parentSpan && parentSpan.getBufferedSpan()
       if (buffered) {
         this._encodeAndSendSpan(buffered)
-        span.setBufferedSpan(null)
+        parentSpan.setBufferedSpan(null)
       }
       this._encodeAndSendSpan(span)
-    } else if (!span.getParentSpan().getBufferedSpan()) {
+    } else if (!parentSpan.getBufferedSpan()) {
       // span is compressible and there's nothing buffered
       // add to buffer, move on
-      span.getParentSpan().setBufferedSpan(span)
-    } else if (!span.getParentSpan().getBufferedSpan().tryToCompress(span)) {
+      parentSpan.setBufferedSpan(span)
+    } else if (!parentSpan.getBufferedSpan().tryToCompress(span)) {
       // we could not compress span so SEND bufferend span
       // and buffer the span we could not compress
-      this._encodeAndSendSpan(span.getParentSpan().getBufferedSpan())
-      span.getParentSpan().setBufferedSpan(span)
+      this._encodeAndSendSpan(parentSpan.getBufferedSpan())
+      parentSpan.setBufferedSpan(span)
     }
   }
 }

test/instrumentation/span-compression.test.js

@@ -159,6 +159,57 @@ tape.test('integration/end-to-end span compression tests', function (suite) {
     }, 300)
   })
 
+  // The scenario is as follows:
+  //   trans t0
+  //     span s1: _bufferdSpan=s2
+  //       span s2: ended, compressible -> buffered on s1
+  //       span s3: incompressible, _bufferdSpan=s4
+  //         span s4: ended, compressible -> buffered on s3
+  //
+  // What happens when s3 ends? We expect:
+  // - s4 is encoded and sent
+  // - s2 is encoded and sent
+  // - s3 is encoded and sent
+  //
+  // This tests the following from https://github.com/elastic/apm/blob/main/specs/agents/handling-huge-traces/tracing-spans-compress.md#span-buffering
+  // > A buffered span gets reported when
+  // >  1. its parent ends
+  // >  2. a non-compressible sibling ends
+  suite.test('ensure a span buffered on parent is sent when incompressible span ends', function (t) {
+    resetAgent(function (data) {
+      // We expect sent spans for: s4, s2, and s3; in that order.
+      t.equals(data.length, 3, '3 events sent')
+      t.equals(data.spans.length, 3, '3 spans sent')
+      t.equals(data.spans.map(s => s.name).join(','), 's4,s2,s3',
+        'sent spans are s4,s2,s3; in that order')
+      t.end()
+    })
+
+    const t0 = agent.startTransaction('t0')
+    setImmediate(() => {
+      const s1 = agent.startSpan('s1', 'manual')
+
+      setImmediate(() => {
+        const s2 = agent.startSpan('s2', 'db', 'mysql', { exitSpan: true })
+        t.equal(s2.getParentSpan().name, 's1', 's2 is a child of s1')
+        s2.end()
+        t.equal(s1.getBufferedSpan().name, 's2', 's2 is buffered on s1')
+
+        const s3 = t0.startSpan('s3', 'manual') // incompressible (because exitSpan=false)
+        t.equal(s3.getParentSpan().name, 's1', 's3 is a child of s1')
+
+        setImmediate(() => {
+          const s4 = agent.startSpan('s4', 'db', 'mysql', { exitSpan: true })
+          t.equal(s4.getParentSpan().name, 's3', 's4 is a child of s3')
+          s4.end()
+          t.equal(s3.getBufferedSpan().name, 's4', 's4 is buffered on s3')
+
+          s3.end()
+        })
+      })
+    })
+  })
+
   suite.end()
 })