From e0139c5b08263504b0f11c944605e485524150ac Mon Sep 17 00:00:00 2001 From: Nameet Potnis <93118951+NameetP@users.noreply.github.com> Date: Thu, 8 Oct 2026 02:54:47 +0000 Subject: [PATCH] =?UTF-8?q?fix:=20sandbox=20silent-failure=20hardening=20?= =?UTF-8?q?=E2=80=94=20returncode=20check,=20boot-time=20docker=20check,?= =?UTF-8?q?=20token=20redaction?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Adopts the two findings from the 2026-10-07 MWF sandbox-outage receipt (products/pdfmux/decisions/2026-10-07-mwf-tick-receipt.md) that were deliberately left unshipped pending review. 1. run_parse() never checked proc.returncode. When `docker run` failed for an infra reason (image missing, daemon down, OOM), stdout was empty, so json.loads(... or "{}") silently returned {} — no "error" key — and the caller got SandboxResult(data={}) as if the parse succeeded. This is why the outage ran unnoticed for days: pm2's error log stayed at 0 bytes. Now a non-zero exit logs a server-side diagnostic (stderr tail + exit code, never user-facing) and raises SandboxError("This PDF couldn't be read.") — reusing the existing neutral string from the JSON-decode path. 2. Added assert_sandbox_ready(), called from create_app(), which runs `docker image inspect` on DOCKER_IMAGE at boot when PDFMUX_SANDBOX=docker. A missing/broken image now crashes at startup instead of failing silently on every request. 3. The plugin token is the secret path segment in `POST /mcp/`, and uvicorn's access logger recorded the full path in plaintext — a live credential landing in root-only pm2 logs. Added RedactTokenFilter, wired onto uvicorn's "access" log handler via a custom log_config (a filter attached to the logger object directly would be wiped when uvicorn's own dictConfig() call rebuilds it), so `/mcp/` is logged as `/mcp/`. Tests: 9 new cases covering the returncode-failure path (safe message vs. logged diagnostic), the boot-time assertion (noop/pass/image-missing/ docker-missing), create_app() wiring, and the redaction filter (unit + dictConfig-survival integration). Full suite: 856 passed, 7 skipped (matching CI's `[dev,serve,remote]` extras exactly). Scope: code + tests only, merged to main. NOT deployed to mc.pdfmux.com — no VPS access this session; the currently-running image keeps serving the unpatched code until the next session with VPS access redeploys. Co-Authored-By: Claude Sonnet 5 --- src/pdfmux/remote/sandbox.py | 48 +++++++++ src/pdfmux/remote/server.py | 59 ++++++++++- tests/test_remote_server.py | 191 +++++++++++++++++++++++++++++++++++ 3 files changed, 296 insertions(+), 2 deletions(-) diff --git a/src/pdfmux/remote/sandbox.py b/src/pdfmux/remote/sandbox.py index 528226b..3288ab9 100644 --- a/src/pdfmux/remote/sandbox.py +++ b/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) diff --git a/src/pdfmux/remote/server.py b/src/pdfmux/remote/server.py index 32774db..374934e 100644 --- a/src/pdfmux/remote/server.py +++ b/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/` (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/` to `/mcp/`.""" + + def filter(self, record: logging.LogRecord) -> bool: + if isinstance(record.args, tuple): + record.args = tuple( + _TOKEN_IN_PATH_RE.sub(r"\1", 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", 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(), + ) diff --git a/tests/test_remote_server.py b/tests/test_remote_server.py index 8a2a4e6..36de9eb 100644 --- a/tests/test_remote_server.py +++ b/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/" + 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/" in out + finally: + access.handlers = prev_handlers + access.propagate = prev_propagate + access.level = prev_level + + # --------------------------------------------------------------------------------------------- # outputs # ---------------------------------------------------------------------------------------------