From 97e289ae1344e9130448e169b71f73ac97923a32 Mon Sep 17 00:00:00 2001 From: CaliBrain Date: Sun, 30 Aug 2026 03:09:13 -0400 Subject: [PATCH] fix: search, Prowlarr and qBittorrent follow-ups (#1276, #1283) (#1284) --- docs/environment-variables.md | 11 + readme.md | 1 + shelfmark/bypass/cookie_store.py | 23 +- shelfmark/bypass/internal_bypasser.py | 167 +++++++++-- shelfmark/config/env.py | 15 + shelfmark/config/settings.py | 13 + shelfmark/core/search_deadline.py | 134 +++++++++ shelfmark/core/search_plan.py | 62 +++- shelfmark/download/clients/qbittorrent.py | 91 ++++-- shelfmark/download/http.py | 34 ++- shelfmark/download/warmup.py | 19 ++ shelfmark/main.py | 35 ++- shelfmark/release_sources/direct_download.py | 21 +- shelfmark/release_sources/prowlarr/source.py | 31 ++ tests/bypass/test_bypass_budgets.py | 268 ++++++++++++++++++ tests/bypass/test_ddg_cookie_reuse.py | 84 ++++++ .../test_ffmpeg_recording_diagnostics.py | 110 +++++++ tests/bypass/test_rate_limited_clearance.py | 113 ++++++++ tests/core/test_releases_api_budget.py | 139 +++++++++ tests/core/test_search_deadline.py | 257 +++++++++++++++++ tests/core/test_search_plan_language_codes.py | 148 ++++++++++ tests/direct_download/test_search_budget.py | 144 ++++++++++ tests/download/conftest.py | 21 ++ tests/download/test_ddg_handshake_cookies.py | 153 ++++++++++ tests/download/test_warmup_yields_to_user.py | 65 +++++ tests/newznab/test_source.py | 4 +- tests/prowlarr/test_qbittorrent_client.py | 145 ++++++++++ tests/prowlarr/test_source.py | 60 ++++ 28 files changed, 2297 insertions(+), 71 deletions(-) create mode 100644 shelfmark/core/search_deadline.py create mode 100644 tests/bypass/test_bypass_budgets.py create mode 100644 tests/bypass/test_ffmpeg_recording_diagnostics.py create mode 100644 tests/bypass/test_rate_limited_clearance.py create mode 100644 tests/core/test_releases_api_budget.py create mode 100644 tests/core/test_search_deadline.py create mode 100644 tests/core/test_search_plan_language_codes.py create mode 100644 tests/direct_download/test_search_budget.py create mode 100644 tests/download/conftest.py create mode 100644 tests/download/test_ddg_handshake_cookies.py create mode 100644 tests/download/test_warmup_yields_to_user.py diff --git a/docs/environment-variables.md b/docs/environment-variables.md index 963e289..4904d7e 100644 --- a/docs/environment-variables.md +++ b/docs/environment-variables.md @@ -2179,6 +2179,7 @@ Enable Moly.hu as a metadata provider for book searches | `SOURCE_PRIORITY` | Fallback sources, may have waiting. Requires bypasser. Drag to reorder. | JSON array | _see UI for defaults_ | | `MAX_RETRY` | Maximum retry attempts for failed downloads. | number | `10` | | `DEFAULT_SLEEP` | Wait time between download retry attempts. | number | `5` | +| `RELEASE_SEARCH_TIMEOUT` | How long one release search may run before it gives up and reports why. A first search on a cold start pays for a browser solve, so leave room for one. If you use a reverse proxy, its read timeout should be at least this high or it will cut the search off with a 504 first. | number | `300` | | `AA_CONTENT_TYPE_ROUTING` | Override destination based on content type metadata. | boolean | `false` | | `AA_CONTENT_TYPE_DIR_FICTION` | Fiction Books | string | _none_ | | `AA_CONTENT_TYPE_DIR_NON_FICTION` | Non-Fiction Books | string | _none_ | @@ -2257,6 +2258,16 @@ Wait time between download retry attempts. - **Default:** `5` - **Constraints:** min: 1, max: 60 +#### `RELEASE_SEARCH_TIMEOUT` + +**Release Search Timeout (seconds)** + +How long one release search may run before it gives up and reports why. A first search on a cold start pays for a browser solve, so leave room for one. If you use a reverse proxy, its read timeout should be at least this high or it will cut the search off with a 504 first. + +- **Type:** number +- **Default:** `300` +- **Constraints:** min: 30, max: 1800 + #### `AA_CONTENT_TYPE_ROUTING` **Enable Content-Type Routing** diff --git a/readme.md b/readme.md index 1be0e0a..b893a04 100644 --- a/readme.md +++ b/readme.md @@ -147,6 +147,7 @@ See the full [Environment Variables Reference](docs/environment-variables.md) fo Some of the additional options available in Settings: - **Prowlarr** - Configure indexers and download clients to download books and audiobooks - **Additional audiobook sources** - Configure additional sources for audiobook discovery +- **Direct Download mirrors** - Supply your own Anna's Archive mirror URLs; Auto mode tries them in the order listed. The `annas-archive.is` domain does not currently work as a source — use `annas-archive.gl` instead (checked August 2026; mirror availability changes) - **IRC** - Add details for IRC book sources and download directly from the UI. Most networks serve audiobooks from the same channel as ebooks (on `irc.irchighway.net` that's `#ebooks`, while `#bookz` is effectively inactive), so leave the separate audiobook channel blank unless your network actually indexes one. IRC audiobooks usually arrive as ZIP/RAR archives — keep those enabled under Supported Audiobook Formats or the releases are filtered out of results - **Library Link** - Add a link to your Calibre-Web or Grimmory instance in the UI header - **File processing** - Customiseable download paths, file renaming and directory creation with template-based renaming diff --git a/shelfmark/bypass/cookie_store.py b/shelfmark/bypass/cookie_store.py index 4ea2692..2b4e1d3 100644 --- a/shelfmark/bypass/cookie_store.py +++ b/shelfmark/bypass/cookie_store.py @@ -71,11 +71,18 @@ def _get_full_cookie_domains() -> set[str]: return {_get_base_domain(domain) for domain in get_zlib_cookie_domains()} +def _replay_per_check_cookies() -> bool: + """Whether the per-check trio is kept rather than dropped (see env.py).""" + from shelfmark.config import env + + return env.DDG_REPLAY_PER_CHECK_COOKIES + + def _should_extract_cookie(name: str, *, extract_all: bool) -> bool: """Determine if a cookie should be extracted based on its name.""" # Checked before extract_all: a per-check token is wrong to replay for every # domain, including the full-session ones. - if name in DDG_EPHEMERAL_COOKIE_NAMES: + if name in DDG_EPHEMERAL_COOKIE_NAMES and not _replay_per_check_cookies(): return False if extract_all: return True @@ -138,9 +145,11 @@ def store_extracted_cookies( extract_all = base_domain in _get_full_cookie_domains() cookies_found: dict[str, dict[str, Any]] = {} + dropped: list[str] = [] for cookie in cookies: name = _cookie_field(cookie, "name") or "" if not _should_extract_cookie(name, extract_all=extract_all): + dropped.append(name) continue secure = _cookie_field(cookie, "secure") cookies_found[name] = { @@ -152,6 +161,18 @@ def store_extracted_cookies( "httpOnly": True, } + # Names only, never values. Which cookies a solve won, and which of them were held + # back, is the evidence needed to settle what DDoS-Guard actually treats as clearance + # (issue #1276) - and without it a debug log shows a solve succeeding and the next + # request being challenged with nothing in between to explain why. + logger.debug( + "Solve on %s won %s; keeping %s; dropping %s", + base_domain, + sorted({_cookie_field(c, "name") or "" for c in cookies}), + sorted(cookies_found), + sorted(set(dropped)) or "nothing", + ) + if not cookies_found: return diff --git a/shelfmark/bypass/internal_bypasser.py b/shelfmark/bypass/internal_bypasser.py index 96a1c1c..1536e50 100644 --- a/shelfmark/bypass/internal_bypasser.py +++ b/shelfmark/bypass/internal_bypasser.py @@ -83,11 +83,14 @@ _HELPER_RESULT_POLL_SECONDS = 0.05 _HELPER_SHUTDOWN_GRACE_SECONDS = 15.0 _HELPER_IDLE_TIMEOUT_DEFAULT = 180.0 _PARENT_WATCHDOG_INTERVAL_SECONDS = 5.0 +# How much of ffmpeg's stderr to quote when reporting that it died. +_FFMPEG_ERROR_TAIL_CHARS = 500 class _DisplayState(TypedDict): ffmpeg: subprocess.Popen[bytes] | None ffmpeg_output: Path | None + ffmpeg_error_log: Path | None class _PageWithWindowRect(Protocol): @@ -101,6 +104,7 @@ class _BrowserWithWindowRectPage(Protocol): DISPLAY: _DisplayState = { "ffmpeg": None, "ffmpeg_output": None, + "ffmpeg_error_log": None, } LOCKED = threading.Lock() _PROC_ROOT = Path("/proc") @@ -618,6 +622,25 @@ BYPASS_METHODS = [ MAX_CONSECUTIVE_SAME_CHALLENGE = 3 +# How many method attempts one _bypass() pass may make. Deliberately *not* MAX_RETRY: +# that value is already the outer page-load retry in _run_bypass_in_current_process, and +# reading it here too squared the budget - the default 10 meant 10 page loads x 4 methods +# = 40 solve attempts on one browser, which overruns the worker deadline and reports +# `TimeoutError` instead of a plain "bypass failed". One full pass through the methods +# plus a spare is all this loop can use anyway: the stuck-challenge guard below aborts at +# len(BYPASS_METHODS) + 1, so a larger number here only ever showed up in the logs. +_BYPASS_METHOD_ATTEMPTS = len(BYPASS_METHODS) + 1 + +# The undisturbed window a passive challenge gets before any method runs. Sized off the +# real thing: a desktop browser clears Anna's Archive's DDoS-Guard JS check in under 10s. +_PASSIVE_SOLVE_SECONDS = 15.0 +_PASSIVE_SOLVE_POLL_SECONDS = 1.0 + +# Head-room the retry loop leaves itself so it can return a real failure rather than be +# cancelled at the worker deadline. Enough for the pass in flight to unwind and the +# browser to close. +_RESERVE_FOR_CLEAN_FAILURE_SECONDS = 60.0 + def _check_cancellation(cancel_flag: Event | None, message: str) -> None: """Check if cancellation was requested and raise if so.""" @@ -627,13 +650,26 @@ def _check_cancellation(cancel_flag: Event | None, message: str) -> None: raise BypassCancelledError(msg) +async def _wait_for_passive_solve(page: Any, cancel_flag: Event | None = None) -> bool: + """Poll for a challenge that clears itself, without touching the page. + + Returns True as soon as the page looks bypassed, False once the window is spent. + """ + logger.info("Waiting up to %.0fs for the challenge to clear itself...", _PASSIVE_SOLVE_SECONDS) + deadline = time.monotonic() + _PASSIVE_SOLVE_SECONDS + while time.monotonic() < deadline: + _check_cancellation(cancel_flag, "Bypass cancelled while waiting for a passive solve") + await asyncio.sleep(_PASSIVE_SOLVE_POLL_SECONDS) + if await _is_bypassed(page): + return True + return False + + async def _bypass( page: Any, max_retries: int | None = None, cancel_flag: Event | None = None ) -> bool: """Attempt to bypass Cloudflare/DDOS-Guard protection using multiple methods.""" - max_retries = ( - max_retries if max_retries is not None else _coerce_positive_int(app_config.MAX_RETRY, 10) - ) + max_retries = max_retries if max_retries is not None else _BYPASS_METHOD_ATTEMPTS last_challenge_type = None consecutive_same_challenge = 0 @@ -651,6 +687,20 @@ async def _bypass( challenge_type = await _detect_challenge_type(page) logger.debug("Challenge detected: %s", challenge_type) + # Give a passive check the undisturbed window it needs before touching the page. + # DDoS-Guard's JS check on Anna's Archive has no click target: it runs, then + # navigates on its own - a desktop browser clears it in well under 15s. Every + # method below either clicks a selector that is not there or reloads, and a reload + # restarts an in-flight check (which DDoS-Guard also throttles), so going straight + # to them meant the one thing that actually solves this challenge was the one + # thing never tried. Costs one 15s window per solve against a minutes-long budget, + # and a challenge that needs interaction simply falls through to the methods. + if try_count == 0 and challenge_type != "none": + if await _wait_for_passive_solve(page, cancel_flag): + logger.info("Bypass successful: %s challenge cleared itself", challenge_type) + return True + logger.debug("Challenge did not clear on its own; trying bypass methods") + # No challenge detected but page doesn't look bypassed - wait and retry if challenge_type == "none": logger.info("No challenge detected, waiting for page to settle...") @@ -810,14 +860,33 @@ async def _get(url: str, driver: Any, cancel_flag: Event | None = None) -> str: def _run_bypass_in_current_process(url: str, retry: int, cancel_flag: Event | None = None) -> str: """Run the CDP bypass in the current process.""" + timeout = ( + _CHILD_BYPASS_TIMEOUT_SECONDS + if os.environ.get(_BYPASS_CHILD_ENV) == "1" + else _IN_PROCESS_BYPASS_TIMEOUT_SECONDS + ) async def _run_bypass() -> str: driver = None + # Stop retrying while there is still time to say so. A challenge nothing can solve + # would otherwise spend every one of `retry` passes and be cut off mid-pass by the + # worker deadline, which surfaces to the caller as `RuntimeError: TimeoutError` - + # a message that says nothing about protection and sent users looking at their + # reverse proxy. Giving up a pass early returns the real "bypass failed" instead. + deadline = time.monotonic() + timeout - _RESERVE_FOR_CLEAN_FAILURE_SECONDS try: driver = await _create_cdp_browser(url) for attempt in range(retry): _check_cancellation(cancel_flag, "Bypass cancelled before attempt") + if attempt > 0 and time.monotonic() >= deadline: + logger.warning( + "Bypass budget spent after %s/%s attempts; giving up on %s", + attempt, + retry, + url, + ) + break try: result = await _get(url, driver, cancel_flag) @@ -838,7 +907,7 @@ def _run_bypass_in_current_process(url: str, retry: int, cancel_flag: Event | No await _close_cdp_driver(driver) driver = await _create_cdp_browser(url) - logger.error("Bypass failed after %s attempts", retry) + logger.error("Bypass failed for %s", url) return "" finally: if driver: @@ -852,12 +921,9 @@ def _run_bypass_in_current_process(url: str, retry: int, cancel_flag: Event | No # one call and closes it on the way out, so a helper serving many requests would build # and tear down a loop per bypass and would carry no deadline of its own. The worker's # loop lives in a thread, outlives any single bypass, and cancels the coroutine when the - # deadline passes. - timeout = ( - _CHILD_BYPASS_TIMEOUT_SECONDS - if os.environ.get(_BYPASS_CHILD_ENV) == "1" - else _IN_PROCESS_BYPASS_TIMEOUT_SECONDS - ) + # deadline passes. `_run_bypass` aims to finish inside this same budget of its own + # accord, so reaching this deadline now means a wedged session rather than a stubborn + # challenge - which is the only case worth reporting as a timeout. return _CDP_WORKER.run(_run_bypass(), timeout=timeout) @@ -1155,6 +1221,20 @@ def get(url: str, retry: int | None = None, cancel_flag: Event | None = None) -> if cached_result: return cached_result + # Re-checked after the cached attempt, not just in get_bypassed_page: that check + # ran before the queue, and this call may have spent minutes holding for LOCKED + # while another request collected a 429 (or collected one itself, just above). + # A solve cannot clear a throttle - the challenge renders, the solve "succeeds", + # and the cleared request is refused again while the backoff is renewed. + remaining = network.host_cooldown_remaining(url) + if remaining > 0: + hostname = urlparse(url).hostname or url + msg = ( + f"{hostname} is rate-limited (429); skipping bypass for ~{remaining:.0f}s " + "until the cooldown clears." + ) + raise network.RateLimitedError(msg) + if env.DOCKERMODE and os.environ.get(_BYPASS_CHILD_ENV) != "1": return _get_via_subprocess(url, retry, cancel_flag) return _run_bypass_in_current_process(url, retry, cancel_flag) @@ -1339,13 +1419,48 @@ def _start_ffmpeg_recording(display: str) -> None: "-an", output_file.as_posix(), "-nostats", + # Was "0", which discards everything including the reason it could not start. + # Recordings have been arriving empty with no explanation anywhere: on issue + # #1276 all three of a session's recordings were gone and the log said only + # "FFmpeg already stopped", because ffmpeg exits before creating the file when + # it cannot open the X display. Errors only - this is a debug-mode recorder, not + # something to make chatty. "-loglevel", - "0", + "error", ] logger.debug("Starting FFmpeg recording to %s", output_file) logger.debug_trace(f"FFmpeg command: {' '.join(ffmpeg_cmd)}") - DISPLAY["ffmpeg"] = subprocess.Popen(ffmpeg_cmd) + # Kept beside the recording so it travels in the debug bundle, which is the only + # place anyone will look for it. A file rather than a pipe: nothing here would drain + # a pipe, and a full one would wedge ffmpeg partway through a capture. + error_log = output_file.with_suffix(".ffmpeg.log") + try: + stderr_handle = error_log.open("wb") + except OSError as exc: + logger.debug("Could not open FFmpeg error log %s: %s", error_log, exc) + stderr_handle = None + DISPLAY["ffmpeg"] = subprocess.Popen( + ffmpeg_cmd, stderr=stderr_handle, stdout=subprocess.DEVNULL + ) + if stderr_handle is not None: + # The child holds its own descriptor; this one has done its job. + stderr_handle.close() DISPLAY["ffmpeg_output"] = output_file + DISPLAY["ffmpeg_error_log"] = error_log + + +def _ffmpeg_error_summary() -> str: + """What ffmpeg wrote to stderr, for the log line that reports it died.""" + error_log = DISPLAY.get("ffmpeg_error_log") + if not error_log: + return "No FFmpeg error log was captured." + try: + text = Path(error_log).read_text(encoding="utf-8", errors="replace").strip() + except OSError as exc: + return f"FFmpeg error log unreadable ({exc})." + if not text: + return f"FFmpeg logged nothing to {error_log}." + return f"FFmpeg said: {text[-_FFMPEG_ERROR_TAIL_CHARS:]}" def _stop_ffmpeg_recording() -> None: @@ -1357,9 +1472,17 @@ def _stop_ffmpeg_recording() -> None: if not proc: return if proc.poll() is not None: - logger.debug("FFmpeg already stopped") + # Not "already stopped" - ffmpeg was asked to record until now and is gone, so + # the recording for this bypass does not exist. Say so, with the reason, rather + # than leaving an empty recording/ directory to be discovered later. + logger.warning( + "FFmpeg exited early (code %s); no recording for this bypass. %s", + proc.returncode, + _ffmpeg_error_summary(), + ) DISPLAY["ffmpeg"] = None DISPLAY["ffmpeg_output"] = None + DISPLAY["ffmpeg_error_log"] = None return try: proc.send_signal(signal.SIGINT) @@ -1374,6 +1497,7 @@ def _stop_ffmpeg_recording() -> None: proc.kill() DISPLAY["ffmpeg"] = None DISPLAY["ffmpeg_output"] = None + DISPLAY["ffmpeg_error_log"] = None def _try_with_cached_cookies(url: str, hostname: str) -> str | None: @@ -1401,10 +1525,19 @@ def _try_with_cached_cookies(url: str, hostname: str) -> str | None: logger.debug("Cached cookies worked, skipped Chrome bypass") return response.text if response.status_code == HTTPStatus.TOO_MANY_REQUESTS: - # Throttled, not challenged: arm the per-host backoff so the caller stops - # rotating into this host and re-solving. get_bypassed_page checks it before - # the next Chrome solve. - network.note_rate_limited(url) + # Throttled, not challenged. The clearance is still good - the origin is + # rate-limiting this IP and would answer 429 to a browser holding the very + # same cookies. Discarding it here (as every other rejection does) meant a + # solve won seconds earlier was thrown away and the next query bought its + # own 20-60s browser solve, which is itself more traffic at a host that has + # just asked for less. Keep it, arm the backoff, and let the caller wait. + wait = network.note_rate_limited(url) + logger.debug( + "Cached cookies hit a 429 for %s; keeping them and backing off ~%.0fs", + url, + wait, + ) + return None logger.debug( "Cached cookies rejected (%s) for %s; discarding them", response.status_code, diff --git a/shelfmark/config/env.py b/shelfmark/config/env.py index c55614a..e4b6e7f 100644 --- a/shelfmark/config/env.py +++ b/shelfmark/config/env.py @@ -203,6 +203,21 @@ ONBOARDING = string_to_bool(os.getenv("ONBOARDING", "true")) _DEBUG_SKIP_SOURCES_RAW = os.getenv("DEBUG_SKIP_SOURCES", "").strip().lower() DEBUG_SKIP_SOURCES = {s.strip() for s in _DEBUG_SKIP_SOURCES_RAW.split(",") if s.strip()} +# Debug: keep DDoS-Guard's __ddg8_/__ddg9_/__ddg10_ in the clearance store instead of +# dropping them after a solve. +# +# Which of DDoS-Guard's cookies actually *are* clearance is not settled. The store treats +# the trio as describing one check (client IP, timestamp, token) and drops them, on the +# reasoning that replaying a stale IP/timestamp is what re-arms the ?check=1 loop - see +# shelfmark.bypass.cookie_store. Field reports on issue #1276 point the other way: every +# request after a successful solve was challenged again, which is only consistent with +# what the store keeps not being sufficient clearance on its own. +# +# Deliberately env-only and off by default: this is a knob for reproducing the question +# against a live host, not a setting to offer users. Set it to true, solve once, and watch +# whether the next search still logs "Redirect loop detected". +DDG_REPLAY_PER_CHECK_COOKIES = string_to_bool(os.getenv("DDG_REPLAY_PER_CHECK_COOKIES", "false")) + # ============================================================================= # Legacy migration support - will be removed in future version diff --git a/shelfmark/config/settings.py b/shelfmark/config/settings.py index a119d2c..bfe85f2 100644 --- a/shelfmark/config/settings.py +++ b/shelfmark/config/settings.py @@ -1560,6 +1560,19 @@ def download_source_settings() -> list[SettingsField]: min_value=1, max_value=60, ), + NumberField( + key="RELEASE_SEARCH_TIMEOUT", + label="Release Search Timeout (seconds)", + description=( + "How long one release search may run before it gives up and reports why. " + "A first search on a cold start pays for a browser solve, so leave room " + "for one. If you use a reverse proxy, its read timeout should be at least " + "this high or it will cut the search off with a 504 first." + ), + default=300, + min_value=30, + max_value=1800, + ), HeadingField( key="content_type_routing_heading", title="Content-Type Routing", diff --git a/shelfmark/core/search_deadline.py b/shelfmark/core/search_deadline.py new file mode 100644 index 0000000..fb66aee --- /dev/null +++ b/shelfmark/core/search_deadline.py @@ -0,0 +1,134 @@ +"""A wall-clock budget for one release search, enforced through the existing cancel flag. + +`/api/releases` is synchronous: the browser waits on it while the search runs. Nothing +bounded that wait, and the bypasser's own worst case is minutes long +(`internal_bypasser.max_duration_seconds()`), so a search that ran into an unsolvable +protection challenge outlived every reverse proxy in front of it. The user then saw +"Server unavailable (504)" - a gateway timeout that says nothing about what went wrong +and points the blame at their proxy config. See issue #1276. + +The budget is expressed as the cancel flag the download path already understands: an +Event armed by a timer. `html_get_page`, the bypassers and the helper subprocess all poll +it, so an expired budget stops a solve already in flight rather than only refusing the +next one. When it trips, the search fails with a message that names the real cause. + +Scoped to a context variable so it applies to the request that set it and to nothing else +- a queued download must keep its own, much longer, budget. +""" + +from __future__ import annotations + +import threading +import time +from contextlib import contextmanager +from contextvars import ContextVar +from typing import TYPE_CHECKING + +from shelfmark.core.logger import setup_logger + +if TYPE_CHECKING: + from collections.abc import Iterator + +logger = setup_logger(__name__) + +# What one search may spend. A first search on a cold start legitimately pays for a +# browser solve - jfmlima measured 60-120s for a successful one on Anna's Archive - so +# this cannot be as tight as a proxy's default read timeout without breaking working +# setups. It is instead well below the ~840s the bypass path could previously reach, +# which is what turned a failing challenge into a gateway timeout. +DEFAULT_SEARCH_BUDGET_SECONDS = 300.0 + +_MIN_SEARCH_BUDGET_SECONDS = 30.0 +_MAX_SEARCH_BUDGET_SECONDS = 1800.0 + +# Raised to the caller when the budget runs out, so the API can say so plainly. +SEARCH_DEADLINE_MESSAGE = ( + "The release search ran out of time (%.0fs). Anna's Archive is behind a protection " + "challenge the bypasser could not solve in that window. Raise the release search " + "timeout if your setup is simply slow." +) + + +class SearchDeadline: + """A budget with an Event that trips when it expires.""" + + def __init__(self, budget_seconds: float) -> None: + self.budget_seconds = budget_seconds + self.expires_at = time.monotonic() + budget_seconds + # A plain threading.Event on purpose: this is handed on as a cancel flag, and + # that is the type the download path, the CDP worker thread and the bypass helper + # already poll. + self.event = threading.Event() + self._timer = threading.Timer(budget_seconds, self.event.set) + self._timer.daemon = True + + def start(self) -> None: + self._timer.start() + + def cancel(self) -> None: + self._timer.cancel() + + @property + def remaining(self) -> float: + return max(0.0, self.expires_at - time.monotonic()) + + @property + def expired(self) -> bool: + return self.event.is_set() or self.remaining <= 0 + + +_current: ContextVar[SearchDeadline | None] = ContextVar("search_deadline", default=None) + + +def budget_seconds() -> float: + """The configured budget for one release search.""" + from shelfmark.core.config import config as app_config + + raw = app_config.get("RELEASE_SEARCH_TIMEOUT", DEFAULT_SEARCH_BUDGET_SECONDS) + if isinstance(raw, bool) or not isinstance(raw, int | float | str): + return DEFAULT_SEARCH_BUDGET_SECONDS + try: + value = float(raw) + except TypeError, ValueError: + return DEFAULT_SEARCH_BUDGET_SECONDS + if value <= 0: + return DEFAULT_SEARCH_BUDGET_SECONDS + return min(max(value, _MIN_SEARCH_BUDGET_SECONDS), _MAX_SEARCH_BUDGET_SECONDS) + + +@contextmanager +def search_deadline(budget: float | None = None) -> Iterator[SearchDeadline]: + """Apply a budget to everything the calling context does.""" + deadline = SearchDeadline(budget if budget is not None else budget_seconds()) + token = _current.set(deadline) + deadline.start() + logger.debug("Release search budget: %.0fs", deadline.budget_seconds) + try: + yield deadline + finally: + deadline.cancel() + _current.reset(token) + + +def current() -> SearchDeadline | None: + """The budget in force, or None outside a search.""" + return _current.get() + + +def expired() -> bool: + """Whether the budget in force has run out. False when there is no budget.""" + deadline = _current.get() + return deadline is not None and deadline.expired + + +def cancel_event() -> threading.Event | None: + """The Event that trips when the budget runs out, for use as a cancel flag.""" + deadline = _current.get() + return deadline.event if deadline is not None else None + + +def deadline_message() -> str: + """The failure to report when the budget has run out.""" + deadline = _current.get() + budget = deadline.budget_seconds if deadline else DEFAULT_SEARCH_BUDGET_SECONDS + return SEARCH_DEADLINE_MESSAGE % budget diff --git a/shelfmark/core/search_plan.py b/shelfmark/core/search_plan.py index 0249ad6..99810b0 100644 --- a/shelfmark/core/search_plan.py +++ b/shelfmark/core/search_plan.py @@ -7,6 +7,7 @@ from dataclasses import dataclass from typing import TYPE_CHECKING from shelfmark.core.config import config +from shelfmark.core.logger import setup_logger from shelfmark.metadata_providers import ( BookMetadata, build_localized_search_titles, @@ -16,6 +17,8 @@ from shelfmark.metadata_providers import ( if TYPE_CHECKING: from shelfmark.core.models import SearchFilters +logger = setup_logger(__name__) + MANUAL_QUERY_MAX_LEN = 256 @@ -52,6 +55,49 @@ class ReleaseSearchPlan: return self.title_variants[0].query if self.title_variants else "" +def _to_language_codes(values: Iterable[object], *, source: str) -> list[str] | None: + """Resolve any spelling of a language to the ISO code the sources expect. + + Anna's Archive matches `lang=` against ISO codes: `lang=english` is not a loose + spelling of `lang=en`, it is a facet value AA does not have, and it filters every + search down to nothing. Only the *per-user* override was normalised + (config.users_settings.validate), so a global BOOK_LANGUAGE=english - the spelling + the old docs used - reached the query verbatim and silently emptied every search + with no error anywhere. See issue #1276. + + An entry that resolves to nothing is dropped with a warning rather than passed + through: searching unfiltered and saying so beats reporting "no results" for a book + the source is full of. + """ + from shelfmark.core.languages import normalize_language + + codes: list[str] = [] + unresolved: list[str] = [] + for value in values: + text = str(value).strip() if value is not None else "" + if not text: + continue + if text.lower() == "all": + # An explicit "search every language", not a language. + return None + code = normalize_language(text) + if code is None: + unresolved.append(text) + continue + if code not in codes: + codes.append(code) + + if unresolved: + logger.warning( + "Ignoring unrecognised language(s) in %s: %s. Use an ISO code such as 'en', " + "a three-letter code, or an English name like 'English'.", + source, + ", ".join(unresolved), + ) + + return codes or None + + def _normalize_languages(languages: list[str] | None, user_id: int | None) -> list[str] | None: if not languages: default = config.get("BOOK_LANGUAGE", None, user_id=user_id) @@ -61,21 +107,9 @@ def _normalize_languages(languages: list[str] | None, user_id: int | None) -> li default_values = list(default) else: return None - return [str(lang).strip() for lang in default_values if str(lang).strip()] + return _to_language_codes(default_values, source="BOOK_LANGUAGE") - normalized: list[str] = [] - for lang in languages: - if not lang: - continue - s = str(lang).strip() - if not s: - continue - normalized.append(s) - - if any(lang.lower() == "all" for lang in normalized): - return None - - return normalized or None + return _to_language_codes(languages, source="the search request") def _pick_search_author(book: BookMetadata) -> str: diff --git a/shelfmark/download/clients/qbittorrent.py b/shelfmark/download/clients/qbittorrent.py index ab7c943..c65dc77 100644 --- a/shelfmark/download/clients/qbittorrent.py +++ b/shelfmark/download/clients/qbittorrent.py @@ -225,6 +225,9 @@ class QBittorrentClient(DownloadClient): self._category = config_text(config.get("QBITTORRENT_CATEGORY", "books")) self._download_dir = config_text(config.get("QBITTORRENT_DOWNLOAD_DIR", "")) self._tags = _normalize_tags(config.get("QBITTORRENT_TAG", [])) + # download_id -> qBittorrent's current primary hash, for identities that no + # longer match it directly. See _resolve_torrent(). + self._primary_hashes: dict[str, str] = {} @property def _can_reauthenticate(self) -> bool: @@ -311,13 +314,31 @@ class QBittorrentClient(DownloadClient): params = {"category": category} if category else {} return self._request_torrent_info_records(params) + def _remember_primary_hash(self, download_id: str, torrent: SimpleNamespace) -> None: + """Note the primary hash a listing scan found, so later lookups skip the scan.""" + torrent_hash = getattr(torrent, "hash", None) + if isinstance(torrent_hash, str) and torrent_hash: + self._primary_hashes[download_id.lower()] = torrent_hash.lower() + def _resolve_torrent( self, download_id: str, category: str | None = None ) -> tuple[SimpleNamespace | None, str | None]: - """Resolve any known torrent identity to its current qBittorrent record.""" - torrent, error = self._get_torrent_info(download_id) - if error or torrent: - return torrent, error + """Resolve any known torrent identity to its current qBittorrent record. + + A hybrid torrent's primary hash switches from the v1 hash to the truncated v2 + hash once metadata resolves, so a download tracked by its v1 hash misses the + `hashes=` lookup and falls through to a full listing. Since `get_status()` + polls every couple of seconds for the life of the download, remember the + primary hash a scan finds and try it first. + """ + cached = self._primary_hashes.get(download_id.lower()) + for candidate in (item for item in dict.fromkeys((cached, download_id)) if item): + torrent, error = self._get_torrent_info(candidate) + if error: + return None, error + if torrent: + self._remember_primary_hash(download_id, torrent) + return torrent, None categories = [candidate for candidate in (category, self._category) if candidate] for candidate in dict.fromkeys(categories): @@ -329,18 +350,23 @@ class QBittorrentClient(DownloadClient): None, ) if torrent: + self._remember_primary_hash(download_id, torrent) return torrent, None torrents, error = self._list_torrents_by_category(None) if error: return None, error - return ( - next( - (item for item in torrents if _torrent_matches_download_id(item, download_id)), - None, - ), + torrent = next( + (item for item in torrents if _torrent_matches_download_id(item, download_id)), None, ) + if torrent: + self._remember_primary_hash(download_id, torrent) + else: + # The torrent is gone; drop the note so a re-add is not looked up by a + # hash that no longer exists. + self._primary_hashes.pop(download_id.lower(), None) + return torrent, None def _current_hash(self, download_id: str) -> str: """qBittorrent's current primary hash for any identity we know the torrent by. @@ -539,12 +565,11 @@ class QBittorrentClient(DownloadClient): expected_hash, _METADATA_WAIT_POLLS * _METADATA_WAIT_INTERVAL_SECONDS, ) - return expected_hash.lower() except _QBITTORRENT_CLIENT_ERRORS: logger.exception("qBittorrent add failed") raise else: - return expected_hash + return expected_hash.lower() def get_status(self, download_id: str) -> DownloadStatus: """Get torrent status by hash. @@ -643,6 +668,7 @@ class QBittorrentClient(DownloadClient): try: torrent_hash = self._current_hash(download_id) self._client.torrents_delete(torrent_hashes=torrent_hash, delete_files=delete_files) + self._primary_hashes.pop(download_id.lower(), None) logger.info( "Removed torrent from qBittorrent: %s%s", download_id, @@ -787,6 +813,33 @@ class QBittorrentClient(DownloadClient): ) return None + def _await_existing_torrent( + self, info_hash: str, category: str | None + ) -> tuple[str, DownloadStatus] | None: + """Report a torrent already in qBittorrent, waiting out magnet metadata first.""" + for _ in range(_METADATA_WAIT_POLLS): + torrent, error = self._resolve_torrent(info_hash, category) + if error: + logger.debug("qBittorrent find_existing: %s", error) + return None + if not torrent: + return None + if getattr(torrent, "state", None) not in _METADATA_DOWNLOAD_STATES: + torrent_hash = getattr(torrent, "hash", None) + if isinstance(torrent_hash, str) and torrent_hash: + torrent_hash = torrent_hash.lower() + return (torrent_hash, self.get_status(torrent_hash)) + time.sleep(_METADATA_WAIT_INTERVAL_SECONDS) + + # Metadata is still pending, but the torrent is here and `add_download` keeps + # one in this state rather than giving up. Report it by info hash so the + # caller joins the download in progress instead of adding a duplicate. + logger.info( + "Existing torrent %s is still fetching metadata; joining it by info hash", + info_hash, + ) + return (info_hash.lower(), self.get_status(info_hash)) + def find_existing( self, url: str, category: str | None = None ) -> tuple[str, DownloadStatus] | None: @@ -796,21 +849,9 @@ class QBittorrentClient(DownloadClient): if not torrent_info.info_hash: return None - for _ in range(20): - torrent, error = self._resolve_torrent(torrent_info.info_hash, category) - if error: - logger.debug("qBittorrent find_existing: %s", error) - return None - if not torrent: - return None - if getattr(torrent, "state", None) not in _METADATA_DOWNLOAD_STATES: - torrent_hash = getattr(torrent, "hash", None) - if isinstance(torrent_hash, str) and torrent_hash: - torrent_hash = torrent_hash.lower() - return (torrent_hash, self.get_status(torrent_hash)) - time.sleep(0.5) + existing = self._await_existing_torrent(torrent_info.info_hash, category) except _QBITTORRENT_CLIENT_ERRORS as e: logger.debug("Error checking for existing torrent: %s", e) return None else: - return None + return existing diff --git a/shelfmark/download/http.py b/shelfmark/download/http.py index 5c3d443..3fe5f18 100644 --- a/shelfmark/download/http.py +++ b/shelfmark/download/http.py @@ -12,6 +12,7 @@ from tqdm import tqdm from shelfmark.bypass import BypassCancelledError, cookie_store from shelfmark.bypass.challenge import challenge_marker +from shelfmark.core import search_deadline from shelfmark.core.config import config as app_config from shelfmark.core.logger import setup_logger from shelfmark.core.request_helpers import coerce_bool, normalize_positive_int @@ -338,6 +339,14 @@ def html_get_page( # so it must be a concrete selector, not the Optional parameter. selector = selector or network.AAMirrorSelector() + # A release search runs under a wall-clock budget (see shelfmark.core.search_deadline). + # Adopting it as the cancel flag is what makes the budget bite on a solve already in + # flight: the bypassers and the helper subprocess poll this flag but know nothing about + # deadlines. Only when the caller has no flag of its own - a queued download brings one + # and must keep it, and runs outside any search context anyway. + if cancel_flag is None: + cancel_flag = search_deadline.cancel_event() + def _result(html: str, response_url: str) -> str | tuple[str, str]: if include_response_url: return html, response_url @@ -362,6 +371,13 @@ def html_get_page( retry-loop branch above with `continue`, and with MAX_RETRY=1 there is no later attempt for that branch to run on either. """ + # Never start a minutes-long browser solve on a budget that has already run out: + # nothing downstream would get to report the real reason before the caller's + # deadline (or its reverse proxy) cut the request off. + if search_deadline.expired(): + logger.info("Release search budget spent; not starting a bypass for %s", bypass_url) + return _fail(search_deadline.deadline_message(), bypass_url) + if status_callback: status_callback("resolving", "Bypassing protection...") try: @@ -400,6 +416,10 @@ def html_get_page( except _STATUS_CALLBACK_ERRORS: logger.debug("Bypass error status callback failed", exc_info=True) if isinstance(e, BypassCancelledError): + # The budget trips the same cancel flag a user's cancel does, so tell them + # apart here - "cancelled" is a confusing thing to read when nobody did. + if search_deadline.expired(): + return _fail(search_deadline.deadline_message(), bypass_url) return _fail("The protection bypass was cancelled.", bypass_url) return _fail(f"The protection bypasser failed: {type(e).__name__}: {e}", bypass_url) finally: @@ -456,6 +476,9 @@ def html_get_page( for attempt in range(1, retry_limit + 1): # Check for cancellation before each attempt if cancel_flag and cancel_flag.is_set(): + if search_deadline.expired(): + logger.info("Release search budget spent before attempt %s", attempt) + return _fail(search_deadline.deadline_message(), current_url) logger.info("html_get_page cancelled before attempt %s", attempt) return _fail("The request was cancelled.", current_url) @@ -484,8 +507,15 @@ def html_get_page( current_url, proxies=get_proxies(current_url), timeout=REQUEST_TIMEOUT, - # Bypasser-derived cookies win: they came from a real solved challenge. - cookies={**handshake_cookies, **cookies}, + # Handshake cookies win. They were issued by *this* exchange, so by + # definition they are fresher than anything the store holds, and the + # server is waiting to see them echoed back on the very next hop. + # Letting the store overwrite them meant a stored cookie of the same + # name (DDoS-Guard reuses __ddg1_/__ddg2_ for both) was replayed on + # every hop and the freshly issued value never left this process - the + # ?check=1 probe could then never terminate, so every request ended in + # the redirect-loop handoff and paid for a full browser solve. + cookies={**cookies, **handshake_cookies}, headers=headers, allow_redirects=allow_redirects, verify=get_ssl_verify(current_url), diff --git a/shelfmark/download/warmup.py b/shelfmark/download/warmup.py index 06c693b..98c2cf7 100644 --- a/shelfmark/download/warmup.py +++ b/shelfmark/download/warmup.py @@ -32,6 +32,19 @@ _DEFAULT_QUERY = "The Great Gatsby" _warmup_thread: threading.Thread | None = None _warmup_lock = threading.Lock() +# Set as soon as a real release search starts. The warm-up exists to pay the cold path +# *before* the user does; once they have beaten it to the box there is nothing left to +# pre-solve, and running anyway is actively harmful - the bypasser serializes on one +# browser, so the warm-up's solve goes in front of the search the user is watching. In +# the bundle on issue #1276 that cost a full minute of a 2m27s wait, on a container 16 +# seconds old, for a throwaway "The Great Gatsby" query nobody asked for. +_user_search_seen = threading.Event() + + +def note_user_search() -> None: + """Record that a real search has run, so a pending warm-up stands down.""" + _user_search_seen.set() + def _as_bool(value: object, *, default: bool) -> bool: """Coerce a config value that may arrive as a string, bool or None.""" @@ -85,6 +98,12 @@ def run_warmup() -> bool: """ from shelfmark.core.mirrors import has_aa_mirror_configuration + # Checked here rather than only at schedule time: the delay is what this races with, + # so the user's first search usually lands *during* the wait, not before it. + if _user_search_seen.is_set(): + logger.info("Search warm-up skipped: a real search got there first") + return False + if not has_aa_mirror_configuration(): logger.debug("Search warm-up skipped: no Anna's Archive mirrors configured") return False diff --git a/shelfmark/main.py b/shelfmark/main.py index 5f60008..b7c54ea 100644 --- a/shelfmark/main.py +++ b/shelfmark/main.py @@ -42,6 +42,7 @@ from shelfmark.config.settings import ( _SUPPORTED_BOOK_LANGUAGE, migrate_audiobook_format_settings, ) +from shelfmark.core import search_deadline from shelfmark.core.activity_view_state_service import ActivityViewStateService from shelfmark.core.auth_modes import ( get_auth_check_admin_status, @@ -2987,18 +2988,36 @@ def api_releases() -> Response | tuple[Response, int]: # Search only enabled sources sources_to_search = [src["name"] for src in list_available_sources() if src["enabled"]] - # Search each source for releases + # Search each source for releases. + # + # Under a wall-clock budget: this endpoint is synchronous, and the bypass path it + # can reach used to be allowed minutes per URL with nothing bounding the request + # as a whole. A search that ran into an unsolvable protection challenge therefore + # outlived every reverse proxy in front of it and surfaced to the user as + # "Server unavailable (504)" - a gateway timeout that blames their proxy for a + # challenge failure. The budget is shared across sources, so a stuck first source + # cannot spend the whole request on its own. See issue #1276. all_releases = [] errors = [] source_instances = {} # Keep source instances for column config - for source_name in sources_to_search: - source, releases, error = _search_source_releases(source_name, book) - if source is not None: - source_instances[source_name] = source - all_releases.extend(releases) - if error is not None: - errors.append(error) + # A real search is under way, so a warm-up still sitting on its start-up delay + # should stand down rather than queue its throwaway solve in front of this one. + warmup.note_user_search() + + with search_deadline.search_deadline(): + for source_name in sources_to_search: + if search_deadline.expired(): + logger.warning("Release search budget spent; %s not searched", source_name) + errors.append(f"{source_name}: {search_deadline.deadline_message()}") + continue + + source, releases, error = _search_source_releases(source_name, book) + if source is not None: + source_instances[source_name] = source + all_releases.extend(releases) + if error is not None: + errors.append(error) # Convert Release objects to dicts releases_data = [_serialize_release(release) for release in all_releases] diff --git a/shelfmark/release_sources/direct_download.py b/shelfmark/release_sources/direct_download.py index 3257ede..f481599 100644 --- a/shelfmark/release_sources/direct_download.py +++ b/shelfmark/release_sources/direct_download.py @@ -17,6 +17,7 @@ from bs4 import BeautifulSoup, Tag from bs4.element import NavigableString from shelfmark.config.env import DEBUG_SKIP_SOURCES, TMP_DIR +from shelfmark.core import search_deadline from shelfmark.core.config import config from shelfmark.core.languages import language_alias_map from shelfmark.core.logger import setup_logger @@ -586,6 +587,11 @@ def _fetch_search_table(url: str, selector: network.AAMirrorSelector) -> tuple[s """ attempt_url = url for _ in range(len(network.get_available_aa_urls()) or 1): + # Every mirror shares the protection, so once the search budget is gone another + # mirror is another full solve nobody is still waiting for. + if search_deadline.expired(): + raise SearchUnavailableError(search_deadline.deadline_message()) + response = downloader.html_get_page( attempt_url, selector=selector, allow_bypasser_fallback=True ) @@ -1973,6 +1979,12 @@ class DirectDownloadSource(ReleaseSource): query = f"{title} {author}".strip() if not query: continue + # `except Exception` below keeps this loop going past a failed variant, which + # is right for a parse error and wrong for a spent budget: without this the + # variants queue up behind each other and the request outlives the caller. + if search_deadline.expired(): + logger.info("Release search budget spent; skipping remaining title variants") + break logger.debug("Searching direct_download: title_author='%s', langs=%s", query, langs) filters = SearchFilters(lang=langs if langs is not None else []) @@ -1986,7 +1998,11 @@ class DirectDownloadSource(ReleaseSource): except Exception: logger.exception("Search error") - if not all_results and any(langs for _, langs in searches): + if ( + not all_results + and any(langs for _, langs in searches) + and not search_deadline.expired() + ): logger.debug( "No title+author results with language filter, retrying without language filter" ) @@ -1994,6 +2010,9 @@ class DirectDownloadSource(ReleaseSource): query = f"{title} {author}".strip() if not query: continue + if search_deadline.expired(): + logger.info("Release search budget spent; skipping remaining retries") + break logger.debug("Searching direct_download: title_author='%s', langs=[]", query) try: diff --git a/shelfmark/release_sources/prowlarr/source.py b/shelfmark/release_sources/prowlarr/source.py index 20fb7cc..f77ae6d 100644 --- a/shelfmark/release_sources/prowlarr/source.py +++ b/shelfmark/release_sources/prowlarr/source.py @@ -145,6 +145,36 @@ def _build_indexer_priority(indexers: list[dict]) -> dict[int, int]: return priority +def _drop_unknown_indexer_ids( + selected_ids: list[int] | None, indexers: list[dict] +) -> list[int] | None: + """Keep only selected indexer ids Prowlarr still serves. + + An indexer removed or disabled in Prowlarr stays in the saved selection, + where settings can no longer show it - so it cannot be unselected, and every + search keeps querying an indexer that is gone (#1283). Dropping it here + keeps the saved selection intact for an indexer that comes back. + """ + if selected_ids is None: + return None + + live_ids = { + indexer_id + for indexer in indexers + if (indexer_id := _coerce_indexer_id(indexer.get("id"))) is not None + } + kept = [indexer_id for indexer_id in selected_ids if indexer_id in live_ids] + + stale = [indexer_id for indexer_id in selected_ids if indexer_id not in live_ids] + if stale: + logger.warning( + "Skipping selected Prowlarr indexers that are no longer enabled in Prowlarr: %s", + stale, + ) + + return kept + + def _rank_for_indexer_id(indexer_id: object, priority: dict[int, int]) -> int: """Preference rank for an indexer id. Lower wins, unknown ranks last.""" coerced = _coerce_indexer_id(indexer_id) @@ -961,6 +991,7 @@ class ProwlarrSource(ReleaseSource): # found for this book" - the same lie as a swallowed timeout (#1249). msg = f"could not reach Prowlarr: {e}" raise SourceUnavailableError(msg) from e + indexer_ids = _drop_unknown_indexer_ids(indexer_ids, enabled_indexers) indexer_priority = _build_indexer_priority(enabled_indexers) # Some indexers benefit from title+author queries and extra format detection. enriched_indexer_ids = client.get_enriched_indexer_ids( diff --git a/tests/bypass/test_bypass_budgets.py b/tests/bypass/test_bypass_budgets.py new file mode 100644 index 0000000..a526ead --- /dev/null +++ b/tests/bypass/test_bypass_budgets.py @@ -0,0 +1,268 @@ +"""How long the internal bypasser is allowed to spend, and on what. + +Issue #1276: MAX_RETRY drove *both* the outer page-load loop and the per-page method +loop, so the default of 10 meant ~40 solve attempts on one browser. That overran the +worker deadline, and the failure reached the user as `RuntimeError: TimeoutError` - a +message that says nothing about a protection challenge and sent people looking at their +reverse proxy instead. + +Also covered: the undisturbed window a passive challenge gets before anything touches the +page. Anna's Archive's DDoS-Guard check has no click target and clears itself; going +straight to the click/reload methods meant the one thing that solves it was never tried. +""" + +import asyncio + +import pytest + + +@pytest.fixture +def bypass(monkeypatch): + """internal_bypasser with sleeps and jitter removed.""" + import shelfmark.bypass.internal_bypasser as internal_bypasser + + async def _no_sleep(_seconds) -> None: + return None + + monkeypatch.setattr(internal_bypasser.asyncio, "sleep", _no_sleep) + monkeypatch.setattr(internal_bypasser._RNG, "uniform", lambda _a, _b: 0) + return internal_bypasser + + +def _recording_methods(calls: list[str], count: int = 4): + def _make(name: str): + async def _method(_page) -> bool: + calls.append(name) + return False + + _method.__name__ = name + return _method + + return [_make(f"m{i}") for i in range(count)] + + +def _stub_page_state(monkeypatch, bypass, *, bypassed=False, challenge="ddos_guard"): + async def _is_bypassed(*_args, **_kwargs) -> bool: + return bypassed + + async def _detect(*_args, **_kwargs) -> str: + return challenge + + monkeypatch.setattr(bypass, "_is_bypassed", _is_bypassed) + monkeypatch.setattr(bypass, "_detect_challenge_type", _detect) + + +# --------------------------------------------------------------------------- # +# The method loop must not read MAX_RETRY +# --------------------------------------------------------------------------- # +def test_method_loop_budget_is_independent_of_max_retry(monkeypatch, bypass): + """MAX_RETRY is the outer page-load retry; reading it here squared the budget. + + Exercised against a challenge whose *type* keeps changing, because that is the case + where max_retries is what bounds the loop: the stuck-challenge guard only fires on a + run of the same type, so with a stable challenge it hid the real budget entirely. + """ + monkeypatch.setattr(type(bypass.app_config), "MAX_RETRY", 50, raising=False) + + types = iter(["ddos_guard", "cloudflare"] * 100) + + async def _alternating(*_args, **_kwargs) -> str: + return next(types) + + calls: list[str] = [] + monkeypatch.setattr(bypass, "BYPASS_METHODS", _recording_methods(calls)) + monkeypatch.setattr(bypass, "_wait_for_passive_solve", _never_passes) + _stub_page_state(monkeypatch, bypass) + monkeypatch.setattr(bypass, "_detect_challenge_type", _alternating) + + assert asyncio.run(bypass._bypass(object())) is False + assert len(calls) == bypass._BYPASS_METHOD_ATTEMPTS + assert len(calls) < 50, "MAX_RETRY must not reach the method loop" + + +def test_method_attempt_budget_is_reachable(bypass): + """The number reported as `attempt N/X` must be a number the loop can reach. + + It used to be MAX_RETRY (10) while the stuck-challenge guard capped the loop at 5, + so logs showed `4/10` and stopped, which reads like six lost attempts. + """ + assert bypass._BYPASS_METHOD_ATTEMPTS == len(bypass.BYPASS_METHODS) + 1 + assert bypass._BYPASS_METHOD_ATTEMPTS >= ( + max(bypass.MAX_CONSECUTIVE_SAME_CHALLENGE, len(bypass.BYPASS_METHODS) + 1) + ) + + +# --------------------------------------------------------------------------- # +# A passive challenge gets an undisturbed window first +# --------------------------------------------------------------------------- # +async def _never_passes(*_args, **_kwargs) -> bool: + return False + + +def test_passive_challenge_is_given_time_before_any_method_runs(monkeypatch, bypass): + """DDoS-Guard's JS check clears itself; nothing should click or reload first.""" + calls: list[str] = [] + monkeypatch.setattr(bypass, "BYPASS_METHODS", _recording_methods(calls)) + _stub_page_state(monkeypatch, bypass) + + async def _passes(*_args, **_kwargs) -> bool: + return True + + monkeypatch.setattr(bypass, "_wait_for_passive_solve", _passes) + + assert asyncio.run(bypass._bypass(object())) is True + assert calls == [], "the page must not be touched while the check can still pass" + + +def test_passive_wait_happens_once_not_before_every_method(monkeypatch, bypass): + """It is a settling window, not a delay bolted onto each attempt.""" + waits: list[int] = [] + calls: list[str] = [] + + async def _count_wait(*_args, **_kwargs) -> bool: + waits.append(1) + return False + + monkeypatch.setattr(bypass, "BYPASS_METHODS", _recording_methods(calls)) + monkeypatch.setattr(bypass, "_wait_for_passive_solve", _count_wait) + _stub_page_state(monkeypatch, bypass) + + asyncio.run(bypass._bypass(object())) + + assert len(waits) == 1 + assert calls == ["m0", "m1", "m2", "m3"] + + +def test_no_passive_wait_when_no_challenge_is_detected(monkeypatch, bypass): + """The 'none' branch has its own settle-and-refresh handling.""" + waits: list[int] = [] + + async def _count_wait(*_args, **_kwargs) -> bool: + waits.append(1) + return False + + monkeypatch.setattr(bypass, "_wait_for_passive_solve", _count_wait) + _stub_page_state(monkeypatch, bypass, challenge="none") + + class _Page: + async def reload(self, **_kwargs) -> None: + return None + + asyncio.run(bypass._bypass(_Page(), max_retries=1)) + + assert waits == [] + + +def test_wait_for_passive_solve_returns_as_soon_as_the_page_clears(monkeypatch, bypass): + polls = {"n": 0} + + async def _is_bypassed(*_args, **_kwargs) -> bool: + polls["n"] += 1 + return polls["n"] >= 3 + + monkeypatch.setattr(bypass, "_is_bypassed", _is_bypassed) + + assert asyncio.run(bypass._wait_for_passive_solve(object())) is True + assert polls["n"] == 3 + + +def test_wait_for_passive_solve_gives_up_at_the_window(monkeypatch, bypass): + """It must not poll forever - the methods still need their share of the budget.""" + clock = {"now": 0.0} + monkeypatch.setattr(bypass.time, "monotonic", lambda: clock["now"]) + + async def _tick(*_args, **_kwargs) -> bool: + clock["now"] += 1.0 + return False + + monkeypatch.setattr(bypass, "_is_bypassed", _tick) + + assert asyncio.run(bypass._wait_for_passive_solve(object())) is False + assert clock["now"] >= bypass._PASSIVE_SOLVE_SECONDS + + +def test_wait_for_passive_solve_honours_cancellation(monkeypatch, bypass): + import threading + + from shelfmark.bypass import BypassCancelledError + + cancel = threading.Event() + cancel.set() + monkeypatch.setattr(bypass, "_is_bypassed", _never_passes) + + with pytest.raises(BypassCancelledError): + asyncio.run(bypass._wait_for_passive_solve(object(), cancel)) + + +# --------------------------------------------------------------------------- # +# The page-load loop stops while there is still time to report a real failure +# --------------------------------------------------------------------------- # +def test_page_load_loop_stops_before_the_worker_deadline(monkeypatch, bypass): + """A stubborn challenge must produce "bypass failed", not a cancelled coroutine.""" + clock = {"now": 0.0} + monkeypatch.setattr(bypass.time, "monotonic", lambda: clock["now"]) + monkeypatch.delenv(bypass._BYPASS_CHILD_ENV, raising=False) + + attempts = {"n": 0} + + async def _create(_url): + return object() + + async def _get(_url, _driver, _cancel=None) -> str: + attempts["n"] += 1 + # Each pass eats a realistic slice of the budget. + clock["now"] += 120.0 + return "" + + async def _close(_driver) -> None: + return None + + monkeypatch.setattr(bypass, "_create_cdp_browser", _create) + monkeypatch.setattr(bypass, "_get", _get) + monkeypatch.setattr(bypass, "_close_cdp_driver", _close) + + class _RealWorker: + def run(self, coro, timeout=None): + return asyncio.run(coro) + + monkeypatch.setattr(bypass, "_CDP_WORKER", _RealWorker()) + + result = bypass._run_bypass_in_current_process("https://example.com", 10) + + assert result == "" + # Well short of the 10 it was asked for, and short of the deadline it had. + assert attempts["n"] < 10 + budget = bypass._IN_PROCESS_BYPASS_TIMEOUT_SECONDS + assert clock["now"] < budget, "the loop must leave room to report the failure" + + +def test_page_load_loop_still_makes_one_attempt_on_a_spent_budget(monkeypatch, bypass): + """The deadline check must never skip the request entirely.""" + clock = {"now": 10_000.0} + monkeypatch.setattr(bypass.time, "monotonic", lambda: clock["now"]) + monkeypatch.delenv(bypass._BYPASS_CHILD_ENV, raising=False) + + attempts = {"n": 0} + + async def _create(_url): + return object() + + async def _get(_url, _driver, _cancel=None) -> str: + attempts["n"] += 1 + return "solved" + + async def _close(_driver) -> None: + return None + + monkeypatch.setattr(bypass, "_create_cdp_browser", _create) + monkeypatch.setattr(bypass, "_get", _get) + monkeypatch.setattr(bypass, "_close_cdp_driver", _close) + + class _RealWorker: + def run(self, coro, timeout=None): + return asyncio.run(coro) + + monkeypatch.setattr(bypass, "_CDP_WORKER", _RealWorker()) + + assert bypass._run_bypass_in_current_process("https://example.com", 10) == "solved" + assert attempts["n"] == 1 diff --git a/tests/bypass/test_ddg_cookie_reuse.py b/tests/bypass/test_ddg_cookie_reuse.py index 88cfee4..3bf6431 100644 --- a/tests/bypass/test_ddg_cookie_reuse.py +++ b/tests/bypass/test_ddg_cookie_reuse.py @@ -43,6 +43,37 @@ def _store(cookies, url="https://annas-archive.gl/search"): cs.store_extracted_cookies(url=url, cookies=cookies, user_agent="UA/1.0") +@pytest.fixture +def cookie_store_logs(): + """Collect cookie-store log messages. + + The store's logger is built outside the standard hierarchy, so its records never + reach the root handler caplog installs. + """ + import logging + + messages: list[str] = [] + + class _Capture(logging.Handler): + def emit(self, record: logging.LogRecord) -> None: + messages.append(record.getMessage()) + + handler = _Capture() + cs.logger.addHandler(handler) + previous = cs.logger.level + cs.logger.setLevel(logging.DEBUG) + # setup_logger builds its loggers with CustomLogger(name) rather than getLogger, so + # they are not in the manager's hierarchy - and Logger.setLevel only invalidates the + # is-enabled cache *through* the manager. Without this the logger keeps answering + # "DEBUG is off" from a cache entry made while it was at INFO. + cs.logger._cache.clear() + try: + yield messages + finally: + cs.logger.removeHandler(handler) + cs.logger.setLevel(previous) + + # --------------------------------------------------------------------------- # # Per-check cookies must not be persisted for replay # --------------------------------------------------------------------------- # @@ -220,3 +251,56 @@ def test_failure_only_clears_the_failing_host(monkeypatch): assert ib.get_cf_cookies_for_domain("annas-archive.gl") == {} assert ib.get_cf_cookies_for_domain("other-site.test") == {"__ddg1_": "other"} + + +# --------------------------------------------------------------------------- # +# Settling what DDoS-Guard actually treats as clearance (issue #1276) +# --------------------------------------------------------------------------- # +def test_per_check_cookies_can_be_kept_for_a_field_test(monkeypatch): + """Which __ddg* cookies are clearance is not settled, so it has to be testable. + + The store's premise - that __ddg8_/__ddg9_/__ddg10_ describe one check and must not + be replayed - is contradicted by the field reports on #1276, where every request + after a successful solve was challenged again. This env-only switch is how that gets + answered against a live host without building a branch. + """ + from shelfmark.config import env + + monkeypatch.setattr(env, "DDG_REPLAY_PER_CHECK_COOKIES", True) + _store( + [ + _Cookie("__ddg1_", "clearance"), + _Cookie("__ddg8_", "opaque"), + _Cookie("__ddg9_", "203.0.113.7"), + _Cookie("__ddg10_", "1786826304"), + ] + ) + + stored = ib.get_cf_cookies_for_domain("annas-archive.gl") + + assert set(stored) == {"__ddg1_", "__ddg8_", "__ddg9_", "__ddg10_"} + + +def test_dropping_per_check_cookies_is_the_default(monkeypatch): + """The switch is for reproducing the question, not a behaviour change.""" + from shelfmark.config import env + + assert env.DDG_REPLAY_PER_CHECK_COOKIES is False + _store([_Cookie("__ddg1_", "clearance"), _Cookie("__ddg9_", "203.0.113.7")]) + + assert set(ib.get_cf_cookies_for_domain("annas-archive.gl")) == {"__ddg1_"} + + +def test_a_solve_logs_which_cookies_it_won_and_which_were_held_back(cookie_store_logs): + """Without this, a debug log shows a solve succeed and the next request challenged, + with nothing in between to explain why.""" + _store([_Cookie("__ddg1_", "clearance"), _Cookie("__ddg9_", "203.0.113.7")]) + + messages = cookie_store_logs + line = next((m for m in messages if "won" in m and "dropping" in m), None) + assert line is not None, messages + assert "__ddg1_" in line + assert "__ddg9_" in line + # Names only - a clearance cookie's value is a credential. + assert "clearance" not in line + assert "203.0.113.7" not in line diff --git a/tests/bypass/test_ffmpeg_recording_diagnostics.py b/tests/bypass/test_ffmpeg_recording_diagnostics.py new file mode 100644 index 0000000..fc4804f --- /dev/null +++ b/tests/bypass/test_ffmpeg_recording_diagnostics.py @@ -0,0 +1,110 @@ +"""A recording that never happened must say why. + +Issue #1276: the debug bundle's recording/ directory was empty, and the only trace was +three "FFmpeg already stopped" debug lines - one per bypass, each logged 20-56s after +the recorder was started, meaning ffmpeg had exited almost immediately every time. It ran +with `-loglevel 0` and no stderr capture, so nothing anywhere recorded the reason. The +screen recording is the single most useful artifact for diagnosing a bypass failure. +""" + +import subprocess + +import pytest + +import shelfmark.bypass.internal_bypasser as ib + + +@pytest.fixture(autouse=True) +def _clean_display(): + before = dict(ib.DISPLAY) + ib.DISPLAY["ffmpeg"] = None + ib.DISPLAY["ffmpeg_output"] = None + ib.DISPLAY["ffmpeg_error_log"] = None + yield + ib.DISPLAY.update(before) + + +class _Proc: + def __init__(self, returncode): + self.returncode = returncode + + def poll(self): + return self.returncode + + +def test_ffmpeg_errors_are_captured_to_a_file_beside_the_recording(monkeypatch, tmp_path): + monkeypatch.setattr(ib, "RECORDING_DIR", tmp_path) + captured: dict[str, object] = {} + + def fake_popen(cmd, **kwargs): + captured["cmd"] = cmd + captured["stderr"] = kwargs.get("stderr") + return _Proc(None) + + monkeypatch.setattr(ib.subprocess, "Popen", fake_popen) + + ib._start_ffmpeg_recording(display=":99") + + cmd = captured["cmd"] + # Errors must not be thrown away any more. + assert "-loglevel" in cmd + assert cmd[cmd.index("-loglevel") + 1] == "error" + # stderr goes to a real file, not a pipe nothing would drain. + assert captured["stderr"] is not None + assert captured["stderr"] is not subprocess.PIPE + + error_log = ib.DISPLAY["ffmpeg_error_log"] + assert error_log is not None + assert error_log.parent == tmp_path + # It sits beside the mp4, so it travels in the debug bundle. + assert error_log.name.startswith("screen_recording_") + + +def test_an_early_exit_is_reported_with_ffmpegs_own_reason(monkeypatch, tmp_path, caplog): + reason = "[x11grab @ 0x1] Cannot open display :99, error 1." + error_log = tmp_path / "screen_recording_x.ffmpeg.log" + error_log.write_text(reason, encoding="utf-8") + + ib.DISPLAY["ffmpeg"] = _Proc(1) + ib.DISPLAY["ffmpeg_output"] = tmp_path / "screen_recording_x.mp4" + ib.DISPLAY["ffmpeg_error_log"] = error_log + + messages: list[str] = [] + + class _Capture: + def emit(self, record): + messages.append(record.getMessage()) + + import logging + + handler = logging.Handler() + handler.emit = _Capture().emit # type: ignore[method-assign] + ib.logger.addHandler(handler) + previous = ib.logger.level + ib.logger.setLevel(logging.DEBUG) + ib.logger._cache.clear() + try: + ib._stop_ffmpeg_recording() + finally: + ib.logger.removeHandler(handler) + ib.logger.setLevel(previous) + + line = next((m for m in messages if "exited early" in m), None) + assert line is not None, messages + assert "code 1" in line + assert "Cannot open display" in line + assert ib.DISPLAY["ffmpeg"] is None + + +def test_summary_is_explicit_when_ffmpeg_logged_nothing(tmp_path): + empty = tmp_path / "screen_recording_y.ffmpeg.log" + empty.write_text("", encoding="utf-8") + ib.DISPLAY["ffmpeg_error_log"] = empty + + assert "logged nothing" in ib._ffmpeg_error_summary() + + +def test_summary_survives_a_missing_log(): + ib.DISPLAY["ffmpeg_error_log"] = None + + assert "No FFmpeg error log" in ib._ffmpeg_error_summary() diff --git a/tests/bypass/test_rate_limited_clearance.py b/tests/bypass/test_rate_limited_clearance.py new file mode 100644 index 0000000..12056fe --- /dev/null +++ b/tests/bypass/test_rate_limited_clearance.py @@ -0,0 +1,113 @@ +"""A 429 is throttling, not a dead clearance cookie. + +Issue #1276: every rejection of the cached cookies took the same exit, which cleared the +host's clearance. That is right for a 403 and for the ?check=1 redirect loop - being +challenged while presenting a cookie proves the cookie is dead - and wrong for a 429, +where the origin is rate-limiting the IP and would answer a real browser holding the very +same cookies identically. + +The cost in the reported bundle: a solve completed at 13:41:23 and stored five cookies; +six seconds later a 429 threw them away, and the next query bought its own 56-second +browser solve. Reuse rate across the whole log was 0 of 2. +""" + +import pytest + +import shelfmark.bypass.cookie_store as cs +import shelfmark.bypass.internal_bypasser as ib + +URL = "https://annas-archive.gl/search?q=dune" +HOST = "annas-archive.gl" + + +class _Resp: + def __init__(self, status_code, text="page"): + self.status_code = status_code + self.text = text + + +@pytest.fixture(autouse=True) +def _clean(monkeypatch): + monkeypatch.setattr(cs, "_cf_cookies", {}) + monkeypatch.setattr(cs, "_cf_user_agents", {}) + monkeypatch.setattr(cs, "_get_full_cookie_domains", set) + monkeypatch.setattr(ib, "get_proxies", lambda _url: None) + monkeypatch.setattr(ib, "get_ssl_verify", lambda _url: True) + cs._cf_cookies[HOST] = { + "__ddg1_": {"value": "clearance", "expiry": None}, + "__ddg2_": {"value": "c2", "expiry": None}, + } + + +def _cooldowns(monkeypatch): + """Record note_rate_limited calls without arming the real per-host ladder.""" + armed: list[str] = [] + monkeypatch.setattr(ib.network, "note_rate_limited", lambda url: armed.append(url) or 120.0) + return armed + + +def test_429_keeps_the_clearance(monkeypatch): + armed = _cooldowns(monkeypatch) + monkeypatch.setattr(ib.requests, "get", lambda *a, **k: _Resp(429)) + + assert ib._try_with_cached_cookies(URL, HOST) is None + assert ib.get_cf_cookies_for_domain(HOST) == {"__ddg1_": "clearance", "__ddg2_": "c2"} + assert armed == [URL], "the backoff must still be armed" + + +def test_403_still_discards_the_clearance(monkeypatch): + """The pre-existing behaviour for a genuine rejection must not regress.""" + _cooldowns(monkeypatch) + monkeypatch.setattr(ib.requests, "get", lambda *a, **k: _Resp(403)) + + assert ib._try_with_cached_cookies(URL, HOST) is None + assert ib.get_cf_cookies_for_domain(HOST) == {} + + +def test_redirect_loop_still_discards_the_clearance(monkeypatch): + _cooldowns(monkeypatch) + + def boom(*_a, **_k): + raise ib.requests.exceptions.TooManyRedirects("Exceeded 30 redirects") + + monkeypatch.setattr(ib.requests, "get", boom) + + assert ib._try_with_cached_cookies(URL, HOST) is None + assert ib.get_cf_cookies_for_domain(HOST) == {} + + +def test_a_throttled_host_is_not_handed_a_browser_solve(monkeypatch): + """A solve cannot clear a throttle, and is itself more traffic at a host asking for + less. get_bypassed_page checks the cooldown before the queue; get() has to re-check + after it, because a request can hold for LOCKED while another collects the 429.""" + monkeypatch.setattr(ib.requests, "get", lambda *a, **k: _Resp(429)) + monkeypatch.setattr(ib.network, "note_rate_limited", lambda _url: 120.0) + monkeypatch.setattr(ib.network, "host_cooldown_remaining", lambda _url: 118.0) + + solved: list[str] = [] + monkeypatch.setattr( + ib, "_run_bypass_in_current_process", lambda url, *a, **k: solved.append(url) or "html" + ) + monkeypatch.setattr(ib.env, "DOCKERMODE", False) + + with pytest.raises(ib.network.RateLimitedError) as excinfo: + ib.get(URL, retry=1) + + assert solved == [], "no browser should have been started" + assert "rate-limited" in str(excinfo.value) + # And the clearance survives, ready for when the cooldown clears. + assert ib.get_cf_cookies_for_domain(HOST) == {"__ddg1_": "clearance", "__ddg2_": "c2"} + + +def test_a_host_that_is_not_throttled_still_solves(monkeypatch): + monkeypatch.setattr(ib.requests, "get", lambda *a, **k: _Resp(403)) + monkeypatch.setattr(ib.network, "host_cooldown_remaining", lambda _url: 0.0) + + solved: list[str] = [] + monkeypatch.setattr( + ib, "_run_bypass_in_current_process", lambda url, *a, **k: solved.append(url) or "html" + ) + monkeypatch.setattr(ib.env, "DOCKERMODE", False) + + assert ib.get(URL, retry=1) == "html" + assert solved == [URL] diff --git a/tests/core/test_releases_api_budget.py b/tests/core/test_releases_api_budget.py new file mode 100644 index 0000000..79d90ce --- /dev/null +++ b/tests/core/test_releases_api_budget.py @@ -0,0 +1,139 @@ +"""GET /api/releases answers within a budget instead of outliving the caller. + +Issue #1276: the endpoint is synchronous and had no deadline, while the bypass path it +reaches was allowed ~840s per URL. A protection challenge nobody could solve therefore +ran until the reverse proxy in front of Shelfmark gave up, and the user was shown +"Server unavailable (504). If using a reverse proxy, check its configuration." - which +names the wrong thing entirely. +""" + +from __future__ import annotations + +import importlib +from unittest.mock import patch + +import pytest + +from shelfmark.core import search_deadline + + +@pytest.fixture(scope="module") +def main_module(): + with patch("shelfmark.download.orchestrator.start"): + import shelfmark.main as main + + importlib.reload(main) + return main + + +@pytest.fixture +def client(main_module): + return main_module.app.test_client() + + +def _authenticate(client) -> None: + with client.session_transaction() as sess: + sess["user_id"] = "alice" + sess["is_admin"] = False + sess["db_user_id"] = 7 + + +def _request(client, main_module, sources, search_impl): + """Drive /api/releases with a stubbed source list and search implementation.""" + + class _Source: + def search(self, book, plan, *, expand_search=False, content_type="ebook"): + return search_impl(book, plan) + + def get_column_config(self): + from shelfmark.release_sources import _default_column_config + + return _default_column_config() + + with ( + patch.object(main_module, "get_auth_mode", return_value="none"), + patch("shelfmark.release_sources.list_available_sources", return_value=sources), + patch("shelfmark.release_sources.get_source", return_value=_Source()), + patch("shelfmark.release_sources.source_results_are_releases", return_value=False), + ): + return client.get( + "/api/releases", + query_string={"provider": "manual", "book_id": "abc", "title": "Dune"}, + ) + + +def test_a_search_runs_under_a_budget(client, main_module): + """The handler must put a deadline in force for whatever the sources do.""" + _authenticate(client) + observed: list[float | None] = [] + + def _search(_book, _plan): + deadline = search_deadline.current() + observed.append(deadline.budget_seconds if deadline else None) + return [] + + resp = _request(client, main_module, [{"name": "direct_download", "enabled": True}], _search) + + assert resp.status_code == 200 + assert observed and observed[0] is not None, "no budget was in force during the search" + + +def test_the_budget_is_shared_across_sources(client, main_module): + """A stuck first source must not spend the whole request on its own.""" + _authenticate(client) + searched: list[str] = [] + + def _search(book, _plan): + searched.append(book.title) + # Whatever the first source did, it ran the clock out. + deadline = search_deadline.current() + if deadline is not None: + deadline.event.set() + return [] + + sources = [ + {"name": "direct_download", "enabled": True}, + {"name": "prowlarr", "enabled": True}, + ] + resp = _request(client, main_module, sources, _search) + + assert len(searched) == 1, "the second source should not have been started" + assert "ran out of time" in resp.get_json()["error"] + + +def test_the_failure_carries_a_message_the_frontend_will_show(client, main_module): + """The whole point of the budget. + + Shelfmark answers 503 when a search comes back empty with errors, and the frontend + only substitutes its "Server unavailable ... check your reverse proxy" text when the + body carries no message of its own. So the budget has to produce a body that names + the protection challenge - and has to trip before the proxy's own timeout, where + there would be no body at all. + """ + _authenticate(client) + + def _search(_book, _plan): + deadline = search_deadline.current() + if deadline is not None: + deadline.event.set() + return [] + + sources = [ + {"name": "direct_download", "enabled": True}, + {"name": "prowlarr", "enabled": True}, + ] + resp = _request(client, main_module, sources, _search) + + message = resp.get_json()["error"] + assert "protection challenge" in message + assert "reverse proxy" not in message + # The source prefix is stripped by the handler; the sentence must survive intact. + assert message.startswith("The release search ran out of time") + + +def test_no_budget_leaks_out_of_the_request(client, main_module): + """A queued download later on must not inherit a search's deadline.""" + _authenticate(client) + _request(client, main_module, [{"name": "direct_download", "enabled": True}], lambda *_: []) + + assert search_deadline.current() is None diff --git a/tests/core/test_search_deadline.py b/tests/core/test_search_deadline.py new file mode 100644 index 0000000..6cbf445 --- /dev/null +++ b/tests/core/test_search_deadline.py @@ -0,0 +1,257 @@ +"""The wall-clock budget on a release search. + +Issue #1276: `/api/releases` is synchronous and nothing bounded it, while the bypass path +it can reach was allowed ~840s per URL. A search that ran into an unsolvable protection +challenge therefore outlived every reverse proxy in front of it, and the user was shown +"Server unavailable (504)" - a gateway timeout that names their proxy rather than the +challenge that actually failed. +""" + +import threading + +import pytest + +from shelfmark.core import search_deadline + + +@pytest.fixture(autouse=True) +def _no_ambient_deadline(): + """Each test starts outside any budget.""" + token = search_deadline._current.set(None) + yield + search_deadline._current.reset(token) + + +# --------------------------------------------------------------------------- # +# The budget itself +# --------------------------------------------------------------------------- # +def test_no_budget_outside_a_search(): + """A queued download must not inherit a search's budget.""" + assert search_deadline.current() is None + assert search_deadline.expired() is False + assert search_deadline.cancel_event() is None + + +def test_budget_applies_inside_the_context_and_not_after(): + with search_deadline.search_deadline(60) as deadline: + assert search_deadline.current() is deadline + assert search_deadline.expired() is False + assert search_deadline.current() is None + + +def test_expiry_trips_the_cancel_event(): + """The Event is the mechanism: the bypassers poll it and know nothing of deadlines.""" + with search_deadline.search_deadline(0.05): + event = search_deadline.cancel_event() + assert isinstance(event, threading.Event) + assert event.wait(timeout=5) is True + assert search_deadline.expired() is True + + +def test_timer_is_cancelled_on_exit(): + """A finished search must not leave a timer running to fire later.""" + with search_deadline.search_deadline(3600) as deadline: + pass + assert deadline._timer.finished.is_set() + + +def test_message_names_the_challenge_not_the_proxy(): + with search_deadline.search_deadline(120): + message = search_deadline.deadline_message() + assert "120s" in message + assert "protection challenge" in message + assert "504" not in message + + +# --------------------------------------------------------------------------- # +# Reading the setting +# --------------------------------------------------------------------------- # +@pytest.mark.parametrize( + ("configured", "expected"), + [ + (600, 600.0), + ("450", 450.0), + (None, search_deadline.DEFAULT_SEARCH_BUDGET_SECONDS), + ("nonsense", search_deadline.DEFAULT_SEARCH_BUDGET_SECONDS), + (0, search_deadline.DEFAULT_SEARCH_BUDGET_SECONDS), + (True, search_deadline.DEFAULT_SEARCH_BUDGET_SECONDS), + (5, 30.0), # clamped up: below this nothing can finish + (99999, 1800.0), # clamped down + ], +) +def test_budget_seconds_coerces_and_clamps(monkeypatch, configured, expected): + from shelfmark.core.config import config as app_config + + monkeypatch.setattr( + app_config, + "get", + lambda key, default=None: configured if key == "RELEASE_SEARCH_TIMEOUT" else default, + ) + + assert search_deadline.budget_seconds() == expected + + +# --------------------------------------------------------------------------- # +# What the search path does with it +# --------------------------------------------------------------------------- # +def test_html_get_page_will_not_start_a_bypass_on_a_spent_budget(monkeypatch): + """A minutes-long solve nobody is still waiting for is worse than a clear failure.""" + import shelfmark.download.http as http + + started: list[str] = [] + monkeypatch.setattr( + http, "get_bypassed_page", lambda *a, **k: started.append(a[0]) or "" + ) + monkeypatch.setattr(http, "_is_cf_bypass_enabled", lambda: True) + monkeypatch.setattr(http, "_bypass_grace_seconds", lambda: 1.0) + monkeypatch.setattr(http.network, "should_rotate_dns_for_url", lambda _url: True) + monkeypatch.setattr(http, "get_proxies", lambda _url: {}) + monkeypatch.setattr(http.time, "sleep", lambda _s: None) + + class _Selector: + current_base = "https://annas-archive.gl" + attempts_this_dns = 0 + last_failure = None + + def rewrite(self, url): + return url + + with search_deadline.search_deadline(60) as deadline: + deadline.event.set() + result = http.html_get_page( + "https://annas-archive.gl/search", + retry=1, + selector=_Selector(), + use_bypasser=True, + success_delay=0, + ) + + assert result == "" + assert started == [], "no solve should have been started" + + +def test_search_budget_becomes_the_cancel_flag(monkeypatch): + """This is what makes the budget bite on a solve already running.""" + import shelfmark.download.http as http + + seen: list[object] = [] + + def fake_bypass(_url, _selector=None, cancel_flag=None): + seen.append(cancel_flag) + return "solved" + + monkeypatch.setattr(http, "get_bypassed_page", fake_bypass) + monkeypatch.setattr(http, "_is_cf_bypass_enabled", lambda: True) + monkeypatch.setattr(http, "_bypass_grace_seconds", lambda: 1.0) + monkeypatch.setattr(http.network, "should_rotate_dns_for_url", lambda _url: True) + monkeypatch.setattr(http, "get_proxies", lambda _url: {}) + monkeypatch.setattr(http.time, "sleep", lambda _s: None) + + class _Selector: + current_base = "https://annas-archive.gl" + attempts_this_dns = 0 + last_failure = None + + def rewrite(self, url): + return url + + with search_deadline.search_deadline(60) as deadline: + http.html_get_page( + "https://annas-archive.gl/search", + retry=1, + selector=_Selector(), + use_bypasser=True, + success_delay=0, + ) + + assert seen == [deadline.event] + + +def test_a_callers_own_cancel_flag_is_not_replaced(monkeypatch): + """A queued download brings its own and must keep it.""" + import shelfmark.download.http as http + + seen: list[object] = [] + + def fake_bypass(_url, _selector=None, cancel_flag=None): + seen.append(cancel_flag) + return "solved" + + monkeypatch.setattr(http, "get_bypassed_page", fake_bypass) + monkeypatch.setattr(http, "_is_cf_bypass_enabled", lambda: True) + monkeypatch.setattr(http, "_bypass_grace_seconds", lambda: 1.0) + monkeypatch.setattr(http.network, "should_rotate_dns_for_url", lambda _url: True) + monkeypatch.setattr(http, "get_proxies", lambda _url: {}) + monkeypatch.setattr(http.time, "sleep", lambda _s: None) + + class _Selector: + current_base = "https://annas-archive.gl" + attempts_this_dns = 0 + last_failure = None + + def rewrite(self, url): + return url + + own_flag = threading.Event() + with search_deadline.search_deadline(60): + http.html_get_page( + "https://annas-archive.gl/search", + retry=1, + selector=_Selector(), + cancel_flag=own_flag, + use_bypasser=True, + success_delay=0, + ) + + assert seen == [own_flag] + + +def test_expired_budget_reports_the_challenge_not_a_cancellation(monkeypatch): + """The budget trips the same flag a user's cancel does; the messages must differ.""" + import shelfmark.download.http as http + from shelfmark.bypass import BypassCancelledError + + def fake_bypass(*_a, **_k): + msg = "Bypass cancelled" + raise BypassCancelledError(msg) + + monkeypatch.setattr(http, "get_bypassed_page", fake_bypass) + monkeypatch.setattr(http, "_is_cf_bypass_enabled", lambda: True) + monkeypatch.setattr(http, "_bypass_grace_seconds", lambda: 1.0) + monkeypatch.setattr(http.network, "should_rotate_dns_for_url", lambda _url: True) + monkeypatch.setattr(http, "get_proxies", lambda _url: {}) + monkeypatch.setattr(http.time, "sleep", lambda _s: None) + + failures: list[str] = [] + + class _Selector: + current_base = "https://annas-archive.gl" + attempts_this_dns = 0 + + def rewrite(self, url): + return url + + @property + def last_failure(self): + return None + + @last_failure.setter + def last_failure(self, value): + if value: + failures.append(value) + + with search_deadline.search_deadline(60) as deadline: + # Expire mid-solve: the flag is set, but the caller reaches the handler by way of + # BypassCancelledError, which on its own reads as "someone cancelled this". + deadline.expires_at = 0.0 + http.html_get_page( + "https://annas-archive.gl/search", + retry=1, + selector=_Selector(), + use_bypasser=True, + success_delay=0, + ) + + assert failures, "a give-up reason should have been recorded" + assert "ran out of time" in failures[-1] + assert "cancelled" not in failures[-1] diff --git a/tests/core/test_search_plan_language_codes.py b/tests/core/test_search_plan_language_codes.py new file mode 100644 index 0000000..65995f8 --- /dev/null +++ b/tests/core/test_search_plan_language_codes.py @@ -0,0 +1,148 @@ +"""Language filters must reach the sources as ISO codes. + +Issue #1276: a debug bundle showed `BOOK_LANGUAGE=english` arriving at Anna's Archive +verbatim as `&lang=english`. AA matches that parameter against ISO codes, so it is not a +loose spelling of `lang=en` - it is a facet value AA does not have, and it empties every +search. In that bundle a successful solve of an ISBN search for Philosopher's Stone +returned zero hits, while a warm-up query carrying no language filter hit the same host +in the same minute and returned 50. + +Only the per-user override was normalised (config.users_settings.validate). The global +default - which is what the env var feeds - was passed through with nothing but a +.strip(), so anyone carrying `BOOK_LANGUAGE=english` from the old docs had every search +silently filtered to nothing, with no error anywhere. +""" + +import logging + +import pytest + +import shelfmark.core.search_plan as sp +from shelfmark.metadata_providers import BookMetadata + + +def _config_get(global_languages): + def _get(key: str, default: object = None, user_id: int | None = None) -> object: + return global_languages if key == "BOOK_LANGUAGE" else default + + return _get + + +def _book() -> BookMetadata: + return BookMetadata( + provider="hardcover", + provider_id="123", + title="Harry Potter and the Philosopher's Stone", + search_title="Harry Potter and the Philosopher's Stone", + search_author="J.K. Rowling", + authors=["J.K. Rowling"], + ) + + +@pytest.fixture +def plan_logs(): + """Collect search_plan log records. + + setup_logger builds its loggers outside the standard hierarchy, so caplog's root + handler never sees them, and Logger.setLevel cannot clear their is-enabled cache. + """ + messages: list[str] = [] + + class _Capture(logging.Handler): + def emit(self, record: logging.LogRecord) -> None: + messages.append(record.getMessage()) + + handler = _Capture() + sp.logger.addHandler(handler) + previous = sp.logger.level + sp.logger.setLevel(logging.DEBUG) + sp.logger._cache.clear() + try: + yield messages + finally: + sp.logger.removeHandler(handler) + sp.logger.setLevel(previous) + + +# --------------------------------------------------------------------------- # +# The global default (what BOOK_LANGUAGE feeds) +# --------------------------------------------------------------------------- # +@pytest.mark.parametrize( + ("configured", "expected"), + [ + (["english"], ["en"]), # the spelling from the old docs - the reported bug + ("english", ["en"]), # env vars arrive as a bare string + (["English"], ["en"]), + (["eng"], ["en"]), # ISO 639-2 + (["en"], ["en"]), # already a code, unchanged + (["english", "german"], ["en", "de"]), + (["english", "en", "English"], ["en"]), # collapses to one code + ], +) +def test_default_languages_reach_the_plan_as_iso_codes(monkeypatch, configured, expected): + monkeypatch.setattr(sp.config, "get", _config_get(configured)) + + plan = sp.build_release_search_plan(_book(), languages=None) + + assert plan.languages == expected + + +def test_unrecognised_default_searches_unfiltered_rather_than_empty(monkeypatch, plan_logs): + """Dropping the filter is the safe failure: a warned-about unfiltered search beats + telling the user a book AA is full of does not exist.""" + monkeypatch.setattr(sp.config, "get", _config_get(["klingon"])) + + plan = sp.build_release_search_plan(_book(), languages=None) + + assert plan.languages is None + assert any("klingon" in m and "BOOK_LANGUAGE" in m for m in plan_logs), plan_logs + + +def test_partly_unrecognised_default_keeps_what_resolved(monkeypatch, plan_logs): + monkeypatch.setattr(sp.config, "get", _config_get(["english", "klingon"])) + + plan = sp.build_release_search_plan(_book(), languages=None) + + assert plan.languages == ["en"] + assert any("klingon" in m for m in plan_logs) + + +def test_a_clean_default_logs_no_warning(monkeypatch, plan_logs): + monkeypatch.setattr(sp.config, "get", _config_get(["en", "de"])) + + sp.build_release_search_plan(_book(), languages=None) + + assert not [m for m in plan_logs if "Ignoring unrecognised" in m] + + +# --------------------------------------------------------------------------- # +# Explicit request languages go through the same door +# --------------------------------------------------------------------------- # +def test_explicit_languages_are_normalised_too(monkeypatch): + """The request branch had the same bare .strip(), so an API client could reproduce + the bug even with BOOK_LANGUAGE set correctly.""" + monkeypatch.setattr(sp.config, "get", _config_get(["en"])) + + plan = sp.build_release_search_plan(_book(), languages=["english", "German"]) + + assert plan.languages == ["en", "de"] + + +def test_all_still_means_no_language_filter(monkeypatch): + monkeypatch.setattr(sp.config, "get", _config_get(["en"])) + + assert sp.build_release_search_plan(_book(), languages=["all"]).languages is None + + +def test_blank_entries_are_skipped(monkeypatch): + monkeypatch.setattr(sp.config, "get", _config_get(["en"])) + + plan = sp.build_release_search_plan(_book(), languages=["english", "", " ", None]) + + assert plan.languages == ["en"] + + +def test_no_configured_default_leaves_the_filter_off(monkeypatch): + monkeypatch.setattr(sp.config, "get", _config_get(None)) + + assert sp.build_release_search_plan(_book(), languages=None).languages is None diff --git a/tests/direct_download/test_search_budget.py b/tests/direct_download/test_search_budget.py new file mode 100644 index 0000000..8c936da --- /dev/null +++ b/tests/direct_download/test_search_budget.py @@ -0,0 +1,144 @@ +"""A spent search budget stops the search rather than starting the next attempt. + +One release search fans out: a mirror loop inside `_fetch_search_table`, then a title +variant per grouped variant, then the whole set again without the language filter. Each +of those can reach the bypasser, and `except Exception` around the variant loops was +built to keep going past a parse failure. Applied to a spent budget that meant the +variants queued up behind each other long after anyone was still waiting - which is how +a challenge failure became a gateway timeout (issue #1276). +""" + +import pytest + +import shelfmark.release_sources.direct_download as dd +from shelfmark.core import search_deadline + + +@pytest.fixture(autouse=True) +def _no_ambient_deadline(): + token = search_deadline._current.set(None) + yield + search_deadline._current.reset(token) + + +class _Selector: + current_base = "https://annas-archive.gl" + last_failure = None + + def rewrite(self, url: str) -> str: + return url + + def next_mirror_or_rotate_dns(self, *, fatal: bool = False, reason: str = ""): + return None, "exhausted" + + +def test_fetch_search_table_gives_up_when_the_budget_is_spent(monkeypatch): + """Every mirror shares the protection, so another mirror is another wasted solve.""" + fetches: list[str] = [] + monkeypatch.setattr(dd.downloader, "html_get_page", lambda url, **_k: fetches.append(url) or "") + monkeypatch.setattr(dd.network, "get_available_aa_urls", lambda: ["https://annas-archive.gl"]) + + with search_deadline.search_deadline(60) as deadline: + deadline.event.set() + with pytest.raises(dd.SearchUnavailableError) as excinfo: + dd._fetch_search_table("https://annas-archive.gl/search?q=dune", _Selector()) + + assert fetches == [], "no fetch should have been attempted" + assert "ran out of time" in str(excinfo.value) + + +def test_fetch_search_table_runs_normally_within_budget(monkeypatch): + page = "
" + monkeypatch.setattr(dd.downloader, "html_get_page", lambda _url, **_k: page) + monkeypatch.setattr(dd.network, "get_available_aa_urls", lambda: ["https://annas-archive.gl"]) + + with search_deadline.search_deadline(60): + html, table = dd._fetch_search_table("https://annas-archive.gl/search?q=dune", _Selector()) + + assert table is not None + assert html == page + + +def _plan(titles): + """A search plan with one grouped title variant per title.""" + from shelfmark.core.search_plan import ReleaseSearchPlan, ReleaseSearchVariant + + variants = [ReleaseSearchVariant(t, "Frank Herbert", ["en"]) for t in titles] + return ReleaseSearchPlan( + languages=["en"], + isbn_candidates=[], + author="Frank Herbert", + title_variants=variants, + grouped_title_variants=variants, + ) + + +def _book(): + from shelfmark.metadata_providers import BookMetadata + + return BookMetadata( + provider="manual", + provider_id="x", + provider_display_name="Manual", + title="Dune", + search_title="Dune", + authors=["Frank Herbert"], + ) + + +def test_title_variants_stop_once_the_budget_is_spent(monkeypatch): + """`except Exception` keeps this loop going past a failure; a spent budget must not.""" + queries: list[str] = [] + + def fake_search_books(query, _filters): + queries.append(query) + # The first variant is what spends the budget. + deadline = search_deadline.current() + if deadline is not None: + deadline.event.set() + return [] + + monkeypatch.setattr(dd, "search_books", fake_search_books) + monkeypatch.setattr(dd, "_ensure_direct_download_available", lambda: None) + + source = dd.DirectDownloadSource() + with search_deadline.search_deadline(60): + releases = source.search(_book(), _plan(["Dune", "Duna", "Dünen"])) + + assert releases == [] + assert len(queries) == 1, f"only the first variant should have run, got {queries}" + + +def test_all_title_variants_run_within_budget(monkeypatch): + queries: list[str] = [] + monkeypatch.setattr(dd, "search_books", lambda q, _f: queries.append(q) or []) + monkeypatch.setattr(dd, "_ensure_direct_download_available", lambda: None) + + source = dd.DirectDownloadSource() + with search_deadline.search_deadline(60): + source.search(_book(), _plan(["Dune", "Duna"])) + + # Two variants with a language filter, then both again without one. + assert len(queries) == 4 + + +def test_language_filter_retry_is_skipped_on_a_spent_budget(monkeypatch): + """The no-language sweep doubles the work; it must not start after the deadline.""" + queries: list[str] = [] + + def fake_search_books(query, _filters): + queries.append(query) + if len(queries) == 2: + deadline = search_deadline.current() + if deadline is not None: + deadline.event.set() + return [] + + monkeypatch.setattr(dd, "search_books", fake_search_books) + monkeypatch.setattr(dd, "_ensure_direct_download_available", lambda: None) + + source = dd.DirectDownloadSource() + with search_deadline.search_deadline(60): + source.search(_book(), _plan(["Dune", "Duna"])) + + assert len(queries) == 2, f"the retry sweep should not have started, got {queries}" diff --git a/tests/download/conftest.py b/tests/download/conftest.py new file mode 100644 index 0000000..8b19a73 --- /dev/null +++ b/tests/download/conftest.py @@ -0,0 +1,21 @@ +"""Shared fixtures for the download tests.""" + +import pytest + + +@pytest.fixture(autouse=True) +def _clear_warmup_user_search_flag(): + """Start every download test with the warm-up's "a user searched" flag clear. + + The flag is process-global by design - the warm-up is a one-shot per process, and + once a real search has run there is nothing left to pre-solve. That makes it leak + between tests: `/api/releases` sets it, so any API test sharing an xdist worker with + the warm-up tests would otherwise decide the warm-up for them. It surfaced as + test_search_warmup.py failing only on CI, where the workers divide up differently + than they happen to locally. + """ + from shelfmark.download import warmup + + warmup._user_search_seen.clear() + yield + warmup._user_search_seen.clear() diff --git a/tests/download/test_ddg_handshake_cookies.py b/tests/download/test_ddg_handshake_cookies.py new file mode 100644 index 0000000..173662a --- /dev/null +++ b/tests/download/test_ddg_handshake_cookies.py @@ -0,0 +1,153 @@ +"""The DDoS-Guard ?check=1 handshake must win over anything the clearance store holds. + +DDoS-Guard reuses the same cookie names (__ddg1_/__ddg2_) for the probe it issues on the +302 and for what a solve leaves behind. When the store's copy was merged on top, the value +the server had just issued never left the process, the probe could never terminate, and +every request ended in the redirect-loop handoff and paid for a full browser solve - one +per query, which is exactly what was reported on issue #1276. +""" + +import pytest +import requests + +import shelfmark.bypass.cookie_store as cs +import shelfmark.download.http as http + +URL = "https://annas-archive.gl/search?q=dune" +FRESH = {"__ddg1_": "FRESH1", "__ddg2_": "FRESH2"} + + +class _FakeResponse: + def __init__(self, status_code, *, headers=None, cookies=None, text="", url=URL): + self.status_code = status_code + self.headers = headers or {} + self.cookies = cookies or {} + self.text = text + self.url = url + + @property + def is_redirect(self): + return self.status_code in (301, 302, 303, 307, 308) and "Location" in self.headers + + def raise_for_status(self): + if self.status_code >= 400: + error = requests.exceptions.HTTPError(f"{self.status_code} Error") + error.response = self + raise error + + +class _DummySelector: + """AA selector stub, so these tests never elect a real mirror.""" + + def __init__(self) -> None: + self.current_base = "https://annas-archive.gl" + self.attempts_this_dns = 0 + self.last_failure: str | None = None + + def rewrite(self, url: str) -> str: + return url + + def next_mirror_or_rotate_dns(self, allow_dns=True, *, fatal=False, reason=""): + return None, "exhausted" + + +@pytest.fixture +def ddos_guard(monkeypatch): + """An AA mirror that grants the page only once the client echoes what it issued.""" + monkeypatch.setattr(cs, "_cf_cookies", {}) + monkeypatch.setattr(cs, "_cf_user_agents", {}) + # Keeps the store from importing the mirror registry (and its dependency graph) + # for a lookup these tests do not exercise. + monkeypatch.setattr(cs, "_get_full_cookie_domains", set) + monkeypatch.setattr(http.network, "should_rotate_dns_for_url", lambda _url: True) + monkeypatch.setattr(http.network, "is_aa_auto_mode", lambda: True) + monkeypatch.setattr(http, "get_proxies", lambda _url: {}) + monkeypatch.setattr(http, "get_ssl_verify", lambda _url: True) + monkeypatch.setattr(http, "_is_cf_bypass_enabled", lambda: True) + monkeypatch.setattr(http.time, "sleep", lambda _seconds: None) + + sent: list[dict[str, str]] = [] + + def fake_get(_url, **kwargs): + cookies = dict(kwargs.get("cookies") or {}) + sent.append(cookies) + if all(cookies.get(name) == value for name, value in FRESH.items()): + return _FakeResponse(200, text="the real search page") + return _FakeResponse( + 302, headers={"Location": "/search?q=dune&check=1"}, cookies=dict(FRESH) + ) + + monkeypatch.setattr(http.requests, "get", fake_get) + return sent + + +@pytest.fixture +def bypasser_calls(monkeypatch): + """Record redirect-loop handoffs instead of starting a browser.""" + calls: list[str] = [] + + def fake_get_bypassed_page(url, _selector=None, _cancel_flag=None): + calls.append(url) + return "solved by the browser" + + monkeypatch.setattr(http, "get_bypassed_page", fake_get_bypassed_page) + monkeypatch.setattr(http, "_bypass_grace_seconds", lambda: 1.0) + return calls + + +def test_handshake_completes_with_an_empty_store(ddos_guard, bypasser_calls): + """The baseline: echoing the issued cookies back clears the probe in two hops.""" + html = http.html_get_page(URL, retry=1, selector=_DummySelector(), success_delay=0) + + assert html == "the real search page" + assert ddos_guard == [{}, FRESH] + assert not bypasser_calls, "no browser solve should have been needed" + + +def test_stored_clearance_does_not_mask_the_issued_cookies(ddos_guard, bypasser_calls): + """A solve leaves __ddg1_/__ddg2_ behind; the next probe must still be answerable. + + This is the regression. With the store merged last, all six hops re-sent the stale + pair, the loop never terminated and the request fell through to a browser solve. + """ + cs._cf_cookies["annas-archive.gl"] = { + "__ddg1_": {"value": "STALE1", "expiry": None}, + "__ddg2_": {"value": "STALE2", "expiry": None}, + } + + html = http.html_get_page(URL, retry=1, selector=_DummySelector(), success_delay=0) + + assert html == "the real search page" + assert not bypasser_calls, "a stale cookie must not cost a browser solve" + # First hop presents what the store had; the second answers with what was just issued. + assert ddos_guard[0] == {"__ddg1_": "STALE1", "__ddg2_": "STALE2"} + assert ddos_guard[-1] == FRESH + + +def test_store_still_applies_when_the_server_issues_nothing(monkeypatch, bypasser_calls): + """Handshake cookies winning must not stop stored clearance being presented.""" + monkeypatch.setattr(cs, "_cf_cookies", {}) + monkeypatch.setattr(cs, "_cf_user_agents", {}) + # Keeps the store from importing the mirror registry (and its dependency graph) + # for a lookup these tests do not exercise. + monkeypatch.setattr(cs, "_get_full_cookie_domains", set) + monkeypatch.setattr(http.network, "should_rotate_dns_for_url", lambda _url: True) + monkeypatch.setattr(http, "get_proxies", lambda _url: {}) + monkeypatch.setattr(http, "get_ssl_verify", lambda _url: True) + monkeypatch.setattr(http, "_is_cf_bypass_enabled", lambda: True) + monkeypatch.setattr(http.time, "sleep", lambda _seconds: None) + cs._cf_cookies["annas-archive.gl"] = {"__ddg1_": {"value": "CLEARANCE", "expiry": None}} + + sent: list[dict[str, str]] = [] + + def fake_get(_url, **kwargs): + sent.append(dict(kwargs.get("cookies") or {})) + return _FakeResponse(200, text="page") + + monkeypatch.setattr(http.requests, "get", fake_get) + + assert ( + http.html_get_page(URL, retry=1, selector=_DummySelector(), success_delay=0) + == "page" + ) + assert sent == [{"__ddg1_": "CLEARANCE"}] diff --git a/tests/download/test_warmup_yields_to_user.py b/tests/download/test_warmup_yields_to_user.py new file mode 100644 index 0000000..b8ea9fa --- /dev/null +++ b/tests/download/test_warmup_yields_to_user.py @@ -0,0 +1,65 @@ +"""The warm-up must not queue its throwaway solve in front of the user's first search. + +Issue #1276: the warm-up fires 15s after boot, and the bundle showed a user clicking a +book 13 seconds in. Three seconds later the warm-up started anyway, and because the +bypasser serializes on one browser, the user's title+author search sat behind a solve for +"The Great Gatsby" from 13:41:26 to 13:42:26 - a full minute of a 2m27s wait, for a query +nobody asked for. Once the user has beaten the warm-up to it there is nothing left to +pre-solve. +""" + +import shelfmark.download.warmup as warmup + +# The flag is cleared around every test by an autouse fixture in conftest.py - it is +# process-global, and /api/releases sets it, so tests that read it cannot rely on +# whatever else shared their xdist worker. + + +def test_warmup_runs_when_nobody_has_searched(monkeypatch): + monkeypatch.setattr( + "shelfmark.core.mirrors.has_aa_mirror_configuration", lambda: True, raising=False + ) + searched: list[str] = [] + monkeypatch.setattr( + "shelfmark.release_sources.direct_download.search_books", + lambda query, _filters: searched.append(query) or ["a result"], + ) + + assert warmup.run_warmup() is True + assert searched == [warmup.warmup_query()] + + +def test_warmup_stands_down_once_a_real_search_has_started(monkeypatch): + searched: list[str] = [] + monkeypatch.setattr( + "shelfmark.release_sources.direct_download.search_books", + lambda query, _filters: searched.append(query) or [], + ) + + warmup.note_user_search() + + assert warmup.run_warmup() is False + assert searched == [], "the warm-up must not compete for the bypasser" + + +def test_the_check_happens_at_fire_time_not_schedule_time(monkeypatch): + """The start-up delay is exactly what this races with, so a search that lands during + the wait has to count - checking only in start() would miss every real case.""" + monkeypatch.setattr( + "shelfmark.core.mirrors.has_aa_mirror_configuration", lambda: True, raising=False + ) + searched: list[str] = [] + monkeypatch.setattr( + "shelfmark.release_sources.direct_download.search_books", + lambda query, _filters: searched.append(query) or [], + ) + + # Scheduling succeeds: at this point nothing has searched. + monkeypatch.setattr(warmup, "_setting", lambda _key, _default: True) + assert warmup.is_enabled() is True + + # The user clicks while the timer is still pending. + warmup.note_user_search() + + assert warmup.run_warmup() is False + assert searched == [] diff --git a/tests/newznab/test_source.py b/tests/newznab/test_source.py index dbb4011..4b6fe9c 100644 --- a/tests/newznab/test_source.py +++ b/tests/newznab/test_source.py @@ -547,9 +547,7 @@ class TestSearch: def client_factory(url, _api_key): client = MagicMock() - client.search.return_value = [ - _make_result(guid=f"{url}/guid", indexer=None) - ] + client.search.return_value = [_make_result(guid=f"{url}/guid", indexer=None)] return client monkeypatch.setattr(mod, "NewznabClient", client_factory) diff --git a/tests/prowlarr/test_qbittorrent_client.py b/tests/prowlarr/test_qbittorrent_client.py index f61a311..48728b6 100644 --- a/tests/prowlarr/test_qbittorrent_client.py +++ b/tests/prowlarr/test_qbittorrent_client.py @@ -1001,6 +1001,106 @@ class TestQBittorrentClientAddDownload: assert status.state.value == "downloading" + def test_status_polls_reuse_resolved_hash_after_metadata_switch(self, monkeypatch): + """Scan for the re-keyed hash once, then poll it directly.""" + config_values = { + "QBITTORRENT_URL": "http://localhost:8080", + "QBITTORRENT_USERNAME": "admin", + "QBITTORRENT_PASSWORD": "password", + "QBITTORRENT_CATEGORY": "books", + } + monkeypatch.setattr( + "shelfmark.download.clients.qbittorrent.config.get", + lambda key, default="": config_values.get(key, default), + ) + + v1_hash = "edf46c7f938a3c678081734d7bff8b9c652ba5e5" + v2_hash = "0bed5f40753b342cb143e83c2b21924cc8474731" + full_v2_hash = "0bed5f40753b342cb143e83c2b21924cc847473134e44d1bd300bdc58c13010f" + resolved_torrent = MockTorrent( + hash_val=v2_hash, + state="downloading", + infohash_v1=v1_hash, + infohash_v2=full_v2_hash, + ) + mock_client_instance = MagicMock() + mock_client_instance._session.get.side_effect = [ + create_mock_session_response([]), + create_mock_session_response([resolved_torrent]), + create_mock_session_response([resolved_torrent]), + ] + mock_client_class = MagicMock(return_value=mock_client_instance) + + with patch.dict("sys.modules", {"qbittorrentapi": MagicMock(Client=mock_client_class)}): + import importlib + + import shelfmark.download.clients.qbittorrent as qb_module + + importlib.reload(qb_module) + + client = qb_module.QBittorrentClient() + + assert client.get_status(v1_hash).state_value == "downloading" + assert client.get_status(v1_hash).state_value == "downloading" + + # The second poll goes straight to the hash the first one resolved, + # rather than listing every torrent again. + assert [ + call.kwargs["params"] for call in mock_client_instance._session.get.call_args_list + ] == [ + {"hashes": v1_hash}, + {"category": "books"}, + {"hashes": v2_hash}, + ] + + def test_remove_forgets_resolved_hash(self, monkeypatch): + """Drop the remembered hash on removal so a re-add is resolved afresh.""" + config_values = { + "QBITTORRENT_URL": "http://localhost:8080", + "QBITTORRENT_USERNAME": "admin", + "QBITTORRENT_PASSWORD": "password", + "QBITTORRENT_CATEGORY": "books", + } + monkeypatch.setattr( + "shelfmark.download.clients.qbittorrent.config.get", + lambda key, default="": config_values.get(key, default), + ) + + v1_hash = "edf46c7f938a3c678081734d7bff8b9c652ba5e5" + v2_hash = "0bed5f40753b342cb143e83c2b21924cc8474731" + full_v2_hash = "0bed5f40753b342cb143e83c2b21924cc847473134e44d1bd300bdc58c13010f" + resolved_torrent = MockTorrent( + hash_val=v2_hash, + state="downloading", + infohash_v1=v1_hash, + infohash_v2=full_v2_hash, + ) + mock_client_instance = MagicMock() + mock_client_instance._session.get.side_effect = [ + create_mock_session_response([]), + create_mock_session_response([resolved_torrent]), + create_mock_session_response([resolved_torrent]), + ] + mock_client_class = MagicMock(return_value=mock_client_instance) + + with patch.dict("sys.modules", {"qbittorrentapi": MagicMock(Client=mock_client_class)}): + import importlib + + import shelfmark.download.clients.qbittorrent as qb_module + + importlib.reload(qb_module) + + client = qb_module.QBittorrentClient() + client.get_status(v1_hash) + + assert client.remove(v1_hash) is True + + # The delete addressed the current primary hash, and the entry is gone. + assert ( + mock_client_instance.torrents_delete.call_args.kwargs["torrent_hashes"] == v2_hash + ) + assert client._primary_hashes == {} + def test_add_download_uses_expected_hash_without_fetch(self, monkeypatch): """Skip proxy fetch when expected hash is provided for URL torrents.""" config_values = { @@ -1785,6 +1885,51 @@ class TestQBittorrentClientFindExisting: {"hashes": v2_hash}, ] + def test_find_existing_keeps_torrent_whose_metadata_is_pending(self, monkeypatch): + """Join a magnet still fetching metadata instead of adding a duplicate.""" + config_values = { + "QBITTORRENT_URL": "http://localhost:8080", + "QBITTORRENT_USERNAME": "admin", + "QBITTORRENT_PASSWORD": "password", + "QBITTORRENT_CATEGORY": "books", + } + monkeypatch.setattr( + "shelfmark.download.clients.qbittorrent.config.get", + lambda key, default="": config_values.get(key, default), + ) + monkeypatch.setattr( + "shelfmark.download.clients.qbittorrent.time.sleep", lambda _seconds: None + ) + + v1_hash = "edf46c7f938a3c678081734d7bff8b9c652ba5e5" + metadata_torrent = MockTorrent( + hash_val=v1_hash, + state="metaDL", + infohash_v1=v1_hash, + ) + mock_client_instance = MagicMock() + mock_client_instance._session.get.return_value = create_mock_session_response( + [metadata_torrent] + ) + mock_client_class = MagicMock(return_value=mock_client_instance) + + with patch.dict("sys.modules", {"qbittorrentapi": MagicMock(Client=mock_client_class)}): + import importlib + + import shelfmark.download.clients.qbittorrent as qb_module + + importlib.reload(qb_module) + + client = qb_module.QBittorrentClient() + magnet = f"magnet:?xt=urn:btih:{v1_hash}&dn=test" + result = client.find_existing(magnet) + + assert result is not None + download_id, status = result + assert download_id == v1_hash + assert status.state_value == "downloading" + assert status.message == "Fetching metadata" + def test_find_existing_not_found(self, monkeypatch): """Test finding non-existent torrent.""" config_values = { diff --git a/tests/prowlarr/test_source.py b/tests/prowlarr/test_source.py index 6a4ee15..5191acc 100644 --- a/tests/prowlarr/test_source.py +++ b/tests/prowlarr/test_source.py @@ -17,6 +17,7 @@ from shelfmark.release_sources.prowlarr.source import ( _build_indexer_priority, _collapse_duplicate_indexer_results, _detect_content_type_from_categories, + _drop_unknown_indexer_ids, _extract_format, _extract_mam_language, _fetch_indexer_seed_settings, @@ -1475,3 +1476,62 @@ class TestUnrecognizedFormatOnRelease: self._result("The Martian by Andy Weir [ENG / AVI]"), "audiobook" ) assert release.extra["unrecognized_formats"] is None + + +class TestProwlarrStaleIndexerSelection: + """Indexers removed or disabled in Prowlarr must not be searched (#1283).""" + + def test_drop_unknown_indexer_ids_keeps_only_live_indexers(self): + assert _drop_unknown_indexer_ids([1, 99], [{"id": 1}, {"id": 2}]) == [1] + + def test_drop_unknown_indexer_ids_leaves_search_all_alone(self): + assert _drop_unknown_indexer_ids(None, [{"id": 1}]) is None + + def _search_with_selection(self, monkeypatch, selection): + import shelfmark.release_sources.prowlarr.source as prowlarr_source + + def fake_get(key: str, default=None): + values = { + "PROWLARR_INDEXERS": selection, + "PROWLARR_AUTO_EXPAND": False, + } + return values.get(key, default) + + monkeypatch.setattr(prowlarr_source.config, "get", fake_get) + + class RecordingClient(FakeTorznabClient): + def __init__(self): + super().__init__() + self.searched_indexer_ids: list[int] = [] + + def torznab_search(self, *, indexer_id: int, **kwargs): + self.searched_indexer_ids.append(indexer_id) + return super().torznab_search(indexer_id=indexer_id, **kwargs) + + fake_client = RecordingClient() + source = ProwlarrSource() + monkeypatch.setattr(source, "_get_client", lambda: fake_client) + + book = BookMetadata( + provider="hardcover", + provider_id="123", + title="Anything", + authors=["Someone"], + ) + + from shelfmark.core.search_plan import build_release_search_plan + + plan = build_release_search_plan(book, languages=["en"], manual_query="my custom") + source.search(book, plan, content_type="ebook") + return fake_client + + def test_search_skips_indexer_missing_from_prowlarr(self, monkeypatch): + # The fake Prowlarr only serves indexer 1; 99 was removed behind our back. + fake_client = self._search_with_selection(monkeypatch, [1, 99]) + + assert fake_client.searched_indexer_ids == [1] + + def test_search_queries_nothing_when_every_selected_indexer_is_gone(self, monkeypatch): + fake_client = self._search_with_selection(monkeypatch, [98, 99]) + + assert fake_client.searched_indexer_ids == []