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