Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Improved logging mechanism for operations on ended spans, making it easier to trace issues in both Node.js and Browser environments #5113 #5184

Open
wants to merge 7 commits into
base: main
Choose a base branch
from
Open

Improved logging mechanism for operations on ended spans, making it easier to trace issues in both Node.js and Browser environments #5113 #5184

Show file tree
Hide file tree
Changes from 4 commits
Commits
Show all changes
7 commits
Select commit Hold shift + click to select a range
8a71fbb
feat(sdk-trace-base): improved logging mechanism for operations on en…
Victorsesan Nov 17, 2024
64fa408
feat(sdk-trace-base): improved logging mechanism for operations on en…
Victorsesan Nov 20, 2024
faa7b9f
Merge branch 'main' into main
Victorsesan Nov 20, 2024
67228f3
Merge branch 'main' into main
Victorsesan Nov 20, 2024
70c4547
feat(sdk-trace-base): improved logging mechanism for operations on en…
Victorsesan Dec 3, 2024
7e52271
Merge branch 'main' of https://github.com/Victorsesan/opentelemetry-js
Victorsesan Dec 3, 2024
d855356
Merge branch 'open-telemetry:main' into main
Victorsesan Dec 3, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
4 changes: 3 additions & 1 deletion packages/opentelemetry-sdk-trace-base/src/Span.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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}`);
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Using just the stack trace string leads to dev tools not being able to apply custom formatting it does to error object - most notably the ability to jump to source code, which becomes inconsistent

// Test 1
console.log(`stack test - inline - ${new Error().stack}`);

// Test 2
console.log('stack test - arg2', new Error().stack);

// Test 3
console.log('stack test - error obj', new Error());

In chrome, the experience is okay as chrome auto-linkifys links
image

... as long as you don't expect to use sourcemaps - you just get lead into the built file instead of the source
image
image

(realistically at otel bundle size, yeah I'll take sourcemaps thanks)

while firefox doesn't touch non-error objects
image

But it's also an issue when debugging node over --inspect, chrome tries it's best to find some links but only the Error object version is correct:

node --inspect-brk .\logger_test.js

image

(at this point it's also worth considering if it's better to change issue requirements to just change into .warn(message, Error) as diag api allows 2nd+ argument to be unknown)

}
return this._ended;
}
Expand Down
26 changes: 26 additions & 0 deletions packages/opentelemetry-sdk-trace-base/test/common/Span.test.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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', () => {
Expand Down