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.
This commit is contained in:
@@ -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 () => {
|
it('reports what the queue processor last did', async () => {
|
||||||
const body = await failures();
|
const body = await failures();
|
||||||
// Never started in this process — which is the condition that makes a
|
// Never started in this process — which is the condition that makes a
|
||||||
|
|||||||
@@ -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);
|
||||||
|
});
|
||||||
|
});
|
||||||
|
});
|
||||||
@@ -24,6 +24,7 @@ const { handleAsync, validateRequest, successResponse } = require('../utils/rout
|
|||||||
const { verifyDocumentArtefacts } = require('../services/backupIntegrityService');
|
const { verifyDocumentArtefacts } = require('../services/backupIntegrityService');
|
||||||
const { getCoverageReport } = require('../services/backupCoverageService');
|
const { getCoverageReport } = require('../services/backupCoverageService');
|
||||||
const { getQueueProcessorStatus, processEmailQueue } = require('../services/emailProcessor');
|
const { getQueueProcessorStatus, processEmailQueue } = require('../services/emailProcessor');
|
||||||
|
const { toMillis } = require('../utils/queueTimestamps');
|
||||||
const logger = require('../utils/logger');
|
const logger = require('../utils/logger');
|
||||||
const { db } = require('../database/db');
|
const { db } = require('../database/db');
|
||||||
|
|
||||||
@@ -96,41 +97,28 @@ router.get(
|
|||||||
const WAITING_EMAIL_GRACE_MS = 10 * 60 * 1000;
|
const WAITING_EMAIL_GRACE_MS = 10 * 60 * 1000;
|
||||||
|
|
||||||
/**
|
/**
|
||||||
* A timestamp column as milliseconds, whatever the engine handed back.
|
* 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
|
* The time filtering happens in JS, so the candidate rows have to be paged
|
||||||
* `queueEmail` writes -- a JS Date, which the native binding turns into a
|
* rather than cut off with a single LIMIT: a queue holding a thousand
|
||||||
* ms-number -- and hands back that number. Test fixtures and older rows carry
|
* future-scheduled rows (split-payment invoices) would otherwise fill one page
|
||||||
* ISO strings.
|
* 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
|
* WAITING_SCAN_MAX bounds the work: past it the response is explicitly a
|
||||||
* INTEGER before TEXT regardless of value, so comparing a ms-number column
|
* sample, which the 200-row cap already made it.
|
||||||
* 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) {
|
const WAITING_PAGE_SIZE = 500;
|
||||||
if (value == null) return null;
|
const WAITING_SCAN_MAX = 10000;
|
||||||
if (value instanceof Date) return value.getTime();
|
const WAITING_REPORT_LIMIT = 200;
|
||||||
if (typeof value === 'number') return value;
|
|
||||||
const text = String(value).trim();
|
|
||||||
if (text === '') return null;
|
|
||||||
// A numeric string is epoch ms; anything else goes through Date.parse.
|
|
||||||
const numeric = Number(text);
|
|
||||||
if (Number.isFinite(numeric)) return numeric;
|
|
||||||
const parsed = Date.parse(text);
|
|
||||||
return Number.isNaN(parsed) ? null : parsed;
|
|
||||||
}
|
|
||||||
|
|
||||||
/**
|
|
||||||
* How many pending rows to pull before filtering by time in JS. Everything
|
|
||||||
* overdue sorts first, so the cap only bites on a queue with more than this
|
|
||||||
* many pending rows -- at which point the 200-row response was already a
|
|
||||||
* sample rather than a census.
|
|
||||||
*/
|
|
||||||
const WAITING_SCAN_LIMIT = 1000;
|
|
||||||
|
|
||||||
const mapEmailRow = (r) => ({
|
const mapEmailRow = (r) => ({
|
||||||
id: r.id,
|
id: r.id,
|
||||||
@@ -181,18 +169,10 @@ router.get(
|
|||||||
// set above and must not be counted twice.
|
// set above and must not be counted twice.
|
||||||
//
|
//
|
||||||
// Only the engine-safe half of that predicate runs in SQL; the two time
|
// 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 now = Date.now();
|
||||||
const dueBefore = now - WAITING_EMAIL_GRACE_MS;
|
const dueBefore = now - WAITING_EMAIL_GRACE_MS;
|
||||||
const pendingRows = await db('email_queue')
|
const isWaiting = (r) => {
|
||||||
.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 scheduledAt = toMillis(r.scheduled_at);
|
const scheduledAt = toMillis(r.scheduled_at);
|
||||||
// Parked for later on purpose — split-payment invoices, the
|
// Parked for later on purpose — split-payment invoices, the
|
||||||
// business-hours floor. Not being sent yet is the point of those.
|
// 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.
|
// rather than reporting every such row as waiting.
|
||||||
if (createdAt === null) return false;
|
if (createdAt === null) return false;
|
||||||
return createdAt <= dueBefore;
|
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, {
|
return successResponse(res, {
|
||||||
stuckEmails: stuckEmails.map(mapEmailRow),
|
stuckEmails: stuckEmails.map(mapEmailRow),
|
||||||
|
|||||||
@@ -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 };
|
||||||
Reference in New Issue
Block a user