feat(sdk-trace-base): add diagnostic logging when spans are dropped (#…

…3610)
open-telemetry · Feb 22, 2023 · 86973eb · 86973eb
1 parent 47444f2
commit 86973eb
Show file tree

Hide file tree

Showing 3 changed files with 51 additions and 0 deletions.
diff --git a/CHANGELOG.md b/CHANGELOG.md
@@ -16,6 +16,7 @@ For experimental package changes, see the [experimental CHANGELOG](experimental/
 * feat(sdk-metrics): apply binary search in histogram recording [#3539](https://github.com/open-telemetry/opentelemetry-js/pull/3539) @legendecas
 * perf(propagator-jaeger): improve deserializeSpanContext performance [#3541](https://github.com/open-telemetry/opentelemetry-js/pull/3541) @doochik
 * feat: support TraceState in SamplingResult [#3530](https://github.com/open-telemetry/opentelemetry-js/pull/3530) @raphael-theriault-swi
+* feat(sdk-trace-base): add diagnostic logging when spans are dropped [#3610](https://github.com/open-telemetry/opentelemetry-js/pull/3610) @neoeinstein
 
 ### :bug: (Bug Fix)
 

diff --git a/packages/opentelemetry-sdk-trace-base/src/export/BatchSpanProcessorBase.ts b/packages/opentelemetry-sdk-trace-base/src/export/BatchSpanProcessorBase.ts
@@ -44,6 +44,7 @@ export abstract class BatchSpanProcessorBase<T extends BufferConfig>
   private _finishedSpans: ReadableSpan[] = [];
   private _timer: NodeJS.Timeout | undefined;
   private _shutdownOnce: BindOnceFuture<void>;
+  private _droppedSpansCount: number = 0;
 
   constructor(private readonly _exporter: SpanExporter, config?: T) {
     const env = getEnv();
@@ -117,8 +118,23 @@ export abstract class BatchSpanProcessorBase<T extends BufferConfig>
   private _addToBuffer(span: ReadableSpan) {
     if (this._finishedSpans.length >= this._maxQueueSize) {
       // limit reached, drop span
+
+      if (this._droppedSpansCount === 0) {
+        diag.debug('maxQueueSize reached, dropping spans');
+      }
+      this._droppedSpansCount++;
+
       return;
     }
+
+    if (this._droppedSpansCount > 0) {
+      // some spans were dropped, log once with count of spans dropped
+      diag.warn(
+        `Dropped ${this._droppedSpansCount} spans because maxQueueSize reached`
+      );
+      this._droppedSpansCount = 0;
+    }
+
     this._finishedSpans.push(span);
     this._maybeStartTimer();
   }

diff --git a/packages/opentelemetry-sdk-trace-base/test/common/export/BatchSpanProcessorBase.test.ts b/packages/opentelemetry-sdk-trace-base/test/common/export/BatchSpanProcessorBase.test.ts
@@ -462,6 +462,40 @@ describe('BatchSpanProcessorBase', () => {
         }
         assert.equal(processor['_finishedSpans'].length, 6);
       });
+      it('should count and report dropped spans', done => {
+        const debugStub = sinon.spy(diag, 'debug');
+        const warnStub = sinon.spy(diag, 'warn');
+        const span = createSampledSpan('test');
+        for (let i = 0, j = 6; i < j; i++) {
+          processor.onStart(span, ROOT_CONTEXT);
+          processor.onEnd(span);
+        }
+        assert.equal(processor['_finishedSpans'].length, 6);
+        assert.equal(processor['_droppedSpansCount'], 0);
+        sinon.assert.notCalled(debugStub);
+
+        processor.onStart(span, ROOT_CONTEXT);
+        processor.onEnd(span);
+
+        assert.equal(processor['_finishedSpans'].length, 6);
+        assert.equal(processor['_droppedSpansCount'], 1);
+        sinon.assert.calledOnce(debugStub);
+
+        processor.forceFlush().then(() => {
+          processor.onStart(span, ROOT_CONTEXT);
+          processor.onEnd(span);
+
+          assert.equal(processor['_finishedSpans'].length, 1);
+          assert.equal(processor['_droppedSpansCount'], 0);
+
+          sinon.assert.calledOnceWithExactly(
+            warnStub,
+            'Dropped 1 spans because maxQueueSize reached'
+          );
+
+          done();
+        });
+      });
     });
   });