Skip to content

_fix_tg_delivery.md

Latest commit

 

History

History
379 lines (312 loc) · 29.3 KB

_fix_tg_delivery.md

File metadata and controls

379 lines (312 loc) · 29.3 KB
Raw

Лан: устойчивость доставки в assistant.py

Файлы во владении: assistant.py, test_tg_delivery.py (создан). Вспомогательные замеры: _measure_tgdelivery.py, _measure_callback_gap.py (попадают под .gitignore:79 _measure_*.py, в diff их не будет — числа ниже).

Копии assistant.py и скрипт диверсий из дерева УДАЛЕНЫ: файл, который перезаписывает боевой assistant.py, — это ровно авария 28 июля 2026 (patch_assistant.py), и оставлять такой в дереве нельзя. Каждая диверсия ниже описана точной заменой, поэтому воспроизводима без скрипта. После каждой восстановление сверялось по md5; итоговый файл — 5724549d85...(md5, укорочен).

Базовая линия ДО правок (все зелёные, красных не было)

Прогон до единого изменения — чтобы потом не приписать себе чужой цвет:

набор PASSED FAILED
test_tg_safety.py 131 0
test_flood_discipline.py 35 0
test_silence_all_paths.py 21 0
test_validator_coverage.py 24 0
test_summary_delivery.py 41 0
test_group_quiz.py 28 0
test_thread_dedupe.py 55 0
test_passive_gate.py 19 0
test_group_summary.py 20 0

Ни один из восьми названных наборов до меня красным НЕ был.

Замеры на живых данных

python _measure_tgdelivery.py:

  • Обрыв связи — доминирующий отказ, подтверждён. Server closed the connection: 51542 в bot.log.1 + 181 в bot.log = 51723. Attempt N at connecting failed: 2447 + 26. ConnectionAbortedError 1205, TimeoutError 1240 + 50, Telegram is having internal issues 51. Flood в журналах не доминирует.
  • Ни одной отправки под сроком. В assistant.py 100 вызовов Telegram API (по регулярному выражению на send_message|edit_message|delete_messages|get_messages| get_me|send_file|pin_message|get_permissions|get_entity|iter_messages|download_media), из них под asyncio.wait_for — 2, и оба это скачивание медиа. tg_safety. встречается 6 раз, но все шесть — classify()/flood_wait_seconds() в путях пингов. tg_safety.guard в assistant.py не был подключён нигде.
  • Верхняя граница зависания — из конфигурации клиента, а не из догадки. main.py:900-910: timeout=30, request_retries=10, connection_retries=1000, retry_delay=5, flood_sleep_threshold=TELETHON_FLOOD_SLEEP_THRESHOLD=20 (main.py:883). То есть один await bot_client.edit_message(...) без границы расходует до 10 x (30 + 20) = 500 с, а на переподключении — до 1000 x 5 с. Всё это время наверху не срабатывает ничего: см. следующий пункт.
  • Родительского дедлайна на пути сводки НЕТ. handle_group_summary зовётся ровно из одного места (main.py:2084) по цепочке runtime_guard.create_task(run_assistant_safe()) -> run_group_features(). runtime_guard.create_task (runtime_guard.py:404) — это голый asyncio.create_task без срока; слова wait_for в runtime_guard.py нет вовсе, и вокруг run_assistant_safe/run_group_features в main.py его тоже нет. Значит зависший edit_message висит бессрочно, а не «до родительского таймаута».

Честная оговорка про один замер, который НЕ получился

Я пытался измерить, сколько врач реально смотрит на крутящийся спиннер, по повторным доставкам callback (_measure_callback_gap.py). Вышло 50 строк skipping repeated callback id= в bot.log и 38 в bot_test.log — но все они на ОДНОМ и том же id 555001, то есть это тестовая выдумка, попавшая в боевой журнал (ровно та беда, которую описывает test_import_safety.py [6]), а не поведение врачей. Реальный интервал повторного нажатия по этим журналам измерить НЕЛЬЗЯ, и я его не заявляю. Число для Д3 выведено из конфигурации клиента, см. ниже.

Д1 (P1). Доставка готовой сводки без границы

Где. assistant.py:3941 — await bot_client.edit_message(chat_id, status_msg.id, final_text, parse_mode='html'). Это единственный путь, которым готовая сводка попадает врачу.

