Merge pull request #1273 from PicPeak/fix/1262-email-queue-visibility
fix(email): show a queue nobody is working instead of reporting all-clear (#1262)
This commit is contained in:
Paul Nothaft
@@ -0,0 +1,397 @@
|
||||
/**
|
||||
* 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');
|
||||
|
||||
/**
|
||||
* Stand up a transport without touching a socket.
|
||||
*
|
||||
* processEmailQueue bails before it reads a single row when there is no
|
||||
* transport, so the two tests below cannot otherwise reach the code they are
|
||||
* about. Spying on the webhook transport is the cheapest way in — and it must
|
||||
* be a spy rather than a dead URL, because real connection attempts leave open
|
||||
* handles that destabilise unrelated suites in the same worker.
|
||||
*
|
||||
* `send` rejects: a failed delivery is a delivery ATTEMPT, which is exactly
|
||||
* what these two need to observe.
|
||||
*/
|
||||
function stubWebhookTransport() {
|
||||
const transport = require('../../src/services/emailWebhookTransport');
|
||||
const savedFrom = process.env.EMAIL_FROM;
|
||||
process.env.EMAIL_FROM = '[email protected]';
|
||||
const enabled = jest.spyOn(transport, 'isEnabled').mockReturnValue(true);
|
||||
const send = jest.spyOn(transport, 'send').mockRejectedValue(new Error('transport down'));
|
||||
return {
|
||||
send,
|
||||
restore() {
|
||||
enabled.mockRestore();
|
||||
send.mockRestore();
|
||||
if (savedFrom === undefined) delete process.env.EMAIL_FROM;
|
||||
else process.env.EMAIL_FROM = savedFrom;
|
||||
},
|
||||
};
|
||||
}
|
||||
|
||||
const MINUTE = 60 * 1000;
|
||||
const 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;
|
||||
|
||||
/**
|
||||
* `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: '[email protected]',
|
||||
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)
|
||||
.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: '[email protected]',
|
||||
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([]);
|
||||
});
|
||||
|
||||
// --- 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']);
|
||||
});
|
||||
});
|
||||
|
||||
// --- 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('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
|
||||
// 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('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('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
|
||||
// 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('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('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 {
|
||||
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);
|
||||
|
||||
expect(transport.send).not.toHaveBeenCalled();
|
||||
const after = await db('email_queue').where({ id }).first();
|
||||
expect(after.status).toBe('pending');
|
||||
expect(after.retry_count).toBe(0);
|
||||
} 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' });
|
||||
|
||||
// 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);
|
||||
});
|
||||
});
|
||||
@@ -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);
|
||||
});
|
||||
});
|
||||
});
|
||||
@@ -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()
|
||||
};
|
||||
|
||||
@@ -23,6 +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 { toMillis } = require('../utils/queueTimestamps');
|
||||
const { db } = require('../database/db');
|
||||
|
||||
const router = express.Router();
|
||||
@@ -85,6 +87,53 @@ 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 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;
|
||||
|
||||
/**
|
||||
* 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 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.
|
||||
*
|
||||
* WAITING_SCAN_MAX bounds the work: past it the response is explicitly a
|
||||
* sample, which the 200-row cap already made it.
|
||||
*/
|
||||
const WAITING_PAGE_SIZE = 500;
|
||||
const WAITING_SCAN_MAX = 10000;
|
||||
const WAITING_REPORT_LIMIT = 200;
|
||||
|
||||
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 +143,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 +167,81 @@ 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.
|
||||
//
|
||||
// Only the engine-safe half of that predicate runs in SQL; the two time
|
||||
// comparisons are done in JS — see utils/queueTimestamps.
|
||||
const now = Date.now();
|
||||
const dueBefore = now - WAITING_EMAIL_GRACE_MS;
|
||||
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.
|
||||
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;
|
||||
// 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')
|
||||
.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;
|
||||
let examined = 0;
|
||||
for (const row of page) {
|
||||
examined += 1;
|
||||
if (isWaiting(row)) waitingEmails.push(row);
|
||||
if (waitingEmails.length >= WAITING_REPORT_LIMIT) 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
|
||||
// not turn it into an all-clear.
|
||||
if (offset + WAITING_PAGE_SIZE >= WAITING_SCAN_MAX) scanTruncated = true;
|
||||
}
|
||||
|
||||
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,
|
||||
pendingScanned: scanned,
|
||||
},
|
||||
// True when the pending queue was larger than this endpoint will read.
|
||||
scanTruncated,
|
||||
});
|
||||
}),
|
||||
);
|
||||
@@ -129,6 +250,28 @@ 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).
|
||||
*
|
||||
* 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.
|
||||
*
|
||||
* 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.
|
||||
*
|
||||
* 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',
|
||||
|
||||
@@ -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,11 +996,18 @@ 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;
|
||||
}
|
||||
|
||||
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;
|
||||
}
|
||||
|
||||
@@ -1043,8 +1077,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 +1239,7 @@ function startEmailQueueProcessor() {
|
||||
});
|
||||
}, 60000);
|
||||
|
||||
processorStatus.started = true;
|
||||
logger.info('Email queue processor started successfully');
|
||||
} else {
|
||||
logger.info('Email queue processor: Already running');
|
||||
@@ -1213,6 +1250,7 @@ function stopEmailQueueProcessor() {
|
||||
if (emailQueueInterval) {
|
||||
clearInterval(emailQueueInterval);
|
||||
emailQueueInterval = null;
|
||||
processorStatus.started = false;
|
||||
logger.info('Email queue processor stopped');
|
||||
}
|
||||
}
|
||||
@@ -1231,6 +1269,7 @@ module.exports = {
|
||||
sendRawEmail,
|
||||
renderQueuedEmail,
|
||||
processEmailQueue,
|
||||
getQueueProcessorStatus,
|
||||
queueEmail,
|
||||
stopEmailQueueProcessor,
|
||||
testEmailConnection,
|
||||
|
||||
@@ -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 };
|
||||
@@ -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<StatusTabProps> = ({
|
||||
</div>
|
||||
<p className="text-xs text-neutral-600 dark:text-neutral-400">{t('settings.systemStatus.expirationCheckerDesc')}</p>
|
||||
</div>
|
||||
{/* #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. */}
|
||||
<div className="bg-neutral-50 dark:bg-neutral-800 rounded-lg p-4">
|
||||
<div className="flex items-center justify-between mb-2">
|
||||
<p className="text-sm font-medium text-neutral-700 dark:text-neutral-300">{t('settings.systemStatus.emailProcessor')}</p>
|
||||
{systemStatus?.services?.emailProcessor?.status === 'active' ? (
|
||||
<CheckCircle className="w-5 h-5 text-green-600" />
|
||||
) : (
|
||||
<AlertTriangle className="w-5 h-5 text-red-600" />
|
||||
)}
|
||||
</div>
|
||||
<p className="text-xs text-neutral-600 dark:text-neutral-400">{t('settings.systemStatus.emailProcessorDesc')}</p>
|
||||
<p className="text-xs text-neutral-600 dark:text-neutral-400">
|
||||
{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')}
|
||||
</p>
|
||||
</div>
|
||||
</div>
|
||||
|
||||
|
||||
@@ -107,7 +107,30 @@
|
||||
"error": "Fehler",
|
||||
"queued": "Eingereiht",
|
||||
"actions": "Aktionen"
|
||||
}
|
||||
},
|
||||
"emptyNotAllClear": "Nichts ist fehlgeschlagen — beachten Sie aber die Hinweise oben."
|
||||
},
|
||||
"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"
|
||||
},
|
||||
"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",
|
||||
"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 +1347,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",
|
||||
@@ -1944,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",
|
||||
|
||||
@@ -107,7 +107,30 @@
|
||||
"error": "Error",
|
||||
"queued": "Queued",
|
||||
"actions": "Actions"
|
||||
}
|
||||
},
|
||||
"emptyNotAllClear": "Nothing has failed — but see above."
|
||||
},
|
||||
"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"
|
||||
},
|
||||
"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",
|
||||
"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 +843,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",
|
||||
@@ -1307,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",
|
||||
|
||||
@@ -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);
|
||||
},
|
||||
|
||||
@@ -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,33 +42,32 @@ 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;
|
||||
|
||||
return (
|
||||
<div className="container py-6">
|
||||
<div className="mb-6">
|
||||
<h1 className="text-2xl font-bold text-neutral-900 dark:text-neutral-100">{t('systemHealth.title', 'System health')}</h1>
|
||||
<p className="text-sm text-neutral-500 dark:text-neutral-400 mt-1">
|
||||
{t('systemHealth.subtitle', 'Background failures that need attention.')}
|
||||
</p>
|
||||
</div>
|
||||
// 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';
|
||||
|
||||
<Card padding="lg">
|
||||
<div className="flex items-center gap-2 mb-3">
|
||||
<AlertCircle className="w-5 h-5 text-amber-500" />
|
||||
<h2 className="text-lg font-semibold text-neutral-900 dark:text-neutral-100">
|
||||
{t('systemHealth.stuckEmails.title', 'Stuck / failed emails')}
|
||||
</h2>
|
||||
{!isLoading && (
|
||||
<span className="ml-1 text-sm text-neutral-500 dark:text-neutral-400">({stuckEmails.length})</span>
|
||||
)}
|
||||
</div>
|
||||
|
||||
{isLoading ? <Loading /> : stuckEmails.length === 0 ? (
|
||||
<div className="flex items-center gap-2 text-sm text-green-700 dark:text-green-400 py-6">
|
||||
<CheckCircle className="w-5 h-5" />
|
||||
{t('systemHealth.stuckEmails.empty', 'No stuck or failed emails — all clear.')}
|
||||
</div>
|
||||
) : (
|
||||
/**
|
||||
* `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) => (
|
||||
<div className="rounded-lg border border-neutral-200 dark:border-neutral-700 overflow-hidden">
|
||||
<div className="overflow-x-auto">
|
||||
<table className="w-full text-sm">
|
||||
@@ -69,22 +75,40 @@ export const SystemHealthPage: React.FC = () => {
|
||||
<tr>
|
||||
<th className="px-3 py-2 text-left">{t('systemHealth.stuckEmails.col.recipient', 'Recipient')}</th>
|
||||
<th className="px-3 py-2 text-left">{t('systemHealth.stuckEmails.col.type', 'Type')}</th>
|
||||
<th className="px-3 py-2 text-left">{t('systemHealth.stuckEmails.col.error', 'Error')}</th>
|
||||
<th className="px-3 py-2 text-left">
|
||||
{showError
|
||||
? t('systemHealth.stuckEmails.col.error', 'Error')
|
||||
: t('systemHealth.waitingEmails.col.attempts', 'Attempts')}
|
||||
</th>
|
||||
<th className="px-3 py-2 text-left">{t('systemHealth.stuckEmails.col.queued', 'Queued')}</th>
|
||||
{actions && (
|
||||
<th className="px-3 py-2 text-right">{t('systemHealth.stuckEmails.col.actions', 'Actions')}</th>
|
||||
)}
|
||||
</tr>
|
||||
</thead>
|
||||
<tbody>
|
||||
{stuckEmails.map((m) => (
|
||||
{rows.map((m) => (
|
||||
<tr key={m.id} className="border-t border-neutral-200 dark:border-neutral-700 align-top">
|
||||
<td className="px-3 py-2 break-all">{m.recipientEmail}</td>
|
||||
<td className="px-3 py-2 font-mono text-xs">{m.emailType}</td>
|
||||
<td className="px-3 py-2 max-w-xs">
|
||||
{showError ? (
|
||||
<span className="text-xs text-red-700 dark:text-red-400 break-words">
|
||||
{m.errorMessage || t('systemHealth.stuckEmails.noError', 'retries exhausted')}
|
||||
</span>
|
||||
) : (
|
||||
<span className="text-xs text-neutral-600 dark:text-neutral-400">
|
||||
{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')}
|
||||
</span>
|
||||
)}
|
||||
</td>
|
||||
<td className="px-3 py-2 whitespace-nowrap">{m.createdAt ? fmtDateTime(m.createdAt) : '—'}</td>
|
||||
{actions && (
|
||||
<td className="px-3 py-2">
|
||||
<div className="flex items-center justify-end gap-1">
|
||||
<Button variant="outline" size="sm"
|
||||
@@ -101,13 +125,135 @@ export const SystemHealthPage: React.FC = () => {
|
||||
</button>
|
||||
</div>
|
||||
</td>
|
||||
)}
|
||||
</tr>
|
||||
))}
|
||||
</tbody>
|
||||
</table>
|
||||
</div>
|
||||
</div>
|
||||
);
|
||||
|
||||
return (
|
||||
<div className="container py-6">
|
||||
<div className="mb-6">
|
||||
<h1 className="text-2xl font-bold text-neutral-900 dark:text-neutral-100">{t('systemHealth.title', 'System health')}</h1>
|
||||
<p className="text-sm text-neutral-500 dark:text-neutral-400 mt-1">
|
||||
{t('systemHealth.subtitle', 'Background failures that need attention.')}
|
||||
</p>
|
||||
</div>
|
||||
|
||||
{/* 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 && (
|
||||
<Card padding="lg" className="mb-4">
|
||||
<div className="flex items-start gap-3">
|
||||
{processorState === 'ok'
|
||||
? <Mail className="w-5 h-5 mt-0.5 text-green-600 dark:text-green-400 shrink-0" />
|
||||
: <MailX className="w-5 h-5 mt-0.5 text-red-600 dark:text-red-400 shrink-0" />}
|
||||
<div className="min-w-0">
|
||||
<h2 className="text-lg font-semibold text-neutral-900 dark:text-neutral-100">
|
||||
{t('systemHealth.processor.title', 'Email queue processor')}
|
||||
</h2>
|
||||
<p className={`text-sm mt-0.5 ${
|
||||
processorState === 'ok'
|
||||
? 'text-neutral-600 dark:text-neutral-400'
|
||||
: 'text-red-700 dark:text-red-400'
|
||||
}`}>
|
||||
{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.')}
|
||||
</p>
|
||||
<p className="text-xs text-neutral-500 dark:text-neutral-400 mt-1">
|
||||
{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,
|
||||
})}
|
||||
</>
|
||||
)}
|
||||
</p>
|
||||
</div>
|
||||
</div>
|
||||
</Card>
|
||||
)}
|
||||
|
||||
{/* Due but unsent. Distinct from failed: nothing went wrong with these,
|
||||
they were simply never picked up. */}
|
||||
<Card padding="lg" className="mb-4">
|
||||
<div className="flex items-center gap-2 mb-3">
|
||||
<Clock className="w-5 h-5 text-amber-500" />
|
||||
<h2 className="text-lg font-semibold text-neutral-900 dark:text-neutral-100">
|
||||
{t('systemHealth.waitingEmails.title', 'Waiting to send')}
|
||||
</h2>
|
||||
{!isLoading && (
|
||||
<span className="ml-1 text-sm text-neutral-500 dark:text-neutral-400">({waitingEmails.length})</span>
|
||||
)}
|
||||
</div>
|
||||
|
||||
{isLoading ? <Loading /> : waitingEmails.length === 0 ? (
|
||||
// "Nothing waiting" is only reassuring when something is working the
|
||||
// queue. A processor that stopped a minute ago has no waiting rows
|
||||
// yet either — the grace window has not elapsed — and a green check
|
||||
// there is the same false all-clear this page exists to remove.
|
||||
processorState === 'ok' && !scanTruncated ? (
|
||||
<div className="flex items-center gap-2 text-sm text-green-700 dark:text-green-400 py-6">
|
||||
<CheckCircle className="w-5 h-5" />
|
||||
{t('systemHealth.waitingEmails.empty', 'Nothing waiting — the queue is being worked.')}
|
||||
</div>
|
||||
) : (
|
||||
<div className="flex items-center gap-2 text-sm text-amber-700 dark:text-amber-400 py-6">
|
||||
<AlertCircle className="w-5 h-5" />
|
||||
{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.')}
|
||||
</div>
|
||||
)
|
||||
) : (
|
||||
<>
|
||||
<p className="text-sm text-neutral-600 dark:text-neutral-400 mb-3">
|
||||
{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.')}
|
||||
</p>
|
||||
{emailTable(waitingEmails, false, false)}
|
||||
</>
|
||||
)}
|
||||
</Card>
|
||||
|
||||
<Card padding="lg">
|
||||
<div className="flex items-center gap-2 mb-3">
|
||||
<AlertCircle className="w-5 h-5 text-amber-500" />
|
||||
<h2 className="text-lg font-semibold text-neutral-900 dark:text-neutral-100">
|
||||
{t('systemHealth.stuckEmails.title', 'Stuck / failed emails')}
|
||||
</h2>
|
||||
{!isLoading && (
|
||||
<span className="ml-1 text-sm text-neutral-500 dark:text-neutral-400">({stuckEmails.length})</span>
|
||||
)}
|
||||
</div>
|
||||
|
||||
{isLoading ? <Loading /> : stuckEmails.length === 0 ? (
|
||||
<div className="flex items-center gap-2 text-sm text-green-700 dark:text-green-400 py-6">
|
||||
<CheckCircle className="w-5 h-5" />
|
||||
{/* "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' && !scanTruncated
|
||||
? t('systemHealth.stuckEmails.empty', 'No stuck or failed emails — all clear.')
|
||||
: t('systemHealth.stuckEmails.emptyNotAllClear', 'Nothing has failed — but see above.')}
|
||||
</div>
|
||||
) : emailTable(stuckEmails, true)}
|
||||
</Card>
|
||||
</div>
|
||||
);
|
||||
|
||||
@@ -193,7 +193,10 @@ export const ShareLinkCard: React.FC<ShareLinkCardProps> = ({ 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'));
|
||||
}
|
||||
|
||||
@@ -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;
|
||||
}
|
||||
|
||||
@@ -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,23 @@ 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;
|
||||
/** 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 = {
|
||||
|
||||
Reference in New Issue
Block a user