diff --git a/modules/mailu/health.ts b/modules/mailu/health.ts index 3ffcc5e4..ff6126ff 100644 --- a/modules/mailu/health.ts +++ b/modules/mailu/health.ts @@ -3,9 +3,12 @@ // inbound mail was refused with 450 and outbound mail sat in the deferred queue for days. The parts' // checks judge parts; this judges the flow, from inside the postfix container, the way postfix sees it: // -// 1. postfix runs (`postfix status`, the check the image itself ships, which this one replaces); -// 2. no message waits in the deferred queue longer than the bound (`postqueue -j`): a message that -// cannot be delivered for that long is mail that does not flow, whatever the reason; +// 1. postfix runs (`postfix status`, standing in for the image's own check, `! /usr/libexec/postfix/master +// -t`, which this one replaces); +// 2. the deferred queue (`postqueue -j`) shows no fault of this side: a recipient deferred longer than the +// bound because a lookup failed here, or overdue mail to three or more domains. One or two far domains +// that do not answer are theirs, and can stay deferred for days: said, never unhealthy, so one dead +// recipient does not page the operator for days; // 3. a public mail host's name resolves through the resolver postfix is given: a resolver that // SERVFAILs refuses inbound mail before anything reaches the queue. // @@ -34,6 +37,23 @@ const RESOLVE = [ " sys.exit(type(e).__name__ + ': ' + str(e))", ].join("\n"); +/** Overdue mail to this many recipient domains or more is our side's fault, not one far server's. */ +export const SPREAD_DOMAINS = 3; + +/** + * What postfix writes when its own lookups fail, as on 2026-10-14 (issue 687): "Host or domain name not + * found. Name service error for name=gmail.com type=MX: Host not found, try again", or "Temporary lookup + * failure". A far server that is down reads otherwise ("Connection timed out", "Connection refused"). + */ +export const LOCAL_LOOKUP_FAILURE = + /Name service error|Temporary lookup failure|Host or domain name not found.*try again/is; + +/** The domain of an address, lower-cased; "(no recipient)" when there is none. */ +function domainOf(address?: string): string { + const at = address?.lastIndexOf("@") ?? -1; + return address && at >= 0 ? address.slice(at + 1).toLowerCase() : "(no recipient)"; +} + /** Runs a command in a container: its stdout, or a rejection carrying stderr. */ export type Exec = (container: string, command: string[]) => Promise; @@ -42,7 +62,14 @@ export interface HealthAnswer { state: "healthy" | "unhealthy"; healthy: boolean; why: string; - queue?: { messages: number; deferred: number; overdue: number; oldestDeferredSeconds?: number }; + queue?: { + messages: number; + deferred: number; + overdue: number; + oldestDeferredSeconds?: number; + overdueDomains?: string[]; + nameServiceFailures?: number; + }; } /** One message as `postqueue -j` prints it, one JSON object a line (postfix 3.1 and later). */ @@ -109,6 +136,7 @@ export async function mailFlows( } let summary: HealthAnswer["queue"]; + const notes: string[] = []; if (queue.status === "rejected") { faults.push(`postfix's queue in ${container} could not be read: ${said(queue.reason)}.`); } else { @@ -126,20 +154,42 @@ export async function mailFlows( (o, q) => (typeof q.arrival_time === "number" && (o === undefined || q.arrival_time < o) ? q.arrival_time : o), undefined, ); + // Each overdue recipient, oldest message first: what our side is judged by, not one far host. + const late = overdue.flatMap((q) => + (q.recipients?.length ? q.recipients : [{}]).map((r) => ({ + to: r.address, + domain: domainOf(r.address), + reason: r.delay_reason?.trim() || "postfix gave no reason", + waited: now - (q.arrival_time ?? now), + })), + ); + const lookups = late.filter((r) => LOCAL_LOOKUP_FAILURE.test(r.reason)); + const domains = [...new Set(late.map((r) => r.domain))]; summary = { messages: queued.length, deferred: deferred.length, overdue: overdue.length, ...(oldest !== undefined ? { oldestDeferredSeconds: Math.max(0, Math.floor(now - oldest)) } : {}), + ...(domains.length > 0 ? { overdueDomains: domains } : {}), + ...(lookups.length > 0 ? { nameServiceFailures: lookups.length } : {}), }; - if (overdue.length > 0) { - const first = overdue[0]; - const reason = first.recipients?.find((r) => r.delay_reason)?.delay_reason?.trim(); - const to = first.recipients?.[0]?.address; + const one = (r: (typeof late)[number]) => + `the oldest, ${age(r.waited)} old${r.to ? ` to ${r.to}` : ""}, waits because: ${r.reason}`; + const bound = age(boundSeconds); + if (lookups.length > 0) { faults.push( - `${overdue.length} of ${deferred.length} deferred messages have waited longer than ${age(boundSeconds)}; ` + - `the oldest, ${age(now - (first.arrival_time ?? now))} old${to ? ` to ${to}` : ""}, ` + - `waits because: ${reason || "postfix gave no reason"}.`, + `${lookups.length} deferred ${lookups.length === 1 ? "recipient has" : "recipients have"} waited longer ` + + `than ${bound} on a name-service failure, which is this server's resolver; ${one(lookups[0])}.`, + ); + } else if (domains.length >= SPREAD_DOMAINS) { + faults.push( + `${overdue.length} of ${deferred.length} deferred messages have waited longer than ${bound}, to ` + + `${domains.length} domains (${domains.join(", ")}): more than one far server's fault; ${one(late[0])}.`, + ); + } else if (late.length > 0) { + notes.push( + `${overdue.length} deferred ${overdue.length === 1 ? "message has" : "messages have"} waited longer than ` + + `${bound}, only to ${domains.join(" and ")}, which reads as the far side's: ${one(late[0])}.`, ); } } @@ -149,11 +199,14 @@ export async function mailFlows( } if (faults.length > 0) { - return { state: "unhealthy", healthy: false, why: `Mail does not flow. ${faults.join(" ")}`, queue: summary }; + const why = [`Mail does not flow.`, ...faults, ...notes].join(" "); + return { state: "unhealthy", healthy: false, why, queue: summary }; } - const waiting = summary && summary.deferred > 0 - ? ` ${summary.deferred} deferred, the oldest ${age(summary.oldestDeferredSeconds ?? 0)} old, within ${age(boundSeconds)}.` - : " The deferred queue is empty."; + const waiting = !summary || summary.deferred === 0 + ? " The deferred queue is empty." + : notes.length > 0 + ? ` ${notes.join(" ")}` + : ` ${summary.deferred} deferred, the oldest ${age(summary.oldestDeferredSeconds ?? 0)} old, within ${age(boundSeconds)}.`; return { state: "healthy", healthy: true, diff --git a/modules/mailu/test/mail-flows.test.ts b/modules/mailu/test/mail-flows.test.ts index c945767a..ddea9791 100644 --- a/modules/mailu/test/mail-flows.test.ts +++ b/modules/mailu/test/mail-flows.test.ts @@ -28,14 +28,14 @@ function failed(stderr: string): Error { return Object.assign(new Error("Command failed: docker exec"), { stderr }); } -function deferred(id: string, ageSeconds: number, reason: string): string { +function deferred(id: string, ageSeconds: number, reason: string, to = "friend@example.com"): string { return JSON.stringify({ queue_name: "deferred", queue_id: id, arrival_time: NOW - ageSeconds, message_size: 1234, sender: "someone@example.org", - recipients: [{ address: "friend@example.com", delay_reason: reason }], + recipients: [{ address: to, delay_reason: reason }], }); } @@ -49,8 +49,8 @@ test("an empty queue is healthy, and says so", async () => { assert.equal(c.asked.length, 3, "postfix, its queue and a lookup were each asked"); }); -test("a deferred message older than the bound is unhealthy, with counts, its age and its reason", async () => { - const reason = "Host or domain name not found. Name service error for name=example.com type=MX: Host not found, try again"; +test("a recipient overdue on a name-service failure is unhealthy, with counts, its age and its reason", async () => { + const reason = "Host or domain name not found. Name service error for name=gmail.com type=MX: Host not found, try again"; const queue = [ deferred("AAA111", 3 * 86400 + 2 * 3600, reason), deferred("BBB222", 5 * 60, "connect to mx.example.net[192.0.2.1]:25: Connection timed out"), @@ -60,10 +60,39 @@ test("a deferred message older than the bound is unhealthy, with counts, its age assert.equal(a.state, "unhealthy"); assert.equal(a.healthy, false); assert.match(a.why, /^Mail does not flow\./); - assert.match(a.why, /1 of 2 deferred messages have waited longer than 30 minutes/); + assert.match(a.why, /1 deferred recipient has waited longer than 30 minutes on a name-service failure/); assert.match(a.why, /3 days 2 hours old to friend@example\.com/); - assert.ok(a.why.includes(reason), "the first reason is said"); - assert.deepEqual(a.queue, { messages: 3, deferred: 2, overdue: 1, oldestDeferredSeconds: 3 * 86400 + 2 * 3600 }); + assert.ok(a.why.includes(reason), "the reason is said"); + assert.deepEqual(a.queue, { + messages: 3, deferred: 2, overdue: 1, oldestDeferredSeconds: 3 * 86400 + 2 * 3600, + overdueDomains: ["example.com"], nameServiceFailures: 1, + }); +}); + +test("one dead far domain overdue is healthy, and said", async () => { + const queue = [ + deferred("AAA111", 2 * 86400, "connect to mx.dead.example[192.0.2.9]:25: Connection timed out", "a@dead.example"), + deferred("BBB222", 3600, "connect to mx.dead.example[192.0.2.9]:25: Connection timed out", "b@dead.example"), + ].join("\n"); + const a = await mailFlows(container({ queue }).exec, "mailu-smtp", NOW); + assert.equal(a.state, "healthy"); + assert.equal(a.healthy, true); + assert.match(a.why, /2 deferred messages have waited longer than 30 minutes, only to dead\.example, which reads as the far side's/); + assert.match(a.why, /2 days old to a@dead\.example, waits because: connect to mx\.dead\.example/); + assert.deepEqual(a.queue?.overdueDomains, ["dead.example"]); +}); + +test("overdue mail to three domains is unhealthy, whatever the reason", async () => { + const timedOut = "connect to mx[192.0.2.1]:25: Connection timed out"; + const queue = [ + deferred("AAA111", 7200, timedOut, "a@one.example"), + deferred("BBB222", 3600, timedOut, "b@two.example"), + deferred("CCC333", 3600, timedOut, "c@three.example"), + ].join("\n"); + const a = await mailFlows(container({ queue }).exec, "mailu-smtp", NOW); + assert.equal(a.state, "unhealthy"); + assert.match(a.why, /3 of 3 deferred messages have waited longer than 30 minutes, to 3 domains \(one\.example, two\.example, three\.example\)/); + assert.match(a.why, /the oldest, 2 hours old to a@one\.example/); }); test("a deferred message younger than the bound is healthy, and is said", async () => { diff --git a/modules/mailu/tools/index.ts b/modules/mailu/tools/index.ts index 19d5fbe0..6b8442e9 100644 --- a/modules/mailu/tools/index.ts +++ b/modules/mailu/tools/index.ts @@ -4,7 +4,7 @@ import { registerModuleTools, type ToolDefinition } from "@novox/mesh-sdk/tools"; import { MailuClient } from "../client.js"; -import { dockerExec, mailFlows, DEFERRED_BOUND_SECONDS, PUBLIC_NAME } from "../health.js"; +import { dockerExec, mailFlows, DEFERRED_BOUND_SECONDS, PUBLIC_NAME, SPREAD_DOMAINS } from "../health.js"; /** * Whether mail flows (novox/hq ADR 0240, issue 690): the tool the node-engine asks as the smtp container's @@ -16,10 +16,11 @@ export function getHealthTool(env: NodeJS.ProcessEnv): ToolDefinition { return { name: "mailu_health", description: - `Whether mail flows through mailu, asked inside ${container}: postfix runs, no message has waited in ` + - `its deferred queue longer than ${DEFERRED_BOUND_SECONDS / 60} minutes, and ${PUBLIC_NAME} resolves ` + - "through the resolver postfix uses. Unhealthy with counts, the oldest message's age and its first reason " + - "(novox/hq ADR 0240, issue 690).", + `Whether mail flows through mailu, asked inside ${container}: postfix runs; no recipient has waited ` + + `deferred longer than ${DEFERRED_BOUND_SECONDS / 60} minutes on a name-service failure here, and overdue ` + + `deferred mail does not reach ${SPREAD_DOMAINS} or more domains (one or two far domains are said, not ` + + `unhealthy); and ${PUBLIC_NAME} resolves through the resolver postfix uses. Says counts, domains, the ` + + "oldest message's age and its reason (novox/hq ADR 0240, issue 690).", input: {}, run: async () => mailFlows(dockerExec(), container), };