Последствие для врача. Сводка уже сгенерирована (заплачено за генерацию, timeout=90), врач держит перед собой сообщение «Собираю и анализирую историю обсуждения... Подождите». Если Telegram не отвечает, await висит до 500 с и дольше, сводка не уходит НИКОМУ, а в журнале об этом нет ни строки: except Exception ниже зависание не ловит (зависание — не исключение), и строка Successfully posted group summary просто не появляется.

Правка. Доставка идёт через tg_safety.edit_message (готовый модуль, 131 проверка в test_tg_safety.py), бюджет SUMMARY_DELIVERY_TIMEOUT_SECONDS = 90. Отказ теперь ЗВУЧИТ: tg_safety пишет WARNING tg give up op=... reason=..., а рядом добавлен WARNING про потерянную сводку. Три служебных edit_message того же обработчика (нет сообщений / ошибка генерации / неожиданная ошибка) тоже получили границу — иначе задача повисала бы навсегда на попытке сказать врачу, что ответа не будет.

Вложенность бюджета: почему 90 с влезает

  • Родительского срока нет вовсе (замер выше), поэтому 90 с не может его превысить — превышать нечего.
  • Внутри функции бюджеты идут последовательно, а не вложенно: generate_gemini_text_async(timeout=90) -> доставка 90 с. Худший случай пути 90 + 90 = 180 с, и никто сверху на 180 с не обрывает.
  • 90 с строго меньше внутреннего худшего случая telethon (500 с), поэтому граница РЕАЛЬНО срабатывает, а не является украшением.
  • 90 — не новое число: summarizer.TELEGRAM_SEND_TIMEOUT_SECONDS = 90 и tg_safety.DEFAULT_TIMEOUT_SECONDS = 90 (там прямо написано, что число согласовано). Второе число рядом разъехалось бы — это тот самый дефект, за которым следит test_budget_nesting.py.

Д2 (P2). get_me() на горячем пути под пустым except

Где. assistant.py:2069-2083, check_and_trigger_assistant_media: два await bot_client.get_me() (строки 2071 и 2079), каждый под except Exception: pass.

Последствие для врача. Врач отвечает на сообщение бота своим снимком или зовёт бота по имени. При отказе get_me (обрыв — 51723 события) оба флага остаются False, обращение считается ПАССИВНЫМ и попадает под 2-часовой кулдаун last_passive_media_run: снимок отбрасывается молча, врач не получает разбора и не узнаёт, что бот просто не разобрал, к кому обращались. В журнале — ни строки.

Правка. get_me() с горячего пути убран полностью. Личность бота берётся из BOT_ID/BOT_USERNAME (резолвятся один раз в resolve_bot_identity, assistant.py:191-207), с тем же догоняющим резолвом, что уже стоит в check_and_trigger_assistant:1524-1527. Пустой except заменён на разбор с записью в журнал.

Попутно найден и закрыт второй дефект в этих же строках. Старая проверка имени была bot_info.username.lower() in text.lower() — совпадение ПОДСТРОКОЙ без «@». Я сначала заменил её на f"@{BOT_USERNAME}" in text.lower(), а потом сверился с канонической проверкой проекта main.py:1150-1166 strip_bot_mention: там стоит rf"(?i)@{re.escape(name)}\b", то есть «@» И граница слова, и в докстринге прямо сказано почему — «@stomchat_bot_old» это ДРУГОЙ аккаунт. Мой вариант без границы принял бы его за обращение к нам и разобрал бы снимок, которого никто не просил. Итоговая проверка использует ту же регулярку с \b. Это тот же класс, что «рот» внутри «оборот».

Д3 (P2). 10 edit_message в handle_quiz_callback без границы

Где. assistant.py:4547-4888, десять bot_client.edit_message: строки 4575, 4595, 4634, 4650, 4661, 4678, 4694, 4708, 4730, 4762 (замер скриптом: ровно 10).

Механизм точнее, чем «не наступает finally». Спиннер снимает event.answer(), и он стоит СТРОКОЙ НИЖЕ каждого edit_message. Страховка в main.py:2306-2327 (answered = False ... finally: if not answered: await event.answer()) спасает только от ИСКЛЮЧЕНИЯ. При ЗАВИСАНИИ await handle_quiz_callback(...) не возвращается вообще, поэтому finally не наступает, event.answer() не уходит ни изнутри, ни из страховки — и кнопка у врача крутится, пока он не сдастся и не нажмёт ещё раз.

