log start and end of span

Author: lobsterkatie

packages/tracing/src/span.ts

@@ -1,6 +1,6 @@
 /* eslint-disable max-lines */
 import { Primitive, Span as SpanInterface, SpanContext, Transaction } from '@sentry/types';
-import { dropUndefinedKeys, timestampWithMs, uuid4 } from '@sentry/utils';
+import { dropUndefinedKeys, logger, timestampWithMs, uuid4 } from '@sentry/utils';
 
 /**
  * Keeps track of finished spans for a given transaction
@@ -169,6 +169,18 @@ export class Span implements SpanInterface {
 
     childSpan.transaction = this.transaction;
 
+    if (__DEBUG_BUILD__ && childSpan.transaction) {
+      const opStr = (spanContext && spanContext.op) || '< unknown op >';
+      const nameStr = childSpan.transaction.name || '< unknown name >';
+      const idStr = childSpan.transaction.spanId;
+
+      // TODO: It would be safer to shove this in metadata (would need to move `metadata` from the `Transaction` class
+      // to the `Span` class)
+      childSpan.data.__log_message__ = `[Tracing] Starting ${opStr} span on transaction ${nameStr} (${idStr}).`;
+
+      logger.log(childSpan.data.__log_message__);
+    }
+
     return childSpan;
   }
 
@@ -220,6 +232,17 @@ export class Span implements SpanInterface {
    * @inheritDoc
    */
   public finish(endTimestamp?: number): void {
+    if (
+      __DEBUG_BUILD__ &&
+      this.transaction &&
+      // We only want to log this for spans, not for transactions
+      this.transaction.spanId !== this.spanId &&
+      this.data.__log_message__
+    ) {
+      logger.log((this.data.__log_message__ as string).replace('Starting', 'Finishing'));
+      delete this.data.__log_message__;
+    }
+
     this.endTimestamp = typeof endTimestamp === 'number' ? endTimestamp : timestampWithMs();
   }
 

packages/tracing/test/browser/request.test.ts

@@ -134,11 +134,13 @@ describe('callbacks', () => {
 
       expect(newSpan).toBeDefined();
       expect(newSpan).toBeInstanceOf(Span);
-      expect(newSpan.data).toEqual({
-        method: 'GET',
-        type: 'fetch',
-        url: 'http://dogs.are.great/',
-      });
+      expect(newSpan.data).toEqual(
+        expect.objectContaining({
+          method: 'GET',
+          type: 'fetch',
+          url: 'http://dogs.are.great/',
+        }),
+      );
       expect(newSpan.description).toBe('GET http://dogs.are.great/');
       expect(newSpan.op).toBe('http.client');
       expect(fetchHandlerData.fetchData?.__span).toBeDefined();
@@ -241,11 +243,13 @@ describe('callbacks', () => {
       const newSpan = transaction.spanRecorder?.spans[1] as Span;
 
       expect(newSpan).toBeInstanceOf(Span);
-      expect(newSpan.data).toEqual({
-        method: 'GET',
-        type: 'xhr',
-        url: 'http://dogs.are.great/',
-      });
+      expect(newSpan.data).toEqual(
+        expect.objectContaining({
+          method: 'GET',
+          type: 'xhr',
+          url: 'http://dogs.are.great/',
+        }),
+      );
       expect(newSpan.description).toBe('GET http://dogs.are.great/');
       expect(newSpan.op).toBe('http.client');
       expect(xhrHandlerData.xhr.__sentry_xhr_span_id__).toBeDefined();