diff --git a/plugins/remote/host/redacted_logs.py b/plugins/remote/host/redacted_logs.py index 91d5575a2..55842c10b 100644 --- a/plugins/remote/host/redacted_logs.py +++ b/plugins/remote/host/redacted_logs.py @@ -8,6 +8,7 @@ logger or handler, the host's or a library's, can write a credential out. import logging import re +from collections.abc import Mapping from typing import Any REDACTED = "***" @@ -57,13 +58,37 @@ def redact_every_record() -> None: 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 diff --git a/plugins/remote/host/tests/test_redacted_logs.py b/plugins/remote/host/tests/test_redacted_logs.py index 13669aab4..562849599 100644 --- a/plugins/remote/host/tests/test_redacted_logs.py +++ b/plugins/remote/host/tests/test_redacted_logs.py @@ -2,6 +2,7 @@ import logging 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()