Правка. Все десять вызовов идут через tg_safety.edit_message с бюджетом CALLBACK_EDIT_TIMEOUT_SECONDS = 25. tg_safety.guard при исчерпании бюджета НЕ поднимает исключение, а возвращает TgOutcome(ok=False) — поэтому event.answer() строкой ниже ВСЁ РАВНО выполняется и спиннер снимается.

Почему 25 с, а не 90

  • Ветки взаимоисключающие (каждая кончается return), поэтому за одно нажатие тратится ОДИН бюджет, а не десять: 25 с, а не 250 с.
  • 25 = 20 + 5 = flood_sleep_threshold (main.py:883) + retry_delay (main.py:907). Короткий FloodWait telethon пересиживает сам внутри вызова, и меньший бюджет обрывал бы законное ожидание, которое вот-вот завершится; больший — оплачивал бы вторую и последующие из десяти внутренних попыток, ради которых врач смотрит на крутящуюся кнопку.
  • 25 < 60 (main.py:106 TELEGRAM_REQUEST_TIMEOUT_SECONDS, общий сетевой потолок проекта) и 25 < 90 (бюджет доставки сводки). Вложено в оба.
  • Против 500 с внутреннего худшего случая telethon это сокращение ожидания врача в 20 раз.

Что изменено в assistant.py

Место Было Стало
константы модуля — SUMMARY_DELIVERY_TIMEOUT_SECONDS = 90, CALLBACK_EDIT_TIMEOUT_SECONDS = 25
handle_group_summary (доставка сводки) await bot_client.edit_message(...) tg_safety.edit_message(...) + WARNING о потерянной сводке
handle_group_summary (3 служебных сообщения) без границы, одно под except: pass под границей; отказ последнего логируется, наружу не летит
check_and_trigger_assistant_media 2 x await bot_client.get_me() под except: pass BOT_ID/BOT_USERNAME + догоняющий резолв; отказ запроса родителя — WARNING
новая edit_callback_message — тонкая обёртка: tg_safety.edit_message с бюджетом кнопки
handle_quiz_callback 10 x bot_client.edit_message без границы 10 x edit_callback_message

check_and_trigger_assistant НЕ тронута (её тело разбирают по имени test_silence_all_paths.py:85 и test_validator_coverage.py:73).

Тест: test_tg_delivery.py — 60 проверок, поведенческие

12 блоков. Ни одна проверка не смотрит «есть ли такая строка в исходнике»: измеряется факт возврата, значение, факт вызова и запись в журнале.

  • [1] Зависший Telegram: обработчик сводки ВОЗВРАЩАЕТСЯ, потеря записана в журнал с причиной.
  • [2] Обычный день: сводка доходит, успех в журнале, ложной тревоги нет.
  • [3] Отказ генерации доходит до врача; зависание на служебном сообщении тоже ограничено.
  • [4] Ответ боту опознан по BOT_ID, хотя get_me бросает ConnectionError; get_me не вызван НИ РАЗУ.
  • [5] Обращение по @имени опознано без сети. Плюс три обратные проверки: пассивный снимок в кулдауне по-прежнему отбрасывается (иначе правка сняла бы защиту от болтливости вместо починки опознания); @stomchat_bot_old за обращение к нам НЕ считается; @stomchat_bot, с запятой — считается.
  • [6] Отказ запроса родителя записан в журнал, обработчик не упал.
  • [7] Вложенность: 90 == tg_safety.DEFAULT_TIMEOUT_SECONDS, 90 < 500, 25 < 90, 25 < 60, 25 >= 20+5.
  • [8] Кнопка при зависании: обработчик вернулся, спиннер снят, ожидание — один бюджет, отказ в журнале.
  • [9] Спиннер снимается на КАЖДОЙ из 10 ветвей (все ветви прогоняются реально, а не считаются по исходнику).
  • [10] Обычный день: кнопка работает, врач видит меню.
  • [11] Границе передан именно бюджет кнопки (наблюдается аргумент вызова).
  • [12] Отмена задачи остаётся отменой, спиннер у снятой задачи не трогаем.

Про тайминги — здесь я ошибся дважды и оба раза починил

