From ecd6d5c91de1544f4bc8d284cf544e5b3a45d6bd Mon Sep 17 00:00:00 2001 From: bot-backend Date: Sat, 5 Sep 2026 22:48:37 +0500 Subject: [PATCH 1/2] =?UTF-8?q?test(auth):=20=D0=BF=D1=80=D0=BE=D0=B2?= =?UTF-8?q?=D0=B5=D1=80=D1=8F=D1=82=D1=8C=20=D0=B2=D1=8B=D0=BD=D0=BE=D1=81?= =?UTF-8?q?=20bcrypt=20=D0=BC=D0=B5=D1=85=D0=B0=D0=BD=D0=B8=D0=B7=D0=BC?= =?UTF-8?q?=D0=BE=D0=BC,=20=D0=B0=20=D0=BD=D0=B5=20=D1=81=D0=B5=D0=BA?= =?UTF-8?q?=D1=83=D0=BD=D0=B4=D0=BE=D0=BC=D0=B5=D1=80=D0=BE=D0=BC?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `probe_latencies[-1] < 0.5` мерил на общем раннере не свойство кода, а свободен ли CPU у соседей: 03.09 деплой Trade-In встал на «худший сторонний запрос 544мс» на коммите, который часом раньше прошёл на незанятой машине (#3343). Тест из #2712 проверял правильную вещь неправильной метрикой. Вердикт теперь дискретный: сверка пароля обязана исполниться НЕ в потоке событийного цикла (двойник bcrypt пишет `threading.get_ident()`). Загрузка раннера этого не подделает. Второй половиной остаётся счётчик тиков пробы: при bcrypt в `async def` цикл стоит всю секунду флуда и проба не успевает почти никогда, при выносе в пул успевает ~100 — порог 10 лежит посередине с запасом ×10 в обе стороны. Абсолютные латентности сохранены в тексте падения как диагностика, но не гейтят. Фальсификация: возврат `verify_password` из пула прямо в `async def` роняет тест на новом утверждении («сверка пароля исполнилась в потоке событийного цикла», `assert 8387963968 not in {8387963968}`), 5 прогонов подряд под load average 24 — зелёные. Closes #3343 --- tradein-mvp/backend/tests/test_auth_api.py | 45 +++++++++++++++++----- 1 file changed, 35 insertions(+), 10 deletions(-) diff --git a/tradein-mvp/backend/tests/test_auth_api.py b/tradein-mvp/backend/tests/test_auth_api.py index 9436d1f7..ab5c5880 100644 --- a/tradein-mvp/backend/tests/test_auth_api.py +++ b/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 @@ -763,14 +764,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 @@ -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() - assert probe_latencies[-1] < 0.5, ( - f"худший сторонний запрос {probe_latencies[-1] * 1000:.0f}мс — API встаёт под флудом входа" - ) 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}с — цикл был занят" + f"проба успела всего {len(probe_latencies)} раз за {elapsed:.2f}с " + f"(медиана {median_probe * 1000:.0f}мс, худший {probe_latencies[-1] * 1000:.0f}мс) " + f"— цикл был занят" ) # 2. ТЕМП ограничен. Флуд предлагал больше попыток в секунду, чем разрешает -- 2.45.3 From cd95222d90556ebe6aba695430d62290a1102749 Mon Sep 17 00:00:00 2001 From: bot-backend Date: Sat, 5 Sep 2026 23:06:35 +0500 Subject: [PATCH 2/2] =?UTF-8?q?test(auth):=20=D0=BF=D0=BE=D1=80=D0=BE?= =?UTF-8?q?=D0=B3=20=D0=BF=D1=80=D0=BE=D0=B1=D1=8B=20=D0=BF=D0=BE=20=D1=82?= =?UTF-8?q?=D0=B5=D0=BC=D0=BF=D1=83=20=D1=82=D0=B8=D0=BA=D0=BE=D0=B2,=20?= =?UTF-8?q?=D0=B4=D0=B8=D0=B0=D0=B3=D0=BD=D0=BE=D1=81=D1=82=D0=B8=D0=BA?= =?UTF-8?q?=D0=B0=20=D0=B2=20=D0=BB=D0=BE=D0=B3=20CI?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Абсолютное `len(probe_latencies) >= 10` слабело ровно в целевом сценарии: elapsed под нагрузкой растёт, и заблокированный цикл добирает 10 тиков за 3-5с. Сверяем темп: замер пул 65.5-66.3 тик/с против 1.0 тик/с у bcrypt в `async def`, порог 8.0 — геометрическая середина, запас x8 в обе стороны. Тики/медиану/темп печатаем безусловно через capsys.disabled(): у зелёного теста pytest захваченный вывод не показывает, а запас на общем раннере виден только когда всё прошло. --- tradein-mvp/backend/tests/test_auth_api.py | 54 ++++++++++++++++------ 1 file changed, 41 insertions(+), 13 deletions(-) diff --git a/tradein-mvp/backend/tests/test_auth_api.py b/tradein-mvp/backend/tests/test_auth_api.py index ab5c5880..8051796a 100644 --- a/tradein-mvp/backend/tests/test_auth_api.py +++ b/tradein-mvp/backend/tests/test_auth_api.py @@ -723,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 продолжает отвечать. @@ -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] 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` # сторонний запрос ждёт столько, сколько длится очередь сверок. @@ -842,12 +870,14 @@ async def test_login_flood_capped_by_rate_while_api_stays_responsive( # - ПОТОК, в котором исполнилась сверка, — величина дискретная. Вернись # bcrypt в `async def` — здесь окажется поток цикла, и никакой простой # раннера этого не замаскирует и не подделает; - # - ТИКИ пробы: цикл с bcrypt внутри стоит практически всю секунду - # флуда (сверки идут подряд по 50мс), и проба не успевает почти - # никогда; при выносе в пул она просыпается раз в 10мс, то есть ~100 - # раз. Порог 10 лежит в середине этого разрыва с запасом ×10 в обе - # стороны — на общем раннере съедается пропускная способность, но не - # порядок величины. + # - ТЕМП тиков пробы: цикл с bcrypt внутри стоит практически всю + # секунду флуда (сверки идут подряд по 50мс), и проба не успевает + # почти никогда; при выносе в пул она просыпается раз в 10мс. + # Сверяется именно ТЕМП (тик/с), а не число тиков: `elapsed` под + # нагрузкой растёт, и абсолютный порог «>= 10 тиков» заблокированный + # цикл наберёт за 3-5с — то есть абсолютный ассерт слабеет ровно в + # целевом сценарии. Порог MIN_PROBE_TICKS_PER_S — геометрическая + # середина между замерами, см. константу. # Сами латентности остаются в сообщении как ДИАГНОСТИКА: числа полезны, # когда тест красный, и не годятся в вердикт, пока машина общая. assert verify_threads, "ни одной сверки пароля не состоялось — мерить нечего" @@ -856,12 +886,10 @@ async def test_login_flood_capped_by_rate_while_api_stays_responsive( "API на всё время проверки (вынос в пул из #2665 отменён)" ) assert probe_latencies, "проба не сделала ни одного запроса — цикл был занят" - probe_latencies.sort() - median_probe = probe_latencies[len(probe_latencies) // 2] - assert len(probe_latencies) >= 10, ( - f"проба успела всего {len(probe_latencies)} раз за {elapsed:.2f}с " - f"(медиана {median_probe * 1000:.0f}мс, худший {probe_latencies[-1] * 1000:.0f}мс) " - f"— цикл был занят" + 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. ТЕМП ограничен. Флуд предлагал больше попыток в секунду, чем разрешает -- 2.45.3