diff --git a/CHANGELOG.md b/CHANGELOG.md index 255a649..7becee6 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -47,6 +47,10 @@ The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.1.0/). - `setup_logging(use_queue=True)` hands records to a background thread through a queue, so slow handlers do not block the caller, with `shutdown_logging()` to flush and stop it. It also runs at interpreter exit (#23). +- `setup_logging(redact_keys=..., redact_patterns=...)` masks secrets in extra + and context fields and in message text for every handler, and + `RedactionFilter` and `DEFAULT_REDACT_KEYS` are exported. Redaction is off + by default (#24). ### Changed diff --git a/README.md b/README.md index 964cb19..2225e19 100644 --- a/README.md +++ b/README.md @@ -130,6 +130,8 @@ log.info("outside") # carries neither | `console_level` | `None` | Console level, defaulting to `level`. | | `console_stream` | `None` | Console stream, for example `sys.stderr`. Defaults to `sys.stdout`. | | `use_queue` | `False` | Write records on a background thread, so slow handlers do not block your code. See below. | +| `redact_keys` | `None` | Field names to mask in every output, for example `DEFAULT_REDACT_KEYS`. See below. | +| `redact_patterns` | `None` | Regular expressions whose matches are masked in the message text. | | `use_emoji` | `True` | Show a level emoji in the verbose console layout. Set `False` for terminals that render emoji badly. | | `mode` | `None` | Console layout: `"verbose"` (coloured, with source location and context) or `"compact"` (`[LEVEL] message`). Falls back to `LOG_FORMAT`, then `"verbose"`. | | `use_json` | `None` | Write JSON lines to the console instead. Needs the `json` extra. Falls back to `LOG_FORMAT`. | @@ -159,6 +161,30 @@ Things worth knowing: - Asking for JSON output without `python-json-logger` installed raises an `ImportError` with an install hint. +### Redacting secrets + +Pass `redact_keys` to mask the value of any field whose name contains one of the given words, and +`redact_patterns` to mask text inside the message. Both apply to every handler, including JSON and +syslog, and are off unless you ask for them. + +```python +from pylogkit import DEFAULT_REDACT_KEYS, setup_logging + +logger = setup_logging( + "app", + redact_keys=DEFAULT_REDACT_KEYS, # password, token, authorization, ... + redact_patterns=[r"Bearer \S+"], # secrets that appear inside message text +) +logger.info("calling the API with Bearer abc123", extra={"api_token": "abc123"}) +# message: calling the API with *** api_token field: *** +``` + +- Field names match case-insensitively by substring, so `token` also masks `access_token`. +- Fields from `extra=`, `ContextualLoggerAdapter` and the global context are covered, including + nested dictionaries and lists. The objects you pass in are not modified. +- Tracebacks are not searched, so keep secrets out of exception messages. +- The same filter is available as `RedactionFilter` for handlers you attach yourself. + ### Non-blocking logging File, syslog and network handlers can stall the thread that logs. With `use_queue=True` the logger diff --git a/pylogkit/__init__.py b/pylogkit/__init__.py index b24ee54..3393f7d 100644 --- a/pylogkit/__init__.py +++ b/pylogkit/__init__.py @@ -11,7 +11,9 @@ from pylogkit._version import __version__ from pylogkit.log_setup import ( + DEFAULT_REDACT_KEYS, ContextualLoggerAdapter, + RedactionFilter, clear_log_context, get_log_context, log_context, @@ -25,8 +27,10 @@ ) __all__ = [ - "__version__", + "DEFAULT_REDACT_KEYS", "ContextualLoggerAdapter", + "RedactionFilter", + "__version__", "clear_log_context", "get_log_context", "log_context", diff --git a/pylogkit/log_setup.py b/pylogkit/log_setup.py index 5d07cf1..b44f4c0 100644 --- a/pylogkit/log_setup.py +++ b/pylogkit/log_setup.py @@ -29,6 +29,7 @@ import logging import os import queue +import re import socket import sys import time @@ -285,6 +286,90 @@ def filter(self, record: logging.LogRecord) -> bool: return True +DEFAULT_REDACT_KEYS: tuple[str, ...] = ( + "password", + "passwd", + "secret", + "token", + "authorization", + "api_key", + "apikey", + "cookie", +) +"""Field names worth masking in most applications, for ``redact_keys=``.""" + +_STANDARD_RECORD_ATTRIBUTES = frozenset(logging.LogRecord("", 0, "", 0, "", (), None).__dict__) | { + "message", + "asctime", + "taskName", +} + + +class RedactionFilter(logging.Filter): + """Mask secrets in a record's extra fields and, optionally, in its message. + + Fields are the attributes added through ``extra=``, a + :class:`ContextualLoggerAdapter` or the global context. A field is masked + when its name contains any of ``keys``, compared case-insensitively, so + ``"token"`` also masks ``access_token``. Dictionaries, lists and tuples + inside a field are searched too, on a copy, so the caller's objects are + never modified. Masking is idempotent, which makes it safe for a record to + pass through the filter once per handler. + + Message text is only touched when ``patterns`` are given. Tracebacks are + not searched. + + Args: + keys: Field names to mask, for example :data:`DEFAULT_REDACT_KEYS`. + patterns: Regular expressions, as strings or compiled patterns, whose + matches are replaced by ``mask`` in the message. + mask: Replacement text. + """ + + def __init__( + self, + keys: Iterable[str] = (), + patterns: Iterable[str | re.Pattern[str]] = (), + mask: str = "***", + ) -> None: + """Create the filter.""" + super().__init__() + self._keys = tuple(key.lower() for key in keys) + self._patterns = tuple(re.compile(p) if isinstance(p, str) else p for p in patterns) + self._mask = mask + + def _is_secret(self, name: object) -> bool: + """Return whether a field called ``name`` must be masked.""" + lowered = str(name).lower() + return any(key in lowered for key in self._keys) + + def _clean(self, value: Any) -> Any: + """Return ``value`` with secret entries of nested containers masked.""" + if isinstance(value, dict): + return { + k: self._mask if self._is_secret(k) else self._clean(v) for k, v in value.items() + } + if isinstance(value, (list, tuple)): + return type(value)(self._clean(v) for v in value) + return value + + def filter(self, record: logging.LogRecord) -> bool: + """Mask ``record`` in place and accept it.""" + if self._patterns: + message = record.getMessage() + redacted = message + for pattern in self._patterns: + redacted = pattern.sub(self._mask, redacted) + if redacted != message: + record.msg = redacted + record.args = None + for name, value in list(record.__dict__.items()): + if name in _STANDARD_RECORD_ATTRIBUTES: + continue + record.__dict__[name] = self._mask if self._is_secret(name) else self._clean(value) + return True + + class ContextualLoggerAdapter(_AdapterBase): """Logger adapter that attaches context fields to every record. @@ -512,6 +597,8 @@ def setup_logging( console_stream: IO[str] | None = None, use_emoji: bool = True, use_queue: bool = False, + redact_keys: Iterable[str] | None = None, + redact_patterns: Iterable[str | re.Pattern[str]] | None = None, ) -> logging.Logger: """Configure and return a logger with console, file, JSON and syslog output. @@ -580,6 +667,10 @@ def setup_logging( The queue is unbounded. Records are written when the thread gets to them, so call :func:`shutdown_logging` to wait for the queue to drain. That happens automatically at interpreter exit. + redact_keys: Field names to mask in every handler's output, for + example :data:`DEFAULT_REDACT_KEYS`. See :class:`RedactionFilter`. + redact_patterns: Regular expressions whose matches are masked in the + message text. Returns: The configured :class:`logging.Logger`. @@ -649,29 +740,34 @@ def setup_logging( syslog_handler.setFormatter(syslog_formatter) handlers.append(syslog_handler) - context_filter = ContextFilter(use_emoji=use_emoji) + filters: list[logging.Filter] = [ContextFilter(use_emoji=use_emoji)] + if redact_keys or redact_patterns: + filters.append(RedactionFilter(redact_keys or (), redact_patterns or ())) if use_queue: - _start_queue(logger, handlers, context_filter) + _start_queue(logger, handlers, filters) else: for handler in handlers: - handler.addFilter(context_filter) + for log_filter in filters: + handler.addFilter(log_filter) logger.addHandler(handler) return logger def _start_queue( - logger: logging.Logger, handlers: list[logging.Handler], context_filter: ContextFilter + logger: logging.Logger, handlers: list[logging.Handler], filters: list[logging.Filter] ) -> None: """Route ``logger`` through a queue drained by a listener thread owning ``handlers``. - The context filter runs on the queue handler, that is in the thread that - logs, because the listener thread has no access to that thread's context. + The filters run on the queue handler, that is in the thread that logs. + The listener thread has no access to that thread's context, and secrets + are masked before a record is queued. """ global _atexit_registered log_queue: queue.SimpleQueue[logging.LogRecord] = queue.SimpleQueue() queue_handler = _QueueHandler(log_queue) - queue_handler.addFilter(context_filter) + for log_filter in filters: + queue_handler.addFilter(log_filter) listener = QueueListener(log_queue, *handlers, respect_handler_level=True) listener.start() _listeners[logger.name] = listener diff --git a/tests/test_redaction.py b/tests/test_redaction.py new file mode 100644 index 0000000..79daf55 --- /dev/null +++ b/tests/test_redaction.py @@ -0,0 +1,168 @@ +"""Tests for masking secrets with ``redact_keys`` and ``redact_patterns``.""" + +import json +import logging + +import pytest + +from pylogkit import ( + DEFAULT_REDACT_KEYS, + ContextualLoggerAdapter, + RedactionFilter, + set_log_context, + setup_logging, + shutdown_logging, +) + + +def _record(msg="hello", args=(), **extra): + """Build a record with extra attributes the way ``extra=`` does.""" + record = logging.LogRecord("t", logging.INFO, __file__, 1, msg, args, None) + record.__dict__.update(extra) + return record + + +def test_matching_fields_are_masked_case_insensitively_by_substring(): + """``token`` masks ``Access_Token`` and ``password`` masks ``db_password``.""" + record = _record(Access_Token="abc", db_password="hunter2", user="alice") + + RedactionFilter(["token", "password"]).filter(record) + + assert record.Access_Token == "***" + assert record.db_password == "***" + assert record.user == "alice" + + +def test_standard_record_attributes_are_never_masked(): + """A key such as ``name`` or ``msg`` must not wipe the logger name or the message.""" + record = _record("the message") + + RedactionFilter(["name", "msg", "message"]).filter(record) + + assert record.name == "t" + assert record.getMessage() == "the message" + + +def test_nested_values_are_masked_without_touching_the_callers_objects(): + """Dictionaries inside lists inside extras are searched, on a copy.""" + original = {"user": "alice", "auth": {"password": "p"}, "items": [{"token": "t"}]} + record = _record(payload=original) + + RedactionFilter(["password", "token"]).filter(record) + + assert record.payload == { + "user": "alice", + "auth": {"password": "***"}, + "items": [{"token": "***"}], + } + assert original["auth"]["password"] == "p" + + +def test_patterns_mask_message_text_including_arguments(): + """Matches in the formatted message are replaced, strings or compiled.""" + import re + + record = _record("login %s with Bearer abc123", ("alice",)) + + RedactionFilter(patterns=[r"Bearer \S+", re.compile("alice")], mask="[hidden]").filter(record) + + assert record.getMessage() == "login [hidden] with [hidden]" + + +def test_message_is_left_alone_without_a_match(): + """A message without matches keeps its arguments, so nothing is formatted early.""" + record = _record("value %d", (5,)) + + RedactionFilter(patterns=["secret"]).filter(record) + + assert record.msg == "value %d" + assert record.args == (5,) + + +def test_filter_is_idempotent(): + """A record passes through once per handler, so a second pass changes nothing.""" + record = _record("Bearer abc", token="t") + log_filter = RedactionFilter(["token"], [r"Bearer \S+"]) + + log_filter.filter(record) + log_filter.filter(record) + + assert record.getMessage() == "***" + assert record.token == "***" + + +def test_default_keys_cover_the_usual_suspects(): + """The exported defaults include the names from the issue.""" + assert {"password", "token", "authorization"} <= set(DEFAULT_REDACT_KEYS) + + +def test_nothing_is_masked_by_default(): + """Redaction is opt-in: without arguments no handler carries the filter.""" + logger = setup_logging("red-off") + + filters = [f for handler in logger.handlers for f in handler.filters] + + assert filters + assert not any(isinstance(f, RedactionFilter) for f in filters) + + +def test_context_fields_are_masked_in_every_handler(tmp_path): + """Global context, adapter fields and ``extra`` all go through the filter.""" + text = tmp_path / "a.log" + set_log_context(session_id="sess-1", api_key="KEY-1") + logger = setup_logging( + "red-ctx", + to_console=False, + to_file=True, + file_path=str(text), + redact_keys=["api_key", "request_id"], + ) + log = ContextualLoggerAdapter(logger).with_context(request_id="REQ-9") + + log.info("hello", extra={"api_key": "KEY-2"}) + + contents = text.read_text(encoding="utf-8") + assert "REQ-9" not in contents + assert "KEY-" not in contents + assert "[session_id=sess-1]" in contents + + +@pytest.mark.json_logger +def test_json_output_is_masked(tmp_path): + """Extras and message text are masked in the JSON file too.""" + path = tmp_path / "red.json.log" + logger = setup_logging( + "red-json", + to_console=False, + to_json_file=True, + json_file_path=str(path), + redact_keys=DEFAULT_REDACT_KEYS, + redact_patterns=[r"card=\d+"], + ) + + logger.info("paid card=4111", extra={"authorization": "Bearer x", "order": 7}) + + record = json.loads(path.read_text(encoding="utf-8").splitlines()[0]) + assert record["message"] == "paid ***" + assert record["authorization"] == "***" + assert record["order"] == 7 + + +def test_masking_happens_before_records_are_queued(tmp_path): + """With ``use_queue`` the secret never reaches the listener thread.""" + path = tmp_path / "q.log" + set_log_context(token="TOKEN-1") + logger = setup_logging( + "red-queue", + to_console=False, + to_file=True, + file_path=str(path), + use_queue=True, + redact_keys=["token"], + redact_patterns=["TOKEN-\\d"], + ) + + logger.info("using TOKEN-1") + shutdown_logging() + + assert "TOKEN-1" not in path.read_text(encoding="utf-8")