From 8a71fbbe866088a3a027cbc6191b8a4083da2a07 Mon Sep 17 00:00:00 2001 From: Victor Date: Sun, 17 Nov 2024 02:34:04 +0100 Subject: [PATCH 1/3] feat(sdk-trace-base): improved logging mechanism for operations on ended spans, making it easier to trace issues in both Node.js and Browser environments Reviewer: pichlermarc Refs: #5113 --- package.json | 30 +++++++++---------- .../opentelemetry-sdk-trace-base/src/Span.ts | 4 ++- .../test/common/Span.test.ts | 26 ++++++++++++++++ 3 files changed, 44 insertions(+), 16 deletions(-) diff --git a/package.json b/package.json index dc11f3e0d25..17c2ce279d1 100644 --- a/package.json +++ b/package.json @@ -85,34 +85,34 @@ "author": "OpenTelemetry Authors", "license": "Apache-2.0", "devDependencies": { - "@typescript-eslint/eslint-plugin": "5.59.11", - "@typescript-eslint/parser": "5.59.11", + "@typescript-eslint/eslint-plugin": "8.14.0", + "@typescript-eslint/parser": "8.14.0", "assert": "2.1.0", "benchmark": "2.1.4", - "eslint": "8.44.0", - "eslint-config-prettier": "9.0.0", + "eslint": "9.15.0", + "eslint-config-prettier": "9.1.0", "eslint-plugin-header": "3.1.1", "eslint-plugin-node": "11.1.0", - "eslint-plugin-prettier": "5.0.1", - "gh-pages": "6.0.0", + "eslint-plugin-prettier": "5.2.1", + "gh-pages": "6.2.0", "glob": "^11.0.0", "karma": "6.4.4", - "karma-chrome-launcher": "3.1.0", + "karma-chrome-launcher": "3.2.0", "karma-coverage": "2.2.1", "karma-mocha": "2.0.1", "karma-mocha-webworker": "1.3.0", "karma-spec-reporter": "0.0.36", "karma-webpack": "5.0.1", - "lerna": "6.6.2", - "linkinator": "6.0.6", - "markdownlint-cli2": "0.13.0", - "prettier": "3.0.3", + "lerna": "8.1.9", + "linkinator": "6.1.2", + "markdownlint-cli2": "0.15.0", + "prettier": "3.3.3", "process": "0.11.10", "semver": "7.6.3", - "typedoc": "0.22.18", - "typedoc-plugin-missing-exports": "1.0.0", - "typedoc-plugin-resolve-crossmodule-references": "0.2.2", - "typescript": "4.4.4", + "typedoc": "0.26.11", + "typedoc-plugin-missing-exports": "3.0.2", + "typedoc-plugin-resolve-crossmodule-references": "0.3.3", + "typescript": "5.6.3", "util": "0.12.5" }, "changelog": { diff --git a/packages/opentelemetry-sdk-trace-base/src/Span.ts b/packages/opentelemetry-sdk-trace-base/src/Span.ts index b5f3b75b4b5..91156732640 100644 --- a/packages/opentelemetry-sdk-trace-base/src/Span.ts +++ b/packages/opentelemetry-sdk-trace-base/src/Span.ts @@ -364,8 +364,10 @@ export class Span implements APISpan, ReadableSpan { private _isSpanEnded(): boolean { if (this._ended) { diag.warn( - `Can not execute the operation on ended Span {traceId: ${this._spanContext.traceId}, spanId: ${this._spanContext.spanId}}` + `Cannot execute the operation on ended Span {traceId: ${this._spanContext.traceId}, spanId: ${this._spanContext.spanId}}. Change log level to debug for stack trace.` ); + // Adding a debug log to capture the stack trace + diag.debug(`Stack trace for ended span operation: ${new Error().stack}`); } return this._ended; } diff --git a/packages/opentelemetry-sdk-trace-base/test/common/Span.test.ts b/packages/opentelemetry-sdk-trace-base/test/common/Span.test.ts index ef06a1d884f..b555d5ac4b7 100644 --- a/packages/opentelemetry-sdk-trace-base/test/common/Span.test.ts +++ b/packages/opentelemetry-sdk-trace-base/test/common/Span.test.ts @@ -250,6 +250,32 @@ describe('Span', () => { assert.ok(span.isRecording() === false); }); }); + it('should log a warning and a debug message when span is ended', () => { + const span = new Span( + tracer, + ROOT_CONTEXT, + name, + spanContext, + SpanKind.CLIENT + ); + span.end(); // End the span to set it to ended state + + const warnStub = sinon.spy(diag, 'warn'); + const debugStub = sinon.spy(diag, 'debug'); + + // Call the method that checks if the span is ended + span['_isSpanEnded'](); + + // Assert that the warning log was called with the expected message + sinon.assert.calledOnce(warnStub); + sinon.assert.calledWith(warnStub, sinon.match(/Cannot execute the operation on ended Span/)); + + // Assert that the debug log was called and contains a stack trace + sinon.assert.calledOnce(debugStub); + const debugMessage = debugStub.getCall(0).args[0]; + assert.ok(debugMessage.startsWith('Stack trace for ended span operation:')); + }); + }); describe('setAttribute', () => { describe('when default options set', () => { From 64fa40875b9b30e29b9ad9c6f2c9dfc30a076e98 Mon Sep 17 00:00:00 2001 From: Victor Date: Wed, 20 Nov 2024 14:34:07 +0100 Subject: [PATCH 2/3] feat(sdk-trace-base): improved logging mechanism for operations on ended spans, making it easier to trace issues in both Node.js and Browser environments Reviewer: pichlermarc Refs: #5113 --- package.json | 24 ++++++++++++------------ 1 file changed, 12 insertions(+), 12 deletions(-) diff --git a/package.json b/package.json index 17c2ce279d1..74deb674803 100644 --- a/package.json +++ b/package.json @@ -85,34 +85,34 @@ "author": "OpenTelemetry Authors", "license": "Apache-2.0", "devDependencies": { - "@typescript-eslint/eslint-plugin": "8.14.0", - "@typescript-eslint/parser": "8.14.0", + "@typescript-eslint/eslint-plugin": "5.59.11", + "@typescript-eslint/parser": "5.59.11", "assert": "2.1.0", "benchmark": "2.1.4", - "eslint": "9.15.0", - "eslint-config-prettier": "9.1.0", + "eslint": "8.44.0", + "eslint-config-prettier": "9.0.0", "eslint-plugin-header": "3.1.1", "eslint-plugin-node": "11.1.0", - "eslint-plugin-prettier": "5.2.1", + "eslint-plugin-prettier": "5.0.1", "gh-pages": "6.2.0", "glob": "^11.0.0", "karma": "6.4.4", - "karma-chrome-launcher": "3.2.0", + "karma-chrome-launcher": "3.1.0", "karma-coverage": "2.2.1", "karma-mocha": "2.0.1", "karma-mocha-webworker": "1.3.0", "karma-spec-reporter": "0.0.36", "karma-webpack": "5.0.1", - "lerna": "8.1.9", + "lerna": "6.6.2", "linkinator": "6.1.2", "markdownlint-cli2": "0.15.0", - "prettier": "3.3.3", + "prettier": "3.0.3", "process": "0.11.10", "semver": "7.6.3", - "typedoc": "0.26.11", - "typedoc-plugin-missing-exports": "3.0.2", - "typedoc-plugin-resolve-crossmodule-references": "0.3.3", - "typescript": "5.6.3", + "typedoc": "0.22.18", + "typedoc-plugin-missing-exports": "1.0.0", + "typedoc-plugin-resolve-crossmodule-references": "0.2.2", + "typescript": "4.4.4", "util": "0.12.5" }, "changelog": { From 70c45474bb5d704d5b26aaecb7feca8e6b22d0b4 Mon Sep 17 00:00:00 2001 From: Victor Date: Tue, 3 Dec 2024 01:59:26 +0100 Subject: [PATCH 3/3] feat(sdk-trace-base): improved logging mechanism for operations on ended spans, making it easier to trace issues in both Node.js and Browser environments Reviewer: pichlermarc Refs: #5113 --- .../opentelemetry-sdk-trace-base/src/Span.ts | 16 ++++++---- .../test/common/Span.test.ts | 32 +++++++++---------- 2 files changed, 26 insertions(+), 22 deletions(-) diff --git a/packages/opentelemetry-sdk-trace-base/src/Span.ts b/packages/opentelemetry-sdk-trace-base/src/Span.ts index 91156732640..f10516ab3c8 100644 --- a/packages/opentelemetry-sdk-trace-base/src/Span.ts +++ b/packages/opentelemetry-sdk-trace-base/src/Span.ts @@ -363,14 +363,18 @@ export class Span implements APISpan, ReadableSpan { private _isSpanEnded(): boolean { if (this._ended) { - diag.warn( - `Cannot execute the operation on ended Span {traceId: ${this._spanContext.traceId}, spanId: ${this._spanContext.spanId}}. Change log level to debug for stack trace.` - ); - // Adding a debug log to capture the stack trace - diag.debug(`Stack trace for ended span operation: ${new Error().stack}`); + const error = new Error(`Operation attempted on ended Span {traceId: ${this._spanContext.traceId}, spanId: ${this._spanContext.spanId}}`); + + diag.warn( + `Cannot execute the operation on ended Span {traceId: ${this._spanContext.traceId}, spanId: ${this._spanContext.spanId}}. Change log level to debug for stack trace.`, + error // Pass the error object as the second argument + ); + + // Optionally, you can still log the stack trace for additional context + diag.debug(`Stack trace for ended span operation: ${error.stack}`); } return this._ended; - } +} // Utility function to truncate given value within size // for value type of string, will truncate to given limit diff --git a/packages/opentelemetry-sdk-trace-base/test/common/Span.test.ts b/packages/opentelemetry-sdk-trace-base/test/common/Span.test.ts index b555d5ac4b7..7a236a65a09 100644 --- a/packages/opentelemetry-sdk-trace-base/test/common/Span.test.ts +++ b/packages/opentelemetry-sdk-trace-base/test/common/Span.test.ts @@ -250,27 +250,27 @@ describe('Span', () => { assert.ok(span.isRecording() === false); }); }); - it('should log a warning and a debug message when span is ended', () => { - const span = new Span( + it('should log a warning and a debug message when span is ended', () => { + const span = new Span( tracer, ROOT_CONTEXT, name, spanContext, SpanKind.CLIENT - ); - span.end(); // End the span to set it to ended state - - const warnStub = sinon.spy(diag, 'warn'); - const debugStub = sinon.spy(diag, 'debug'); - - // Call the method that checks if the span is ended - span['_isSpanEnded'](); - - // Assert that the warning log was called with the expected message - sinon.assert.calledOnce(warnStub); - sinon.assert.calledWith(warnStub, sinon.match(/Cannot execute the operation on ended Span/)); - - // Assert that the debug log was called and contains a stack trace + ); + span.end(); // End the span to set it to ended state + + const warnStub = sinon.spy(diag, 'warn'); + const debugStub = sinon.spy(diag, 'debug'); + + // Call the method that checks if the span is ended + span['_isSpanEnded'](); + + // Assert that the warning log was called with the expected message and an Error object + sinon.assert.calledOnce(warnStub); + sinon.assert.calledWith(warnStub, sinon.match(/Cannot execute the operation on ended Span/), sinon.match.instanceOf(Error)); + + // Assert that the debug log was called and contains a stack trace sinon.assert.calledOnce(debugStub); const debugMessage = debugStub.getCall(0).args[0]; assert.ok(debugMessage.startsWith('Stack trace for ended span operation:'));