From 54e4ba843fd2ec23fb85080c1f855dd69f5c0833 Mon Sep 17 00:00:00 2001 From: Broque Thomas <26755000+Nezreka@users.noreply.github.com> Date: Tue, 19 May 2026 19:44:17 -0700 Subject: [PATCH] fix(soulseek): suppress connection-error log spam when slskd unreachable (#649) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit When slskd_url is configured but the host is unreachable (slskd not running, wrong port, host.docker.internal not resolving), the frontend's /api/downloads/status polling fanned out to every download plugin including Soulseek. soulseek_client._make_request hit a DNS / connect failure on each poll and logged it at ERROR. Result: one "Cannot connect to host host.docker.internal:5030" log line every ~2-3 seconds for the entire duration of any download — visible spam even when the user wasn't using Soulseek at all. Caught aiohttp.ClientConnectorError explicitly in both _make_request and _make_direct_request. First failure emits one WARNING with actionable context (start slskd, or clear soulseek.slskd_url if you don't use Soulseek). Subsequent failures demote to DEBUG. The _last_unreachable_logged flag resets on any successful (200/201/204) response so a later outage warns again — suppression is per-outage, not per-process-lifetime. Same shape as the existing _last_401_logged suppression for auth failures. The architectural gap (status polling fans out to soulseek even when the user has soulseek disabled in their active download sources) is intentionally left for a follow-up. The plugin-iteration code lives in core/download_engine/engine.py and core/download_orchestrator.py; threading a "skip-when-not-active" gate through every caller is a bigger refactor than this user-facing log cleanup warrants. The WARNING-once message tells the user what to do in the meantime. 5 new pinning tests cover the suppression contract: connection error returns None (not raises), first failure WARNs + sets flag, repeats stay quiet, successful response resets the flag, _make_direct_request follows the same pattern, and non-connection exceptions still log at ERROR so real bugs aren't hidden behind the new suppression. --- core/soulseek_client.py | 33 +++++ tests/downloads/test_soulseek_pinning.py | 164 +++++++++++++++++++++++ webui/static/helper.js | 1 + 3 files changed, 198 insertions(+) diff --git a/core/soulseek_client.py b/core/soulseek_client.py index 6b928688..96cdb19d 100644 --- a/core/soulseek_client.py +++ b/core/soulseek_client.py @@ -250,6 +250,7 @@ class SoulseekClient(DownloadSourcePlugin): if response.status in [200, 201, 204]: # Accept 200 OK, 201 Created, and 204 No Content self._last_401_logged = False # Reset on success + self._last_unreachable_logged = False # Same reset for unreachable-host suppression try: if response_text.strip(): # Only parse if there's content return await response.json() @@ -291,6 +292,25 @@ class SoulseekClient(DownloadSourcePlugin): f"{method} {url} — slskd may be overloaded or unreachable" ) return None + except aiohttp.ClientConnectorError as e: + # Issue #649: slskd_url is configured but the host is unreachable + # (slskd not running, wrong port, DNS / Docker bridge issue). + # Status polling at /api/downloads/status fans out to every plugin + # including soulseek even when the user has soulseek toggled out + # of their active download sources, so each frontend poll + # produced an ERROR log line — visible spam during any + # non-soulseek download. Suppress repeats to debug; emit one + # WARNING with actionable context, then reset on any successful + # response (slskd came back up). + if not getattr(self, '_last_unreachable_logged', False): + logger.warning( + f"slskd unreachable at {self.base_url}: {e}. " + f"Either start slskd or clear `soulseek.slskd_url` in settings " + f"if you don't use Soulseek. Suppressing further connection errors." + ) + self._last_unreachable_logged = True + logger.debug(f"slskd connection failed: {method} {url}: {e}") + return None except Exception as e: logger.error(f"Error making API request: {e}") return None @@ -348,6 +368,19 @@ class SoulseekClient(DownloadSourcePlugin): f"{method} {url} — slskd may be overloaded or unreachable" ) return None + except aiohttp.ClientConnectorError as e: + # Issue #649 — same suppression as _make_request. Direct + # request is a less common path but uses the same base_url, + # so the same unreachable-host condition fires here. + if not getattr(self, '_last_unreachable_logged', False): + logger.warning( + f"slskd unreachable at {self.base_url}: {e}. " + f"Either start slskd or clear `soulseek.slskd_url` in settings " + f"if you don't use Soulseek. Suppressing further connection errors." + ) + self._last_unreachable_logged = True + logger.debug(f"slskd direct connection failed: {method} {url}: {e}") + return None except Exception as e: logger.error(f"Error making direct API request: {e}") return None diff --git a/tests/downloads/test_soulseek_pinning.py b/tests/downloads/test_soulseek_pinning.py index 253be224..ef4daec7 100644 --- a/tests/downloads/test_soulseek_pinning.py +++ b/tests/downloads/test_soulseek_pinning.py @@ -347,3 +347,167 @@ def test_make_direct_request_returns_none_on_timeout(configured_client): result = _run_async(configured_client._make_direct_request('GET', 'health')) assert result is None + + +# --------------------------------------------------------------------------- +# Issue #649 — connection-error log spam suppression +# --------------------------------------------------------------------------- + + +def _build_unreachable_session(error_message: str = 'Cannot connect to host'): + """Stub aiohttp session whose request() raises ClientConnectorError.""" + import aiohttp + from unittest.mock import MagicMock + + class _Cm: + async def __aenter__(self_inner): + # ClientConnectorError needs a connection_key + OSError. The + # exact values don't matter for the test — we just need an + # instance of the right class so the except-branch fires. + os_err = OSError(-2, 'Name or service not known') + raise aiohttp.ClientConnectorError(MagicMock(), os_err) + async def __aexit__(self_inner, *args): + return None + + class _StubSession: + async def __aenter__(self): + return self + async def __aexit__(self, *args): + return None + def request(self, *args, **kwargs): + return _Cm() + async def close(self): + return None + + return _StubSession + + +def test_unreachable_slskd_returns_none_not_raises(configured_client): + """Pin: ClientConnectorError must not propagate. Caller treats None + as a normal failure (same as a 5xx) — every consumer that gates on + `if response is None` keeps working when slskd is unreachable.""" + StubSession = _build_unreachable_session() + with patch('aiohttp.ClientSession', return_value=StubSession()): + result = _run_async(configured_client._make_request('GET', 'transfers/downloads')) + assert result is None + + +def test_unreachable_slskd_logs_warning_once_then_debug(configured_client, caplog): + """Issue #649: status polling at /api/downloads/status fans out to + every plugin including soulseek even when the user has soulseek + toggled out, so each frontend poll produced an ERROR log line. Pin + that the FIRST unreachable response emits one WARNING with + actionable context, and subsequent repeats demote to DEBUG so the + log isn't spammed for the lifetime of every non-soulseek download.""" + import logging + configured_client._last_unreachable_logged = False + StubSession = _build_unreachable_session() + + with patch('aiohttp.ClientSession', return_value=StubSession()): + with caplog.at_level(logging.DEBUG, logger='soulseek_client'): + # Three repeated polls — first must warn, rest must stay quiet. + _run_async(configured_client._make_request('GET', 'transfers/downloads')) + _run_async(configured_client._make_request('GET', 'transfers/downloads')) + _run_async(configured_client._make_request('GET', 'transfers/downloads')) + + warning_records = [r for r in caplog.records if r.levelno == logging.WARNING + and 'slskd unreachable' in r.message] + error_records = [r for r in caplog.records if r.levelno == logging.ERROR + and 'Error making API request' in r.message] + assert len(warning_records) == 1, \ + f"Expected exactly 1 WARNING (one-time slskd-unreachable notice), got {len(warning_records)}" + assert len(error_records) == 0, \ + "Connection errors must not log at ERROR — that's the spam pattern #649 reported" + assert configured_client._last_unreachable_logged is True + + +def test_unreachable_flag_resets_on_successful_response(configured_client, caplog): + """When slskd comes back up after a stretch of being down, a fresh + WARNING should fire if it goes down again later — the suppression is + per-outage, not per-process-lifetime. The flag resets on any + successful (200/201/204) response.""" + import logging + configured_client._last_unreachable_logged = True # Simulate prior outage already warned + + # Simulate a 200 response — must reset the suppression flag. + class _OkCm: + async def __aenter__(self_inner): + class _Resp: + status = 200 + reason = 'OK' + async def text(self_resp): + return '{"ok": true}' + async def json(self_resp): + return {'ok': True} + return _Resp() + async def __aexit__(self_inner, *args): + return None + + class _OkSession: + async def __aenter__(self): + return self + async def __aexit__(self, *args): + return None + def request(self, *args, **kwargs): + return _OkCm() + async def close(self): + return None + + with patch('aiohttp.ClientSession', return_value=_OkSession()): + _run_async(configured_client._make_request('GET', 'server/state')) + + assert configured_client._last_unreachable_logged is False, \ + "Successful response must reset the suppression flag so a future outage warns again" + + +def test_make_direct_request_also_suppresses_unreachable_spam(configured_client, caplog): + """`_make_direct_request` shares the same base_url and same outage + mode, so it gets the same WARNING-once + DEBUG-after treatment.""" + import logging + configured_client._last_unreachable_logged = False + StubSession = _build_unreachable_session() + + with patch('aiohttp.ClientSession', return_value=StubSession()): + with caplog.at_level(logging.DEBUG, logger='soulseek_client'): + _run_async(configured_client._make_direct_request('GET', 'health')) + _run_async(configured_client._make_direct_request('GET', 'health')) + + warning_records = [r for r in caplog.records if r.levelno == logging.WARNING + and 'slskd unreachable' in r.message] + error_records = [r for r in caplog.records if r.levelno == logging.ERROR + and 'Error making direct API request' in r.message] + assert len(warning_records) == 1 + assert len(error_records) == 0 + + +def test_non_connection_exception_still_logs_error(configured_client, caplog): + """Guard: only ClientConnectorError gets the suppression treatment. + Any other exception (programming bug, unexpected aiohttp behaviour, + etc.) must still surface at ERROR so we don't accidentally hide + real problems behind the noise reduction.""" + import logging + + class _BoomCm: + async def __aenter__(self_inner): + raise ValueError("not a connection error — should still log ERROR") + async def __aexit__(self_inner, *args): + return None + + class _BoomSession: + async def __aenter__(self): + return self + async def __aexit__(self, *args): + return None + def request(self, *args, **kwargs): + return _BoomCm() + async def close(self): + return None + + with patch('aiohttp.ClientSession', return_value=_BoomSession()): + with caplog.at_level(logging.DEBUG, logger='soulseek_client'): + result = _run_async(configured_client._make_request('GET', 'transfers/downloads')) + + assert result is None # Still returns None — non-raising contract preserved + error_records = [r for r in caplog.records if r.levelno == logging.ERROR + and 'Error making API request' in r.message] + assert len(error_records) == 1, "Non-connection exceptions must still log ERROR" diff --git a/webui/static/helper.js b/webui/static/helper.js index 9b497dd8..e0caf2c3 100644 --- a/webui/static/helper.js +++ b/webui/static/helper.js @@ -3424,6 +3424,7 @@ const WHATS_NEW = { { title: 'Fix popup: paste a MusicBrainz URL or MBID to match directly', desc: 'new escape hatch on the Fix Track Match modal (the 🔧 Fix button on mirrored / YouTube / Tidal / Deezer / Beatport / ListenBrainz / Spotify-public discovery rows). when fuzzy search keeps ranking the wrong recording among many same-title versions, paste the MusicBrainz recording URL like `https://musicbrainz.org/recording/` or the bare UUID into the new field and hit "Look up". skips all fuzzy logic, resolves straight to that record, and runs it through the same confirm + match pipeline.' }, { title: 'Fix popup: MusicBrainz added to the auto-search cascade', desc: 'the Fix Track Match modal used to query only Spotify → Deezer → iTunes for the auto-search, leaving MusicBrainz out of the loop entirely — even for users with MusicBrainz set as their primary metadata source. now MB is part of the cascade. when MB is your primary, it gets queried first; otherwise it sits as the last fallback. catches niche / non-mainstream / canonical-with-diacritics recordings that the commercial sources miss. Discogs is intentionally absent — Discogs has no track-level search API.' }, { title: 'Fix: Docker basic-search streaming silently failed under rootless Docker', desc: 'the streaming "Play" flow on the basic search page tried to create `/app/Stream` lazily at runtime, which fails silently when the container runs under rootless Docker / Podman (in-container root can\'t write to `/app`). pre-baked the directory at image build time, matching the same pattern that fixed `/app/Staging` earlier in the cycle. non-persistent — no volume needed.' }, + { title: 'Fix: slskd-unreachable log spam during non-Soulseek downloads', desc: 'when slskd was configured but not actually running (or unreachable on its configured port), the `/api/downloads/status` polling loop fanned out to every download plugin including Soulseek, producing one `ERROR - Cannot connect to host ... [Name or service not known]` log line per poll for the entire duration of any download — visible spam even when the user wasn\'t using Soulseek at all. Connection failures now emit one WARNING with actionable context (start slskd, or clear the slskd_url if you don\'t use Soulseek) and demote subsequent failures to debug. The flag resets on the next successful slskd response so a later outage warns again.' }, ], '2.5.5': [ { date: 'May 17, 2026 — 2.5.5 release' },