diff --git a/.github/workflows/ci-resilience-nightly.yml b/.github/workflows/ci-resilience-nightly.yml new file mode 100644 index 0000000..3df8ac8 --- /dev/null +++ b/.github/workflows/ci-resilience-nightly.yml @@ -0,0 +1,35 @@ +name: ci-resilience-nightly + +on: + schedule: + - cron: '20 3 * * *' + workflow_dispatch: + push: + branches: + - main + paths: + - 'src/lock-ops.mjs' + - 'test/lock-acquisition-resilience.integration.test.mjs' + - 'package.json' + - 'package-lock.json' + - '.github/workflows/ci-resilience-nightly.yml' + +jobs: + ci-resilience: + runs-on: ubuntu-latest + timeout-minutes: 20 + steps: + - name: Checkout + uses: actions/checkout@v4 + + - name: Setup Node.js + uses: actions/setup-node@v4 + with: + node-version: 20 + cache: npm + + - name: Install dependencies + run: npm ci + + - name: Run resilience lock acquisition suite + run: npm run test:ci-resilience diff --git a/package.json b/package.json index f328bfd..d806930 100644 --- a/package.json +++ b/package.json @@ -44,7 +44,9 @@ "scheduler:weekly": "node scripts/agent/run-scheduler-cycle.mjs weekly", "report:lock-reliability": "node scripts/agent/summarize-lock-reliability.mjs --since-days 30", "test:integration:e2e": "node --test test/scheduler-preflight-lock.e2e.test.mjs", - "validate:scheduler-failure-schema": "node --test test/scheduler-lock-failure-schema.contract.test.mjs" + "validate:scheduler-failure-schema": "node --test test/scheduler-lock-failure-schema.contract.test.mjs", + "test:ci-resilience": "node --test test/lock-acquisition-resilience.integration.test.mjs", + "test:extended-main": "npm run test:integration:e2e && npm run test:ci-resilience" }, "dependencies": { "nostr-tools": "2.19.4", diff --git a/test/lock-acquisition-resilience.integration.test.mjs b/test/lock-acquisition-resilience.integration.test.mjs new file mode 100644 index 0000000..d178395 --- /dev/null +++ b/test/lock-acquisition-resilience.integration.test.mjs @@ -0,0 +1,219 @@ +import { afterEach, beforeEach, describe, it, mock } from 'node:test'; +import assert from 'node:assert'; + +import { publishLock, _resetRelayHealthState } from '../src/lock-ops.mjs'; + +const RELAYS = ['wss://relay-a', 'wss://relay-b', 'wss://relay-c']; + +function parseTelemetry(lines) { + return lines.map((line) => JSON.parse(line)); +} + +function createDynamicPool(outcomeForAttempt) { + let publishCallCount = 0; + return { + publish(relays) { + publishCallCount += 1; + return relays.map((relay) => { + const outcome = outcomeForAttempt({ + relay, + attempt: publishCallCount, + nowMs: Date.now(), + }); + if (outcome.ok) { + return Promise.resolve('ok'); + } + return Promise.reject(new Error(outcome.message)); + }); + }, + close() {}, + getPublishCallCount() { + return publishCallCount; + }, + }; +} + +describe('ci-resilience lock acquisition under unstable relays', { concurrency: false }, () => { + const healthStabilityOverrides = { + failureThreshold: 999, + rollingWindowSize: 100, + }; + + beforeEach(() => { + _resetRelayHealthState(); + mock.timers.enable({ apis: ['Date', 'setTimeout'] }); + }); + + afterEach(() => { + mock.timers.reset(); + }); + + it('recovers after all relays are down for an initial outage window', async () => { + const telemetryLogs = []; + const sleepCalls = []; + const initialOutageMs = 3_000; + + const pool = createDynamicPool(({ relay, nowMs }) => { + if (nowMs < initialOutageMs) { + return { ok: false, message: 'relay unavailable during outage' }; + } + if (relay === 'wss://relay-c') { + return { ok: true }; + } + return { ok: false, message: 'relay unavailable during outage recovery' }; + }); + + const result = await publishLock(RELAYS, { id: 'evt-outage-recovery' }, { + poolFactory: () => pool, + getPublishTimeoutMsFn: () => 25, + getMinSuccessfulRelayPublishesFn: () => 1, + getRelayFallbacksFn: () => [], + getMinActiveRelayPoolFn: () => 1, + retryAttempts: 8, + retryBaseDelayMs: 1_000, + retryCapDelayMs: 1_000, + randomFn: () => 1, + sleepFn: async (delayMs) => { + sleepCalls.push(delayMs); + mock.timers.tick(delayMs); + }, + telemetryLogger: (line) => telemetryLogs.push(line), + healthLogger: () => {}, + ...healthStabilityOverrides, + }); + + assert.strictEqual(result.id, 'evt-outage-recovery'); + assert.strictEqual(pool.getPublishCallCount(), 4); + assert.deepStrictEqual(sleepCalls, [1_000, 1_000, 1_000]); + + const telemetry = parseTelemetry(telemetryLogs); + const quorumMet = telemetry.find((entry) => entry.event === 'lock_publish_quorum_met'); + assert.ok(quorumMet); + assert.strictEqual(quorumMet.publishAttempt, 4); + assert.ok(quorumMet.totalElapsedMs >= initialOutageMs); + assert.ok(quorumMet.totalElapsedMs < 6_000); + + const retriesByRelay = telemetry + .filter((entry) => entry.event === 'lock_publish_retry') + .reduce((acc, entry) => { + acc[entry.relayUrl] = (acc[entry.relayUrl] || 0) + 1; + return acc; + }, {}); + + assert.strictEqual(retriesByRelay['wss://relay-a'], 3); + assert.strictEqual(retriesByRelay['wss://relay-b'], 3); + assert.strictEqual(retriesByRelay['wss://relay-c'], 3); + }); + + it('survives intermittent timeout spikes and reaches quorum with bounded retries', async () => { + const telemetryLogs = []; + const sleepCalls = []; + + const pool = createDynamicPool(({ relay, attempt }) => { + if (relay === 'wss://relay-a') { + return { ok: true }; + } + + if (relay === 'wss://relay-b' && (attempt === 1 || attempt === 3)) { + return { ok: false, message: 'publish timed out after 25ms (spike)' }; + } + + return { ok: true }; + }); + + const result = await publishLock(['wss://relay-a', 'wss://relay-b'], { id: 'evt-timeout-spikes' }, { + poolFactory: () => pool, + getPublishTimeoutMsFn: () => 25, + getMinSuccessfulRelayPublishesFn: () => 2, + getRelayFallbacksFn: () => [], + getMinActiveRelayPoolFn: () => 1, + retryAttempts: 4, + retryBaseDelayMs: 200, + retryCapDelayMs: 200, + randomFn: () => 1, + sleepFn: async (delayMs) => { + sleepCalls.push(delayMs); + mock.timers.tick(delayMs); + }, + telemetryLogger: (line) => telemetryLogs.push(line), + healthLogger: () => {}, + ...healthStabilityOverrides, + }); + + assert.strictEqual(result.id, 'evt-timeout-spikes'); + assert.strictEqual(pool.getPublishCallCount(), 2); + assert.deepStrictEqual(sleepCalls, [200]); + + const telemetry = parseTelemetry(telemetryLogs); + const retryEvents = telemetry.filter((entry) => entry.event === 'lock_publish_retry'); + assert.strictEqual(retryEvents.length, 1); + assert.strictEqual(retryEvents[0].relayUrl, 'wss://relay-b'); + assert.strictEqual(retryEvents[0].errorCategory, 'publish_timeout'); + + const quorumMet = telemetry.find((entry) => entry.event === 'lock_publish_quorum_met'); + assert.ok(quorumMet); + assert.strictEqual(quorumMet.publishAttempt, 2); + assert.ok(quorumMet.totalElapsedMs <= 1_000); + }); + + it('handles staggered relay recovery and never exceeds retry budget', async () => { + const telemetryLogs = []; + const sleepCalls = []; + + const pool = createDynamicPool(({ relay, attempt }) => { + if (attempt <= 2) { + return { ok: false, message: 'connect timeout during outage' }; + } + if (attempt === 3) { + if (relay === 'wss://relay-a') return { ok: true }; + return { ok: false, message: 'connect timeout during staged recovery' }; + } + if (relay === 'wss://relay-a' || relay === 'wss://relay-b') { + return { ok: true }; + } + return { ok: false, message: 'relay unavailable' }; + }); + + const retryAttempts = 6; + const result = await publishLock(RELAYS, { id: 'evt-staggered-recovery' }, { + poolFactory: () => pool, + getPublishTimeoutMsFn: () => 25, + getMinSuccessfulRelayPublishesFn: () => 2, + getRelayFallbacksFn: () => [], + getMinActiveRelayPoolFn: () => 1, + retryAttempts, + retryBaseDelayMs: 300, + retryCapDelayMs: 300, + randomFn: () => 1, + sleepFn: async (delayMs) => { + sleepCalls.push(delayMs); + mock.timers.tick(delayMs); + }, + telemetryLogger: (line) => telemetryLogs.push(line), + healthLogger: () => {}, + ...healthStabilityOverrides, + }); + + assert.strictEqual(result.id, 'evt-staggered-recovery'); + assert.strictEqual(pool.getPublishCallCount(), 4); + assert.ok(pool.getPublishCallCount() <= retryAttempts); + assert.deepStrictEqual(sleepCalls, [300, 300, 300]); + + const telemetry = parseTelemetry(telemetryLogs); + const quorumMet = telemetry.find((entry) => entry.event === 'lock_publish_quorum_met'); + assert.ok(quorumMet); + assert.strictEqual(quorumMet.publishAttempt, 4); + assert.ok(quorumMet.totalElapsedMs < 3_000); + + const retriesByRelay = telemetry + .filter((entry) => entry.event === 'lock_publish_retry') + .reduce((acc, entry) => { + acc[entry.relayUrl] = (acc[entry.relayUrl] || 0) + 1; + return acc; + }, {}); + + assert.strictEqual(retriesByRelay['wss://relay-a'], 2); + assert.strictEqual(retriesByRelay['wss://relay-b'], 3); + assert.strictEqual(retriesByRelay['wss://relay-c'], 3); + }); +});