fix/redact log secrets (#1488)

- fix(logging): mask tracker API keys in log output (#1486)
- fix(welib): follow slow_download links through the countdown (#1447)

shelfmark/core/logger.py

@@ -1,6 +1,7 @@
 """Logging configuration and custom logger with error tracing."""
 
 import logging
+import re
 import sys
 from collections.abc import Mapping
 from logging.handlers import RotatingFileHandler
@@ -16,6 +17,29 @@ if TYPE_CHECKING:
 _file_handlers: dict[Path, RotatingFileHandler] = {}
 _file_handlers_lock = Lock()
 
+# Query parameters that carry tracker/indexer credentials. Prowlarr guids are often
+# the download URL itself (apikey included), and they end up in task ids that are
+# logged all over the download pipeline, so mask them at the formatter instead.
+_SECRET_QUERY_PARAM_PATTERN = re.compile(
+    r"(?<=[?&;])"
+    r"([a-z0-9_-]*api[_-]?key|api|apitoken|access_token|token|passkey|authkey|rsskey"
+    r"|torrent_pass|auth|key|password|passwd|pwd|pass|secret|sid|uid)"
+    r"=[^&\s#'\"<>;:,)\]]+",
+    re.IGNORECASE,
+)
+
+
+def redact_secrets(text: str) -> str:
+    """Mask credential query parameters in text, keeping the rest of the URL readable."""
+    return _SECRET_QUERY_PARAM_PATTERN.sub(r"\1=(removed)", text)
+
+
+class RedactingFormatter(logging.Formatter):
+    """Formatter that masks credentials in the message, traceback and stack info."""
+
+    def format(self, record: logging.LogRecord) -> str:
+        return redact_secrets(super().format(record))
+
 
 class CustomLogger(logging.Logger):
     """Custom logger class with additional error_trace method."""
@@ -162,7 +186,7 @@ def setup_logger(name: str, log_file: Path = LOG_FILE) -> CustomLogger:
     log_level = getattr(logging, LOG_LEVEL, logging.INFO)
     logger.setLevel(log_level)
 
-    formatter = logging.Formatter(
+    formatter = RedactingFormatter(
         "%(asctime)s - %(name)s - %(levelname)s - %(filename)s:%(lineno)d - %(message)s"
     )
 

shelfmark/release_sources/direct_download/annas_archive.py

@@ -1641,6 +1641,18 @@ def _get_download_url(
         ) or _find_first_anchor_with_text(soup, "Download", href_contains=md5)
         if get_btn:
             url = get_attr(get_btn, "href") or ""
+            # Welib's "Download" leads to a slow_download page with the same countdown
+            # as AA's, not to the file. Resolve it like an AA slow link, or the countdown
+            # HTML is what gets downloaded (#1447).
+            if "/slow_download/" in url:
+                return _get_download_url(
+                    downloader.get_absolute_url(link, url),
+                    title,
+                    cancel_flag,
+                    status_callback,
+                    sel,
+                    source_context,
+                )
         elif md5:
             logger.info("No download link for md5 %s on %s", md5, link)
         else:

tests/core/test_logger.py

@@ -1,7 +1,11 @@
 """Tests for Shelfmark's logging configuration."""
 
+import io
+import logging
 from logging.handlers import RotatingFileHandler
 
+import pytest
+
 import shelfmark.core.logger as logger_module
 
 
@@ -58,3 +62,52 @@ def test_setup_logger_keeps_separate_handlers_for_separate_files(monkeypatch, tm
         with logger_module._file_handlers_lock:
             logger_module._file_handlers.pop(log_file)
         handler.close()
+
+
+@pytest.mark.parametrize(
+    ("text", "expected"),
+    [
+        (
+            "Task 12:https://tracker.example/api?t=get&id=42&apikey=s3cr3t: starting download",
+            "Task 12:https://tracker.example/api?t=get&id=42&apikey=(removed): starting download",
+        ),
+        (
+            "https://t.example/dl.php?passkey=abc&torrent_pass=def&API_KEY=ghi&r=1",
+            "https://t.example/dl.php?passkey=(removed)&torrent_pass=(removed)"
+            "&API_KEY=(removed)&r=1",
+        ),
+        (
+            "url='http://prowlarr:9696/1/download?apikey=xyz&link=abc'",
+            "url='http://prowlarr:9696/1/download?apikey=(removed)&link=abc'",
+        ),
+        (
+            "https://t.example/rss?id=7&uid=99&key=k",
+            "https://t.example/rss?id=7&uid=(removed)&key=(removed)",
+        ),
+        ("download_id=7 api_key_set=True", "download_id=7 api_key_set=True"),
+    ],
+)
+def test_redact_secrets_masks_credential_query_params(text, expected):
+    assert logger_module.redact_secrets(text) == expected
+
+
+def test_setup_logger_redacts_messages_args_and_tracebacks(monkeypatch):
+    """Task ids built from Prowlarr guids carry tracker API keys (#1486)."""
+    monkeypatch.setattr(logger_module, "ENABLE_LOGGING", False)
+    logger = logger_module.setup_logger("shelfmark.test.redaction")
+    stream = io.StringIO()
+    for handler in logger.handlers:
+        assert isinstance(handler, logging.StreamHandler)
+        handler.setStream(stream)
+
+    task_id = "3:https://tracker.example/api?t=get&id=42&apikey=s3cr3t"
+    logger.info("Task %s: starting download (%s) - %s", task_id, "Prowlarr", "Title")
+    try:
+        raise RuntimeError(f"refresh failed for {task_id}")
+    except RuntimeError:
+        logger.exception("Prowlarr release refresh failed: %s", task_id)
+
+    output = stream.getvalue()
+    assert "s3cr3t" not in output
+    assert output.count("apikey=(removed)") == 3
+    assert "id=42" in output

tests/direct_download/test_welib_md5_match.py

@@ -63,3 +63,37 @@ def test_a_page_that_is_not_md5_addressed_keeps_taking_the_first_download():
     assert (
         _resolve("https://example.org/book/42", page) == f"https://example.org/files/{OTHER}.epub"
     )
+
+
+def test_a_slow_download_link_is_followed_through_its_countdown():
+    """Issue #1447: welib's Download leads to a slow_download page with AA's countdown.
+
+    It was handed straight to the downloader, which got the countdown HTML instead of
+    the file. It must be resolved like an AA slow link: wait, re-fetch, take the link.
+    """
+    slow_url = f"https://welib.org/slow_download/{WANTED}/0/0"
+    file_url = f"https://partner.example/files/{WANTED}.epub"
+    pages = {
+        WELIB_PAGE: [f'<a href="/slow_download/{WANTED}/0/0">Download</a>'],
+        slow_url: [
+            '<span class="js-partner-countdown">1</span>',
+            f'<a href="{file_url}">📚 Download now</a>',
+        ],
+    }
+    fetched: list[str] = []
+
+    def fake_get_page(url, **_kwargs):
+        fetched.append(url)
+        return pages[url].pop(0)
+
+    with (
+        patch.object(annas_archive.downloader, "html_get_page", side_effect=fake_get_page),
+        patch.object(
+            annas_archive.network, "get_aa_base_url", return_value="https://annas-archive.gl"
+        ),
+        patch.object(annas_archive, "_is_configured_zlib_link", return_value=False),
+    ):
+        resolved = annas_archive._get_download_url(WELIB_PAGE, "Amorino", selector=object())  # type: ignore[arg-type]
+
+    assert resolved == file_url
+    assert fetched == [WELIB_PAGE, slow_url, slow_url]