From 01effc57e51807e615f58d182822cff5c6cab7ca Mon Sep 17 00:00:00 2001 From: Trent Mick Date: Tue, 20 Dec 2022 13:48:39 -0800 Subject: [PATCH] fix: span compression bug where a buffered span would not be sent when 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 | 1 + CHANGELOG.asciidoc | 19 +++++++ lib/instrumentation/index.js | 18 ++++--- test/instrumentation/span-compression.test.js | 51 +++++++++++++++++++ 4 files changed, 81 insertions(+), 8 deletions(-) diff --git a/.eslintrc.json b/.eslintrc.json index 05895a6912..a4a2847bb4 100644 --- a/.eslintrc.json +++ b/.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", diff --git a/CHANGELOG.asciidoc b/CHANGELOG.asciidoc index 10c3a9b3d0..304b228a1b 100644 --- a/CHANGELOG.asciidoc +++ b/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 diff --git a/lib/instrumentation/index.js b/lib/instrumentation/index.js index 18e2d92a6e..c3c871b7b7 100644 --- a/lib/instrumentation/index.js +++ b/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) } } } diff --git a/test/instrumentation/span-compression.test.js b/test/instrumentation/span-compression.test.js index 50f14d8031..f1434461e5 100644 --- a/test/instrumentation/span-compression.test.js +++ b/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() })