diff --git a/docs/SCANNER_DEBUG_MODE.md b/docs/SCANNER_DEBUG_MODE.md new file mode 100644 index 0000000..02f6af9 --- /dev/null +++ b/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. diff --git a/lib/scanner-card-identify.js b/lib/scanner-card-identify.js index e375599..79afc1b 100644 --- a/lib/scanner-card-identify.js +++ b/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, diff --git a/lib/use-scanner-identification.js b/lib/use-scanner-identification.js index 0609db9..4d38e9f 100644 --- a/lib/use-scanner-identification.js +++ b/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');