diff --git a/docs/app-store-metadata.md b/docs/app-store-metadata.md index 1387bde..7cf2e77 100644 --- a/docs/app-store-metadata.md +++ b/docs/app-store-metadata.md @@ -18,7 +18,7 @@ Queued apps are selected first, followed by the oldest eligible refreshes. Faile Apple reports an unknown bundle ID as HTTP 200 with an empty result set, never as a 404, so `lib/appStore.js` infers absence and flags it. A flagged absence is stored as `app_not_found`, does not change `apps.status`, and does not consume the transport-failure cap. A genuine HTTP 404 is a routing or edge problem rather than a missing app, so it is stored with its own message and does count against that cap. Five consecutive transport failures stop the run. -A 403 or 429 stops the run immediately and, because it describes this client rather than the app it interrupted, records no failure against that app. Apple's `Retry-After` is included in the reported stop reason when present. +A 403 or 429 describes this client rather than the app it interrupted, so it never records a failure against that app. The run pauses and retries the same app instead of ending: `--rate-limit-retries=` (default 3, also `METADATA_REFRESH_RATE_LIMIT_RETRIES`) is a budget for the whole run rather than per app, and `--rate-limit-backoff-ms=` (default 60000, also `METADATA_REFRESH_RATE_LIMIT_BACKOFF_MS`) sets the first pause, doubling with each pause taken. Apple's `Retry-After` overrides the computed pause when present, and either way a pause is capped at 15 minutes so a cron run does not idle with an open database connection. Once the budget is spent the run stops, reporting the stop reason with `Retry-After` and the number of pauses taken. Search responses continue to populate the cache, behind a Cloudflare WAF challenge. A direct lookup only contacts Apple on a cache miss; its app insert and cache seed are committed in one transaction. Public `GET /analysis/:appId` never contacts Apple. @@ -28,13 +28,15 @@ Search responses continue to populate the cache, behind a Cloudflare WAF challen `pnpm storefront-status` reports total, referenced, unreferenced, stale, and failing rows, the oldest and newest successful refresh, failing-row errors, and the table size. The staleness threshold defaults to 30 days and supports `--stale-days=`. +Both jobs connect with a 60-second `statement_timeout` (`METADATA_JOB_STATEMENT_TIMEOUT_MS`, `0` disables it). Neither runs a query that should take longer, and the timeout is a session parameter, so it bounds only these jobs — the web service and the analyser uploads are unaffected. Without it a query blocked on a lock would hang the run indefinitely, and because Railway never terminates a deployment, every later firing would be skipped. + ## Railway cron Create a separate Railway service in the same project with this repository as its root directory, `node scripts/metadata-cron.js` as its start command, and schedule `0 3 * * *`. Share `DATABASE_URL` with the web service. The cron service must not run migrations; it runs refresh followed by prune, closes its PostgreSQL clients, and exits when complete. Railway cron has a five-minute minimum granularity and may drift by a few minutes; overlapping runs are skipped, with PostgreSQL advisory locks also protecting manual runs. If Railway cron is unavailable on the current plan, run the two jobs manually. An authenticated operational trigger endpoint is a follow-up and is intentionally not public in this change. -Manual `pnpm metadata-cron` invocations forward refresh flags (`--limit=`, `--min-age-days=`, `--delay-ms=`, and `--country=`) and prune flags (`--retention-days=` and `--max-unreferenced=`); `--dry-run` applies to both jobs. +Manual `pnpm metadata-cron` invocations forward refresh flags (`--limit=`, `--min-age-days=`, `--delay-ms=`, `--country=`, `--rate-limit-retries=`, and `--rate-limit-backoff-ms=`) and prune flags (`--retention-days=` and `--max-unreferenced=`); `--dry-run` applies to both jobs. ## Deployment diff --git a/lib/jobClient.js b/lib/jobClient.js new file mode 100644 index 0000000..5bf22e2 --- /dev/null +++ b/lib/jobClient.js @@ -0,0 +1,32 @@ +'use strict'; + +// Neither metadata job runs a query that should take more than a moment, so a +// server-side statement timeout is the cheap guard against a run that blocks +// forever waiting on a lock. That matters because Railway does not terminate a +// deployment: a hung run leaves the cron service Active and every later firing +// is skipped, which looks exactly like a cron that was never scheduled. +// +// The timeout is a session parameter, so it constrains this job's own queries +// and nothing else — the web service's pool and the analyser's uploads keep +// whatever the server default gives them. +// +// A minute is far longer than any query here needs. The margin is for a deploy +// whose migration holds a heavy lock on app_store_cache while a run is in +// flight: the run should wait for that rather than fail, and a failed run is +// harmless anyway since both jobs are idempotent and retry the next night. +const DEFAULT_STATEMENT_TIMEOUT_MS = 60000; + +function statementTimeoutMs(env = process.env) { + const parsed = Number.parseInt(env.METADATA_JOB_STATEMENT_TIMEOUT_MS, 10); + return Number.isInteger(parsed) && parsed >= 0 ? parsed : DEFAULT_STATEMENT_TIMEOUT_MS; +} + +// 0 disables the timeout, for an operator who needs a one-off long run. +function jobClientConfig(connectionString, env = process.env) { + const timeout = statementTimeoutMs(env); + return timeout > 0 + ? { connectionString, statement_timeout: timeout } + : { connectionString }; +} + +module.exports = { DEFAULT_STATEMENT_TIMEOUT_MS, statementTimeoutMs, jobClientConfig }; diff --git a/scripts/metadata-cron.js b/scripts/metadata-cron.js index 11541da..9ff723b 100644 --- a/scripts/metadata-cron.js +++ b/scripts/metadata-cron.js @@ -23,6 +23,8 @@ function parseArgs(argv = process.argv.slice(2)) { || arg.startsWith('--min-age-days=') || arg.startsWith('--delay-ms=') || arg.startsWith('--country=') + || arg.startsWith('--rate-limit-retries=') + || arg.startsWith('--rate-limit-backoff-ms=') ) { refreshArgs.push(arg); } else if (arg.startsWith('--retention-days=') || arg.startsWith('--max-unreferenced=')) { @@ -31,7 +33,8 @@ function parseArgs(argv = process.argv.slice(2)) { console.log([ 'Usage: pnpm metadata-cron [refresh/prune options]', '', - ' Refresh options: --limit=, --min-age-days=, --delay-ms=, --country=', + ' Refresh options: --limit=, --min-age-days=, --delay-ms=, --country=,', + ' --rate-limit-retries=, --rate-limit-backoff-ms=', ' Prune options: --retention-days=, --max-unreferenced=', ' Shared option: --dry-run' ].join('\n')); diff --git a/scripts/prune-app-store-cache.js b/scripts/prune-app-store-cache.js index 2785560..1ce84c6 100644 --- a/scripts/prune-app-store-cache.js +++ b/scripts/prune-app-store-cache.js @@ -6,6 +6,7 @@ const path = require('path'); const dotenv = require('dotenv'); const { Client } = require('pg'); const { withAdvisoryLock } = require('../lib/jobLock'); +const { jobClientConfig } = require('../lib/jobClient'); dotenv.config({ path: path.join(__dirname, '..', '.env') }); dotenv.config({ path: path.join(__dirname, '..', 'analyser', '.env') }); @@ -159,7 +160,7 @@ async function main({ } = {}) { if (!databaseUrl) throw new Error('DATABASE_URL is not set. Configure .env or analyser/.env.'); - const client = new ClientClass({ connectionString: databaseUrl }); + const client = new ClientClass(jobClientConfig(databaseUrl)); try { await client.connect(); return await withAdvisoryLock( diff --git a/scripts/refresh-app-store-metadata.js b/scripts/refresh-app-store-metadata.js index 3208743..65c661f 100644 --- a/scripts/refresh-app-store-metadata.js +++ b/scripts/refresh-app-store-metadata.js @@ -8,6 +8,7 @@ const { Client } = require('pg'); const store = require('../lib/appStore'); const { buildAppStoreCacheUpsert } = require('../models/Apps'); const { withAdvisoryLock } = require('../lib/jobLock'); +const { jobClientConfig } = require('../lib/jobClient'); dotenv.config({ path: path.join(__dirname, '..', '.env') }); dotenv.config({ path: path.join(__dirname, '..', 'analyser', '.env') }); @@ -17,9 +18,16 @@ const DEFAULTS = Object.freeze({ limit: 100, minAgeDays: 30, delayMs: 5000, - country: 'gb' + country: 'gb', + rateLimitRetries: 3, + rateLimitBackoffMs: 60000 }); +// Apple's throttling clears in minutes, so a pause is worth taking inside the +// run; anything longer than this belongs to the next scheduled run instead of +// a cron service sitting idle with an open database connection. +const MAX_RATE_LIMIT_BACKOFF_MS = 900000; + function positiveInteger(value, fallback) { const parsed = Number.parseInt(value, 10); return Number.isInteger(parsed) && parsed > 0 ? parsed : fallback; @@ -36,6 +44,14 @@ function parseArgs(argv = process.argv.slice(2), env = process.env) { minAgeDays: positiveInteger(env.METADATA_REFRESH_MIN_AGE_DAYS, DEFAULTS.minAgeDays), delayMs: nonNegativeInteger(env.METADATA_REFRESH_DELAY_MS, DEFAULTS.delayMs), country: env.APP_STORE_COUNTRY || DEFAULTS.country, + rateLimitRetries: nonNegativeInteger( + env.METADATA_REFRESH_RATE_LIMIT_RETRIES, + DEFAULTS.rateLimitRetries + ), + rateLimitBackoffMs: nonNegativeInteger( + env.METADATA_REFRESH_RATE_LIMIT_BACKOFF_MS, + DEFAULTS.rateLimitBackoffMs + ), dryRun: false }; @@ -45,6 +61,8 @@ function parseArgs(argv = process.argv.slice(2), env = process.env) { else if (arg.startsWith('--min-age-days=')) options.minAgeDays = positiveInteger(arg.slice(15), options.minAgeDays); else if (arg.startsWith('--delay-ms=')) options.delayMs = nonNegativeInteger(arg.slice(11), options.delayMs); else if (arg.startsWith('--country=')) options.country = arg.slice(10) || options.country; + else if (arg.startsWith('--rate-limit-retries=')) options.rateLimitRetries = nonNegativeInteger(arg.slice(21), options.rateLimitRetries); + else if (arg.startsWith('--rate-limit-backoff-ms=')) options.rateLimitBackoffMs = nonNegativeInteger(arg.slice(24), options.rateLimitBackoffMs); else if (arg === '--help') { console.log([ 'Usage: pnpm refresh-metadata [options]', @@ -52,6 +70,8 @@ function parseArgs(argv = process.argv.slice(2), env = process.env) { ' --limit=100 Maximum apps per run', ' --min-age-days=30 Minimum age of a successful refresh', ' --delay-ms=5000 Delay between Apple requests', + ' --rate-limit-retries=3 Pauses allowed per run when Apple throttles', + ' --rate-limit-backoff-ms=60000 First pause length; doubles per pause, capped at 15 minutes', ' --dry-run Select and print apps without requesting Apple data' ].join('\n')); process.exit(0); @@ -116,10 +136,33 @@ function isAppAbsent(error) { return /App not found \(404\)/.test(String(error && error.message || error)); } -function isRateLimitStop(error) { +function isRateLimited(error) { return [403, 429].includes(appStoreStatus(error)); } +// Retry-After is sent either as a number of seconds or as an HTTP date. +function retryAfterMs(error) { + const retryAfter = error && error.retryAfter; + if (retryAfter === null || retryAfter === undefined || retryAfter === '') return null; + + const seconds = Number.parseInt(String(retryAfter).trim(), 10); + if (Number.isInteger(seconds) && String(seconds) === String(retryAfter).trim()) + return seconds > 0 ? seconds * 1000 : 0; + + const deadline = Date.parse(retryAfter); + if (Number.isFinite(deadline)) return Math.max(deadline - Date.now(), 0); + return null; +} + +// Apple's own Retry-After wins when it sends one; otherwise the pause doubles +// per pause taken in this run. Either way the cap applies, so a header asking +// for an hour does not hold the run open for an hour. +function rateLimitPauseMs(error, pausesTaken, backoffMs) { + const requested = retryAfterMs(error); + const backoff = backoffMs * Math.pow(2, Math.max(pausesTaken - 1, 0)); + return Math.min(requested === null ? backoff : requested, MAX_RATE_LIMIT_BACKOFF_MS); +} + function errorMessage(error, absent = isAppAbsent(error)) { if (absent) return 'app_not_found'; return String(error && error.message || error).slice(0, 2000); @@ -174,6 +217,8 @@ async function refreshAppStoreMetadata(client, options = {}) { minAgeDays = DEFAULTS.minAgeDays, delayMs = DEFAULTS.delayMs, country = DEFAULTS.country, + rateLimitRetries = DEFAULTS.rateLimitRetries, + rateLimitBackoffMs = DEFAULTS.rateLimitBackoffMs, dryRun = false, storeClient = store, sleepFn = sleep, @@ -184,36 +229,64 @@ async function refreshAppStoreMetadata(client, options = {}) { if (dryRun) { for (const row of selected.rows) logger.log(`${row.appid} (${row.status})`); - return { selected: selected.rows, attempted: 0, refreshed: 0, failed: 0, stoppedReason: null }; + return { selected: selected.rows, attempted: 0, refreshed: 0, failed: 0, pauses: 0, stoppedReason: null }; } let refreshed = 0; let failed = 0; let consecutiveFailures = 0; let stoppedReason = null; + // Budgeted across the whole run rather than per app, so a throttled night + // pauses a few times and gives up instead of pausing once per remaining app. + let pausesRemaining = rateLimitRetries; + let pausesTaken = 0; + + // Resolves to { details } or { error }; a rate-limited request is retried + // after a pause while the run's pause budget lasts. + async function fetchDetails(appId) { + for (;;) { + try { + return { details: await storeClient.app({ appId, country }) }; + } catch (error) { + if (!isRateLimited(error) || pausesRemaining <= 0) return { error }; + + pausesRemaining--; + pausesTaken++; + const pauseMs = rateLimitPauseMs(error, pausesTaken, rateLimitBackoffMs); + logger.warn( + `Apple rate limited ${appId}; pausing ${Math.round(pauseMs / 1000)}s` + + ` before retrying (${pausesRemaining} pause(s) left)` + ); + await sleepFn(pauseMs); + } + } + } for (const [index, row] of selected.rows.entries()) { if (index > 0 && delayMs > 0) await sleepFn(delayMs); await markAttempt(client, row.appid); - try { - const details = await storeClient.app({ appId: row.appid, country }); + const { details, error } = await fetchDetails(row.appid); + + if (!error) { await recordSuccess(client, details, new Date()); refreshed++; consecutiveFailures = 0; logger.log(`Refreshed ${row.appid}`); - } catch (error) { + } else { const absent = isAppAbsent(error); const message = errorMessage(error, absent); // A 403 or 429 describes this client, not the app that happened to be - // next in the queue, so the run stops without recording a failure that - // would push an innocent app into exponential backoff. - if (isRateLimitStop(error)) { + // next in the queue, so once the pause budget is spent the run stops + // without recording a failure that would push an innocent app into + // exponential backoff. + if (isRateLimited(error)) { failed++; const retryAfter = error && error.retryAfter; stoppedReason = `Apple request stop signal: ${message}` - + (retryAfter ? ` (retry-after: ${retryAfter})` : ''); + + (retryAfter ? ` (retry-after: ${retryAfter})` : '') + + (pausesTaken ? ` after ${pausesTaken} pause(s)` : ''); logger.warn(`Refresh stopped at ${row.appid}: ${stoppedReason}`); break; } @@ -239,6 +312,7 @@ async function refreshAppStoreMetadata(client, options = {}) { attempted: refreshed + failed, refreshed, failed, + pauses: pausesTaken, stoppedReason }; } @@ -250,7 +324,7 @@ async function main({ } = {}) { if (!databaseUrl) throw new Error('DATABASE_URL is not set. Configure .env or analyser/.env.'); - const client = new ClientClass({ connectionString: databaseUrl }); + const client = new ClientClass(jobClientConfig(databaseUrl)); try { await client.connect(); return await withAdvisoryLock( @@ -279,7 +353,9 @@ module.exports = { buildRefreshSelectionQuery, appStoreStatus, isAppAbsent, - isRateLimitStop, + isRateLimited, + retryAfterMs, + rateLimitPauseMs, refreshAppStoreMetadata, main }; diff --git a/test/metadataJobs.test.js b/test/metadataJobs.test.js index 727b2e2..a70cb35 100644 --- a/test/metadataJobs.test.js +++ b/test/metadataJobs.test.js @@ -5,6 +5,7 @@ const test = require('node:test'); const refresh = require('../scripts/refresh-app-store-metadata'); const prune = require('../scripts/prune-app-store-cache'); const cron = require('../scripts/metadata-cron'); +const { jobClientConfig, statementTimeoutMs } = require('../lib/jobClient'); const { withAdvisoryLock } = require('../lib/jobLock'); const silentLogger = { log() {}, warn() {}, error() {} }; @@ -44,6 +45,8 @@ test('refresh parses country flags without retaining the equals sign', () => { test('metadata cron forwards refresh, prune, and shared flags', () => { const options = cron.parseArgs([ '--limit=7', + '--rate-limit-retries=2', + '--rate-limit-backoff-ms=1500', '--min-age-days=14', '--delay-ms=0', '--country=gb', @@ -57,6 +60,8 @@ test('metadata cron forwards refresh, prune, and shared flags', () => { minAgeDays: 14, delayMs: 0, country: 'gb', + rateLimitRetries: 2, + rateLimitBackoffMs: 1500, dryRun: true }); assert.deepEqual(options.pruneOptions, { @@ -66,7 +71,7 @@ test('metadata cron forwards refresh, prune, and shared flags', () => { }); }); -test('refresh stops on a 429 and leaves remaining selections untouched', async () => { +test('refresh stops on a 429 once the pause budget is spent, leaving remaining selections untouched', async () => { const client = refreshClient([ { appid: 'com.example.first', status: 'analysed' }, { appid: 'com.example.second', status: 'analysed' }, @@ -75,6 +80,7 @@ test('refresh stops on a 429 and leaves remaining selections untouched', async ( const requested = []; const result = await refresh.refreshAppStoreMetadata(client, { delayMs: 0, + rateLimitRetries: 0, storeClient: { async app({ appId }) { requested.push(appId); @@ -102,6 +108,7 @@ test('a rate limit stop reports Apple\'s Retry-After when it sends one', async ( const client = refreshClient([{ appid: 'com.example.first', status: 'analysed' }]); const result = await refresh.refreshAppStoreMetadata(client, { delayMs: 0, + rateLimitRetries: 0, storeClient: { async app() { throw Object.assign(new Error('App Store request failed (429)'), { @@ -116,6 +123,89 @@ test('a rate limit stop reports Apple\'s Retry-After when it sends one', async ( assert.match(result.stoppedReason, /retry-after: 120/); }); +test('a rate limited request resumes after a pause instead of ending the run', async () => { + const client = refreshClient([ + { appid: 'com.example.first', status: 'analysed' }, + { appid: 'com.example.second', status: 'analysed' } + ]); + const requested = []; + const pauses = []; + let throttled = false; + const result = await refresh.refreshAppStoreMetadata(client, { + delayMs: 0, + rateLimitBackoffMs: 1000, + sleepFn: async (ms) => { pauses.push(ms); }, + storeClient: { + async app({ appId }) { + requested.push(appId); + if (appId.endsWith('first') && !throttled) { + throttled = true; + throw Object.assign(new Error('App Store request failed (429)'), { statusCode: 429 }); + } + return { appId, title: appId, version: '1.0' }; + } + }, + logger: silentLogger + }); + + assert.deepEqual(requested, ['com.example.first', 'com.example.first', 'com.example.second']); + assert.deepEqual(pauses, [1000]); + assert.equal(result.refreshed, 2); + assert.equal(result.failed, 0); + assert.equal(result.pauses, 1); + assert.equal(result.stoppedReason, null); + // The throttled app was retried, not marked as its own failure. + assert.equal( + client.queries.filter(({ text }) => /refresh_failures = refresh_failures/.test(text)).length, + 0 + ); +}); + +test('the pause budget is spent across the run and doubles each time', async () => { + const client = refreshClient([ + { appid: 'com.example.first', status: 'analysed' }, + { appid: 'com.example.second', status: 'analysed' } + ]); + const pauses = []; + const result = await refresh.refreshAppStoreMetadata(client, { + delayMs: 0, + rateLimitRetries: 3, + rateLimitBackoffMs: 1000, + sleepFn: async (ms) => { pauses.push(ms); }, + storeClient: { + async app() { + throw Object.assign(new Error('App Store request failed (403)'), { statusCode: 403 }); + } + }, + logger: silentLogger + }); + + assert.deepEqual(pauses, [1000, 2000, 4000]); + assert.equal(result.pauses, 3); + assert.match(result.stoppedReason, /after 3 pause\(s\)/); + // The budget belongs to the run, so the second app was never reached. + assert.equal(result.attempted, 1); +}); + +test('Apple\'s Retry-After overrides the backoff and stays under the cap', () => { + const header = (retryAfter) => ({ retryAfter }); + + assert.equal(refresh.rateLimitPauseMs(header('30'), 1, 60000), 30000); + assert.equal(refresh.rateLimitPauseMs(header(null), 3, 1000), 4000); + assert.equal(refresh.rateLimitPauseMs(header('3600'), 1, 60000), 900000); + assert.equal(refresh.rateLimitPauseMs(header(undefined), 1, 60000), 60000); +}); + +test('Retry-After is read as seconds or as an HTTP date', () => { + assert.equal(refresh.retryAfterMs({ retryAfter: '120' }), 120000); + assert.equal(refresh.retryAfterMs({ retryAfter: null }), null); + assert.equal(refresh.retryAfterMs({ retryAfter: 'not-a-date' }), null); + assert.equal(refresh.retryAfterMs({ retryAfter: new Date(Date.now() - 5000).toUTCString() }), 0); + + const ms = refresh.retryAfterMs({ retryAfter: new Date(Date.now() + 60000).toUTCString() }); + assert.ok(ms > 50000 && ms <= 60000, `unexpected pause: ${ms}`); +}); + test('a real HTTP 404 counts against the transport failure cap', async () => { const rows = Array.from({ length: 6 }, (_, index) => ({ appid: `com.example.${index}`, @@ -288,4 +378,26 @@ test('metadata cron closes both PostgreSQL clients after refresh and prune', asy assert.equal(result.refresh.attempted, 0); assert.equal(result.prune.unreferenced, 0); assert.equal(events.filter(([event]) => event === 'end').length, 2); + + // Both clients carry the statement timeout, so neither job can hold the + // cron service Active by blocking on a lock forever. + const constructed = events.filter(([event]) => event === 'construct'); + assert.equal(constructed.length, 2); + for (const [, options] of constructed) { + assert.equal(options.connectionString, 'postgres://example/test'); + assert.equal(options.statement_timeout, 60000); + } +}); + +test('the job statement timeout is configurable and can be disabled', () => { + assert.equal(statementTimeoutMs({}), 60000); + assert.equal(statementTimeoutMs({ METADATA_JOB_STATEMENT_TIMEOUT_MS: '5000' }), 5000); + // Unparseable values fall back rather than silently disabling the guard. + assert.equal(statementTimeoutMs({ METADATA_JOB_STATEMENT_TIMEOUT_MS: 'soon' }), 60000); + assert.equal(statementTimeoutMs({ METADATA_JOB_STATEMENT_TIMEOUT_MS: '-1' }), 60000); + + assert.deepEqual( + jobClientConfig('postgres://example/test', { METADATA_JOB_STATEMENT_TIMEOUT_MS: '0' }), + { connectionString: 'postgres://example/test' } + ); });