ref(tracing): Remove span.startChild()

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

Author: mydea

packages/angular/src/sdk.ts

@@ -12,6 +12,7 @@ import {
   dedupeIntegration,
   functionToStringIntegration,
   inboundFiltersIntegration,
+  spanLoggerIntegration,
 } from '@sentry/core';
 import type { Integration } from '@sentry/types';
 import { logger } from '@sentry/utils';
@@ -30,7 +31,7 @@ export function getDefaultIntegrations(): Integration[] {
   // see:
   //  - https://github.com/getsentry/sentry-javascript/issues/5417#issuecomment-1453407097
   //  - https://github.com/getsentry/sentry-javascript/issues/2744
-  return [
+  const integrations: Integration[] = [
     inboundFiltersIntegration(),
     functionToStringIntegration(),
     breadcrumbsIntegration(),
@@ -39,6 +40,12 @@ export function getDefaultIntegrations(): Integration[] {
     dedupeIntegration(),
     httpContextIntegration(),
   ];
+
+  if (IS_DEBUG_BUILD) {
+    integrations.push(spanLoggerIntegration());
+  }
+
+  return integrations;
 }
 
 /**

packages/aws-serverless/src/index.ts

@@ -99,6 +99,7 @@ export {
   extraErrorDataIntegration,
   rewriteFramesIntegration,
   sessionTimingIntegration,
+  spanLoggerIntegration,
 } from '@sentry/core';
 
 export { getDefaultIntegrations, init, tryPatchHandler, wrapHandler } from './awslambda';

packages/browser/src/index.ts

@@ -10,6 +10,7 @@ export {
   extraErrorDataIntegration,
   rewriteFramesIntegration,
   sessionTimingIntegration,
+  spanLoggerIntegration,
 } from '@sentry/core';
 
 export {

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/browser/src/sdk.ts

@@ -1,4 +1,4 @@
-import { getCurrentScope } from '@sentry/core';
+import { getCurrentScope, spanLoggerIntegration } from '@sentry/core';
 import { functionToStringIntegration, inboundFiltersIntegration } from '@sentry/core';
 import {
   captureSession,
@@ -36,7 +36,7 @@ export function getDefaultIntegrations(_options: Options): Integration[] {
    * Note: Please make sure this stays in sync with Angular SDK, which re-exports
    * `getDefaultIntegrations` but with an adjusted set of integrations.
    */
-  return [
+  const integrations: Integration[] = [
     inboundFiltersIntegration(),
     functionToStringIntegration(),
     browserApiErrorsIntegration(),
@@ -46,6 +46,12 @@ export function getDefaultIntegrations(_options: Options): Integration[] {
     dedupeIntegration(),
     httpContextIntegration(),
   ];
+
+  if (DEBUG_BUILD) {
+    integrations.push(spanLoggerIntegration());
+  }
+
+  return integrations;
 }
 
 function applyDefaultOptions(optionsArg: BrowserOptions = {}): BrowserOptions {

packages/bun/src/index.ts

@@ -120,6 +120,7 @@ export {
   extraErrorDataIntegration,
   rewriteFramesIntegration,
   sessionTimingIntegration,
+  spanLoggerIntegration,
 } from '@sentry/core';
 
 export type { BunOptions } from './types';

packages/bun/src/sdk.ts

@@ -3,6 +3,7 @@ import {
   inboundFiltersIntegration,
   linkedErrorsIntegration,
   requestDataIntegration,
+  spanLoggerIntegration,
 } from '@sentry/core';
 import {
   consoleIntegration,
@@ -29,6 +30,7 @@ export function getDefaultIntegrations(_options: Options): Integration[] {
     functionToStringIntegration(),
     linkedErrorsIntegration(),
     requestDataIntegration(),
+    spanLoggerIntegration(),
     // Native Wrappers
     consoleIntegration(),
     httpIntegration(),

packages/core/src/index.ts

@@ -99,6 +99,7 @@ export { dedupeIntegration } from './integrations/dedupe';
 export { extraErrorDataIntegration } from './integrations/extraerrordata';
 export { rewriteFramesIntegration } from './integrations/rewriteframes';
 export { sessionTimingIntegration } from './integrations/sessiontiming';
+export { spanLoggerIntegration } from './integrations/spanlogger';
 export { metrics } from './metrics/exports';
 export type { MetricData } from './metrics/exports';
 export { metricsDefault } from './metrics/exports-default';

packages/core/src/integrations/spanlogger.ts

@@ -0,0 +1,65 @@
+import type { IntegrationFn } from '@sentry/types';
+import { logger } from '@sentry/utils';
+import { DEBUG_BUILD } from '../debug-build';
+import { defineIntegration } from '../integration';
+import { getRootSpan, spanIsSampled, spanToJSON } from '../utils/spanUtils';
+
+const _spanLoggerIntegration = (() => {
+  return {
+    name: 'SpanLogger',
+    setup(client) {
+      if (!DEBUG_BUILD) return;
+
+      client.on('spanStart', span => {
+        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  ')}`);
+      });
+
+      client.on('spanEnd', span => {
+        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);
+      });
+    },
+  };
+}) satisfies IntegrationFn;
+
+/**
+ * Log span information to the debugger.
+ * This will not do anything if DEUBG_BUILD is disabled.
+ */
+export const spanLoggerIntegration = defineIntegration(_spanLoggerIntegration);

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/sentrySpan.ts

@@ -11,20 +11,16 @@ import type {
   TraceContext,
   Transaction,
 } 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,
   spanToTraceContext,
 } from '../utils/spanUtils';
 
@@ -50,8 +46,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.
@@ -132,58 +126,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);
-    // TODO: still set span.transaction here until we have a more permanent solution
-    // Probably similarly to the weakmap we hold in node
-    // eslint-disable-next-line deprecation/deprecation
-    childSpan.transaction = rootSpan as Transaction;
-
-    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) {
@@ -233,18 +175,6 @@ 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);