From a89238cfa622e4b5d4b8d5eb139b0f9f1402c297 Mon Sep 17 00:00:00 2001 From: NinjaLikesCheez Date: Sun, 18 Oct 2026 12:45:07 +0200 Subject: [PATCH] Handle refused Discord acknowledgements once, and tell 10062 from 40060 A deferral that Discord refused had no handler until the work finished, so Node raised an unhandled rejection (logged and sent to Sentry with no actor) before the adapter logged it again. A refused placeholder reply was caught by the dispatcher as command.failed and captured. The deferral now has a no-op catch at creation (still awaited later), and an onPending failure is rethrown by the dispatcher unreported, so the adapter handles it once. The handler still doesn't run. Only 40060 is now treated as a second instance (discord.duplicate_handler). 10062 means Pixel acknowledged too slowly: it is logged as discord.slow_ack with the command and actor, and reported as a SlowAcknowledgementError naming the command. Co-Authored-By: Claude Opus 5.5 --- CHANGELOG.md | 5 + docs/runbook.md | 6 +- src/adapters/discord/discord.test.ts | 57 ++++++++ src/adapters/discord/index.ts | 41 ++---- .../discord/interaction-errors.test.ts | 134 +++++++++++++++--- src/adapters/discord/interaction-errors.ts | 82 ++++++++++- src/adapters/discord/respond.ts | 11 +- src/core/dispatcher.test.ts | 34 ++++- src/core/dispatcher.ts | 9 +- vitest.config.ts | 2 +- 10 files changed, 320 insertions(+), 61 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 1f5410c..c3ceb15 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -9,6 +9,11 @@ Until 1.0.0, releases stay on 0.x: `Added` bumps minor, `Fixed`/`Changed` (and t ## [Unreleased] +### Fixed + +- Discord: when Discord refused a slow command's acknowledgement (its deferral), the failure is no longer also logged and sent to Sentry as an unhandled rejection with no user or command; it is handled once, by the adapter. A command whose "Checking…" placeholder couldn't be posted (`/status`, `/ha` and others) is no longer reported as a failed command: the handler still doesn't run, and the adapter logs it like any other refused acknowledgement. +- Discord: only "already acknowledged" (40060) is logged as `discord.duplicate_handler` (a second Pixel on the token). "Unknown interaction" (10062) means Pixel didn't acknowledge within Discord's 3 seconds, so it is now logged as `discord.slow_ack` with the command and who ran it, and reported to Sentry as a `SlowAcknowledgementError` naming the command. + ## [0.17.0] - 2026-10-15 ### Added diff --git a/docs/runbook.md b/docs/runbook.md index e18ae00..07cb37c 100644 --- a/docs/runbook.md +++ b/docs/runbook.md @@ -539,10 +539,14 @@ Do not run `just bump` on a feature branch unless you are deliberately cutting a **Duplicate replies, "I don't know that command" for a command Discord lists, or Discord shows an error and then the action still happens** -Two instances are connected with the same token. Discord's slash list comes from `just register`; each running Pixel answers from its own code. An older instance replies "I don't know that command" (or answers first); the newer one still does the work and then fails to ACK (Discord 40060 / 10062). Logs on either side show `discord.duplicate_handler`. +Two instances are connected with the same token. Discord's slash list comes from `just register`; each running Pixel answers from its own code. An older instance replies "I don't know that command" (or answers first); the newer one still does the work and then fails to ACK (Discord 40060, "already acknowledged"). Logs on either side show `discord.duplicate_handler`. Find and stop the extra one: `docker ps` locally (leftover `just dev` or a worktree container), and check that nobody has a copy on a laptop or another server. In Azure: `az containerapp replica list -g pixel-dev -n pixel-dev -o table` must show one replica (same for `pixel-prod` once it exists). Never fix this by raising limits. CD pins min=max=1. Retry the command after only one instance is left. +**Discord says "The application did not respond"** (log `discord.slow_ack`, Sentry `SlowAcknowledgementError`) + +Pixel didn't acknowledge the command within Discord's 3 seconds (Discord 10062, "unknown interaction"). That is Pixel being slow, not a second instance. The log and the Sentry title name the command. Usual causes: the host is overloaded or the event loop was blocked, the network to Discord is slow, or a command that opens a form did slow work before showing it. One-offs after a restart or a Discord hiccup can be ignored. If it repeats for one command, open an issue with the command and the time. + **SpaceAPI is down** (`/status` says "Couldn't check") Pixel can't tell whether the space is open, so it says so rather than guess. Check `https://spaceapi.pixelbar.nl/` yourself. When it's back, `/status` works again by itself and changes are announced as normal. Nothing to restart. Pixel never announces a change it didn't see itself, so a restart or an outage never produces a stale announcement. If it stays down, that is a problem with the space's own server, not with Pixel. diff --git a/src/adapters/discord/discord.test.ts b/src/adapters/discord/discord.test.ts index f76950f..ae85d4f 100644 --- a/src/adapters/discord/discord.test.ts +++ b/src/adapters/discord/discord.test.ts @@ -428,6 +428,63 @@ describe("respond", () => { ); }); + describe("when Discord refuses the acknowledgement", () => { + const expired = Object.assign(new Error("Unknown interaction"), { code: 10062 }); + const unhandled: unknown[] = []; + const onUnhandled = (reason: unknown) => unhandled.push(reason); + // Captured before fake timers replace it. + const realSetImmediate = setImmediate; + beforeEach(() => { + unhandled.length = 0; + process.on("unhandledRejection", onUnhandled); + }); + afterEach(() => { + process.off("unhandledRejection", onUnhandled); + }); + + it("rejects once with a failed deferral, never as an unhandled rejection", async () => { + // A plain function: a vi.fn would itself handle the promise it returns. + let deferrals = 0; + const i = { + ...fakeInteraction(), + deferReply: () => { + deferrals++; + return Promise.reject(expired); + }, + }; + const done = respond(i, { + defaultPrivate: false, + deferAfterMs: 1500, + work: delayed(publicResult, 3000), + }); + const outcome = done.catch((error: unknown) => error); + await vi.advanceTimersByTimeAsync(1600); + // Let Node look for unhandled rejections while the work is still running. + await new Promise((resolve) => realSetImmediate(resolve)); + expect(deferrals).toBe(1); + expect(unhandled).toEqual([]); + await vi.advanceTimersByTimeAsync(1400); + expect(await outcome).toBe(expired); + expect(i.editReply).not.toHaveBeenCalled(); + }); + + it("rejects with a failed placeholder", async () => { + const i = fakeInteraction(); + i.reply.mockImplementation(async () => Promise.reject(expired)); + await expect( + respond(i, { + defaultPrivate: false, + deferAfterMs: 1500, + work: async (showPending) => { + await showPending({ reply: { text: "Checking…" }, private: false }); + return publicResult; + }, + }), + ).rejects.toBe(expired); + expect(i.editReply).not.toHaveBeenCalled(); + }); + }); + describe("with a placeholder", () => { const checking: DispatchResult = { reply: { embeds: [{ title: "Checking…" }] }, diff --git a/src/adapters/discord/index.ts b/src/adapters/discord/index.ts index 6813196..e6fc6f0 100644 --- a/src/adapters/discord/index.ts +++ b/src/adapters/discord/index.ts @@ -1,5 +1,5 @@ import { Client, Events, GatewayIntentBits } from "discord.js"; -import { actorLogFields, type PlatformActor } from "../../core/access.ts"; +import type { PlatformActor } from "../../core/access.ts"; import type { Publisher } from "../../core/announcement.ts"; import type { AnnouncementRoutes } from "../../core/announcement-routes.ts"; import type { Announcer } from "../../core/announcer.ts"; @@ -31,7 +31,7 @@ import { createModalHandler, discordActor, } from "./handlers.ts"; -import { isConsumedInteractionError } from "./interaction-errors.ts"; +import { handleInteractionFailure } from "./interaction-errors.ts"; import { createPresencePublisher } from "./presence.ts"; import { DiscordRoleMirror, type RoleMapping } from "./role-mirror.ts"; @@ -234,16 +234,11 @@ export function createDiscordAdapter(deps: DiscordAdapterDeps): DiscordAdapter { } if (interaction.isModalSubmit()) { handleModal(interaction).catch((error: unknown) => { - const actor = discordActor(interaction.user); - if (isConsumedInteractionError(error)) { - logger.warn( - { err: error, event: "discord.duplicate_handler", ...actorLogFields(actor) }, - "another Pixel already answered this form; is a second instance on this token?", - ); - return; - } - logger.error({ err: error, ...actorLogFields(actor) }, "failed to handle a form"); - reportError(error, actor); + handleInteractionFailure( + error, + { logger, reportError }, + { actor: discordActor(interaction.user) }, + ); }); return; } @@ -273,25 +268,11 @@ export function createDiscordAdapter(deps: DiscordAdapterDeps): DiscordAdapter { }, }); handleCommand(incoming, displayName).catch((error: unknown) => { - const actor = discordActor(interaction.user, displayName); - if (isConsumedInteractionError(error)) { - logger.warn( - { - err: error, - event: "discord.duplicate_handler", - command: interaction.commandName, - ...actorLogFields(actor), - }, - "another Pixel already answered this interaction; is a second instance on this token?", - ); - return; - } - logger.error( - { err: error, command: interaction.commandName, ...actorLogFields(actor) }, - "failed to handle interaction", + handleInteractionFailure( + error, + { logger, reportError }, + { actor: discordActor(interaction.user, displayName), command: interaction.commandName }, ); - // Name who it happened to, by ID, so the report can be traced. - reportError(error, actor); }); }); diff --git a/src/adapters/discord/interaction-errors.test.ts b/src/adapters/discord/interaction-errors.test.ts index 5c26b82..2e44239 100644 --- a/src/adapters/discord/interaction-errors.test.ts +++ b/src/adapters/discord/interaction-errors.test.ts @@ -1,19 +1,119 @@ -import { describe, expect, it } from "vitest"; -import { isConsumedInteractionError } from "./interaction-errors.ts"; - -describe("isConsumedInteractionError", () => { - it("matches Discord 40060 (already acknowledged) and 10062 (unknown interaction)", () => { - expect(isConsumedInteractionError({ code: 40060 })).toBe(true); - expect(isConsumedInteractionError({ code: 10062 })).toBe(true); - expect(isConsumedInteractionError({ code: "40060" })).toBe(true); - expect(isConsumedInteractionError({ code: "10062" })).toBe(true); - }); - - it("ignores other errors", () => { - expect(isConsumedInteractionError(undefined)).toBe(false); - expect(isConsumedInteractionError("already acknowledged")).toBe(false); - expect(isConsumedInteractionError({ message: "Unknown interaction" })).toBe(false); - expect(isConsumedInteractionError({ code: 50013 })).toBe(false); - expect(isConsumedInteractionError(new Error("boom"))).toBe(false); +import { describe, expect, it, vi } from "vitest"; +import type { PlatformActor } from "../../core/access.ts"; +import type { Logger } from "../../core/logger.ts"; +import { IDS } from "../../testing/fixtures.ts"; +import { + classifyInteractionError, + handleInteractionFailure, + SlowAcknowledgementError, +} from "./interaction-errors.ts"; + +describe("classifyInteractionError", () => { + it("calls Discord 40060 (already acknowledged) a duplicate", () => { + expect(classifyInteractionError({ code: 40060 })).toBe("duplicate"); + expect(classifyInteractionError({ code: "40060" })).toBe("duplicate"); + }); + + it("calls Discord 10062 (unknown interaction) expired, not a duplicate", () => { + expect(classifyInteractionError({ code: 10062 })).toBe("expired"); + expect(classifyInteractionError({ code: "10062" })).toBe("expired"); + }); + + it("leaves other errors alone", () => { + expect(classifyInteractionError(undefined)).toBe("other"); + expect(classifyInteractionError(null)).toBe("other"); + expect(classifyInteractionError("already acknowledged")).toBe("other"); + expect(classifyInteractionError({ message: "Unknown interaction" })).toBe("other"); + expect(classifyInteractionError({ code: 50013 })).toBe("other"); + expect(classifyInteractionError(new Error("boom"))).toBe("other"); + }); +}); + +describe("handleInteractionFailure", () => { + const actor: PlatformActor = { + platform: "discord", + userId: IDS.member, + displayName: "Member", + handle: "member_handle", + chat: "group", + }; + const who = { user: `discord:${IDS.member}`, userName: "Member", userHandle: "member_handle" }; + + function setup() { + const logger = { + debug: vi.fn(), + info: vi.fn(), + warn: vi.fn(), + error: vi.fn(), + child: vi.fn(), + } satisfies Logger; + const reportError = vi.fn(); + return { logger, reportError }; + } + + const discordError = (code: number) => Object.assign(new Error(`discord ${code}`), { code }); + + it("warns about a second instance on 40060, without reporting it", () => { + const deps = setup(); + const error = discordError(40060); + handleInteractionFailure(error, deps, { actor, command: "status" }); + expect(deps.logger.warn).toHaveBeenCalledWith( + { err: error, command: "status", ...who, event: "discord.duplicate_handler" }, + expect.stringContaining("second instance"), + ); + expect(deps.logger.error).not.toHaveBeenCalled(); + expect(deps.reportError).not.toHaveBeenCalled(); + }); + + it("says form for a duplicate form submission", () => { + const deps = setup(); + handleInteractionFailure(discordError(40060), deps, { actor }); + expect(deps.logger.warn).toHaveBeenCalledWith( + expect.objectContaining({ event: "discord.duplicate_handler" }), + expect.stringContaining("this form"), + ); + expect(deps.logger.warn.mock.calls[0]?.[0]).not.toHaveProperty("command"); + }); + + it("reports 10062 as a slow acknowledgement of the command, not a second instance", () => { + const deps = setup(); + const error = discordError(10062); + handleInteractionFailure(error, deps, { actor, command: "ha" }); + expect(deps.logger.warn).not.toHaveBeenCalled(); + expect(deps.logger.error).toHaveBeenCalledWith( + { err: error, command: "ha", ...who, event: "discord.slow_ack" }, + expect.not.stringContaining("second instance"), + ); + const [reported, reportedActor] = deps.reportError.mock.calls[0] ?? []; + expect(reported).toBeInstanceOf(SlowAcknowledgementError); + expect((reported as Error).message).toContain("/ha"); + expect((reported as Error).cause).toBe(error); + expect(reportedActor).toBe(actor); + }); + + it("names a form when a slow form submission expires", () => { + const deps = setup(); + handleInteractionFailure(discordError(10062), deps, { actor }); + expect(deps.reportError).toHaveBeenCalledWith( + expect.objectContaining({ message: expect.stringContaining("a form") }), + actor, + ); + }); + + it("logs and reports anything else with who it happened to", () => { + const deps = setup(); + const error = new Error("boom"); + handleInteractionFailure(error, deps, { actor, command: "status" }); + expect(deps.logger.error).toHaveBeenCalledWith( + { err: error, command: "status", ...who }, + "failed to handle interaction", + ); + expect(deps.reportError).toHaveBeenCalledWith(error, actor); + + handleInteractionFailure(error, deps, { actor }); + expect(deps.logger.error).toHaveBeenLastCalledWith( + { err: error, ...who }, + "failed to handle a form", + ); }); }); diff --git a/src/adapters/discord/interaction-errors.ts b/src/adapters/discord/interaction-errors.ts index e574675..ffb0e33 100644 --- a/src/adapters/discord/interaction-errors.ts +++ b/src/adapters/discord/interaction-errors.ts @@ -1,11 +1,81 @@ +import { actorLogFields, type PlatformActor } from "../../core/access.ts"; +import type { Logger } from "../../core/logger.ts"; + /** - * Discord already used this interaction (another handler replied, or Discord - * dropped it). Typical when two Pixels share one bot token. + * Why Discord wouldn't take an answer to an interaction. * - * 40060 = already acknowledged. 10062 = unknown / expired interaction. + * - `duplicate` (40060, already acknowledged): something else answered first. + * Typical when two Pixels share one bot token. + * - `expired` (10062, unknown interaction): nobody acknowledged it within + * Discord's 3 s. That's Pixel (or the network) being too slow, not a second + * instance: a second instance answering first gives 40060. + * - `other`: anything else. */ -export function isConsumedInteractionError(error: unknown): boolean { - if (error === null || typeof error !== "object" || !("code" in error)) return false; +export type InteractionFailure = "duplicate" | "expired" | "other"; + +export function classifyInteractionError(error: unknown): InteractionFailure { + if (error === null || typeof error !== "object" || !("code" in error)) return "other"; const code = error.code; - return code === 40060 || code === 10062 || code === "40060" || code === "10062"; + if (code === 40060 || code === "40060") return "duplicate"; + if (code === 10062 || code === "10062") return "expired"; + return "other"; +} + +/** + * Reported when Discord expired an interaction before Pixel acknowledged it. + * The message names the command so Sentry groups slow commands apart. + */ +export class SlowAcknowledgementError extends Error { + constructor(what: string, cause: unknown) { + super(`Discord expired ${what} before Pixel acknowledged it`, { cause }); + this.name = "SlowAcknowledgementError"; + } +} + +export type InteractionFailureDeps = { + logger: Logger; + reportError: (error: unknown, actor?: PlatformActor) => void; +}; + +/** + * Logs and reports an error that escaped a command (`command` set) or form + * handler. Never logs what was typed: only the command and who ran it. + */ +export function handleInteractionFailure( + error: unknown, + { logger, reportError }: InteractionFailureDeps, + { actor, command }: { actor: PlatformActor; command?: string }, +): void { + const fields = { + err: error, + ...(command === undefined ? {} : { command }), + ...actorLogFields(actor), + }; + switch (classifyInteractionError(error)) { + case "duplicate": + logger.warn( + { ...fields, event: "discord.duplicate_handler" }, + command === undefined + ? "another Pixel already answered this form; is a second instance on this token?" + : "another Pixel already answered this interaction; is a second instance on this token?", + ); + return; + case "expired": + logger.error( + { ...fields, event: "discord.slow_ack" }, + "Discord expired the interaction before Pixel acknowledged it", + ); + reportError( + new SlowAcknowledgementError(command === undefined ? "a form" : `/${command}`, error), + actor, + ); + return; + case "other": + logger.error( + fields, + command === undefined ? "failed to handle a form" : "failed to handle interaction", + ); + // Name who it happened to, by ID, so the report can be traced. + reportError(error, actor); + } } diff --git a/src/adapters/discord/respond.ts b/src/adapters/discord/respond.ts index 3c4a20d..ee40961 100644 --- a/src/adapters/discord/respond.ts +++ b/src/adapters/discord/respond.ts @@ -38,6 +38,9 @@ export type RespondOptions = { * the public message is deleted and the result is sent as an ephemeral * follow-up. If it was private, the result stays private — never more visible * than intended. + * + * If Discord refuses an acknowledgement (e.g. the interaction expired or was + * already answered), the returned promise rejects with that error, once. */ export async function respond( interaction: Respondable, @@ -46,7 +49,13 @@ export async function respond( let acknowledged: Promise | undefined; let acknowledgedPrivate = defaultPrivate; const timer = setTimeout(() => { - acknowledged = interaction.deferReply(defaultPrivate ? { flags: MessageFlags.Ephemeral } : {}); + const deferral = interaction.deferReply( + defaultPrivate ? { flags: MessageFlags.Ephemeral } : {}, + ); + // Awaited below once the work is done, which is where a failure surfaces. + // Until then it must not count as unhandled while the work still runs. + deferral.catch(() => {}); + acknowledged = deferral; }, deferAfterMs); const showPending: ShowPending = async (pending) => { diff --git a/src/core/dispatcher.test.ts b/src/core/dispatcher.test.ts index 8b9110c..4c254fd 100644 --- a/src/core/dispatcher.test.ts +++ b/src/core/dispatcher.test.ts @@ -281,14 +281,40 @@ describe("Dispatcher", () => { expect(onPending).not.toHaveBeenCalled(); }); - it("turns a failure to show the placeholder into a reported internal error", async () => { + it("leaves a failure to show the placeholder to the adapter, without running the handler", async () => { const handler = vi.fn(async () => ({ text: "x" })); - const { dispatcher, reporter } = setup([command({ name: "x", placeholder, handler })]); + const { dispatcher, reporter, entries } = setup([ + command({ name: "x", placeholder, handler }), + ]); + const error = Object.assign(new Error("Interaction has already been acknowledged."), { + code: 40060, + }); + await expect( + dispatcher.dispatch( + { actor: as(IDS.guest), command: "x", args: {} }, + { onPending: async () => Promise.reject(error) }, + ), + ).rejects.toBe(error); + expect(handler).not.toHaveBeenCalled(); + // Not a command failure: the adapter logs and reports it. + expect(reporter.capture).not.toHaveBeenCalled(); + expect(entries.some((e) => e.obj.event === "command.failed")).toBe(false); + }); + + it("still reports a handler failure after the placeholder was shown", async () => { + const { dispatcher, reporter } = setup([ + command({ + name: "x", + placeholder, + handler: async () => { + throw new Error("boom"); + }, + }), + ]); const result = await dispatcher.dispatch( { actor: as(IDS.guest), command: "x", args: {} }, - { onPending: async () => Promise.reject(new Error("discord down")) }, + { onPending: async () => {} }, ); - expect(handler).not.toHaveBeenCalled(); expect(result.reply.text).toBe(MESSAGES.internalError); expect(reporter.capture).toHaveBeenCalled(); }); diff --git a/src/core/dispatcher.ts b/src/core/dispatcher.ts index 6690241..502c8a7 100644 --- a/src/core/dispatcher.ts +++ b/src/core/dispatcher.ts @@ -75,7 +75,9 @@ export type DispatchHooks = { /** * Called with the command's placeholder after access and argument checks * pass, before the handler runs. Adapters show it immediately and later - * replace it with the result. + * replace it with the result. If it throws, the handler doesn't run and + * `dispatch` rejects with that error, unlogged and unreported: it's the + * platform's failure, so the adapter decides how to log and report it. */ onPending?: (pending: DispatchResult) => Promise; }; @@ -287,14 +289,17 @@ export class Dispatcher { "command executed", ); + let showingPending = false; try { const valid = validateArgs(definition, args, users, channels); if (definition.placeholder && hooks.onPending) { const { placeholder } = definition; + showingPending = true; await hooks.onPending({ reply: placeholder, private: placeholder.private ?? definition.private ?? false, }); + showingPending = false; } const run = () => definition.handler({ @@ -312,6 +317,8 @@ export class Dispatcher { executed("ok"); return { reply, private: reply.private ?? definition.private ?? false }; } catch (error) { + // The adapter couldn't show the placeholder; see `DispatchHooks.onPending`. + if (showingPending) throw error; if (error instanceof UserFacingError) { executed("user_error"); return privateText(error.message); diff --git a/vitest.config.ts b/vitest.config.ts index 3b9a540..5b8e1bd 100644 --- a/vitest.config.ts +++ b/vitest.config.ts @@ -21,7 +21,7 @@ export default defineConfig({ "src/core/**": { lines: 98, statements: 98, functions: 90, branches: 95 }, "src/services/**": { lines: 98, statements: 98, functions: 98, branches: 85 }, "src/features/**": { lines: 95, statements: 95, functions: 95, branches: 90 }, - "src/adapters/discord/{args,commands,handlers,render,respond,announce-render,announce-publishers,announce-state,calendar-map,calendar-source,forms,direct-message,presence}.ts": + "src/adapters/discord/{args,commands,handlers,render,respond,announce-render,announce-publishers,announce-state,calendar-map,calendar-source,forms,direct-message,presence,interaction-errors}.ts": { lines: 98, statements: 98,