test(auth): порог пробы по темпу тиков, диагностика в лог CI
All checks were successful
CI Trade-In / changes (pull_request) Successful in 14s
CI / changes (pull_request) Successful in 17s
CI Trade-In / browser-tests (pull_request) Has been skipped
CI Trade-In / frontend-checks (pull_request) Has been skipped
CI / backend-tests (pull_request) Has been skipped
CI / frontend-tests (pull_request) Has been skipped
CI / openapi-codegen-check (pull_request) Has been skipped
CI Trade-In / backend-tests (pull_request) Successful in 6m17s

Абсолютное `len(probe_latencies) >= 10` слабело ровно в целевом сценарии:
elapsed под нагрузкой растёт, и заблокированный цикл добирает 10 тиков за
3-5с. Сверяем темп: замер пул 65.5-66.3 тик/с против 1.0 тик/с у bcrypt в
`async def`, порог 8.0 — геометрическая середина, запас x8 в обе стороны.

Тики/медиану/темп печатаем безусловно через capsys.disabled(): у зелёного
теста pytest захваченный вывод не показывает, а запас на общем раннере виден
только когда всё прошло.
This commit is contained in:
bot-backend 2026-09-05 23:06:35 +05:00
parent ecd6d5c91d
commit cd95222d90

View file

@ -723,9 +723,21 @@ def test_failed_login_events_reach_audit_with_counter_state(
# #2665 — настоящий потолок ТЕМПА проверок пароля + свободный событийный цикл # #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( 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: ) -> None:
"""Сто одновременных соединений не получают больше N попыток В СЕКУНДУ, и при """Сто одновременных соединений не получают больше N попыток В СЕКУНДУ, и при
этом остальной API продолжает отвечать. этом остальной API продолжает отвечать.
@ -824,6 +836,22 @@ async def test_login_flood_capped_by_rate_while_api_stays_responsive(
codes = [c for lst in code_lists for c in lst] codes = [c for lst in code_lists for c in lst]
attempts_per_s = len(attempts) / elapsed 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` # 1. Событийный цикл СВОБОДЕН всё это время. С bcrypt внутри `async def`
# сторонний запрос ждёт столько, сколько длится очередь сверок. # сторонний запрос ждёт столько, сколько длится очередь сверок.
@ -842,12 +870,14 @@ async def test_login_flood_capped_by_rate_while_api_stays_responsive(
# - ПОТОК, в котором исполнилась сверка, — величина дискретная. Вернись # - ПОТОК, в котором исполнилась сверка, — величина дискретная. Вернись
# bcrypt в `async def` — здесь окажется поток цикла, и никакой простой # bcrypt в `async def` — здесь окажется поток цикла, и никакой простой
# раннера этого не замаскирует и не подделает; # раннера этого не замаскирует и не подделает;
# - ТИКИ пробы: цикл с bcrypt внутри стоит практически всю секунду # - ТЕМП тиков пробы: цикл с bcrypt внутри стоит практически всю
# флуда (сверки идут подряд по 50мс), и проба не успевает почти # секунду флуда (сверки идут подряд по 50мс), и проба не успевает
# никогда; при выносе в пул она просыпается раз в 10мс, то есть ~100 # почти никогда; при выносе в пул она просыпается раз в 10мс.
# раз. Порог 10 лежит в середине этого разрыва с запасом ×10 в обе # Сверяется именно ТЕМП (тик/с), а не число тиков: `elapsed` под
# стороны — на общем раннере съедается пропускная способность, но не # нагрузкой растёт, и абсолютный порог «>= 10 тиков» заблокированный
# порядок величины. # цикл наберёт за 3-5с — то есть абсолютный ассерт слабеет ровно в
# целевом сценарии. Порог MIN_PROBE_TICKS_PER_S — геометрическая
# середина между замерами, см. константу.
# Сами латентности остаются в сообщении как ДИАГНОСТИКА: числа полезны, # Сами латентности остаются в сообщении как ДИАГНОСТИКА: числа полезны,
# когда тест красный, и не годятся в вердикт, пока машина общая. # когда тест красный, и не годятся в вердикт, пока машина общая.
assert verify_threads, "ни одной сверки пароля не состоялось — мерить нечего" assert verify_threads, "ни одной сверки пароля не состоялось — мерить нечего"
@ -856,12 +886,10 @@ async def test_login_flood_capped_by_rate_while_api_stays_responsive(
"API на всё время проверки (вынос в пул из #2665 отменён)" "API на всё время проверки (вынос в пул из #2665 отменён)"
) )
assert probe_latencies, "проба не сделала ни одного запроса — цикл был занят" assert probe_latencies, "проба не сделала ни одного запроса — цикл был занят"
probe_latencies.sort() assert probe_ticks_per_s >= MIN_PROBE_TICKS_PER_S, (
median_probe = probe_latencies[len(probe_latencies) // 2] f"проба тикала {probe_ticks_per_s:.1f} раз/с при пороге {MIN_PROBE_TICKS_PER_S} "
assert len(probe_latencies) >= 10, ( f"({len(probe_latencies)} тиков за {elapsed:.2f}с, медиана "
f"проба успела всего {len(probe_latencies)} раз за {elapsed:.2f}с " f"{median_probe * 1000:.0f}мс, худший {worst_probe * 1000:.0f}мс) — цикл был занят"
f"(медиана {median_probe * 1000:.0f}мс, худший {probe_latencies[-1] * 1000:.0f}мс) "
f"— цикл был занят"
) )
# 2. ТЕМП ограничен. Флуд предлагал больше попыток в секунду, чем разрешает # 2. ТЕМП ограничен. Флуд предлагал больше попыток в секунду, чем разрешает