From 02e07abccb726c5153caa95304e72f25e94e9a07 Mon Sep 17 00:00:00 2001 From: ArthurBernard Date: Sun, 2 Aug 2026 17:39:52 +0200 Subject: [PATCH 1/2] =?UTF-8?q?chore:=20leaf=2001=20access-log-redaction?= =?UTF-8?q?=20=E2=86=92=20executing?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- doc/dev/plans/redact-token-logs/01-access-log-redaction.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/doc/dev/plans/redact-token-logs/01-access-log-redaction.md b/doc/dev/plans/redact-token-logs/01-access-log-redaction.md index 14de808..f33f1c6 100644 --- a/doc/dev/plans/redact-token-logs/01-access-log-redaction.md +++ b/doc/dev/plans/redact-token-logs/01-access-log-redaction.md @@ -1,7 +1,7 @@ --- plan: redact-token-logs/01-access-log-redaction kind: leaf -status: planned +status: executing complexity: medium depends: [] parallel: false From fe00b666918878c92d9b796b830bf4867051c4f4 Mon Sep 17 00:00:00 2001 From: ArthurBernard Date: Sun, 2 Aug 2026 17:50:46 +0200 Subject: [PATCH 2/2] fix: redact secret query values from the uvicorn access log MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The documented `?token=` script auth was written verbatim by uvicorn's access logger (observed in journald on the 2026-08-02 systemd deploy; token rotated). A mutating logger-level filter — reusing the transport URL scrubber via the new public `redact_url` alias — is installed at all three uvicorn launch sites and survives uvicorn's own dictConfig. --- CHANGELOG.md | 7 + doc/dev/03-decisions.md | 21 ++ doc/dev/06-status.md | 8 +- doc/dev/07-roadmap.md | 16 +- .../01-access-log-redaction.md | 127 ----------- trading_bot/application/log_setup.py | 100 ++++++++- trading_bot/interfaces/cli/main.py | 15 +- .../application/test_access_log_redaction.py | 200 ++++++++++++++++++ .../tests/interfaces/test_dashboard.py | 83 ++++++++ trading_bot/transport/http.py | 16 +- 10 files changed, 449 insertions(+), 144 deletions(-) delete mode 100644 doc/dev/plans/redact-token-logs/01-access-log-redaction.md create mode 100644 trading_bot/tests/application/test_access_log_redaction.py diff --git a/CHANGELOG.md b/CHANGELOG.md index 2066543..48ddff0 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -12,6 +12,13 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ### Fixed +- **The access log never prints secrets** — a redaction filter on the uvicorn + `access`/`error` loggers masks sensitive query values (`token`, `signature`, + `api_key`, `nonce` — the `transport/http.py` key set, public as `redact_url`) + at all three serving commands (`serve`, `start --serve`, `dashboard`), so the + documented `?token=` script auth can no longer write the dashboard token to + journald/log files. (#232) + ### Deprecated ### Removed diff --git a/doc/dev/03-decisions.md b/doc/dev/03-decisions.md index 8b017d3..57178b8 100644 --- a/doc/dev/03-decisions.md +++ b/doc/dev/03-decisions.md @@ -6,6 +6,27 @@ rejected approaches as tombstones. --- +### 2026-08-02 Access-log redaction: reuse the transport scrubber, filter at logger level (PR #232) [accepted] +- **Choice**: scrub uvicorn's request log by attaching a mutating + `logging.Filter` (`AccessLogRedactionFilter`, in `application/log_setup.py`) + to the `uvicorn.access` + `uvicorn.error` **loggers** before every uvicorn + launch (`serve`, `start --serve`, `dashboard`), reusing the transport's + existing URL scrubber via a public alias (`transport/http.py:redact_url` — + same key set `token`/`signature`/`api_key`/`nonce`, same `` + marker). Install is idempotent; the filter sanitises, never suppresses. +- **Why**: uvicorn's access logger writes the raw request target, so the + documented `?token=` script auth wrote the real dashboard token to journald + on the 2026-08-02 systemd deploy (invariant: secrets never logged; token + rotated). Logger-level placement is load-bearing: uvicorn's startup + `dictConfig` replaces the loggers' *handlers* but leaves + programmatically-attached logger *filters* in place (locked by a test), so + the scrub survives uvicorn's own logging setup at all three sites. +- **Rejected alternatives**: forking uvicorn's `LOGGING_CONFIG` dict per launch + site (three copies to keep in sync with upstream); duplicating the key set at + the interface layer (two lists to drift apart — one implementation means one + grep finds every masked value); handler-level filters (discarded with the + handler when `dictConfig` runs). + ### 2026-07-14 Tick scheduler semantics pinned; timing is a health signal (PR #228) [accepted] - **Choice**: the daemon tick job runs with explicit `coalesce=True`, `max_instances=1`, `misfire_grace_time=interval` (cron triggers: fixed diff --git a/doc/dev/06-status.md b/doc/dev/06-status.md index 5468618..d34086e 100644 --- a/doc/dev/06-status.md +++ b/doc/dev/06-status.md @@ -1,6 +1,6 @@ # 06 — Status -_Last updated: 2026-07-10_ +_Last updated: 2026-08-02_ ## Where things stand @@ -194,6 +194,12 @@ engine code: **real-key live enablement** (validate Kraken private endpoints + venue-level idempotency against a real-key sandbox, then flip `live_enabled`) — the one maintainer step in [`07-roadmap.md`](07-roadmap.md). +Ops: the dashboard daemon runs under **systemd** on the ops machine since +2026-08-02 (`deploy/trading-bot.service` installed + enabled; crash-restart and +clean SIGTERM verified; access log redacts `?token=`). Still open from +road-to-1.0 #4: an alert when the process dies, backups of the trading stores, +and the multi-week paper soak (running since 2026-07-10). + ## Known gaps / deferred diff --git a/doc/dev/07-roadmap.md b/doc/dev/07-roadmap.md index 723dc7d..40d43b3 100644 --- a/doc/dev/07-roadmap.md +++ b/doc/dev/07-roadmap.md @@ -86,9 +86,10 @@ order — none started yet, each is a `/pick-task` candidate: risk-limit visibility incl. daily-loss usage); `last_error` on `/api/strategies` (a stopped unit is indistinguishable from a crashed one). -4. [ ] **Ops readiness** (not engine code): daemon under **systemd** (restart - policy + an alert when the process dies — today it is a `nohup` from a - terminal session); a **multi-week paper soak** on the real-data books +4. [ ] **Ops readiness** (not engine code): daemon under **systemd** — **done + 2026-08-02** on the ops machine (`deploy/trading-bot.service` installed + + enabled, crash-restart verified); still missing an **alert** when the + process dies; a **multi-week paper soak** on the real-data books (running since 2026-07-10, capital 100/strategy — KPIs and equity curves as evidence); **backup of the trading stores** (`var/dashboard/*.sqlite` — the dccd data has its hourly rclone sync, the books have nothing). @@ -125,15 +126,6 @@ engine bugs and a set of API/UX gaps. **All six epics shipped 2026-07-11/12** vehicle for road-to-1.0 #1 (PRs #221–#223; found `Fill.fee_asset` and the Binance HTTP-400 mapping along the way). -## Hardening follow-up (2026-08-02) - -- [ ] **Access-log token redaction** — uvicorn's access log writes request URLs - verbatim, so the documented `?token=` script auth leaks the dashboard token - into journald/log files (observed during the 2026-08-02 systemd deploy; the - token was rotated). Redact sensitive query values (`token`, `signature`, - `api_key`, `nonce` — the `transport/http.py` key set) at every uvicorn launch - site (invariant: secrets never logged). - ## Not gating 1.0 (post-1.0 candidates) - [ ] **Binance USDT-M futures adapter** — *unless* chosen as the first live diff --git a/doc/dev/plans/redact-token-logs/01-access-log-redaction.md b/doc/dev/plans/redact-token-logs/01-access-log-redaction.md deleted file mode 100644 index f33f1c6..0000000 --- a/doc/dev/plans/redact-token-logs/01-access-log-redaction.md +++ /dev/null @@ -1,127 +0,0 @@ ---- -plan: redact-token-logs/01-access-log-redaction -kind: leaf -status: executing -complexity: medium -depends: [] -parallel: false -branch: fix/access-log-token-redaction -pr: "" ---- - -# 01 — Redact secret query values from the uvicorn access log - -## Goal - -No secret query value ever reaches a uvicorn log line. Today the documented -`?token=` script auth is written **verbatim** by uvicorn's access logger — on the -systemd deploy (2026-08-02) the real dashboard token landed in journald as -`GET /api/strategies?token= HTTP/1.1 200 OK` (the token was rotated). -This violates the repo invariant *"Secrets never logged — redact keys in any log -line."* The transport layer already solved the identical problem for signed -broker URLs (`trading_bot/transport/http.py:_redact_url`, key set -`{signature, api_key, apikey, token, nonce}`, marker ``); the fix -reuses that exact semantic at the web-serving surface. - -## Files to change - -- `trading_bot/transport/http.py` — expose the existing scrubber under a public - name: `redact_url = _redact_url` (module-level alias right after the def, with - a short comment: other layers reuse the same key set + marker so a URL is - redacted identically wherever it could reach a log). No behaviour change. -- `trading_bot/application/log_setup.py` — add: - - `class AccessLogRedactionFilter(logging.Filter)` — mutates the record in - place and always returns `True`: applies `redact_url` to `record.msg` (when - `str`) and to every `str` element of `record.args` (tuple args; leave dict - args untouched). `redact_url` is a no-op on strings without a query string, - so non-URL args (`"GET"`, client addr, HTTP version) pass through unchanged. - - `def install_access_log_redaction() -> None` — attaches one instance to the - `uvicorn.access` **and** `uvicorn.error` loggers. **Idempotent**: skip if a - filter of this class is already present (repeated CLI invocations in one - process — the test suite — must not stack filters). - - Why logger-level (load-bearing): `logging.config.dictConfig` (which uvicorn - applies at startup with its default `LOGGING_CONFIG`) replaces a configured - logger's **handlers** but does **not** clear programmatically-attached - logger **filters** — so installing before `uvicorn.run()` survives uvicorn's - own logging setup. A test must lock this assumption (below). -- `trading_bot/interfaces/cli/main.py` — call `install_access_log_redaction()` - immediately before each of the **three** uvicorn launch sites: - 1. `serve` — `uvicorn.run(...)` (~line 1210); - 2. `start --serve` — the `uvicorn.Server(uvicorn.Config(...))` site (~line 1477); - 3. `dashboard` — `uvicorn.run(...)` (~line 1861). - Import in the `# Local` import group. Match each site's surrounding comment - style (one line on why: the access log would otherwise write `?token=` URLs - verbatim). - -## Steps - -1. Add the `redact_url` public alias in `transport/http.py`. -2. Implement `AccessLogRedactionFilter` + `install_access_log_redaction()` in - `application/log_setup.py` (module docstring already frames the logging - spine; extend it with one line on the access-log scrubber). -3. Wire the three CLI sites. -4. Write the tests (below); run the gates until green: - `python -m pytest`, `ruff check trading_bot/`, `ruff format --check .`, - `mypy trading_bot/` (all under `~/.pyenv/versions/trading_bot_env/bin/python`). -5. Real-data verification (below). - -## Tests - -New `trading_bot/tests/application/test_access_log_redaction.py`: - -- **Redacts the uvicorn access record shape**: build - `logging.LogRecord(name="uvicorn.access", msg='%s - "%s %s HTTP/%s" %d', - args=("127.0.0.1:5", "GET", "/api/health?token=SENTINEL&x=1", "1.1", 200), …)`, - run the filter, assert `record.getMessage()` contains `` and `x=1` - and does **not** contain `SENTINEL`; method/addr/status unchanged. -- **All sensitive keys**: `token`, `signature`, `api_key`, `apiKey`, `nonce` - each redacted (case-insensitive); a non-sensitive query (`?symbol=BTCUSDT`) - and a query-less path pass through byte-identical. -- **Idempotent install**: `install_access_log_redaction()` twice → exactly one - `AccessLogRedactionFilter` on `uvicorn.access` and on `uvicorn.error`. -- **Survives uvicorn's dictConfig**: install, then - `logging.config.dictConfig(uvicorn.config.LOGGING_CONFIG)`, assert the filter - is still attached and still redacts (this locks the load-bearing assumption). -- Tests must clean up the filters they install (fixture removing the filter from - the shared loggers) so state never leaks across the suite. - -In `trading_bot/tests/interfaces/test_cli_commands.py` (follow the existing -pattern that patches `uvicorn.run` / `uvicorn.Server`): - -- After invoking each of `serve`, `dashboard`, and the `start --serve` path, - assert the filter is present on `uvicorn.access` (the install happens even - though uvicorn itself is patched out). - -## Verification on real data - -Launch the real dashboard on a **spare port** and read the actual access log: - -1. `~/.pyenv/versions/trading_bot_env/bin/trading-bot dashboard --port 8010` - (default paper config, loopback; capture stdout+stderr to a file). -2. `curl "http://127.0.0.1:8010/api/health?token=LEAKCANARY123"` (and one - clean request without query). -3. Read the captured log: the line for the probe must contain `` and - must **not** contain `LEAKCANARY123`; the clean request's line is unchanged. -4. Stop the daemon with `SIGTERM` **to the python PID** (find it via - `ss -tlnp`/`pgrep -f "trading-bot dashboard"` — a bash wrapper PID ignores - the signal) and confirm clean exit. - -**Constraints (do not violate):** - -- **Never touch port 8000, the running `trading-bot` systemd service, - `configs/dashboard.yaml`, or the real token.** All verification runs on port - 8010 with the throwaway `LEAKCANARY123` value. -- Secrets: the canary value is fake by construction; never read or echo real - credentials (`.env` stays closed). - -## Closeout (orchestrator, not the agent) - -- CHANGELOG (Fixed): access log redacts secret query values (`?token=` …) at - every uvicorn launch site. -- ADR: reuse of the transport scrubber via a public alias + a logger-level - filter that survives uvicorn's dictConfig (vs forking uvicorn's log-config - dict per site, vs duplicating the key set at the interface layer). -- Status: dashboard runs under systemd on the ops machine (2026-08-02) and the - access log no longer leaks the token; roadmap: remove the "Access-log token - redaction" line (single-leaf tree) and refresh the now-false "today it is a - nohup" parenthetical in road-to-1.0 item 4. diff --git a/trading_bot/application/log_setup.py b/trading_bot/application/log_setup.py index d25b14f..32f5541 100644 --- a/trading_bot/application/log_setup.py +++ b/trading_bot/application/log_setup.py @@ -27,7 +27,11 @@ Secrets discipline: the formatter adds nothing beyond time / level / logger name / message — no request bodies, no credentials. Callers stay responsible for never -passing a credential-adjacent value into a log record. +passing a credential-adjacent value into a log record — with one exception this +module handles itself: uvicorn's *access* logger writes the request URL verbatim, +so the dashboard's documented ``?token=`` script auth would land in the journal on +every request. :func:`install_access_log_redaction` scrubs it at the source (see +:class:`AccessLogRedactionFilter`). """ from __future__ import annotations @@ -40,11 +44,15 @@ # Local from trading_bot.application.config import LoggingConfig +from trading_bot.transport.http import redact_url __all__ = [ "configure_daemon_logging", + "install_access_log_redaction", + "AccessLogRedactionFilter", "OWNED_HANDLER_ATTR", "NOISY_NAMESPACES", + "ACCESS_LOG_NAMESPACES", ] #: Attribute stamped ``True`` on every handler this module installs, so a re-call @@ -63,6 +71,13 @@ "websockets", ) +#: The uvicorn logger namespaces whose records can carry a request URL — and so a +#: query-string secret. ``uvicorn.access`` writes one line per request (the leak +#: that motivated this); ``uvicorn.error`` carries the lifecycle/exception lines, +#: which quote the URL on a failed request. Both are scrubbed by +#: :func:`install_access_log_redaction`. +ACCESS_LOG_NAMESPACES: tuple[str, ...] = ("uvicorn.access", "uvicorn.error") + #: The shared log-line layout: ISO timestamp, padded level, logger name, message. _LOG_FORMAT = "%(asctime)s %(levelname)-8s %(name)s — %(message)s" @@ -146,3 +161,86 @@ def configure_daemon_logging(cfg: LoggingConfig) -> None: for namespace in NOISY_NAMESPACES: logging.getLogger(namespace).setLevel(logging.WARNING) + + +class AccessLogRedactionFilter(logging.Filter): + """Scrub query-string secrets out of uvicorn's request log lines. + + uvicorn's access logger formats one record per request as + ``'%s - "%s %s HTTP/%s" %d'`` with the **raw request target** among its + ``args`` — so the dashboard's documented ``?token=…`` script auth is written + verbatim to stderr/journald on every request. This filter rewrites the record + in place before any handler formats it, applying + :func:`~trading_bot.transport.http.redact_url` to ``record.msg`` and to every + string in ``record.args``; the value of a sensitive parameter (``token``, + ``signature``, ``api_key`` / ``apiKey``, ``nonce``, case-insensitively) + becomes ````. + + Reusing the transport's scrubber is deliberate: one key set, one marker, so a + URL is masked identically wherever it could reach a log. That function is a + no-op on a string with no query part, so the record's other args (the client + address, ``GET``, the HTTP version, the status code) pass through untouched, + as does a query carrying nothing sensitive (``?symbol=BTCUSDT``). + + Never drops a record: :meth:`filter` always returns ``True``. It is a + *sanitiser*, not a gate — a suppressed access line would cost observability, + which is not the trade being made here. + """ + + def filter(self, record: logging.LogRecord) -> bool: + """Redact *record* in place; always keep it. + + Parameters + ---------- + record : logging.LogRecord + The record about to be handled. Mutated in place — filters run once + per record before formatting, so every handler downstream (file, + stderr, journald) sees the scrubbed version. + + Returns + ------- + bool + Always ``True`` — the record is sanitised, never suppressed. + """ + if isinstance(record.msg, str): + record.msg = redact_url(record.msg) + # Only tuple args are positional `%s` substitutions worth scrubbing; a + # mapping-style `record.args` (`%(key)s` formatting) is left alone rather + # than rebuilt — uvicorn never uses it, and mutating an unknown mapping + # shape risks corrupting a third-party record. + if isinstance(record.args, tuple): + record.args = tuple( + redact_url(arg) if isinstance(arg, str) else arg for arg in record.args + ) + return True + + +def install_access_log_redaction() -> None: + """Attach one :class:`AccessLogRedactionFilter` to each uvicorn log namespace. + + Call this **before** handing control to uvicorn (``uvicorn.run`` / + ``Server.serve``) on every serving path, so no request line can be emitted + unscrubbed. The filters go on the *loggers* named in + :data:`ACCESS_LOG_NAMESPACES`, not on handlers, and that placement is + load-bearing: uvicorn configures logging at startup with + :func:`logging.config.dictConfig` (its ``LOGGING_CONFIG``), which replaces a + configured logger's **handlers** but leaves filters attached + programmatically to the logger itself in place. A handler-level filter would + be discarded with the handler it sat on; a logger-level one survives, and + runs once per record before any handler formats it. + + Idempotent: a namespace that already carries a filter of this class is left + alone, so repeated calls in one process (three CLI serving commands, or a + test suite invoking them many times) never stack duplicate filters on the + process-global uvicorn loggers. + + Returns + ------- + None + + """ + for namespace in ACCESS_LOG_NAMESPACES: + logger = logging.getLogger(namespace) + if any(isinstance(f, AccessLogRedactionFilter) for f in logger.filters): + continue + logger.addFilter(AccessLogRedactionFilter()) diff --git a/trading_bot/interfaces/cli/main.py b/trading_bot/interfaces/cli/main.py index 3c88793..b1eb3a4 100644 --- a/trading_bot/interfaces/cli/main.py +++ b/trading_bot/interfaces/cli/main.py @@ -73,7 +73,10 @@ from trading_bot.application.config import AppConfig, BrokerConfig, StrategyConfig from trading_bot.application.data_feed import BARS_SCHEMA, InMemoryFeed from trading_bot.application.instrument_specs import InstrumentSpecResolver -from trading_bot.application.log_setup import configure_daemon_logging +from trading_bot.application.log_setup import ( + configure_daemon_logging, + install_access_log_redaction, +) from trading_bot.application.performance_service import PerformanceService from trading_bot.application.run_app import run_app from trading_bot.application.service_factory import Engine, build_engine @@ -1207,6 +1210,9 @@ def serve( f"[green]serving dashboard[/green] (read-only, mode={config.mode}) on " f"http://{host}:{port} — use 'trading-bot dashboard' for the full control UI" ) + # Scrub uvicorn's access log first: it writes the request target verbatim, so + # a `?token=…` script-auth call would otherwise print the token in the clear. + install_access_log_redaction() uvicorn.run( application, host=host, @@ -1474,6 +1480,10 @@ def _schedule_info() -> dict[str, Any]: ) if auth_token: _console.print("[dim]control dashboard auth: token login enabled[/dim]") + # Scrub uvicorn's access log before it can emit a line: it writes the + # request target verbatim, so a `?token=…` script-auth call would + # otherwise write this daemon's auth token to the journal. + install_access_log_redaction() server = uvicorn.Server( uvicorn.Config( api, @@ -1856,6 +1866,9 @@ def _persist_manifest() -> None: f"{', read-only' if read_only else ''}) on http://{host}:{port}" " — Ctrl-C to stop" ) + # Scrub uvicorn's access log first: it writes the request target verbatim, so + # a `?token=…` script-auth call would otherwise print the token in the clear. + install_access_log_redaction() try: # uvicorn owns SIGINT: Ctrl-C returns from run() cleanly the first time. uvicorn.run( diff --git a/trading_bot/tests/application/test_access_log_redaction.py b/trading_bot/tests/application/test_access_log_redaction.py new file mode 100644 index 0000000..81744dc --- /dev/null +++ b/trading_bot/tests/application/test_access_log_redaction.py @@ -0,0 +1,200 @@ +"""Tests for the uvicorn access-log scrubber (:mod:`trading_bot.application.log_setup`). + +The dashboard documents a ``?token=`` query parameter for script auth, and +uvicorn's access logger writes the request target **verbatim** — so before this +filter existed, every such request printed the live token to stderr/journald (it +did, on a real deploy). These tests pin the fix at the record level: + +* a record shaped exactly like uvicorn's access line comes out with the token + replaced by the ```` marker (percent-encoded by ``urlencode``, as the + transport's own tests assert) and everything else (client address, method, HTTP + version, status, the harmless ``x=1``) byte-identical; +* every sensitive key the transport knows about (``token`` / ``signature`` / + ``api_key`` / ``apiKey`` / ``nonce``, case-insensitively) is masked, while a + non-sensitive query and a query-less path pass through untouched; +* installing twice leaves exactly one filter per namespace (the CLI's three + serving commands, and a test suite invoking them repeatedly, share one process); +* the filter **survives** uvicorn's own ``logging.config.dictConfig`` at startup — + the load-bearing assumption behind installing at the *logger* level rather than + on a handler. + +Test hygiene: the uvicorn loggers are process-global, so the ``clean_uvicorn_loggers`` +fixture strips every filter this module installs (and restores handlers/levels that +``dictConfig`` rewrites) after each test — the leak would otherwise silently change +what the rest of the suite logs. +""" + +from __future__ import annotations + +import logging +import logging.config +from collections.abc import Iterator + +import pytest + +from trading_bot.application.log_setup import ( + ACCESS_LOG_NAMESPACES, + AccessLogRedactionFilter, + install_access_log_redaction, +) + +#: The uvicorn access-log record shape (uvicorn.logging.AccessFormatter's input): +#: client address, method, full request target, HTTP version, status code. +_ACCESS_MSG = '%s - "%s %s HTTP/%s" %d' + + +@pytest.fixture +def clean_uvicorn_loggers() -> Iterator[None]: + """Restore the process-global uvicorn loggers around a test. + + Snapshots the filters, handlers, level and ``propagate`` flag of every + namespace in :data:`ACCESS_LOG_NAMESPACES` (plus the ``uvicorn`` root, which + uvicorn's ``LOGGING_CONFIG`` also rewrites) and puts them back on teardown, so + neither an installed redaction filter nor a ``dictConfig`` call leaks into the + rest of the suite. + """ + names = ("uvicorn", *ACCESS_LOG_NAMESPACES) + saved = { + name: ( + list(logging.getLogger(name).filters), + list(logging.getLogger(name).handlers), + logging.getLogger(name).level, + logging.getLogger(name).propagate, + ) + for name in names + } + yield + for name, (filters, handlers, level, propagate) in saved.items(): + logger = logging.getLogger(name) + logger.filters = filters + logger.handlers = handlers + logger.setLevel(level) + logger.propagate = propagate + + +def _access_record(target: str) -> logging.LogRecord: + """Build the access-log record uvicorn emits for a GET on *target*.""" + return logging.LogRecord( + name="uvicorn.access", + level=logging.INFO, + pathname=__file__, + lineno=0, + msg=_ACCESS_MSG, + args=("127.0.0.1:5", "GET", target, "1.1", 200), + exc_info=None, + ) + + +def test_filter_redacts_the_token_in_a_uvicorn_access_record() -> None: + """The token vanishes from the rendered line; every other field survives. + + The exact leak seen in production: ``GET /api/health?token= HTTP/1.1`` + written verbatim by the access logger. + """ + record = _access_record("/api/health?token=SENTINEL&x=1") + + assert AccessLogRedactionFilter().filter(record) is True # never drops a record + + message = record.getMessage() + assert "SENTINEL" not in message + # The marker as urlencode emits it (angle brackets percent-encoded) — the + # bare substring "redacted" is what stays greppable either way, so the + # assertion is written the way the transport's own tests write it. + assert "token=%3Credacted%3E" in message or "token=" in message + assert "x=1" in message # a harmless parameter stays readable + # The rest of the access line is untouched — the log stays useful. + assert '127.0.0.1:5 - "GET /api/health?token=' in message + assert message.endswith(' HTTP/1.1" 200') + + +@pytest.mark.parametrize("key", ["token", "signature", "api_key", "apiKey", "nonce"]) +def test_filter_redacts_every_sensitive_query_key(key: str) -> None: + """All of the transport's sensitive keys are masked, whatever their casing. + + The filter delegates to the transport's scrubber precisely so the key set is + shared: what is a secret on a signed broker URL is a secret in an access log. + """ + record = _access_record(f"/api/health?{key}=SENTINEL") + + AccessLogRedactionFilter().filter(record) + + message = record.getMessage() + assert "SENTINEL" not in message + assert f"{key}=%3Credacted%3E" in message or f"{key}=" in message + + +@pytest.mark.parametrize( + "target", ["/api/strategies?symbol=BTCUSDT", "/api/health", "/"] +) +def test_filter_leaves_a_secret_free_request_byte_identical(target: str) -> None: + """A non-sensitive query and a query-less path come through unchanged. + + Nothing about the ordinary access log changes — no re-quoting, no rewriting — + so the scrubber is invisible until there is something to hide. + """ + record = _access_record(target) + expected = record.getMessage() + + AccessLogRedactionFilter().filter(record) + + assert record.getMessage() == expected + + +def test_install_is_idempotent(clean_uvicorn_loggers: None) -> None: + """A second install adds no second filter — the CLI has three serving commands. + + They share one process (and one process-global logger), and the suite invokes + them many times; stacked filters would redact repeatedly and grow without + bound. + """ + install_access_log_redaction() + install_access_log_redaction() + + for namespace in ACCESS_LOG_NAMESPACES: + installed = [ + f + for f in logging.getLogger(namespace).filters + if isinstance(f, AccessLogRedactionFilter) + ] + assert len(installed) == 1, namespace + + +def test_install_covers_both_uvicorn_namespaces(clean_uvicorn_loggers: None) -> None: + """Both ``uvicorn.access`` (request lines) and ``uvicorn.error`` (which quotes + the URL on a failed request) are covered.""" + install_access_log_redaction() + + assert set(ACCESS_LOG_NAMESPACES) == {"uvicorn.access", "uvicorn.error"} + for namespace in ACCESS_LOG_NAMESPACES: + assert any( + isinstance(f, AccessLogRedactionFilter) + for f in logging.getLogger(namespace).filters + ), namespace + + +def test_filter_survives_uvicorns_dictconfig(clean_uvicorn_loggers: None) -> None: + """Installing *before* ``uvicorn.run`` outlives uvicorn's own logging setup. + + This locks the reason the filter goes on the logger and not on a handler: + uvicorn applies its ``LOGGING_CONFIG`` through + :func:`logging.config.dictConfig` at startup, which **replaces** a configured + logger's handlers (a handler-level filter would be thrown away with them) but + does not clear filters attached programmatically to the logger. If a future + uvicorn/stdlib release changed that, this test fails and the leak would + otherwise return silently. + """ + import uvicorn.config + + install_access_log_redaction() + logging.config.dictConfig(uvicorn.config.LOGGING_CONFIG) + + access = logging.getLogger("uvicorn.access") + assert any(isinstance(f, AccessLogRedactionFilter) for f in access.filters) + + # Still functional, not merely present: push a record through the logger's own + # filter chain the way `Logger.handle` does. (`Filterer.filter` is truthy on + # "keep" — since 3.12 it may return the record itself rather than `True`.) + record = _access_record("/api/health?token=SENTINEL") + assert access.filter(record) + assert "SENTINEL" not in record.getMessage() + assert "redacted" in record.getMessage() diff --git a/trading_bot/tests/interfaces/test_dashboard.py b/trading_bot/tests/interfaces/test_dashboard.py index b3df241..1397a74 100644 --- a/trading_bot/tests/interfaces/test_dashboard.py +++ b/trading_bot/tests/interfaces/test_dashboard.py @@ -20,6 +20,7 @@ import json import logging import time +from collections.abc import Iterator from decimal import Decimal # Third-party @@ -30,6 +31,10 @@ from trading_bot.application.accounting import Violation from trading_bot.application.config import AppConfig from trading_bot.application.events import FillEvent, LogEvent, OrderEvent +from trading_bot.application.log_setup import ( + ACCESS_LOG_NAMESPACES, + AccessLogRedactionFilter, +) from trading_bot.application.supervisor import StrategySupervisor from trading_bot.domain.fill import Fill from trading_bot.domain.instrument import Instrument, Symbol @@ -3861,3 +3866,81 @@ def test_graceful_shutdown_cancellation_filter_installs_once_per_process() -> No isinstance(f, _SuppressGracefulShutdownCancellation) for f in target.filters ) assert after == max(before, 1) + + +# --- CLI: every serving path installs the access-log scrubber --------------- # + + +@pytest.fixture +def clean_access_log_filters() -> Iterator[None]: + """Strip any :class:`AccessLogRedactionFilter` a test installs, on teardown. + + The uvicorn loggers are process-global, so a filter left attached would keep + rewriting records for the rest of the suite. Only filters of that class are + removed — the dashboard's own ``uvicorn.error`` carve-out filter is left alone. + """ + yield + for namespace in ACCESS_LOG_NAMESPACES: + logger = logging.getLogger(namespace) + logger.filters = [ + f for f in logger.filters if not isinstance(f, AccessLogRedactionFilter) + ] + + +def _access_filters() -> list[logging.Filter]: + """The redaction filters currently attached to the ``uvicorn.access`` logger.""" + return [ + f + for f in logging.getLogger("uvicorn.access").filters + if isinstance(f, AccessLogRedactionFilter) + ] + + +def test_dashboard_installs_the_access_log_redaction( + monkeypatch: pytest.MonkeyPatch, clean_access_log_filters: None +) -> None: + """`dashboard` scrubs uvicorn's access log before serving. + + The dashboard documents a ``?token=`` query parameter for script auth, and + uvicorn's access logger writes the request target verbatim — so the token + must be redacted at the logger, installed *before* control reaches uvicorn + (patched out here, which is exactly why the assertion can be made at all). + """ + import uvicorn + + monkeypatch.setattr(uvicorn, "run", lambda app, **kw: None) + + result = runner.invoke(cli_app, ["dashboard", "--port", "9138"]) + + assert result.exit_code == 0, result.output + assert len(_access_filters()) == 1 + + +def test_serve_installs_the_access_log_redaction( + monkeypatch: pytest.MonkeyPatch, clean_access_log_filters: None +) -> None: + """The read-only `serve` alias scrubs the access log too — same leak, same fix.""" + import uvicorn + + monkeypatch.setattr(uvicorn, "run", lambda app, **kw: None) + + result = runner.invoke(cli_app, ["serve", "--port", "9152"]) + + assert result.exit_code == 0, result.output + assert len(_access_filters()) == 1 + + +def test_start_serve_installs_the_access_log_redaction( + monkeypatch: pytest.MonkeyPatch, clean_access_log_filters: None +) -> None: + """`start --serve` — the long-lived daemon, the path that actually leaked. + + This is the systemd unit's code path: its access lines go to journald, where a + token would sit in the logs indefinitely. + """ + _patch_serve_stack(monkeypatch) + + result = runner.invoke(cli_app, ["start", "--serve", "--interval", "0.05"]) + + assert result.exit_code == 0, result.output + assert len(_access_filters()) == 1 diff --git a/trading_bot/transport/http.py b/trading_bot/transport/http.py index b55641c..28e2c3f 100644 --- a/trading_bot/transport/http.py +++ b/trading_bot/transport/http.py @@ -41,6 +41,7 @@ "AmbiguousRequestError", "HTTPError", "ResponseTooLargeError", + "redact_url", ] logger = logging.getLogger(__name__) @@ -130,12 +131,23 @@ def _redact_url(url: str) -> str: (key, _REDACTED if key.lower() in _SENSITIVE_QUERY_KEYS else value) for key, value in pairs ] - # quote_via=quote keeps ```` readable rather than percent-encoding - # the angle brackets, so the marker is easy to grep for in logs. + # quote_via=quote (not the default quote_plus) re-encodes values path-style; + # the marker's angle brackets still percent-encode, so it reaches a log line + # as ``%3Credacted%3E`` — grep for ``redacted`` to find every masked value. new_query = urllib.parse.urlencode(redacted, quote_via=urllib.parse.quote) return urllib.parse.urlunsplit(split._replace(query=new_query)) +#: Public alias of :func:`_redact_url` for the other layers that must scrub a URL +#: before it reaches a log. Sharing the one implementation — rather than +#: re-deriving a key set per layer — is what makes a URL redacted *identically* +#: wherever it could be logged: same :data:`_SENSITIVE_QUERY_KEYS`, same +#: ```` marker, so one grep finds every masked value. Used by +#: :mod:`trading_bot.application.log_setup` to scrub uvicorn's access log (the +#: dashboard's ``?token=`` script auth would otherwise be written verbatim). +redact_url = _redact_url + + def _redact_exc(exc: BaseException) -> str: """Return ``str(exc)`` with any embedded signed URL scrubbed of secrets.