From d7ab12e8a6e3a3c62769191f4de786f715dda1a3 Mon Sep 17 00:00:00 2001 From: bot-backend Date: Sun, 13 Sep 2026 13:34:08 +0300 Subject: [PATCH] =?UTF-8?q?fix(tradein):=20=D1=82=D0=BE=D0=BA=D0=B5=D0=BD?= =?UTF-8?q?=20DaData=20=D0=BD=D0=B5=20=D1=83=D1=82=D0=B5=D0=BA=D0=B0=D0=B5?= =?UTF-8?q?=D1=82=20=D0=B2=20=D0=BB=D0=BE=D0=B3=20+=20=D1=84=D0=B8=D0=BA?= =?UTF-8?q?=D1=81=20crash=20=D0=B2=20access-log=20=D1=81=D0=BA=D1=80=D0=B0?= =?UTF-8?q?=D0=B1=D0=B1=D0=B5=D1=80=D0=B5?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit DaData на 403 возвращает "Feature CLEAN disabled for token '<действующий токен>'." открытым текстом — body_preview копировал это в WARNING/ERROR лог как есть, токен уезжал в docker logs (потенциальный breadcrumb в GlitchTip). Добавлен scrub_body_secrets() в app/core/log_scrub.py: маскирует token '' и любую generic hex/base64-подобную последовательность 24+ символов — защита не зависит от точной формулировки вендора. Заодно найден и исправлен источник "--- Logging error ---" / ValueError: not enough values to unpack (expected 5, got 0) из прод-логов tradein-backend: QuerySecretFilter (#3154) при найденном секрете в query-строке схлопывал record.args в (), а uvicorn.logging.AccessFormatter.formatMessage() распаковывает record.args напрямую как 5-tuple в обход record.getMessage() — сама попытка заскрабить секрет ронла форматирование access-лога. Фильтр переписан на поэлементный скраб record.args (arity не трогается). Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01JY6iWDnGDthdvsMWgK1BMG --- tradein-mvp/backend/app/core/log_scrub.py | 79 +++++++++++++++++-- tradein-mvp/backend/app/services/dadata.py | 7 +- .../backend/tests/services/test_dadata.py | 40 ++++++++++ .../tests/test_3154_query_secret_scrub.py | 54 ++++++++++++- 4 files changed, 169 insertions(+), 11 deletions(-) diff --git a/tradein-mvp/backend/app/core/log_scrub.py b/tradein-mvp/backend/app/core/log_scrub.py index 9336cec9..d6e58301 100644 --- a/tradein-mvp/backend/app/core/log_scrub.py +++ b/tradein-mvp/backend/app/core/log_scrub.py @@ -41,17 +41,84 @@ def scrub_query_secrets(text: str) -> str: class QuerySecretFilter(logging.Filter): - """Маскирует секреты в query-строке ЛЮБОЙ записи логгера, к которому привязан.""" + """Маскирует секреты в query-строке ЛЮБОЙ записи логгера, к которому привязан. + + Скрабит `record.msg` и КАЖДЫЙ элемент `record.args` по отдельности — НЕ схлопывает + их в единую строку через `record.getMessage()` с последующим `args = ()`. + + Прод-баг (#3471): схлопывание ломало `uvicorn.access` — там `record.args` это + структурный 5-tuple `(client_addr, method, full_path, http_version, status_code)`, + который `uvicorn.logging.AccessFormatter.formatMessage()` распаковывает напрямую + (`a, b, c, d, e = record.args`), в обход `record.getMessage()`. Как только фильтр + находил секрет (например `?secret=` в webhook-пути) и обнулял `args`, форматтер падал + с `ValueError: not enough values to unpack (expected 5, got 0)` — сама попытка + заскрабить секрет ломала запись лога целиком (`--- Logging error ---` в докер-логах). + """ def filter(self, record: logging.LogRecord) -> bool: - message = record.getMessage() - scrubbed = scrub_query_secrets(message) - if scrubbed != message: - record.msg = scrubbed - record.args = () + args = record.args + if isinstance(args, tuple) and args: + # Есть позиционные args — скрабим КАЖДЫЙ элемент отдельно, arity не трогаем. + # `record.msg` (шаблон вида `"%s ..."`) не трогаем вовсе: в реальных вызовах + # этого кодбейза секрет+query-контекст лежат САМОДОСТАТОЧНО внутри одного + # аргумента (например body_preview в app/services/dadata.py), а не расщеплены + # между текстом шаблона и голым значением — трогать msg тут не нужно и опасно + # (шаблонный `%s` сам по себе мог бы ложно совпасть с чувствительным именем + # параметра прямо перед ним). + scrubbed_args = tuple( + scrub_query_secrets(a) if isinstance(a, str) else a for a in args + ) + if scrubbed_args != args: + record.args = scrubbed_args + elif isinstance(record.msg, str): + # Args нет — вся запись уже готовым текстом в msg (f-string и т.п.). + scrubbed_msg = scrub_query_secrets(record.msg) + if scrubbed_msg != record.msg: + record.msg = scrubbed_msg + return True +# ── Секреты в произвольном тексте (тело ответа внешнего API) — #3471 ────────── +# +# DaData на HTTP 403 возвращает диагностику вида: +# "Feature 'CLEAN' disabled for token '<действующий 40-символьный токен>'. See ..." +# body_preview из этого текста уходит в WARNING/ERROR лог (app/services/dadata.py) → +# docker logs → потенциально breadcrumb к любой последующей ошибке в GlitchTip. +# Маскируем ДО логирования. Не завязываемся на конкретную формулировку вендора — +# она может измениться (см. generic-слой ниже). + +_TOKEN_QUOTED = re.compile(r"(\btoken\s*['\"])([^'\"]+)(['\"])", re.IGNORECASE) +# Любая hex/base64-подобная последовательность 24+ символов — ловит секрет независимо +# от контекста (Authorization/X-Secret значения, если когда-нибудь попадут в текст как есть). +_LONG_SECRET_LIKE = re.compile(r"[A-Za-z0-9+/_-]{24,}") + + +def _mask_value(value: str) -> str: + """`8d4e…(40)` — первые 4 символа + длина в скобках, остальное скрыто.""" + if len(value) <= 4: + return "***" + return f"{value[:4]}…({len(value)})" + + +def scrub_body_secrets(text: str | None) -> str: + """Маскирует токены/секреты в произвольном тексте (тело ответа внешнего API и т.п.). + + Двухслойно: 1) явный ``token ''`` (текущая формулировка DaData на 403), + 2) generic — любая hex/base64-подобная последовательность 24+ символов, чтобы защита + не зависела от того, как вендор сформулирует сообщение завтра. + """ + if not text: + return text or "" + + def _replace_quoted(m: re.Match[str]) -> str: + return f"{m.group(1)}{_mask_value(m.group(2))}{m.group(3)}" + + scrubbed = _TOKEN_QUOTED.sub(_replace_quoted, text) + scrubbed = _LONG_SECRET_LIKE.sub(lambda m: _mask_value(m.group(0)), scrubbed) + return scrubbed + + def install_query_secret_filter(*logger_names: str) -> None: """Вешает фильтр на access-лог uvicorn И на обработчики корневого логгера. diff --git a/tradein-mvp/backend/app/services/dadata.py b/tradein-mvp/backend/app/services/dadata.py index 7c581c22..030d887d 100644 --- a/tradein-mvp/backend/app/services/dadata.py +++ b/tradein-mvp/backend/app/services/dadata.py @@ -29,6 +29,7 @@ from typing import Any import httpx from app.core.config import settings +from app.core.log_scrub import scrub_body_secrets logger = logging.getLogger(__name__) @@ -173,7 +174,7 @@ async def clean_address(address: str) -> DadataAddressResult | None: logger.warning("dadata: HTTP 429 — quota exceeded (100/день demo limit?)") return None if status in (401, 403): - body_preview = (response.text or "")[:200] + body_preview = scrub_body_secrets(response.text)[:200] # 403 «Feature 'CLEAN' disabled for token …» ≠ отклонённый токен: токен валиден, # но услуга «Стандартизация» (CLEAN) не подключена на аккаунте. Refresh токена НЕ # поможет — нужно включить услугу в кабинете DaData ИЛИ полагаться на suggest-fallback @@ -213,7 +214,7 @@ async def clean_address(address: str) -> DadataAddressResult | None: logger.warning("dadata: HTTP %d — transient server error", status) return None if status >= 400: - body_preview = (response.text or "")[:200] + body_preview = scrub_body_secrets(response.text)[:200] logger.warning("dadata: HTTP %d — bad request: %r", status, body_preview) return None @@ -436,7 +437,7 @@ async def suggest_addresses( logger.warning("dadata suggest: HTTP %d — transient server error", status) return [] if status >= 400: - body_preview = (response.text or "")[:200] + body_preview = scrub_body_secrets(response.text)[:200] logger.warning("dadata suggest: HTTP %d — bad request: %r", status, body_preview) return [] diff --git a/tradein-mvp/backend/tests/services/test_dadata.py b/tradein-mvp/backend/tests/services/test_dadata.py index a7670fc8..5e3989ab 100644 --- a/tradein-mvp/backend/tests/services/test_dadata.py +++ b/tradein-mvp/backend/tests/services/test_dadata.py @@ -829,6 +829,46 @@ async def test_clean_address_throttles_repeated_feature_disabled_warning(caplog) assert dadata._clean_disabled_warned is True +# Вымышленный токен ТОЙ ЖЕ формы, что настоящий DaData API-ключ (40 hex-символов) — НЕ +# реальный секрет. Прод-факт: DaData на 403 кладёт действующий токен в тело ответа +# открытым текстом, и body_preview копирует его в WARNING/ERROR лог как есть (#3471). +FAKE_LEAKED_TOKEN = "deadbeef1234deadbeef1234deadbeef12345678" + +CLEAN_TOKEN_LEAK_BODY = { + "timestamp": "2026-09-13T10:00:00.000+00:00", + "status": 403, + "error": "Forbidden", + "message": ( + f"Feature 'CLEAN' disabled for token '{FAKE_LEAKED_TOKEN}'. " + "See https://dadata.userecho.com/topics/7784 for help." + ), + "path": "/api/v1/clean/address", +} + + +async def test_clean_address_masks_token_in_feature_disabled_log(caplog) -> None: + """403 body в реалистичной прод-форме (40-символьный токен) — токен НЕ должен светиться в логе. + + Отличие от test_clean_address_logs_feature_disabled_distinctly: тот тест использует + укороченный токен 'xxx' и не проверяет утечку. Здесь — токен длины настоящего DaData-ключа, + именно такая форма ушла в docker logs на проде (#3471). + """ + from app.services import dadata + + dadata._clean_disabled_warned = False # изоляция от порядка тестов (module-level throttle) + + transport = _mock_transport_returning(403, CLEAN_TOKEN_LEAK_BODY) + with _patch_settings(), _patch_async_client(transport): + with caplog.at_level(_logging.WARNING, logger="app.services.dadata"): + result = await dadata.clean_address("Екатеринбург, Малышева 4") + + assert result is None + text = caplog.text + assert FAKE_LEAKED_TOKEN not in text, "токен утёк в лог-запись открытым текстом" + # Диагностика (какая услуга выключена) обязана сохраниться несмотря на маскирование. + assert "Стандартизация" in text or "выключена" in text + + async def test_clean_address_logs_real_auth_rejection_as_auth(caplog) -> None: """401 (или 403 без 'disabled') → сообщение про креды.""" from app.services import dadata diff --git a/tradein-mvp/backend/tests/test_3154_query_secret_scrub.py b/tradein-mvp/backend/tests/test_3154_query_secret_scrub.py index e5c7c10e..68af6523 100644 --- a/tradein-mvp/backend/tests/test_3154_query_secret_scrub.py +++ b/tradein-mvp/backend/tests/test_3154_query_secret_scrub.py @@ -64,7 +64,14 @@ def test_uvicorn_access_line_masks_secret_query_param() -> None: def test_app_logger_via_root_handler_masks_secret() -> None: - """Фильтр стоит и на handler'ах корня — прикладные логгеры тоже закрыты.""" + """Фильтр стоит и на handler'ах корня — прикладные логгеры тоже закрыты. + + Секрет + query-контекст (`?token=...`) передаются ОДНИМ %s-аргументом — как реально + устроены вызовы в этом кодбейзе (см. body_preview в app/services/dadata.py), а не + расщеплены между msg-шаблоном и голым значением в args. Фильтр (#3471) скрабит + ЭЛЕМЕНТЫ `record.args` по отдельности, не трогая arity/`record.msg`-шаблон — поэтому + секрет обязан быть самодостаточным (с контекстом) внутри одного аргумента. + """ stream = io.StringIO() handler = logging.StreamHandler(stream) handler.setFormatter(logging.Formatter("%(message)s")) @@ -73,7 +80,7 @@ def test_app_logger_via_root_handler_masks_secret() -> None: root.addHandler(handler) try: logging.getLogger("app.some.module").warning( - "retry callback https://gendsgn.ru/hook?token=%s", _SECRET + "retry callback %s", f"https://gendsgn.ru/hook?token={_SECRET}" ) finally: root.removeHandler(handler) @@ -133,3 +140,46 @@ def test_install_is_idempotent() -> None: install_query_secret_filter("uvicorn.access") filters = logging.getLogger("uvicorn.access").filters assert sum(isinstance(f, QuerySecretFilter) for f in filters) == 1, filters + + +def test_uvicorn_access_formatter_survives_secret_scrub() -> None: + """Прод-баг: скраб секрета в access-логе ронял сам процесс логирования (docker logs). + + `uvicorn.logging.AccessFormatter.formatMessage()` распаковывает `record.args` НАПРЯМУЮ + как 5-tuple (`client_addr, method, full_path, http_version, status_code = record.args`), + в обход `record.getMessage()`. Старая реализация фильтра при найденном секрете обнуляла + `record.args = ()` → `ValueError: not enough values to unpack (expected 5, got 0)` → + `--- Logging error ---` в docker-логах ТОЛЬКО в момент, когда фильтр пытался защитить + секрет (см. трассу через starlette/middleware/errors.py `_send` — это просто цепочка + вложенных ASGI `send()`, ведущая к access-log вызову внутри uvicorn). + """ + from uvicorn.logging import AccessFormatter + + stream = io.StringIO() + handler = logging.StreamHandler(stream) + handler.setFormatter(AccessFormatter("%(client_addr)s - %(request_line)s %(status_code)s")) + logger = logging.getLogger("uvicorn.access.formatter_test") + logger.addHandler(handler) + logger.setLevel(logging.INFO) + logger.propagate = False + install_query_secret_filter("uvicorn.access.formatter_test") + try: + # НЕ должно бросить ValueError при обработке handler'ом (падение уходит в + # handleError → stderr, а не наверх — поэтому проверяем результат, а не raises). + logger.info( + '%s - "%s %s HTTP/%s" %d', + "172.18.0.3:60322", + "POST", + f"/api/v1/trade-in/ops/glitchtip-webhook?secret={_SECRET}", + "1.1", + 200, + ) + finally: + logger.removeHandler(handler) + logger.filters.clear() + + out = stream.getvalue() + assert out, "форматтер не выдал ни строки — запись эмита провалилась (см. handleError)" + assert _SECRET not in out, out + assert "secret=***" in out, out + assert "200" in out and "POST" in out -- 2.45.3