fix: sandbox silent-failure hardening (returncode check, boot-time docker check, token redaction)

src/pdfmux/remote/sandbox.py

@@ -15,6 +15,7 @@
 from __future__ import annotations
 
 import json
+import logging
 import os
 import shlex
 import subprocess
@@ -24,6 +25,8 @@
 from pathlib import Path
 from typing import Any
 
+logger = logging.getLogger("pdfmux.remote.sandbox")
+
 DEFAULT_TIMEOUT_S = 90
 MEMORY_BYTES = 1024 * 1024 * 1024  # 1 GiB
 DOCKER_IMAGE = os.environ.get("PDFMUX_SANDBOX_IMAGE", "pdfmux-sandbox:latest")
@@ -91,6 +94,22 @@ def run_parse(pdf: Path, max_pages: int = 30, timeout_s: int = DEFAULT_TIMEOUT_S
         if not process_mode:
             subprocess.run(["docker", "kill", ctx["container"]], capture_output=True, timeout=15)  # noqa: S603,S607
         raise SandboxError("This PDF took too long to read.") from None
+    if proc.returncode != 0:
+        # docker run / the child process exited non-zero for an infra reason (image missing,
+        # daemon down, registry denied, OOM-killed, ...). stdout is typically empty here, so
+        # without this check json.loads(... or "{}") silently returns {} — no "error" key — and
+        # the caller gets SandboxResult(data={}) as if the parse succeeded. That's the exact
+        # failure mode that let a production outage run unnoticed for days: pm2's error log
+        # stayed 0 bytes because nothing ever raised. Log server-side only; never put stderr in
+        # the user-facing message (it may contain host paths, image internals, etc).
+        stderr_tail = proc.stderr.decode("utf-8", errors="replace")[-2000:]
+        logger.error(
+            "sandbox parse failed: mode=%s returncode=%s stderr_tail=%r",
+            "process" if process_mode else "docker",
+            proc.returncode,
+            stderr_tail,
+        )
+        raise SandboxError("This PDF couldn't be read.")
     try:
         data = json.loads(proc.stdout.decode("utf-8") or "{}")
     except (json.JSONDecodeError, UnicodeDecodeError):
@@ -102,6 +121,35 @@ def run_parse(pdf: Path, max_pages: int = 30, timeout_s: int = DEFAULT_TIMEOUT_S
     return SandboxResult(data=data)
 
 
+def assert_sandbox_ready() -> None:
+    """Fail loudly at boot, not silently per-request.
+
+    The 2026-10-07 outage: ``PDFMUX_SANDBOX=docker`` but ``pdfmux-sandbox:latest`` was never
+    built on the box, so every call's ``docker run`` exited non-zero and (before the
+    returncode check above existed) was laundered into an empty-but-valid result — no error,
+    no log line, for days. Call this once at process startup so a missing/broken image turns
+    into an immediate boot-time crash instead of a silent per-request failure.
+    """
+    if os.environ.get("PDFMUX_SANDBOX", "process") != "docker":
+        return
+    try:
+        proc = subprocess.run(  # noqa: S603 — fixed argv, no shell
+            ["docker", "image", "inspect", DOCKER_IMAGE],  # noqa: S607
+            capture_output=True,
+            timeout=15,
+        )
+    except (OSError, subprocess.TimeoutExpired) as e:
+        raise RuntimeError(
+            f"PDFMUX_SANDBOX=docker but `docker image inspect {DOCKER_IMAGE}` could not run: {e}"
+        ) from e
+    if proc.returncode != 0:
+        stderr_tail = proc.stderr.decode("utf-8", errors="replace").strip()[-500:]
+        raise RuntimeError(
+            f"PDFMUX_SANDBOX=docker but image {DOCKER_IMAGE!r} is not available locally "
+            f"(`docker image inspect` exit {proc.returncode}): {stderr_tail}"
+        )
+
+
 def describe() -> str:
     """For logs and the conformance checklist: which isolation is actually in force."""
     cmd, _ = _command(Path("/tmp/x.pdf"), 1)

src/pdfmux/remote/server.py

@@ -22,7 +22,9 @@
 import asyncio
 import hashlib
 import hmac
+import logging
 import os
+import re
 import shutil
 import tempfile
 import threading
@@ -51,7 +53,7 @@
     untrusted,
 )
 from pdfmux.remote.outputs import table_csv, workbook_bytes
-from pdfmux.remote.sandbox import SandboxError, run_parse
+from pdfmux.remote.sandbox import SandboxError, assert_sandbox_ready, run_parse
 
 MAX_PAGES = 30
 INLINE_CSV_ROWS = 150
@@ -493,6 +495,7 @@ def assert_neutral_copy() -> None:
 
 def create_app(start_sweeper: bool = True) -> Starlette:
     assert_neutral_copy()
+    assert_sandbox_ready()
     if start_sweeper:
         threading.Thread(target=_sweeper, daemon=True, name="pdfmux-remote-sweeper").start()
     return Starlette(
@@ -504,7 +507,59 @@ def create_app(start_sweeper: bool = True) -> Starlette:
     )
 
 
+# ---------------------------------------------------------------------------------------------
+# Access-log token redaction
+# ---------------------------------------------------------------------------------------------
+# The plugin token is the secret path segment in `POST /mcp/<token>` (see module docstring).
+# uvicorn's access logger records the full request path, so every call writes a live
+# credential in plaintext to pm2/root-owned access logs — low severity (logs are root-only,
+# this doesn't change the token itself) but it violates the "tokens never land in plaintext
+# logs" discipline the rest of this codebase holds elsewhere. This filter rewrites the token
+# out of the log record's format args before it's emitted; it never touches request handling.
+
+_TOKEN_IN_PATH_RE = re.compile(r"(/mcp/)[^\s\"/?]+")
+
+
+class RedactTokenFilter(logging.Filter):
+    """logging.Filter for uvicorn's access logger: redacts `/mcp/<token>` to `/mcp/<redacted>`."""
+
+    def filter(self, record: logging.LogRecord) -> bool:
+        if isinstance(record.args, tuple):
+            record.args = tuple(
+                _TOKEN_IN_PATH_RE.sub(r"\1<redacted>", a) if isinstance(a, str) else a
+                for a in record.args
+            )
+        elif isinstance(record.msg, str):
+            record.msg = _TOKEN_IN_PATH_RE.sub(r"\1<redacted>", record.msg)
+        return True
+
+
+def _log_config() -> dict[str, Any]:
+    """uvicorn's default LOGGING_CONFIG, with the redaction filter wired onto the access
+    handler. uvicorn calls ``logging.config.dictConfig(log_config)`` itself at server start
+    (and ``disable_existing_loggers`` is False in its default, but the "uvicorn.access" logger
+    IS named in the config so it gets rebuilt) — so the filter has to be declared inside the
+    dict uvicorn consumes, not attached to the logger object beforehand, or dictConfig
+    overwrites it.
+    """
+    import copy
+
+    import uvicorn.config
+
+    cfg = copy.deepcopy(uvicorn.config.LOGGING_CONFIG)
+    cfg["filters"] = {"redact_token": {"()": f"{__name__}.RedactTokenFilter"}}
+    cfg["handlers"]["access"]["filters"] = ["redact_token"]
+    return cfg
+
+
 def run(host: str = "127.0.0.1", port: int = 8011) -> None:
     import uvicorn
 
-    uvicorn.run(create_app(), host=host, port=port, proxy_headers=False, server_header=False)
+    uvicorn.run(
+        create_app(),
+        host=host,
+        port=port,
+        proxy_headers=False,
+        server_header=False,
+        log_config=_log_config(),
+    )

tests/test_remote_server.py

@@ -4,8 +4,10 @@
 
 import io
 import json
+import logging
 import shutil
 import socket
+import sys
 import time
 from pathlib import Path
 
@@ -15,6 +17,7 @@
 from starlette.testclient import TestClient
 
 from pdfmux.remote import fetch as fetch_mod
+from pdfmux.remote import sandbox as sandbox_mod
 from pdfmux.remote import server as server_mod
 from pdfmux.remote.fetch import FetchError, fetch_pdf, validate_url
 from pdfmux.remote.kit import Caller, Limits, client_ip, find_banned_copy, untrusted
@@ -162,6 +165,194 @@ def test_sandbox_turns_garbage_and_timeouts_into_safe_errors(
         run_parse(pdf, timeout_s=0.01)
 
 
+def test_sandbox_logs_diagnostic_and_raises_safe_error_on_nonzero_returncode(
+    tmp_path: Path, monkeypatch: pytest.MonkeyPatch, caplog: pytest.LogCaptureFixture
+) -> None:
+    """The silent-failure regression: `docker run` (or the child process) can exit non-zero
+    with empty stdout — before this fix that laundered into SandboxResult(data={}) as if the
+    parse succeeded, with nothing logged. Simulate a non-zero exit via a fake _command and
+    assert it raises the same user-facing string as the existing JSON-decode-failure branch,
+    while the real diagnostic (exit code + stderr) only ever reaches the server-side log.
+    """
+    monkeypatch.setenv("PDFMUX_SANDBOX", "process")
+    monkeypatch.setattr(
+        sandbox_mod,
+        "_command",
+        lambda pdf, max_pages: (
+            [
+                sys.executable,
+                "-c",
+                "import sys; sys.stderr.write('disk full: /var/lib/docker'); sys.exit(3)",
+            ],
+            {},
+        ),
+    )
+    pdf = tmp_path / "whatever.pdf"
+    pdf.write_bytes(b"%PDF-1.4")
+
+    with caplog.at_level(logging.ERROR, logger="pdfmux.remote.sandbox"):
+        with pytest.raises(SandboxError, match="couldn't be read") as exc_info:
+            sandbox_mod.run_parse(pdf)
+
+    # user-facing message is the existing neutral string, never the raw stderr/exit code
+    assert "disk full" not in str(exc_info.value)
+    assert "3" not in str(exc_info.value)
+
+    # the real diagnostic landed server-side in the log, not swallowed silently
+    messages = [r.getMessage() for r in caplog.records]
+    assert any("returncode=3" in m and "disk full" in m for m in messages)
+
+
+def test_assert_sandbox_ready_noop_when_not_docker_mode(
+    monkeypatch: pytest.MonkeyPatch,
+) -> None:
+    monkeypatch.setenv("PDFMUX_SANDBOX", "process")
+
+    def fail_if_called(*_a, **_k):
+        raise AssertionError("must not shell out when not in docker mode")
+
+    monkeypatch.setattr(sandbox_mod.subprocess, "run", fail_if_called)
+    sandbox_mod.assert_sandbox_ready()  # no raise, no subprocess call
+
+
+def test_assert_sandbox_ready_passes_when_image_present(monkeypatch: pytest.MonkeyPatch) -> None:
+    monkeypatch.setenv("PDFMUX_SANDBOX", "docker")
+
+    class _Ok:
+        returncode = 0
+        stdout = b"[{}]"
+        stderr = b""
+
+    monkeypatch.setattr(sandbox_mod.subprocess, "run", lambda *a, **k: _Ok())
+    sandbox_mod.assert_sandbox_ready()  # no raise
+
+
+def test_assert_sandbox_ready_fails_loudly_when_image_missing(
+    monkeypatch: pytest.MonkeyPatch,
+) -> None:
+    """This is the check that would have turned the multi-day silent outage (image never
+    built) into an immediate boot-time failure instead."""
+    monkeypatch.setenv("PDFMUX_SANDBOX", "docker")
+
+    class _Missing:
+        returncode = 1
+        stdout = b""
+        stderr = b"Error: No such image: pdfmux-sandbox:latest"
+
+    monkeypatch.setattr(sandbox_mod.subprocess, "run", lambda *a, **k: _Missing())
+    with pytest.raises(RuntimeError, match="not available"):
+        sandbox_mod.assert_sandbox_ready()
+
+
+def test_assert_sandbox_ready_fails_loudly_when_docker_binary_missing(
+    monkeypatch: pytest.MonkeyPatch,
+) -> None:
+    monkeypatch.setenv("PDFMUX_SANDBOX", "docker")
+
+    def raise_missing(*_a, **_k):
+        raise FileNotFoundError("docker: command not found")
+
+    monkeypatch.setattr(sandbox_mod.subprocess, "run", raise_missing)
+    with pytest.raises(RuntimeError, match="could not run"):
+        sandbox_mod.assert_sandbox_ready()
+
+
+def test_create_app_runs_the_sandbox_readiness_assertion_at_startup(
+    monkeypatch: pytest.MonkeyPatch,
+) -> None:
+    """Wiring check: create_app() must actually call the boot-time assertion (the point of
+    Fix 1's second half — fail at boot, not per-request), not just define it unused."""
+
+    def boom() -> None:
+        raise RuntimeError("sandbox not ready")
+
+    monkeypatch.setattr(server_mod, "assert_sandbox_ready", boom)
+    with pytest.raises(RuntimeError, match="sandbox not ready"):
+        server_mod.create_app(start_sweeper=False)
+
+
+# ---------------------------------------------------------------------------------------------
+# access-log token redaction
+# ---------------------------------------------------------------------------------------------
+
+
+def test_redact_token_filter_strips_token_from_access_log_record() -> None:
+    token = "a" * 48
+    record = logging.LogRecord(
+        name="uvicorn.access",
+        level=logging.INFO,
+        pathname="",
+        lineno=0,
+        msg='%s - "%s %s HTTP/%s" %d',
+        args=("127.0.0.1:54321", "POST", f"/mcp/{token}", "1.1", 200),
+        exc_info=None,
+    )
+    assert server_mod.RedactTokenFilter().filter(record) is True
+    assert record.args[2] == "/mcp/<redacted>"
+    assert token not in record.getMessage()
+
+
+def test_redact_token_filter_leaves_non_mcp_paths_and_non_tuple_args_alone() -> None:
+    record = logging.LogRecord(
+        name="uvicorn.access",
+        level=logging.INFO,
+        pathname="",
+        lineno=0,
+        msg='%s - "%s %s HTTP/%s" %d',
+        args=("127.0.0.1:1", "GET", "/dl/abc123.xlsx", "1.1", 200),
+        exc_info=None,
+    )
+    assert server_mod.RedactTokenFilter().filter(record) is True
+    assert record.args[2] == "/dl/abc123.xlsx"  # unrelated path untouched
+
+    plain = logging.LogRecord(
+        name="uvicorn.error",
+        level=logging.INFO,
+        pathname="",
+        lineno=0,
+        msg="server started",
+        args=None,
+        exc_info=None,
+    )
+    assert server_mod.RedactTokenFilter().filter(plain) is True
+    assert plain.msg == "server started"
+
+
+def test_log_config_wires_the_redaction_filter_onto_uvicorns_access_handler() -> None:
+    cfg = server_mod._log_config()
+    assert cfg["handlers"]["access"]["filters"] == ["redact_token"]
+    assert cfg["filters"]["redact_token"]["()"] == "pdfmux.remote.server.RedactTokenFilter"
+
+
+def test_log_config_redaction_survives_dictconfig_and_reaches_the_actual_log_line() -> None:
+    """End-to-end: uvicorn applies log_config via logging.config.dictConfig() at server
+    start, which rebuilds the named loggers/handlers from the dict — a filter attached to a
+    logger object beforehand would be wiped. Verify the filter declared *inside* the dict
+    survives that and actually redacts a real emitted access-log line."""
+    import copy
+    import logging.config
+
+    token = "b" * 48
+    access = logging.getLogger("uvicorn.access")
+    prev_handlers = list(access.handlers)
+    prev_propagate = access.propagate
+    prev_level = access.level
+    try:
+        logging.config.dictConfig(copy.deepcopy(server_mod._log_config()))
+        access = logging.getLogger("uvicorn.access")
+        buf = io.StringIO()
+        for h in access.handlers:
+            h.stream = buf
+        access.info('%s - "%s %s HTTP/%s" %d', "127.0.0.1:1", "POST", f"/mcp/{token}", "1.1", 200)
+        out = buf.getvalue()
+        assert token not in out
+        assert "/mcp/<redacted>" in out
+    finally:
+        access.handlers = prev_handlers
+        access.propagate = prev_propagate
+        access.level = prev_level
+
+
 # ---------------------------------------------------------------------------------------------
 # outputs
 # ---------------------------------------------------------------------------------------------