From 07d09d7d0ebd07b289ff4bd967be27c610dfadf6 Mon Sep 17 00:00:00 2001 From: BoulderBadgeDad Date: Sat, 6 Jun 2026 12:43:20 -0700 Subject: [PATCH] Stream button: the player never learns its stream is ready (2.6.5 regression) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Since the per-listener stream sessions refactor (Phase 3b), every browser gets its own stream session — but the 1s 'tool:stream' socket broadcast still read the legacy GLOBAL state (the DEFAULT session no real browser uses), so it told every client "stopped" forever. The frontend skipped HTTP polling whenever the WebSocket was up, so it only ever saw that wrong broadcast: the backend prep downloaded the track, moved it into the session's stream folder and sat at "ready" while the mini player showed nothing. Proxy users whose WebSockets don't connect fell back to HTTP polling (session-correct) and streamed fine — which is why this hid so well. Fix: stream status is inherently per-listener, so stop pretending a global broadcast can carry it — - web_server.py: remove the 'tool:stream' emit from the tool-progress loop (the broadcast thread has no request context; it can only ever see DEFAULT) - media-player.js: the status poller always polls /api/stream/status (resolves the caller's own session from the cookie); drop the dead broadcast handler - core.js: unwire the 'tool:stream' socket listener Observability fix that made this undebuggable: core/streaming/prepare.py used getLogger(__name__) — outside the soulsync.* namespace where handlers attach — so every prep log line (including failures) vanished from app.log. Moved to get_logger("streaming.prepare") + a regression test locking the namespace. 34 streaming tests pass; ruff clean; web_server compiles; JS syntax-checked. --- core/streaming/prepare.py | 8 +++- tests/streaming/test_prepare.py | 15 +++++++ web_server.py | 18 ++++----- webui/static/core.js | 4 +- webui/static/media-player.js | 71 +++++---------------------------- 5 files changed, 41 insertions(+), 75 deletions(-) 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