feat(profiling): add debug logs

src/hubextensions.hub.test.ts

@@ -2,10 +2,11 @@ import * as Sentry from '@sentry/node';
 import '@sentry/tracing'; // this has a addExtensionMethods side effect
 import { ProfilingIntegration } from './index'; // this has a addExtensionMethods side effect
 import { importCppBindingsModule } from './cpu_profiler';
+import { logger } from '@sentry/utils';
 
 Sentry.init({
   dsn: 'https://[email protected]/6625302',
-  debug: false,
+  debug: true,
   tracesSampleRate: 1,
   // @ts-expect-error profilingSampleRate is not part of the options type yet
   profilesSampleRate: 1,
@@ -17,6 +18,7 @@ const profiler = importCppBindingsModule();
 describe('hubextensions', () => {
   beforeEach(() => {
     jest.clearAllMocks();
+    jest.useRealTimers();
   });
   it('calls profiler when startTransaction is invoked on hub', async () => {
     const startProfilingSpy = jest.spyOn(profiler, 'startProfiling');
@@ -64,4 +66,61 @@ describe('hubextensions', () => {
     transaction.finish();
     expect(stopProfilingSpy).toHaveBeenCalledTimes(1);
   });
+
+  it('logger warns user if there are invalid samples', async () => {
+    const logSpy = jest.spyOn(logger, 'log');
+    const transport = Sentry.getCurrentHub().getClient()?.getTransport();
+
+    jest.spyOn(profiler, 'stopProfiling').mockImplementation(() => {
+      return {
+        samples: [
+          {
+            stack_id: 0,
+            thread_id: '0',
+            elapsed_since_start_ns: '10'
+          }
+        ],
+        stacks: [[0]],
+        frames: [],
+        profile_relative_ended_at_ns: 0,
+        profile_relative_started_at_ns: 0,
+        profiler_logging_mode: 'lazy'
+      };
+    });
+
+    if (!transport) {
+      throw new Error('Sentry getCurrentHub()->getClient()->getTransport() did not return a transport');
+    }
+
+    jest.spyOn(transport, 'send').mockImplementation(() => {
+      // Do nothing so we don't send events to Sentry
+      return Promise.resolve();
+    });
+
+    const transaction = Sentry.getCurrentHub().startTransaction({ name: 'profile_hub' });
+    transaction.finish();
+
+    await Sentry.flush(1000);
+    expect(logSpy.mock?.lastCall?.[0]).toBe('[Profiling] Profile has less than 2 samples');
+  });
+
+  it('logger warns user if traceId is invalid', async () => {
+    const logSpy = jest.spyOn(logger, 'log');
+    const transport = Sentry.getCurrentHub().getClient()?.getTransport();
+
+    if (!transport) {
+      throw new Error('Sentry getCurrentHub()->getClient()->getTransport() did not return a transport');
+    }
+
+    jest.spyOn(transport, 'send').mockImplementation(() => {
+      // Do nothing so we don't send events to Sentry
+      return Promise.resolve();
+    });
+
+    const transaction = Sentry.getCurrentHub().startTransaction({ name: 'profile_hub', traceId: 'boop' });
+    transaction.finish();
+
+    await Sentry.flush(1000);
+    expect(logSpy.mock?.calls?.[5]?.[0]).toBe('[Profiling] Invalid traceId: ' + 'boop' + ' on profiled event');
+  });
 });

src/utils.ts

@@ -11,8 +11,10 @@ import type {
   EventEnvelope,
   EventEnvelopeHeaders
 } from '@sentry/types';
-import { createEnvelope, dropUndefinedKeys, dsnToString, uuid4 } from '@sentry/utils';
+
+import { createEnvelope, dropUndefinedKeys, dsnToString, uuid4, logger } from '@sentry/utils';
 import type { ThreadCpuProfile, RawThreadCpuProfile } from './cpu_profiler';
+import { isDebugBuild } from './env';
 
 // We require the file because if we import it, it will be included in the bundle.
 // I guess tsc does not check file contents when it's imported.
@@ -175,6 +177,26 @@ export function createProfilingEventEnvelope(
   const transactionStartMs = typeof event.start_timestamp === 'number' ? event.start_timestamp * 1000 : Date.now();
   const transactionEndMs = typeof event.timestamp === 'number' ? event.timestamp * 1000 : Date.now();
 
+  const traceId = (event?.contexts?.['trace']?.['trace_id'] as string) ?? '';
+
+  // Log a warning if the profile has an invalid traceId (should be uuidv4).
+  // All profiles and transactions are rejected if this is the case and we want to
+  // warn users that this is happening if they enable debug flag
+  if (isDebugBuild()) {
+    if (traceId.length !== 36) {
+      logger.log('[Profiling] Invalid traceId: ' + traceId + ' on profiled event');
+    }
+  }
+
+  // Log a warning if the profile has less than 2 samples so users can know why
+  // they are not seeing any profiling data and we cant avoid the back and forth
+  // of asking them to provide us with a dump of the profile data.
+  if (isDebugBuild()) {
+    if (enrichedThreadProfile.samples.length <= 1) {
+      logger.log('[Profiling] Profile has less than 2 samples');
+    }
+  }
+
   const profile: Profile = {
     event_id: uuid4(),
     timestamp: new Date(transactionStartMs).toISOString(),
@@ -203,7 +225,7 @@ export function createProfilingEventEnvelope(
       {
         name: event.transaction || '',
         id: event.event_id || uuid4(),
-        trace_id: (event?.contexts?.['trace']?.['trace_id'] as string) ?? '',
+        trace_id: traceId,
         active_thread_id: THREAD_ID_STRING,
         relative_start_ns: '0',
         relative_end_ns: ((transactionEndMs - transactionStartMs) * 1e6).toFixed(0)