diff --git a/frontend/package-lock.json b/frontend/package-lock.json index 0180a4e6..03b46a81 100644 --- a/frontend/package-lock.json +++ b/frontend/package-lock.json @@ -8,7 +8,8 @@ "name": "oxicloud-frontend", "version": "0.0.0", "dependencies": { - "@serenity-kit/opaque": "^1.1.0" + "@serenity-kit/opaque": "^1.1.0", + "loglevel": "^1.9.2" }, "devDependencies": { "@eslint/js": "^10.0.1", @@ -3969,6 +3970,19 @@ "dev": true, "license": "MIT" }, + "node_modules/loglevel": { + "version": "1.9.2", + "resolved": "https://registry.npmjs.org/loglevel/-/loglevel-1.9.2.tgz", + "integrity": "sha512-HgMmCqIJSAKqo68l0rS2AanEWfkxaZ5wNiEFb5ggm08lDs9Xl2KxBlX3PTcaD2chBM1gXAYf491/M2Rv8Jwayg==", + "license": "MIT", + "engines": { + "node": ">= 0.6.0" + }, + "funding": { + "type": "tidelift", + "url": "https://tidelift.com/funding/github/npm/loglevel" + } + }, "node_modules/lru-cache": { "version": "11.5.1", "resolved": "https://registry.npmjs.org/lru-cache/-/lru-cache-11.5.1.tgz", diff --git a/frontend/package.json b/frontend/package.json index daf4d24d..dd0287c3 100644 --- a/frontend/package.json +++ b/frontend/package.json @@ -47,6 +47,7 @@ "vitest": "^4.1.9" }, "dependencies": { - "@serenity-kit/opaque": "^1.1.0" + "@serenity-kit/opaque": "^1.1.0", + "loglevel": "^1.9.2" } } diff --git a/frontend/src/hooks.client.ts b/frontend/src/hooks.client.ts index 38c815c6..7bbccb79 100644 --- a/frontend/src/hooks.client.ts +++ b/frontend/src/hooks.client.ts @@ -3,12 +3,58 @@ * - wires the API client's session-expired behaviour (clear store + redirect), * - loads translations for the resolved locale. */ +import log from 'loglevel'; import { setSessionExpiredHandler } from '$lib/api/client'; import { initI18n } from '$lib/i18n/index.svelte'; import { session } from '$lib/stores/session.svelte'; import { seedNonceFromCookie } from '$lib/auth/dpop-proof'; +// DevTools shortcut: expose a small `oxi.*` helper on window so users +// can toggle log levels from the browser console without needing to +// import anything. Namespaces used today: `oxi:upload` (delta + direct +// upload pipeline). Levels: 'trace' | 'debug' | 'info' | 'warn' | 'error' | 'silent'. +// Choices persist to `localStorage['loglevel:']` via loglevel. +// +// Usage: +// oxi.setLogLevel('oxi:upload', 'debug') // deep dive +// oxi.setLogLevel('oxi:upload', 'warn') // quiet +// oxi.log.setLevel('debug') // everything to debug +declare global { + interface Window { + oxi?: { + log: typeof log; + setLogLevel: (namespace: string, level: log.LogLevelDesc) => string; + listLogLevels: () => Record; + }; + } +} + export async function init(): Promise { + if (typeof window !== 'undefined') { + window.oxi = { + log, + // Return a confirmation string so the DevTools echo is a + // useful "worked → new level" signal instead of `undefined`. + setLogLevel(namespace, level) { + log.getLogger(namespace).setLevel(level); + return `${namespace} → ${level}`; + }, + // Enumerate the levels loglevel has persisted so users can see + // what's currently set without opening the Application tab. + listLogLevels() { + const out: Record = {}; + if (typeof localStorage === 'undefined') return out; + for (let i = 0; i < localStorage.length; i++) { + const key = localStorage.key(i); + if (key?.startsWith('loglevel:')) { + out[key.slice('loglevel:'.length)] = localStorage.getItem(key) ?? ''; + } + } + return out; + } + }; + } + setSessionExpiredHandler(() => { session.reset(); if (typeof window !== 'undefined') { diff --git a/frontend/src/lib/api/endpoints/deltaUpload.ts b/frontend/src/lib/api/endpoints/deltaUpload.ts index 802e3cd3..d647d4d2 100644 --- a/frontend/src/lib/api/endpoints/deltaUpload.ts +++ b/frontend/src/lib/api/endpoints/deltaUpload.ts @@ -7,10 +7,27 @@ * commits. Any failure resolves `null` so the caller falls back to a plain * byte upload — delta is an optimization, never a gate. */ +import log from 'loglevel'; import { getCsrfToken } from '$lib/api/csrf'; import { createFileByHash, dedupCheckBatch } from '$lib/api/endpoints/files'; import { blake3HexOfFile } from '$lib/vendor/hashWasm'; +// Namespaced logger — level configurable at runtime from the browser +// console via `log.getLogger('oxi:upload').setLevel('debug')`, persisted +// to `localStorage['loglevel:oxi:upload']`. Default = info so common +// phase transitions are visible without extra opt-in; users chasing a +// bug flip to `debug` for per-chunk verbose trace without a page reload. +const uploadLog = log.getLogger('oxi:upload'); +uploadLog.setDefaultLevel('info'); + +// Short random id — one per upload attempt — so multiple concurrent +// files stay distinguishable in the console. +function newUploadId(): string { + const buf = new Uint8Array(3); + crypto.getRandomValues(buf); + return Array.from(buf, (b) => b.toString(16).padStart(2, '0')).join(''); +} + /** Files smaller than this skip delta: the round-trips cost more than the bytes. * Also the upper bound for client-side whole-file hashing (instant by-hash * uploads) — we never read a file larger than this fully into memory. Files at @@ -49,8 +66,25 @@ interface DoneMsg { type: 'done'; status: number; body?: { message?: string; error?: string; still_missing?: unknown }; + /** Final worker-side counters, sourced from the worker so throttled + * progress messages can't undercount on fast dedup-heavy paths. */ + reusedBytes?: number; + uploadedBytes?: number; + /** Whole-file BLAKE3 the delta protocol committed — same value the + * server stores as `file_blobs.hash`. Correlates a client-side log + * line with the resulting server-side blob. */ + fileHash?: string; } -type WorkerMsg = ProgressMsg | FallbackMsg | DoneMsg; +/** Worker-emitted log line forwarded to the main-thread `uploadLog` — the + * worker can't import loglevel from a static file, so it postMessages + * and we relay it through the shared logger. */ +interface LogMsg { + type: 'log'; + level: 'debug' | 'info' | 'warn' | 'error'; + msg: string; + extra?: Record; +} +type WorkerMsg = ProgressMsg | FallbackMsg | DoneMsg | LogMsg; /** * Try to upload `file` through the delta protocol. Resolves `null` whenever @@ -62,21 +96,38 @@ export function tryDeltaUpload( folderId: string | null | undefined, onProgress?: (pct: number) => void ): Promise { + const id = newUploadId(); if ( !folderId || file.size < DELTA_UPLOAD_MIN_SIZE || usable === false || typeof Worker === 'undefined' ) { + // Not a bug — these are the documented skip conditions. Log at + // debug so verbose-flag users see why delta was skipped; silent + // in the default path (would be noise on every small file). + const reason = !folderId + ? 'no folder id' + : file.size < DELTA_UPLOAD_MIN_SIZE + ? `file below ${DELTA_UPLOAD_MIN_SIZE} B threshold` + : usable === false + ? 'delta previously disabled for this tab' + : 'Worker constructor unavailable'; + uploadLog.debug(`[${id}] delta skipped: ${reason}`, { file: file.name, size: file.size }); return Promise.resolve(null); } + uploadLog.info(`[${id}] delta start`, { file: file.name, size: file.size }); + return new Promise((resolve) => { let worker: Worker; try { worker = new Worker(DELTA_WORKER_URL, { type: 'module' }); - } catch { + } catch (err) { usable = false; + uploadLog.warn(`[${id}] delta disabled for this tab: Worker constructor threw`, { + error: err instanceof Error ? err.message : String(err) + }); resolve(null); return; } @@ -92,7 +143,13 @@ export function tryDeltaUpload( worker.terminate(); resolve(answer); }; - const timer = setTimeout(() => settle(null), timeoutMs); + const timer = setTimeout(() => { + uploadLog.error( + `[${id}] delta timeout after ${Math.round(timeoutMs / 1000)}s — falling back to direct upload`, + { file: file.name, size: file.size } + ); + settle(null); + }, timeoutMs); // Liveness watchdog: a healthy worker posts progress sub-second while it // hashes and uploads. If it goes SILENT this long it is wedged (WASM init @@ -105,6 +162,10 @@ export function tryDeltaUpload( clearTimeout(stallTimer); stallTimer = setTimeout(() => { usable = false; + uploadLog.error( + `[${id}] delta worker went silent for ${STALL_MS / 1000}s — disabling delta for this tab (later files this session will go direct)`, + { file: file.name } + ); settle(null); }, STALL_MS); }; @@ -113,6 +174,18 @@ export function tryDeltaUpload( worker.onmessage = (event: MessageEvent) => { armStall(); // worker is alive — reset the liveness watchdog const msg = event.data; + if (msg.type === 'log') { + // Relay worker log through the shared logger so runtime-set + // level (via `log.getLogger('oxi:upload').setLevel(...)`) + // filters worker output too. Worker id doesn't know the + // upload id — we prefix it here for correlation. Skip the + // second arg when there's no extras: loglevel would log the + // literal `undefined` next to the message otherwise. + const line = `[${id}] worker: ${msg.msg}`; + if (msg.extra) uploadLog[msg.level](line, msg.extra); + else uploadLog[msg.level](line); + return; + } if (msg.type === 'progress') { savedBytes = msg.reusedBytes; if (onProgress && msg.totalBytes > 0) { @@ -125,29 +198,57 @@ export function tryDeltaUpload( return; } if (msg.type === 'fallback') { + uploadLog.warn(`[${id}] worker requested fallback: ${msg.reason ?? 'no reason'}`, { + file: file.name + }); settle(null); return; } if (msg.type === 'done') { if (msg.status === 201 || msg.status === 200) { - settle({ ok: true, data: msg.body, savedBytes }); + // Prefer the worker's authoritative final counter over + // the throttled progress-message-derived one — throttling + // can hide the reused-bytes update on fast paths. + const finalSaved = msg.reusedBytes ?? savedBytes; + uploadLog.info(`[${id}] delta done`, { + file: file.name, + blake3: msg.fileHash, + savedBytes: finalSaved, + uploadedBytes: msg.uploadedBytes ?? 0 + }); + settle({ ok: true, data: msg.body, savedBytes: finalSaved }); return; } const errorMsg = msg.body?.message || msg.body?.error || `Delta upload failed (HTTP ${msg.status})`; if (msg.status === 507) { + uploadLog.warn(`[${id}] delta hit quota (HTTP 507)`, { file: file.name, errorMsg }); settle({ ok: false, isQuotaError: true, errorMsg }); return; } if (msg.status === 409 && !msg.body?.still_missing) { + uploadLog.warn(`[${id}] delta conflict (HTTP 409)`, { file: file.name, errorMsg }); settle({ ok: false, errorMsg }); return; } + uploadLog.warn( + `[${id}] delta done with non-2xx (HTTP ${msg.status}) — falling back to direct upload`, + { file: file.name, errorMsg } + ); settle(null); } }; - worker.onerror = () => { + worker.onerror = (e) => { usable = false; + // Real browsers pass an ErrorEvent; test doubles fire onerror + // with no argument. Optional-chain so the no-arg path doesn't + // throw on `.message` and mask the real disable-signal. + uploadLog.error(`[${id}] delta worker onerror — disabling delta for this tab`, { + file: file.name, + message: e?.message, + filename: e?.filename, + lineno: e?.lineno + }); settle(null); }; diff --git a/frontend/static/workers/deltaWorker.js b/frontend/static/workers/deltaWorker.js index 6ceb22e6..81fe5efa 100644 --- a/frontend/static/workers/deltaWorker.js +++ b/frontend/static/workers/deltaWorker.js @@ -65,8 +65,26 @@ async function loadWasm() { workerScope.onmessage = async (event) => { const { file, folderId, name, csrfToken } = /** @type {{ file: File, folderId: string, name: string, csrfToken: string }} */ (event.data); + /** + * Forward a log line to the main-thread orchestrator, which routes it + * through the shared `loglevel` logger (namespace `oxi:upload`). Worker + * can't `import 'loglevel'` — it's served from /static and isn't + * bundler-resolved — so postMessage is the transport. + * + * @param {'debug'|'info'|'warn'|'error'} level + * @param {string} msg + * @param {Record=} extra + */ + const log = (level, msg, extra) => + workerScope.postMessage({ type: 'log', level, msg, extra }); + /** @param {string} reason */ - const fallback = (reason) => workerScope.postMessage({ type: 'fallback', reason }); + const fallback = (reason) => { + log('warn', `worker fallback: ${reason}`); + workerScope.postMessage({ type: 'fallback', reason }); + }; + + log('info', `worker start`, { file: name, size: file.size }); /** @type {Record} */ const mutHeaders = { 'Content-Type': 'application/json' }; @@ -75,6 +93,7 @@ workerScope.onmessage = async (event) => { let wasm; try { wasm = await loadWasm(); + log('debug', 'wasm loaded'); } catch (err) { fallback(`wasm unavailable: ${err instanceof Error ? err.message : String(err)}`); return; @@ -172,6 +191,7 @@ workerScope.onmessage = async (event) => { try { // eslint-disable-next-line no-await-in-loop -- bounded by pool size const wire = await encodeFrames(batch); + log('debug', `chunk PUT: ${batch.length} chunks, ${wire.length} bytes`); // eslint-disable-next-line no-await-in-loop -- bounded by pool size const response = await fetch('/api/files/delta/chunks', { method: 'PUT', @@ -183,12 +203,14 @@ workerScope.onmessage = async (event) => { }); if (!response.ok) { failed = `chunk PUT failed (HTTP ${response.status})`; + log('error', failed); return; } for (const c of batch) uploadedBytes += c.s; progress(); } catch (err) { failed = `chunk PUT failed: ${err instanceof Error ? err.message : String(err)}`; + log('error', failed); return; } } @@ -216,6 +238,7 @@ workerScope.onmessage = async (event) => { }); if (!response.ok) { failed = failed || `negotiate failed (HTTP ${response.status})`; + log('error', `negotiate failed (HTTP ${response.status})`); return; } const missing = new Set(/** @type {{missing: string[]}} */ (await response.json()).missing); @@ -226,10 +249,15 @@ workerScope.onmessage = async (event) => { reusedBytes += c.s; } } + log( + 'info', + `negotiate: ${fresh.length} hashes → ${missing.size} missing, ${fresh.length - missing.size} dedup'd` + ); signalUploaders(); progress(); } catch (err) { failed = failed || `negotiate failed: ${err instanceof Error ? err.message : String(err)}`; + log('error', `negotiate failed: ${err instanceof Error ? err.message : String(err)}`); } }); negotiateTail = run.catch(() => {}); @@ -281,6 +309,10 @@ workerScope.onmessage = async (event) => { const fileHash = /** @type {string} */ (fin.file_hash); hashedBytes = file.size; progress(true); + // Log the whole-file BLAKE3 immediately so it's visible in the + // trace regardless of whether the commit succeeds. Correlates + // the client-side view with the server's `file_blobs.hash`. + log('info', `hashed — blake3=${fileHash} (${chunks.length} chunks)`); // ── Drain: negotiations → uploads → commit ─────────────── await Promise.all(negotiations); @@ -349,7 +381,39 @@ workerScope.onmessage = async (event) => { // Conclusive: 201 created, or a real error (quota, name // conflict, validation). The spawner maps it to the uploaders' // UploadAnswer contract. - workerScope.postMessage({ type: 'done', status: response.status, body }); + const ok = response.status >= 200 && response.status < 300; + if (ok) { + // Human-friendly outcome line — the raw commit line below + // still carries the byte counts for anyone who wants them. + if (uploadedBytes === 0 && reusedBytes > 0) { + log('info', `✅ file already on server — 100% dedup, no bytes transferred (${reusedBytes.toLocaleString()} B reused, blake3=${fileHash})`); + } else if (reusedBytes > 0) { + const pct = Math.round((100 * reusedBytes) / file.size); + log('info', `✅ committed — uploaded ${uploadedBytes.toLocaleString()} B, reused ${reusedBytes.toLocaleString()} B (${pct}% dedup, blake3=${fileHash})`); + } else { + log('info', `✅ committed — uploaded ${uploadedBytes.toLocaleString()} B (no dedup, blake3=${fileHash})`); + } + } + log(ok ? 'info' : 'warn', `commit HTTP ${response.status}`, { + blake3: fileHash, + uploadedBytes, + reusedBytes, + totalBytes: file.size, + attempt, + }); + // Include the final counters + file hash on the done envelope + // so the orchestrator's summary is accurate even when the last + // throttled progress() got skipped (fast dedup-heavy paths + // complete under 150ms — progress' throttle window — so + // reusedBytes never surfaced via a progress message). + workerScope.postMessage({ + type: 'done', + status: response.status, + body, + reusedBytes, + uploadedBytes, + fileHash, + }); return; } } catch (err) {