fix(tracing): buffer bridge events to eliminate 50-60s ghost traces (#116) (#116)

Root cause: Runtime.addBinding is async — on page navigation, the bridge
script (via addScriptToEvaluateOnNewDocument) fires BEFORE Chrome
registers __rrwebPush in the new execution context. For fast-solving
managed Turnstile widgets (Ahrefs), the token is available within ms
of page load. emit() silently dropped the event, tokenReported=true
prevented retries, and awaitResolutionRace waited the full 60s timeout
for a signal that was permanently lost.

Fix: Buffer events in emit() and flush via 50ms poll when the binding
appears. Also includes trace improvements from production analysis:
- Add click timing attributes to cf.resolutionRace span
- Fix empty cf.domain for malformed URLs
- Update tab.url span attribute on navigation
- Add screencast.fps/duration_s attributes
- Add solved_set_size warning log (>50)
- Add BridgeEvent timing type to union
- Add vitest JSON reporter for test output capture

Author: DivMode

src/browser/cf-bridge.ts

@@ -14,13 +14,41 @@ import { setupTurnstileHooks } from './turnstile-hooks';
 import { setupErrorMonitor } from './turnstile-error';
 import type { BridgeEvent } from './types';
 
+// ── Buffered emit ─────────────────────────────────────────────────────
+// Runtime.addBinding is async — on navigation, the bridge script fires BEFORE
+// Chrome registers __rrwebPush in the new execution context. Without buffering,
+// solved events are silently dropped (tokenReported=true prevents retry),
+// causing 50-60s ghost traces while awaitResolutionRace waits for a signal
+// that was lost. Buffer events and flush when the binding appears.
+const pendingEvents: string[] = [];
+let flushTimer: ReturnType<typeof setInterval> | null = null;
+
+function flushPending(): void {
+  while (pendingEvents.length > 0) {
+    try { window.__rrwebPush!(pendingEvents.shift()!); } catch (_) {}
+  }
+  if (flushTimer) {
+    clearInterval(flushTimer);
+    flushTimer = null;
+  }
+}
+
 function emit(event: BridgeEvent): void {
-  // Multiplex through rrweb binding — avoids adding a new detectable binding.
-  // Server distinguishes bridge events (object with type) from rrweb batches (array).
+  const payload = JSON.stringify(event);
   if (typeof window.__rrwebPush === 'function') {
-    try {
-      window.__rrwebPush(JSON.stringify(event));
-    } catch (_) {}
+    if (pendingEvents.length > 0) flushPending();
+    try { window.__rrwebPush(payload); } catch (_) {}
+  } else {
+    pendingEvents.push(payload);
+    if (!flushTimer) {
+      flushTimer = setInterval(() => {
+        if (typeof window.__rrwebPush === 'function') flushPending();
+      }, 50);
+      // Stop after 10s — binding should appear within milliseconds
+      setTimeout(() => {
+        if (flushTimer) { clearInterval(flushTimer); flushTimer = null; }
+      }, 10000);
+    }
   }
 }
 

src/browser/types.ts

@@ -8,7 +8,8 @@ export type BridgeEvent =
   | { type: 'detected'; method: string; cType?: string; cRay?: string }
   | { type: 'solved'; token: string; tokenLength: number }
   | { type: 'error'; errorType: string; hasToken: boolean }
-  | { type: 'still_detected'; detected: boolean };
+  | { type: 'still_detected'; detected: boolean }
+  | { type: 'timing'; event: string; ts: number };
 
 /** Emit function — pushes a BridgeEvent to the server. */
 export type Emit = (event: BridgeEvent) => void;

src/session/cdp-session.ts

@@ -1535,6 +1535,12 @@ export class CdpSession {
         'cdp.url': targetInfo.url?.substring(0, 200) ?? '',
       });
       if (targetInfo.type === 'page') {
+        // Update tab span URL attribute — shows final URL, not initial about:blank
+        const tab = session.tabs.get(changedTargetId);
+        if (tab && targetInfo.url) {
+          tab.span.attribute('tab.url', targetInfo.url.substring(0, 200));
+        }
+
         const target = session.targets.getByTarget(changedTargetId);
         if (target) {
           // Re-enable CDP domains that Chrome resets on same-target navigation

src/session/cf/cf-detection-registry.ts

@@ -51,7 +51,10 @@ export class DetectionRegistry {
       // Extract domain from page URL for Tempo filtering
       let domain = 'unknown';
       try {
-        if (active.info.url) domain = new URL(active.info.url).hostname;
+        if (active.info.url) {
+          const hostname = new URL(active.info.url).hostname;
+          domain = hostname || 'unknown';
+        }
       } catch { /* malformed URL */ }
 
       // Assign detectionId — groups all solve spans for this challenge

src/session/cf/cloudflare-detector.ts

@@ -647,6 +647,15 @@ export class CloudflareDetector {
 
       const maybeResolved = yield* active.resolution.awaitBounded;
 
+      // Tasks 2+4: Click timing attributes — distinguish pre-click vs post-click timeout
+      yield* Effect.annotateCurrentSpan({
+        'cf.click_delivered': !!active.clickDelivered,
+        ...(active.clickDeliveredAt ? {
+          'cf.click_delivered_at_ms': active.clickDeliveredAt,
+          'cf.click_to_resolve_ms': Date.now() - active.clickDeliveredAt,
+        } : {}),
+      });
+
       if (maybeResolved._tag === 'Some') {
         const resolved = maybeResolved.value;
         if (resolved._tag === 'solved') {

src/session/cf/cloudflare-solve-strategies.ts

@@ -788,12 +788,19 @@ export class CloudflareSolveStrategies {
           (t: { targetId?: string }) => t.targetId && solvedCFTargetIds?.has(t.targetId),
         );
 
+        const solvedSetSize = solvedCFTargetIds?.size ?? 0;
+        if (solvedSetSize > 50) {
+          yield* Effect.logWarning('cf.detect.solved_set_size exceeds 50').pipe(
+            Effect.annotateLogs({ solved_set_size: solvedSetSize }),
+          );
+        }
+
         yield* Effect.annotateCurrentSpan({
           'cf.detect.total_targets': targetInfos.length,
           'cf.detect.cf_targets': cfTargets.length,
           'cf.detect.filtered_stale': filteredOut.length,
           'cf.detect.fresh': matched.length,
-          'cf.detect.solved_set_size': solvedCFTargetIds?.size ?? 0,
+          'cf.detect.solved_set_size': solvedSetSize,
           'cf.detect.matched_urls': matched.map((t: { url?: string; targetId?: string }) => `${t.targetId?.slice(0, 8)}=${t.url}`).join(' | '),
           'cf.detect.filtered_ids': filteredOut.map((t: { targetId?: string }) => t.targetId?.slice(0, 8)).join(','),
         });

src/session/screencast-capture.ts

@@ -75,6 +75,7 @@ const targetConsumer = (
 ): Effect.Effect<number> =>
   Effect.fn('screencast.target')(function*() {
     yield* Effect.annotateCurrentSpan({ 'screencast.target_id': cdpSessionId });
+    const startTime = Date.now();
     let frameCount = 0;
 
     // Ref holds the current fallback fiber so we can interrupt+restart it
@@ -137,7 +138,13 @@ const targetConsumer = (
     const fb = yield* Ref.get(fallbackRef);
     if (fb) yield* Fiber.interrupt(fb).pipe(Effect.ignore);
 
-    yield* Effect.annotateCurrentSpan({ 'screencast.frame_count': frameCount });
+    const durationSec = (Date.now() - startTime) / 1000;
+    const fps = durationSec > 0 ? frameCount / durationSec : 0;
+    yield* Effect.annotateCurrentSpan({
+      'screencast.frame_count': frameCount,
+      'screencast.fps': Math.round(fps * 100) / 100,
+      'screencast.duration_s': Math.round(durationSec * 100) / 100,
+    });
     return frameCount;
   })();
 

vitest.config.ts

@@ -15,6 +15,8 @@ const resolveConfig = {
 export default defineConfig({
   test: {
     bail: 1,
+    reporters: ['default', 'json'],
+    outputFile: { json: '/tmp/vitest-results.json' },
     projects: [
       {
         resolve: resolveConfig,