fix: format slow listener logs

This commit is contained in:
Peter Steinberger
2026-01-08 01:28:17 +01:00
parent 67213e0fc6
commit 3398fc3820
4 changed files with 107 additions and 23 deletions

View File

@@ -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.

View File

@@ -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<string, DiscordThreadStarter>();
const DISCORD_SLOW_LISTENER_THRESHOLD_MS = 1000;
function logSlowDiscordListener(params: {
logger: ReturnType<typeof getChildLogger> | 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<typeof getChildLogger>,
) {
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,
});
}
}
}

View File

@@ -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",
});
}

View File

@@ -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 {