From 8e14847643f7046c63f6dd1d195bbd77ccf24745 Mon Sep 17 00:00:00 2001 From: jonaswre Date: Sat, 1 Aug 2026 20:08:58 +0000 Subject: [PATCH] fix(test): stop test_download_policies hanging on a double-counted download This test has been timing out at its own 120s TIMEOUT on i686, Windows and Ubuntu, blocking three PRs. It is not architecture-specific and never was; it is a race that any sufficiently loaded machine loses. The event loop breaks only on exact equality of counters that never decrease: if synced_a == EXPECTED_A_SYNCED && downloaded_a.len() == EXPECTED_A_DOWNLOADED ... and `downloaded_*` was pushed from two event arms that are not mutually exclusive: - ContentReady { hash } -- emitted by `on_download_ready` when a download completes (engine/live.rs); - InsertRemote { content_status } -- where the status comes from `content_status_cb(entry.content_hash())`, evaluated when the event is CONVERTED (engine.rs), not when the entry synced. Under scheduling pressure the download finishes and emits ContentReady before its InsertRemote reaches the subscriber. By the time that event converts, the content is present, so its status reads Complete and the same key is recorded twice. downloaded_b.len() reaches 4 against an expected 3, the equality can never hold again, and the loop spins until the deadline. Reproduced locally by saturating all 8 cores: 40 consecutive passes when idle, then failures under load. Instrumenting every push site proved the mechanism directly rather than by inference -- 2 of 14 loaded runs printed "DUPE b via InsertRemote{Complete}" and exactly 2 timed out, the counts matching. That also corrected the ordering: ContentReady arrives first, and InsertRemote is the duplicate. This is a test bug, not a product bug. The two events mean different things -- "download finished" versus "entry synced, content already present" -- and a real consumer must handle both. Only the test assumed they were exclusive, so recording each key once is what it actually wanted; the assertions already compare exact contents. Also relax `==` to `>=`. The dedup fixes this instance, but an exact comparison against a monotonic counter is a hang waiting to happen: any future overshoot would spin for 120s with no diagnosis. With `>=` the loop exits and the existing assertions report the discrepancy legibly. Verified: 0 failures in 25 runs under full CPU load, against a pre-fix baseline of 2 in 14 under the same load. Full krikos-docs suite green (99 passed). Co-Authored-By: Claude Opus 5 --- protocols/krikos-docs/tests/sync.rs | 35 ++++++++++++++++++++++------- 1 file changed, 27 insertions(+), 8 deletions(-) diff --git a/protocols/krikos-docs/tests/sync.rs b/protocols/krikos-docs/tests/sync.rs index 2ef6c8cf6a6..853345ee9b7 100644 --- a/protocols/krikos-docs/tests/sync.rs +++ b/protocols/krikos-docs/tests/sync.rs @@ -829,6 +829,20 @@ async fn test_download_policies() -> Result<()> { assert_eq!(key_hashes.len(), star_wars_movies.len() + lotr_movies.len()); + // A hash can legitimately be reported downloaded by BOTH event arms: the + // engine emits ContentReady when a download completes (engine/live.rs, + // `on_download_ready`), and InsertRemote carries a `content_status` that is + // evaluated when the event is converted (engine.rs) -- so if the download + // finishes before its InsertRemote reaches the subscriber, that status + // reads Complete for content already announced by ContentReady. The two + // events mean different things and are not mutually exclusive; only the + // test assumed they were. Record each key once. + fn record(seen: &mut Vec<&'static str>, key: &'static str) { + if !seen.contains(&key) { + seen.push(key); + } + } + let fut = async { use LiveEvent::*; let mut downloaded_a: Vec<&'static str> = Vec::new(); @@ -842,11 +856,11 @@ async fn test_download_policies() -> Result<()> { InsertRemote { content_status, entry, .. } => { synced_a += 1; if let ContentStatus::Complete = content_status { - downloaded_a.push(key_hashes.get(&entry.content_hash()).unwrap()) + record(&mut downloaded_a, key_hashes.get(&entry.content_hash()).unwrap()) } }, ContentReady { hash } => { - downloaded_a.push(key_hashes.get(&hash).unwrap()); + record(&mut downloaded_a, key_hashes.get(&hash).unwrap()); }, _ => {} } @@ -856,21 +870,26 @@ async fn test_download_policies() -> Result<()> { InsertRemote { content_status, entry, .. } => { synced_b += 1; if let ContentStatus::Complete = content_status { - downloaded_b.push(key_hashes.get(&entry.content_hash()).unwrap()) + record(&mut downloaded_b, key_hashes.get(&entry.content_hash()).unwrap()) } }, ContentReady { hash } => { - downloaded_b.push(key_hashes.get(&hash).unwrap()); + record(&mut downloaded_b, key_hashes.get(&hash).unwrap()); }, _ => {} } } } - if synced_a == EXPECTED_A_SYNCED - && downloaded_a.len() == EXPECTED_A_DOWNLOADED - && synced_b == EXPECTED_B_SYNCED - && downloaded_b.len() == EXPECTED_B_DOWNLOADED + // `>=`, not `==`: these counters only ever grow, so an exact + // comparison that is overshot once can never become true again and + // the loop spins to TIMEOUT. The assertions after this loop still + // check the exact contents, so an unexpected extra event now fails + // legibly instead of as a 120s timeout with no diagnosis. + if synced_a >= EXPECTED_A_SYNCED + && downloaded_a.len() >= EXPECTED_A_DOWNLOADED + && synced_b >= EXPECTED_B_SYNCED + && downloaded_b.len() >= EXPECTED_B_DOWNLOADED { break; }