danvics/soulsync
1
0
Fork 0
Code Issues Pull requests Projects Releases Packages Wiki Activity Actions 1

Stream button: the player never learns its stream is ready (2.6.5 regression)

Browse source 
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.
This commit is contained in:
BoulderBadgeDad 2026-06-06 12:43:20 -07:00
parent 69fc21d6b2
commit 07d09d7d0e
5 changed files with 41 additions and 75 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

8
core/streaming/prepare.py
View file

@ -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

15
tests/streaming/test_prepare.py
View file

@ -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"
)

18
web_server.py
View file

@ -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:

4
webui/static/core.js
View file

@ -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));

71
webui/static/media-player.js
View file

@ -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