fix(email): compare queue timestamps in JS, and make retry actually send

Codex review round 1 on #1273. One of the four is a real bug on every SQLite
deployment.

The waiting-row query compared `created_at` against a bound ISO string. On
SQLite that column does not hold a string: queueEmail writes a JS Date and the
native binding stores epoch ms, and SQLite orders INTEGER before TEXT
regardless of value -- so the comparison was true for EVERY row. Mail queued a
second ago read as ten minutes overdue, and a scheduled_at years in the future
read as already due. Confirmed directly against sqlite3: a 2026 row matches
`created_at <= '2020-01-01T00:00:00.000Z'`.

Binding a Date instead is not the fix, since knex hands sqlite3 a Date the same
way and jest's sandbox Dates stringify to "[object Object]" (CLAUDE.md). So the
engine-safe half of the predicate stays in SQL and the two time comparisons
move into JS behind a toMillis() that accepts all three shapes this column
really has -- Date from Postgres, ms-number from SQLite, ISO string from
fixtures and older rows. The scan is capped at 1000 pending rows ordered
oldest-first; everything overdue sorts into that window, and the response was
already capped at 200. The existing tests missed this because they store ISO
strings, which is what CLAUDE.md prescribes for jest -- so the new ones store
epoch ms, the production shape, and one mixes both in a single queue.

Retry was a no-op for the rows it most needed to help. It wrote pending /
retry_count 0 / no schedule, which is exactly what a waiting row already is:
the row came back unchanged while the toast said it had been re-queued. And
since the usual reason a row is waiting is that nothing is working the queue,
deferring it to the next pass is the one answer that cannot help. It now
follows the reset with the same single-row flush the project cockpit uses.

An idle pass no longer inherits the previous pass's totals -- the no-pending
early return skipped the lastResult assignment, so System Health kept
attributing an old sent/failed count to a run that did nothing.

"All clear" now means the whole queue is clear, which is what the PR claimed
and the code did not do. An empty waiting list is only reassuring when
something is working the queue: a processor stopped a minute ago has no overdue
rows yet either, and a green check there is the same false all-clear this
branch exists to remove.

7 more tests. The 5 that pin new behaviour fail before this commit; the SQLite
ones fail in the way the bug predicts rather than erroring.

