| … | … | @@ -0,0 +1,187 @@ |
| 1 | // A failed release pull must not throw the work away. |
| 2 | // |
| 3 | // reconcile() clears `pending` BEFORE pulling, then restored the repo list on |
| 4 | // exactly ONE failure reason ('a pull is already in progress'). Every other |
| 5 | // failure — notably the 15s `swarm-rpc: connection timeout` that fires when the |
| 6 | // mirror answers its own request for the origin — silently discarded the scoped |
| 7 | // repos and scheduled no retry. |
| 8 | // |
| 9 | // Nothing replays them: pear-git.js saveCursor(seq) runs immediately after |
| 10 | // notify(entry), and notify only QUEUES, so the release-event cursor is already |
| 11 | // past the dropped work — across restarts too. |
| 12 | // |
| 13 | // Measured on stortron 2026-08-16: 24 timeouts vs 46 successful pulls in ~40 |
| 14 | // minutes, i.e. a third of reconciles dropped. Net drift was zero only because |
| 15 | // repos publish repeatedly and a later event covered the loss; a repo that |
| 16 | // publishes ONCE loses that release until its next publish. |
| 17 | |
| 18 | import test from 'brittle' |
| 19 | import { mkdtemp, rm } from '#node:fs/promises' |
| 20 | import { tmpdir } from '#node:os' |
| 21 | import { join } from '#node:path' |
| 22 | |
| 23 | import { startReleasePull, ReleasePuller } from '../lib/services/release-puller.js' |
| 24 | |
| 25 | const tick = (ms) => new Promise((r) => setTimeout(r, ms)) |
| 26 | |
| 27 | function fakePuller (onPull) { |
| 28 | return { pullFrom: onPull, stats: { errors: [] } } |
| 29 | } |
| 30 | |
| 31 | test('a connect failure re-queues the repos and retries', async (t) => { |
| 32 | const attempts = [] |
| 33 | let failNext = true |
| 34 | |
| 35 | const pull = startReleasePull({ |
| 36 | puller: fakePuller(async () => ({ ok: true, stats: { fetched: 1, replaced: 0, skipped: 0, errors: [] } })), |
| 37 | originServerKey: 'a'.repeat(64), |
| 38 | debounceMs: 10, |
| 39 | connect: async () => { |
| 40 | attempts.push(Date.now()) |
| 41 | if (failNext) { |
| 42 | failNext = false |
| 43 | throw new Error('swarm-rpc: connection timeout (2 peer(s) answered but failed verification)') |
| 44 | } |
| 45 | return { call: async () => ({ files: [] }), close: async () => {} } |
| 46 | }, |
| 47 | log: () => {} |
| 48 | }) |
| 49 | t.teardown(() => pull.stop()) |
| 50 | |
| 51 | pull.notify({ repo: 'ifsrenderer-linux' }) |
| 52 | |
| 53 | // First attempt fails. Pre-fix the repo was gone here and nothing retried. |
| 54 | await tick(400) |
| 55 | |
| 56 | t.ok(attempts.length >= 2, 'the failed pull was retried rather than dropped') |
| 57 | t.is(pull.pending().length, 0, 'and the repo was drained once a retry succeeded') |
| 58 | }) |
| 59 | |
| 60 | test('the re-queued repo is the one that failed', async (t) => { |
| 61 | const seen = [] |
| 62 | let fail = true |
| 63 | |
| 64 | const pull = startReleasePull({ |
| 65 | puller: fakePuller(async (client, opts) => { |
| 66 | seen.push([...(opts.repos || [])].sort()) |
| 67 | return { ok: true, stats: { fetched: 0, replaced: 0, skipped: 0, errors: [] } } |
| 68 | }), |
| 69 | originServerKey: 'b'.repeat(64), |
| 70 | debounceMs: 10, |
| 71 | connect: async () => { |
| 72 | if (fail) { fail = false; throw new Error('swarm-rpc: connection timeout') } |
| 73 | return { call: async () => ({ files: [] }), close: async () => {} } |
| 74 | }, |
| 75 | log: () => {} |
| 76 | }) |
| 77 | t.teardown(() => pull.stop()) |
| 78 | |
| 79 | pull.notify({ repo: 'hyper-tps' }) |
| 80 | await tick(400) |
| 81 | |
| 82 | t.ok(seen.length >= 1, 'a pull eventually reached the puller') |
| 83 | t.alike(seen[0], ['hyper-tps'], 'carrying the repo whose event was dropped') |
| 84 | }) |
| 85 | |
| 86 | test('repeated failures back off instead of hot-looping', async (t) => { |
| 87 | const at = [] |
| 88 | const pull = startReleasePull({ |
| 89 | puller: fakePuller(async () => ({ ok: true, stats: { errors: [] } })), |
| 90 | originServerKey: 'c'.repeat(64), |
| 91 | debounceMs: 20, |
| 92 | connect: async () => { |
| 93 | at.push(Date.now()) |
| 94 | throw new Error('swarm-rpc: connection timeout') |
| 95 | }, |
| 96 | log: () => {} |
| 97 | }) |
| 98 | t.teardown(() => pull.stop()) |
| 99 | |
| 100 | pull.notify({ repo: 'always-fails' }) |
| 101 | await tick(700) |
| 102 | |
| 103 | t.ok(at.length >= 3, 'it kept retrying') |
| 104 | // Fixed-interval retry at 20ms would be ~35 attempts in 700ms. Backoff must |
| 105 | // grow the gap, so the count stays far below that. |
| 106 | t.ok(at.length < 15, 'but backed off rather than retrying every debounce (' + at.length + ' attempts)') |
| 107 | const first = at[1] - at[0] |
| 108 | const last = at[at.length - 1] - at[at.length - 2] |
| 109 | t.ok(last > first, 'the gap between attempts grew (' + first + 'ms → ' + last + 'ms)') |
| 110 | }) |
| 111 | |
| 112 | test('a successful pull clears the backoff', async (t) => { |
| 113 | let fail = true |
| 114 | const at = [] |
| 115 | const pull = startReleasePull({ |
| 116 | puller: fakePuller(async () => ({ ok: true, stats: { errors: [] } })), |
| 117 | originServerKey: 'd'.repeat(64), |
| 118 | debounceMs: 10, |
| 119 | connect: async () => { |
| 120 | at.push(Date.now()) |
| 121 | if (fail) throw new Error('swarm-rpc: connection timeout') |
| 122 | return { call: async () => ({ files: [] }), close: async () => {} } |
| 123 | }, |
| 124 | log: () => {} |
| 125 | }) |
| 126 | t.teardown(() => pull.stop()) |
| 127 | |
| 128 | pull.notify({ repo: 'r1' }) |
| 129 | await tick(300) |
| 130 | fail = false |
| 131 | await tick(400) |
| 132 | |
| 133 | const before = at.length |
| 134 | pull.notify({ repo: 'r2' }) |
| 135 | await tick(200) |
| 136 | t.ok(at.length > before, 'a later event is served promptly, not stuck behind the grown backoff') |
| 137 | t.is(pull.pending().length, 0, 'and nothing is left queued') |
| 138 | }) |
| 139 | |
| 140 | test('per-pull deltas are reported, not lifetime totals', async (t) => { |
| 141 | // ReleasePuller.stats is cumulative by design (fetched++, skipped +=, |
| 142 | // errors.push, never reset). The summary printed those cumulative fields per |
| 143 | // repo, so the live log read `[ifsrenderer-linux] fetched 61, skipped 1994` |
| 144 | // when that pull had done far less — counts that only ever climbed, across |
| 145 | // different repos. |
| 146 | const puller = new ReleasePuller({ |
| 147 | releaseDir: '/nonexistent', |
| 148 | overlay: { fetchFile: async () => null } |
| 149 | }) |
| 150 | |
| 151 | puller.stats.fetched = 60 |
| 152 | puller.stats.skipped = 1900 |
| 153 | puller.stats.errors.push('an old error from a previous pull') |
| 154 | |
| 155 | const res = await puller.pullFrom({ call: async () => ({ files: [] }) }, { repos: ['x'] }) |
| 156 | |
| 157 | t.ok(res.delta, 'a per-pull delta is returned') |
| 158 | t.is(res.delta.fetched, 0, 'delta counts only this pull, not the lifetime 60') |
| 159 | t.is(res.delta.skipped, 0, 'same for skipped') |
| 160 | t.is(res.delta.errors.length, 0, 'and the stale error is not re-reported') |
| 161 | t.is(res.stats.fetched, 60, 'the cumulative total is still available') |
| 162 | }) |
| 163 | |
| 164 | test('a new error is logged with its text, not just counted', async (t) => { |
| 165 | const lines = [] |
| 166 | // A REAL dir: with a bogus releaseDir the fetch loop dies in mkdirSync and |
| 167 | // never reaches the "no holder" branch this test is about. |
| 168 | const dir = await mkdtemp(join(tmpdir(), 'relpull-')) |
| 169 | t.teardown(() => rm(dir, { recursive: true, force: true })) |
| 170 | |
| 171 | const puller = new ReleasePuller({ |
| 172 | releaseDir: dir, |
| 173 | overlay: { fetchFile: async () => null }, // null = "no holder" |
| 174 | log: (l) => lines.push(l) |
| 175 | }) |
| 176 | |
| 177 | await puller.pullFrom({ |
| 178 | call: async () => ({ |
| 179 | files: [{ path: 'demo/versions/1/app.bin', hash: 'f'.repeat(64), size: 10, repo: 'demo', version: '1' }] |
| 180 | }) |
| 181 | }) |
| 182 | |
| 183 | t.is(puller.stats.errors.length, 1, 'the failure was recorded') |
| 184 | const logged = lines.filter((l) => l.includes('no holder')) |
| 185 | t.is(logged.length, 1, 'and its TEXT reached the log, not only the count') |
| 186 | t.ok(logged[0].includes('app.bin'), 'naming the artifact that failed') |
| 187 | }) |