fix(tradein): токен DaData не утекает в лог, скраббер больше не ломает access-log (#3514)

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()
+        args = record.args
-        scrubbed = scrub_query_secrets(message)
+        if isinstance(args, tuple) and args:
-        if scrubbed != message:
+            # Есть позиционные args — скрабим КАЖДЫЙ элемент отдельно, arity не трогаем.
-            record.msg = scrubbed
+            # `record.msg` (шаблон вида `"%s ..."`) не трогаем вовсе: в реальных вызовах
-            record.args = ()
+            # этого кодбейза секрет+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 '<value>'`` (текущая формулировка 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 И на обработчики корневого логгера.
 

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 []
 

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

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