diff --git a/packages/browser/src/integrations/breadcrumbs.ts b/packages/browser/src/integrations/breadcrumbs.ts index d9e149ae4a0d..474432fedb48 100644 --- a/packages/browser/src/integrations/breadcrumbs.ts +++ b/packages/browser/src/integrations/breadcrumbs.ts @@ -1,4 +1,3 @@ -/* eslint-disable max-lines */ import { addBreadcrumb, defineIntegration, getClient } from '@sentry/core'; import type { Client, diff --git a/packages/core/src/tracing/idleSpan.ts b/packages/core/src/tracing/idleSpan.ts index 8dc61426f6dd..0a1a279f7b5c 100644 --- a/packages/core/src/tracing/idleSpan.ts +++ b/packages/core/src/tracing/idleSpan.ts @@ -196,8 +196,6 @@ export function startIdleSpan(startSpanOptions: StartSpanOptions, options: Parti function _pushActivity(spanId: string): void { _cancelIdleTimeout(); activities.set(spanId, true); - DEBUG_BUILD && logger.log(`[Tracing] pushActivity: ${spanId}`); - DEBUG_BUILD && logger.log('[Tracing] new activities count', activities.size); const endTimestamp = timestampInSeconds(); // We need to add the timeout here to have the real endtimestamp of the idle span @@ -211,9 +209,7 @@ export function startIdleSpan(startSpanOptions: StartSpanOptions, options: Parti */ function _popActivity(spanId: string): void { if (activities.has(spanId)) { - DEBUG_BUILD && logger.log(`[Tracing] popActivity ${spanId}`); activities.delete(spanId); - DEBUG_BUILD && logger.log('[Tracing] new activities count', activities.size); } if (activities.size === 0) { @@ -248,8 +244,7 @@ export function startIdleSpan(startSpanOptions: StartSpanOptions, options: Parti span.setAttribute(SEMANTIC_ATTRIBUTE_SENTRY_IDLE_SPAN_FINISH_REASON, _finishReason); } - DEBUG_BUILD && - logger.log('[Tracing] finishing idle span', new Date(endTimestamp * 1000).toISOString(), spanJSON.op); + logger.log(`[Tracing] Idle span "${spanJSON.op}" finished`); const childSpans = getSpanDescendants(span).filter(child => child !== span); @@ -259,7 +254,7 @@ export function startIdleSpan(startSpanOptions: StartSpanOptions, options: Parti childSpan.setStatus({ code: SPAN_STATUS_ERROR, message: 'cancelled' }); childSpan.end(endTimestamp); DEBUG_BUILD && - logger.log('[Tracing] cancelling span since span ended early', JSON.stringify(childSpan, undefined, 2)); + logger.log('[Tracing] Cancelling span since span ended early', JSON.stringify(childSpan, undefined, 2)); } const childSpanJSON = spanToJSON(childSpan); @@ -274,9 +269,9 @@ export function startIdleSpan(startSpanOptions: StartSpanOptions, options: Parti if (DEBUG_BUILD) { const stringifiedSpan = JSON.stringify(childSpan, undefined, 2); if (!spanStartedBeforeIdleSpanEnd) { - logger.log('[Tracing] discarding Span since it happened after idle span was finished', stringifiedSpan); + logger.log('[Tracing] Discarding span since it happened after idle span was finished', stringifiedSpan); } else if (!spanEndedBeforeFinalTimeout) { - logger.log('[Tracing] discarding Span since it finished after idle span final timeout', stringifiedSpan); + logger.log('[Tracing] Discarding span since it finished after idle span final timeout', stringifiedSpan); } } @@ -284,8 +279,6 @@ export function startIdleSpan(startSpanOptions: StartSpanOptions, options: Parti removeChildSpanFromSpan(span, childSpan); } }); - - DEBUG_BUILD && logger.log('[Tracing] flushing idle span'); } client.on('spanStart', startedSpan => { @@ -349,7 +342,7 @@ function _startIdleSpan(options: StartSpanOptions): Span { _setSpanForScope(getCurrentScope(), span); - DEBUG_BUILD && logger.log(`Setting idle span on scope. Span ID: ${span.spanContext().spanId}`); + DEBUG_BUILD && logger.log('[Tracing] Started span is an idle span'); return span; } diff --git a/packages/core/src/tracing/index.ts b/packages/core/src/tracing/index.ts index 49052bda6371..979fe1f702f3 100644 --- a/packages/core/src/tracing/index.ts +++ b/packages/core/src/tracing/index.ts @@ -18,3 +18,4 @@ export { export { getDynamicSamplingContextFromClient, getDynamicSamplingContextFromSpan } from './dynamicSamplingContext'; export { setMeasurement } from './measurement'; export { sampleSpan } from './sampling'; +export { logSpanEnd, logSpanStart } from './logSpans'; diff --git a/packages/core/src/tracing/logSpans.ts b/packages/core/src/tracing/logSpans.ts new file mode 100644 index 000000000000..11a83c6b7a41 --- /dev/null +++ b/packages/core/src/tracing/logSpans.ts @@ -0,0 +1,55 @@ +import type { Span } from '@sentry/types'; +import { logger } from '@sentry/utils'; +import { DEBUG_BUILD } from '../debug-build'; +import { getRootSpan, spanIsSampled, spanToJSON } from '../utils/spanUtils'; + +/** + * Print a log message for a started span. + */ +export function logSpanStart(span: Span): void { + if (!DEBUG_BUILD) return; + + const { description = '< unknown name >', op = '< unknown op >', parent_span_id: parentSpanId } = spanToJSON(span); + const { spanId } = span.spanContext(); + + const sampled = spanIsSampled(span); + const rootSpan = getRootSpan(span); + const isRootSpan = rootSpan === span; + + const header = `[Tracing] Starting ${sampled ? 'sampled' : 'unsampled'} ${isRootSpan ? 'root ' : ''}span`; + + const infoParts: string[] = [`op: ${op}`, `name: ${description}`, `ID: ${spanId}`]; + + if (parentSpanId) { + infoParts.push(`parent ID: ${parentSpanId}`); + } + + if (!isRootSpan) { + const { op, description } = spanToJSON(rootSpan); + infoParts.push(`root ID: ${rootSpan.spanContext().spanId}`); + if (op) { + infoParts.push(`root op: ${op}`); + } + if (description) { + infoParts.push(`root description: ${description}`); + } + } + + logger.log(`${header} + ${infoParts.join('\n ')}`); +} + +/** + * Print a log message for an ended span. + */ +export function logSpanEnd(span: Span): void { + if (!DEBUG_BUILD) return; + + const { description = '< unknown name >', op = '< unknown op >' } = spanToJSON(span); + const { spanId } = span.spanContext(); + const rootSpan = getRootSpan(span); + const isRootSpan = rootSpan === span; + + const msg = `[Tracing] Finishing "${op}" ${isRootSpan ? 'root ' : ''}span "${description}" with ID ${spanId}`; + logger.log(msg); +} diff --git a/packages/core/src/tracing/sentrySpan.ts b/packages/core/src/tracing/sentrySpan.ts index fc7e871df53f..20a40f7e7233 100644 --- a/packages/core/src/tracing/sentrySpan.ts +++ b/packages/core/src/tracing/sentrySpan.ts @@ -9,21 +9,13 @@ import type { SpanStatus, SpanTimeInput, } from '@sentry/types'; -import { dropUndefinedKeys, logger, timestampInSeconds, uuid4 } from '@sentry/utils'; +import { dropUndefinedKeys, timestampInSeconds, uuid4 } from '@sentry/utils'; import { getClient } from '../currentScopes'; -import { DEBUG_BUILD } from '../debug-build'; import { getMetricSummaryJsonForSpan } from '../metrics/metric-summary'; import { SEMANTIC_ATTRIBUTE_SENTRY_OP, SEMANTIC_ATTRIBUTE_SENTRY_ORIGIN } from '../semanticAttributes'; -import { - TRACE_FLAG_NONE, - TRACE_FLAG_SAMPLED, - addChildSpanToSpan, - getRootSpan, - getStatusMessage, - spanTimeInputToSeconds, - spanToJSON, -} from '../utils/spanUtils'; +import { TRACE_FLAG_NONE, TRACE_FLAG_SAMPLED, getStatusMessage, spanTimeInputToSeconds } from '../utils/spanUtils'; +import { logSpanEnd } from './logSpans'; /** * Span contains all data about a span @@ -42,8 +34,6 @@ export class SentrySpan implements Span { /** Internal keeper of the status */ protected _status?: SpanStatus; - private _logMessage?: string; - /** * You should never call the constructor manually, always use `Sentry.startSpan()` * or other span methods. @@ -87,54 +77,6 @@ export class SentrySpan implements Span { }; } - /** - * Creates a new `Span` while setting the current `Span.id` as `parentSpanId`. - * Also the `sampled` decision will be inherited. - * - * @deprecated Use `startSpan()`, `startSpanManual()` or `startInactiveSpan()` instead. - */ - public startChild( - spanContext: Pick< - SentrySpanArguments, - Exclude - > = {}, - ): Span { - const childSpan = new SentrySpan({ - ...spanContext, - parentSpanId: this._spanId, - sampled: this._sampled, - traceId: this._traceId, - }); - - // To allow for interoperability we track the children of a span twice: Once with the span recorder (old) once with - // the `addChildSpanToSpan`. Eventually we will only use `addChildSpanToSpan` and drop the span recorder. - // To ensure interoperability with the `startSpan` API, `addChildSpanToSpan` is also called here. - addChildSpanToSpan(this, childSpan); - - const rootSpan = getRootSpan(this); - - if (DEBUG_BUILD && rootSpan) { - const opStr = (spanContext && spanContext.op) || '< unknown op >'; - const nameStr = spanToJSON(childSpan).description || '< unknown name >'; - const idStr = rootSpan.spanContext().spanId; - - const logMessage = `[Tracing] Starting '${opStr}' span on transaction '${nameStr}' (${idStr}).`; - logger.log(logMessage); - this._logMessage = logMessage; - } - - const client = getClient(); - if (client) { - client.emit('spanStart', childSpan); - // If it has an endTimestamp, it's already ended - if (spanContext.endTimestamp) { - client.emit('spanEnd', childSpan); - } - } - - return childSpan; - } - /** @inheritdoc */ public setAttribute(key: string, value: SpanAttributeValue | undefined): void { if (value === undefined) { @@ -184,20 +126,9 @@ export class SentrySpan implements Span { if (this._endTime) { return; } - const rootSpan = getRootSpan(this); - if ( - DEBUG_BUILD && - // Don't call this for transactions - rootSpan && - rootSpan.spanContext().spanId !== this._spanId - ) { - const logMessage = this._logMessage; - if (logMessage) { - logger.log((logMessage as string).replace('Starting', 'Finishing')); - } - } this._endTime = spanTimeInputToSeconds(endTimestamp); + logSpanEnd(this); this._onSpanEnded(); } diff --git a/packages/core/src/tracing/trace.ts b/packages/core/src/tracing/trace.ts index 94b1a80c31a4..a364a6584c06 100644 --- a/packages/core/src/tracing/trace.ts +++ b/packages/core/src/tracing/trace.ts @@ -1,4 +1,12 @@ -import type { ClientOptions, Scope, Span, SpanTimeInput, StartSpanOptions, TransactionArguments } from '@sentry/types'; +import type { + ClientOptions, + Scope, + SentrySpanArguments, + Span, + SpanTimeInput, + StartSpanOptions, + TransactionArguments, +} from '@sentry/types'; import { propagationContextFromHeaders } from '@sentry/utils'; import type { AsyncContextStrategy } from '../asyncContext'; @@ -18,9 +26,10 @@ import { spanToJSON, } from '../utils/spanUtils'; import { getDynamicSamplingContextFromSpan } from './dynamicSamplingContext'; +import { logSpanStart } from './logSpans'; import { sampleSpan } from './sampling'; import { SentryNonRecordingSpan } from './sentryNonRecordingSpan'; -import type { SentrySpan } from './sentrySpan'; +import { SentrySpan } from './sentrySpan'; import { SPAN_STATUS_ERROR } from './spanstatus'; import { Transaction } from './transaction'; import { setCapturedScopesOnSpan } from './utils'; @@ -223,8 +232,7 @@ function createChildSpanOrTransaction({ let span: Span; if (parentSpan && !forceTransaction) { - // eslint-disable-next-line deprecation/deprecation - span = parentSpan.startChild(spanContext); + span = _startChild(parentSpan, spanContext); addChildSpanToSpan(parentSpan, span); } else if (parentSpan) { // If we forced a transaction but have a parent span, make sure to continue from the parent span, not the scope @@ -262,6 +270,8 @@ function createChildSpanOrTransaction({ }); } + logSpanStart(span); + // TODO v8: Technically `startTransaction` can return undefined, which is not reflected by the types // This happens if tracing extensions have not been added // In this case, we just want to return a non-recording span @@ -321,3 +331,32 @@ function _startTransaction(transactionContext: TransactionArguments): Transactio return transaction; } + +/** + * Creates a new `Span` while setting the current `Span.id` as `parentSpanId`. + * This inherits the sampling decision from the parent span. + */ +function _startChild(parentSpan: Span, spanContext: SentrySpanArguments): SentrySpan { + const { spanId, traceId } = parentSpan.spanContext(); + const sampled = spanIsSampled(parentSpan); + + const childSpan = new SentrySpan({ + ...spanContext, + parentSpanId: spanId, + traceId, + sampled, + }); + + addChildSpanToSpan(parentSpan, childSpan); + + const client = getClient(); + if (client) { + client.emit('spanStart', childSpan); + // If it has an endTimestamp, it's already ended + if (spanContext.endTimestamp) { + client.emit('spanEnd', childSpan); + } + } + + return childSpan; +} diff --git a/packages/core/src/tracing/transaction.ts b/packages/core/src/tracing/transaction.ts index 4f943c856f86..88029db68beb 100644 --- a/packages/core/src/tracing/transaction.ts +++ b/packages/core/src/tracing/transaction.ts @@ -241,7 +241,6 @@ export class Transaction extends SentrySpan implements TransactionInterface { transaction.measurements = this._measurements; } - DEBUG_BUILD && logger.log(`[Tracing] Finishing ${spanToJSON(this).op} transaction: ${this._name}.`); return transaction; } } diff --git a/packages/core/test/lib/tracing/sentrySpan.test.ts b/packages/core/test/lib/tracing/sentrySpan.test.ts index cedf1d216eff..6ed12488000c 100644 --- a/packages/core/test/lib/tracing/sentrySpan.test.ts +++ b/packages/core/test/lib/tracing/sentrySpan.test.ts @@ -1,13 +1,7 @@ import { timestampInSeconds } from '@sentry/utils'; import { SentrySpan } from '../../../src/tracing/sentrySpan'; import { SPAN_STATUS_ERROR } from '../../../src/tracing/spanstatus'; -import { - TRACE_FLAG_NONE, - TRACE_FLAG_SAMPLED, - spanIsSampled, - spanToJSON, - spanToTraceContext, -} from '../../../src/utils/spanUtils'; +import { TRACE_FLAG_NONE, TRACE_FLAG_SAMPLED, spanToJSON, spanToTraceContext } from '../../../src/utils/spanUtils'; describe('SentrySpan', () => { describe('name', () => { @@ -26,17 +20,6 @@ describe('SentrySpan', () => { }); }); - describe('new SentrySpan', () => { - test('simple', () => { - const span = new SentrySpan({ sampled: true }); - // eslint-disable-next-line deprecation/deprecation - const span2 = span.startChild(); - expect(spanToJSON(span2).parent_span_id).toBe(span.spanContext().spanId); - expect(span.spanContext().traceId).toBe(span.spanContext().traceId); - expect(spanIsSampled(span2)).toBe(spanIsSampled(span)); - }); - }); - describe('setters', () => { test('setName', () => { const span = new SentrySpan({}); diff --git a/packages/core/test/lib/utils/spanUtils.test.ts b/packages/core/test/lib/utils/spanUtils.test.ts index cb36e701cf33..9020a6e59229 100644 --- a/packages/core/test/lib/utils/spanUtils.test.ts +++ b/packages/core/test/lib/utils/spanUtils.test.ts @@ -7,7 +7,6 @@ import { SPAN_STATUS_OK, SPAN_STATUS_UNSET, SentrySpan, - Transaction, addTracingExtensions, setCurrentClient, spanToTraceHeader, @@ -247,15 +246,4 @@ describe('getRootSpan', () => { }); }); }); - - it('returns the root span of a legacy transaction & its children', () => { - // eslint-disable-next-line deprecation/deprecation - const root = new Transaction({ name: 'test' }); - - expect(getRootSpan(root)).toBe(root); - - // eslint-disable-next-line deprecation/deprecation - const childSpan = root.startChild({ name: 'child' }); - expect(getRootSpan(childSpan)).toBe(root); - }); }); diff --git a/packages/opentelemetry/src/spanProcessor.ts b/packages/opentelemetry/src/spanProcessor.ts index a873faaa52d1..740afc2cc6fa 100644 --- a/packages/opentelemetry/src/spanProcessor.ts +++ b/packages/opentelemetry/src/spanProcessor.ts @@ -1,10 +1,14 @@ import type { Context } from '@opentelemetry/api'; -import { ROOT_CONTEXT, TraceFlags, trace } from '@opentelemetry/api'; +import { ROOT_CONTEXT, 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'; - -import { DEBUG_BUILD } from './debug-build'; +import { + addChildSpanToSpan, + getClient, + getDefaultCurrentScope, + getDefaultIsolationScope, + logSpanEnd, + logSpanStart, +} from '@sentry/core'; import { SEMANTIC_ATTRIBUTE_SENTRY_PARENT_IS_REMOTE } from './semanticAttributes'; import { SentrySpanExporter } from './spanExporter'; import { getScopesFromContext } from './utils/contextData'; @@ -41,13 +45,17 @@ function onSpanStart(span: Span, parentContext: Context): void { setSpanScopes(span, scopes); } + logSpanStart(span); + const client = getClient(); client?.emit('spanStart', span); } -function onSpanEnd(span: ReadableSpan): void { +function onSpanEnd(span: Span): void { + logSpanEnd(span); + const client = getClient(); - client?.emit('spanEnd', span as Span); + client?.emit('spanEnd', span); } /** @@ -81,22 +89,10 @@ export class SentrySpanProcessor implements SpanProcessorInterface { */ public onStart(span: Span, parentContext: Context): void { onSpanStart(span, parentContext); - - // TODO (v8): Trigger client `spanStart` & `spanEnd` in here, - // once we decoupled opentelemetry from SentrySpan - - DEBUG_BUILD && logger.log(`[Tracing] Starting span "${span.name}" (${span.spanContext().spanId})`); } /** @inheritDoc */ - 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; - } - - DEBUG_BUILD && logger.log(`[Tracing] Finishing span "${span.name}" (${span.spanContext().spanId})`); - + public onEnd(span: Span & ReadableSpan): void { onSpanEnd(span); this._exporter.export(span); diff --git a/packages/sveltekit/test/client/browserTracingIntegration.test.ts b/packages/sveltekit/test/client/browserTracingIntegration.test.ts index 1075d21f3b86..315985433e66 100644 --- a/packages/sveltekit/test/client/browserTracingIntegration.test.ts +++ b/packages/sveltekit/test/client/browserTracingIntegration.test.ts @@ -40,9 +40,6 @@ describe('browserTracingIntegration', () => { ...txnCtx, updateName: vi.fn(), setAttribute: vi.fn(), - startChild: vi.fn().mockImplementation(ctx => { - return { ...mockedRoutingSpan, ...ctx }; - }), setTag: vi.fn(), }; return createdRootSpan; diff --git a/packages/tracing-internal/src/browser/browserTracingIntegration.ts b/packages/tracing-internal/src/browser/browserTracingIntegration.ts index 42fc68fcaabf..2415e5b0b734 100644 --- a/packages/tracing-internal/src/browser/browserTracingIntegration.ts +++ b/packages/tracing-internal/src/browser/browserTracingIntegration.ts @@ -191,8 +191,6 @@ export const browserTracingIntegration = ((_options: Partial): void; - - /** - * Creates a new `Span` while setting the current `Span.id` as `parentSpanId`. - * Also the `sampled` decision will be inherited. - * - * @deprecated Use `startSpan()`, `startSpanManual()` or `startInactiveSpan()` instead. - */ - startChild( - spanContext?: Pick>, - ): Span; } /**