Handle refused Discord acknowledgements once, and tell 10062 from 40060

CHANGELOG.md

@@ -12,6 +12,8 @@ Until 1.0.0, releases stay on 0.x: `Added` bumps minor, `Fixed`/`Changed` (and t
 ### Fixed
 
 - `/spacestate`: the Sentry context for a failed call now says why the network failed (`errorCause`, such as `ENOTFOUND`, `ECONNREFUSED` or `UNEXPECTED_REDIRECT`), and shows the address without its query. Sentry was replacing the old redacted address with `[Filtered]`.
+- 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.
 - Sentry: traces no longer carry Discord interaction tokens. Every reply to a command goes to a Discord URL with the interaction token in its path, and the request's span (`url.full`, `url.path`) and `http` breadcrumb kept it, so anyone with access to the Sentry project could post as the bot for 15 minutes after each command. Spans now go through the same scrubbing as errors, breadcrumbs and logs, and the token in `/interactions/<id>/<token>` and `/webhooks/<id>/<token>` paths is shown as `[redacted]`. The scrubbing also no longer skips an object that appears twice in what is sent, and keeps an error's message and stack (scrubbed) instead of dropping them.
 - CD on `main` no longer loses an image: runs queue instead of cancelling each other, and each one publishes when an image path changed since the last green CD run, not just since the previous push. Before, a docs-only merge right after a code merge cancelled that merge's publish and then skipped its own, so the code merge never got a GHCR image or a Sentry release.
 - The Release workflow runs `just check` on the `main` commit it is about to release, and only tags, publishes and deploys to prod if it passes. CI on `main` can be cancelled or red and never runs on the bump commit, so before this nothing tested what reached prod.

docs/runbook.md

@@ -541,10 +541,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.

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<void>((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…" }] },

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

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

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);
+	}
 }