docs/SCANNER_DEBUG_MODE.md

@@ -0,0 +1,156 @@
+# Scanner Debug Mode
+
+Real-time performance instrumentation for the card scanner pipeline. Use this to diagnose slow identification, rate-limit issues, or layer-specific bottlenecks on iOS Chrome, Mac webcam, or any device.
+
+## Activation
+
+**Method 1: Browser console (temporary)**
+```javascript
+window.__SCANNER_DEBUG = true
+```
+
+**Method 2: localStorage (persists across reloads)**
+```javascript
+localStorage.setItem('SCANNER_DEBUG', 'true')
+```
+
+Then navigate to `/scanner` or reload the page.
+
+## What Gets Logged
+
+Every scanner operation logs timestamped messages with emoji prefixes for quick visual scanning:
+
+### Shutter Press & Overall Timing
+```
+[Scanner Debug 21:45:32.123] 🎯 Shutter pressed (tracker-42, attempt 1)
+[Scanner Debug 21:45:37.456] ✅ Card verified successfully → 5333ms total
+```
+
+### Layer 0: pgvector Visual Similarity
+```
+[Scanner Debug 21:45:32.150] 🔍 Layer 0 (pgvector visual) started
+[Scanner Debug 21:45:32.270] ⬆️ Layer 0 escalating → 120ms { reason: 'low confidence' }
+```
+or
+```
+[Scanner Debug 21:45:32.270] ✅ Layer 0 resolved → 120ms { card: 'Lightning Bolt', matches: undefined }
+```
+
+### Layer 1: Tesseract OCR + pg_trgm
+```
+[Scanner Debug 21:45:32.280] 📝 Layer 1 (Tesseract OCR + pg_trgm) started
+[Scanner Debug 21:45:33.130] 🔤 OCR completed → 850ms { nameText: 'Lightning Bolt', confidence: 88 }
+[Scanner Debug 21:45:33.280] ✅ Layer 1 resolved → 1000ms { card: 'Lightning Bolt', matches: 3 }
+```
+
+### Layer 2: Vision API (Gemini/OpenAI)
+```
+[Scanner Debug 21:45:33.290] 🤖 Layer 2 (Vision API) call started
+[Scanner Debug 21:45:37.490] ✅ Vision API success → 4200ms { card: 'Lightning Bolt', needsUserSelection: false }
+```
+
+### Rate Limit / Cooldown
+```
+[Scanner Debug 21:45:37.500] 🚫 Rate limit hit (15/min) — cooldown until 21:46:37 → 10ms
+```
+or
+```
+[Scanner Debug 21:45:38.000] ⏸️ Vision cooldown active — retry in 59s
+```
+
+### Errors
+```
+[Scanner Debug 21:45:32.500] ⚠️ Layer 0 failed → 220ms { rateLimited: true }
+[Scanner Debug 21:45:33.500] ❌ Verification failed (no outcome) → 1000ms
+[Scanner Debug 21:45:34.500] 💥 Verification exception → 1200ms { error: 'Network request failed' }
+```
+
+## Reading the Output
+
+**Total scan time breakdown:**
+- **Layer 0 (pgvector):** Typically 80–200ms. If this escalates, L1 runs next.
+- **Layer 1 OCR:** Tesseract runs in-browser; expect 600–1200ms. If name extraction fails or confidence is low, escalates to L2.
+- **Layer 2 Vision API:** Network call to `/api/scan/identify` (Gemini/OpenAI). Typically 2–8 seconds depending on network + API latency.
+
+**Rate limit (15/min):** The scanner allows 15 vision API calls per minute per user (Redis key `deckhearth:scan:{userId}`). If you hit this, you'll see the cooldown message with the exact retry timestamp.
+
+## Common Patterns
+
+### Fast path (Layer 0 hit)
+```
+🎯 Shutter pressed
+🔍 Layer 0 started
+✅ Layer 0 resolved → 120ms
+🎉 Pipeline complete (L0) → 125ms total
+✅ Card verified successfully → 130ms total
+```
+
+### OCR path (Layer 0 miss, Layer 1 hit)
+```
+🎯 Shutter pressed
+🔍 Layer 0 started
+⬆️ Layer 0 escalating → 120ms
+📝 Layer 1 started
+🔤 OCR completed → 850ms
+✅ Layer 1 resolved → 1000ms
+🎉 Pipeline complete (L1) → 1020ms total
+✅ Card verified successfully → 1025ms total
+```
+
+### Vision API path (both layers escalate)
+```
+🎯 Shutter pressed
+🔍 Layer 0 started
+⬆️ Layer 0 escalating → 120ms
+📝 Layer 1 started
+🔤 OCR completed → 850ms
+⬆️ Layer 1 escalating → 1000ms
+🤖 Layer 2 (Vision API) started
+✅ Vision API success → 4200ms
+🎉 Pipeline complete (L2) → 5320ms total
+✅ Card verified successfully → 5325ms total
+```
+
+### Rate limit hit
+```
+🎯 Shutter pressed (attempt 16)
+🔍 Layer 0 started
+⬆️ Layer 0 escalating → 110ms
+📝 Layer 1 started
+⬆️ Layer 1 escalating → 950ms
+🤖 Layer 2 (Vision API) started
+🚫 Vision API rate limited → 80ms
+🚫 Pipeline halted (rate limited) → 1140ms total
+🚫 Rate limit hit (15/min) — cooldown until 21:46:32 → 1145ms
+```
+
+## iOS Chrome Specific Issues
+
+If you see **no logs at all** on iOS Chrome:
+1. Open Safari on macOS, connect your iPhone via USB
+2. Develop → [Your iPhone] → [deckhearth tab]
+3. The Safari Web Inspector console will show the debug logs
+
+If **Layer 0/1 succeed but L2 times out**:
+- iOS Chrome network throttling may be active (Settings → Safari → Advanced → Experimental Features)
+- Vision API may be slow on cellular — test on Wi-Fi
+
+If **OCR step shows `nameText: ""` repeatedly**:
+- Camera capture may be producing black frames on iOS — check canvas output in the inspector
+
+## Deactivation
+
+```javascript
+delete window.__SCANNER_DEBUG
+localStorage.removeItem('SCANNER_DEBUG')
+```
+
+Then reload the page.
+
+## Implementation
+
+Debug logs are injected at:
+- `lib/scanner-card-identify.js` — Layer 0/1/2 network calls + pipeline orchestration
+- `lib/use-scanner-identification.js` — Shutter press + verification wrapper
+
+The `isDebugMode()` check is inlined in every `debugLog()` call, so there's zero runtime overhead when debug mode is off.

