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) => ( +
| {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) : '—'} | +
+
+
+
+
+ |
+
+ {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, + })} + > + )} +
++ {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)} + > + )} +| {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) : '—'} | -
-
-
-
-
- |
-