3dtours/SonicForgeStudio
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

debug: add detailed tracing logs for entire SF download→SpessaSynth flow

Browse Source
This commit is contained in:
3dtours
2026-07-26 20:05:34 +07:00
parent 6242eba3c8
commit 5eb0c26ce4
2 changed files with 107 additions and 55 deletions
Download Patch File Download Diff File Expand all files Collapse all files
app/api/v1/plugins.py
+7 -6
View File
@@ -127,22 +127,23 @@ async def delete_soundfont(sf_id: str, current_user: dict = Depends(get_current_
@router.get("/soundfonts/download/{sf_id}") @router.get("/soundfonts/download/{sf_id}")
async def download_soundfont_asset(sf_id: str): 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 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]: for base_dir in [UPLOAD_SF_DIR, SYSTEM_SF_DIR]:
if not os.path.isdir(base_dir): if not os.path.isdir(base_dir):
_log.info(f"[DOWNLOAD_DEBUG] dir NOT_FOUND: {base_dir}")
continue continue
for ext in [".sf2", ".sf3"]: for ext in [".sf2", ".sf3"]:
for fname in os.listdir(base_dir): for fname in os.listdir(base_dir):
fbase, fext = os.path.splitext(fname) fbase, fext = os.path.splitext(fname)
if fext.lower() == ext and fbase.lower() == clean_id.lower(): if fext.lower() == ext and fbase.lower() == clean_id.lower():
full = os.path.join(base_dir, fname) 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}") return FileResponse(full, media_type="application/octet-stream", filename=f"soundfont{ext}")
# Fallback: try exact match on sf_id _log.warning(f"[DOWNLOAD_DEBUG] NOT_FOUND for {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}")
raise HTTPException(status_code=404, detail="SoundFont asset not found") raise HTTPException(status_code=404, detail="SoundFont asset not found")
app/static/js/services/soundfontPlayer.js
+100 -49
View File
@@ -34,22 +34,24 @@
let _synthInstance = null; let _synthInstance = null;
let _initialized = false; let _initialized = false;
let _currentSfId = null; 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) { async function _addBankWithTimeout(synth, buffer, sfId, timeoutMs) {
console.log("[SonicSF][DEBUG] _addBankWithTimeout start sfId=" + sfId + " size=" + buffer.byteLength + " timeout=" + timeoutMs);
return new Promise((resolve) => { return new Promise((resolve) => {
const timer = setTimeout(() => { const timer = setTimeout(() => {
console.warn("[SonicSF] addSoundBank timeout after", timeoutMs, "ms"); console.warn("[SonicSF][DEBUG] _addBankWithTimeout TIMEOUT after " + timeoutMs + "ms for " + sfId);
resolve(false); resolve(false);
}, timeoutMs); }, timeoutMs);
synth.soundBankManager.addSoundBank(buffer.slice(0), sfId).then(() => { synth.soundBankManager.addSoundBank(buffer.slice(0), sfId).then(() => {
clearTimeout(timer); clearTimeout(timer);
const bl = synth.soundBankManager?.soundBankList?.length ?? 0;
console.log("[SonicSF][DEBUG] _addBankWithTimeout SUCCESS for " + sfId + " banks=" + bl);
resolve(true); resolve(true);
}).catch((err) => { }).catch((err) => {
clearTimeout(timer); clearTimeout(timer);
console.error("[SonicSF] addSoundBank rejected:", err); console.error("[SonicSF][DEBUG] _addBankWithTimeout REJECTED for " + sfId + " error=" + err);
resolve(false); resolve(false);
}); });
}); });
@@ -58,74 +60,117 @@
const SonicSF = { const SonicSF = {
loadedFonts: {}, loadedFonts: {},
// ══════════════════════════════════════════════════ // ════════════════════════════════════════════════
// PHASE 1: Init SpessaSynth Engine (FlowClient.md 1.1) // PHASE 1: Init SpessaSynth
// ══════════════════════════════════════════════════ // ════════════════════════════════════════════════
init: async function (audioContext) { init: async function (audioContext) {
console.log("[SonicSF][DEBUG] PHASE1: init start");
if (!window.SpessaSynthClass || !window.__SpessaSynthCDN) { if (!window.SpessaSynthClass || !window.__SpessaSynthCDN) {
console.warn("[SonicSF] SpessaSynth CDN not available. Using oscillator."); console.warn("[SonicSF][DEBUG] PHASE1: SpessaSynth CDN not available");
return; return;
} }
try { try {
console.log("[SonicSF][DEBUG] PHASE1: loading worklet from " + window.__SpessaSynthCDN + "spessasynth_processor.min.js");
const procUrl = window.__SpessaSynthCDN + "spessasynth_processor.min.js"; const procUrl = window.__SpessaSynthCDN + "spessasynth_processor.min.js";
await audioContext.audioWorklet.addModule(procUrl); await audioContext.audioWorklet.addModule(procUrl);
console.log("[SonicSF][DEBUG] PHASE1: worklet loaded, creating WorkletSynthesizer");
_synthInstance = new window.SpessaSynthClass(audioContext); _synthInstance = new window.SpessaSynthClass(audioContext);
console.log("[SonicSF][DEBUG] PHASE1: connecting to destination");
_synthInstance.connect(audioContext.destination); _synthInstance.connect(audioContext.destination);
console.log("[SonicSF][DEBUG] PHASE1: awaiting isReady");
await _synthInstance.isReady; await _synthInstance.isReady;
_initialized = true; _initialized = true;
console.log("[SonicSF] SpessaSynth engine ready."); console.log("[SonicSF][DEBUG] PHASE1: SpessaSynth engine ready. isReady resolved.");
} catch (e) { } catch (e) {
console.warn("[SonicSF] AudioWorklet failed:", e); console.warn("[SonicSF][DEBUG] PHASE1: AudioWorklet failed:", e);
try { 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"); const mod = await import("https://cdn.jsdelivr.net/npm/spessasynth_lib@4.3.1/dist/index.js");
_synthInstance = new mod.WorkerSynthesizer(audioContext); _synthInstance = new mod.WorkerSynthesizer(audioContext);
_synthInstance.connect(audioContext.destination); _synthInstance.connect(audioContext.destination);
await _synthInstance.isReady; await _synthInstance.isReady;
_initialized = true; _initialized = true;
console.log("[SonicSF] WorkerSynthesizer ready."); console.log("[SonicSF][DEBUG] PHASE1: WorkerSynthesizer ready.");
} catch (e2) { } 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) { loadSoundFont: async function (sfId) {
if (!_initialized || !_synthInstance) return false; console.log("[SonicSF][DEBUG] PHASE2: loadSoundFont start sfId=" + sfId + " _initialized=" + _initialized + " _currentSfId=" + _currentSfId);
if (_currentSfId === sfId) return true; if (!_initialized || !_synthInstance) {
console.log("[SonicSF] Loading SoundFont:", sfId); 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; let buffer = null;
// Step 2a: Check IndexedDB cache
if (window.SonicSFStorage) { if (window.SonicSFStorage) {
console.log("[SonicSF][DEBUG] PHASE2a: checking IndexedDB for " + sfId);
buffer = await window.SonicSFStorage.getBuffer(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) { if (!buffer) {
try { try {
const url = "/api/v1/plugins/soundfonts/download/" + encodeURIComponent(sfId) + "?t=" + Date.now(); 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); 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); if (!resp.ok) throw new Error("HTTP " + resp.status);
buffer = await resp.arrayBuffer(); 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) { if (window.SonicSFStorage) {
console.log("[SonicSF][DEBUG] PHASE2c: saving to IndexedDB");
await window.SonicSFStorage.saveBuffer(sfId, buffer); await window.SonicSFStorage.saveBuffer(sfId, buffer);
console.log("[SonicSF][DEBUG] PHASE2c: saved to IndexedDB OK");
} }
} catch (e) { } catch (e) {
console.error("[SonicSF] Download failed:", sfId, e); console.error("[SonicSF][DEBUG] PHASE2b: download FAILED for " + sfId + ": " + e);
return false; 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); const ok = await _addBankWithTimeout(_synthInstance, buffer, sfId, 15000);
if (ok) { if (ok) {
_currentSfId = sfId; _currentSfId = sfId;
_bankLoadedCount = _synthInstance.soundBankManager?.soundBankList?.length ?? 0; const bankCount = _synthInstance.soundBankManager?.soundBankList?.length ?? 0;
console.log("[SonicSF] SoundFont loaded:", sfId, "- banks:", _bankLoadedCount); 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; return true;
} else { } 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) { if (window.SonicSFStorage) {
try { try {
const db = await window.SonicSFStorage.openDB(); 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) { selectInstrument: async function (channel, bank, program, sfId) {
if (!_initialized || !_synthInstance) return; console.log("[SonicSF][DEBUG] PHASE3: selectInstrument ch=" + channel + " bank=" + bank + " prog=" + program + " sf=" + sfId + " _initialized=" + _initialized);
// Phase 2: ensure SoundFont is loaded if (!_initialized || !_synthInstance) {
console.log("[SonicSF][DEBUG] PHASE3: engine not ready, returning");
return;
}
// Phase 2 first: ensure SoundFont is loaded
if (sfId) { if (sfId) {
const loaded = await this.loadSoundFont(sfId); const loaded = await this.loadSoundFont(sfId);
if (!loaded) { if (!loaded) {
console.warn("[SonicSF] selectInstrument: no SoundFont loaded, ch", channel); console.warn("[SonicSF][DEBUG] PHASE3: loadSoundFont returned false, no bank to select");
return; return;
} }
} }
// Phase 3a: controllerChange(CC0) → bank MSB // Send CC0 + CC32 + Program Change
try { _synthInstance.controllerChange(channel, 0, bank); } catch (e) {} console.log("[SonicSF][DEBUG] PHASE3: sending controllerChange(ch=" + channel + ", cc=0, val=" + bank + ")");
// Phase 3b: controllerChange(CC32) → bank LSB try { _synthInstance.controllerChange(channel, 0, bank); } catch (e) { console.warn("[SonicSF][DEBUG] PHASE3: CC0 error:", e); }
try { _synthInstance.controllerChange(channel, 32, 0); } catch (e) {} console.log("[SonicSF][DEBUG] PHASE3: sending controllerChange(ch=" + channel + ", cc=32, val=0)");
// Phase 3c: programChange try { _synthInstance.controllerChange(channel, 32, 0); } catch (e) { console.warn("[SonicSF][DEBUG] PHASE3: CC32 error:", e); }
try { _synthInstance.programChange(channel, program); } catch (e) {} console.log("[SonicSF][DEBUG] PHASE3: sending programChange(ch=" + channel + ", prog=" + program + ")");
// Phase 3d: update SonicSF internal state 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.controllerChange(channel, 0, bank);
this.programChange(channel, program); 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) { controllerChange: function (channel, controller, value) {
if (channel < 0 || channel > 15) return; if (channel < 0 || channel > 15) return;
if (_initialized && _synthInstance) { if (_initialized && _synthInstance) {
@@ -208,8 +260,6 @@
}, },
playNote: function (note, velocity, durationMs, startTime, program, destinationNode, channel, synthEngine) { 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 (_initialized && _synthInstance && _currentSfId) {
if (synthEngine) { if (synthEngine) {
const ch = channel !== undefined ? channel : (synthEngine.soundfont_bank === 128 ? 9 : 0); const ch = channel !== undefined ? channel : (synthEngine.soundfont_bank === 128 ? 9 : 0);
@@ -219,13 +269,15 @@
if (channel === undefined) channel = ch; if (channel === undefined) channel = ch;
} }
if (channel === undefined) channel = 0; 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 { try {
this._playNoteSpessa(note, velocity, durationMs, channel); this._playNoteSpessa(note, velocity, durationMs, channel);
return; return;
} catch (e) { } 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); this._playNoteOsc(note, velocity, durationMs, startTime, program, destinationNode, channel, synthEngine);
}, },
@@ -237,14 +289,13 @@
typeof velocity === 'number' ? (velocity > 1 ? velocity : velocity * 127) : 100 typeof velocity === 'number' ? (velocity > 1 ? velocity : velocity * 127) : 100
))); )));
const durSec = durationMs / 1000; const durSec = durationMs / 1000;
console.log("[SonicSF][DEBUG] PHASE4: noteOn ch=" + channel + " pitch=" + midiPitch + " vel=" + midiVel + " banks=" + (_synthInstance.soundBankManager?.soundBankList?.length ?? 0));
const doNoteOn = () => { const doNoteOn = () => {
try { 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); _synthInstance.noteOn(channel, midiPitch, midiVel);
setTimeout(() => { try { _synthInstance.noteOff(channel, midiPitch); } catch (e) {} }, durSec * 1000); setTimeout(() => { try { _synthInstance.noteOff(channel, midiPitch); } catch (e) {} }, durSec * 1000);
} catch (e) { } catch (e) {
console.warn("[SonicSF] noteOn failed:", e); console.warn("[SonicSF][DEBUG] PHASE4: noteOn threw:", e);
} }
}; };
doNoteOn(); doNoteOn();