Fix LOG_LEVEL being ignored and Z-Library 503 cookie gate (#1188)

LOG_LEVEL never reached the app logger: env.py hardcoded the level to
DEBUG or INFO, so INFO lines kept appearing under LOG_LEVEL=error. Read
it from the env var and advanced settings, normalize unknown values to
INFO, and expose it as a setting. entrypoint.sh now normalizes
gunicorn's level too, so a typo falls back to info instead of stopping
the container from booting.

Z-Library gates the first hit on /md5/<hash> with a 503 whose only
payload is a Set-Cookie; echoing that cookie back returns the 302 to the
real page. html_get_page dropped it and re-ran the same rejected request
on every retry, ending in "No download URL resolved". Retry once with
the
cookies the 503 issued.

Fixes #1185
Fixes #1187
This commit is contained in:
CaliBrain
2026-08-11 23:27:44 -04:00
committed by GitHub
parent bb848f05bc
commit e320b7623d
10 changed files with 381 additions and 18 deletions
+54 -1
View File
@@ -23,6 +23,7 @@ This document lists all configuration options that can be set via environment va
- [Hardcover](#metadata-providers-hardcover)
- [Open Library](#metadata-providers-open-library)
- [Google Books](#metadata-providers-google-books)
- [Moly.hu](#metadata-providers-moly.hu)
- [Direct Download](#direct-download)
- [Download Sources](#direct-download-download-sources)
- [Cloudflare Bypass](#direct-download-cloudflare-bypass)
@@ -1046,6 +1047,7 @@ Comma-separated hosts to bypass proxy (e.g., localhost,127.0.0.1,10.*,*.local)
|----------|-------------|------|---------|
| `URL_BASE` | Optional URL path prefix. Use a path like /shelfmark (no hostname). Leave blank for root. | string | _none_ |
| `DEBUG` | Enable verbose logging to console and file. Not recommended for normal use. | boolean | `false` |
| `LOG_LEVEL` | Lowest severity written to the console and log file. Ignored while Debug Mode is on, which forces Debug. | string (choice) | `INFO` |
| `MAIN_LOOP_SLEEP_TIME` | How often the download queue is checked for new items. | number | `5` |
| `DOWNLOAD_PROGRESS_UPDATE_INTERVAL` | How often download progress is broadcast to the UI. | number | `1` |
| `CUSTOM_SCRIPT` | Path to a script to run after each successful download. Must be executable. | string | _none_ |
@@ -1082,6 +1084,17 @@ Enable verbose logging to console and file. Not recommended for normal use.
- **Default:** `false`
- **Requires restart:** Yes
#### `LOG_LEVEL`
**Log Level**
Lowest severity written to the console and log file. Ignored while Debug Mode is on, which forces Debug.
- **Type:** string (choice)
- **Default:** `INFO`
- **Requires restart:** Yes
- **Options:** `DEBUG` (Debug), `INFO` (Info), `WARNING` (Warning), `ERROR` (Error), `CRITICAL` (Critical)
#### `MAIN_LOOP_SLEEP_TIME`
**Queue Check Interval (seconds)**
@@ -1508,6 +1521,8 @@ How long to keep cached search results before they expire.
| Variable | Description | Type | Default |
|----------|-------------|------|---------|
| `PROWLARR_TORRENT_CLIENT` | Choose which torrent client to use | string (choice) | _empty string_ |
| `ALLDEBRID_API_KEY` | AllDebrid API Key (apiv4) from your AllDebrid account settings | string (secret) | _none_ |
| `REALDEBRID_API_KEY` | Real-Debrid API Key (Secret Token) from your Real-Debrid account settings | string (secret) | _none_ |
| `QBITTORRENT_URL` | Web UI URL of your qBittorrent instance | string | _none_ |
| `QBITTORRENT_USERNAME` | qBittorrent Web UI username | string | _none_ |
| `QBITTORRENT_PASSWORD` | qBittorrent Web UI password | string (secret) | _none_ |
@@ -1559,7 +1574,25 @@ Choose which torrent client to use
- **Type:** string (choice)
- **Default:** _empty string_
- **Options:** `""` (None), `qbittorrent` (qBittorrent), `transmission` (Transmission), `deluge` (Deluge), `rtorrent` (rTorrent)
- **Options:** `""` (None), `alldebrid` (AllDebrid), `qbittorrent` (qBittorrent), `realdebrid` (Real-Debrid), `transmission` (Transmission), `deluge` (Deluge), `rtorrent` (rTorrent)
#### `ALLDEBRID_API_KEY`
**API Key**
AllDebrid API Key (apiv4) from your AllDebrid account settings
- **Type:** string (secret)
- **Default:** _none_
#### `REALDEBRID_API_KEY`
**API Key**
Real-Debrid API Key (Secret Token) from your Real-Debrid account settings
- **Type:** string (secret)
- **Default:** _none_
#### `QBITTORRENT_URL`
@@ -2064,6 +2097,26 @@ Default sort order for Google Books search results.
</details>
### Metadata Providers: Moly.hu
| Variable | Description | Type | Default |
|----------|-------------|------|---------|
| `MOLY_ENABLED` | Enable Moly.hu as a metadata provider for book searches | boolean | `false` |
<details>
<summary>Detailed descriptions</summary>
#### `MOLY_ENABLED`
**Enable Moly.hu**
Enable Moly.hu as a metadata provider for book searches
- **Type:** boolean
- **Default:** `false`
</details>
## Direct Download
### Direct Download: Download Sources
+12 -1
View File
@@ -484,7 +484,18 @@ fi
# Always run Gunicorn (even when DEBUG=true) to ensure Socket.IO WebSocket
# upgrades work reliably on customer machines.
# Map app LOG_LEVEL (often DEBUG/INFO/...) to gunicorn's --log-level (lowercase).
gunicorn_loglevel=$([ "$DEBUG" = "true" ] && echo debug || echo "${LOG_LEVEL:-info}" | tr '[:upper:]' '[:lower:]')
# Gunicorn rejects anything outside its own list, so normalize and fall back to
# info rather than letting a typo stop the container from booting.
if [ "$DEBUG" = "true" ]; then
gunicorn_loglevel=debug
else
gunicorn_loglevel=$(echo "${LOG_LEVEL:-info}" | tr '[:upper:]' '[:lower:]')
[ "$gunicorn_loglevel" = "warn" ] && gunicorn_loglevel=warning
case "$gunicorn_loglevel" in
debug|info|warning|error|critical) ;;
*) gunicorn_loglevel=info ;;
esac
fi
command="${GUNICORN_BIN} --log-level ${gunicorn_loglevel} --access-logfile - --error-logfile - --worker-class geventwebsocket.gunicorn.workers.GeventWebSocketWorker --workers 1 -t 300 -b ${FLASK_HOST:-0.0.0.0}:${FLASK_PORT:-8084} shelfmark.main:app"
# If DEBUG and not using an external bypass
+4 -1
View File
@@ -260,7 +260,10 @@ Logs are available via:
- `docker logs <container-name>`
- `/var/log/shelfmark/` inside the container (when `ENABLE_LOGGING=true`)
Log level is configurable via Settings or `LOG_LEVEL` environment variable.
Log level is configurable under Settings → Advanced or via the `LOG_LEVEL` environment
variable (`DEBUG`, `INFO`, `WARNING`, `ERROR`, `CRITICAL`; case-insensitive, defaults to
`INFO`). The environment variable wins over the setting, and `DEBUG=true` forces `DEBUG`
regardless of either. Changes take effect on restart.
## Development
+57 -13
View File
@@ -6,34 +6,78 @@ import shutil
import tempfile
from pathlib import Path
LOG_LEVELS = ("DEBUG", "INFO", "WARNING", "ERROR", "CRITICAL")
def string_to_bool(s: str) -> bool:
"""Convert string to boolean."""
return s.lower() in ["true", "yes", "1", "y"]
def _read_advanced_config(key: str) -> object | None:
"""Read a key from the advanced settings file (import-time safe)."""
config_dir = Path(os.getenv("CONFIG_DIR", "/config"))
config_file = config_dir / "plugins" / "advanced.json"
if config_file.exists():
try:
with config_file.open() as f:
config = json.load(f)
if key in config:
return config[key]
except json.JSONDecodeError, OSError:
pass
return None
def _read_debug_from_config() -> bool:
"""Read DEBUG from env var or config file (import-time safe)."""
env_debug = os.environ.get("DEBUG")
if env_debug is not None:
return string_to_bool(env_debug)
# Try to read from config file
config_dir = Path(os.getenv("CONFIG_DIR", "/config"))
config_file = config_dir / "plugins" / "advanced.json"
if config_file.exists():
try:
with config_file.open() as f:
config = json.load(f)
if "DEBUG" in config:
return bool(config["DEBUG"])
except json.JSONDecodeError, OSError:
pass
value = _read_advanced_config("DEBUG")
if value is not None:
return bool(value)
return False
def normalize_log_level(raw: str | None) -> str:
"""Normalize a log level name, falling back to INFO when unrecognized."""
if raw is None:
return "INFO"
normalized = raw.strip().upper()
# "WARN" is a logging alias, but gunicorn only accepts "warning".
if normalized == "WARN":
normalized = "WARNING"
if normalized not in LOG_LEVELS:
return "INFO"
return normalized
def _read_log_level_from_config(debug: bool) -> str:
"""Resolve the app log level from DEBUG, env var, or config file.
DEBUG wins when enabled, mirroring how entrypoint.sh picks gunicorn's level.
Otherwise LOG_LEVEL is read from the env var, then the settings file, and
falls back to INFO when unset or unrecognized.
"""
if debug:
return "DEBUG"
raw = os.environ.get("LOG_LEVEL")
if raw is None:
value = _read_advanced_config("LOG_LEVEL")
raw = value if isinstance(value, str) else None
return normalize_log_level(raw)
def _is_sqlite_file(path: Path) -> bool:
"""Check if a file is a valid SQLite database by reading magic bytes."""
try:
@@ -101,7 +145,7 @@ INGEST_DIR = Path(os.getenv("INGEST_DIR", "/books"))
# =============================================================================
DEBUG = _read_debug_from_config()
LOG_LEVEL = "DEBUG" if DEBUG else "INFO"
LOG_LEVEL = _read_log_level_from_config(DEBUG)
ENABLE_LOGGING = string_to_bool(os.getenv("ENABLE_LOGGING", "true"))
+17
View File
@@ -1761,6 +1761,23 @@ def advanced_settings() -> list[SettingsField]:
default=False,
requires_restart=True,
),
SelectField(
key="LOG_LEVEL",
label="Log Level",
description=(
"Lowest severity written to the console and log file. "
"Ignored while Debug Mode is on, which forces Debug."
),
options=[
{"value": "DEBUG", "label": "Debug", "description": "Everything, very noisy."},
{"value": "INFO", "label": "Info", "description": "Normal activity (default)."},
{"value": "WARNING", "label": "Warning", "description": "Warnings and problems."},
{"value": "ERROR", "label": "Error", "description": "Failures only."},
{"value": "CRITICAL", "label": "Critical", "description": "Fatal errors only."},
],
default="INFO",
requires_restart=True,
),
NumberField(
key="MAIN_LOOP_SLEEP_TIME",
label="Queue Check Interval (seconds)",
+4
View File
@@ -9,6 +9,7 @@ from typing import TYPE_CHECKING, Any
from werkzeug.utils import secure_filename
from shelfmark.config.env import normalize_log_level
from shelfmark.core.logger import setup_logger
from shelfmark.core.request_helpers import coerce_bool, normalize_optional_text
@@ -898,6 +899,9 @@ def _get_env_value_for_field(field: FieldBase) -> tuple[bool, object | None]:
"WELIB_MIRROR_URLS",
} and isinstance(parsed, list):
parsed = _normalize_mirror_env_urls(parsed)
if field.key == "LOG_LEVEL" and isinstance(parsed, str):
# LOG_LEVEL is commonly set lowercase; the field options are uppercase.
parsed = normalize_log_level(parsed)
return True, parsed
if field.key == "AA_MIRROR_URLS":
+42 -1
View File
@@ -27,9 +27,14 @@ logger = setup_logger(__name__)
_RNG = random.SystemRandom()
_MAX_REDIRECTS = 5
# Z-Library answers the first hit with a 503 whose only real payload is a Set-Cookie; echoing
# that cookie back returns the 302 to the real page. Two attempts cover the handshake without
# letting a server that keeps re-issuing cookies hold us in the loop.
_MAX_COOKIE_HANDSHAKE_RETRIES = 2
_HTTP_STATUS_FORBIDDEN = HTTPStatus.FORBIDDEN
_HTTP_STATUS_NOT_FOUND = HTTPStatus.NOT_FOUND
_HTTP_STATUS_RATE_LIMITED = HTTPStatus.TOO_MANY_REQUESTS
_HTTP_STATUS_SERVICE_UNAVAILABLE = HTTPStatus.SERVICE_UNAVAILABLE
_HTTP_STATUS_OK = HTTPStatus.OK
_HTTP_STATUS_RANGE_NOT_SATISFIABLE = HTTPStatus.REQUESTED_RANGE_NOT_SATISFIABLE
_HTTP_STATUS_PARTIAL_CONTENT = HTTPStatus.PARTIAL_CONTENT
@@ -58,6 +63,18 @@ def _raise_too_many_redirects(message: str) -> NoReturn:
raise requests.exceptions.TooManyRedirects(message)
def _new_cookies(response: requests.Response, already_sent: dict[str, str]) -> dict[str, str]:
"""Cookies a response set that we were not already echoing back.
Returning only the *new* ones is what makes the retry terminate: a server that keeps
re-issuing the same cookie yields nothing here, so we stop instead of spinning.
"""
jar = getattr(response, "cookies", None)
if not jar:
return {}
return {name: value for name, value in jar.items() if already_sent.get(name) != value}
def _get_internal_bypasser() -> ModuleType:
"""Lazy import of internal bypasser module."""
global _internal_bypasser
@@ -278,6 +295,9 @@ def html_get_page(
original_url = url
current_url = selector.rewrite(original_url)
use_bypasser_now = use_bypasser
# Survives across attempts so a cookie won once is still presented on later retries.
handshake_cookies: dict[str, str] = {}
handshake_retries = 0
for attempt in range(1, retry_limit + 1):
# Check for cancellation before each attempt
@@ -332,12 +352,31 @@ def html_get_page(
current_url,
proxies=get_proxies(current_url),
timeout=REQUEST_TIMEOUT,
cookies=cookies,
# Bypasser-derived cookies win: they came from a real solved challenge.
cookies={**handshake_cookies, **cookies},
headers=headers,
allow_redirects=allow_redirects,
verify=get_ssl_verify(current_url),
)
# Z-Library gates the first hit with a 503 that carries nothing but a
# Set-Cookie; echoing it back yields the 302 to the real page. Without this
# the cookie is dropped and every retry re-runs the same rejected request.
if (
response.status_code == _HTTP_STATUS_SERVICE_UNAVAILABLE
and handshake_retries < _MAX_COOKIE_HANDSHAKE_RETRIES
):
issued = _new_cookies(response, handshake_cookies)
if issued:
handshake_cookies.update(issued)
handshake_retries += 1
logger.debug(
"503 set %s cookie(s); retrying with them: %s",
len(issued),
current_url,
)
continue
if is_aa_url and response.is_redirect:
location = response.headers.get("Location", "")
if not location:
@@ -366,6 +405,7 @@ def html_get_page(
current_url = new_url
# Reset per-request state for the new host.
headers = {"User-Agent": DOWNLOAD_HEADERS["User-Agent"]}
handshake_cookies.clear()
is_aa_url = network.should_rotate_dns_for_url(current_url)
allow_redirects = not is_aa_url
redirects_followed = 0
@@ -435,6 +475,7 @@ def html_get_page(
new_url = _try_rotation(original_url, current_url, selector)
if new_url:
current_url = new_url
handshake_cookies.clear()
continue
# Retry with backoff
+81
View File
@@ -8,6 +8,7 @@ Run with: uv run pytest tests/config/test_environment.py -v
"""
import importlib
import json
import os
import tempfile
from pathlib import Path
@@ -15,6 +16,15 @@ from unittest.mock import patch
import pytest
def _restore_env(monkeypatch, name: str, value: str | None) -> None:
"""Restore an env var to its pre-test value."""
if value is None:
monkeypatch.delenv(name, raising=False)
else:
monkeypatch.setenv(name, value)
# =============================================================================
# Directory Setup Tests
# =============================================================================
@@ -436,6 +446,7 @@ class TestDebugConfiguration:
original_debug = os.environ.get("DEBUG")
try:
monkeypatch.delenv("LOG_LEVEL", raising=False)
monkeypatch.setenv("DEBUG", "true")
importlib.reload(env_module)
assert env_module.DEBUG is True
@@ -452,6 +463,76 @@ class TestDebugConfiguration:
monkeypatch.setenv("DEBUG", original_debug)
importlib.reload(env_module)
@pytest.mark.parametrize(
("raw", "expected"),
[
("error", "ERROR"),
("ERROR", "ERROR"),
(" Warning ", "WARNING"),
("warn", "WARNING"),
("critical", "CRITICAL"),
("nonsense", "INFO"),
("", "INFO"),
(None, "INFO"),
],
)
def test_normalize_log_level(self, raw, expected):
"""Log level names are case-insensitive and fall back to INFO."""
from shelfmark.config.env import normalize_log_level
assert normalize_log_level(raw) == expected
def test_log_level_from_env_var(self, monkeypatch):
"""LOG_LEVEL env var should set the app log level when DEBUG is off."""
import shelfmark.config.env as env_module
original_debug = os.environ.get("DEBUG")
original_level = os.environ.get("LOG_LEVEL")
try:
monkeypatch.setenv("DEBUG", "false")
monkeypatch.setenv("LOG_LEVEL", "error")
importlib.reload(env_module)
assert env_module.LOG_LEVEL == "ERROR"
# DEBUG wins over LOG_LEVEL, matching entrypoint.sh.
monkeypatch.setenv("DEBUG", "true")
importlib.reload(env_module)
assert env_module.LOG_LEVEL == "DEBUG"
finally:
_restore_env(monkeypatch, "DEBUG", original_debug)
_restore_env(monkeypatch, "LOG_LEVEL", original_level)
importlib.reload(env_module)
def test_log_level_from_config_file(self, monkeypatch, tmp_path):
"""LOG_LEVEL should fall back to the advanced settings file."""
import shelfmark.config.env as env_module
original_debug = os.environ.get("DEBUG")
original_level = os.environ.get("LOG_LEVEL")
original_config_dir = os.environ.get("CONFIG_DIR")
advanced = tmp_path / "plugins" / "advanced.json"
advanced.parent.mkdir(parents=True)
advanced.write_text(json.dumps({"LOG_LEVEL": "WARNING"}))
try:
monkeypatch.setenv("DEBUG", "false")
monkeypatch.delenv("LOG_LEVEL", raising=False)
monkeypatch.setenv("CONFIG_DIR", str(tmp_path))
importlib.reload(env_module)
assert env_module.LOG_LEVEL == "WARNING"
# Env var takes precedence over the stored setting.
monkeypatch.setenv("LOG_LEVEL", "critical")
importlib.reload(env_module)
assert env_module.LOG_LEVEL == "CRITICAL"
finally:
_restore_env(monkeypatch, "DEBUG", original_debug)
_restore_env(monkeypatch, "LOG_LEVEL", original_level)
_restore_env(monkeypatch, "CONFIG_DIR", original_config_dir)
importlib.reload(env_module)
# =============================================================================
# Proxy and Network Configuration Tests
+7 -1
View File
@@ -28,6 +28,9 @@ _BOOTSTRAP_ENV_ACCESS_ALLOWLIST = {
}
_BOOTSTRAP_ENV_ACCESS_KEY_ALLOWLIST = {
(Path("shelfmark/config/settings.py"), "USING_TOR"),
# Loggers are configured while settings_registry itself is still importing,
# so the level has to come from the bootstrap env module.
(Path("shelfmark/core/logger.py"), "LOG_LEVEL"),
}
_RAW_CONFIG_READ_ALLOWLIST = {
Path("shelfmark/config/notifications_settings.py"),
@@ -205,7 +208,10 @@ class ConfigAccessVisitor(ast.NodeVisitor):
return
for alias in node.names:
imported_name = alias.name
if imported_name in self.registered_keys:
if (
imported_name in self.registered_keys
and imported_name not in self._bootstrap_env_key_allowlist
):
self._record_violation(
node,
"direct env-module import",
@@ -0,0 +1,103 @@
"""Tests for the Z-Library 503 cookie handshake."""
import requests
class _FakeResponse:
"""Minimal stand-in for requests.Response covering what html_get_page touches."""
def __init__(
self,
status_code: int,
*,
url: str = "https://z-lib.fm/md5/abc",
text: str = "",
cookies: dict[str, str] | None = None,
) -> None:
self.status_code = status_code
self.url = url
self.text = text
self.cookies = cookies or {}
self.headers = {"Content-Type": "text/html;charset=utf-8"}
self.is_redirect = False
def raise_for_status(self) -> None:
if self.status_code >= 400:
error = requests.exceptions.HTTPError(f"{self.status_code} Error")
error.response = self
raise error
def _neutralize_network(monkeypatch, http):
monkeypatch.setattr(http, "_apply_cf_bypass", lambda _url, _headers: {})
monkeypatch.setattr(http, "get_proxies", lambda _url: {})
monkeypatch.setattr(http, "get_ssl_verify", lambda _url: True)
monkeypatch.setattr(http.network, "should_rotate_dns_for_url", lambda _url: False)
monkeypatch.setattr(http.time, "sleep", lambda _seconds: None)
def test_html_get_page_echoes_503_cookie(monkeypatch):
"""A 503 that only sets a cookie is cleared by sending that cookie back."""
import shelfmark.download.http as http
_neutralize_network(monkeypatch, http)
sent_cookies: list[dict[str, str]] = []
def fake_get(_url: str, **kwargs):
sent_cookies.append(dict(kwargs["cookies"]))
if len(sent_cookies) == 1:
return _FakeResponse(503, cookies={"zlib_sid": "s3cr3t"})
return _FakeResponse(200, text="<html>real page</html>")
monkeypatch.setattr(http.requests, "get", fake_get)
html = http.html_get_page("https://z-lib.fm/md5/abc", retry=3, success_delay=0)
assert html == "<html>real page</html>"
# The first hit carries nothing; the retry echoes back exactly what the 503 issued.
assert sent_cookies == [{}, {"zlib_sid": "s3cr3t"}]
def test_html_get_page_stops_echoing_when_cookie_is_reissued(monkeypatch):
"""A server repeating the same cookie must not spin the request loop forever."""
import shelfmark.download.http as http
_neutralize_network(monkeypatch, http)
monkeypatch.setattr(http, "_is_cf_bypass_enabled", lambda: False)
sent_cookies: list[dict[str, str]] = []
def fake_get(_url: str, **kwargs):
sent_cookies.append(dict(kwargs["cookies"]))
return _FakeResponse(503, cookies={"zlib_sid": "same"})
monkeypatch.setattr(http.requests, "get", fake_get)
html = http.html_get_page("https://z-lib.fm/md5/abc", retry=1, success_delay=0)
assert html == ""
# One initial hit plus one echo; the reissued identical cookie yields no third request.
assert sent_cookies == [{}, {"zlib_sid": "same"}]
def test_html_get_page_leaves_cookieless_503_on_the_retry_path(monkeypatch):
"""A plain overloaded-server 503 keeps its existing retry behaviour."""
import shelfmark.download.http as http
_neutralize_network(monkeypatch, http)
monkeypatch.setattr(http, "_is_cf_bypass_enabled", lambda: False)
attempts: list[dict[str, str]] = []
def fake_get(_url: str, **kwargs):
attempts.append(dict(kwargs["cookies"]))
return _FakeResponse(503)
monkeypatch.setattr(http.requests, "get", fake_get)
html = http.html_get_page("https://z-lib.fm/md5/abc", retry=2, success_delay=0)
assert html == ""
# Two ordinary attempts, no extra in-place retry and no cookies invented.
assert attempts == [{}, {}]