diff --git a/core/streaming/prepare.py b/core/streaming/prepare.py index b22b763d..942d0288 100644 --- a/core/streaming/prepare.py +++ b/core/streaming/prepare.py @@ -31,14 +31,18 @@ from __future__ import annotations import asyncio import glob -import logging import os import shutil import time from dataclasses import dataclass from typing import Any, Callable -logger = logging.getLogger(__name__) +from utils.logging_config import get_logger + +# Must live under the soulsync.* namespace — handlers are only attached there, +# so a bare getLogger(__name__) ("core.streaming.prepare") logged into the void +# and made stream-prep failures invisible in app.log. +logger = get_logger("streaming.prepare") @dataclass diff --git a/tests/streaming/test_prepare.py b/tests/streaming/test_prepare.py index f33d7680..d86aa7ea 100644 --- a/tests/streaming/test_prepare.py +++ b/tests/streaming/test_prepare.py @@ -200,3 +200,18 @@ def test_worker_drives_a_real_stream_session(tmp_path): assert session['status'] == 'error' assert 'Failed to initiate' in session['error_message'] assert session['track_info'] == {'username': 'u', 'filename': 'song.flac', 'size': 1} + + +# --------------------------------------------------------------------------- +# Observability: prep logs must actually reach app.log +# --------------------------------------------------------------------------- + +def test_prepare_logger_is_in_soulsync_namespace(): + """Handlers only attach to the soulsync.* hierarchy. A bare + getLogger(__name__) gave this module a 'core.streaming.prepare' logger with + no handler — every prep log (including failures) vanished, which made the + broken-stream report undebuggable from app.log. Lock the namespace.""" + assert sp.logger.name.startswith('soulsync.'), ( + f"prepare logger '{sp.logger.name}' is outside the soulsync.* namespace " + "— its output never reaches app.log" + ) diff --git a/web_server.py b/web_server.py index 24fdf547..b40c2509 100644 --- a/web_server.py +++ b/web_server.py @@ -35129,17 +35129,13 @@ def _emit_tool_progress_loop(): """Background thread that pushes all tool progress statuses every 1 second.""" while not globals().get('IS_SHUTTING_DOWN', False): socketio.sleep(1) - # Stream status - try: - with stream_lock: - socketio.emit('tool:stream', { - "status": stream_state["status"], - "progress": stream_state["progress"], - "track_info": stream_state["track_info"], - "error_message": stream_state["error_message"] - }) - except Exception as e: - logger.debug(f"Error emitting stream status: {e}") + # NOTE: no 'tool:stream' broadcast here. Stream state is PER-LISTENER + # (Phase 3b sessions) and this thread has no request context, so it can + # only ever read the DEFAULT session — which no real browser uses. The + # old global emit told every client "stopped" forever, and the player + # (which skipped HTTP polling while the socket was up) never learned + # its stream was ready. Each client polls /api/stream/status instead, + # which resolves its own session from the cookie. # Quality Scanner try: with quality_scanner_lock: diff --git a/webui/static/core.js b/webui/static/core.js index 44681920..c550b612 100644 --- a/webui/static/core.js +++ b/webui/static/core.js @@ -484,7 +484,9 @@ function initializeWebSocket() { }); // Phase 4 event listeners (tool progress) - socket.on('tool:stream', (data) => updateStreamStatusFromData(data)); + // 'tool:stream' is intentionally NOT wired: stream state is per-listener + // (session cookie), so the global broadcast could only carry the DEFAULT + // session's eternal "stopped" — the player polls /api/stream/status instead. socket.on('tool:quality-scanner', (data) => updateQualityScanProgressFromData(data)); socket.on('tool:duplicate-cleaner', (data) => updateDuplicateCleanProgressFromData(data)); socket.on('tool:db-update', (data) => updateDbProgressFromData(data)); diff --git a/webui/static/media-player.js b/webui/static/media-player.js index 2408ed3f..7da43aa8 100644 --- a/webui/static/media-player.js +++ b/webui/static/media-player.js @@ -597,7 +597,11 @@ function updateWishlistStatsFromData(data) { } async function updateStreamStatus() { - if (socketConnected) return; // WebSocket handles this + // Always poll over HTTP: stream state is per-listener (resolved from the + // session cookie), and the old global 'tool:stream' socket broadcast could + // only see the DEFAULT session — it told every real browser "stopped" + // forever while this poller deferred to it. The poller only runs while a + // stream is being prepared, so the 1s fetch is negligible. // Poll server for streaming progress and handle state changes with enhanced error recovery try { const controller = new AbortController(); @@ -709,66 +713,11 @@ async function updateStreamStatus() { } } -function updateStreamStatusFromData(data) { - const prev = _lastToolStatus['stream']; - _lastToolStatus['stream'] = data.status; - // Skip repeated terminal states to avoid duplicate toasts/actions - if (prev !== undefined && data.status === prev && data.status !== 'loading' && data.status !== 'queued') return; - - currentStream.status = data.status; - currentStream.progress = data.progress; - - switch (data.status) { - case 'loading': - setLoadingProgress(data.progress); - const loadingText = document.querySelector('.loading-text'); - if (loadingText && data.progress > 0) { - loadingText.textContent = `Downloading... ${Math.round(data.progress)}%`; - } - break; - case 'queued': - const queueText = document.querySelector('.loading-text'); - if (queueText) { - queueText.textContent = 'Queuing with uploader...'; - } - setLoadingProgress(0); - break; - case 'ready': - console.log('🎵 Stream ready, starting audio playback'); - stopStreamStatusPolling(); - // Restore player UI if JS state was wiped (e.g. page refresh) - if (!currentTrack && data.track_info) { - const ti = data.track_info; - setTrackInfo({ - title: ti.name || ti.title || 'Unknown Track', - artist: ti.artist || 'Unknown Artist', - album: ti.album || 'Unknown Album', - filename: ti.filename || '', - is_library: !!ti.is_library, - image_url: ti.image_url || null, - id: ti.id || null, - artist_id: ti.artist_id || null, - album_id: ti.album_id || null, - }); - } - startAudioPlayback(); - break; - case 'error': - console.error('❌ Streaming error:', data.error_message); - stopStreamStatusPolling(); - hideLoadingAnimation(); - showToast(`Streaming error: ${data.error_message || 'Unknown error'}`, 'error'); - clearTrack(); - break; - case 'stopped': - // Do NOT clear track here — explicit stop (handleStop) calls clearTrack() directly. - // Clearing here collapses the player after audio naturally ends or during queue transitions. - console.log('🛑 Stream stopped'); - stopStreamStatusPolling(); - hideLoadingAnimation(); - break; - } -} +// (updateStreamStatusFromData removed: it consumed the global 'tool:stream' +// socket broadcast, which could only carry the DEFAULT session's state — every +// real browser has its own per-listener stream session, so the broadcast told +// everyone "stopped" forever. Stream status is driven by the per-session HTTP +// poller (updateStreamStatus) exclusively.) async function startAudioPlayback() { // Start HTML5 audio playback of the streamed file with enhanced state management