From 05a429bc2e2816f0cc8cccf7cc372155558a69ba Mon Sep 17 00:00:00 2001 From: Anton Gladkov Date: Wed, 21 Oct 2026 10:24:33 +0300 Subject: [PATCH] fix(bot): tell the chat when a busy bot blocks commands A message sent while a long update handler was running waited in the sequential update loop, and once it was finally handled the stale check dropped it with "Telegram was unreachable" - although Telegram had delivered it. After five seconds without chat output the bot now tells the chat it is busy, so the user does not resend into the silence. Messages delayed by a busy handler are executed after it within fifteen seconds; older ones are dropped with a separate "the bot was busy" notice, and messages delayed without such a window keep the outage notice. --- PRODUCT.md | 3 +- .../telegram-outage-notice-service.ts | 41 +++++- .../services/update-busy-window-service.ts | 51 ++++++++ src/bot/index.ts | 11 +- src/bot/middleware/stale-update.ts | 47 ++++++- src/bot/middleware/update-busy-window.ts | 51 ++++++++ src/bot/telegram-outage-notices.ts | 16 ++- src/i18n/ar.ts | 4 + src/i18n/de.ts | 4 + src/i18n/en.ts | 4 + src/i18n/es.ts | 4 + src/i18n/fr.ts | 4 + src/i18n/id.ts | 4 + src/i18n/it.ts | 4 + src/i18n/ko.ts | 4 + src/i18n/pt.ts | 4 + src/i18n/ru.ts | 4 + src/i18n/tr.ts | 4 + src/i18n/zh.ts | 2 + .../update-busy-window-service.test.ts | 77 +++++++++++ tests/bot/middleware/stale-update.test.ts | 62 +++++++++ .../bot/middleware/update-busy-window.test.ts | 122 ++++++++++++++++++ tests/bot/telegram-outage-notices.test.ts | 32 +++++ ...telegram-server-error-retry-policy.test.ts | 13 ++ tests/helpers/reset-singleton-state.ts | 3 + 25 files changed, 555 insertions(+), 20 deletions(-) create mode 100644 src/app/services/update-busy-window-service.ts create mode 100644 src/bot/middleware/update-busy-window.ts create mode 100644 tests/app/services/update-busy-window-service.test.ts create mode 100644 tests/bot/middleware/update-busy-window.test.ts diff --git a/PRODUCT.md b/PRODUCT.md index c3079f032..22e7746bf 100644 --- a/PRODUCT.md +++ b/PRODUCT.md @@ -109,6 +109,7 @@ No public inbound ports are required for normal usage. - Ignore messages from non-authorized users - Ignore updates queued while the bot was offline or unreachable, so they are not executed on startup - Mid-session, messages older than 60 seconds after an outage are still not executed; the chat gets one notice that messages were skipped while Telegram was unreachable +- A message delayed by a long-running update handler (for example a session pick while the reply keeps streaming) is not treated as an outage: after 5 seconds without chat output the bot says it is busy, messages delayed up to 15 seconds are executed after the handler, and older ones are dropped with a separate "the bot was busy" notice - If Telegram is unreachable at startup (network error, 5xx, 429), keep retrying with a growing delay capped at 60 seconds until it answers, then start polling; a rejected or invalid token (401/404) or any other fatal startup error logs the cause and exits the process with code 1 so a supervisor can restart it ### Configuration @@ -244,7 +245,7 @@ Agent picker behavior: - [x] Native Telegram rich message formatting for assistant replies (Bot API 10.1) - [x] Incoming Telegram rich formatted messages (Bot API 10.1): converted to Markdown, accepted anywhere text is accepted, with photos attached and unsupported message types answered explicitly - [x] Startup either reaches Telegram polling or the process exits: transient Telegram failures are retried in-process; a bad token or other fatal startup error exits with code 1 -- [x] After a Telegram outage the bot answers again without restart; an undelivered assistant reply is not resent, and skipped stale messages are reported once +- [x] After a Telegram outage the bot answers again without restart; an undelivered assistant reply is not resent, and skipped stale messages are reported once per cause ## Current Task List diff --git a/src/app/services/telegram-outage-notice-service.ts b/src/app/services/telegram-outage-notice-service.ts index 8a32241d6..a56cfd0bd 100644 --- a/src/app/services/telegram-outage-notice-service.ts +++ b/src/app/services/telegram-outage-notice-service.ts @@ -1,17 +1,22 @@ const CHAT_INTERVAL_MS = 1000; const BURST_GAP_MS = 60_000; -export type TelegramOutageNoticeKind = "undelivered" | "skipped"; +export type TelegramOutageNoticeKind = "undelivered" | "skipped" | "busy"; + +export type SkippedMessagesReason = "outage" | "busy"; export interface TelegramOutageNoticesDue { undelivered: boolean; skipped: boolean; + busy: boolean; } export class TelegramOutageNoticeService { private undeliveredPending = false; private skippedPending = false; + private busyPending = false; private burstActive = false; + private burstReasons = new Set(); private lastStaleAt = 0; private lastChatSendAt = 0; private flushInFlight = false; @@ -20,25 +25,48 @@ export class TelegramOutageNoticeService { this.undeliveredPending = true; } - markMessagesSkipped(): void { + markMessagesSkipped(reason: SkippedMessagesReason = "outage"): void { const now = Date.now(); if (this.burstActive && now - this.lastStaleAt <= BURST_GAP_MS) { this.lastStaleAt = now; + if (!this.burstReasons.has(reason)) { + this.burstReasons.add(reason); + this.markSkippedPending(reason); + } return; } + this.burstActive = true; - this.skippedPending = true; + this.burstReasons = new Set([reason]); + this.markSkippedPending(reason); this.lastStaleAt = now; } + private markSkippedPending(reason: SkippedMessagesReason): void { + if (reason === "busy") { + this.busyPending = true; + } else { + this.skippedPending = true; + } + } + closeBurst(): void { this.burstActive = false; + this.burstReasons = new Set(); } noteChatSendSucceeded(): void { this.lastChatSendAt = Date.now(); } + /** Milliseconds since the last chat delivery, or null when nothing was sent yet. */ + msSinceLastChatSend(): number | null { + if (this.lastChatSendAt === 0) { + return null; + } + return Date.now() - this.lastChatSendAt; + } + msUntilAllowedSend(): number { if (this.lastChatSendAt === 0) { return 0; @@ -50,13 +78,14 @@ export class TelegramOutageNoticeService { if (this.flushInFlight) { return null; } - if (!this.undeliveredPending && !this.skippedPending) { + if (!this.undeliveredPending && !this.skippedPending && !this.busyPending) { return null; } this.flushInFlight = true; return { undelivered: this.undeliveredPending, skipped: this.skippedPending, + busy: this.busyPending, }; } @@ -66,6 +95,8 @@ export class TelegramOutageNoticeService { } if (kind === "undelivered") { this.undeliveredPending = false; + } else if (kind === "busy") { + this.busyPending = false; } else { this.skippedPending = false; } @@ -78,7 +109,9 @@ export class TelegramOutageNoticeService { __resetForTests(): void { this.undeliveredPending = false; this.skippedPending = false; + this.busyPending = false; this.burstActive = false; + this.burstReasons = new Set(); this.lastStaleAt = 0; this.lastChatSendAt = 0; this.flushInFlight = false; diff --git a/src/app/services/update-busy-window-service.ts b/src/app/services/update-busy-window-service.ts new file mode 100644 index 000000000..cd14ad015 --- /dev/null +++ b/src/app/services/update-busy-window-service.ts @@ -0,0 +1,51 @@ +export const STALE_THRESHOLD_MS = 60_000; +export const BUSY_CANCEL_MS = 15_000; +// The stale check floors the age to whole seconds, so a handler just under the cancel +// window can still leave a message looking one second older; record with that margin. +const RECORD_THRESHOLD_MS = BUSY_CANCEL_MS - 1000; +const WINDOW_TTL_MS = 60 * 60_000; + +export interface UpdateBusyWindow { + startedAt: number; + endedAt: number; +} + +/** + * Remembers update handlers that ran longer than the busy-cancel window. A message the + * user sent while the bot was busy was delayed by the bot itself, not by a Telegram outage, + * and the stale-update middleware uses these windows to tell the two apart. + * + * The window starts at the beginning of the handler's first second: Telegram dates messages + * in whole seconds, so a message sent in that same second must still be covered. + * + * Only handlers that individually outlive the threshold are recorded: a backlog of shorter + * handlers can still delay a message past it without a window. + */ +export class UpdateBusyWindowService { + private windows: UpdateBusyWindow[] = []; + + record(startedAt: number, endedAt: number): void { + if (endedAt - startedAt < RECORD_THRESHOLD_MS) { + return; + } + + this.windows.push({ startedAt: Math.floor(startedAt / 1000) * 1000, endedAt }); + this.windows = this.windows.filter((window) => endedAt - window.endedAt <= WINDOW_TTL_MS); + } + + covers(timestampMs: number): boolean { + const now = Date.now(); + return this.windows.some( + (window) => + now - window.endedAt <= WINDOW_TTL_MS && + timestampMs >= window.startedAt && + timestampMs <= window.endedAt, + ); + } + + __resetForTests(): void { + this.windows = []; + } +} + +export const updateBusyWindowService = new UpdateBusyWindowService(); diff --git a/src/bot/index.ts b/src/bot/index.ts index 7d355bed4..f4b8c37a8 100644 --- a/src/bot/index.ts +++ b/src/bot/index.ts @@ -23,10 +23,8 @@ import { normalizeRichMessage } from "./handlers/rich-message-handler.js"; import { authMiddleware } from "./middleware/auth.js"; import { interactionGuardMiddleware } from "./middleware/interaction-guard.js"; import { staleUpdateMiddleware } from "./middleware/stale-update.js"; -import { - ensureCommandsInitialized, - registerCommandRouter, -} from "./routers/command-router.js"; +import { updateBusyWindowMiddleware } from "./middleware/update-busy-window.js"; +import { ensureCommandsInitialized, registerCommandRouter } from "./routers/command-router.js"; import { registerMessageRouter } from "./routers/message-router.js"; import { createAttachPresentation } from "./services/attach-presentation.js"; import { createTelegramBotOptions } from "./telegram-client-options.js"; @@ -44,6 +42,8 @@ const STARTUP_MANAGED_TELEGRAM_METHODS = new Set(["deleteWebhook", "getMe", "get const CHAT_DELIVERY_TELEGRAM_METHODS = new Set([ "sendMessage", "sendRichMessage", + "sendMessageDraft", + "sendRichMessageDraft", "editMessageText", "sendDocument", "sendAudio", @@ -211,7 +211,10 @@ export function createBot( }); bot.use(authMiddleware); + // The busy timer must wrap only handlers that actually run: the stale check drops + // updates before it. bot.use(staleUpdateMiddleware); + bot.use(updateBusyWindowMiddleware); bot.on("message:rich_message", normalizeRichMessage); bot.use((ctx, next) => ensureCommandsInitialized(ctx, next, localCommandRegistry)); const guardDeps = { ...container, localCommandRegistry }; diff --git a/src/bot/middleware/stale-update.ts b/src/bot/middleware/stale-update.ts index 5c7632cce..5114a6ffe 100644 --- a/src/bot/middleware/stale-update.ts +++ b/src/bot/middleware/stale-update.ts @@ -1,5 +1,10 @@ import type { Context, NextFunction } from "grammy"; import { telegramOutageNoticeService } from "../../app/services/telegram-outage-notice-service.js"; +import { + BUSY_CANCEL_MS, + STALE_THRESHOLD_MS, + updateBusyWindowService, +} from "../../app/services/update-busy-window-service.js"; import { flushTelegramOutageNotices } from "../telegram-outage-notices.js"; import { logger } from "../../utils/logger.js"; @@ -7,7 +12,12 @@ import { logger } from "../../utils/logger.js"; // the bot long after it was sent - after a restart, or after long polling was // interrupted by a network outage. Acting on such a message is unwanted: it // would start tasks the user no longer expects to run. -const MAX_MESSAGE_AGE_SECONDS = 60; +const MAX_MESSAGE_AGE_SECONDS = STALE_THRESHOLD_MS / 1000; +// A message the bot delayed itself is executed after the handler, but only within this +// window: the chat has had feedback by then (the 5-second busy notice or streaming +// progress), and older commands are dropped with an honest notice instead of being +// executed late. +const BUSY_CANCEL_SECONDS = BUSY_CANCEL_MS / 1000; export async function staleUpdateMiddleware(ctx: Context, next: NextFunction): Promise { // Only `ctx.message` carries the time the user acted. `ctx.msg` also resolves @@ -23,7 +33,7 @@ export async function staleUpdateMiddleware(ctx: Context, next: NextFunction): P const chatId = ctx.chat?.id; const canNotify = typeof chatId === "number" && ctx.api !== undefined; - if (ageSeconds <= MAX_MESSAGE_AGE_SECONDS) { + if (ageSeconds <= BUSY_CANCEL_SECONDS) { telegramOutageNoticeService.closeBurst(); if (canNotify) { await flushTelegramOutageNotices({ api: ctx.api, chatId }); @@ -32,11 +42,36 @@ export async function staleUpdateMiddleware(ctx: Context, next: NextFunction): P return; } - telegramOutageNoticeService.markMessagesSkipped(); - logger.warn( - `[StaleUpdate] Ignored stale message: ageSeconds=${ageSeconds}, updateId=${ctx.update.update_id}, messageId=${message.message_id}`, - ); + // The bot was busy when this message arrived: Telegram delivered it, the update loop + // was held by a long handler. That is not an outage, so it gets its own notice. + const delayedByBusyBot = updateBusyWindowService.covers(message.date * 1000); + if (delayedByBusyBot) { + telegramOutageNoticeService.markMessagesSkipped("busy"); + logger.warn( + `[StaleUpdate] Ignored a message delayed by a long handler: ageSeconds=${ageSeconds}, updateId=${ctx.update.update_id}, messageId=${message.message_id}`, + ); + if (canNotify) { + await flushTelegramOutageNotices({ api: ctx.api, chatId }); + } + return; + } + + if (ageSeconds > MAX_MESSAGE_AGE_SECONDS) { + telegramOutageNoticeService.markMessagesSkipped("outage"); + logger.warn( + `[StaleUpdate] Ignored stale message: ageSeconds=${ageSeconds}, updateId=${ctx.update.update_id}, messageId=${message.message_id}`, + ); + if (canNotify) { + await flushTelegramOutageNotices({ api: ctx.api, chatId }); + } + return; + } + + // Delayed without a recorded busy window: the transport was slow, or the delay came from + // a backlog of shorter handlers. Execute it. + telegramOutageNoticeService.closeBurst(); if (canNotify) { await flushTelegramOutageNotices({ api: ctx.api, chatId }); } + await next(); } diff --git a/src/bot/middleware/update-busy-window.ts b/src/bot/middleware/update-busy-window.ts new file mode 100644 index 000000000..264b0c84d --- /dev/null +++ b/src/bot/middleware/update-busy-window.ts @@ -0,0 +1,51 @@ +import type { Context, NextFunction } from "grammy"; +import { telegramOutageNoticeService } from "../../app/services/telegram-outage-notice-service.js"; +import { updateBusyWindowService } from "../../app/services/update-busy-window-service.js"; +import { t } from "../../i18n/index.js"; +import { logger } from "../../utils/logger.js"; + +const BUSY_NOTICE_DELAY_MS = 5000; + +/** + * Records a handler that outlived the busy-cancel window, and tells the chat when a handler + * blocks silently for too long: a message delayed by the bot itself is not an outage, and + * the user must not be left without feedback long enough to resend it. + */ +export async function updateBusyWindowMiddleware(ctx: Context, next: NextFunction): Promise { + const startedAt = Date.now(); + const chatId = ctx.chat?.id; + let timer: ReturnType | null = null; + let completed = false; + + if (typeof chatId === "number" && ctx.api) { + const api = ctx.api; + const checkSilence = (): void => { + timer = null; + if (completed) { + return; + } + + const sinceLastSend = telegramOutageNoticeService.msSinceLastChatSend(); + if (sinceLastSend !== null && sinceLastSend < BUSY_NOTICE_DELAY_MS) { + // The chat already shows progress; look again once the gap is long enough. + timer = setTimeout(checkSilence, BUSY_NOTICE_DELAY_MS - sinceLastSend); + return; + } + + void api.sendMessage(chatId, t("bot.busy_operation")).catch((error) => { + logger.warn("[UpdateBusyWindow] Failed to send the busy notice:", error); + }); + }; + timer = setTimeout(checkSilence, BUSY_NOTICE_DELAY_MS); + } + + try { + await next(); + } finally { + completed = true; + if (timer !== null) { + clearTimeout(timer); + } + updateBusyWindowService.record(startedAt, Date.now()); + } +} diff --git a/src/bot/telegram-outage-notices.ts b/src/bot/telegram-outage-notices.ts index afb1446c1..028d30c47 100644 --- a/src/bot/telegram-outage-notices.ts +++ b/src/bot/telegram-outage-notices.ts @@ -14,11 +14,14 @@ export interface FlushTelegramOutageNoticesOptions { const unretriedSend = new AsyncLocalStorage(); -const NOTICE_TEXT: Record = - { - undelivered: "bot.assistant_reply_undelivered", - skipped: "bot.stale_messages_skipped", - }; +const NOTICE_TEXT: Record< + TelegramOutageNoticeKind, + "bot.assistant_reply_undelivered" | "bot.stale_messages_skipped" | "bot.busy_messages_skipped" +> = { + undelivered: "bot.assistant_reply_undelivered", + skipped: "bot.stale_messages_skipped", + busy: "bot.busy_messages_skipped", +}; export function isUnretriedTelegramSend(): boolean { return unretriedSend.getStore() === true; @@ -73,6 +76,9 @@ export async function flushTelegramOutageNotices( if (due.skipped) { await sendNotice(options, "skipped"); } + if (due.busy) { + await sendNotice(options, "busy"); + } } finally { telegramOutageNoticeService.finishFlush(); } diff --git a/src/i18n/ar.ts b/src/i18n/ar.ts index 0ef23d9dc..8223b1ee3 100644 --- a/src/i18n/ar.ts +++ b/src/i18n/ar.ts @@ -101,6 +101,10 @@ export const ar: I18nDictionary = { "bot.session_error": "🔴 أعاد OpenCode الخطأ التالي: {message}", "bot.assistant_reply_undelivered": "⚠️ The last assistant reply could not be delivered. Send your message again if you still need it.", + "bot.busy_operation": + "⏳ البوت مشغول بالعملية الحالية. انتظر حتى تنتهي — قد يتم تخطي الرسائل المرسلة الآن.", + "bot.busy_messages_skipped": + "⚠️ كان البوت مشغولاً وتخطى بعض الرسائل. يرجى إرسالها مرة أخرى.", "bot.stale_messages_skipped": "⚠️ Some messages were skipped while Telegram was unreachable. Please send them again.", "bot.session_retry": diff --git a/src/i18n/de.ts b/src/i18n/de.ts index ef42750fd..3ff03462b 100644 --- a/src/i18n/de.ts +++ b/src/i18n/de.ts @@ -101,6 +101,10 @@ export const de: I18nDictionary = { "bot.session_error": "🔴 OpenCode meldete einen Fehler: {message}", "bot.assistant_reply_undelivered": "⚠️ The last assistant reply could not be delivered. Send your message again if you still need it.", + "bot.busy_operation": + "⏳ Der Bot ist mit der aktuellen Operation beschäftigt. Warten Sie, bis sie abgeschlossen ist — jetzt gesendete Nachrichten können übersprungen werden.", + "bot.busy_messages_skipped": + "⚠️ Der Bot war beschäftigt und hat einige Nachrichten übersprungen. Bitte senden Sie sie erneut.", "bot.stale_messages_skipped": "⚠️ Some messages were skipped while Telegram was unreachable. Please send them again.", "bot.session_retry": diff --git a/src/i18n/en.ts b/src/i18n/en.ts index 2272ddff4..3a579a75e 100644 --- a/src/i18n/en.ts +++ b/src/i18n/en.ts @@ -98,6 +98,10 @@ export const en = { "bot.session_error": "🔴 OpenCode returned an error: {message}", "bot.assistant_reply_undelivered": "⚠️ The last assistant reply could not be delivered. Send your message again if you still need it.", + "bot.busy_operation": + "⏳ The bot is busy with the current operation. Wait for it to finish — messages sent now may be skipped.", + "bot.busy_messages_skipped": + "⚠️ The bot was busy and skipped some messages. Please send them again.", "bot.stale_messages_skipped": "⚠️ Some messages were skipped while Telegram was unreachable. Please send them again.", "bot.session_retry": diff --git a/src/i18n/es.ts b/src/i18n/es.ts index 2d0b43d05..5b8fc555c 100644 --- a/src/i18n/es.ts +++ b/src/i18n/es.ts @@ -102,6 +102,10 @@ export const es: I18nDictionary = { "bot.session_error": "🔴 OpenCode devolvió un error: {message}", "bot.assistant_reply_undelivered": "⚠️ The last assistant reply could not be delivered. Send your message again if you still need it.", + "bot.busy_operation": + "⏳ El bot está ocupado con la operación actual. Espera a que termine: los mensajes enviados ahora pueden omitirse.", + "bot.busy_messages_skipped": + "⚠️ El bot estaba ocupado y omitió algunos mensajes. Vuelve a enviarlos.", "bot.stale_messages_skipped": "⚠️ Some messages were skipped while Telegram was unreachable. Please send them again.", "bot.session_retry": diff --git a/src/i18n/fr.ts b/src/i18n/fr.ts index cac30629c..023463465 100644 --- a/src/i18n/fr.ts +++ b/src/i18n/fr.ts @@ -101,6 +101,10 @@ export const fr: I18nDictionary = { "bot.session_error": "🔴 OpenCode a renvoyé une erreur : {message}", "bot.assistant_reply_undelivered": "⚠️ The last assistant reply could not be delivered. Send your message again if you still need it.", + "bot.busy_operation": + "⏳ Le bot est occupé par l'opération en cours. Attendez qu'elle se termine — les messages envoyés maintenant peuvent être ignorés.", + "bot.busy_messages_skipped": + "⚠️ Le bot était occupé et a ignoré certains messages. Veuillez les renvoyer.", "bot.stale_messages_skipped": "⚠️ Some messages were skipped while Telegram was unreachable. Please send them again.", "bot.session_retry": diff --git a/src/i18n/id.ts b/src/i18n/id.ts index 37f808c48..543dae59c 100644 --- a/src/i18n/id.ts +++ b/src/i18n/id.ts @@ -105,6 +105,10 @@ export const id: I18nDictionary = { "bot.session_error": "🔴 OpenCode mengembalikan kesalahan: {message}", "bot.assistant_reply_undelivered": "⚠️ Balasan terakhir dari asisten tidak berhasil dikirim. Kirim ulang pesanmu jika masih membutuhkannya.", + "bot.busy_operation": + "⏳ Bot sedang sibuk dengan operasi saat ini. Tunggu hingga selesai — pesan yang dikirim sekarang mungkin dilewati.", + "bot.busy_messages_skipped": + "⚠️ Bot sedang sibuk dan melewatkan beberapa pesan. Kirim ulang pesan-pesan itu.", "bot.stale_messages_skipped": "⚠️ Beberapa pesan terlewat saat Telegram tidak bisa dijangkau. Kirim ulang pesan-pesan itu.", "bot.session_retry": diff --git a/src/i18n/it.ts b/src/i18n/it.ts index 4f9d907b9..c804a700c 100644 --- a/src/i18n/it.ts +++ b/src/i18n/it.ts @@ -103,6 +103,10 @@ export const it: I18nDictionary = { "bot.session_error": "🔴 OpenCode ha restituito un errore: {message}", "bot.assistant_reply_undelivered": "⚠️ The last assistant reply could not be delivered. Send your message again if you still need it.", + "bot.busy_operation": + "⏳ Il bot è occupato con l'operazione corrente. Attendi che finisca: i messaggi inviati ora potrebbero essere saltati.", + "bot.busy_messages_skipped": + "⚠️ Il bot era occupato e ha saltato alcuni messaggi. Inviali di nuovo.", "bot.stale_messages_skipped": "⚠️ Some messages were skipped while Telegram was unreachable. Please send them again.", "bot.session_retry": diff --git a/src/i18n/ko.ts b/src/i18n/ko.ts index 9afb0742f..7688c15d5 100644 --- a/src/i18n/ko.ts +++ b/src/i18n/ko.ts @@ -107,6 +107,10 @@ export const ko: I18nDictionary = { "bot.session_error": "🔴 OpenCode 오류가 발생했습니다: {message}", "bot.assistant_reply_undelivered": "⚠️ The last assistant reply could not be delivered. Send your message again if you still need it.", + "bot.busy_operation": + "⏳ 봇이 현재 작업으로 바쁩니다. 작업이 끝날 때까지 기다려 주세요. 지금 보낸 메시지는 건너뛸 수 있습니다.", + "bot.busy_messages_skipped": + "⚠️ 봇이 바빠서 일부 메시지를 건너뛰었습니다. 다시 보내 주세요.", "bot.stale_messages_skipped": "⚠️ Some messages were skipped while Telegram was unreachable. Please send them again.", "bot.session_retry": diff --git a/src/i18n/pt.ts b/src/i18n/pt.ts index 92ba41f57..22aa53bf9 100644 --- a/src/i18n/pt.ts +++ b/src/i18n/pt.ts @@ -101,6 +101,10 @@ export const pt: I18nDictionary = { "bot.session_error": "🔴 O OpenCode retornou um erro: {message}", "bot.assistant_reply_undelivered": "⚠️ The last assistant reply could not be delivered. Send your message again if you still need it.", + "bot.busy_operation": + "⏳ O bot está ocupado com a operação atual. Aguarde o término — mensagens enviadas agora podem ser ignoradas.", + "bot.busy_messages_skipped": + "⚠️ O bot estava ocupado e ignorou algumas mensagens. Envie-as novamente.", "bot.stale_messages_skipped": "⚠️ Some messages were skipped while Telegram was unreachable. Please send them again.", "bot.session_retry": diff --git a/src/i18n/ru.ts b/src/i18n/ru.ts index c43ff9826..fa19de5e4 100644 --- a/src/i18n/ru.ts +++ b/src/i18n/ru.ts @@ -97,6 +97,10 @@ export const ru: I18nDictionary = { "bot.session_error": "🔴 OpenCode вернул ошибку: {message}", "bot.assistant_reply_undelivered": "⚠️ Последний ответ ассистента не удалось доставить. Отправьте сообщение ещё раз, если оно ещё нужно.", + "bot.busy_operation": + "⏳ Бот занят текущей операцией. Дождитесь её завершения — отправленные сейчас сообщения могут быть пропущены.", + "bot.busy_messages_skipped": + "⚠️ Бот был занят и пропустил некоторые сообщения. Отправьте их ещё раз.", "bot.stale_messages_skipped": "⚠️ Некоторые сообщения пропущены, пока не было связи с Telegram. Отправьте их ещё раз.", "bot.session_retry": diff --git a/src/i18n/tr.ts b/src/i18n/tr.ts index b6ce2fd2a..10484c266 100644 --- a/src/i18n/tr.ts +++ b/src/i18n/tr.ts @@ -98,6 +98,10 @@ export const tr: I18nDictionary = { "bot.session_error": "🔴 OpenCode bir hata döndürdü: {message}", "bot.assistant_reply_undelivered": "⚠️ The last assistant reply could not be delivered. Send your message again if you still need it.", + "bot.busy_operation": + "⏳ Bot şu anki işlemle meşgul. Bitmesini bekleyin — şimdi gönderilen mesajlar atlanabilir.", + "bot.busy_messages_skipped": + "⚠️ Bot meşguldü ve bazı mesajları atladı. Lütfen tekrar gönderin.", "bot.stale_messages_skipped": "⚠️ Some messages were skipped while Telegram was unreachable. Please send them again.", "bot.session_retry": diff --git a/src/i18n/zh.ts b/src/i18n/zh.ts index 2e6fb4f90..784aa0403 100644 --- a/src/i18n/zh.ts +++ b/src/i18n/zh.ts @@ -90,6 +90,8 @@ export const zh: I18nDictionary = { "bot.session_error": "🔴 OpenCode 返回错误：{message}", "bot.assistant_reply_undelivered": "⚠️ The last assistant reply could not be delivered. Send your message again if you still need it.", + "bot.busy_operation": "⏳ 机器人正在执行当前操作。请等待完成——现在发送的消息可能会被跳过。", + "bot.busy_messages_skipped": "⚠️ 机器人忙，跳过了一些消息。请重新发送。", "bot.stale_messages_skipped": "⚠️ Some messages were skipped while Telegram was unreachable. Please send them again.", "bot.session_retry": "🔁 {message}\n\n提供方在重复重试时持续返回同一错误。使用 /abort 可停止。", diff --git a/tests/app/services/update-busy-window-service.test.ts b/tests/app/services/update-busy-window-service.test.ts new file mode 100644 index 000000000..8ba4d0cea --- /dev/null +++ b/tests/app/services/update-busy-window-service.test.ts @@ -0,0 +1,77 @@ +import { afterEach, beforeEach, describe, expect, it, vi } from "vitest"; +import { UpdateBusyWindowService } from "../../../src/app/services/update-busy-window-service.js"; + +const NOW_MS = Date.UTC(2026, 6, 27, 12, 0, 0); + +describe("update busy window service", () => { + let service: UpdateBusyWindowService; + + beforeEach(() => { + vi.useFakeTimers(); + vi.setSystemTime(NOW_MS); + service = new UpdateBusyWindowService(); + }); + + afterEach(() => { + vi.useRealTimers(); + }); + + it("does not record a handler shorter than the cancel window", () => { + service.record(NOW_MS, NOW_MS + 13_999); + + expect(service.covers(NOW_MS + 10_000)).toBe(false); + }); + + it("records a handler just under the cancel window to absorb the second rounding", () => { + service.record(NOW_MS, NOW_MS + 14_000); + + expect(service.covers(NOW_MS + 10_000)).toBe(true); + }); + + it("covers a handler's first second even when it starts mid-second", () => { + // Telegram dates a message at the start of the second the handler began in. + const startedAt = NOW_MS + 400; + service.record(startedAt, startedAt + 20_000); + + expect(service.covers(NOW_MS)).toBe(true); + expect(service.covers(startedAt + 10_000)).toBe(true); + expect(service.covers(startedAt + 20_001)).toBe(false); + }); + + it("covers messages sent while a long handler ran", () => { + service.record(NOW_MS, NOW_MS + 90_000); + + expect(service.covers(NOW_MS + 1)).toBe(true); + expect(service.covers(NOW_MS + 90_000)).toBe(true); + expect(service.covers(NOW_MS - 1)).toBe(false); + expect(service.covers(NOW_MS + 90_001)).toBe(false); + }); + + it("stops covering after the window TTL without a new long handler", () => { + service.record(NOW_MS, NOW_MS + 90_000); + + vi.setSystemTime(NOW_MS + 2 * 60 * 60_000); + + expect(service.covers(NOW_MS + 60_000)).toBe(false); + }); + + it("forgets windows older than an hour when a new one is recorded", () => { + service.record(NOW_MS, NOW_MS + 90_000); + + const laterStart = NOW_MS + 2 * 60 * 60_000; + service.record(laterStart, laterStart + 90_000); + + expect(service.covers(NOW_MS + 60_000)).toBe(false); + expect(service.covers(laterStart + 60_000)).toBe(true); + }); + + it("keeps every window within the TTL", () => { + for (let index = 0; index < 11; index += 1) { + const startedAt = NOW_MS + index * 2 * 60_000; + service.record(startedAt, startedAt + 90_000); + } + + expect(service.covers(NOW_MS + 60_000)).toBe(true); + expect(service.covers(NOW_MS + 10 * 2 * 60_000 + 60_000)).toBe(true); + }); +}); diff --git a/tests/bot/middleware/stale-update.test.ts b/tests/bot/middleware/stale-update.test.ts index d40a88aa8..bafb13be6 100644 --- a/tests/bot/middleware/stale-update.test.ts +++ b/tests/bot/middleware/stale-update.test.ts @@ -19,6 +19,8 @@ vi.mock("../../../src/utils/logger.js", () => ({ import { staleUpdateMiddleware } from "../../../src/bot/middleware/stale-update.js"; import { telegramOutageNoticeService } from "../../../src/app/services/telegram-outage-notice-service.js"; +import { updateBusyWindowService } from "../../../src/app/services/update-busy-window-service.js"; +import { t } from "../../../src/i18n/index.js"; const NOW_MS = Date.UTC(2026, 6, 27, 12, 0, 0); const NOW_SECONDS = Math.floor(NOW_MS / 1000); @@ -65,6 +67,7 @@ describe("staleUpdateMiddleware", () => { vi.setSystemTime(NOW_MS); mocked.loggerWarnMock.mockReset(); telegramOutageNoticeService.__resetForTests(); + updateBusyWindowService.__resetForTests(); }); afterEach(() => { @@ -177,6 +180,65 @@ describe("staleUpdateMiddleware", () => { expect(sendMessage).toHaveBeenCalledTimes(1); }); + it("runs a message at the busy-cancel boundary", async () => { + updateBusyWindowService.record(NOW_MS - 120_000, NOW_MS - 10_000); + const sendMessage = vi.fn().mockResolvedValue({ message_id: 1 }); + const ctx = createMessageContext(15, { sendMessage }); + const next: NextFunction = vi.fn().mockResolvedValue(undefined); + + await staleUpdateMiddleware(ctx, next); + + expect(next).toHaveBeenCalledTimes(1); + expect(mocked.loggerWarnMock).not.toHaveBeenCalled(); + expect(sendMessage).not.toHaveBeenCalled(); + }); + + it("drops a message delayed by a busy bot past the cancel window with the busy notice", async () => { + updateBusyWindowService.record(NOW_MS - 20 * 60_000, NOW_MS - 10_000); + const sendMessage = vi.fn().mockResolvedValue({ message_id: 1 }); + const ctx = createMessageContext(16, { sendMessage }); + const next: NextFunction = vi.fn().mockResolvedValue(undefined); + + await staleUpdateMiddleware(ctx, next); + + expect(next).not.toHaveBeenCalled(); + expect(mocked.loggerWarnMock).toHaveBeenCalledTimes(1); + expect(sendMessage).toHaveBeenCalledWith(1, t("bot.busy_messages_skipped")); + }); + + it("runs a transport-delayed message without a busy window", async () => { + const ctx = createMessageContext(30); + const next: NextFunction = vi.fn().mockResolvedValue(undefined); + + await staleUpdateMiddleware(ctx, next); + + expect(next).toHaveBeenCalledTimes(1); + expect(mocked.loggerWarnMock).not.toHaveBeenCalled(); + }); + + it("prefers the busy notice for an old message covered by a busy window", async () => { + updateBusyWindowService.record(NOW_MS - 30 * 60_000, NOW_MS - 10_000); + const sendMessage = vi.fn().mockResolvedValue({ message_id: 1 }); + const ctx = createMessageContext(61, { sendMessage }); + const next: NextFunction = vi.fn().mockResolvedValue(undefined); + + await staleUpdateMiddleware(ctx, next); + + expect(next).not.toHaveBeenCalled(); + expect(sendMessage).toHaveBeenCalledWith(1, t("bot.busy_messages_skipped")); + }); + + it("keeps the outage notice for a stale message outside busy windows", async () => { + const sendMessage = vi.fn().mockResolvedValue({ message_id: 1 }); + const ctx = createMessageContext(61, { sendMessage }); + const next: NextFunction = vi.fn().mockResolvedValue(undefined); + + await staleUpdateMiddleware(ctx, next); + + expect(next).not.toHaveBeenCalled(); + expect(sendMessage).toHaveBeenCalledWith(1, t("bot.stale_messages_skipped")); + }); + it("passes through a message dated in the future when clocks drift", async () => { const ctx = createMessageContext(-30); const next: NextFunction = vi.fn().mockResolvedValue(undefined); diff --git a/tests/bot/middleware/update-busy-window.test.ts b/tests/bot/middleware/update-busy-window.test.ts new file mode 100644 index 000000000..ba0ff478f --- /dev/null +++ b/tests/bot/middleware/update-busy-window.test.ts @@ -0,0 +1,122 @@ +import { afterEach, beforeEach, describe, expect, it, vi } from "vitest"; +import type { Context, NextFunction } from "grammy"; +import { updateBusyWindowMiddleware } from "../../../src/bot/middleware/update-busy-window.js"; +import { updateBusyWindowService } from "../../../src/app/services/update-busy-window-service.js"; +import { telegramOutageNoticeService } from "../../../src/app/services/telegram-outage-notice-service.js"; +import { t } from "../../../src/i18n/index.js"; +import { logger } from "../../../src/utils/logger.js"; + +const NOW_MS = Date.UTC(2026, 6, 27, 12, 0, 0); + +function createNext(advanceMs: number): NextFunction { + return vi.fn(async () => { + vi.setSystemTime(NOW_MS + advanceMs); + }) as unknown as NextFunction; +} + +function createChatContext(sendMessage: ReturnType): Context { + return { chat: { id: 1 }, api: { sendMessage } } as unknown as Context; +} + +describe("updateBusyWindowMiddleware", () => { + beforeEach(() => { + vi.useFakeTimers(); + vi.setSystemTime(NOW_MS); + updateBusyWindowService.__resetForTests(); + telegramOutageNoticeService.__resetForTests(); + }); + + afterEach(() => { + vi.useRealTimers(); + updateBusyWindowService.__resetForTests(); + telegramOutageNoticeService.__resetForTests(); + }); + + it("records a window for a handler that outlives the busy-record threshold", async () => { + await updateBusyWindowMiddleware({} as Context, createNext(90_000)); + + expect(updateBusyWindowService.covers(NOW_MS + 30_000)).toBe(true); + }); + + it("does not record a short handler", async () => { + await updateBusyWindowMiddleware({} as Context, createNext(10_000)); + + expect(updateBusyWindowService.covers(NOW_MS + 5_000)).toBe(false); + }); + + it("records the window even when the handler throws", async () => { + const next = vi.fn(async () => { + vi.setSystemTime(NOW_MS + 90_000); + throw new Error("handler failed"); + }) as unknown as NextFunction; + + await expect(updateBusyWindowMiddleware({} as Context, next)).rejects.toThrow("handler failed"); + + expect(updateBusyWindowService.covers(NOW_MS + 30_000)).toBe(true); + }); + + it("sends the busy notice when a handler blocks the chat silently for five seconds", async () => { + const sendMessage = vi.fn().mockResolvedValue({ message_id: 1 }); + const next = vi.fn(async () => { + await vi.advanceTimersByTimeAsync(6_000); + }) as unknown as NextFunction; + + await updateBusyWindowMiddleware(createChatContext(sendMessage), next); + + expect(sendMessage).toHaveBeenCalledWith(1, t("bot.busy_operation")); + }); + + it("does not send the busy notice for a short handler", async () => { + const sendMessage = vi.fn().mockResolvedValue({ message_id: 1 }); + const next = vi.fn(async () => { + await vi.advanceTimersByTimeAsync(3_000); + }) as unknown as NextFunction; + + await updateBusyWindowMiddleware(createChatContext(sendMessage), next); + await vi.advanceTimersByTimeAsync(10_000); + + expect(sendMessage).not.toHaveBeenCalled(); + }); + + it("does not send the busy notice when the chat already shows progress", async () => { + const sendMessage = vi.fn().mockResolvedValue({ message_id: 1 }); + const next = vi.fn(async () => { + await vi.advanceTimersByTimeAsync(3_000); + telegramOutageNoticeService.noteChatSendSucceeded(); + await vi.advanceTimersByTimeAsync(3_000); + }) as unknown as NextFunction; + + await updateBusyWindowMiddleware(createChatContext(sendMessage), next); + await vi.advanceTimersByTimeAsync(10_000); + + expect(sendMessage).not.toHaveBeenCalled(); + }); + + it("sends the busy notice after an early chat update stops being recent", async () => { + const sendMessage = vi.fn().mockResolvedValue({ message_id: 1 }); + const next = vi.fn(async () => { + await vi.advanceTimersByTimeAsync(500); + telegramOutageNoticeService.noteChatSendSucceeded(); + await vi.advanceTimersByTimeAsync(20_000); + }) as unknown as NextFunction; + + await updateBusyWindowMiddleware(createChatContext(sendMessage), next); + + expect(sendMessage).toHaveBeenCalledTimes(1); + expect(sendMessage).toHaveBeenCalledWith(1, t("bot.busy_operation")); + }); + + it("logs and continues when the busy notice cannot be sent", async () => { + const warnSpy = vi.spyOn(logger, "warn").mockImplementation(() => {}); + const sendMessage = vi.fn().mockRejectedValue(new Error("drop")); + const next = vi.fn(async () => { + await vi.advanceTimersByTimeAsync(6_000); + }) as unknown as NextFunction; + + await updateBusyWindowMiddleware(createChatContext(sendMessage), next); + await vi.advanceTimersByTimeAsync(0); + + expect(warnSpy).toHaveBeenCalled(); + warnSpy.mockRestore(); + }); +}); diff --git a/tests/bot/telegram-outage-notices.test.ts b/tests/bot/telegram-outage-notices.test.ts index 865168bb1..d1506bc11 100644 --- a/tests/bot/telegram-outage-notices.test.ts +++ b/tests/bot/telegram-outage-notices.test.ts @@ -2,6 +2,7 @@ import { afterEach, beforeEach, describe, expect, it, vi } from "vitest"; import type { Api } from "grammy"; import { telegramOutageNoticeService } from "../../src/app/services/telegram-outage-notice-service.js"; import { flushTelegramOutageNotices } from "../../src/bot/telegram-outage-notices.js"; +import { t } from "../../src/i18n/index.js"; describe("telegram-outage-notices", () => { beforeEach(() => { @@ -41,6 +42,37 @@ describe("telegram-outage-notices", () => { expect(sendMessage).toHaveBeenCalledTimes(1); }); + it("sends the busy notice for messages delayed by a long handler", async () => { + telegramOutageNoticeService.markMessagesSkipped("busy"); + const sendMessage = vi.fn().mockResolvedValue({ message_id: 1 }); + + await flushTelegramOutageNotices({ + api: { sendMessage } as unknown as Api, + chatId: 1, + }); + + expect(sendMessage).toHaveBeenCalledTimes(1); + expect(sendMessage).toHaveBeenCalledWith(1, t("bot.busy_messages_skipped")); + }); + + it("queues both reasons when a burst mixes outage and busy skips", async () => { + telegramOutageNoticeService.markMessagesSkipped("outage"); + telegramOutageNoticeService.markMessagesSkipped("busy"); + const sendMessage = vi.fn().mockResolvedValue({ message_id: 1 }); + + const flush = flushTelegramOutageNotices({ + api: { sendMessage } as unknown as Api, + chatId: 1, + }); + await vi.advanceTimersByTimeAsync(0); + expect(sendMessage).toHaveBeenCalledTimes(1); + await vi.advanceTimersByTimeAsync(1000); + await flush; + + expect(sendMessage).toHaveBeenNthCalledWith(1, 1, t("bot.stale_messages_skipped")); + expect(sendMessage).toHaveBeenNthCalledWith(2, 1, t("bot.busy_messages_skipped")); + }); + it("spaces two notices one second apart", async () => { telegramOutageNoticeService.markAssistantReplyUndelivered(); telegramOutageNoticeService.markMessagesSkipped(); diff --git a/tests/bot/telegram-server-error-retry-policy.test.ts b/tests/bot/telegram-server-error-retry-policy.test.ts index ff8dba1d3..b68cf4dd2 100644 --- a/tests/bot/telegram-server-error-retry-policy.test.ts +++ b/tests/bot/telegram-server-error-retry-policy.test.ts @@ -108,6 +108,19 @@ describe("bot Telegram 5xx retry policy", () => { expect(mocked.fetch).toHaveBeenCalledTimes(2); }); + it("tracks draft sends as chat activity", async () => { + mocked.fetch.mockResolvedValue(telegramApiResponse(200, true)); + const bot = createBot(container); + telegramOutageNoticeService.__resetForTests(); + + await bot.api.sendMessageDraft(123, 1, "hi"); + expect(telegramOutageNoticeService.msSinceLastChatSend()).not.toBeNull(); + + telegramOutageNoticeService.__resetForTests(); + await bot.api.sendRichMessageDraft(123, 2, { markdown: "hi" }); + expect(telegramOutageNoticeService.msSinceLastChatSend()).not.toBeNull(); + }); + it("retries a connection-not-established error when creating a message", async () => { vi.useFakeTimers(); const refused = Object.assign(new Error("connect ECONNREFUSED"), { code: "ECONNREFUSED" }); diff --git a/tests/helpers/reset-singleton-state.ts b/tests/helpers/reset-singleton-state.ts index 2156472eb..38a732e27 100644 --- a/tests/helpers/reset-singleton-state.ts +++ b/tests/helpers/reset-singleton-state.ts @@ -9,6 +9,7 @@ export async function resetSingletonState(): Promise { { promptAttachment }, { __resetStreamThrottleForTests }, { telegramOutageNoticeService }, + { updateBusyWindowService }, { __resetServerHealthStateForTests }, modelSelectionModule, promptHandoverDeliveryModule, @@ -26,6 +27,7 @@ export async function resetSingletonState(): Promise { import("../../src/app/managers/prompt-attachment-manager.js"), import("../../src/bot/streaming/stream-throttle.js"), import("../../src/app/services/telegram-outage-notice-service.js"), + import("../../src/app/services/update-busy-window-service.js"), import("../../src/opencode/server-health.js"), import("../../src/app/services/model-selection-service.js"), import("../../src/bot/handlers/prompt-handover.js"), @@ -43,6 +45,7 @@ export async function resetSingletonState(): Promise { promptHandover.__resetForTests(); promptAttachment.__resetForTests(); telegramOutageNoticeService.__resetForTests(); + updateBusyWindowService.__resetForTests(); __resetSessionDirectoryCacheForTests(); __resetServerHealthStateForTests();