From 3398fc38204fbe8881b46a97e37565b68dd76a6f Mon Sep 17 00:00:00 2001 From: Peter Steinberger Date: Thu, 8 Jan 2026 01:28:17 +0100 Subject: [PATCH] fix: format slow listener logs --- CHANGELOG.md | 1 + src/discord/monitor.ts | 89 ++++++++++++++++++++++++++++-------- src/infra/format-duration.ts | 34 ++++++++++++++ src/web/auto-reply.ts | 6 +-- 4 files changed, 107 insertions(+), 23 deletions(-) create mode 100644 src/infra/format-duration.ts diff --git a/CHANGELOG.md b/CHANGELOG.md index f410a1f0d..b82ad24f9 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -18,6 +18,7 @@ - Auto-reply: removed `autoReply` from Discord/Slack/Telegram channel configs; use `requireMention` instead (Telegram topics now support `requireMention` overrides). ### Fixes +- Discord: format slow listener logs in seconds to match shared duration style. - Agent: avoid duplicating context/skills when SDK rebuilds the system prompt. (#418) - Signal: reconnect SSE monitor with abortable backoff; log stream errors. Thanks @nexty5870 for PR #430. - Gateway: pass resolved provider as messageProvider for agent runs so provider-specific tools are available. Thanks @imfing for PR #389. diff --git a/src/discord/monitor.ts b/src/discord/monitor.ts index 11482199d..a61b51971 100644 --- a/src/discord/monitor.ts +++ b/src/discord/monitor.ts @@ -46,6 +46,7 @@ import type { ReplyToMode } from "../config/config.js"; import { loadConfig } from "../config/config.js"; import { resolveStorePath, updateLastRoute } from "../config/sessions.js"; import { danger, logVerbose, shouldLogVerbose } from "../globals.js"; +import { formatDurationSeconds } from "../infra/format-duration.js"; import { enqueueSystemEvent } from "../infra/system-events.js"; import { getChildLogger } from "../logging.js"; import { detectMime } from "../media/mime.js"; @@ -101,6 +102,22 @@ type DiscordThreadStarter = { }; const DISCORD_THREAD_STARTER_CACHE = new Map(); +const DISCORD_SLOW_LISTENER_THRESHOLD_MS = 1000; + +function logSlowDiscordListener(params: { + logger: ReturnType | undefined; + listener: string; + event: string; + durationMs: number; +}) { + if (params.durationMs < DISCORD_SLOW_LISTENER_THRESHOLD_MS) return; + const duration = formatDurationSeconds(params.durationMs, { + decimals: 1, + unit: "seconds", + }); + const message = `[EventQueue] Slow listener detected: ${params.listener} took ${duration} for event ${params.event}`; + params.logger?.warn ? params.logger.warn(message) : console.warn(message); +} async function resolveDiscordThreadStarter(params: { channel: DiscordThreadChannel; @@ -295,6 +312,7 @@ export async function monitorDiscordProvider(opts: MonitorDiscordOpts = {}) { publicKey: "a", token, autoDeploy: nativeEnabled, + eventQueue: { logSlowListeners: false }, }, { commands, @@ -352,7 +370,7 @@ export async function monitorDiscordProvider(opts: MonitorDiscordOpts = {}) { guildEntries, }); - client.listeners.push(new DiscordMessageListener(messageHandler)); + client.listeners.push(new DiscordMessageListener(messageHandler, logger)); client.listeners.push( new DiscordReactionListener({ runtime, @@ -1021,12 +1039,25 @@ export function createDiscordMessageHandler(params: { } class DiscordMessageListener extends MessageCreateListener { - constructor(private handler: DiscordMessageHandler) { + constructor( + private handler: DiscordMessageHandler, + private logger?: ReturnType, + ) { super(); } async handle(data: DiscordMessageEvent, client: Client) { - await this.handler(data, client); + const startedAt = Date.now(); + try { + await this.handler(data, client); + } finally { + logSlowDiscordListener({ + logger: this.logger, + listener: this.constructor.name, + event: this.type, + durationMs: Date.now() - startedAt, + }); + } } } @@ -1043,14 +1074,24 @@ class DiscordReactionListener extends MessageReactionAddListener { } async handle(data: DiscordReactionEvent, client: Client) { - await handleDiscordReactionEvent({ - data, - client, - action: "added", - botUserId: this.params.botUserId, - guildEntries: this.params.guildEntries, - logger: this.params.logger, - }); + const startedAt = Date.now(); + try { + await handleDiscordReactionEvent({ + data, + client, + action: "added", + botUserId: this.params.botUserId, + guildEntries: this.params.guildEntries, + logger: this.params.logger, + }); + } finally { + logSlowDiscordListener({ + logger: this.params.logger, + listener: this.constructor.name, + event: this.type, + durationMs: Date.now() - startedAt, + }); + } } } @@ -1067,14 +1108,24 @@ class DiscordReactionRemoveListener extends MessageReactionRemoveListener { } async handle(data: DiscordReactionEvent, client: Client) { - await handleDiscordReactionEvent({ - data, - client, - action: "removed", - botUserId: this.params.botUserId, - guildEntries: this.params.guildEntries, - logger: this.params.logger, - }); + const startedAt = Date.now(); + try { + await handleDiscordReactionEvent({ + data, + client, + action: "removed", + botUserId: this.params.botUserId, + guildEntries: this.params.guildEntries, + logger: this.params.logger, + }); + } finally { + logSlowDiscordListener({ + logger: this.params.logger, + listener: this.constructor.name, + event: this.type, + durationMs: Date.now() - startedAt, + }); + } } } diff --git a/src/infra/format-duration.ts b/src/infra/format-duration.ts new file mode 100644 index 000000000..5b9892f35 --- /dev/null +++ b/src/infra/format-duration.ts @@ -0,0 +1,34 @@ +export type FormatDurationSecondsOptions = { + decimals?: number; + unit?: "s" | "seconds"; +}; + +export function formatDurationSeconds( + ms: number, + options: FormatDurationSecondsOptions = {}, +): string { + if (!Number.isFinite(ms)) return "unknown"; + const decimals = options.decimals ?? 1; + const unit = options.unit ?? "s"; + const seconds = Math.max(0, ms) / 1000; + const fixed = seconds.toFixed(Math.max(0, decimals)); + const trimmed = fixed.replace(/\.0+$/, "").replace(/(\.\d*[1-9])0+$/, "$1"); + return unit === "seconds" ? `${trimmed} seconds` : `${trimmed}s`; +} + +export type FormatDurationMsOptions = { + decimals?: number; + unit?: "s" | "seconds"; +}; + +export function formatDurationMs( + ms: number, + options: FormatDurationMsOptions = {}, +): string { + if (!Number.isFinite(ms)) return "unknown"; + if (ms < 1000) return `${ms}ms`; + return formatDurationSeconds(ms, { + decimals: options.decimals ?? 2, + unit: options.unit ?? "s", + }); +} diff --git a/src/web/auto-reply.ts b/src/web/auto-reply.ts index 8f4d46b4a..94269aa11 100644 --- a/src/web/auto-reply.ts +++ b/src/web/auto-reply.ts @@ -40,6 +40,7 @@ import { import { logVerbose, shouldLogVerbose } from "../globals.js"; import { emitHeartbeatEvent } from "../infra/heartbeat-events.js"; import { enqueueSystemEvent } from "../infra/system-events.js"; +import { formatDurationMs } from "../infra/format-duration.js"; import { registerUnhandledRejectionHandler } from "../infra/unhandled-rejections.js"; import { createSubsystemLogger, getChildLogger } from "../logging.js"; import { toLocationContext } from "../providers/location.js"; @@ -132,9 +133,6 @@ export type WebMonitorTuning = { accountId?: string; }; -const formatDuration = (ms: number) => - ms >= 1000 ? `${(ms / 1000).toFixed(2)}s` : `${ms}ms`; - export { HEARTBEAT_PROMPT, HEARTBEAT_TOKEN, SILENT_REPLY_TOKEN }; export type WebProviderStatus = { @@ -1654,7 +1652,7 @@ export async function monitorWebProvider( "web reconnect: scheduling retry", ); runtime.error( - `WhatsApp Web connection closed (status ${statusCode}). Retry ${reconnectAttempts}/${reconnectPolicy.maxAttempts || "∞"} in ${formatDuration(delay)}… (${errorStr})`, + `WhatsApp Web connection closed (status ${statusCode}). Retry ${reconnectAttempts}/${reconnectPolicy.maxAttempts || "∞"} in ${formatDurationMs(delay)}… (${errorStr})`, ); await closeListener(); try {