Первая версия проверяла время одиночным прогоном и флакнула под параллельной нагрузкой (ожидание врача ограничено одним бюджетом упало на здоровом коде). Вторая версия брала три прогона, но требовала завершения ВСЕХ трёх — это уже не минимум, а И по трём замерам, и оно флакнуло снова. Итог: fastest() берёт ЛУЧШИЙ из трёх и по времени, и по факту возврата, HANG_LIMIT поднят с 8 до 20 с. Различающая сила не потеряна — диверсия даёт 0 возвратов из 3. После правки 5 прогонов подряд: 58/0 каждый.

Саботаж: 6 диверсий, все 6 поймано

Каждая диверсия — точная замена в МОЁМ продакшн-коде, после каждой assistant.py восстанавливался и сверялся по md5 (e851773327...(md5, укорочен)). Все шесть перепроверены на ФИНАЛЬНОЙ версии теста (после правки таймингов).

№ Что сломано Упало проверок Поймано
1 Д1: снята граница с доставки готовой сводки 6 да
2 Д2: возвращён get_me() на горячий путь под пустым except 2 да
3 Д3: снята граница с одной ветки кнопок (меню энциклопедии) 6 да
4 Д3: бюджет кнопки поднят 25 -> 120 (сломана вложенность) 2 да
5 Д3: границе передан DEFAULT_TIMEOUT_SECONDS вместо бюджета кнопки 25 да
6 Д2: отключено опознание по @имени 1 да
7 Д2: граница слова заменена на совпадение подстрокой 1 да

Диверсии, которая НЕ уронила бы тест, не нашлось. Замечания по отдельным:

  • №2 уронила ровно две проверки — те самые, что описывают последствие для врача («снимок пошёл в разбор» и «get_me не вызывается»). Это не слабость: остальные 56 к этому пути не относятся.
  • №5 уронила 25 проверок, потому что подмена бюджета в тесте перестаёт действовать, и все 10 ветвей начинают ждать по-настоящему. Заодно это доказывает, что тест наблюдает именно СОБЛЮДЕНИЕ константы, а не «какой-то таймаут есть».
  • Диверсия №3 нашла дефект в моём собственном тесте: при нуле возвратов elapsed был None, и пояснение к отказу f"{elapsed:.3f}" роняло весь набор с TypeError вместо честного FAIL — то есть падение теста скрывало все последующие проверки. Добавлена secs(), после чего диверсия даёт чистый FAIL на 6 проверках. Без саботажа этот дефект уехал бы к лиду.
  • №7 накладывалась через heredoc и не наложилась: \b в шелле съедается, assert count==1 это поймал, и я увидел бы ложное «диверсия не уронила тест» (60/0 на здоровом коде). Повторил через Edit — упала 1 проверка. Отдельно отмечаю: проверка счётчика замен в скрипте диверсии обязательна, иначе неналоженная диверсия читается как «тест ничего не заметил».

Прогон наборов ПОСЛЕ правок

Восемь обязательных — все зелёные, как и до меня:

набор было стало
test_tg_safety.py 131/0 131/0
test_flood_discipline.py 35/0 35/0
test_silence_all_paths.py 21/0 21/0
test_validator_coverage.py 24/0 24/0
test_summary_delivery.py 41/0 41/0
test_group_quiz.py 28/0 28/0
test_thread_dedupe.py 55/0 55/0
test_passive_gate.py 19/0 19/0

Соседние, которые трогает мой файл:

набор результат
test_tg_delivery.py (мой) 60/0, стабильно 5 прогонов подряд
test_group_summary.py 20/0
test_import_safety.py 271/0
test_routing_behaviour.py 31/0
test_budget_nesting.py 29/0
test_silent_failures.py 11/0
test_bookmarks.py 25/0
test_wiki_pagination.py 40/0
test_style_setting.py 30/0
test_protocols_ui.py 31/1 сломал Я -> 32/0 после правки лида в c2dfec2, см. ниже
test_isolation.py 107/2 — красным был и ДО меня, не мой

Для лида

1. Я сломал test_protocols_ui.py — УЖЕ ЗАКРЫТО лидом в c2dfec2

Оставляю разбор для истории: правка внесена, набор снова 32/0 (перепроверил). Лид выбрал якорь "edit_message" вместо предложенного мной "await edit_callback_message" — он совпадает с моей меткой op= (строка "edit_message:proto_list" идёт сразу после текста), блок снова короткий и проверка проходит. Дальше — исходный разбор.

test_protocols_ui.py:87 вырезает ветку proto:back по текстовому якорю:

back_block = SOURCE.split('if data_str == "proto:back"', 1)[1].split("await bot_client.edit_message", 1)[0]

