From ea534b86db7f37de286aeb209bd62b34885339ca Mon Sep 17 00:00:00 2001 From: Musiker15 Date: Tue, 18 Aug 2026 00:12:36 +0200 Subject: [PATCH] fix(bot): bound outbox delivery retries, treat 50278 as permanent An applicant who leaves the guild makes their queued DM undeliverable forever. Discord answers that with 50278 ("no mutual guilds"), but only 50007 was treated as permanent, so those rows were never retired: the poller picked them up every 15 seconds and failed again, indefinitely. Three users were in that state in production. The retry noise is the smaller half. The poller selects `take: 25` ordered by createdAt ascending, so permanently stuck rows are the oldest and hold their slots for good. At 25 of them the outbox stops entirely, and not just for DMs: review embeds and the guild activity log share the table. Two changes, one for this bug and one for its class: - apps/bot/src/delivery-policy.ts collects the permanent DM codes (now 50007 and 50278), the attempt ceiling and the backoff, free of discord.js and Prisma so it can be tested. New permanent codes belong there. - Notification gains attempts / lastError / nextAttemptAt, the same shape WebhookDelivery already uses. A failed row backs off exponentially and is retired after 8 attempts, roughly two hours, which outlasts an ordinary Discord incident. readAt keeps meaning "retired", covering delivered and never-deliverable alike; lastError is what tells them apart afterwards. The poller's transient path now records why a row failed instead of only logging it, which is the part that was missing when diagnosing this: the evidence lived in a log that rotates, not in the row. The migration folds next_attempt_at into the pending partial index and drops its predecessor rather than keeping both over the same rows. Existing rows default to a due timestamp, so they are picked up immediately after deploy, and the three stuck ones retire on the first poll. --- apps/bot/src/delivery-policy.test.ts | 62 ++++++++++++++++ apps/bot/src/delivery-policy.ts | 48 +++++++++++++ apps/bot/src/notifications.ts | 72 ++++++++++++++++--- .../migration.sql | 25 +++++++ packages/db/prisma/schema.prisma | 7 ++ 5 files changed, 203 insertions(+), 11 deletions(-) create mode 100644 apps/bot/src/delivery-policy.test.ts create mode 100644 apps/bot/src/delivery-policy.ts create mode 100644 packages/db/prisma/migrations/20260818003000_notification_retry_bounds/migration.sql diff --git a/apps/bot/src/delivery-policy.test.ts b/apps/bot/src/delivery-policy.test.ts new file mode 100644 index 0000000..eac9cad --- /dev/null +++ b/apps/bot/src/delivery-policy.test.ts @@ -0,0 +1,62 @@ +import { describe, expect, it } from "vitest"; + +import { + isExhausted, + isTerminalDmCode, + MAX_DELIVERY_ATTEMPTS, + nextAttemptAt, + retryDelayMs, +} from "./delivery-policy.js"; + +describe("terminal DM codes", () => { + it("treats both 'cannot DM this user' codes as permanent", () => { + expect(isTerminalDmCode(50007)).toBe(true); + // The one that was missing and caused rows to be retried forever. + expect(isTerminalDmCode(50278)).toBe(true); + }); + + it("accepts the string form discord.js sometimes hands back", () => { + expect(isTerminalDmCode("50278")).toBe(true); + }); + + it("leaves genuinely transient failures retryable", () => { + expect(isTerminalDmCode(500)).toBe(false); + expect(isTerminalDmCode(undefined)).toBe(false); + expect(isTerminalDmCode(null)).toBe(false); + }); +}); + +describe("backoff", () => { + it("grows with each failure", () => { + expect(retryDelayMs(0)).toBe(30_000); + expect(retryDelayMs(1)).toBe(60_000); + expect(retryDelayMs(2)).toBe(120_000); + }); + + it("is capped so a stuck row cannot drift years into the future", () => { + expect(retryDelayMs(50)).toBe(30 * 60_000); + }); + + it("never returns a negative or NaN delay for junk input", () => { + expect(retryDelayMs(-5)).toBe(30_000); + expect(retryDelayMs(1.7)).toBe(60_000); + }); + + it("offsets from the given clock", () => { + const now = new Date("2026-08-18T00:00:00.000Z"); + expect(nextAttemptAt(0, now).toISOString()).toBe("2026-08-18T00:00:30.000Z"); + }); +}); + +describe("exhaustion", () => { + it("retires a row only after the last attempt", () => { + expect(isExhausted(MAX_DELIVERY_ATTEMPTS - 1)).toBe(false); + expect(isExhausted(MAX_DELIVERY_ATTEMPTS)).toBe(true); + }); + + it("keeps the whole retry window under a few hours", () => { + let total = 0; + for (let i = 0; i < MAX_DELIVERY_ATTEMPTS; i++) total += retryDelayMs(i); + expect(total).toBeLessThan(3 * 60 * 60_000); + }); +}); diff --git a/apps/bot/src/delivery-policy.ts b/apps/bot/src/delivery-policy.ts new file mode 100644 index 0000000..d967bf7 --- /dev/null +++ b/apps/bot/src/delivery-policy.ts @@ -0,0 +1,48 @@ +// When to stop trying to deliver an outbox row. +// +// Kept free of discord.js and Prisma so the policy itself is unit-testable: +// getting this wrong is not loud. A row that can never succeed and is never +// retired simply stays at the head of the queue, and since the poller takes a +// fixed batch ordered by age, enough of them starve every newer notification. + +/** + * Discord error codes that mean "this DM will never arrive", as opposed to + * "not right now". Both are 403s and both look alike in a log: + * + * 50007 Cannot send messages to this user (DMs closed) + * 50278 Cannot send messages to this user due to having no mutual guilds + * + * 50278 was missing here until 2026-08-18, so applicants who left the guild + * left behind a row that was retried every 15 seconds indefinitely. + */ +export const TERMINAL_DM_CODES = [50007, 50278] as const; + +export function isTerminalDmCode(code: unknown): boolean { + return (TERMINAL_DM_CODES as readonly number[]).includes(Number(code)); +} + +/** + * Give up after this many failed attempts. The backoff below spreads them over + * roughly two hours, which outlasts a normal Discord incident without letting a + * permanently broken row live forever. + */ +export const MAX_DELIVERY_ATTEMPTS = 8; + +const BASE_DELAY_MS = 30_000; +const MAX_DELAY_MS = 30 * 60_000; + +/** Exponential backoff, capped. `attempts` is the number of failures so far. */ +export function retryDelayMs(attempts: number): number { + const n = Math.min(Math.max(0, Math.trunc(attempts)), 20); + return Math.min(MAX_DELAY_MS, BASE_DELAY_MS * 2 ** n); +} + +/** When a row that just failed for the `attempts`-th time may be tried again. */ +export function nextAttemptAt(attempts: number, now: Date): Date { + return new Date(now.getTime() + retryDelayMs(attempts)); +} + +/** True once a row has burned through its attempts and should be retired. */ +export function isExhausted(attempts: number): boolean { + return attempts >= MAX_DELIVERY_ATTEMPTS; +} diff --git a/apps/bot/src/notifications.ts b/apps/bot/src/notifications.ts index 0faecea..a96f2f2 100644 --- a/apps/bot/src/notifications.ts +++ b/apps/bot/src/notifications.ts @@ -17,6 +17,7 @@ import { } from "discord.js"; import { config } from "./config.js"; +import { isExhausted, isTerminalDmCode, nextAttemptAt } from "./delivery-policy.js"; import { fmt, guildStrings } from "./guild-i18n.js"; import { dmStrings, localizedStatus } from "./i18n.js"; import { postBranded } from "./posting.js"; @@ -27,19 +28,32 @@ const MSK_GREEN = 0x00e676; const LOG_RED = 0xff5252; const LOG_BLURPLE = 0x5865f2; const BATCH = 25; -/** Discord error code: "Cannot send messages to this user" (DMs closed / no mutual guild). */ -const CANNOT_DM = 50007; /** Permanent channel errors: Unknown Channel / Missing Access / Missing Permissions. */ const CHANNEL_GONE = [10003, 50001, 50013]; /** Guards against overlapping ticks if a batch outlives the poll interval. */ let running = false; +/** + * What to do with a row after an attempt. `true` retires it — delivered, or + * permanently undeliverable, which for an outbox amounts to the same thing. + * Anything else is transient and carries the reason, so a row that keeps + * failing can be diagnosed from the table instead of from a log that has + * long since rotated away. + */ +type Outcome = true | { retry: string }; + +const retry = (err: unknown): Outcome => ({ + retry: err instanceof Error ? err.message.slice(0, 500) : String(err).slice(0, 500), +}); + type PendingRow = { id: string; type: string; payload: unknown; guildId: string | null; + /** Failed deliveries so far. Drives the backoff and the give-up threshold. */ + attempts: number; user: { discordId: string; locale: string } | null; }; @@ -82,7 +96,7 @@ function buildMessage( * channel. Drops (marks read) when there's no guild, no configured channel, or * the channel is permanently unreachable; retries on transient errors. */ -async function deliverReview(client: Client, row: PendingRow): Promise { +async function deliverReview(client: Client, row: PendingRow): Promise { if (!row.guildId) return true; const payload = row.payload as Partial; if (!payload?.submissionId) return true; @@ -137,7 +151,7 @@ async function deliverReview(client: Client, row: PendingRow): Promise return true; } console.error(`[bot] failed to post review embed to ${channelId}:`, err); - return false; + return retry(err); } } @@ -166,7 +180,7 @@ const LOG_PRESENTATION: Record { +async function deliverLog(client: Client, row: PendingRow): Promise { if (!row.guildId) return true; const payload = row.payload as Partial; if (!payload?.action) return true; @@ -236,7 +250,7 @@ async function deliverLog(client: Client, row: PendingRow): Promise { return true; } console.error(`[bot] failed to post log entry to ${channelId}:`, err); - return false; + return retry(err); } } @@ -245,7 +259,7 @@ async function deliverLog(client: Client, row: PendingRow): Promise { * read — on success, when there's no recipient, or on a permanent "can't DM" * error. Returns false for transient failures so the next tick retries. */ -async function deliverOne(client: Client, row: PendingRow): Promise { +async function deliverOne(client: Client, row: PendingRow): Promise { if (row.type === "submission_review") return deliverReview(client, row); if (row.type === "log") return deliverLog(client, row); @@ -298,12 +312,14 @@ async function deliverOne(client: Client, row: PendingRow): Promise { await user.send(message); return true; } catch (err) { - if (err instanceof DiscordAPIError && Number(err.code) === CANNOT_DM) { - console.warn(`[bot] can't DM user ${discordId} — dropping notification ${row.id}.`); + if (err instanceof DiscordAPIError && isTerminalDmCode(err.code)) { + console.warn( + `[bot] can't DM user ${discordId} (${err.code}) — dropping notification ${row.id}.`, + ); return true; } console.error(`[bot] failed to DM user ${discordId}:`, err); - return false; + return retry(err); } } @@ -312,9 +328,11 @@ export async function deliverPendingNotifications(client: Client): Promise if (running) return; running = true; try { + const now = new Date(); const pending = (await prisma.notification.findMany({ where: { readAt: null, + nextAttemptAt: { lte: now }, type: { in: ["status_change", "message", "submission_review", "log"] }, }, orderBy: { createdAt: "asc" }, @@ -324,6 +342,7 @@ export async function deliverPendingNotifications(client: Client): Promise type: true, payload: true, guildId: true, + attempts: true, user: { select: { discordId: true, locale: true } }, }, })) as PendingRow[]; @@ -331,11 +350,21 @@ export async function deliverPendingNotifications(client: Client): Promise // Deliver each row independently (one failure must not abort the batch), // collect the ones to retire, then mark them all read in a single write. const deliveredIds: string[] = []; + const failures: { id: string; attempts: number; error: string }[] = []; for (const row of pending) { try { - if (await deliverOne(client, row)) deliveredIds.push(row.id); + const outcome = await deliverOne(client, row); + if (outcome === true) deliveredIds.push(row.id); + else failures.push({ id: row.id, attempts: row.attempts + 1, error: outcome.retry }); } catch (err) { + // A throw escaping deliverOne is transient by definition: the row never + // reached a verdict, so it must not be retired on the strength of it. console.error(`[bot] delivery failed for notification ${row.id}:`, err); + failures.push({ + id: row.id, + attempts: row.attempts + 1, + error: err instanceof Error ? err.message.slice(0, 500) : String(err).slice(0, 500), + }); } } if (deliveredIds.length > 0) { @@ -344,6 +373,27 @@ export async function deliverPendingNotifications(client: Client): Promise data: { readAt: new Date() }, }); } + // Record each failure with its own backoff, and retire the ones that have + // run out of attempts. Without this a row that can never succeed sits at + // the head of the queue forever and, once enough of them pile up, starves + // every newer notification out of the batch. + for (const f of failures) { + const done = isExhausted(f.attempts); + if (done) { + console.warn( + `[bot] giving up on notification ${f.id} after ${f.attempts} attempts: ${f.error}`, + ); + } + await prisma.notification.update({ + where: { id: f.id }, + data: { + attempts: f.attempts, + lastError: f.error, + nextAttemptAt: nextAttemptAt(f.attempts, new Date()), + ...(done ? { readAt: new Date() } : {}), + }, + }); + } } catch (err) { console.error("[bot] notification delivery error:", err); } finally { diff --git a/packages/db/prisma/migrations/20260818003000_notification_retry_bounds/migration.sql b/packages/db/prisma/migrations/20260818003000_notification_retry_bounds/migration.sql new file mode 100644 index 0000000..e394024 --- /dev/null +++ b/packages/db/prisma/migrations/20260818003000_notification_retry_bounds/migration.sql @@ -0,0 +1,25 @@ +-- Bound the outbox retry loop. +-- +-- Until now a notification that failed to deliver was simply left unread and +-- picked up again on the next 15s tick, forever. Discord returns 50278 ("no +-- mutual guilds") for applicants who left the server, and the bot only treated +-- 50007 as permanent, so those rows never retired. Because the poller takes a +-- fixed batch ordered by age, enough of them at the head of the queue would +-- have starved every newer notification. +ALTER TABLE "notifications" + ADD COLUMN "attempts" INTEGER NOT NULL DEFAULT 0, + ADD COLUMN "last_error" TEXT, + ADD COLUMN "next_attempt_at" TIMESTAMP(3) NOT NULL DEFAULT CURRENT_TIMESTAMP; + +-- The poller now scans: +-- WHERE read_at IS NULL AND next_attempt_at <= now() ORDER BY created_at ASC +-- so the pending partial index gains the new column. It supersedes +-- notifications_pending_idx from 20260620180000, which is dropped rather than +-- kept alongside: two partial indexes over the same rows would both have to be +-- maintained on every insert into a hot table. (Partial indexes aren't +-- expressible in the Prisma schema, hence the hand-written migration.) +CREATE INDEX IF NOT EXISTS "notifications_due_idx" + ON "notifications" ("next_attempt_at", "created_at") + WHERE "read_at" IS NULL; + +DROP INDEX IF EXISTS "notifications_pending_idx"; diff --git a/packages/db/prisma/schema.prisma b/packages/db/prisma/schema.prisma index 34f7b80..32d58b3 100644 --- a/packages/db/prisma/schema.prisma +++ b/packages/db/prisma/schema.prisma @@ -331,6 +331,13 @@ model Notification { readAt DateTime? @map("read_at") createdAt DateTime @default(now()) @map("created_at") + // Retry bounds, same shape as WebhookDelivery. `readAt` marks a row as + // retired, which covers both "delivered" and "will never be deliverable"; + // `lastError` is what tells the two apart afterwards. + attempts Int @default(0) + lastError String? @map("last_error") + nextAttemptAt DateTime @default(now()) @map("next_attempt_at") + user User? @relation(fields: [userId], references: [id], onDelete: Cascade) guild Guild? @relation(fields: [guildId], references: [id], onDelete: Cascade)