lib/scanner-card-identify.js

@@ -1,5 +1,24 @@
 import { isValidCardQuad, warpCardCaptureFromVideo } from './scanner-card-warp.js';
 
+/** Debug mode flag — set via localStorage or window global */
+function isDebugMode() {
+  if (typeof window === 'undefined') return false;
+  return (
+    window.__SCANNER_DEBUG === true ||
+    localStorage.getItem('SCANNER_DEBUG') === 'true'
+  );
+}
+
+function debugLog(emoji, message, data) {
+  if (!isDebugMode()) return;
+  const timestamp = new Date().toISOString().split('T')[1].slice(0, 12);
+  if (data !== undefined) {
+    console.log(`[Scanner Debug ${timestamp}] ${emoji} ${message}`, data);
+  } else {
+    console.log(`[Scanner Debug ${timestamp}] ${emoji} ${message}`);
+  }
+}
+
 /** Default margin (px) around tracked bounds when cropping a card capture. */
 export const CAPTURE_MARGIN_PX = 20;
 
@@ -266,15 +285,23 @@ export async function fetchIdentifyByImage(imageData, authHeaders, game) {
  * Layer 0: visual kNN against precomputed catalog embeddings.
  */
 export async function tryLayer0VisualIdentify(imageData, authHeaders, game) {
+  const startMs = Date.now();
+  debugLog('🔍', 'Layer 0 (pgvector visual) started');
+  
   const l0 = await fetchIdentifyByImage(imageData, authHeaders, game);
+  const durationMs = Date.now() - startMs;
+  
   if (!l0.ok) {
+    debugLog('⚠️', `Layer 0 failed → ${durationMs}ms`, { rateLimited: l0.rateLimited });
     return { handled: false };
   }
 
   if (l0.result.escalate) {
+    debugLog('⬆️', `Layer 0 escalating → ${durationMs}ms`, { reason: l0.result.escalateReason || 'low confidence' });
     return { handled: false };
   }
 
+  debugLog('✅', `Layer 0 resolved → ${durationMs}ms`, { card: l0.result.card?.name, matches: l0.result.matches?.length });
   return {
     handled: true,
     outcome: resolveIdentifyOutcome(l0.result),
@@ -282,22 +309,30 @@ export async function tryLayer0VisualIdentify(imageData, authHeaders, game) {
 }
 
 export async function fetchVisionIdentify(imageData, authHeaders) {
+  const startMs = Date.now();
+  debugLog('🤖', 'Layer 2 (Vision API) call started');
+  
   const response = await fetch('/api/scan/identify', {
     method: 'POST',
     headers: authHeaders,
     body: JSON.stringify({ imageData }),
   });
+  
+  const durationMs = Date.now() - startMs;
 
   if (response.status === 429) {
+    debugLog('🚫', `Vision API rate limited → ${durationMs}ms`);
     return { ok: false, rateLimited: true };
   }
 
   if (!response.ok) {
     const errBody = await response.json().catch(() => ({}));
+    debugLog('❌', `Vision API failed (${response.status}) → ${durationMs}ms`, { error: errBody.error });
     throw new Error(errBody.error || `Scan identify failed: ${response.status}`);
   }
 
   const result = await response.json();
+  debugLog('✅', `Vision API success → ${durationMs}ms`, { card: result.card?.name, needsUserSelection: result.needsUserSelection });
   return { ok: true, result };
 }
 
@@ -306,10 +341,18 @@ export async function fetchVisionIdentify(imageData, authHeaders) {
  * Returns { handled: true, outcome } when L1 resolves without escalation.
  */
 export async function tryLayer1TextIdentify(imageData, authHeaders) {
+  const startMs = Date.now();
+  debugLog('📝', 'Layer 1 (Tesseract OCR + pg_trgm) started');
+  
   const { recognizeCardFields } = await import('./ocr-worker.js');
+  const ocrStartMs = Date.now();
   const ocr = await recognizeCardFields(imageData);
+  const ocrDurationMs = Date.now() - ocrStartMs;
+  
+  debugLog('🔤', `OCR completed → ${ocrDurationMs}ms`, { nameText: ocr.nameText, confidence: ocr.nameConfidence });
 
   if (ocr.nameText.length < 3) {
+    debugLog('⚠️', `Layer 1 skipped (name too short: "${ocr.nameText}") → ${Date.now() - startMs}ms`);
     return { handled: false };
   }
 
@@ -319,11 +362,15 @@ export async function tryLayer1TextIdentify(imageData, authHeaders) {
     cardNumber: ocr.cardNumber || undefined,
     authHeaders,
   });
+  
+  const durationMs = Date.now() - startMs;
 
   if (!l1.ok || l1.result.escalate) {
+    debugLog('⬆️', `Layer 1 escalating → ${durationMs}ms`, { escalate: l1.result?.escalate });
     return { handled: false };
   }
 
+  debugLog('✅', `Layer 1 resolved → ${durationMs}ms`, { card: l1.result.card?.name, matches: l1.result.matches?.length });
   return {
     handled: true,
     outcome: resolveIdentifyOutcome(l1.result),
@@ -340,6 +387,9 @@ export async function identifyTrackedCardCapture({
   authHeaders,
   visionCooldownUntilMs = 0,
 }) {
+  const pipelineStartMs = Date.now();
+  debugLog('🎯', `Card verification started (tracker-${cardTracker.id})`);
+  
   const imageData = captureCardRegionFromVideo(
     video,
     canvas,
@@ -351,30 +401,38 @@ export async function identifyTrackedCardCapture({
   try {
     const l0 = await tryLayer0VisualIdentify(imageData, authHeaders);
     if (l0.handled) {
+      debugLog('🎉', `Pipeline complete (L0) → ${Date.now() - pipelineStartMs}ms total`);
       return { imageData, ...l0 };
     }
   } catch (l0Error) {
     console.warn('Layer-0 visual path failed, falling back to text/vision:', l0Error);
+    debugLog('⚠️', 'Layer 0 exception', { error: l0Error.message });
   }
 
   try {
     const l1 = await tryLayer1TextIdentify(imageData, authHeaders);
     if (l1.handled) {
+      debugLog('🎉', `Pipeline complete (L1) → ${Date.now() - pipelineStartMs}ms total`);
       return { imageData, ...l1 };
     }
   } catch (l1Error) {
     console.warn('Layer-1 OCR path failed, escalating to vision:', l1Error);
+    debugLog('⚠️', 'Layer 1 exception', { error: l1Error.message });
   }
 
   if (Date.now() < visionCooldownUntilMs) {
+    const cooldownSecondsRemaining = Math.ceil((visionCooldownUntilMs - Date.now()) / 1000);
+    debugLog('⏸️', `Vision cooldown active — retry in ${cooldownSecondsRemaining}s`);
     return { imageData, retry: true };
   }
 
   const vision = await fetchVisionIdentify(imageData, authHeaders);
   if (vision.rateLimited) {
+    debugLog('🚫', `Pipeline halted (rate limited) → ${Date.now() - pipelineStartMs}ms total`);
     return { imageData, rateLimited: true };
   }
 
+  debugLog('🎉', `Pipeline complete (L2) → ${Date.now() - pipelineStartMs}ms total`);
   return {
     imageData,
     handled: true,

lib/use-scanner-identification.js

@@ -13,6 +13,25 @@ import {
   fetchVisionIdentify,
 } from './scanner-card-identify.js';
 
+/** Debug mode flag — set via localStorage or window global */
+function isDebugMode() {
+  if (typeof window === 'undefined') return false;
+  return (
+    window.__SCANNER_DEBUG === true ||
+    localStorage.getItem('SCANNER_DEBUG') === 'true'
+  );
+}
+
+function debugLog(emoji, message, data) {
+  if (!isDebugMode()) return;
+  const timestamp = new Date().toISOString().split('T')[1].slice(0, 12);
+  if (data !== undefined) {
+    console.log(`[Scanner Debug ${timestamp}] ${emoji} ${message}`, data);
+  } else {
+    console.log(`[Scanner Debug ${timestamp}] ${emoji} ${message}`);
+  }
+}
+
 /**
  * Card identification, disambiguation, and review-submission flow for the scanner.
  * Camera refs and verify-card wiring are supplied by the parent + useCameraScanner.
@@ -298,6 +317,9 @@ export function useScannerIdentification({
     if (disambiguation) return;
     if (activeVerificationRef.current >= 1) return;
 
+    const verifyStartMs = Date.now();
+    debugLog('🎯', `Shutter pressed (tracker-${cardTracker.id}, attempt ${cardTracker.scanAttempts + 1})`);
+
     activeVerificationRef.current += 1;
     cardTracker.status = 'verifying';
     setIsIdentifying(true);
@@ -314,12 +336,15 @@ export function useScannerIdentification({
       });
 
       if (identification.retry) {
+        debugLog('⏸️', `Verification skipped (cooldown active) → ${Date.now() - verifyStartMs}ms`);
         cardTracker.status = 'detecting';
         return;
       }
 
       if (identification.rateLimited) {
         visionCooldownUntilRef.current = Date.now() + VISION_RATE_LIMIT_MS;
+        const cooldownUntil = new Date(visionCooldownUntilRef.current).toISOString().split('T')[1].slice(0, 8);
+        debugLog('🚫', `Rate limit hit (15/min) — cooldown until ${cooldownUntil} → ${Date.now() - verifyStartMs}ms`);
         reportScannerError('Too many scan attempts. Please wait a moment and try again.');
         cardTracker.status = 'negative';
         cardTracker.negativeAt = Date.now();
@@ -328,13 +353,16 @@ export function useScannerIdentification({
 
       if (identification.handled && identification.outcome) {
         cardTracker.status = 'confirmed';
+        debugLog('✅', `Card verified successfully → ${Date.now() - verifyStartMs}ms total`, { outcome: identification.outcome.type });
         await applyIdentifyOutcome(cardTracker, identification.imageData, identification.outcome);
       } else {
+        debugLog('❌', `Verification failed (no outcome) → ${Date.now() - verifyStartMs}ms`);
         cardTracker.status = 'negative';
         cardTracker.negativeAt = Date.now();
       }
     } catch (error) {
       console.error(`Error verifying card ${cardTracker.id}:`, error);
+      debugLog('💥', `Verification exception → ${Date.now() - verifyStartMs}ms`, { error: error.message });
       cardTracker.status = 'negative';
       cardTracker.negativeAt = Date.now();
       reportScannerError(error.message || 'Scan failed');