mirror of
https://github.com/calibrain/shelfmark.git
synced 2026-09-24 19:10:30 +01:00
This commit is contained in:
@@ -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**
|
||||
|
||||
@@ -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
|
||||
|
||||
@@ -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
|
||||
|
||||
|
||||
@@ -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,
|
||||
|
||||
@@ -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
|
||||
|
||||
@@ -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",
|
||||
|
||||
@@ -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
|
||||
@@ -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:
|
||||
|
||||
@@ -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
|
||||
|
||||
@@ -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),
|
||||
|
||||
@@ -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
|
||||
|
||||
+27
-8
@@ -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]
|
||||
|
||||
@@ -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:
|
||||
|
||||
@@ -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(
|
||||
|
||||
@@ -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 "<html>solved</html>"
|
||||
|
||||
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) == "<html>solved</html>"
|
||||
assert attempts["n"] == 1
|
||||
@@ -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
|
||||
|
||||
@@ -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()
|
||||
@@ -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]
|
||||
@@ -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
|
||||
@@ -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 "<html/>"
|
||||
)
|
||||
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 "<html>solved</html>"
|
||||
|
||||
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 "<html>solved</html>"
|
||||
|
||||
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]
|
||||
@@ -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
|
||||
@@ -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 = "<html><body><main><table><tbody></tbody></table></main></body></html>"
|
||||
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}"
|
||||
@@ -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()
|
||||
@@ -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="<html>the real search page</html>")
|
||||
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 "<html>solved by the browser</html>"
|
||||
|
||||
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 == "<html>the real search page</html>"
|
||||
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 == "<html>the real search page</html>"
|
||||
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="<html>page</html>")
|
||||
|
||||
monkeypatch.setattr(http.requests, "get", fake_get)
|
||||
|
||||
assert (
|
||||
http.html_get_page(URL, retry=1, selector=_DummySelector(), success_delay=0)
|
||||
== "<html>page</html>"
|
||||
)
|
||||
assert sent == [{"__ddg1_": "CLEARANCE"}]
|
||||
@@ -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 == []
|
||||
@@ -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)
|
||||
|
||||
@@ -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 = {
|
||||
|
||||
@@ -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 == []
|
||||
|
||||
Reference in New Issue
Block a user