Merge pull request 'test(tradein/auth): флаки-замер «< 500 мс» заменён проверкой механизма — bcrypt обязан исполняться вне потока event loop' (#3350) from fix/3343-auth-latency-flaky into main

tradein-mvp/backend/tests/test_auth_api.py

@@ -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. ТЕМП ограничен. Флуд предлагал больше попыток в секунду, чем разрешает