diff --git a/backend/__tests__/routes/adminSystemHealthWaitingEmails.test.js b/backend/__tests__/routes/adminSystemHealthWaitingEmails.test.js index 4397087f..e6275f80 100644 --- a/backend/__tests__/routes/adminSystemHealthWaitingEmails.test.js +++ b/backend/__tests__/routes/adminSystemHealthWaitingEmails.test.js @@ -25,6 +25,35 @@ const jwt = require('jsonwebtoken'); 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 = 'noreply@example.com'; + 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 ago = (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([]); }); + // --- 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 () => { const body = await failures(); // 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'); }); + 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 () => { const { processEmailQueue, getQueueProcessorStatus } = require('../../src/services/emailProcessor'); await queue({ email_type: 'gallery_created' }); diff --git a/backend/src/routes/adminSystemHealth.js b/backend/src/routes/adminSystemHealth.js index 20de8108..de9cb04d 100644 --- a/backend/src/routes/adminSystemHealth.js +++ b/backend/src/routes/adminSystemHealth.js @@ -23,7 +23,8 @@ const { requirePermission } = require('../middleware/permissions'); const { handleAsync, validateRequest, successResponse } = require('../utils/routeHelpers'); const { verifyDocumentArtefacts } = require('../services/backupIntegrityService'); 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 router = express.Router(); @@ -94,6 +95,43 @@ router.get( */ 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) => ({ id: r.id, 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 // one it should already have taken. Rows over the cap are the `stuckEmails` // set above and must not be counted twice. - const now = new Date(); - const dueBefore = new Date(now.getTime() - WAITING_EMAIL_GRACE_MS); - const waitingEmails = await db('email_queue') + // + // Only the engine-safe half of that predicate runs in SQL; the two time + // 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('retry_count', '<', 3) - .where('created_at', '<=', dueBefore.toISOString()) - .andWhere(function () { - this.whereNull('scheduled_at').orWhere('scheduled_at', '<=', now.toISOString()); - }) .orderBy('created_at', 'asc') - .limit(200) - .select('id', 'recipient_email', 'email_type', 'status', 'retry_count', 'error_message', 'created_at'); + .limit(WAITING_SCAN_LIMIT) + .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, { stuckEmails: stuckEmails.map(mapEmailRow), @@ -167,9 +217,20 @@ router.get( ); /** - * POST /failures/email/:id/retry — re-queue a stuck email (status back to - * pending, retry_count reset, error cleared, scheduled_at cleared so the - * 60s processor picks it up on its next pass). + * POST /failures/email/:id/retry — re-queue an email and flush it now. + * + * 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( '/failures/email/:id/retry', @@ -184,7 +245,14 @@ router.post( scheduled_at: null, }); 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 }); }), ); diff --git a/backend/src/services/emailProcessor.js b/backend/src/services/emailProcessor.js index 9f8b4c08..6d0aab60 100644 --- a/backend/src/services/emailProcessor.js +++ b/backend/src/services/emailProcessor.js @@ -1003,6 +1003,11 @@ async function processEmailQueue({ ignoreSchedule = false, limit = 10, onlyId = if (pendingEmails.length === 0) { 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; } diff --git a/frontend/src/i18n/locales/de.json b/frontend/src/i18n/locales/de.json index dd5ee9a3..dfef7dc8 100644 --- a/frontend/src/i18n/locales/de.json +++ b/frontend/src/i18n/locales/de.json @@ -107,7 +107,8 @@ "error": "Fehler", "queued": "Eingereiht", "actions": "Aktionen" - } + }, + "emptyNotAllClear": "Nichts ist fehlgeschlagen — beachten Sie aber die Hinweise oben." }, "waitingEmails": { "title": "Wartet auf Versand", @@ -118,7 +119,8 @@ "unknownError": "unbekannt", "col": { "attempts": "Versuche" - } + }, + "emptyButUnworked": "Noch ist nichts überfällig, es sendet aber auch nichts — siehe Prozessor oben. Alles ab jetzt Eingereihte bleibt hier liegen." }, "processor": { "title": "E-Mail-Warteschlangen-Prozessor", diff --git a/frontend/src/i18n/locales/en.json b/frontend/src/i18n/locales/en.json index 34e925fd..a677f4b3 100644 --- a/frontend/src/i18n/locales/en.json +++ b/frontend/src/i18n/locales/en.json @@ -107,7 +107,8 @@ "error": "Error", "queued": "Queued", "actions": "Actions" - } + }, + "emptyNotAllClear": "Nothing has failed — but see above." }, "waitingEmails": { "title": "Waiting to send", @@ -118,7 +119,8 @@ "unknownError": "unknown", "col": { "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": { "title": "Email queue processor", diff --git a/frontend/src/pages/admin/SystemHealthPage.tsx b/frontend/src/pages/admin/SystemHealthPage.tsx index 0c39b6cb..4c2e96f9 100644 --- a/frontend/src/pages/admin/SystemHealthPage.tsx +++ b/frontend/src/pages/admin/SystemHealthPage.tsx @@ -186,10 +186,22 @@ export const SystemHealthPage: React.FC = () => { {isLoading ? : waitingEmails.length === 0 ? ( -
- - {t('systemHealth.waitingEmails.empty', 'Nothing waiting — the queue is being worked.')} -
+ // "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' ? ( +
+ + {t('systemHealth.waitingEmails.empty', 'Nothing waiting — the queue is being worked.')} +
+ ) : ( +
+ + {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.')} +
+ ) ) : ( <>

@@ -215,7 +227,13 @@ export const SystemHealthPage: React.FC = () => { {isLoading ? : stuckEmails.length === 0 ? (

- {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.')}
) : emailTable(stuckEmails, true)}