From 73d867521aff9536e95b334192ebf8d131ddc72c Mon Sep 17 00:00:00 2001 From: Paul Nothaft Date: Wed, 2 Sep 2026 12:55:11 +0200 Subject: [PATCH 1/5] fix(email): show a queue nobody is working instead of reporting all-clear Closes #1262. "Gallery email queued" reads as a delivery confirmation, and System Health agreed with it: "No stuck or failed emails -- all clear", while not one email had gone out. Both statements were true and neither was the one the admin needed. Queueing writes an email_queue row at status='pending', retry_count 0 -- nothing more. /failures matched only status='failed' or pending-with-retry_count>=3, so it matched none of those rows, and there are two ordinary ways they never leave that state: - startEmailQueueProcessor() was never reached, so nothing polls the queue. - Every pass returns early. processEmailQueue bails when the transporter will not initialise, before it touches a single row, so retry_count stays 0 and no error_message is ever written. A working SMTP test button does not contradict this: that path builds its own transport. adminSystem.js made it worse by reporting `emailProcessor: { status: 'active' }` as a literal, so the one place that named the worker always said it was fine. - emailProcessor records what each pass did -- started, lastRunAt, lastResult, lastError -- and exports getQueueProcessorStatus(). The transporter bail and the queue-query failure, the two silent early returns, both write lastError. - /failures gains `waitingEmails`: pending, under the retry cap, past any scheduled_at, and queued more than 10 minutes ago. The predicate mirrors the processor's own pickup query, so a row listed there is one it should already have taken; rows over the cap stay in `stuckEmails` and are not counted twice. A future scheduled_at is left alone -- split-payment invoices and the business-hours floor park rows deliberately. - System Health leads with the processor's state (running / stopped / degraded) and lists waiting emails in their own table. The all-clear now needs both buckets empty. - adminSystem reports the real processor state instead of the literal. - The two "queued" toasts say the queue processor is what sends it and where to look if it doesn't arrive. 8 route tests, all 8 failing before the change. --- .../adminSystemHealthWaitingEmails.test.js | 158 +++++++++++++ backend/src/routes/adminSystem.js | 13 +- backend/src/routes/adminSystemHealth.js | 61 ++++- backend/src/services/emailProcessor.js | 34 +++ frontend/src/i18n/locales/de.json | 21 ++ frontend/src/i18n/locales/en.json | 21 ++ frontend/src/pages/admin/EventDetailsPage.tsx | 6 +- frontend/src/pages/admin/SystemHealthPage.tsx | 208 +++++++++++++----- .../admin/event-details/ShareLinkCard.tsx | 5 +- frontend/src/services/systemHealth.service.ts | 17 +- 10 files changed, 480 insertions(+), 64 deletions(-) create mode 100644 backend/__tests__/routes/adminSystemHealthWaitingEmails.test.js diff --git a/backend/__tests__/routes/adminSystemHealthWaitingEmails.test.js b/backend/__tests__/routes/adminSystemHealthWaitingEmails.test.js new file mode 100644 index 00000000..4397087f --- /dev/null +++ b/backend/__tests__/routes/adminSystemHealthWaitingEmails.test.js @@ -0,0 +1,158 @@ +/** + * System Health must not report "all clear" over a queue nobody is working (#1262). + * + * "Gallery email queued" reads as a delivery confirmation, and the two ways the + * queue silently stops — the processor never started, or every pass returns + * early because the transport will not initialise — leave every row at + * status='pending' with retry_count 0. The old /failures query matched only + * status='failed' or pending-with-retry_count>=3, so it matched none of them + * and the page said everything was fine while nothing had been sent. + */ + +const path = require('path'); +const fs = require('fs'); +const os = require('os'); + +process.env.NODE_ENV = 'test'; +process.env.TEST_DATABASE_PATH = path.join( + fs.mkdtempSync(path.join(os.tmpdir(), 'picpeak-mailhealth-')), 'db.sqlite', +); +process.env.JWT_SECRET = process.env.JWT_SECRET || 'mailhealth-test-secret'; + +const request = require('supertest'); +const bcrypt = require('bcrypt'); +const jwt = require('jsonwebtoken'); + +const { bootCrmDb, seedMinimal, buildRouteApp } = require('../integration/helpers/crmDb'); + +const MINUTE = 60 * 1000; +const ago = (ms) => new Date(Date.now() - ms).toISOString(); +const ahead = (ms) => new Date(Date.now() + ms).toISOString(); + +describe('GET /admin/system-health/failures — waiting emails (#1262)', () => { + let db; let cleanup; let app; let token; + + const queue = (row) => db('email_queue').insert({ + recipient_email: 'someone@example.com', + email_type: 'gallery_created', + email_data: '{}', + status: 'pending', + retry_count: 0, + created_at: ago(60 * MINUTE), + ...row, + }); + + const failures = async () => { + const res = await request(app) + .get('/admin/system-health/failures') + .set('Authorization', `Bearer ${token}`); + expect(res.status).toBe(200); + return res.body.data || res.body; + }; + + const typesOf = (rows) => rows.map((r) => r.emailType).sort(); + + beforeAll(async () => { + ({ db, cleanup } = await bootCrmDb()); + await seedMinimal(db); + + const role = await db('roles').where({ name: 'super_admin' }).first(); + const inserted = await db('admin_users').insert({ + username: 'mailhealth-admin', + email: 'mailhealth-admin@example.com', + password_hash: await bcrypt.hash('Passw0rd!', 4), + role_id: role.id, + is_active: 1, + created_at: new Date().toISOString(), + updated_at: new Date().toISOString(), + }).returning('id'); + const adminId = inserted[0]?.id ?? inserted[0]; + token = jwt.sign( + { id: adminId, username: 'mailhealth-admin', type: 'admin', role: 'super_admin', loginTime: Date.now() }, + process.env.JWT_SECRET, + { expiresIn: '1h', issuer: 'picpeak-auth' }, + ); + + app = buildRouteApp('/admin/system-health', require('../../src/routes/adminSystemHealth')); + }); + + afterAll(async () => { await cleanup(); }); + afterEach(async () => { await db('email_queue').del(); }); + + it('reports a due pending email the processor never picked up', async () => { + // Exactly the shape "Gallery email queued" leaves behind when the worker + // is not running: pending, no retries, no error, no scheduled_at. + await queue({ email_type: 'gallery_created' }); + + const body = await failures(); + expect(typesOf(body.waitingEmails)).toEqual(['gallery_created']); + expect(body.counts.waitingEmails).toBe(1); + // ...and it is NOT a failure, so the two buckets stay distinct. + expect(body.stuckEmails).toEqual([]); + }); + + it('leaves a freshly queued email alone — the processor wakes every 60s', async () => { + await queue({ email_type: 'customer_invitation', created_at: ago(30 * 1000) }); + + const body = await failures(); + expect(body.waitingEmails).toEqual([]); + expect(body.counts.waitingEmails).toBe(0); + }); + + it('leaves an email scheduled for later alone', async () => { + // Split-payment invoices and the business-hours floor both park rows in + // the future on purpose. Not being sent yet is the point of those. + await queue({ email_type: 'invoice_due', scheduled_at: ahead(3 * 24 * 60 * MINUTE) }); + + const body = await failures(); + expect(body.waitingEmails).toEqual([]); + }); + + it('counts a past-due scheduled email once its moment has come', async () => { + await queue({ email_type: 'invoice_due', scheduled_at: ago(30 * MINUTE) }); + + const body = await failures(); + expect(typesOf(body.waitingEmails)).toEqual(['invoice_due']); + }); + + it('does not double-count a retry-exhausted email as waiting', async () => { + // retry_count >= 3 is already the `stuckEmails` bucket; listing it in both + // would inflate the badge and make the two tables disagree. + await queue({ email_type: 'quote_sent', retry_count: 3, error_message: 'template missing' }); + + const body = await failures(); + expect(body.waitingEmails).toEqual([]); + expect(typesOf(body.stuckEmails)).toEqual(['quote_sent']); + }); + + it('ignores emails that were sent', async () => { + await queue({ email_type: 'gallery_created', status: 'sent', sent_at: ago(20 * MINUTE) }); + + const body = await failures(); + expect(body.waitingEmails).toEqual([]); + expect(body.stuckEmails).toEqual([]); + }); + + 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 + // pending row invisible, so the page has to be able to say it. + expect(body.processor).toEqual(expect.objectContaining({ started: false })); + expect(body.processor).toHaveProperty('lastRunAt'); + expect(body.processor).toHaveProperty('lastError'); + }); + + 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' }); + + // No SMTP configured, so initializeTransporter() yields nothing and the + // pass returns early. Before #1262 that left no trace anywhere. + await processEmailQueue(); + + expect(getQueueProcessorStatus().lastError).toMatch(/transporter could not be initialised/i); + const body = await failures(); + expect(body.processor.lastError).toMatch(/transporter could not be initialised/i); + expect(body.counts.waitingEmails).toBe(1); + }); +}); diff --git a/backend/src/routes/adminSystem.js b/backend/src/routes/adminSystem.js index a1f8e987..8a5b2c34 100644 --- a/backend/src/routes/adminSystem.js +++ b/backend/src/routes/adminSystem.js @@ -9,6 +9,7 @@ const { formatBoolean } = require('../utils/dbCompat'); const logger = require('../utils/logger'); const { resolveSqlitePath } = require('../utils/databaseEngine'); const { checkForUpdates, getCurrentChannel, getCurrentVersion, getReleasesSince, compareVersions } = require('../services/updateCheckService'); +const { getQueueProcessorStatus } = require('../services/emailProcessor'); const { getAppSetting, upsertAppSetting } = require('../utils/appSettings'); const { parseWhatsNew } = require('../utils/whatsNew'); const { detectEnvironment, generateUpdateInstructions } = require('../services/environmentService'); @@ -346,7 +347,17 @@ router.get('/status', adminAuth, requirePermission(['settings.view', 'system.vie services: { fileWatcher: { status: 'active' }, // These would ideally check actual service status expirationChecker: { status: 'active' }, - emailProcessor: { status: 'active' } + // #1262 — this used to be hardcoded 'active', which reported a healthy + // worker on a deployment whose queue had never been touched. Report + // what the processor itself recorded instead. + emailProcessor: (() => { + const p = getQueueProcessorStatus(); + return { + status: p.started && !p.lastError ? 'active' : (p.started ? 'degraded' : 'stopped'), + lastRunAt: p.lastRunAt, + lastError: p.lastError, + }; + })() }, timestamp: new Date() }; diff --git a/backend/src/routes/adminSystemHealth.js b/backend/src/routes/adminSystemHealth.js index c1a60556..20de8108 100644 --- a/backend/src/routes/adminSystemHealth.js +++ b/backend/src/routes/adminSystemHealth.js @@ -23,6 +23,7 @@ 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 { db } = require('../database/db'); const router = express.Router(); @@ -85,6 +86,24 @@ router.get( }), ); +/** + * How long an email may sit due-but-unsent before it counts as waiting rather + * than merely in flight. The processor wakes every 60s and takes 10 rows a + * pass, so a genuine backlog of ~6000 clears inside this window — anything + * still here has not been worked. + */ +const WAITING_EMAIL_GRACE_MS = 10 * 60 * 1000; + +const mapEmailRow = (r) => ({ + id: r.id, + recipientEmail: r.recipient_email, + emailType: r.email_type, + status: r.status, + retryCount: r.retry_count, + errorMessage: r.error_message, + createdAt: r.created_at, +}); + /** * GET /api/admin/system-health/failures * @@ -94,6 +113,14 @@ router.get( * (status='pending' AND retry_count >= 3 — the processor only picks up * retry_count < 3). Trigger: a 14h window where 'quote_sent' template * errors left invoices unsent with no admin-visible signal. + * + * #1262 added the other half. A queue nobody is working produces no failures + * at all: the rows sit at status='pending' with retry_count 0, matching + * neither branch above, and the page reported "all clear" while not one email + * had gone out. That happens whenever the processor never started, or every + * pass returns early because the transport will not initialise. So the + * response also carries emails that are DUE and still unsent + * (`waitingEmails`), plus what the processor itself last did (`processor`). */ router.get( '/failures', @@ -110,17 +137,31 @@ router.get( .limit(200) .select('id', 'recipient_email', 'email_type', 'status', 'retry_count', 'error_message', 'created_at'); + // Deliberately mirrors the processor's own pickup predicate — pending, + // 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') + .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'); + return successResponse(res, { - stuckEmails: stuckEmails.map((r) => ({ - id: r.id, - recipientEmail: r.recipient_email, - emailType: r.email_type, - status: r.status, - retryCount: r.retry_count, - errorMessage: r.error_message, - createdAt: r.created_at, - })), - counts: { stuckEmails: stuckEmails.length }, + stuckEmails: stuckEmails.map(mapEmailRow), + waitingEmails: waitingEmails.map(mapEmailRow), + processor: getQueueProcessorStatus(), + counts: { + stuckEmails: stuckEmails.length, + waitingEmails: waitingEmails.length, + }, }); }), ); diff --git a/backend/src/services/emailProcessor.js b/backend/src/services/emailProcessor.js index 7b1b9bdf..9f8b4c08 100644 --- a/backend/src/services/emailProcessor.js +++ b/backend/src/services/emailProcessor.js @@ -922,9 +922,32 @@ async function renderQueuedEmail(templateKey, variables = {}, to = '') { // because ignoreSchedule also bypasses that cap. // // Returns { processed, sent, failed }. +// What the last pass actually did, so System Health can say whether the queue +// is being worked at all (#1262). "Queued" is not "delivered", and the two +// ways a queue silently stops -- the processor never started, or every pass +// returns early because the transport will not initialise -- both leave rows +// at status='pending' with retry_count 0, which no failure query matches. +const processorStatus = { + started: false, + lastRunAt: null, + lastResult: null, + lastError: null, +}; + +function getQueueProcessorStatus() { + return { + started: processorStatus.started, + lastRunAt: processorStatus.lastRunAt, + lastResult: processorStatus.lastResult, + lastError: processorStatus.lastError, + }; +} + async function processEmailQueue({ ignoreSchedule = false, limit = 10, onlyId = null } = {}) { logger.info('Email queue processor: Checking for pending emails...'); const result = { processed: 0, sent: 0, failed: 0 }; + processorStatus.lastRunAt = new Date().toISOString(); + processorStatus.lastError = null; try { // Try to initialize transporter if it's null (in case it failed at startup). @@ -937,6 +960,10 @@ async function processEmailQueue({ ignoreSchedule = false, limit = 10, onlyId = transporter = await initializeTransporter(); if (!transporter) { logger.warn('Email transporter could not be initialized, skipping queue processing'); + // #1262 — the row stays pending with retry_count 0, so nothing in the + // queue itself records that this pass did nothing. Say so here. + processorStatus.lastError = 'Email transporter could not be initialised — check the SMTP settings'; + processorStatus.lastResult = result; return result; } } @@ -969,6 +996,8 @@ async function processEmailQueue({ ignoreSchedule = false, limit = 10, onlyId = .limit(limit); } catch (dbError) { logger.error('Failed to query email queue:', dbError); + processorStatus.lastError = dbError.message; + processorStatus.lastResult = result; return result; } @@ -1043,8 +1072,10 @@ async function processEmailQueue({ ignoreSchedule = false, limit = 10, onlyId = } } catch (error) { logger.error('Error processing email queue:', error); + processorStatus.lastError = error.message; } + processorStatus.lastResult = result; return result; } @@ -1203,6 +1234,7 @@ function startEmailQueueProcessor() { }); }, 60000); + processorStatus.started = true; logger.info('Email queue processor started successfully'); } else { logger.info('Email queue processor: Already running'); @@ -1213,6 +1245,7 @@ function stopEmailQueueProcessor() { if (emailQueueInterval) { clearInterval(emailQueueInterval); emailQueueInterval = null; + processorStatus.started = false; logger.info('Email queue processor stopped'); } } @@ -1231,6 +1264,7 @@ module.exports = { sendRawEmail, renderQueuedEmail, processEmailQueue, + getQueueProcessorStatus, queueEmail, stopEmailQueueProcessor, testEmailConnection, diff --git a/frontend/src/i18n/locales/de.json b/frontend/src/i18n/locales/de.json index a2c54391..dd5ee9a3 100644 --- a/frontend/src/i18n/locales/de.json +++ b/frontend/src/i18n/locales/de.json @@ -108,6 +108,26 @@ "queued": "Eingereiht", "actions": "Aktionen" } + }, + "waitingEmails": { + "title": "Wartet auf Versand", + "empty": "Nichts in Wartestellung — die Warteschlange wird abgearbeitet.", + "description": "Vor über 10 Minuten eingereiht, jetzt fällig und weiterhin nicht versendet. Diese E-Mails sind nicht fehlgeschlagen — es hat niemand versucht, sie zu senden.", + "neverAttempted": "kein Versuch", + "attempted": "{{count}} Versuch(e), letzter Fehler: {{error}}", + "unknownError": "unbekannt", + "col": { + "attempts": "Versuche" + } + }, + "processor": { + "title": "E-Mail-Warteschlangen-Prozessor", + "running": "Läuft.", + "stopped": "Läuft auf dieser Instanz nicht. Eingereihte E-Mails werden in die Datenbank geschrieben, aber niemand versendet sie.", + "degraded": "Läuft, aber der letzte Durchlauf konnte nicht senden: {{error}}", + "lastRun": "Letzter Durchlauf {{when}}", + "neverRan": "Seit dem Start dieser Instanz nicht gelaufen.", + "lastResult": "{{sent}} gesendet, {{failed}} fehlgeschlagen" } }, "common": { @@ -1324,6 +1344,7 @@ "resetGalleryPassword": "Galerie-Passwort zurücksetzen", "resendCreationEmail": "Erstellungs-E-Mail erneut senden", "creationEmailResent": "Die Erstellungs-E-Mail wurde zur Warteschlange hinzugefügt", + "emailQueuedHint": "Der Warteschlangen-Prozessor versendet sie — prüfen Sie den Systemzustand, falls sie nicht ankommt.", "failedToResendEmail": "Fehler beim erneuten Senden der Erstellungs-E-Mail", "photoStatistics": "Fotostatistiken", "managePhotos": "Fotos verwalten", diff --git a/frontend/src/i18n/locales/en.json b/frontend/src/i18n/locales/en.json index f4762a49..34e925fd 100644 --- a/frontend/src/i18n/locales/en.json +++ b/frontend/src/i18n/locales/en.json @@ -108,6 +108,26 @@ "queued": "Queued", "actions": "Actions" } + }, + "waitingEmails": { + "title": "Waiting to send", + "empty": "Nothing waiting — the queue is being worked.", + "description": "Queued more than 10 minutes ago, due now, and still unsent. These have not failed — nothing has tried to send them.", + "neverAttempted": "never attempted", + "attempted": "{{count}} attempt(s), last error: {{error}}", + "unknownError": "unknown", + "col": { + "attempts": "Attempts" + } + }, + "processor": { + "title": "Email queue processor", + "running": "Running.", + "stopped": "Not running on this instance. Queued emails are written to the database but nothing is sending them.", + "degraded": "Running, but the last pass could not send: {{error}}", + "lastRun": "Last pass {{when}}", + "neverRan": "Has not run since this instance started.", + "lastResult": "{{sent}} sent, {{failed}} failed" } }, "common": { @@ -820,6 +840,7 @@ "resetGalleryPassword": "Reset Gallery Password", "resendCreationEmail": "Resend Creation Email", "creationEmailResent": "Creation email has been queued for sending", + "emailQueuedHint": "The queue processor sends it — check System health if it does not arrive.", "failedToResendEmail": "Failed to resend creation email", "photoStatistics": "Photo Statistics", "totalPhotos": "Total Photos", diff --git a/frontend/src/pages/admin/EventDetailsPage.tsx b/frontend/src/pages/admin/EventDetailsPage.tsx index da2066b1..01810dd0 100644 --- a/frontend/src/pages/admin/EventDetailsPage.tsx +++ b/frontend/src/pages/admin/EventDetailsPage.tsx @@ -316,11 +316,13 @@ export const EventDetailsPage: React.FC = () => { mutationFn: (password?: string) => eventsService.sendGalleryEmail(parseInt(id!), password ? { password } : undefined), onSuccess: (result) => { + // #1262 — queueing is not delivery, and a queue nobody is working + // reports no failure at all. Point at where the queue is visible. toast.success( - t('events.sendGalleryEmail.success', { + `${t('events.sendGalleryEmail.success', { recipient: result.recipient, defaultValue: 'Gallery email queued to {{recipient}}.', - }), + })} ${t('events.emailQueuedHint', 'The queue processor sends it — check System health if it does not arrive.')}`, ); setShowSendEmailDialog(false); }, diff --git a/frontend/src/pages/admin/SystemHealthPage.tsx b/frontend/src/pages/admin/SystemHealthPage.tsx index 21198aa2..0c39b6cb 100644 --- a/frontend/src/pages/admin/SystemHealthPage.tsx +++ b/frontend/src/pages/admin/SystemHealthPage.tsx @@ -2,15 +2,22 @@ * Admin → System health. Aggregates background failures that would * otherwise go unnoticed. v1: stuck/failed outbound emails (the queue * processor gave up or exhausted retries), with retry + dismiss. + * + * #1262 — "no failures" was being read as "everything went out". It is not the + * same claim: a queue nobody is working produces no failures at all, because + * every row sits at status='pending' with retry_count 0. So the page now leads + * with what the processor itself last did, and lists due-but-unsent emails + * next to the failed ones. The all-clear only shows when both are empty and + * the processor is running. */ import React from 'react'; import { useTranslation } from 'react-i18next'; import { useQuery } from '@tanstack/react-query'; -import { AlertCircle, RefreshCw, Trash2, CheckCircle } from 'lucide-react'; +import { AlertCircle, RefreshCw, Trash2, CheckCircle, Clock, Mail, MailX } from 'lucide-react'; import { Button, Card, Loading } from '../../components/common'; import { useMutationWithToast } from '../../hooks'; import { useLocalizedDate } from '../../hooks/useLocalizedDate'; -import { systemHealthService } from '../../services/systemHealth.service'; +import { systemHealthService, type StuckEmail } from '../../services/systemHealth.service'; export const SystemHealthPage: React.FC = () => { const { t } = useTranslation(); @@ -35,6 +42,82 @@ export const SystemHealthPage: React.FC = () => { }); const stuckEmails = data?.stuckEmails ?? []; + const waitingEmails = data?.waitingEmails ?? []; + const processor = data?.processor; + + // The processor is only "fine" when it has been started AND its last pass + // didn't bail. A started-but-erroring processor is the case that used to + // read as healthy, so it gets its own state rather than folding into either. + const processorState: 'ok' | 'degraded' | 'stopped' = !processor + ? 'ok' + : !processor.started + ? 'stopped' + : processor.lastError + ? 'degraded' + : 'ok'; + + const emailTable = (rows: StuckEmail[], showError: boolean) => ( +
+
+ + + + + + + + + + + + {rows.map((m) => ( + + + + + + + + ))} + +
{t('systemHealth.stuckEmails.col.recipient', 'Recipient')}{t('systemHealth.stuckEmails.col.type', 'Type')} + {showError + ? t('systemHealth.stuckEmails.col.error', 'Error') + : t('systemHealth.waitingEmails.col.attempts', 'Attempts')} + {t('systemHealth.stuckEmails.col.queued', 'Queued')}{t('systemHealth.stuckEmails.col.actions', 'Actions')}
{m.recipientEmail}{m.emailType} + {showError ? ( + + {m.errorMessage || t('systemHealth.stuckEmails.noError', 'retries exhausted')} + + ) : ( + + {m.retryCount > 0 + ? t('systemHealth.waitingEmails.attempted', '{{count}} attempt(s), last error: {{error}}', { + count: m.retryCount, + error: m.errorMessage || t('systemHealth.waitingEmails.unknownError', 'unknown'), + }) + : t('systemHealth.waitingEmails.neverAttempted', 'never attempted')} + + )} + {m.createdAt ? fmtDateTime(m.createdAt) : '—'} +
+ + +
+
+
+
+ ); return (
@@ -45,6 +128,79 @@ export const SystemHealthPage: React.FC = () => {

+ {/* Queue processor. Listed first because when this is stopped, every + other count on the page is explained by it — and a stopped processor + shows no failures at all, which is what made it invisible. */} + {!isLoading && processor && ( + +
+ {processorState === 'ok' + ? + : } +
+

+ {t('systemHealth.processor.title', 'Email queue processor')} +

+

+ {processorState === 'stopped' + ? t('systemHealth.processor.stopped', + 'Not running on this instance. Queued emails are written to the database but nothing is sending them.') + : processorState === 'degraded' + ? t('systemHealth.processor.degraded', + 'Running, but the last pass could not send: {{error}}', { error: processor.lastError }) + : t('systemHealth.processor.running', 'Running.')} +

+

+ {processor.lastRunAt + ? t('systemHealth.processor.lastRun', 'Last pass {{when}}', { when: fmtDateTime(processor.lastRunAt) }) + : t('systemHealth.processor.neverRan', 'Has not run since this instance started.')} + {processor.lastResult && ( + <> {' · '} + {t('systemHealth.processor.lastResult', '{{sent}} sent, {{failed}} failed', { + sent: processor.lastResult.sent, + failed: processor.lastResult.failed, + })} + + )} +

+
+
+ + )} + + {/* Due but unsent. Distinct from failed: nothing went wrong with these, + they were simply never picked up. */} + +
+ +

+ {t('systemHealth.waitingEmails.title', 'Waiting to send')} +

+ {!isLoading && ( + ({waitingEmails.length}) + )} +
+ + {isLoading ? : waitingEmails.length === 0 ? ( +
+ + {t('systemHealth.waitingEmails.empty', 'Nothing waiting — the queue is being worked.')} +
+ ) : ( + <> +

+ {t('systemHealth.waitingEmails.description', + 'Queued more than 10 minutes ago, due now, and still unsent. These have not failed — nothing has tried to send them.')} +

+ {emailTable(waitingEmails, false)} + + )} + +
@@ -61,53 +217,7 @@ export const SystemHealthPage: React.FC = () => { {t('systemHealth.stuckEmails.empty', 'No stuck or failed emails — all clear.')}
- ) : ( -
-
- - - - - - - - - - - - {stuckEmails.map((m) => ( - - - - - - - - ))} - -
{t('systemHealth.stuckEmails.col.recipient', 'Recipient')}{t('systemHealth.stuckEmails.col.type', 'Type')}{t('systemHealth.stuckEmails.col.error', 'Error')}{t('systemHealth.stuckEmails.col.queued', 'Queued')}{t('systemHealth.stuckEmails.col.actions', 'Actions')}
{m.recipientEmail}{m.emailType} - - {m.errorMessage || t('systemHealth.stuckEmails.noError', 'retries exhausted')} - - {m.createdAt ? fmtDateTime(m.createdAt) : '—'} -
- - -
-
-
-
- )} + ) : emailTable(stuckEmails, true)} ); diff --git a/frontend/src/pages/admin/event-details/ShareLinkCard.tsx b/frontend/src/pages/admin/event-details/ShareLinkCard.tsx index 8b7f4c7d..859fccd8 100644 --- a/frontend/src/pages/admin/event-details/ShareLinkCard.tsx +++ b/frontend/src/pages/admin/event-details/ShareLinkCard.tsx @@ -193,7 +193,10 @@ export const ShareLinkCard: React.FC = ({ event, setShowPass onClick={async () => { try { await eventsService.resendCreationEmail(event.id); - toast.success(t('events.creationEmailResent')); + // #1262 — "queued" was being read as "delivered". Queueing only + // writes an email_queue row; say where to look when it doesn't + // turn up, because a queue nobody is working raises no failure. + toast.success(`${t('events.creationEmailResent')} ${t('events.emailQueuedHint', 'The queue processor sends it — check System health if it does not arrive.')}`); } catch { toast.error(t('events.failedToResendEmail')); } diff --git a/frontend/src/services/systemHealth.service.ts b/frontend/src/services/systemHealth.service.ts index 2dd84035..ef06b74c 100644 --- a/frontend/src/services/systemHealth.service.ts +++ b/frontend/src/services/systemHealth.service.ts @@ -1,6 +1,10 @@ /** * Admin → System health. Surfaces background failures (v1: stuck/failed * outbound emails) so they don't sit unnoticed, with retry/dismiss. + * + * #1262 added `waitingEmails` and `processor`: a queue nobody is working + * produces no failures at all, so "no failures" was not the same claim as + * "everything went out". */ import { api } from '../config/api'; @@ -14,9 +18,20 @@ export interface StuckEmail { createdAt: string; } +/** What the queue processor last did — the difference between "idle" and "dead". */ +export interface EmailProcessorStatus { + started: boolean; + lastRunAt: string | null; + lastResult: { processed: number; sent: number; failed: number } | null; + lastError: string | null; +} + export interface SystemHealthFailures { stuckEmails: StuckEmail[]; - counts: { stuckEmails: number }; + /** Due, under the retry cap, and still unsent — nobody picked them up. */ + waitingEmails: StuckEmail[]; + processor: EmailProcessorStatus; + counts: { stuckEmails: number; waitingEmails: number }; } export const systemHealthService = { From 89db469f061fcbe5bdd101587f17fff32826c699 Mon Sep 17 00:00:00 2001 From: Paul Nothaft Date: Wed, 2 Sep 2026 14:35:54 +0200 Subject: [PATCH 2/5] 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. --- .../adminSystemHealthWaitingEmails.test.js | 142 ++++++++++++++++++ backend/src/routes/adminSystemHealth.js | 96 ++++++++++-- backend/src/services/emailProcessor.js | 5 + frontend/src/i18n/locales/de.json | 6 +- frontend/src/i18n/locales/en.json | 6 +- frontend/src/pages/admin/SystemHealthPage.tsx | 28 +++- 6 files changed, 260 insertions(+), 23 deletions(-) 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)} From 98aa06aeff18e23e655b14f671fe53441033fe14 Mon Sep 17 00:00:00 2001 From: Paul Nothaft Date: Wed, 2 Sep 2026 14:57:00 +0200 Subject: [PATCH 3/5] fix(email): read naive SQLite timestamps as UTC, and page the candidates Codex review round 2 on #1273. Both findings restore the false all-clear that round 1 set out to remove, by different routes. Both timestamp columns default to CURRENT_TIMESTAMP, which SQLite renders as a zone-less 'YYYY-MM-DD HH:MM:SS' in UTC -- and Date.parse reads that shape as LOCAL time. On a TZ=America/New_York deployment a row due now looked four hours away and never reached the waiting list; nine hours the other way, fresh mail read as long overdue. The parser now stamps the zone the value actually carries. That parser moved to utils/queueTimestamps so it can be tested honestly. This suite runs in UTC, where reading a zone-less value as local and as UTC give the same answer, and process.env.TZ does not reliably re-bind mid-process -- my first attempt at these tests passed against the broken code for exactly that reason. They now force TZ in a child process, so they fail on any host. The candidate rows are paged rather than cut off with one LIMIT. The time filter runs in JS, so a queue holding more than a page of future-scheduled rows -- split-payment invoices are exactly that shape -- filled the window with rows that all got filtered out and hid the due row behind them, reporting nothing waiting. Paging also drops the dependency on ORDER BY created_at meaning anything, which it does not on SQLite once numeric and text timestamps mix. Bounded at 10k scanned; past that the response is a sample, which the 200-row cap already made it. 12 more tests. The paging one fails before this commit, and all four naive-timestamp ones fail against the old parsing on any host. --- .../adminSystemHealthWaitingEmails.test.js | 34 ++++++++ .../__tests__/utils/queueTimestamps.test.js | 83 ++++++++++++++++++ backend/src/routes/adminSystemHealth.js | 85 +++++++++---------- backend/src/utils/queueTimestamps.js | 44 ++++++++++ 4 files changed, 203 insertions(+), 43 deletions(-) create mode 100644 backend/__tests__/utils/queueTimestamps.test.js create mode 100644 backend/src/utils/queueTimestamps.js diff --git a/backend/__tests__/routes/adminSystemHealthWaitingEmails.test.js b/backend/__tests__/routes/adminSystemHealthWaitingEmails.test.js index e6275f80..e8b696c4 100644 --- a/backend/__tests__/routes/adminSystemHealthWaitingEmails.test.js +++ b/backend/__tests__/routes/adminSystemHealthWaitingEmails.test.js @@ -222,6 +222,40 @@ describe('GET /admin/system-health/failures — waiting emails (#1262)', () => { }); }); + // --- Codex review round 2 ------------------------------------------------- + // + // The zone-less CURRENT_TIMESTAMP shape is covered in + // __tests__/utils/queueTimestamps.test.js instead of here: this suite runs + // in UTC, where reading such a value as local and as UTC give the same + // answer, and process.env.TZ does not reliably re-bind mid-process. Those + // tests force the zone in a child process, so they fail on any host. + + it('finds a due row behind a page full of future-scheduled ones', async () => { + // Codex review round 2. The candidates used to be cut off with a single + // LIMIT before the time filter ran, so a queue holding a page of + // split-payment invoices scheduled for later hid the due row behind them + // and reported an empty waiting list — the false all-clear, again. + // Over the 1000-row cut-off the first attempt used, so the due row really + // does sit behind a full page rather than merely late in one. + const rows = []; + for (let i = 0; i < 1200; i += 1) { + rows.push({ + recipient_email: `bulk${i}@example.com`, + email_type: 'invoice_due', + email_data: '{}', + status: 'pending', + retry_count: 0, + created_at: ago(90 * MINUTE), + scheduled_at: ahead(30 * 24 * 60 * MINUTE), + }); + } + await db.batchInsert('email_queue', rows, 100); + await queue({ email_type: 'gallery_created', created_at: ago(52 * MINUTE) }); + + const body = await failures(); + expect(typesOf(body.waitingEmails)).toEqual(['gallery_created']); + }); + 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 diff --git a/backend/__tests__/utils/queueTimestamps.test.js b/backend/__tests__/utils/queueTimestamps.test.js new file mode 100644 index 00000000..741b9ee4 --- /dev/null +++ b/backend/__tests__/utils/queueTimestamps.test.js @@ -0,0 +1,83 @@ +/** + * email_queue timestamps come back in three shapes and must all read as the + * same instant (#1262). + * + * The naive-string case is the one that bites in production and cannot be + * pinned from inside this suite: CI runs in UTC, where reading a zone-less + * timestamp as local time and as UTC give the same answer. So those two cases + * run in child processes with TZ forced, which is the only way to make the + * assertion fail on a machine where the bug does not reproduce. + */ +const { execFileSync } = require('child_process'); +const path = require('path'); + +const { toMillis } = require('../../src/utils/queueTimestamps'); + +const UTIL = path.resolve(__dirname, '../../src/utils/queueTimestamps.js'); + +/** Parse `value` in a fresh node process pinned to `tz`. */ +function parseUnderTz(tz, value) { + const script = ` + const { toMillis } = require(${JSON.stringify(UTIL)}); + process.stdout.write(String(toMillis(${JSON.stringify(value)}))); + `; + return Number(execFileSync(process.execPath, ['-e', script], { + env: { ...process.env, TZ: tz }, + encoding: 'utf8', + })); +} + +describe('toMillis — the shapes email_queue timestamps really have', () => { + const INSTANT = Date.UTC(2026, 8, 2, 12, 0, 0); + + it('reads a Date, as Postgres returns', () => { + expect(toMillis(new Date(INSTANT))).toBe(INSTANT); + }); + + it('reads epoch ms, as SQLite stores what queueEmail writes', () => { + expect(toMillis(INSTANT)).toBe(INSTANT); + expect(toMillis(String(INSTANT))).toBe(INSTANT); + }); + + it('reads an ISO string, as fixtures and older rows carry', () => { + expect(toMillis('2026-09-02T12:00:00.000Z')).toBe(INSTANT); + }); + + it('cannot read nulls or nonsense, and says so rather than guessing', () => { + // The caller skips a row it cannot judge; returning 0 or NaN here would + // report every such row as decades overdue. + expect(toMillis(null)).toBeNull(); + expect(toMillis(undefined)).toBeNull(); + expect(toMillis('')).toBeNull(); + expect(toMillis(' ')).toBeNull(); + expect(toMillis('not a timestamp')).toBeNull(); + }); + + describe('CURRENT_TIMESTAMP on SQLite, which carries no zone', () => { + // Both columns default to CURRENT_TIMESTAMP. SQLite renders that as + // 'YYYY-MM-DD HH:MM:SS' in UTC with no marker, and Date.parse reads that + // shape as LOCAL time. + const NAIVE = '2026-09-02 12:00:00'; + + it('is UTC west of Greenwich, where the old reading looked into the future', () => { + // Read as local in New York, this instant lands 4h later than it is, so + // a row due now looked 4h away and never reached the waiting list. + expect(parseUnderTz('America/New_York', NAIVE)).toBe(INSTANT); + }); + + it('is UTC east of it, where the old reading looked into the past', () => { + // Nine hours the other way: fresh mail read as long overdue, which fills + // the page with rows that are perfectly fine. + expect(parseUnderTz('Asia/Tokyo', NAIVE)).toBe(INSTANT); + }); + + it('agrees with itself across zones', () => { + expect(parseUnderTz('America/New_York', NAIVE)) + .toBe(parseUnderTz('Asia/Tokyo', NAIVE)); + }); + + it('accepts the fractional-seconds variant too', () => { + expect(parseUnderTz('America/New_York', '2026-09-02 12:00:00.000')).toBe(INSTANT); + }); + }); +}); diff --git a/backend/src/routes/adminSystemHealth.js b/backend/src/routes/adminSystemHealth.js index de9cb04d..293ea9c5 100644 --- a/backend/src/routes/adminSystemHealth.js +++ b/backend/src/routes/adminSystemHealth.js @@ -24,6 +24,7 @@ const { handleAsync, validateRequest, successResponse } = require('../utils/rout const { verifyDocumentArtefacts } = require('../services/backupIntegrityService'); const { getCoverageReport } = require('../services/backupCoverageService'); const { getQueueProcessorStatus, processEmailQueue } = require('../services/emailProcessor'); +const { toMillis } = require('../utils/queueTimestamps'); const logger = require('../utils/logger'); const { db } = require('../database/db'); @@ -96,41 +97,28 @@ router.get( const WAITING_EMAIL_GRACE_MS = 10 * 60 * 1000; /** - * A timestamp column as milliseconds, whatever the engine handed back. + * Why the two time comparisons happen in JS (toMillis) and not in the WHERE + * clause: SQLite orders INTEGER before TEXT regardless of value, so comparing + * the ms-number this column really holds 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). * - * 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. + * The time filtering happens in JS, so the candidate rows have to be paged + * rather than cut off with a single LIMIT: a queue holding a thousand + * future-scheduled rows (split-payment invoices) would otherwise fill one page + * with rows that all get filtered out and hide the due row behind them, + * reporting an empty waiting list. Paging also removes the dependency on + * ORDER BY created_at being meaningful, which it is not on SQLite when numeric + * and text timestamps are mixed. * - * 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). + * WAITING_SCAN_MAX bounds the work: past it the response is explicitly a + * sample, which the 200-row cap already made it. */ -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 WAITING_PAGE_SIZE = 500; +const WAITING_SCAN_MAX = 10000; +const WAITING_REPORT_LIMIT = 200; const mapEmailRow = (r) => ({ id: r.id, @@ -181,18 +169,10 @@ router.get( // set above and must not be counted twice. // // 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. + // comparisons are done in JS — see utils/queueTimestamps. const now = Date.now(); const dueBefore = now - WAITING_EMAIL_GRACE_MS; - const pendingRows = await db('email_queue') - .where('status', 'pending') - .where('retry_count', '<', 3) - .orderBy('created_at', 'asc') - .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 isWaiting = (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. @@ -202,7 +182,26 @@ router.get( // rather than reporting every such row as waiting. if (createdAt === null) return false; return createdAt <= dueBefore; - }).slice(0, 200); + }; + + const waitingEmails = []; + for (let offset = 0; offset < WAITING_SCAN_MAX; offset += WAITING_PAGE_SIZE) { + // eslint-disable-next-line no-await-in-loop + const page = await db('email_queue') + .where('status', 'pending') + .where('retry_count', '<', 3) + .orderBy('id', 'asc') + .offset(offset) + .limit(WAITING_PAGE_SIZE) + .select('id', 'recipient_email', 'email_type', 'status', 'retry_count', + 'error_message', 'created_at', 'scheduled_at'); + if (page.length === 0) break; + for (const row of page) { + if (isWaiting(row)) waitingEmails.push(row); + if (waitingEmails.length >= WAITING_REPORT_LIMIT) break; + } + if (waitingEmails.length >= WAITING_REPORT_LIMIT || page.length < WAITING_PAGE_SIZE) break; + } return successResponse(res, { stuckEmails: stuckEmails.map(mapEmailRow), diff --git a/backend/src/utils/queueTimestamps.js b/backend/src/utils/queueTimestamps.js new file mode 100644 index 00000000..2ccb5068 --- /dev/null +++ b/backend/src/utils/queueTimestamps.js @@ -0,0 +1,44 @@ +/** + * Reading email_queue timestamps back, whatever shape the engine stored them in. + * + * The columns are written three different ways and read back three different + * ways, and a comparison that assumes one of them is wrong for the other two: + * + * - Postgres hands back a Date. + * - SQLite stores what queueEmail writes -- a JS Date, which the native + * binding turns into epoch ms -- and hands back that number. + * - Both columns also default to CURRENT_TIMESTAMP, which on SQLite is a + * zone-less 'YYYY-MM-DD HH:MM:SS' string in UTC, and older rows plus test + * fixtures carry ISO strings. + * + * Extracted from adminSystemHealth so the parsing can be tested under a forced + * TZ in a child process, which is the only way to pin the naive-timestamp case + * from a test suite that itself runs in UTC (#1262). + */ + +/** 'YYYY-MM-DD HH:MM:SS[.sss]' with no zone — SQLite's CURRENT_TIMESTAMP shape. */ +const SQLITE_NAIVE_TIMESTAMP = /^\d{4}-\d{2}-\d{2}[ T]\d{2}:\d{2}:\d{2}(\.\d+)?$/; + +/** + * @param {Date|number|string|null|undefined} value + * @returns {number|null} epoch ms, or null when the value cannot be read + */ +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; + // Date.parse reads the zone-less shape as LOCAL time. On a + // TZ=America/New_York deployment that puts a row due now four hours in the + // future, so it never reaches the waiting list -- the false all-clear again, + // arrived at via the clock. Stamp the zone the value actually carries. + const stamped = SQLITE_NAIVE_TIMESTAMP.test(text) ? `${text.replace(' ', 'T')}Z` : text; + const parsed = Date.parse(stamped); + return Number.isNaN(parsed) ? null : parsed; +} + +module.exports = { toMillis, SQLITE_NAIVE_TIMESTAMP }; From 4deac229aca1738d61163a63c3ec1353144971b3 Mon Sep 17 00:00:00 2001 From: Paul Nothaft Date: Wed, 2 Sep 2026 15:15:07 +0200 Subject: [PATCH 4/5] fix(email): make waiting rows read-only, and time the grace from when due Codex review round 3 on #1273. The first finding reverses a round-1 fix of mine, correctly. Retry no longer sends. Round 1 flagged that retry was a no-op for waiting rows and offered two remedies: give them a send-now action, or stop showing them Retry. I took the first, and round 3 showed why it is the wrong half -- processEmailQueue claims nothing before invoking the transport, so a flush overlapping the scheduled pass has both of them sending the same email. Saving 60 seconds is not worth a duplicate landing in a customer's inbox, and a claim protocol would need a status no query watches plus a reaper for rows abandoned mid-send. So retry is a reset again, as it was on main. Waiting rows now carry no actions at all, which is the other half of that round-1 remedy and closes a worse hole the shared table opened: Dismiss DELETEs the queue row. Those emails have not failed and still go out once the processor recovers, so clicking the tidy-up icon on a health warning silently cancelled a customer's mail. The section is diagnostic; what a waiting row needs is the processor fixed, which the panel above it now says. The grace window runs from when a row became DUE, not from when it was queued. A split-payment invoice created three days ago and scheduled until a minute ago has had one minute of the processor's attention, and measuring from created_at reported every scheduled mail as unworked the instant it came due -- which is most of what this panel would then have been showing. A truncated scan can no longer read as an all-clear. The scan is bounded, so a queue larger than the budget whose head is all future-scheduled can hide a due row past the last page read; the response now says so and the UI withholds the green check. The test fixtures were wrong in a way worth keeping: scheduled_at also defaults to CURRENT_TIMESTAMP, so back-dating created_at alone built rows that cannot exist in production -- old, but scheduled for the moment the fixture ran. The helper now back-dates both, as the database would have. 3 more tests; the two that pin new behaviour fail before this commit, and the reverted flush is pinned by asserting the transport is NOT invoked. --- .../adminSystemHealthWaitingEmails.test.js | 84 ++++++++++++++----- backend/src/routes/adminSystemHealth.js | 56 ++++++++----- frontend/src/i18n/locales/de.json | 3 +- frontend/src/i18n/locales/en.json | 3 +- frontend/src/pages/admin/SystemHealthPage.tsx | 64 +++++++++----- frontend/src/services/systemHealth.service.ts | 5 +- 6 files changed, 144 insertions(+), 71 deletions(-) diff --git a/backend/__tests__/routes/adminSystemHealthWaitingEmails.test.js b/backend/__tests__/routes/adminSystemHealthWaitingEmails.test.js index e8b696c4..9e23d16d 100644 --- a/backend/__tests__/routes/adminSystemHealthWaitingEmails.test.js +++ b/backend/__tests__/routes/adminSystemHealthWaitingEmails.test.js @@ -61,15 +61,29 @@ const ahead = (ms) => new Date(Date.now() + ms).toISOString(); describe('GET /admin/system-health/failures — waiting emails (#1262)', () => { let db; let cleanup; let app; let token; - const queue = (row) => db('email_queue').insert({ - recipient_email: 'someone@example.com', - email_type: 'gallery_created', - email_data: '{}', - status: 'pending', - retry_count: 0, - created_at: ago(60 * MINUTE), - ...row, - }); + /** + * `scheduled_at` defaults to the same moment as `created_at` unless the + * caller says otherwise, because that is what the database does: BOTH + * columns default to CURRENT_TIMESTAMP, and queueEmail only sets + * scheduled_at explicitly for a deferred send (split-payment invoices, the + * business-hours floor). Back-dating created_at alone would produce a row + * that never exists in production — old, but scheduled for the moment the + * fixture ran — and the grace window is measured from whichever of the two + * made the row due. + */ + const queue = (row = {}) => { + const createdAt = 'created_at' in row ? row.created_at : ago(60 * MINUTE); + return db('email_queue').insert({ + recipient_email: 'someone@example.com', + email_type: 'gallery_created', + email_data: '{}', + status: 'pending', + retry_count: 0, + scheduled_at: createdAt, + ...row, + created_at: createdAt, + }); + }; const failures = async () => { const res = await request(app) @@ -230,6 +244,26 @@ describe('GET /admin/system-health/failures — waiting emails (#1262)', () => { // answer, and process.env.TZ does not reliably re-bind mid-process. Those // tests force the zone in a child process, so they fail on any host. + it('measures the grace window from when the row became due', async () => { + // Codex review round 3. A split-payment invoice created three days ago and + // scheduled until a minute ago has had one minute of the processor's + // attention, not three days of it. Measuring from created_at alone + // reported every scheduled mail as unworked the instant it came due. + await queue({ + email_type: 'invoice_due', + created_at: ago(3 * 24 * 60 * MINUTE), + scheduled_at: ago(1 * MINUTE), + }); + + const body = await failures(); + expect(body.waitingEmails).toEqual([]); + + // Once the grace window has passed since it came due, it counts. + await db('email_queue').update({ scheduled_at: ago(30 * MINUTE) }); + const later = await failures(); + expect(typesOf(later.waitingEmails)).toEqual(['invoice_due']); + }); + it('finds a due row behind a page full of future-scheduled ones', async () => { // Codex review round 2. The candidates used to be cut off with a single // LIMIT before the time filter ran, so a queue holding a page of @@ -256,6 +290,16 @@ describe('GET /admin/system-health/failures — waiting emails (#1262)', () => { expect(typesOf(body.waitingEmails)).toEqual(['gallery_created']); }); + it('flags a truncated scan, so an empty result cannot read as all-clear', async () => { + // Codex review round 3. The scan is bounded, so on a queue larger than the + // budget an overdue row can sit past the last page read. Reporting zero + // waiting there is "not found yet", not "none", and the UI keys its green + // check off this flag. + const body = await failures(); + expect(body.scanTruncated).toBe(false); + expect(body.counts.pendingScanned).toBe(0); + }); + 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 @@ -288,12 +332,12 @@ describe('GET /admin/system-health/failures — waiting emails (#1262)', () => { } }); - 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. + it('does not send from the retry endpoint, which would race the processor', async () => { + // Codex review round 1 asked for either a send-now action on waiting rows + // or no Retry on them at all. Round 3 showed why the first is the wrong + // half: nothing claims a row before the transport is invoked, so a flush + // overlapping the scheduled pass has both of them sending the same email. + // Retry stays a reset, and waiting rows carry no action at all. const transport = stubWebhookTransport(); try { @@ -305,14 +349,10 @@ describe('GET /admin/system-health/failures — waiting emails (#1262)', () => { .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); + expect(transport.send).not.toHaveBeenCalled(); const after = await db('email_queue').where({ id }).first(); - expect(after.retry_count).toBe(1); - expect(after.error_message).toBeTruthy(); + expect(after.status).toBe('pending'); + expect(after.retry_count).toBe(0); } finally { transport.restore(); } diff --git a/backend/src/routes/adminSystemHealth.js b/backend/src/routes/adminSystemHealth.js index 293ea9c5..c938f6c5 100644 --- a/backend/src/routes/adminSystemHealth.js +++ b/backend/src/routes/adminSystemHealth.js @@ -23,9 +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, processEmailQueue } = require('../services/emailProcessor'); +const { getQueueProcessorStatus } = require('../services/emailProcessor'); const { toMillis } = require('../utils/queueTimestamps'); -const logger = require('../utils/logger'); const { db } = require('../database/db'); const router = express.Router(); @@ -181,10 +180,19 @@ router.get( // 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; + // The grace window runs from the moment the row became DUE, not from + // when it was queued. An invoice created three days ago and scheduled + // until a minute ago has had one minute of the processor's attention, + // not three days of it — measuring from created_at would report every + // split-payment and business-hours mail as unworked the instant it came + // due, which is most of what this panel would then be showing. + const dueSince = scheduledAt === null ? createdAt : Math.max(createdAt, scheduledAt); + return dueSince <= dueBefore; }; const waitingEmails = []; + let scanTruncated = false; + let scanned = 0; for (let offset = 0; offset < WAITING_SCAN_MAX; offset += WAITING_PAGE_SIZE) { // eslint-disable-next-line no-await-in-loop const page = await db('email_queue') @@ -196,11 +204,17 @@ router.get( .select('id', 'recipient_email', 'email_type', 'status', 'retry_count', 'error_message', 'created_at', 'scheduled_at'); if (page.length === 0) break; + scanned += page.length; for (const row of page) { if (isWaiting(row)) waitingEmails.push(row); if (waitingEmails.length >= WAITING_REPORT_LIMIT) break; } if (waitingEmails.length >= WAITING_REPORT_LIMIT || page.length < WAITING_PAGE_SIZE) break; + // Ran out of budget with rows still unread. A queue this size whose head + // is all future-scheduled could be hiding a due row past the cap, so the + // empty result below is "not found yet", not "none" — and the UI must + // not turn it into an all-clear. + if (offset + WAITING_PAGE_SIZE >= WAITING_SCAN_MAX) scanTruncated = true; } return successResponse(res, { @@ -210,26 +224,29 @@ router.get( counts: { stuckEmails: stuckEmails.length, waitingEmails: waitingEmails.length, + pendingScanned: scanned, }, + // True when the pending queue was larger than this endpoint will read. + scanTruncated, }); }), ); /** - * POST /failures/email/:id/retry — re-queue an email and flush it now. + * 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). * - * 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. + * Deliberately does NOT send the mail itself. An earlier revision flushed the + * row here via processEmailQueue({ onlyId }), which reads better but races: + * nothing claims a row before the transport is invoked, so a flush overlapping + * the scheduled pass has both of them sending the same email. Saving 60 + * seconds is not worth a duplicate landing in a customer's inbox. * - * 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. + * That is also why waiting rows carry no actions at all — they are already + * pending with retries and schedule clear, so this endpoint would rewrite them + * to the state they are in and change nothing. What a waiting row needs is the + * processor fixed, which the panel above it says. */ router.post( '/failures/email/:id/retry', @@ -244,14 +261,7 @@ router.post( scheduled_at: null, }); if (!updated) return res.status(404).json({ error: 'Email not found' }); - - 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 }); + return successResponse(res, { retried: true }); }), ); diff --git a/frontend/src/i18n/locales/de.json b/frontend/src/i18n/locales/de.json index dfef7dc8..c26d3c40 100644 --- a/frontend/src/i18n/locales/de.json +++ b/frontend/src/i18n/locales/de.json @@ -120,7 +120,8 @@ "col": { "attempts": "Versuche" }, - "emptyButUnworked": "Noch ist nichts überfällig, es sendet aber auch nichts — siehe Prozessor oben. Alles ab jetzt Eingereihte bleibt hier liegen." + "emptyButUnworked": "Noch ist nichts überfällig, es sendet aber auch nichts — siehe Prozessor oben. Alles ab jetzt Eingereihte bleibt hier liegen.", + "truncated": "Die Warteschlange ist zu groß, um sie vollständig zu prüfen — in den gelesenen Zeilen war nichts überfällig, das ist aber keine Entwarnung." }, "processor": { "title": "E-Mail-Warteschlangen-Prozessor", diff --git a/frontend/src/i18n/locales/en.json b/frontend/src/i18n/locales/en.json index a677f4b3..7e302fc9 100644 --- a/frontend/src/i18n/locales/en.json +++ b/frontend/src/i18n/locales/en.json @@ -120,7 +120,8 @@ "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." + "emptyButUnworked": "Nothing is overdue yet, but nothing is sending either — see the processor above. Anything queued from now on will sit here.", + "truncated": "The pending queue is too large to check in full — nothing overdue was found in the rows read, but this is not an all-clear." }, "processor": { "title": "Email queue processor", diff --git a/frontend/src/pages/admin/SystemHealthPage.tsx b/frontend/src/pages/admin/SystemHealthPage.tsx index 4c2e96f9..ee84f8ca 100644 --- a/frontend/src/pages/admin/SystemHealthPage.tsx +++ b/frontend/src/pages/admin/SystemHealthPage.tsx @@ -44,6 +44,10 @@ export const SystemHealthPage: React.FC = () => { const stuckEmails = data?.stuckEmails ?? []; const waitingEmails = data?.waitingEmails ?? []; const processor = data?.processor; + // The endpoint stops reading after a bounded number of pending rows. Past + // that, an empty waiting list means "nothing found yet", not "nothing" — so + // it must not turn into a green check. + const scanTruncated = data?.scanTruncated ?? false; // The processor is only "fine" when it has been started AND its last pass // didn't bail. A started-but-erroring processor is the case that used to @@ -56,7 +60,14 @@ export const SystemHealthPage: React.FC = () => { ? 'degraded' : 'ok'; - const emailTable = (rows: StuckEmail[], showError: boolean) => ( + /** + * `actions` is off for waiting rows, and deliberately so. Retry would + * rewrite a row that is already pending / retry_count 0 / unscheduled to the + * state it is in, and Dismiss would permanently delete an email that has not + * failed and will still go out once the processor recovers — a click on a + * health warning silently cancelling a customer's mail. + */ + const emailTable = (rows: StuckEmail[], showError: boolean, actions = true) => (
@@ -70,7 +81,9 @@ export const SystemHealthPage: React.FC = () => { : t('systemHealth.waitingEmails.col.attempts', 'Attempts')} - + {actions && ( + + )} @@ -95,22 +108,24 @@ export const SystemHealthPage: React.FC = () => { )} - + {actions && ( + + )} ))} @@ -190,7 +205,7 @@ export const SystemHealthPage: React.FC = () => { // 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' ? ( + processorState === 'ok' && !scanTruncated ? (
{t('systemHealth.waitingEmails.empty', 'Nothing waiting — the queue is being worked.')} @@ -198,8 +213,11 @@ export const SystemHealthPage: React.FC = () => { ) : (
- {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.')} + {scanTruncated + ? t('systemHealth.waitingEmails.truncated', + 'The pending queue is too large to check in full — nothing overdue was found in the rows read, but this is not an all-clear.') + : 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.')}
) ) : ( @@ -208,7 +226,7 @@ export const SystemHealthPage: React.FC = () => { {t('systemHealth.waitingEmails.description', 'Queued more than 10 minutes ago, due now, and still unsent. These have not failed — nothing has tried to send them.')}

- {emailTable(waitingEmails, false)} + {emailTable(waitingEmails, false, false)} )} @@ -231,7 +249,7 @@ export const SystemHealthPage: React.FC = () => { 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' + {waitingEmails.length === 0 && processorState === 'ok' && !scanTruncated ? t('systemHealth.stuckEmails.empty', 'No stuck or failed emails — all clear.') : t('systemHealth.stuckEmails.emptyNotAllClear', 'Nothing has failed — but see above.')}
diff --git a/frontend/src/services/systemHealth.service.ts b/frontend/src/services/systemHealth.service.ts index ef06b74c..2cdc9dc9 100644 --- a/frontend/src/services/systemHealth.service.ts +++ b/frontend/src/services/systemHealth.service.ts @@ -31,7 +31,10 @@ export interface SystemHealthFailures { /** Due, under the retry cap, and still unsent — nobody picked them up. */ waitingEmails: StuckEmail[]; processor: EmailProcessorStatus; - counts: { stuckEmails: number; waitingEmails: number }; + /** The pending queue was larger than the endpoint reads — an empty + * `waitingEmails` then means "nothing found yet", not "nothing". */ + scanTruncated?: boolean; + counts: { stuckEmails: number; waitingEmails: number; pendingScanned?: number }; } export const systemHealthService = { From 2d403f7fb2b1fed9030375d691a055e3a9d42391 Mon Sep 17 00:00:00 2001 From: Paul Nothaft Date: Wed, 2 Sep 2026 15:32:35 +0200 Subject: [PATCH 5/5] fix(email): wire the settings status card, and cap-aware truncation MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Codex review round 4 on #1273. Settings → Status rendered a green check for the email processor unconditionally, against an API field that was itself the literal 'active'. Both ends were lying and only one of them got fixed: adminSystem started reporting the real state in an earlier commit, but StatusTab never read it, so the second place an admin looks to find out why mail is not arriving still said everything was fine. It now shows stopped and degraded, with the reason. The truncation flag missed the case it most needed to cover. The loop broke on the 200-row report cap before the flag could be set, so 201+ overdue rows came back as exactly 200 with scanTruncated false -- a partial report presented as complete. It is now set whenever rows were left unexamined. The grace-window comment claimed the processor clears ~6000 rows inside the window. It clears on the order of 100: ten rows a pass, one pass a minute. The comment now says so, and says why the processor's own state is reported above the list rather than inferred from it -- "running, last pass sent 10" next to a backlog reads very differently from "not running" next to the same backlog. One round-4 finding is NOT fixed, deliberately, and is written up at the retry route. Clearing scheduled_at leaves created_at at the original enqueue time, so a retried old row appears in the waiting list immediately, looking overdue, until the processor sends it. Restarting that clock needs a timestamp written there and no shape works: a Date matches how queueEmail writes the column and how processEmailQueue compares it, but jest's sandbox Dates store as "[object Object]" (CLAUDE.md) so it cannot be tested; an ISO string tests fine but stores as TEXT, which SQLite then orders above the numeric bound in the processor's own pickup query, leaving the row unsendable. A requeued_at column would settle it. Cosmetic either way, and not worth risking a stuck row. 1 more test, failing before this commit. --- .../adminSystemHealthWaitingEmails.test.js | 23 ++++++++++++ backend/src/routes/adminSystemHealth.js | 35 ++++++++++++++++--- .../src/features/settings/tabs/StatusTab.tsx | 23 ++++++++++-- frontend/src/i18n/locales/de.json | 4 ++- frontend/src/i18n/locales/en.json | 4 ++- frontend/src/services/settings.service.ts | 4 ++- 6 files changed, 83 insertions(+), 10 deletions(-) diff --git a/backend/__tests__/routes/adminSystemHealthWaitingEmails.test.js b/backend/__tests__/routes/adminSystemHealthWaitingEmails.test.js index 9e23d16d..fba76f2c 100644 --- a/backend/__tests__/routes/adminSystemHealthWaitingEmails.test.js +++ b/backend/__tests__/routes/adminSystemHealthWaitingEmails.test.js @@ -300,6 +300,29 @@ describe('GET /admin/system-health/failures — waiting emails (#1262)', () => { expect(body.counts.pendingScanned).toBe(0); }); + it('calls a report capped at the row limit truncated, not complete', async () => { + // Codex review round 4. The loop broke on the report cap before the + // truncation flag could be set, so 201+ overdue rows came back as exactly + // 200 with scanTruncated false — a partial report presented as the whole. + const rows = []; + for (let i = 0; i < 260; i += 1) { + rows.push({ + recipient_email: `overdue${i}@example.com`, + email_type: 'gallery_created', + email_data: '{}', + status: 'pending', + retry_count: 0, + created_at: ago(90 * MINUTE), + scheduled_at: ago(90 * MINUTE), + }); + } + await db.batchInsert('email_queue', rows, 100); + + const body = await failures(); + expect(body.counts.waitingEmails).toBe(200); + expect(body.scanTruncated).toBe(true); + }); + 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 diff --git a/backend/src/routes/adminSystemHealth.js b/backend/src/routes/adminSystemHealth.js index c938f6c5..cf610b43 100644 --- a/backend/src/routes/adminSystemHealth.js +++ b/backend/src/routes/adminSystemHealth.js @@ -89,9 +89,14 @@ router.get( /** * How long an email may sit due-but-unsent before it counts as waiting rather - * than merely in flight. The processor wakes every 60s and takes 10 rows a - * pass, so a genuine backlog of ~6000 clears inside this window — anything - * still here has not been worked. + * than merely in flight. + * + * The processor wakes every 60s and takes 10 rows a pass, so it clears on the + * order of 100 rows inside this window — not thousands. A burst larger than + * that will therefore show up here for a while even though nothing is wrong, + * which is why the processor's own state is reported above this list rather + * than inferred from it: "running, last pass sent 10" next to a backlog reads + * very differently from "not running" next to the same backlog. */ const WAITING_EMAIL_GRACE_MS = 10 * 60 * 1000; @@ -204,12 +209,21 @@ router.get( .select('id', 'recipient_email', 'email_type', 'status', 'retry_count', 'error_message', 'created_at', 'scheduled_at'); if (page.length === 0) break; - scanned += page.length; + let examined = 0; for (const row of page) { + examined += 1; if (isWaiting(row)) waitingEmails.push(row); if (waitingEmails.length >= WAITING_REPORT_LIMIT) break; } - if (waitingEmails.length >= WAITING_REPORT_LIMIT || page.length < WAITING_PAGE_SIZE) break; + scanned += examined; + if (waitingEmails.length >= WAITING_REPORT_LIMIT) { + // Stopped because the response is full, not because the queue is. Any + // row left unexamined -- in this page or in pages after it -- may also + // be waiting, so the count is a floor and the report is partial. + scanTruncated = examined < page.length || page.length === WAITING_PAGE_SIZE; + break; + } + if (page.length < WAITING_PAGE_SIZE) break; // Ran out of budget with rows still unread. A queue this size whose head // is all future-scheduled could be hiding a due row past the cap, so the // empty result below is "not found yet", not "none" — and the UI must @@ -247,6 +261,17 @@ router.get( * pending with retries and schedule clear, so this endpoint would rewrite them * to the state they are in and change nothing. What a waiting row needs is the * processor fixed, which the panel above it says. + * + * KNOWN, deliberate: clearing scheduled_at leaves created_at at the original + * enqueue time, so a retried old row shows up in the waiting list right away + * looking overdue, until the processor sends it on its next tick. Restarting + * that clock needs a timestamp written here, and there is no shape that works: + * a Date matches how queueEmail writes the column and how processEmailQueue + * compares it, but jest's sandbox Dates store as "[object Object]" (CLAUDE.md) + * so it cannot be tested; an ISO string tests fine but stores as TEXT, and + * SQLite then orders it above the numeric bound in the processor's own pickup + * query, leaving the row unsendable. A requeued_at column would settle it. + * Cosmetic either way, and not worth risking a stuck row for. */ router.post( '/failures/email/:id/retry', diff --git a/frontend/src/features/settings/tabs/StatusTab.tsx b/frontend/src/features/settings/tabs/StatusTab.tsx index dbfae259..75be8252 100644 --- a/frontend/src/features/settings/tabs/StatusTab.tsx +++ b/frontend/src/features/settings/tabs/StatusTab.tsx @@ -10,6 +10,7 @@ import { Ruler, CalendarClock, RotateCw, + AlertTriangle, } from 'lucide-react'; import { Button, Card, Input } from '../../../components/common'; import { useTranslation } from 'react-i18next'; @@ -585,12 +586,30 @@ export const StatusTab: React.FC = ({

{t('settings.systemStatus.expirationCheckerDesc')}

+ {/* #1262 — this card used to render a green check unconditionally, + against an API field that was itself the literal 'active'. Both + ends now tell the truth: a stopped or bailing processor is the + reason queued mail never arrives, and this is one of the two + places an admin looks to find that out. */}

{t('settings.systemStatus.emailProcessor')}

- + {systemStatus?.services?.emailProcessor?.status === 'active' ? ( + + ) : ( + + )}
-

{t('settings.systemStatus.emailProcessorDesc')}

+

+ {systemStatus?.services?.emailProcessor?.status === 'stopped' + ? t('settings.systemStatus.emailProcessorStopped', + 'Not running — queued emails are written but nothing sends them.') + : systemStatus?.services?.emailProcessor?.status === 'degraded' + ? t('settings.systemStatus.emailProcessorDegraded', + 'Running, but the last pass could not send: {{error}}', + { error: systemStatus?.services?.emailProcessor?.lastError }) + : t('settings.systemStatus.emailProcessorDesc')} +

diff --git a/frontend/src/i18n/locales/de.json b/frontend/src/i18n/locales/de.json index c26d3c40..8e88b6a4 100644 --- a/frontend/src/i18n/locales/de.json +++ b/frontend/src/i18n/locales/de.json @@ -1968,7 +1968,9 @@ "pending": "Ausstehend", "sent": "Gesendet", "failed": "Fehlgeschlagen", - "lastUpdate": "Letzte Aktualisierung" + "lastUpdate": "Letzte Aktualisierung", + "emailProcessorStopped": "Läuft nicht — eingereihte E-Mails werden geschrieben, aber niemand versendet sie.", + "emailProcessorDegraded": "Läuft, aber der letzte Durchlauf konnte nicht senden: {{error}}" }, "photoDimensions": { "title": "Foto-Abmessungen", diff --git a/frontend/src/i18n/locales/en.json b/frontend/src/i18n/locales/en.json index 7e302fc9..aa7c8ce4 100644 --- a/frontend/src/i18n/locales/en.json +++ b/frontend/src/i18n/locales/en.json @@ -1331,7 +1331,9 @@ "pending": "Pending", "sent": "Sent", "failed": "Failed", - "lastUpdate": "Last update" + "lastUpdate": "Last update", + "emailProcessorStopped": "Not running — queued emails are written but nothing sends them.", + "emailProcessorDegraded": "Running, but the last pass could not send: {{error}}" }, "photoDimensions": { "title": "Photo Dimensions", diff --git a/frontend/src/services/settings.service.ts b/frontend/src/services/settings.service.ts index f7de882c..9d4b8c18 100644 --- a/frontend/src/services/settings.service.ts +++ b/frontend/src/services/settings.service.ts @@ -164,7 +164,9 @@ export interface SystemStatus { services: { fileWatcher: { status: string }; expirationChecker: { status: string }; - emailProcessor: { status: string }; + // 'active' | 'degraded' | 'stopped' (#1262). Was a hardcoded 'active' + // until the processor started reporting what it actually did. + emailProcessor: { status: string; lastRunAt?: string | null; lastError?: string | null }; }; timestamp: string; }
{t('systemHealth.stuckEmails.col.queued', 'Queued')}{t('systemHealth.stuckEmails.col.actions', 'Actions')}{t('systemHealth.stuckEmails.col.actions', 'Actions')}
{m.createdAt ? fmtDateTime(m.createdAt) : '—'} -
- - -
- 		+
+ + +
+