From 98aa06aeff18e23e655b14f671fe53441033fe14 Mon Sep 17 00:00:00 2001 From: Paul Nothaft Date: Wed, 2 Sep 2026 14:57:00 +0200 Subject: [PATCH] fix(email): read naive SQLite timestamps as UTC, and page the candidates Codex review round 2 on #1273. Both findings restore the false all-clear that round 1 set out to remove, by different routes. Both timestamp columns default to CURRENT_TIMESTAMP, which SQLite renders as a zone-less 'YYYY-MM-DD HH:MM:SS' in UTC -- and Date.parse reads that shape as LOCAL time. On a TZ=America/New_York deployment a row due now looked four hours away and never reached the waiting list; nine hours the other way, fresh mail read as long overdue. The parser now stamps the zone the value actually carries. That parser moved to utils/queueTimestamps so it can be tested honestly. This suite runs in UTC, where reading a zone-less value as local and as UTC give the same answer, and process.env.TZ does not reliably re-bind mid-process -- my first attempt at these tests passed against the broken code for exactly that reason. They now force TZ in a child process, so they fail on any host. The candidate rows are paged rather than cut off with one LIMIT. The time filter runs in JS, so a queue holding more than a page of future-scheduled rows -- split-payment invoices are exactly that shape -- filled the window with rows that all got filtered out and hid the due row behind them, reporting nothing waiting. Paging also drops the dependency on ORDER BY created_at meaning anything, which it does not on SQLite once numeric and text timestamps mix. Bounded at 10k scanned; past that the response is a sample, which the 200-row cap already made it. 12 more tests. The paging one fails before this commit, and all four naive-timestamp ones fail against the old parsing on any host. --- .../adminSystemHealthWaitingEmails.test.js | 34 ++++++++ .../__tests__/utils/queueTimestamps.test.js | 83 ++++++++++++++++++ backend/src/routes/adminSystemHealth.js | 85 +++++++++---------- backend/src/utils/queueTimestamps.js | 44 ++++++++++ 4 files changed, 203 insertions(+), 43 deletions(-) create mode 100644 backend/__tests__/utils/queueTimestamps.test.js create mode 100644 backend/src/utils/queueTimestamps.js diff --git a/backend/__tests__/routes/adminSystemHealthWaitingEmails.test.js b/backend/__tests__/routes/adminSystemHealthWaitingEmails.test.js index e6275f80..e8b696c4 100644 --- a/backend/__tests__/routes/adminSystemHealthWaitingEmails.test.js +++ b/backend/__tests__/routes/adminSystemHealthWaitingEmails.test.js @@ -222,6 +222,40 @@ describe('GET /admin/system-health/failures — waiting emails (#1262)', () => { }); }); + // --- Codex review round 2 ------------------------------------------------- + // + // The zone-less CURRENT_TIMESTAMP shape is covered in + // __tests__/utils/queueTimestamps.test.js instead of here: this suite runs + // in UTC, where reading such a value as local and as UTC give the same + // answer, and process.env.TZ does not reliably re-bind mid-process. Those + // tests force the zone in a child process, so they fail on any host. + + it('finds a due row behind a page full of future-scheduled ones', async () => { + // Codex review round 2. The candidates used to be cut off with a single + // LIMIT before the time filter ran, so a queue holding a page of + // split-payment invoices scheduled for later hid the due row behind them + // and reported an empty waiting list — the false all-clear, again. + // Over the 1000-row cut-off the first attempt used, so the due row really + // does sit behind a full page rather than merely late in one. + const rows = []; + for (let i = 0; i < 1200; i += 1) { + rows.push({ + recipient_email: `bulk${i}@example.com`, + email_type: 'invoice_due', + email_data: '{}', + status: 'pending', + retry_count: 0, + created_at: ago(90 * MINUTE), + scheduled_at: ahead(30 * 24 * 60 * MINUTE), + }); + } + await db.batchInsert('email_queue', rows, 100); + await queue({ email_type: 'gallery_created', created_at: ago(52 * MINUTE) }); + + const body = await failures(); + expect(typesOf(body.waitingEmails)).toEqual(['gallery_created']); + }); + it('reports what the queue processor last did', async () => { const body = await failures(); // Never started in this process — which is the condition that makes a diff --git a/backend/__tests__/utils/queueTimestamps.test.js b/backend/__tests__/utils/queueTimestamps.test.js new file mode 100644 index 00000000..741b9ee4 --- /dev/null +++ b/backend/__tests__/utils/queueTimestamps.test.js @@ -0,0 +1,83 @@ +/** + * email_queue timestamps come back in three shapes and must all read as the + * same instant (#1262). + * + * The naive-string case is the one that bites in production and cannot be + * pinned from inside this suite: CI runs in UTC, where reading a zone-less + * timestamp as local time and as UTC give the same answer. So those two cases + * run in child processes with TZ forced, which is the only way to make the + * assertion fail on a machine where the bug does not reproduce. + */ +const { execFileSync } = require('child_process'); +const path = require('path'); + +const { toMillis } = require('../../src/utils/queueTimestamps'); + +const UTIL = path.resolve(__dirname, '../../src/utils/queueTimestamps.js'); + +/** Parse `value` in a fresh node process pinned to `tz`. */ +function parseUnderTz(tz, value) { + const script = ` + const { toMillis } = require(${JSON.stringify(UTIL)}); + process.stdout.write(String(toMillis(${JSON.stringify(value)}))); + `; + return Number(execFileSync(process.execPath, ['-e', script], { + env: { ...process.env, TZ: tz }, + encoding: 'utf8', + })); +} + +describe('toMillis — the shapes email_queue timestamps really have', () => { + const INSTANT = Date.UTC(2026, 8, 2, 12, 0, 0); + + it('reads a Date, as Postgres returns', () => { + expect(toMillis(new Date(INSTANT))).toBe(INSTANT); + }); + + it('reads epoch ms, as SQLite stores what queueEmail writes', () => { + expect(toMillis(INSTANT)).toBe(INSTANT); + expect(toMillis(String(INSTANT))).toBe(INSTANT); + }); + + it('reads an ISO string, as fixtures and older rows carry', () => { + expect(toMillis('2026-09-02T12:00:00.000Z')).toBe(INSTANT); + }); + + it('cannot read nulls or nonsense, and says so rather than guessing', () => { + // The caller skips a row it cannot judge; returning 0 or NaN here would + // report every such row as decades overdue. + expect(toMillis(null)).toBeNull(); + expect(toMillis(undefined)).toBeNull(); + expect(toMillis('')).toBeNull(); + expect(toMillis(' ')).toBeNull(); + expect(toMillis('not a timestamp')).toBeNull(); + }); + + describe('CURRENT_TIMESTAMP on SQLite, which carries no zone', () => { + // Both columns default to CURRENT_TIMESTAMP. SQLite renders that as + // 'YYYY-MM-DD HH:MM:SS' in UTC with no marker, and Date.parse reads that + // shape as LOCAL time. + const NAIVE = '2026-09-02 12:00:00'; + + it('is UTC west of Greenwich, where the old reading looked into the future', () => { + // Read as local in New York, this instant lands 4h later than it is, so + // a row due now looked 4h away and never reached the waiting list. + expect(parseUnderTz('America/New_York', NAIVE)).toBe(INSTANT); + }); + + it('is UTC east of it, where the old reading looked into the past', () => { + // Nine hours the other way: fresh mail read as long overdue, which fills + // the page with rows that are perfectly fine. + expect(parseUnderTz('Asia/Tokyo', NAIVE)).toBe(INSTANT); + }); + + it('agrees with itself across zones', () => { + expect(parseUnderTz('America/New_York', NAIVE)) + .toBe(parseUnderTz('Asia/Tokyo', NAIVE)); + }); + + it('accepts the fractional-seconds variant too', () => { + expect(parseUnderTz('America/New_York', '2026-09-02 12:00:00.000')).toBe(INSTANT); + }); + }); +}); diff --git a/backend/src/routes/adminSystemHealth.js b/backend/src/routes/adminSystemHealth.js index de9cb04d..293ea9c5 100644 --- a/backend/src/routes/adminSystemHealth.js +++ b/backend/src/routes/adminSystemHealth.js @@ -24,6 +24,7 @@ const { handleAsync, validateRequest, successResponse } = require('../utils/rout const { verifyDocumentArtefacts } = require('../services/backupIntegrityService'); const { getCoverageReport } = require('../services/backupCoverageService'); const { getQueueProcessorStatus, processEmailQueue } = require('../services/emailProcessor'); +const { toMillis } = require('../utils/queueTimestamps'); const logger = require('../utils/logger'); const { db } = require('../database/db'); @@ -96,41 +97,28 @@ router.get( const WAITING_EMAIL_GRACE_MS = 10 * 60 * 1000; /** - * A timestamp column as milliseconds, whatever the engine handed back. + * Why the two time comparisons happen in JS (toMillis) and not in the WHERE + * clause: SQLite orders INTEGER before TEXT regardless of value, so comparing + * the ms-number this column really holds against a bound ISO string is true + * for EVERY row -- a mail queued one second ago reads as ten minutes overdue, + * and a scheduled_at years in the future reads as already due. Binding a Date + * instead is no fix either, since knex hands sqlite3 a Date the same way and + * jest's sandbox Dates stringify to "[object Object]" (see CLAUDE.md). * - * The three shapes are all real. Postgres returns a Date. SQLite stores what - * `queueEmail` writes -- a JS Date, which the native binding turns into a - * ms-number -- and hands back that number. Test fixtures and older rows carry - * ISO strings. + * The time filtering happens in JS, so the candidate rows have to be paged + * rather than cut off with a single LIMIT: a queue holding a thousand + * future-scheduled rows (split-payment invoices) would otherwise fill one page + * with rows that all get filtered out and hide the due row behind them, + * reporting an empty waiting list. Paging also removes the dependency on + * ORDER BY created_at being meaningful, which it is not on SQLite when numeric + * and text timestamps are mixed. * - * This has to happen in JS rather than in the WHERE clause. SQLite orders - * INTEGER before TEXT regardless of value, so comparing a ms-number column - * against a bound ISO string is true for EVERY row: a mail queued one second - * ago reads as ten minutes overdue, and a scheduled_at years in the future - * reads as already due. Binding a Date instead is no fix either, since knex - * hands sqlite3 a Date the same way and jest's sandbox Dates stringify to - * "[object Object]" (see CLAUDE.md). + * WAITING_SCAN_MAX bounds the work: past it the response is explicitly a + * sample, which the 200-row cap already made it. */ -function toMillis(value) { - if (value == null) return null; - if (value instanceof Date) return value.getTime(); - if (typeof value === 'number') return value; - const text = String(value).trim(); - if (text === '') return null; - // A numeric string is epoch ms; anything else goes through Date.parse. - const numeric = Number(text); - if (Number.isFinite(numeric)) return numeric; - const parsed = Date.parse(text); - return Number.isNaN(parsed) ? null : parsed; -} - -/** - * How many pending rows to pull before filtering by time in JS. Everything - * overdue sorts first, so the cap only bites on a queue with more than this - * many pending rows -- at which point the 200-row response was already a - * sample rather than a census. - */ -const WAITING_SCAN_LIMIT = 1000; +const WAITING_PAGE_SIZE = 500; +const WAITING_SCAN_MAX = 10000; +const WAITING_REPORT_LIMIT = 200; const mapEmailRow = (r) => ({ id: r.id, @@ -181,18 +169,10 @@ router.get( // set above and must not be counted twice. // // Only the engine-safe half of that predicate runs in SQL; the two time - // comparisons are done in JS, for the reason on toMillis above. + // comparisons are done in JS — see utils/queueTimestamps. const now = Date.now(); const dueBefore = now - WAITING_EMAIL_GRACE_MS; - const pendingRows = await db('email_queue') - .where('status', 'pending') - .where('retry_count', '<', 3) - .orderBy('created_at', 'asc') - .limit(WAITING_SCAN_LIMIT) - .select('id', 'recipient_email', 'email_type', 'status', 'retry_count', - 'error_message', 'created_at', 'scheduled_at'); - - const waitingEmails = pendingRows.filter((r) => { + const isWaiting = (r) => { const scheduledAt = toMillis(r.scheduled_at); // Parked for later on purpose — split-payment invoices, the // business-hours floor. Not being sent yet is the point of those. @@ -202,7 +182,26 @@ router.get( // rather than reporting every such row as waiting. if (createdAt === null) return false; return createdAt <= dueBefore; - }).slice(0, 200); + }; + + const waitingEmails = []; + for (let offset = 0; offset < WAITING_SCAN_MAX; offset += WAITING_PAGE_SIZE) { + // eslint-disable-next-line no-await-in-loop + const page = await db('email_queue') + .where('status', 'pending') + .where('retry_count', '<', 3) + .orderBy('id', 'asc') + .offset(offset) + .limit(WAITING_PAGE_SIZE) + .select('id', 'recipient_email', 'email_type', 'status', 'retry_count', + 'error_message', 'created_at', 'scheduled_at'); + if (page.length === 0) break; + for (const row of page) { + if (isWaiting(row)) waitingEmails.push(row); + if (waitingEmails.length >= WAITING_REPORT_LIMIT) break; + } + if (waitingEmails.length >= WAITING_REPORT_LIMIT || page.length < WAITING_PAGE_SIZE) break; + } return successResponse(res, { stuckEmails: stuckEmails.map(mapEmailRow), diff --git a/backend/src/utils/queueTimestamps.js b/backend/src/utils/queueTimestamps.js new file mode 100644 index 00000000..2ccb5068 --- /dev/null +++ b/backend/src/utils/queueTimestamps.js @@ -0,0 +1,44 @@ +/** + * Reading email_queue timestamps back, whatever shape the engine stored them in. + * + * The columns are written three different ways and read back three different + * ways, and a comparison that assumes one of them is wrong for the other two: + * + * - Postgres hands back a Date. + * - SQLite stores what queueEmail writes -- a JS Date, which the native + * binding turns into epoch ms -- and hands back that number. + * - Both columns also default to CURRENT_TIMESTAMP, which on SQLite is a + * zone-less 'YYYY-MM-DD HH:MM:SS' string in UTC, and older rows plus test + * fixtures carry ISO strings. + * + * Extracted from adminSystemHealth so the parsing can be tested under a forced + * TZ in a child process, which is the only way to pin the naive-timestamp case + * from a test suite that itself runs in UTC (#1262). + */ + +/** 'YYYY-MM-DD HH:MM:SS[.sss]' with no zone — SQLite's CURRENT_TIMESTAMP shape. */ +const SQLITE_NAIVE_TIMESTAMP = /^\d{4}-\d{2}-\d{2}[ T]\d{2}:\d{2}:\d{2}(\.\d+)?$/; + +/** + * @param {Date|number|string|null|undefined} value + * @returns {number|null} epoch ms, or null when the value cannot be read + */ +function toMillis(value) { + if (value == null) return null; + if (value instanceof Date) return value.getTime(); + if (typeof value === 'number') return value; + const text = String(value).trim(); + if (text === '') return null; + // A numeric string is epoch ms; anything else goes through Date.parse. + const numeric = Number(text); + if (Number.isFinite(numeric)) return numeric; + // Date.parse reads the zone-less shape as LOCAL time. On a + // TZ=America/New_York deployment that puts a row due now four hours in the + // future, so it never reaches the waiting list -- the false all-clear again, + // arrived at via the clock. Stamp the zone the value actually carries. + const stamped = SQLITE_NAIVE_TIMESTAMP.test(text) ? `${text.replace(' ', 'T')}Z` : text; + const parsed = Date.parse(stamped); + return Number.isNaN(parsed) ? null : parsed; +} + +module.exports = { toMillis, SQLITE_NAIVE_TIMESTAMP };