test(tradein/auth): флаки-замер «< 500 мс» заменён проверкой механизма — bcrypt обязан исполняться вне потока event loop #3350
1 changed files with 66 additions and 13 deletions
|
|
@ -35,6 +35,7 @@ import asyncio
|
|||
import logging
|
||||
import os
|
||||
import re
|
||||
import threading
|
||||
import time
|
||||
from datetime import UTC, datetime, timedelta
|
||||
from types import SimpleNamespace
|
||||
|
|
@ -722,9 +723,21 @@ def test_failed_login_events_reach_audit_with_counter_state(
|
|||
# #2665 — настоящий потолок ТЕМПА проверок пароля + свободный событийный цикл
|
||||
# ---------------------------------------------------------------------------
|
||||
|
||||
# Порог ТЕМПА пробы (тик/с) для #3343. Не «сколько раз», а «как часто»: `elapsed`
|
||||
# под нагрузкой растёт, поэтому абсолютное «>= 10 тиков» заблокированный цикл
|
||||
# наберёт за 3-5с — прежний ассерт слабел ровно в том сценарии, ради которого
|
||||
# написан. Замеры (macOS, 2026-09-05, три прогона каждый):
|
||||
# пул (`asyncio.to_thread`, как в проде) — 65.5 / 65.6 / 66.3 тик/с;
|
||||
# bcrypt прямо в `async def` (`return verify_password(...)` в
|
||||
# `verify_password_bounded`) — 1.0 тик/с (6 тиков за 5.74с; заметь: старый
|
||||
# порог «>= 10» на чуть более медленной машине эти 10 тиков добрал бы).
|
||||
# Порог — геометрическая середина: sqrt(65.5 * 1.0) ≈ 8, то есть запас ×8 в обе
|
||||
# стороны. Общий раннер отъедает пропускную способность, но не порядок величины.
|
||||
MIN_PROBE_TICKS_PER_S = 8.0
|
||||
|
||||
|
||||
async def test_login_flood_capped_by_rate_while_api_stays_responsive(
|
||||
store: _Store, monkeypatch: pytest.MonkeyPatch
|
||||
store: _Store, monkeypatch: pytest.MonkeyPatch, capsys: pytest.CaptureFixture[str]
|
||||
) -> None:
|
||||
"""Сто одновременных соединений не получают больше N попыток В СЕКУНДУ, и при
|
||||
этом остальной API продолжает отвечать.
|
||||
|
|
@ -763,14 +776,19 @@ async def test_login_flood_capped_by_rate_while_api_stays_responsive(
|
|||
app = _build_test_app(store)
|
||||
|
||||
attempts: list[float] = []
|
||||
verify_threads: set[int] = set()
|
||||
|
||||
def _slow_verify(plain: str, hashed: str) -> bool:
|
||||
"""Стенд-двойник bcrypt: столько же БЛОКИРУЮЩЕГО времени, только меньше.
|
||||
|
||||
Блокирующий `time.sleep`, а не `await` — суть проблемы в том, что bcrypt
|
||||
не отпускает поток; двойник с `await` проверял бы не то.
|
||||
|
||||
Заодно записывает ПОТОК исполнения: это и есть механизм выноса (#3343) —
|
||||
величина дискретная, от загрузки раннера не зависящая.
|
||||
"""
|
||||
attempts.append(time.monotonic())
|
||||
verify_threads.add(threading.get_ident())
|
||||
time.sleep(verify_s)
|
||||
return False
|
||||
|
||||
|
|
@ -818,25 +836,60 @@ async def test_login_flood_capped_by_rate_while_api_stays_responsive(
|
|||
|
||||
codes = [c for lst in code_lists for c in lst]
|
||||
attempts_per_s = len(attempts) / elapsed
|
||||
probe_latencies.sort()
|
||||
probe_ticks_per_s = len(probe_latencies) / elapsed
|
||||
median_probe = probe_latencies[len(probe_latencies) // 2] if probe_latencies else float("nan")
|
||||
worst_probe = probe_latencies[-1] if probe_latencies else float("nan")
|
||||
|
||||
# Печать ДО первого утверждения и МИМО перехвата: захваченный вывод зелёного
|
||||
# теста pytest не показывает (CI гоняет `uv run pytest -q -rs`), а запас на
|
||||
# общем раннере интересен ровно когда всё прошло. Выше assert'ов — намеренно:
|
||||
# на сломанной системе иначе не осталось бы и диагностики.
|
||||
with capsys.disabled():
|
||||
print(
|
||||
f"[#3343] проба {len(probe_latencies)} тиков за {elapsed:.2f}с = "
|
||||
f"{probe_ticks_per_s:.1f} тик/с (порог {MIN_PROBE_TICKS_PER_S} тик/с), медиана "
|
||||
f"{median_probe * 1000:.0f}мс, худший {worst_probe * 1000:.0f}мс; сверок "
|
||||
f"{len(attempts)} = {attempts_per_s:.0f}/с при потолке {ceiling_per_s:.0f}/с"
|
||||
)
|
||||
|
||||
# 1. Событийный цикл СВОБОДЕН всё это время. С bcrypt внутри `async def`
|
||||
# сторонний запрос ждёт столько, сколько длится очередь сверок.
|
||||
# Проверяется ПЕРВЫМ: если цикл занят, встаёт и сам флуд, и тогда
|
||||
# остальные числа мерят не потолок, а паралич — их надо читать после
|
||||
# этого вердикта, а не вместо него.
|
||||
assert probe_latencies, "проба не сделала ни одного запроса"
|
||||
probe_latencies.sort()
|
||||
assert probe_latencies[-1] < 0.5, (
|
||||
f"худший сторонний запрос {probe_latencies[-1] * 1000:.0f}мс — API встаёт под флудом входа"
|
||||
#
|
||||
# Вердикт — про МЕХАНИЗМ, а не про секундомер (#3343). Раньше здесь стоял
|
||||
# абсолютный порог латентности пробы (`худший < 500мс`, `медиана < 50мс`).
|
||||
# На общем раннере он мерил не свойство кода, а свободен ли CPU у соседей:
|
||||
# 03.09 деплой встал на «худший сторонний запрос 544мс» ровно на том
|
||||
# коммите, который часом раньше прошёл на незанятой машине. Порог, который
|
||||
# краснеет от чужой параллельной сборки, не отличает поломку от нагрузки,
|
||||
# а красный обязан значить «значение неверно», иначе его начинают
|
||||
# переспрашивать. Обе замены переживают любую загрузку:
|
||||
# - ПОТОК, в котором исполнилась сверка, — величина дискретная. Вернись
|
||||
# bcrypt в `async def` — здесь окажется поток цикла, и никакой простой
|
||||
# раннера этого не замаскирует и не подделает;
|
||||
# - ТЕМП тиков пробы: цикл с bcrypt внутри стоит практически всю
|
||||
# секунду флуда (сверки идут подряд по 50мс), и проба не успевает
|
||||
# почти никогда; при выносе в пул она просыпается раз в 10мс.
|
||||
# Сверяется именно ТЕМП (тик/с), а не число тиков: `elapsed` под
|
||||
# нагрузкой растёт, и абсолютный порог «>= 10 тиков» заблокированный
|
||||
# цикл наберёт за 3-5с — то есть абсолютный ассерт слабеет ровно в
|
||||
# целевом сценарии. Порог MIN_PROBE_TICKS_PER_S — геометрическая
|
||||
# середина между замерами, см. константу.
|
||||
# Сами латентности остаются в сообщении как ДИАГНОСТИКА: числа полезны,
|
||||
# когда тест красный, и не годятся в вердикт, пока машина общая.
|
||||
assert verify_threads, "ни одной сверки пароля не состоялось — мерить нечего"
|
||||
assert threading.get_ident() not in verify_threads, (
|
||||
"сверка пароля исполнилась в потоке событийного цикла — bcrypt держит весь "
|
||||
"API на всё время проверки (вынос в пул из #2665 отменён)"
|
||||
)
|
||||
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, (
|
||||
f"проба успела всего {len(probe_latencies)} раз за {elapsed:.2f}с — цикл был занят"
|
||||
assert probe_latencies, "проба не сделала ни одного запроса — цикл был занят"
|
||||
assert probe_ticks_per_s >= MIN_PROBE_TICKS_PER_S, (
|
||||
f"проба тикала {probe_ticks_per_s:.1f} раз/с при пороге {MIN_PROBE_TICKS_PER_S} "
|
||||
f"({len(probe_latencies)} тиков за {elapsed:.2f}с, медиана "
|
||||
f"{median_probe * 1000:.0f}мс, худший {worst_probe * 1000:.0f}мс) — цикл был занят"
|
||||
)
|
||||
|
||||
# 2. ТЕМП ограничен. Флуд предлагал больше попыток в секунду, чем разрешает
|
||||
|
|
|
|||
Loading…
Add table
Reference in a new issue