feat(ui): add a logger to change log level and permit better diagnostics
in this case logs are added in the delta upload worker
you can increase verbosity from console via:
```javascript
// Usage:
oxi.setLogLevel('oxi:upload', 'debug') // deep dive
oxi.setLogLevel('oxi:upload', 'warn') // quiet
oxi.log.setLevel('debug') // everything to debug
```
values are stored in localstorage
example:
```
oxi.setLogLevel('oxi:upload', 'debug');
'oxi:upload → debug'
deltaUpload.ts:120 [f32ce1] delta start {file: 'Revue de presseg.odp', size: 23658927}
deltaUpload.ts:185 [f32ce1] worker: worker start {file: 'Revue de presseg.odp', size: 23658927}
deltaUpload.ts:186 [f32ce1] worker: wasm loaded
deltaUpload.ts:186 [f32ce1] worker: hashed — blake3=150edbc35f3475a0bdeecd15fe5278dda305ce3b27e53e9c40515a69f0b883f3 (76 chunks)
deltaUpload.ts:186 [f32ce1] worker: negotiate: 76 hashes → 76 missing, 0 dedup'd
deltaUpload.ts:186 [f32ce1] worker: chunk PUT: 28 chunks, 8825338 bytes
deltaUpload.ts:186 [f32ce1] worker: chunk PUT: 29 chunks, 8950230 bytes
deltaUpload.ts:186 [f32ce1] worker: chunk PUT: 19 chunks, 5883663 bytes
deltaUpload.ts:186 [f32ce1] worker: ✅ committed — uploaded 23 658 927 B (no dedup, blake3=150edbc35f3475a0bdeecd15fe5278dda305ce3b27e53e9c40515a69f0b883f3)
deltaUpload.ts:185 [f32ce1] worker: commit HTTP 201 {blake3: '150edbc35f3475a0bdeecd15fe5278dda305ce3b27e53e9c40515a69f0b883f3', uploadedBytes: 23658927, reusedBytes: 0, totalBytes: 23658927, attempt: 0}
deltaUpload.ts:213 [f32ce1] delta done {file: 'Revue de presseg.odp', blake3: '150edbc35f3475a0bdeecd15fe5278dda305ce3b27e53e9c40515a69f0b883f3', savedBytes: 0, uploadedBytes: 23658927}
```
This commit is contained in:
Generated
+15
-1
@@ -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",
|
||||
|
||||
@@ -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"
|
||||
}
|
||||
}
|
||||
|
||||
@@ -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:<namespace>']` 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<string, string>;
|
||||
};
|
||||
}
|
||||
}
|
||||
|
||||
export async function init(): Promise<void> {
|
||||
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<string, string> = {};
|
||||
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') {
|
||||
|
||||
@@ -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<string, unknown>;
|
||||
}
|
||||
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<DeltaUploadAnswer | null> {
|
||||
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<WorkerMsg>) => {
|
||||
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);
|
||||
};
|
||||
|
||||
|
||||
@@ -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<string, unknown>=} 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<string, string>} */
|
||||
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) {
|
||||
|
||||
Reference in New Issue
Block a user