test(tradein/auth): флаки-замер «< 500 мс» заменён проверкой механизма — bcrypt обязан исполняться вне потока event loop #3350

Merged
bot-backend merged 2 commits from fix/3343-auth-latency-flaky into main 2026-09-05 18:14:40 +00:00
Showing only changes of commit ecd6d5c91d - Show all commits

View file

@ -35,6 +35,7 @@ import asyncio
import logging import logging
import os import os
import re import re
import threading
import time import time
from datetime import UTC, datetime, timedelta from datetime import UTC, datetime, timedelta
from types import SimpleNamespace from types import SimpleNamespace
@ -763,14 +764,19 @@ async def test_login_flood_capped_by_rate_while_api_stays_responsive(
app = _build_test_app(store) app = _build_test_app(store)
attempts: list[float] = [] attempts: list[float] = []
verify_threads: set[int] = set()
def _slow_verify(plain: str, hashed: str) -> bool: def _slow_verify(plain: str, hashed: str) -> bool:
"""Стенд-двойник bcrypt: столько же БЛОКИРУЮЩЕГО времени, только меньше. """Стенд-двойник bcrypt: столько же БЛОКИРУЮЩЕГО времени, только меньше.
Блокирующий `time.sleep`, а не `await` суть проблемы в том, что bcrypt Блокирующий `time.sleep`, а не `await` суть проблемы в том, что bcrypt
не отпускает поток; двойник с `await` проверял бы не то. не отпускает поток; двойник с `await` проверял бы не то.
Заодно записывает ПОТОК исполнения: это и есть механизм выноса (#3343) —
величина дискретная, от загрузки раннера не зависящая.
""" """
attempts.append(time.monotonic()) attempts.append(time.monotonic())
verify_threads.add(threading.get_ident())
time.sleep(verify_s) time.sleep(verify_s)
return False return False
@ -824,19 +830,38 @@ async def test_login_flood_capped_by_rate_while_api_stays_responsive(
# Проверяется ПЕРВЫМ: если цикл занят, встаёт и сам флуд, и тогда # Проверяется ПЕРВЫМ: если цикл занят, встаёт и сам флуд, и тогда
# остальные числа мерят не потолок, а паралич — их надо читать после # остальные числа мерят не потолок, а паралич — их надо читать после
# этого вердикта, а не вместо него. # этого вердикта, а не вместо него.
assert probe_latencies, "проба не сделала ни одного запроса" #
# Вердикт — про МЕХАНИЗМ, а не про секундомер (#3343). Раньше здесь стоял
# абсолютный порог латентности пробы (`худший < 500мс`, `медиана < 50мс`).
# На общем раннере он мерил не свойство кода, а свободен ли CPU у соседей:
# 03.09 деплой встал на «худший сторонний запрос 544мс» ровно на том
# коммите, который часом раньше прошёл на незанятой машине. Порог, который
# краснеет от чужой параллельной сборки, не отличает поломку от нагрузки,
# а красный обязан значить «значение неверно», иначе его начинают
# переспрашивать. Обе замены переживают любую загрузку:
# - ПОТОК, в котором исполнилась сверка, — величина дискретная. Вернись
# bcrypt в `async def` — здесь окажется поток цикла, и никакой простой
# раннера этого не замаскирует и не подделает;
# - ТИКИ пробы: цикл с bcrypt внутри стоит практически всю секунду
# флуда (сверки идут подряд по 50мс), и проба не успевает почти
# никогда; при выносе в пул она просыпается раз в 10мс, то есть ~100
# раз. Порог 10 лежит в середине этого разрыва с запасом ×10 в обе
# стороны — на общем раннере съедается пропускная способность, но не
# порядок величины.
# Сами латентности остаются в сообщении как ДИАГНОСТИКА: числа полезны,
# когда тест красный, и не годятся в вердикт, пока машина общая.
assert verify_threads, "ни одной сверки пароля не состоялось — мерить нечего"
assert threading.get_ident() not in verify_threads, (
"сверка пароля исполнилась в потоке событийного цикла — bcrypt держит весь "
"API на всё время проверки (вынос в пул из #2665 отменён)"
)
assert probe_latencies, "проба не сделала ни одного запроса — цикл был занят"
probe_latencies.sort() probe_latencies.sort()
assert probe_latencies[-1] < 0.5, (
f"худший сторонний запрос {probe_latencies[-1] * 1000:.0f}мс — API встаёт под флудом входа"
)
median_probe = probe_latencies[len(probe_latencies) // 2] median_probe = probe_latencies[len(probe_latencies) // 2]
assert median_probe < verify_s, (
f"медиана стороннего запроса {median_probe * 1000:.0f}мс ≥ времени одной "
f"сверки — цикл занят проверкой пароля, API стоит"
)
# Мало проб за секунду — тоже занятый цикл: проба просыпается раз в 10мс.
assert len(probe_latencies) >= 10, ( assert len(probe_latencies) >= 10, (
f"проба успела всего {len(probe_latencies)} раз за {elapsed:.2f}с — цикл был занят" f"проба успела всего {len(probe_latencies)} раз за {elapsed:.2f}с "
f"(медиана {median_probe * 1000:.0f}мс, худший {probe_latencies[-1] * 1000:.0f}мс) "
f"— цикл был занят"
) )
# 2. ТЕМП ограничен. Флуд предлагал больше попыток в секунду, чем разрешает # 2. ТЕМП ограничен. Флуд предлагал больше попыток в секунду, чем разрешает