Both new tests stub the webhook transport with a spy rather than pointing it at
a dead port: real connection attempts left open handles that destabilised
unrelated suites in the same jest worker.
This commit is contained in:
Paul Nothaft
2026-09-02 14:35:54 +02:00
parent 73d867521a
commit 89db469f06
6 changed files with 260 additions and 23 deletions
@@ -25,6 +25,35 @@ const jwt = require('jsonwebtoken');
const { bootCrmDb, seedMinimal, buildRouteApp } = require('../integration/helpers/crmDb'); const { bootCrmDb, seedMinimal, buildRouteApp } = require('../integration/helpers/crmDb');
/**
* Stand up a transport without touching a socket.
*
* processEmailQueue bails before it reads a single row when there is no
* transport, so the two tests below cannot otherwise reach the code they are
* about. Spying on the webhook transport is the cheapest way in — and it must
* be a spy rather than a dead URL, because real connection attempts leave open
* handles that destabilise unrelated suites in the same worker.
*
* `send` rejects: a failed delivery is a delivery ATTEMPT, which is exactly
* what these two need to observe.
*/
function stubWebhookTransport() {
const transport = require('../../src/services/emailWebhookTransport');
const savedFrom = process.env.EMAIL_FROM;
process.env.EMAIL_FROM = '[email protected]';
const enabled = jest.spyOn(transport, 'isEnabled').mockReturnValue(true);
const send = jest.spyOn(transport, 'send').mockRejectedValue(new Error('transport down'));
return {
send,
restore() {
enabled.mockRestore();
send.mockRestore();
if (savedFrom === undefined) delete process.env.EMAIL_FROM;
else process.env.EMAIL_FROM = savedFrom;
},
};
}
const MINUTE = 60 * 1000; const MINUTE = 60 * 1000;
const ago = (ms) => new Date(Date.now() - ms).toISOString(); const ago = (ms) => new Date(Date.now() - ms).toISOString();
const ahead = (ms) => new Date(Date.now() + ms).toISOString(); const ahead = (ms) => new Date(Date.now() + ms).toISOString();
@@ -133,6 +162,66 @@ describe('GET /admin/system-health/failures — waiting emails (#1262)', () => {
expect(body.stuckEmails).toEqual([]); expect(body.stuckEmails).toEqual([]);
}); });
// --- cross-engine timestamps (Codex review round 1) -----------------------
//
// Every test above stores ISO strings, which is what CLAUDE.md prescribes
// for jest + SQLite. Production SQLite does not: queueEmail writes a JS Date
// and the native binding stores it as a ms-NUMBER. SQLite orders INTEGER
// before TEXT whatever the values are, so the original WHERE clause -- a
// ms-number column compared against a bound ISO string -- was true for every
// row. Fresh mail read as ten minutes overdue and future schedules read as
// due, on every SQLite deployment.
describe('rows stored as epoch ms, the SQLite production shape', () => {
const ms = (offset) => Date.now() + offset;
it('does not report a mail queued seconds ago as waiting', async () => {
await queue({ email_type: 'gallery_created', created_at: ms(-30 * 1000) });
const body = await failures();
expect(body.waitingEmails).toEqual([]);
expect(body.counts.waitingEmails).toBe(0);
});
it('still reports a genuinely overdue one', async () => {
await queue({ email_type: 'gallery_created', created_at: ms(-52 * MINUTE) });
const body = await failures();
expect(typesOf(body.waitingEmails)).toEqual(['gallery_created']);
});
it('leaves a future numeric scheduled_at alone', async () => {
await queue({
email_type: 'invoice_due',
created_at: ms(-52 * MINUTE),
scheduled_at: ms(3 * 24 * 60 * MINUTE),
});
const body = await failures();
expect(body.waitingEmails).toEqual([]);
});
it('reports a past-due numeric scheduled_at', async () => {
await queue({
email_type: 'invoice_due',
created_at: ms(-52 * MINUTE),
scheduled_at: ms(-30 * MINUTE),
});
const body = await failures();
expect(typesOf(body.waitingEmails)).toEqual(['invoice_due']);
});
it('mixes both storage shapes in one queue without confusing them', async () => {
await queue({ email_type: 'gallery_created', created_at: ms(-52 * MINUTE) });
await queue({ email_type: 'quote_sent', created_at: ago(52 * MINUTE) });
await queue({ email_type: 'invoice_due', created_at: ms(-30 * 1000) });
await queue({ email_type: 'customer_invitation', created_at: ago(30 * 1000) });
const body = await failures();
expect(typesOf(body.waitingEmails)).toEqual(['gallery_created', 'quote_sent']);
});
});
it('reports what the queue processor last did', async () => { it('reports what the queue processor last did', async () => {
const body = await failures(); const body = await failures();
// Never started in this process — which is the condition that makes a // Never started in this process — which is the condition that makes a
@@ -142,6 +231,59 @@ describe('GET /admin/system-health/failures — waiting emails (#1262)', () => {
expect(body.processor).toHaveProperty('lastError'); expect(body.processor).toHaveProperty('lastError');
}); });
it('does not attribute a previous pass\'s totals to an idle one', async () => {
// Codex review round 1. The no-pending early return skipped the lastResult
// assignment, so after one pass that sent or failed something, every idle
// pass afterwards advanced lastRunAt while still reporting the old totals.
const { processEmailQueue, getQueueProcessorStatus } = require('../../src/services/emailProcessor');
const transport = stubWebhookTransport();
try {
await queue({ email_type: 'gallery_created' });
await processEmailQueue();
const worked = getQueueProcessorStatus().lastResult;
expect(worked.processed).toBe(1);
expect(worked.sent + worked.failed).toBe(1);
await db('email_queue').del();
await processEmailQueue();
expect(getQueueProcessorStatus().lastResult).toEqual({ processed: 0, sent: 0, failed: 0 });
} finally {
transport.restore();
}
});
it('actually flushes the row on retry instead of leaving it as it was', async () => {
// Codex review round 1. The retry endpoint only wrote pending /
// retry_count 0 / no schedule — which is exactly what a WAITING row
// already is, so nothing happened while the toast said "re-queued". And
// the usual reason a row is waiting is that nothing is working the queue,
// so "wait for the next pass" is the one answer that cannot help.
const transport = stubWebhookTransport();
try {
await queue({ email_type: 'gallery_created' });
const { id } = await db('email_queue').first('id');
const res = await request(app)
.post(`/admin/system-health/failures/email/${id}/retry`)
.set('Authorization', `Bearer ${token}`);
expect(res.status).toBe(200);
// A send was ATTEMPTED, which the old endpoint never did. It fails here
// (the transport is stubbed to reject) and that failure is recorded on
// the row, which is itself the proof the row was worked rather than
// merely rewritten to the state it was already in.
expect(transport.send).toHaveBeenCalledTimes(1);
const after = await db('email_queue').where({ id }).first();
expect(after.retry_count).toBe(1);
expect(after.error_message).toBeTruthy();
} finally {
transport.restore();
}
});
it('surfaces the transport failure that makes every pass a no-op', async () => { it('surfaces the transport failure that makes every pass a no-op', async () => {
const { processEmailQueue, getQueueProcessorStatus } = require('../../src/services/emailProcessor'); const { processEmailQueue, getQueueProcessorStatus } = require('../../src/services/emailProcessor');
await queue({ email_type: 'gallery_created' }); await queue({ email_type: 'gallery_created' });
+82 -14
View File
@@ -23,7 +23,8 @@ const { requirePermission } = require('../middleware/permissions');
const { handleAsync, validateRequest, successResponse } = require('../utils/routeHelpers'); const { handleAsync, validateRequest, successResponse } = require('../utils/routeHelpers');
const { verifyDocumentArtefacts } = require('../services/backupIntegrityService'); const { verifyDocumentArtefacts } = require('../services/backupIntegrityService');
const { getCoverageReport } = require('../services/backupCoverageService'); const { getCoverageReport } = require('../services/backupCoverageService');
const { getQueueProcessorStatus } = require('../services/emailProcessor'); const { getQueueProcessorStatus, processEmailQueue } = require('../services/emailProcessor');
const logger = require('../utils/logger');
const { db } = require('../database/db'); const { db } = require('../database/db');
const router = express.Router(); const router = express.Router();
@@ -94,6 +95,43 @@ router.get(
*/ */
const WAITING_EMAIL_GRACE_MS = 10 * 60 * 1000; const WAITING_EMAIL_GRACE_MS = 10 * 60 * 1000;
/**
* A timestamp column as milliseconds, whatever the engine handed back.
*
* The three shapes are all real. Postgres returns a Date. SQLite stores what
* `queueEmail` writes -- a JS Date, which the native binding turns into a
* ms-number -- and hands back that number. Test fixtures and older rows carry
* ISO strings.
*
* This has to happen in JS rather than in the WHERE clause. SQLite orders
* INTEGER before TEXT regardless of value, so comparing a ms-number column
* against a bound ISO string is true for EVERY row: a mail queued one second
* ago reads as ten minutes overdue, and a scheduled_at years in the future
* reads as already due. Binding a Date instead is no fix either, since knex
* hands sqlite3 a Date the same way and jest's sandbox Dates stringify to
* "[object Object]" (see CLAUDE.md).
*/
function toMillis(value) {
if (value == null) return null;
if (value instanceof Date) return value.getTime();
if (typeof value === 'number') return value;
const text = String(value).trim();
if (text === '') return null;
// A numeric string is epoch ms; anything else goes through Date.parse.
const numeric = Number(text);
if (Number.isFinite(numeric)) return numeric;
const parsed = Date.parse(text);
return Number.isNaN(parsed) ? null : parsed;
}
/**
* How many pending rows to pull before filtering by time in JS. Everything
* overdue sorts first, so the cap only bites on a queue with more than this
* many pending rows -- at which point the 200-row response was already a
* sample rather than a census.
*/
const WAITING_SCAN_LIMIT = 1000;
const mapEmailRow = (r) => ({ const mapEmailRow = (r) => ({
id: r.id, id: r.id,
recipientEmail: r.recipient_email, recipientEmail: r.recipient_email,
@@ -141,18 +179,30 @@ router.get(
// under the retry cap, and past any scheduled_at — so a row listed here is // under the retry cap, and past any scheduled_at — so a row listed here is
// one it should already have taken. Rows over the cap are the `stuckEmails` // one it should already have taken. Rows over the cap are the `stuckEmails`
// set above and must not be counted twice. // set above and must not be counted twice.
const now = new Date(); //
const dueBefore = new Date(now.getTime() - WAITING_EMAIL_GRACE_MS); // Only the engine-safe half of that predicate runs in SQL; the two time
const waitingEmails = await db('email_queue') // comparisons are done in JS, for the reason on toMillis above.
const now = Date.now();
const dueBefore = now - WAITING_EMAIL_GRACE_MS;
const pendingRows = await db('email_queue')
.where('status', 'pending') .where('status', 'pending')
.where('retry_count', '<', 3) .where('retry_count', '<', 3)
.where('created_at', '<=', dueBefore.toISOString())
.andWhere(function () {
this.whereNull('scheduled_at').orWhere('scheduled_at', '<=', now.toISOString());
})
.orderBy('created_at', 'asc') .orderBy('created_at', 'asc')
.limit(200) .limit(WAITING_SCAN_LIMIT)
.select('id', 'recipient_email', 'email_type', 'status', 'retry_count', 'error_message', 'created_at'); .select('id', 'recipient_email', 'email_type', 'status', 'retry_count',
'error_message', 'created_at', 'scheduled_at');
const waitingEmails = pendingRows.filter((r) => {
const scheduledAt = toMillis(r.scheduled_at);
// Parked for later on purpose — split-payment invoices, the
// business-hours floor. Not being sent yet is the point of those.
if (scheduledAt !== null && scheduledAt > now) return false;
const createdAt = toMillis(r.created_at);
// An unreadable created_at cannot be judged overdue; leave it alone
// rather than reporting every such row as waiting.
if (createdAt === null) return false;
return createdAt <= dueBefore;
}).slice(0, 200);
return successResponse(res, { return successResponse(res, {
stuckEmails: stuckEmails.map(mapEmailRow), stuckEmails: stuckEmails.map(mapEmailRow),
@@ -167,9 +217,20 @@ router.get(
); );
/** /**
* POST /failures/email/:id/retry — re-queue a stuck email (status back to * POST /failures/email/:id/retry — re-queue an email and flush it now.
* pending, retry_count reset, error cleared, scheduled_at cleared so the *
* 60s processor picks it up on its next pass). * The reset alone (pending, retries cleared, schedule cleared) is what a
* FAILED row needs, but it is a no-op for a waiting row: those are already
* pending at retry_count 0 with a null or past-due schedule, so the row came
* back unchanged while the toast said it had been re-queued. Since the
* commonest reason a row is waiting is that nothing is working the queue,
* telling it to wait for the next pass is the one thing that will not help.
*
* So the reset is followed by a targeted flush — the same single-row path the
* project cockpit uses (projectService.js). `ignoreSchedule` bypasses the
* retry cap and the schedule, which is the point of an admin forcing a send.
* The send is best-effort: a failure is already recorded on the row itself by
* processEmailQueue, and the refreshed list will show it.
*/ */
router.post( router.post(
'/failures/email/:id/retry', '/failures/email/:id/retry',
@@ -184,7 +245,14 @@ router.post(
scheduled_at: null, scheduled_at: null,
}); });
if (!updated) return res.status(404).json({ error: 'Email not found' }); if (!updated) return res.status(404).json({ error: 'Email not found' });
return successResponse(res, { retried: true });
let sent = 0;
try {
({ sent } = await processEmailQueue({ ignoreSchedule: true, onlyId: id }));
} catch (err) {
logger.warn(`System health: flush of email ${id} failed: ${err.message}`);
}
return successResponse(res, { retried: true, sent: sent > 0 });
}), }),
); );
+5
View File
@@ -1003,6 +1003,11 @@ async function processEmailQueue({ ignoreSchedule = false, limit = 10, onlyId =
if (pendingEmails.length === 0) { if (pendingEmails.length === 0) {
logger.info('Email queue processor: No pending emails found'); logger.info('Email queue processor: No pending emails found');
// Record the empty pass too. Without this an idle pass advances
// lastRunAt and clears lastError but leaves the PREVIOUS pass's
// sent/failed totals in place, so System Health attributes them to a run
// that sent nothing.
processorStatus.lastResult = result;
return result; return result;
} }
+4 -2
View File
@@ -107,7 +107,8 @@
"error": "Fehler", "error": "Fehler",
"queued": "Eingereiht", "queued": "Eingereiht",
"actions": "Aktionen" "actions": "Aktionen"
} },
"emptyNotAllClear": "Nichts ist fehlgeschlagen — beachten Sie aber die Hinweise oben."
}, },
"waitingEmails": { "waitingEmails": {
"title": "Wartet auf Versand", "title": "Wartet auf Versand",
@@ -118,7 +119,8 @@
"unknownError": "unbekannt", "unknownError": "unbekannt",
"col": { "col": {
"attempts": "Versuche" "attempts": "Versuche"
} },
"emptyButUnworked": "Noch ist nichts überfällig, es sendet aber auch nichts — siehe Prozessor oben. Alles ab jetzt Eingereihte bleibt hier liegen."
}, },
"processor": { "processor": {
"title": "E-Mail-Warteschlangen-Prozessor", "title": "E-Mail-Warteschlangen-Prozessor",
+4 -2
View File
@@ -107,7 +107,8 @@
"error": "Error", "error": "Error",
"queued": "Queued", "queued": "Queued",
"actions": "Actions" "actions": "Actions"
} },
"emptyNotAllClear": "Nothing has failed — but see above."
}, },
"waitingEmails": { "waitingEmails": {
"title": "Waiting to send", "title": "Waiting to send",
@@ -118,7 +119,8 @@
"unknownError": "unknown", "unknownError": "unknown",
"col": { "col": {
"attempts": "Attempts" "attempts": "Attempts"
} },
"emptyButUnworked": "Nothing is overdue yet, but nothing is sending either — see the processor above. Anything queued from now on will sit here."
}, },
"processor": { "processor": {
"title": "Email queue processor", "title": "Email queue processor",
+19 -1
View File
@@ -186,10 +186,22 @@ export const SystemHealthPage: React.FC = () => {
</div> </div>
{isLoading ? <Loading /> : waitingEmails.length === 0 ? ( {isLoading ? <Loading /> : waitingEmails.length === 0 ? (
// "Nothing waiting" is only reassuring when something is working the
// queue. A processor that stopped a minute ago has no waiting rows
// yet either — the grace window has not elapsed — and a green check
// there is the same false all-clear this page exists to remove.
processorState === 'ok' ? (
<div className="flex items-center gap-2 text-sm text-green-700 dark:text-green-400 py-6"> <div className="flex items-center gap-2 text-sm text-green-700 dark:text-green-400 py-6">
<CheckCircle className="w-5 h-5" /> <CheckCircle className="w-5 h-5" />
{t('systemHealth.waitingEmails.empty', 'Nothing waiting — the queue is being worked.')} {t('systemHealth.waitingEmails.empty', 'Nothing waiting — the queue is being worked.')}
</div> </div>
) : (
<div className="flex items-center gap-2 text-sm text-amber-700 dark:text-amber-400 py-6">
<AlertCircle className="w-5 h-5" />
{t('systemHealth.waitingEmails.emptyButUnworked',
'Nothing is overdue yet, but nothing is sending either — see the processor above. Anything queued from now on will sit here.')}
</div>
)
) : ( ) : (
<> <>
<p className="text-sm text-neutral-600 dark:text-neutral-400 mb-3"> <p className="text-sm text-neutral-600 dark:text-neutral-400 mb-3">
@@ -215,7 +227,13 @@ export const SystemHealthPage: React.FC = () => {
{isLoading ? <Loading /> : stuckEmails.length === 0 ? ( {isLoading ? <Loading /> : stuckEmails.length === 0 ? (
<div className="flex items-center gap-2 text-sm text-green-700 dark:text-green-400 py-6"> <div className="flex items-center gap-2 text-sm text-green-700 dark:text-green-400 py-6">
<CheckCircle className="w-5 h-5" /> <CheckCircle className="w-5 h-5" />
{t('systemHealth.stuckEmails.empty', 'No stuck or failed emails — all clear.')} {/* "all clear" is a claim about the whole queue, so it is only
allowed when the whole queue is clear. With mail waiting or a
processor that is not working, this section is still empty but
the system is not fine. */}
{waitingEmails.length === 0 && processorState === 'ok'
? t('systemHealth.stuckEmails.empty', 'No stuck or failed emails — all clear.')
: t('systemHealth.stuckEmails.emptyNotAllClear', 'Nothing has failed — but see above.')}
</div> </div>
) : emailTable(stuckEmails, true)} ) : emailTable(stuckEmails, true)}
</Card> </Card>