Я заменил в этой ветке await bot_client.edit_message на await edit_callback_message, якоря в файле больше нет вовсе, split возвращает весь остаток исходника (53453 символа вместо 1187), в набор proto: попадает лишний id back — и проверка «возврат к списку показывает все протоколы» падает.

Измерено, а не предположено. С ДО-правочным assistant.py набор даёт 32/0; с моим — 31/1. Предлагаемая правка проверена вычислением на живом файле:

# было
.split("await bot_client.edit_message", 1)[0]
# нужно
.split("await edit_callback_message", 1)[0]

С новым якорем блок снова 1187 символов, back_ids = {bopt, etching, irrigation, obturation, vertical} и равен protocols — проверка проходит. Сам её смысл (кнопка «назад» повторяет тот же набор протоколов) сохраняется полностью. Я эту правку НЕ внёс: файл не мой, параллельно работают другие агенты.

Отдельно стоит отметить: это проверка по тексту исходника, а не по поведению — ровно тот класс, который в этом проекте уже один раз пропустил снятый потолок. Поведение ветки proto:back мой test_tg_delivery.py [9] теперь прогоняет по-настоящему.

2. Остался один edit_message без границы — вне моих трёх дефектов

assistant.py:3443, обработчик разбора файла:

await bot_client.edit_message(chat_id, status_msg.id, "❌ <i>Не удалось обработать файл. Попробуйте еще раз.</i>", parse_mode='html')

Тот же класс, что Д1: врач прислал файл, получил «Не удалось обработать» — или не получил ничего, если Telegram завис. Правка однострочная (tg_safety.edit_message с SUMMARY_DELIVERY_TIMEOUT_SECONDS), но это уже за рамками выданного лана, и я её не делал. Скажите — внесу.

3. Инвентаризация: сколько ещё осталось

В assistant.py по-прежнему 100 вызовов Telegram API (по регулярному выражению), под границей теперь 15 из них: 2 старых asyncio.wait_for на скачивании медиа + 4 на пути сводки + 10 правок кнопок (минус пересечения). То есть основная масса отправок в личку и в группу по-прежнему без срока — handle_group_direct_ask, check_and_trigger_assistant, пути пингов. Это не входило в лан, но именно там живут те же 51723 обрыва.

4. bot.log засорён тестовой выдумкой

50 строк skipping repeated callback id=555001 в боевом bot.log — это id из test_routing_behaviour.py:236, а не поведение врачей. То есть какой-то прогон набора шёл с STOMCHAT_LOG_PATH, указывающим на боевой журнал. Правило test_import_safety.py [6] это ловит, но задним числом журнал уже испорчен, и любые выводы о частоте повторных нажатий по нему делать нельзя.

Что осталось НЕ проверенным — честно

  • Ни одного живого Telegram. Всё на поддельных клиентах: HangingBot имитирует обрыв через asyncio.sleep, а не через реальный разорванный сокет. Я не проверял на боевой машине, что telethon при настоящем обрыве ведёт себя так, как классифицирует tg_safety.
  • Число 500 с — расчёт из конфигурации, а не замер. 10 x (30 + 20) взято из main.py:883, 900-910 и исходников telethon 1.42.0; сколько именно висел реальный edit_message, по журналам не восстанавливается, потому что момент входа в вызов не логируется вообще.
  • 25 с для кнопки не подтверждено окном Telegram. Я НЕ смог измерить, через сколько Telegram перестаёт принимать answer() на callback: единственный источник в журналах оказался тестовой выдумкой (см. выше). Число выведено из конфигурации клиента, и это слабое место: если реальное окно ответа короче 25 с, спиннер погаснет только по таймауту клиента врача, а не по нашему answer(). Проверяется лишь на боевой машине.
  • tg_safety.guard снимает вызов через task.cancel(), то есть после таймаута НЕИЗВЕСТНО, ушла ли правка. Для сводки это значит: возможен случай, когда сводка врачу пришла, а в журнале записано «НЕ доставлена». Поиск своего сообщения (как _find_recent_matching_message в summarizer) я не добавлял — для правки уже отправленного статуса дубля не возникает, но расхождение журнала с реальностью возможно.
  • Пути handle_group_direct_ask и check_and_trigger_assistant я не трогал и не проверял; они остаются без границ.
  • test_isolation.py 107/2 — красный до меня; я не разбирался, чей это дефект.