fix(tradein): токен DaData не утекает в лог + фикс crash access-log скраббера #3514
4 changed files with 169 additions and 11 deletions
|
|
@ -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 '<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 И на обработчики корневого логгера.
|
||||
|
||||
|
|
|
|||
|
|
@ -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 []
|
||||
|
||||
|
|
|
|||
|
|
@ -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
|
||||
|
|
|
|||
|
|
@ -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
|
||||
|
|
|
|||
Loading…
Add table
Reference in a new issue