diff --git a/CHANGELOG.md b/CHANGELOG.md index 0ed63cceff..43aa4482e2 100644 --- 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 index 2f14b77c74..d760ff5809 100644 --- 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 private _finishedSpans: ReadableSpan[] = []; private _timer: NodeJS.Timeout | undefined; private _shutdownOnce: BindOnceFuture; + private _droppedSpansCount: number = 0; constructor(private readonly _exporter: SpanExporter, config?: T) { const env = getEnv(); @@ -117,8 +118,23 @@ export abstract class BatchSpanProcessorBase 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 index fd9574537b..069287fc59 100644 --- 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(); + }); + }); }); });