Skip to content

feat(node): Simplify SentrySpanProcessor #11273

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.

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

Merged
merged 2 commits into from
Mar 26, 2024
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
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
Original file line number Diff line number Diff line change
Expand Up @@ -45,6 +45,11 @@ describe('hapi auto-instrumentation', () => {

test('CJS - should handle returned plain errors in routes.', done => {
createRunner(__dirname, 'scenario.js')
.expect({
transaction: {
transaction: 'GET /error',
},
})
.expect({ event: EXPECTED_ERROR_EVENT })
.expectError()
.start(done)
Expand All @@ -53,6 +58,11 @@ describe('hapi auto-instrumentation', () => {

test('CJS - should handle returned Boom errors in routes.', done => {
createRunner(__dirname, 'scenario.js')
.expect({
transaction: {
transaction: 'GET /boom-error',
},
})
.expect({ event: EXPECTED_ERROR_EVENT })
.expectError()
.start(done)
Expand All @@ -61,6 +71,11 @@ describe('hapi auto-instrumentation', () => {

test('CJS - should handle promise rejections in routes.', done => {
createRunner(__dirname, 'scenario.js')
.expect({
transaction: {
transaction: 'GET /promise-error',
},
})
.expect({ event: EXPECTED_ERROR_EVENT })
.expectError()
.start(done)
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -24,7 +24,7 @@ connection.connect(function (err) {
}
});

Sentry.startSpan(
Sentry.startSpanManual(
Copy link
Member Author

Choose a reason for hiding this comment

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

LOL, this test only passed "on accident" before (but this shows we are being more "strict" now than we used to).

{
op: 'transaction',
name: 'Test Transaction',
Expand Down
5 changes: 3 additions & 2 deletions packages/node-experimental/test/helpers/mockSdkInit.ts
Original file line number Diff line number Diff line change
@@ -1,6 +1,7 @@
import { ProxyTracerProvider, context, propagation, trace } from '@opentelemetry/api';
import { BasicTracerProvider } from '@opentelemetry/sdk-trace-base';
import { getCurrentScope, getGlobalScope, getIsolationScope } from '@sentry/core';
import { getClient, getCurrentScope, getGlobalScope, getIsolationScope } from '@sentry/core';
import type { NodeClient } from '../../src';

import { init } from '../../src/sdk/init';
import type { NodeClientOptions } from '../../src/types';
Expand Down Expand Up @@ -36,7 +37,7 @@ export function cleanupOtel(_provider?: BasicTracerProvider): void {
}

export function getProvider(_provider?: BasicTracerProvider): BasicTracerProvider | undefined {
let provider = _provider || trace.getTracerProvider();
let provider = _provider || getClient<NodeClient>()?.traceProvider || trace.getTracerProvider();

if (provider instanceof ProxyTracerProvider) {
provider = provider.getDelegate();
Expand Down
17 changes: 5 additions & 12 deletions packages/node-experimental/test/integration/transactions.test.ts
Original file line number Diff line number Diff line change
Expand Up @@ -614,7 +614,6 @@ describe('Integration | Transactions', () => {

mockSdkInit({ enableTracing: true, beforeSendTransaction });

const client = Sentry.getClient()!;
const provider = getProvider();
const multiSpanProcessor = provider?.activeSpanProcessor as
| (SpanProcessor & { _spanProcessors?: SpanProcessor[] })
Expand Down Expand Up @@ -645,24 +644,17 @@ describe('Integration | Transactions', () => {
await new Promise(resolve => setTimeout(resolve, 10 * 60 * 1000));
});

// Nothing added to exporter yet
expect(exporter['_finishedSpans'].length).toBe(0);

void client.flush(5_000);
jest.advanceTimersByTime(5_000);

// Now the child-spans have been added to the exporter, but they are pending since they are waiting for their parant
// Child-spans have been added to the exporter, but they are pending since they are waiting for their parant
expect(exporter['_finishedSpans'].length).toBe(2);
expect(beforeSendTransaction).toHaveBeenCalledTimes(0);

// Now wait for 5 mins
jest.advanceTimersByTime(5 * 60 * 1_000);
jest.advanceTimersByTime(5 * 60 * 1_000 + 1);

// Adding another span will trigger the cleanup
Sentry.startSpan({ name: 'other span' }, () => {});

void client.flush(5_000);
jest.advanceTimersByTime(5_000);
jest.advanceTimersByTime(1);

// Old spans have been cleared away
expect(exporter['_finishedSpans'].length).toBe(0);
Expand All @@ -672,7 +664,8 @@ describe('Integration | Transactions', () => {

expect(logs).toEqual(
expect.arrayContaining([
'SpanExporter exported 0 spans, 2 unsent spans remaining',
'SpanExporter has 1 unsent spans remaining',
'SpanExporter has 2 unsent spans remaining',
'SpanExporter exported 1 spans, 2 unsent spans remaining',
`SpanExporter dropping span inner span 1 (${innerSpan1Id}) because it is pending for more than 5 minutes.`,
`SpanExporter dropping span inner span 2 (${innerSpan2Id}) because it is pending for more than 5 minutes.`,
Expand Down
7 changes: 6 additions & 1 deletion packages/node-experimental/test/sdk/api.test.ts
Original file line number Diff line number Diff line change
@@ -1,3 +1,4 @@
import type { Event } from '@sentry/types';
import { getActiveSpan, getClient, startInactiveSpan, startSpan, withActiveSpan } from '../../src';
import { cleanupOtel, mockSdkInit } from '../helpers/mockSdkInit';

Expand Down Expand Up @@ -64,7 +65,11 @@ describe('withActiveSpan()', () => {
});

it('when `null` is passed, should start a new trace for new spans', async () => {
const beforeSendTransaction = jest.fn(() => null);
const transactions: Event[] = [];
const beforeSendTransaction = jest.fn((event: Event) => {
transactions.push(event);
Copy link
Member

Choose a reason for hiding this comment

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

l: why do we have transactions array here?

Copy link
Member Author

Choose a reason for hiding this comment

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

makes it a bit easier to test what is sent than to use hasBeenCalledWith, as you don't have to use objectContains() everywhere which gives weird diffs in jest for large objects 😬

return null;
});
mockSdkInit({ enableTracing: true, beforeSendTransaction });
const client = getClient();

Expand Down
92 changes: 56 additions & 36 deletions packages/opentelemetry/src/spanExporter.ts
Original file line number Diff line number Diff line change
@@ -1,8 +1,6 @@
import type { Span } from '@opentelemetry/api';
import { SpanKind } from '@opentelemetry/api';
import type { ExportResult } from '@opentelemetry/core';
import { ExportResultCode } from '@opentelemetry/core';
import type { ReadableSpan, SpanExporter } from '@opentelemetry/sdk-trace-base';
import type { ReadableSpan } from '@opentelemetry/sdk-trace-base';
import { SemanticAttributes } from '@opentelemetry/semantic-conventions';
import { captureEvent, getMetricSummaryJsonForSpan } from '@sentry/core';
import {
Expand All @@ -21,6 +19,7 @@ import { convertOtelTimeToSeconds } from './utils/convertOtelTimeToSeconds';
import { getDynamicSamplingContextFromSpan } from './utils/dynamicSamplingContext';
import { getRequestSpanData } from './utils/getRequestSpanData';
import type { SpanNode } from './utils/groupSpansWithParents';
import { getLocalParentId } from './utils/groupSpansWithParents';
import { groupSpansWithParents } from './utils/groupSpansWithParents';
import { mapStatus } from './utils/mapStatus';
import { parseSpanDescription } from './utils/parseSpanDescription';
Expand All @@ -31,38 +30,72 @@ type SpanNodeCompleted = SpanNode & { span: ReadableSpan };
/**
* A Sentry-specific exporter that converts OpenTelemetry Spans to Sentry Spans & Transactions.
*/
export class SentrySpanExporter implements SpanExporter {
export class SentrySpanExporter {
private _flushTimeout: ReturnType<typeof setTimeout> | undefined;
private _finishedSpans: ReadableSpan[];
private _stopped: boolean;

public constructor() {
this._stopped = false;
this._finishedSpans = [];
}

/** @inheritDoc */
public export(spans: ReadableSpan[], resultCallback: (result: ExportResult) => void): void {
if (this._stopped) {
return resultCallback({
code: ExportResultCode.FAILED,
error: new Error('Exporter has been stopped'),
});
/** Export a single span. */
public export(span: ReadableSpan): void {
this._finishedSpans.push(span);

// If the span has a local parent ID, we don't need to export anything just yet
if (getLocalParentId(span)) {
const openSpanCount = this._finishedSpans.length;
DEBUG_BUILD && logger.log(`SpanExporter has ${openSpanCount} unsent spans remaining`);
this._cleanupOldSpans();
return;
}

const openSpanCount = this._finishedSpans.length;
const newSpanCount = spans.length;
this._clearTimeout();

// If we got a parent span, we try to send the span tree
// Wait a tick for this, to ensure we avoid race conditions
this._flushTimeout = setTimeout(() => {
this.flush();
}, 1);
}

/** Try to flush any pending spans immediately. */
public flush(): void {
this._clearTimeout();

this._finishedSpans.push(...spans);
const openSpanCount = this._finishedSpans.length;

const remainingSpans = maybeSend(this._finishedSpans);

const remainingOpenSpanCount = remainingSpans.length;
const sentSpanCount = openSpanCount + newSpanCount - remainingOpenSpanCount;
const sentSpanCount = openSpanCount - remainingOpenSpanCount;

DEBUG_BUILD &&
logger.log(`SpanExporter exported ${sentSpanCount} spans, ${remainingOpenSpanCount} unsent spans remaining`);

this._finishedSpans = remainingSpans.filter(span => {
this._cleanupOldSpans(remainingSpans);
}

/** Clear the exporter. */
public clear(): void {
this._finishedSpans = [];
this._clearTimeout();
}

/** Clear the flush timeout. */
private _clearTimeout(): void {
if (this._flushTimeout) {
clearTimeout(this._flushTimeout);
this._flushTimeout = undefined;
}
}

/**
* Remove any span that is older than 5min.
* We do this to avoid leaking memory.
*/
private _cleanupOldSpans(spans = this._finishedSpans): void {
this._finishedSpans = spans.filter(span => {
const shouldDrop = shouldCleanupSpan(span, 5 * 60);
DEBUG_BUILD &&
shouldDrop &&
Expand All @@ -73,23 +106,6 @@ export class SentrySpanExporter implements SpanExporter {
);
return !shouldDrop;
});

resultCallback({ code: ExportResultCode.SUCCESS });
}

/** @inheritDoc */
public shutdown(): Promise<void> {
const forceFlush = this.forceFlush();
this._stopped = true;
this._finishedSpans = [];
return forceFlush;
}

/** @inheritDoc */
public forceFlush(): Promise<void> {
return new Promise(resolve => {
this.export(this._finishedSpans, () => resolve());
});
}
}

Expand Down Expand Up @@ -132,8 +148,12 @@ function maybeSend(spans: ReadableSpan[]): ReadableSpan[] {
.filter((span): span is ReadableSpan => !!span);
}

function nodeIsCompletedRootNode(node: SpanNode): node is SpanNodeCompleted {
return !!node.span && !node.parentNode;
}

function getCompletedRootNodes(nodes: SpanNode[]): SpanNodeCompleted[] {
return nodes.filter((node): node is SpanNodeCompleted => !!node.span && !node.parentNode);
return nodes.filter(nodeIsCompletedRootNode);
}

function shouldCleanupSpan(span: ReadableSpan, maxStartTimeOffsetSeconds: number): boolean {
Expand Down
52 changes: 28 additions & 24 deletions packages/opentelemetry/src/spanProcessor.ts
Original file line number Diff line number Diff line change
@@ -1,7 +1,6 @@
import type { Context } from '@opentelemetry/api';
import { ROOT_CONTEXT, trace } from '@opentelemetry/api';
import type { Span, SpanProcessor as SpanProcessorInterface } from '@opentelemetry/sdk-trace-base';
import { BatchSpanProcessor } from '@opentelemetry/sdk-trace-base';
import { ROOT_CONTEXT, TraceFlags, trace } from '@opentelemetry/api';
import type { ReadableSpan, Span, SpanProcessor as SpanProcessorInterface } from '@opentelemetry/sdk-trace-base';
import { addChildSpanToSpan, getClient, getDefaultCurrentScope, getDefaultIsolationScope } from '@sentry/core';
import { logger } from '@sentry/utils';

Expand Down Expand Up @@ -46,20 +45,35 @@ function onSpanStart(span: Span, parentContext: Context): void {
client?.emit('spanStart', span);
}

function onSpanEnd(span: Span): void {
function onSpanEnd(span: ReadableSpan): void {
const client = getClient();
client?.emit('spanEnd', span);
client?.emit('spanEnd', span as Span);
Copy link
Contributor

Choose a reason for hiding this comment

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

m: Is this safe? If so, why?

Copy link
Member Author

Choose a reason for hiding this comment

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

this is the same as it was before - this is safe because the actual trace code under the hood passes exactly the same class instance to onStart and onEnd, which satisifes the span interface. It's unfortunate, though, of course 😬

Copy link
Contributor

Choose a reason for hiding this comment

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

I do realize that it was like this before, but I now wonder whether we can depend on this. But nothing to duke out in this pr!

Copy link
Member Author

Choose a reason for hiding this comment

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

I checked the actual implementation in the tracer, and I think it's fine - not sure how we could be even safer here without checking the existence of each and every property we'd expect this to have 😬 which also feels overkill. But we can for sure revisit this!

}

/**
* Converts OpenTelemetry Spans to Sentry Spans and sends them to Sentry via
* the Sentry SDK.
*/
export class SentrySpanProcessor extends BatchSpanProcessor implements SpanProcessorInterface {
public constructor() {
super(new SentrySpanExporter());
export class SentrySpanProcessor implements SpanProcessorInterface {
private _exporter: SentrySpanExporter;

public constructor() {
setIsSetup('SentrySpanProcessor');
this._exporter = new SentrySpanExporter();
}

/**
* @inheritDoc
*/
public async forceFlush(): Promise<void> {
this._exporter.flush();
}

/**
* @inheritDoc
*/
public async shutdown(): Promise<void> {
this._exporter.clear();
}

/**
Expand All @@ -72,29 +86,19 @@ export class SentrySpanProcessor extends BatchSpanProcessor implements SpanProce
// once we decoupled opentelemetry from SentrySpan

DEBUG_BUILD && logger.log(`[Tracing] Starting span "${span.name}" (${span.spanContext().spanId})`);

return super.onStart(span, parentContext);
}

/** @inheritDoc */
public onEnd(span: Span): void {
DEBUG_BUILD && logger.log(`[Tracing] Finishing span "${span.name}" (${span.spanContext().spanId})`);

if (!this._shouldSendSpanToSentry(span)) {
// Prevent this being called to super.onEnd(), which would pass this to the span exporter
public onEnd(span: ReadableSpan): void {
if (span.spanContext().traceFlags !== TraceFlags.SAMPLED) {
DEBUG_BUILD && logger.log(`[Tracing] Finishing unsampled span "${span.name}" (${span.spanContext().spanId})`);
return;
}

onSpanEnd(span);
DEBUG_BUILD && logger.log(`[Tracing] Finishing span "${span.name}" (${span.spanContext().spanId})`);

return super.onEnd(span);
}
onSpanEnd(span);

/**
* You can overwrite this in a sub class to implement custom behavior for dropping spans.
* If you return `false` here, the span will not be passed to the exporter and thus not be sent.
*/
protected _shouldSendSpanToSentry(_span: Span): boolean {
return true;
this._exporter.export(span);
}
}
15 changes: 10 additions & 5 deletions packages/opentelemetry/src/utils/groupSpansWithParents.ts
Original file line number Diff line number Diff line change
Expand Up @@ -26,14 +26,19 @@ export function groupSpansWithParents(spans: ReadableSpan[]): SpanNode[] {
});
}

function createOrUpdateSpanNodeAndRefs(nodeMap: SpanMap, span: ReadableSpan): void {
/**
* This returns the _local_ parent ID - `parentId` on the span may point to a remote span.
*/
export function getLocalParentId(span: ReadableSpan): string | undefined {
const parentIsRemote = span.attributes[SEMANTIC_ATTRIBUTE_SENTRY_PARENT_IS_REMOTE] === true;

const id = span.spanContext().spanId;

// If the parentId is the trace parent ID, we pretend it's undefined
// As this means the parent exists somewhere else
const parentId = !parentIsRemote ? span.parentSpanId : undefined;
return !parentIsRemote ? span.parentSpanId : undefined;
}

function createOrUpdateSpanNodeAndRefs(nodeMap: SpanMap, span: ReadableSpan): void {
const id = span.spanContext().spanId;
const parentId = getLocalParentId(span);

if (!parentId) {
createOrUpdateNode(nodeMap, { id, span, children: [] });
Expand Down
Loading