fix(plugins): keep a log record's arguments when redacting it

plugins/remote/host/redacted_logs.py

@@ -8,12 +8,13 @@
 
 import logging
 import re
+from collections.abc import Mapping
 from typing import Any
 
 REDACTED = "***"
 
 _REDACTIONS = (
-    # scheme://user:password@host, the form every proxy is given in.
+    # A URL's user and password before its host, the form every proxy is given in.
     (
         re.compile(r"(\b[a-zA-Z][a-zA-Z0-9+.-]*://)[^\s/?#@'\"<>]+@"),
         rf"\1{REDACTED}@",
@@ -57,13 +58,37 @@ def make_redacted(*args: Any, **kwargs: Any) -> logging.LogRecord:
 
 
 def _redact(record: logging.LogRecord) -> None:
+    # The arguments keep their shape, since a formatter may read them: uvicorn's
+    # access log unpacks its five. Only one that holds a credential is replaced,
+    # and a template with arguments is left whole, so its placeholders still match.
+    if isinstance(record.args, Mapping):
+        record.args = {key: _redacted_value(v) for key, v in record.args.items()}
+    elif isinstance(record.args, tuple) and record.args:
+        record.args = tuple(_redacted_value(arg) for arg in record.args)
+    else:
+        record.msg = _redacted_value(record.msg)
     try:
         message = record.getMessage()
     except Exception:
         # A message that does not format is the logging module's own error to report.
         return
-    record.msg, record.args = redacted(message), None
+    # A credential split across the message and its arguments shows only once
+    # formatted; such a record keeps just its redacted text.
+    if redacted(message) != message:
+        record.msg, record.args = redacted(message), None
     if record.exc_info and not record.exc_text:
         record.exc_text = redacted(logging.Formatter().formatException(record.exc_info))
     if record.stack_info:
         record.stack_info = redacted(record.stack_info)
+
+
+def _redacted_value(value: Any) -> Any:
+    """A string redacted; anything else as it is, unless its text holds a credential."""
+    if isinstance(value, str):
+        return redacted(value)
+    try:
+        text = str(value)
+    except Exception:
+        return value
+    clean = redacted(text)
+    return value if clean == text else clean

plugins/remote/host/tests/test_redacted_logs.py

@@ -2,6 +2,7 @@
 from collections.abc import Iterator
 
 import pytest
+from uvicorn.logging import AccessFormatter
 
 from host.redacted_logs import redact_every_record, redacted
 
@@ -81,6 +82,49 @@ def test_every_record_is_redacted_whoever_formats_it(
     assert f"tunnel to {HIDDEN} refused" in caplog.text
 
 
+def test_a_formatter_that_reads_the_arguments_still_formats(
+    record_factory: None, caplog: pytest.LogCaptureFixture
+) -> None:
+    """uvicorn's access log unpacks its five arguments: they keep their shape and types."""
+    redact_every_record()
+    logger = logging.getLogger("host.tests.redacted.access")
+    with caplog.at_level(logging.INFO, logger=logger.name):
+        logger.info(
+            '%s - "%s %s HTTP/%s" %d',
+            "10.0.1.7:51234",
+            "POST",
+            "/web-crawl/mcp?key=abc123",
+            "1.1",
+            200,
+        )
+
+    (record,) = caplog.records
+    assert record.args == (
+        "10.0.1.7:51234",
+        "POST",
+        "/web-crawl/mcp?key=***",
+        "1.1",
+        200,
+    )
+    formatted = AccessFormatter("%(request_line)s %(status_code)s").format(record)
+    assert formatted == "POST /web-crawl/mcp?key=*** HTTP/1.1 200 OK"
+
+
+def test_a_credential_split_across_message_and_arguments_is_hidden(
+    record_factory: None, caplog: pytest.LogCaptureFixture
+) -> None:
+    redact_every_record()
+    logger = logging.getLogger("host.tests.redacted.split")
+    with caplog.at_level(logging.WARNING, logger=logger.name):
+        logger.warning("proxy http://%s:%s@%s failed", "user-1", "s3cret", "gw:823")
+        logger.warning("open failed: %s", ConnectionError(f"tunnel to {PROXY} refused"))
+
+    assert [record.getMessage() for record in caplog.records] == [
+        "proxy http://***@gw:823 failed",
+        f"open failed: tunnel to {HIDDEN} refused",
+    ]
+
+
 def test_redacting_twice_wraps_the_factory_once(record_factory: None) -> None:
     redact_every_record()
     once = logging.getLogRecordFactory()