SilverElixir commited on
Commit
53310cd
·
1 Parent(s): 5fcacff

Cap a message by a shared deadline and bound streaming's first chunk by it

Browse files

Lock wait, search, route retry and history summary each had their own timeout, so one message could hold the chat lock for minutes. stream_interrupted now survives a successful return so continue works.

bot.py CHANGED
@@ -86,6 +86,23 @@ def _current_log_secrets() -> tuple[str, ...]:
86
  # id, и собрать путь одного запроса по логу было нельзя (прод 27.10.2026).
87
  _LOG_CHAT: contextvars.ContextVar[str] = contextvars.ContextVar("log_chat", default="")
88
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
89
 
90
  class _SecretLogFormatter(logging.Formatter):
91
  def format(self, record: logging.LogRecord, _secrets=_current_log_secrets) -> str:
@@ -405,6 +422,9 @@ ROUTE_MODEL_TIMEOUT_SEC = _env_number("ROUTE_MODEL_TIMEOUT_SEC", 22, min_value=1
405
  # ROUTE_TOTAL_BUDGET_SEC — общий бюджет на ВЕСЬ маршрут одного сообщения. Без него
406
  # каскадный сбой у многих моделей растягивал бы один ответ на минуты под локом чата.
407
  ROUTE_TOTAL_BUDGET_SEC = _env_number("ROUTE_TOTAL_BUDGET_SEC", 40, min_value=1)
 
 
 
408
  # HISTORY_SUMMARY_BUDGET_SEC — потолок саммаризации истории: без него висящие
409
  # вызовы держали бы лок чата десятки секунд уже после готового ответа.
410
  HISTORY_SUMMARY_BUDGET_SEC = _env_number("HISTORY_SUMMARY_BUDGET_SEC", 30, min_value=1)
@@ -1301,10 +1321,13 @@ async def handle_message(message: Message) -> None:
1301
  # Метка чата на всех строках обработки (см. _LOG_CHAT); сброс в finally —
1302
  # иначе значение утечёт в следующий апдейт этого же процесса.
1303
  token = _LOG_CHAT.set(f"chat={message.chat.id if message.chat else 0}")
 
 
1304
  try:
1305
  await _handle_message(message)
1306
  finally:
1307
  _LOG_CHAT.reset(token)
 
1308
 
1309
 
1310
  async def _handle_message(message: Message) -> None:
@@ -1339,8 +1362,10 @@ async def _handle_message(message: Message) -> None:
1339
  await _handle_message_core(message)
1340
  return
1341
 
 
 
1342
  try:
1343
- lock = await acquire_chat_lock(chat_id, CHAT_LOCK_TIMEOUT_SEC)
1344
  except asyncio.TimeoutError:
1345
  log.warning("[lock] Timeout waiting for lock on chat %s", chat_id)
1346
  with contextlib.suppress(Exception):
 
86
  # id, и собрать путь одного запроса по логу было нельзя (прод 27.10.2026).
87
  _LOG_CHAT: contextvars.ContextVar[str] = contextvars.ContextVar("log_chat", default="")
88
 
89
+ # Общий дедлайн сообщения: каждый этап берёт min(свой таймаут, остаток), иначе
90
+ # лок + поиск + маршрут + саммари в сумме давали до двух минут (аудит 27.10.2026).
91
+ _MSG_DEADLINE: contextvars.ContextVar[float | None] = contextvars.ContextVar("msg_deadline", default=None)
92
+
93
+
94
+ def _msg_remaining_sec() -> float | None:
95
+ """Сколько осталось до потолка сообщения; None — обработка вне handle_message."""
96
+ deadline = _MSG_DEADLINE.get()
97
+ return None if deadline is None else max(0.0, deadline - time.monotonic())
98
+
99
+
100
+ def _deadline_within_message(seconds: float) -> float:
101
+ """Дедлайн этапа, не выходящий за общий потолок сообщения."""
102
+ now = time.monotonic()
103
+ remaining = _msg_remaining_sec()
104
+ return now + seconds if remaining is None else now + min(seconds, remaining)
105
+
106
 
107
  class _SecretLogFormatter(logging.Formatter):
108
  def format(self, record: logging.LogRecord, _secrets=_current_log_secrets) -> str:
 
422
  # ROUTE_TOTAL_BUDGET_SEC — общий бюджет на ВЕСЬ маршрут одного сообщения. Без него
423
  # каскадный сбой у многих моделей растягивал бы один ответ на минуты под локом чата.
424
  ROUTE_TOTAL_BUDGET_SEC = _env_number("ROUTE_TOTAL_BUDGET_SEC", 40, min_value=1)
425
+ # MESSAGE_TOTAL_BUDGET_SEC — потолок на всё сообщение (лок + поиск + маршрут).
426
+ # Этапы ниже берут min(свой таймаут, остаток), иначе их сумма выходила за бюджет.
427
+ MESSAGE_TOTAL_BUDGET_SEC = _env_number("MESSAGE_TOTAL_BUDGET_SEC", 90, min_value=10)
428
  # HISTORY_SUMMARY_BUDGET_SEC — потолок саммаризации истории: без него висящие
429
  # вызовы держали бы лок чата десятки секунд уже после готового ответа.
430
  HISTORY_SUMMARY_BUDGET_SEC = _env_number("HISTORY_SUMMARY_BUDGET_SEC", 30, min_value=1)
 
1321
  # Метка чата на всех строках обработки (см. _LOG_CHAT); сброс в finally —
1322
  # иначе значение утечёт в следующий апдейт этого же процесса.
1323
  token = _LOG_CHAT.set(f"chat={message.chat.id if message.chat else 0}")
1324
+ # Потолок сообщения ставится здесь: альбомные задачи наследуют контекст.
1325
+ dtoken = _MSG_DEADLINE.set(time.monotonic() + MESSAGE_TOTAL_BUDGET_SEC)
1326
  try:
1327
  await _handle_message(message)
1328
  finally:
1329
  _LOG_CHAT.reset(token)
1330
+ _MSG_DEADLINE.reset(dtoken)
1331
 
1332
 
1333
  async def _handle_message(message: Message) -> None:
 
1362
  await _handle_message_core(message)
1363
  return
1364
 
1365
+ remaining = _msg_remaining_sec()
1366
+ lock_timeout = CHAT_LOCK_TIMEOUT_SEC if remaining is None else max(1.0, min(CHAT_LOCK_TIMEOUT_SEC, remaining))
1367
  try:
1368
+ lock = await acquire_chat_lock(chat_id, lock_timeout)
1369
  except asyncio.TimeoutError:
1370
  log.warning("[lock] Timeout waiting for lock on chat %s", chat_id)
1371
  with contextlib.suppress(Exception):
lumen_chat_state.py CHANGED
@@ -1325,9 +1325,14 @@ async def _trim_history(history: list[dict[str, Any]]) -> None:
1325
  digest_input = "\n".join(lines)[:_HISTORY_SUMMARY_INPUT_MAX_CHARS]
1326
  summary = ""
1327
  if digest_input.strip():
 
 
 
 
 
1328
  try:
1329
  summary = await asyncio.wait_for(
1330
- _summarize_text(digest_input), timeout=bot.HISTORY_SUMMARY_BUDGET_SEC,
1331
  )
1332
  except Exception as exc:
1333
  log.warning("[history] Summarization over budget/failed, plain cut: %s", exc)
 
1325
  digest_input = "\n".join(lines)[:_HISTORY_SUMMARY_INPUT_MAX_CHARS]
1326
  summary = ""
1327
  if digest_input.strip():
1328
+ # Саммари не должно выходить за потолок сообщения: оно идёт под локом чата.
1329
+ budget = bot.HISTORY_SUMMARY_BUDGET_SEC
1330
+ remaining = bot._msg_remaining_sec()
1331
+ if remaining is not None:
1332
+ budget = max(0.1, min(budget, remaining))
1333
  try:
1334
  summary = await asyncio.wait_for(
1335
+ _summarize_text(digest_input), timeout=budget,
1336
  )
1337
  except Exception as exc:
1338
  log.warning("[history] Summarization over budget/failed, plain cut: %s", exc)
lumen_streaming.py CHANGED
@@ -251,9 +251,14 @@ async def _run_streaming_reply(
251
  bot._record_stats_event("model_attempts")
252
 
253
  # Дальше цикл читает генератор напрямую — проверки кусков/утечек/троттлинга ниже без изменений.
 
 
 
 
 
254
  piece_agen = _pieces_with_waiting_feedback(
255
  piece_agen, placeholder,
256
- first_chunk_limit=_model_first_chunk_limit(_model_speed_key(provider, model_id), bot.FIRST_CHUNK_TIMEOUT_SEC),
257
  )
258
  async for piece in piece_agen:
259
  if not piece:
@@ -433,7 +438,10 @@ async def _run_streaming_reply(
433
  await bot._tg_call(sent_messages[-1].edit_text, _md_to_html(final_text + note), parse_mode=ParseMode.HTML, call_timeout=15.0)
434
  # Частичный ответ уже показан и ляжет в историю ниже — запоминаем, что
435
  # его оборвало: слово «продолжи» добьёт с места обрыва (_continue_after_interrupt).
 
 
436
  state["interrupted"] = True
 
437
  bot.mark_state_dirty(chat_id)
438
  finally:
439
  aclose = getattr(piece_agen, "aclose", None)
 
251
  bot._record_stats_event("model_attempts")
252
 
253
  # Дальше цикл читает генератор напрямую — проверки кусков/утечек/троттлинга ниже без изменений.
254
+ first_chunk_limit = _model_first_chunk_limit(_model_speed_key(provider, model_id), bot.FIRST_CHUNK_TIMEOUT_SEC)
255
+ if deadline is not None:
256
+ # Первый кусок не должен ждать дольше общего бюджета сообщения: до него
257
+ # дедлайн не проверялся и ожидание могло выйти за бюджет (аудит 27.10.2026).
258
+ first_chunk_limit = min(first_chunk_limit, max(0.5, deadline - time.monotonic()))
259
  piece_agen = _pieces_with_waiting_feedback(
260
  piece_agen, placeholder,
261
+ first_chunk_limit=first_chunk_limit,
262
  )
263
  async for piece in piece_agen:
264
  if not piece:
 
438
  await bot._tg_call(sent_messages[-1].edit_text, _md_to_html(final_text + note), parse_mode=ParseMode.HTML, call_timeout=15.0)
439
  # Частичный ответ уже показан и ляжет в историю ниже — запоминаем, что
440
  # его оборвало: слово «продолжи» добьёт с места обрыва (_continue_after_interrupt).
441
+ # stream_interrupted переживает успешный возврат: иначе _handle_message_core
442
+ # снимал общий флаг и «продолжи» не срабатывал (аудит 27.10.2026).
443
  state["interrupted"] = True
444
+ state["stream_interrupted"] = True
445
  bot.mark_state_dirty(chat_id)
446
  finally:
447
  aclose = getattr(piece_agen, "aclose", None)
tests/test_bot_streaming.py CHANGED
@@ -581,6 +581,36 @@ def test_streaming_respects_route_deadline():
581
  bot.chat_state.pop(chat_id, None)
582
 
583
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
584
  def _streaming_rate_limit_quotas(chat_id, model_id, error_text):
585
  async def pieces_429():
586
  raise bot.OpenRouterAPIError(error_text, status_code=429)
 
581
  bot.chat_state.pop(chat_id, None)
582
 
583
 
584
+ def test_streaming_first_chunk_limit_capped_by_route_deadline(monkeypatch):
585
+ # Что защищает: ожидание первого куска не выходит за бюджет маршрута.
586
+ # Регрессия: предел модели (по замерам до 75с) игнорировал дедлайн, и стрим
587
+ # держал лок сверх бюджета (аудит 27.10.2026).
588
+ import lumen_streaming
589
+ seen = {}
590
+
591
+ async def fake_feedback(piece_agen, placeholder, *, first_chunk_limit):
592
+ seen["limit"] = first_chunk_limit
593
+ async for piece in piece_agen:
594
+ yield piece
595
+
596
+ async def one_piece():
597
+ yield "готово"
598
+
599
+ monkeypatch.setattr(lumen_streaming, "_pieces_with_waiting_feedback", fake_feedback)
600
+ monkeypatch.setattr(lumen_streaming, "_model_first_chunk_limit", lambda key, floor: 3600)
601
+ chat_id = 999318
602
+ incoming = _FakeIncomingMessage(chat_id)
603
+ try:
604
+ answer, _ = asyncio.run(bot._run_streaming_reply(
605
+ chat_id, "Привет!", incoming, provider="openrouter", model_id="w:free",
606
+ piece_agen=one_piece(), deadline=time.monotonic() + 1,
607
+ ))
608
+ assert answer == "готово"
609
+ assert seen["limit"] <= 1.1
610
+ finally:
611
+ bot.chat_state.pop(chat_id, None)
612
+
613
+
614
  def _streaming_rate_limit_quotas(chat_id, model_id, error_text):
615
  async def pieces_429():
616
  raise bot.OpenRouterAPIError(error_text, status_code=429)
tests/test_bot_transport.py CHANGED
@@ -525,3 +525,34 @@ def test_telegram_api_call_ok_false_reports_description(monkeypatch):
525
  assert "400" in msg
526
  assert "'ok'" not in msg
527
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
 
525
  assert "400" in msg
526
  assert "'ok'" not in msg
527
 
528
+
529
+ def test_message_deadline_caps_stage_budget():
530
+ # Что защищает: общий потолок сообщения (MESSAGE_TOTAL_BUDGET_SEC). Регрессия:
531
+ # таймауты этапов складывались без учёта остатка, и обработка выходила за
532
+ # бюджет (аудит 27.10.2026).
533
+ token = bot._MSG_DEADLINE.set(time.monotonic() + 5)
534
+ try:
535
+ assert bot._msg_remaining_sec() <= 5
536
+ assert bot._deadline_within_message(40) <= time.monotonic() + 5.1
537
+ finally:
538
+ bot._MSG_DEADLINE.reset(token)
539
+ assert bot._msg_remaining_sec() is None
540
+ assert bot._deadline_within_message(40) > time.monotonic() + 39
541
+
542
+
543
+ def test_handle_message_sets_and_resets_message_deadline(monkeypatch):
544
+ # Что защищает: установку потолка на входе в обработчик. Регрессия: дедлайн
545
+ # оставался бы в контексте после обработки и урезал следующий апдейт
546
+ # (аудит 27.10.2026).
547
+ from types import SimpleNamespace
548
+ seen = {}
549
+
550
+ async def fake_handle(message):
551
+ seen["remaining"] = bot._msg_remaining_sec()
552
+
553
+ monkeypatch.setattr(bot, "_handle_message", fake_handle)
554
+ asyncio.run(bot.handle_message(SimpleNamespace(chat=None, from_user=None)))
555
+ assert seen["remaining"] is not None and seen["remaining"] > 0
556
+ assert bot._msg_remaining_sec() is None
557
+
558
+