ref(tracing): Remove span.startChild() (#11376)

Also refactor the span logging behavior into a logging integration, to
make this consistent between core & otel-powered spans.

Author: mydea

packages/browser/src/integrations/breadcrumbs.ts

@@ -1,4 +1,3 @@
-/* eslint-disable max-lines */
 import { addBreadcrumb, defineIntegration, getClient } from '@sentry/core';
 import type {
   Client,

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,18 +269,16 @@ 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);
         }
       }
 
       if (!spanEndedBeforeFinalTimeout || !spanStartedBeforeIdleSpanEnd) {
         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;
 }

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';

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);
+}

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<keyof SentrySpanArguments, 'sampled' | 'traceId' | 'parentSpanId'>
-    > = {},
-  ): 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();
   }

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;
+}

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;
   }
 }

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({});

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);
-  });
 });