From 5eb0c26ce4328af9830d2b959140f2a5e09100f1 Mon Sep 17 00:00:00 2001 From: 3dtours Date: Sun, 26 Jul 2026 20:05:34 +0700 Subject: [PATCH] =?UTF-8?q?debug:=20add=20detailed=20tracing=20logs=20for?= =?UTF-8?q?=20entire=20SF=20download=E2=86=92SpessaSynth=20flow?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- app/api/v1/plugins.py | 13 +- app/static/js/services/soundfontPlayer.js | 149 +++++++++++++++------- 2 files changed, 107 insertions(+), 55 deletions(-) diff --git a/app/api/v1/plugins.py b/app/api/v1/plugins.py index 074cd5d..d18a5f3 100644 --- a/app/api/v1/plugins.py +++ b/app/api/v1/plugins.py @@ -127,22 +127,23 @@ async def delete_soundfont(sf_id: str, current_user: dict = Depends(get_current_ @router.get("/soundfonts/download/{sf_id}") async def download_soundfont_asset(sf_id: str): + import logging as _lg + _log = _lg.getLogger("uvicorn.access") clean_id = sf_id.replace("sf_", "") if sf_id.startswith("sf_") else sf_id + _log.info(f"[DOWNLOAD_DEBUG] sf_id={sf_id} clean_id={clean_id}") for base_dir in [UPLOAD_SF_DIR, SYSTEM_SF_DIR]: if not os.path.isdir(base_dir): + _log.info(f"[DOWNLOAD_DEBUG] dir NOT_FOUND: {base_dir}") continue for ext in [".sf2", ".sf3"]: for fname in os.listdir(base_dir): fbase, fext = os.path.splitext(fname) if fext.lower() == ext and fbase.lower() == clean_id.lower(): full = os.path.join(base_dir, fname) + sz = os.path.getsize(full) + _log.info(f"[DOWNLOAD_DEBUG] SERVING: {full} ext={ext} size={sz}") return FileResponse(full, media_type="application/octet-stream", filename=f"soundfont{ext}") - # Fallback: try exact match on sf_id - for base_dir in [UPLOAD_SF_DIR, SYSTEM_SF_DIR]: - for ext in [".sf2", ".sf3"]: - full = os.path.join(base_dir, clean_id + ext) - if os.path.exists(full): - return FileResponse(full, media_type="application/octet-stream", filename=f"soundfont{ext}") + _log.warning(f"[DOWNLOAD_DEBUG] NOT_FOUND for {sf_id}") raise HTTPException(status_code=404, detail="SoundFont asset not found") diff --git a/app/static/js/services/soundfontPlayer.js b/app/static/js/services/soundfontPlayer.js index cb5385a..3404253 100644 --- a/app/static/js/services/soundfontPlayer.js +++ b/app/static/js/services/soundfontPlayer.js @@ -34,22 +34,24 @@ let _synthInstance = null; let _initialized = false; let _currentSfId = null; - let _bankLoadedCount = 0; - // ── addSoundBank with timeout (SpessaSynth hangs on parse error) ── + // ── SpessaSynth addSoundBank wrapper with timeout ── async function _addBankWithTimeout(synth, buffer, sfId, timeoutMs) { + console.log("[SonicSF][DEBUG] _addBankWithTimeout start sfId=" + sfId + " size=" + buffer.byteLength + " timeout=" + timeoutMs); return new Promise((resolve) => { const timer = setTimeout(() => { - console.warn("[SonicSF] addSoundBank timeout after", timeoutMs, "ms"); + console.warn("[SonicSF][DEBUG] _addBankWithTimeout TIMEOUT after " + timeoutMs + "ms for " + sfId); resolve(false); }, timeoutMs); synth.soundBankManager.addSoundBank(buffer.slice(0), sfId).then(() => { clearTimeout(timer); + const bl = synth.soundBankManager?.soundBankList?.length ?? 0; + console.log("[SonicSF][DEBUG] _addBankWithTimeout SUCCESS for " + sfId + " banks=" + bl); resolve(true); }).catch((err) => { clearTimeout(timer); - console.error("[SonicSF] addSoundBank rejected:", err); + console.error("[SonicSF][DEBUG] _addBankWithTimeout REJECTED for " + sfId + " error=" + err); resolve(false); }); }); @@ -58,74 +60,117 @@ const SonicSF = { loadedFonts: {}, - // ══════════════════════════════════════════════════ - // PHASE 1: Init SpessaSynth Engine (FlowClient.md 1.1) - // ══════════════════════════════════════════════════ + // ════════════════════════════════════════════════ + // PHASE 1: Init SpessaSynth + // ════════════════════════════════════════════════ init: async function (audioContext) { + console.log("[SonicSF][DEBUG] PHASE1: init start"); if (!window.SpessaSynthClass || !window.__SpessaSynthCDN) { - console.warn("[SonicSF] SpessaSynth CDN not available. Using oscillator."); + console.warn("[SonicSF][DEBUG] PHASE1: SpessaSynth CDN not available"); return; } try { + console.log("[SonicSF][DEBUG] PHASE1: loading worklet from " + window.__SpessaSynthCDN + "spessasynth_processor.min.js"); const procUrl = window.__SpessaSynthCDN + "spessasynth_processor.min.js"; await audioContext.audioWorklet.addModule(procUrl); + console.log("[SonicSF][DEBUG] PHASE1: worklet loaded, creating WorkletSynthesizer"); _synthInstance = new window.SpessaSynthClass(audioContext); + console.log("[SonicSF][DEBUG] PHASE1: connecting to destination"); _synthInstance.connect(audioContext.destination); + console.log("[SonicSF][DEBUG] PHASE1: awaiting isReady"); await _synthInstance.isReady; _initialized = true; - console.log("[SonicSF] SpessaSynth engine ready."); + console.log("[SonicSF][DEBUG] PHASE1: SpessaSynth engine ready. isReady resolved."); } catch (e) { - console.warn("[SonicSF] AudioWorklet failed:", e); + console.warn("[SonicSF][DEBUG] PHASE1: AudioWorklet failed:", e); try { + console.log("[SonicSF][DEBUG] PHASE1: trying WorkerSynthesizer"); const mod = await import("https://cdn.jsdelivr.net/npm/spessasynth_lib@4.3.1/dist/index.js"); _synthInstance = new mod.WorkerSynthesizer(audioContext); _synthInstance.connect(audioContext.destination); await _synthInstance.isReady; _initialized = true; - console.log("[SonicSF] WorkerSynthesizer ready."); + console.log("[SonicSF][DEBUG] PHASE1: WorkerSynthesizer ready."); } catch (e2) { - console.error("[SonicSF] All SpessaSynth paths failed:", e2); + console.error("[SonicSF][DEBUG] PHASE1: All paths failed:", e2); } } }, - // ══════════════════════════════════════════════════ - // PHASE 2: Load SF3/SF2 → IndexedDB → SpessaSynth (FlowClient.md 2.) - // ══════════════════════════════════════════════════ + // ════════════════════════════════════════════════ + // PHASE 2: Load SF → IndexedDB → SpessaSynth + // ════════════════════════════════════════════════ loadSoundFont: async function (sfId) { - if (!_initialized || !_synthInstance) return false; - if (_currentSfId === sfId) return true; - console.log("[SonicSF] Loading SoundFont:", sfId); + console.log("[SonicSF][DEBUG] PHASE2: loadSoundFont start sfId=" + sfId + " _initialized=" + _initialized + " _currentSfId=" + _currentSfId); + if (!_initialized || !_synthInstance) { + console.log("[SonicSF][DEBUG] PHASE2: engine not ready, returning false"); + return false; + } + if (_currentSfId === sfId) { + console.log("[SonicSF][DEBUG] PHASE2: already loaded, returning true"); + return true; + } let buffer = null; + // Step 2a: Check IndexedDB cache if (window.SonicSFStorage) { + console.log("[SonicSF][DEBUG] PHASE2a: checking IndexedDB for " + sfId); buffer = await window.SonicSFStorage.getBuffer(sfId); - if (buffer) console.log("[SonicSF] Cache HIT for", sfId, buffer.byteLength, "bytes"); + if (buffer) { + console.log("[SonicSF][DEBUG] PHASE2a: IndexedDB HIT size=" + buffer.byteLength); + } else { + console.log("[SonicSF][DEBUG] PHASE2a: IndexedDB MISS"); + } } + + // Step 2b: Download from server if (!buffer) { try { const url = "/api/v1/plugins/soundfonts/download/" + encodeURIComponent(sfId) + "?t=" + Date.now(); + console.log("[SonicSF][DEBUG] PHASE2b: fetching from server url=" + url); const resp = await fetch(url); + console.log("[SonicSF][DEBUG] PHASE2b: server response status=" + resp.status + " type=" + resp.headers.get("content-type") + " size=" + resp.headers.get("content-length")); if (!resp.ok) throw new Error("HTTP " + resp.status); buffer = await resp.arrayBuffer(); - console.log("[SonicSF] Downloaded", sfId, buffer.byteLength, "bytes"); + console.log("[SonicSF][DEBUG] PHASE2b: downloaded " + buffer.byteLength + " bytes for " + sfId); + + // Step 2c: Save to IndexedDB if (window.SonicSFStorage) { + console.log("[SonicSF][DEBUG] PHASE2c: saving to IndexedDB"); await window.SonicSFStorage.saveBuffer(sfId, buffer); + console.log("[SonicSF][DEBUG] PHASE2c: saved to IndexedDB OK"); } } catch (e) { - console.error("[SonicSF] Download failed:", sfId, e); + console.error("[SonicSF][DEBUG] PHASE2b: download FAILED for " + sfId + ": " + e); return false; } } - // Load into SpessaSynth with 15s timeout + + // Step 2d: Load ArrayBuffer into SpessaSynth Engine + console.log("[SonicSF][DEBUG] PHASE2d: calling addSoundBank for " + sfId + " size=" + buffer.byteLength); const ok = await _addBankWithTimeout(_synthInstance, buffer, sfId, 15000); if (ok) { _currentSfId = sfId; - _bankLoadedCount = _synthInstance.soundBankManager?.soundBankList?.length ?? 0; - console.log("[SonicSF] SoundFont loaded:", sfId, "- banks:", _bankLoadedCount); + const bankCount = _synthInstance.soundBankManager?.soundBankList?.length ?? 0; + console.log("[SonicSF][DEBUG] PHASE2d: addSoundBank SUCCESS. _currentSfId=" + _currentSfId + " total banks=" + bankCount); + // Try to enumerate presets from loaded bank + try { + const presetList = _synthInstance.soundBankManager?.soundBankList?.[0]?.soundBank?.presets; + if (presetList) { + console.log("[SonicSF][DEBUG] PHASE2d: presets in loaded bank=" + presetList.length); + for (let i = 0; i < Math.min(presetList.length, 10); i++) { + const p = presetList[i]; + console.log("[SonicSF][DEBUG] PHASE2d: preset[" + i + "] name=" + p.name + " bank=" + p.bankMSB + "/" + p.bankLSB + " prog=" + p.program + " drum=" + p.isGMGSDrum); + } + } else { + console.warn("[SonicSF][DEBUG] PHASE2d: soundBankList[0].soundBank.presets is UNDEFINED or EMPTY"); + } + } catch (e) { + console.warn("[SonicSF][DEBUG] PHASE2d: preset enumeration failed:", e); + } return true; } else { - console.warn("[SonicSF] SoundFont load FAILED:", sfId, "- using oscillator fallback"); + console.warn("[SonicSF][DEBUG] PHASE2d: addSoundBank FAILED for " + sfId + ". Clearing IndexedDB cache."); if (window.SonicSFStorage) { try { const db = await window.SonicSFStorage.openDB(); @@ -138,34 +183,41 @@ } }, - // ══════════════════════════════════════════════════ - // PHASE 3: Set up MIDI Channel (FlowClient.md 3.) - // ══════════════════════════════════════════════════ + // ════════════════════════════════════════════════ + // PHASE 3: Set up MIDI Channel (bank/program route) + // ════════════════════════════════════════════════ selectInstrument: async function (channel, bank, program, sfId) { - if (!_initialized || !_synthInstance) return; - // Phase 2: ensure SoundFont is loaded + console.log("[SonicSF][DEBUG] PHASE3: selectInstrument ch=" + channel + " bank=" + bank + " prog=" + program + " sf=" + sfId + " _initialized=" + _initialized); + if (!_initialized || !_synthInstance) { + console.log("[SonicSF][DEBUG] PHASE3: engine not ready, returning"); + return; + } + // Phase 2 first: ensure SoundFont is loaded if (sfId) { const loaded = await this.loadSoundFont(sfId); if (!loaded) { - console.warn("[SonicSF] selectInstrument: no SoundFont loaded, ch", channel); + console.warn("[SonicSF][DEBUG] PHASE3: loadSoundFont returned false, no bank to select"); return; } } - // Phase 3a: controllerChange(CC0) → bank MSB - try { _synthInstance.controllerChange(channel, 0, bank); } catch (e) {} - // Phase 3b: controllerChange(CC32) → bank LSB - try { _synthInstance.controllerChange(channel, 32, 0); } catch (e) {} - // Phase 3c: programChange - try { _synthInstance.programChange(channel, program); } catch (e) {} - // Phase 3d: update SonicSF internal state + // Send CC0 + CC32 + Program Change + console.log("[SonicSF][DEBUG] PHASE3: sending controllerChange(ch=" + channel + ", cc=0, val=" + bank + ")"); + try { _synthInstance.controllerChange(channel, 0, bank); } catch (e) { console.warn("[SonicSF][DEBUG] PHASE3: CC0 error:", e); } + console.log("[SonicSF][DEBUG] PHASE3: sending controllerChange(ch=" + channel + ", cc=32, val=0)"); + try { _synthInstance.controllerChange(channel, 32, 0); } catch (e) { console.warn("[SonicSF][DEBUG] PHASE3: CC32 error:", e); } + console.log("[SonicSF][DEBUG] PHASE3: sending programChange(ch=" + channel + ", prog=" + program + ")"); + try { _synthInstance.programChange(channel, program); } catch (e) { console.warn("[SonicSF][DEBUG] PHASE3: progChange error:", e); } + // Update internal SonicSF state this.controllerChange(channel, 0, bank); this.programChange(channel, program); - console.log("[SonicSF] Switched Channel", channel, "-> Bank:", bank, ", Program:", program, ", SF:", sfId); + // Verify the sound bank list + const bl = _synthInstance.soundBankManager?.soundBankList?.length ?? 0; + console.log("[SonicSF][DEBUG] PHASE3: complete. total banks=" + bl + " _currentSfId=" + _currentSfId); }, - // ══════════════════════════════════════════════════ - // PHASE 4: Play MIDI Note (FlowClient.md 3.) - // ══════════════════════════════════════════════════ + // ════════════════════════════════════════════════ + // PHASE 4: Play Note + // ════════════════════════════════════════════════ controllerChange: function (channel, controller, value) { if (channel < 0 || channel > 15) return; if (_initialized && _synthInstance) { @@ -208,8 +260,6 @@ }, playNote: function (note, velocity, durationMs, startTime, program, destinationNode, channel, synthEngine) { - // TEMP: always use oscillator for reliable preview - // SpessaSynth path: only when bank is confirmed loaded if (_initialized && _synthInstance && _currentSfId) { if (synthEngine) { const ch = channel !== undefined ? channel : (synthEngine.soundfont_bank === 128 ? 9 : 0); @@ -219,13 +269,15 @@ if (channel === undefined) channel = ch; } if (channel === undefined) channel = 0; - // Try SpessaSynth, fallback to oscillator on error + console.log("[SonicSF][DEBUG] PHASE4: playNote via SpessaSynth ch=" + channel + " note=" + note + " vel=" + velocity + " _currentSfId=" + _currentSfId); try { this._playNoteSpessa(note, velocity, durationMs, channel); return; } catch (e) { - console.warn("[SonicSF] SpessaSynth play failed, fallback:", e); + console.warn("[SonicSF][DEBUG] PHASE4: SpessaSynth play failed, oscillator fallback:", e); } + } else { + console.log("[SonicSF][DEBUG] PHASE4: playNote via oscillator (init=" + _initialized + " sf=" + _currentSfId + ")"); } this._playNoteOsc(note, velocity, durationMs, startTime, program, destinationNode, channel, synthEngine); }, @@ -237,14 +289,13 @@ typeof velocity === 'number' ? (velocity > 1 ? velocity : velocity * 127) : 100 ))); const durSec = durationMs / 1000; + console.log("[SonicSF][DEBUG] PHASE4: noteOn ch=" + channel + " pitch=" + midiPitch + " vel=" + midiVel + " banks=" + (_synthInstance.soundBankManager?.soundBankList?.length ?? 0)); const doNoteOn = () => { try { - const bl = _synthInstance.soundBankManager?.soundBankList?.length ?? 0; - console.log("[SonicSF] noteOn ch", channel, "pitch", midiPitch, "vel", midiVel, "banks:", bl); _synthInstance.noteOn(channel, midiPitch, midiVel); setTimeout(() => { try { _synthInstance.noteOff(channel, midiPitch); } catch (e) {} }, durSec * 1000); } catch (e) { - console.warn("[SonicSF] noteOn failed:", e); + console.warn("[SonicSF][DEBUG] PHASE4: noteOn threw:", e); } }; doNoteOn();