debug

Author: RulaKhaled

packages/cloudflare/src/request.ts

@@ -108,6 +108,10 @@ export function wrapRequestHandler(
             res = await handler();
             setHttpStatus(span, res.status);
           } catch (e) {
+            // DEBUG: Log error path
+            if (typeof console !== 'undefined' && console.log) {
+              console.log('[REQUEST.TS] Taking ERROR path, calling flush');
+            }
             span.end();
             if (captureErrors) {
               captureException(e, { mechanism: { handled: false, type: 'auto.http.cloudflare' } });
@@ -119,8 +123,21 @@ export function wrapRequestHandler(
           // Classify response to detect actual streaming
           const classification = classifyResponseStreaming(res);
 
+          // DEBUG: Log classification result
+          if (typeof console !== 'undefined' && console.log) {
+            console.log('[REQUEST.TS] Classification:', {
+              isStreaming: classification.isStreaming,
+              hasBody: !!classification.response.body,
+              contentType: classification.response.headers.get('content-type'),
+              contentLength: classification.response.headers.get('content-length'),
+            });
+          }
+
           if (classification.isStreaming && classification.response.body) {
             // Streaming response detected - monitor consumption to keep span alive
+            if (typeof console !== 'undefined' && console.log) {
+              console.log('[REQUEST.TS] Taking STREAMING path');
+            }
             const [clientStream, monitorStream] = classification.response.body.tee();
 
             // Monitor stream consumption and end span when complete
@@ -153,6 +170,9 @@ export function wrapRequestHandler(
           }
 
           // Non-streaming response - end span immediately and return original
+          if (typeof console !== 'undefined' && console.log) {
+            console.log('[REQUEST.TS] Taking NON-STREAMING path, calling flush');
+          }
           span.end();
           waitUntil?.(flush(2000));
           return classification.response;

packages/cloudflare/test/request.test.ts

@@ -91,6 +91,16 @@ describe('withSentry', () => {
   });
 
   test('flush must be called when all waitUntil are done', async () => {
+    // Also spy on the exported flush function to see how many times it's called
+    let exportedFlushCallCount = 0;
+    const originalExportedFlush = SentryCore.flush;
+    const exportedFlushSpy = vi.spyOn(SentryCore, 'flush').mockImplementation(async (timeout?: number) => {
+      exportedFlushCallCount++;
+      console.log(`[EXPORTED flush() #${exportedFlushCallCount}] timeout: ${timeout}`);
+      // Call through to the real implementation
+      return originalExportedFlush(timeout);
+    });
+
     let flushCallCount = 0;
     const originalFlush = SentryCore.Client.prototype.flush;
 
@@ -99,15 +109,24 @@ describe('withSentry', () => {
       timeout?: number,
     ) {
       flushCallCount++;
-      console.log(`[FLUSH #${flushCallCount}] Client: ${this?.constructor?.name || 'unknown'}, timeout: ${timeout}`);
+      console.log(`\n[FLUSH #${flushCallCount}] Client: ${this?.constructor?.name || 'unknown'}, timeout: ${timeout}`);
       const stack = new Error().stack?.split('\n').slice(2, 10).join('\n  ');
       console.log(`  Stack:\n  ${stack}`);
       console.log(`  this._flushLock:`, this._flushLock ? 'exists' : 'undefined');
       console.log(
         `  Recursion check: flushCallCount=${flushCallCount}, spy.calls.length=${flushSpy.mock.calls.length}`,
       );
 
-      // Important: Return a resolved promise to avoid triggering parent flush logic
+      // Check if we're being called from within another flush
+      const stackString = new Error().stack || '';
+      const flushInStack = (stackString.match(/\.flush\(/g) || []).length;
+      console.log(`  Number of .flush( in stack: ${flushInStack}`);
+
+      // Try calling the original to see if that changes behavior
+      // Comment this out to see if it matters:
+      // return originalFlush.call(this, timeout);
+
+      // Or just return immediately:
       return Promise.resolve(true);
     });
     flushSpy.mockClear(); // Explicitly clear before test
@@ -116,28 +135,33 @@ describe('withSentry', () => {
     onTestFinished(() => {
       vi.useRealTimers();
       flushSpy.mockRestore();
+      exportedFlushSpy.mockRestore();
     });
     let pendingCount = 0;
     const waits: Promise<unknown>[] = [];
+
+    // Track the ORIGINAL waitUntil to see if makeFlushLock wraps it
+    let originalWaitUntilCallCount = 0;
     const waitUntil = vi.fn(promise => {
-      const callNum = waitUntil.mock.calls.length;
+      originalWaitUntilCallCount++;
+      const callNum = originalWaitUntilCallCount;
       pendingCount++;
       console.log(
-        `[WAITUNTIL #${callNum}] Pending: ${pendingCount}, Promise type: ${promise?.constructor?.name || 'unknown'}`,
+        `[ORIGINAL_WAITUNTIL #${callNum}] Pending: ${pendingCount}, Promise type: ${promise?.constructor?.name || 'unknown'}`,
       );
-      const stack = new Error().stack?.split('\n').slice(2, 5).join('\n  ');
+      const stack = new Error().stack?.split('\n').slice(2, 6).join('\n  ');
       console.log(`  Stack:\n  ${stack}`);
 
       // Wrap the promise to log when it resolves
       const wrappedPromise = promise.then(
         val => {
           pendingCount--;
-          console.log(`[WAITUNTIL #${callNum} RESOLVED] Pending now: ${pendingCount}`);
+          console.log(`[ORIGINAL_WAITUNTIL #${callNum} RESOLVED] Pending now: ${pendingCount}`);
           return val;
         },
         err => {
           pendingCount--;
-          console.log(`[WAITUNTIL #${callNum} REJECTED] Pending now: ${pendingCount}`, err);
+          console.log(`[ORIGINAL_WAITUNTIL #${callNum} REJECTED] Pending now: ${pendingCount}`, err);
           throw err;
         },
       );
@@ -175,7 +199,8 @@ describe('withSentry', () => {
 
     console.log('\n=== TEST END ===');
     console.log(`Total waitUntil calls: ${waitUntil.mock.calls.length}`);
-    console.log(`Total flush calls: ${flushSpy.mock.calls.length}`);
+    console.log(`Total EXPORTED flush() calls: ${exportedFlushCallCount}`);
+    console.log(`Total Client.flush() calls: ${flushSpy.mock.calls.length}`);
     console.log(`Flush calls before resolve: ${callsBeforeResolve}`);
 
     // Check that flush was called at least once after waitUntils resolved
@@ -188,10 +213,16 @@ describe('withSentry', () => {
       console.error('\n=== ASSERTION FAILURE ===');
       console.error(`Expected exactly 1 NEW flush call, but got ${delta}`);
       console.error(`Calls before: ${callsBeforeResolve}, Calls after: ${callsAfterResolve}`);
-      console.error('\nAll flush call arguments:');
+      console.error(`\nExported flush() was called ${exportedFlushCallCount} times`);
+      console.error(`Client.flush() was called ${callsAfterResolve} times`);
+      console.error('\nAll Client.flush() call arguments:');
       flushSpy.mock.calls.forEach((call, i) => {
         console.error(`  Call ${i + 1}:`, call);
       });
+      console.error('\nAll exported flush() call arguments:');
+      exportedFlushSpy.mock.calls.forEach((call, i) => {
+        console.error(`  Call ${i + 1}:`, call);
+      });
     }
 
     // Ideally it should be exactly 1, but verify the delta to avoid CI flakiness