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();