diff --git a/.changepacks/changepack_log_skill_fetch_budget.json b/.changepacks/changepack_log_skill_fetch_budget.json new file mode 100644 index 00000000..bb612f93 --- /dev/null +++ b/.changepacks/changepack_log_skill_fetch_budget.json @@ -0,0 +1,7 @@ +{ + "changes": { + "crates/devup-mcp/Cargo.toml": "Patch" + }, + "note": "devup_skills install could report that its four-second fetch budget had elapsed for skills whose upstream it never asked. The budget was one deadline for the whole install, so the time spent writing each skill's files counted against it: on a slow disk the later skills gave up before fetching and fell back to the embedded copy with a misleading reason - even with DEVUP_MCP_SKILLS_OFFLINE set, where the real reason is that fetching is disabled. The budget now covers only the time spent waiting on upstream, as documented, so every skill is still offered to upstream and each one reports why it was or was not fetched. The same timing made the skills install test fail intermittently on slow Windows runners.", + "date": "2026-09-26T18:40:19.654660Z" +} diff --git a/crates/devup-mcp/src/server/skills.rs b/crates/devup-mcp/src/server/skills.rs index d25426c0..1f350aaa 100644 --- a/crates/devup-mcp/src/server/skills.rs +++ b/crates/devup-mcp/src/server/skills.rs @@ -818,10 +818,13 @@ impl Skill { /// Resolve the complete set before staging any of it. One failed reference /// must not leave a new entry document next to old embedded references. + /// + /// `budget` is what is left of the install's time for waiting on + /// upstream, and only that waiting is taken from it. async fn fetch_documents( &self, upstream: &dyn SkillUpstream, - deadline: tokio::time::Instant, + budget: &mut std::time::Duration, ) -> Result { let mut documents = Vec::new(); let mut provenance = Vec::new(); @@ -832,11 +835,13 @@ impl Skill { "the four-second skill install fetch budget elapsed".to_owned(), ) }; - if tokio::time::Instant::now() >= deadline { + if budget.is_zero() { return Err((url, timeout_error())); } - let fetched = tokio::time::timeout_at(deadline, upstream.fetch(&url)) - .await + let asked = tokio::time::Instant::now(); + let answer = tokio::time::timeout(*budget, upstream.fetch(&url)).await; + *budget = budget.saturating_sub(asked.elapsed()); + let fetched = answer .unwrap_or_else(|_| Err(timeout_error())) .map_err(|error| (url.clone(), error))?; let text = std::str::from_utf8(&fetched.contents).map_err(|error| { @@ -1467,8 +1472,12 @@ async fn install_with( let mut refreshed = Vec::new(); let mut left_alone = Vec::new(); let mut warnings = Vec::new(); - // One budget for the call, not four seconds multiplied by the registry. - let deadline = tokio::time::Instant::now() + FETCH_TIMEOUT; + // One budget for the call, not four seconds multiplied by the registry - + // and for waiting on upstream only. Writing what was fetched is local + // work: charged too, a slow disk spent the budget, and the later skills + // reported it elapsed without ever asking upstream, instead of why they + // really could not be fetched. + let mut budget = FETCH_TIMEOUT; for skill in wanted .iter() .filter(|skill| skill.record.origin.is_carried()) @@ -1515,7 +1524,7 @@ async fn install_with( &mut transaction, skill, upstream, - deadline, + &mut budget, &refreshable .iter() .filter_map(|path| Some(path.parent()?.parent()?.to_path_buf())) @@ -1532,7 +1541,7 @@ async fn install_with( &mut transaction, skill, upstream, - deadline, + &mut budget, &roots, &project, &mut warnings, @@ -1579,7 +1588,7 @@ async fn stage_documents( transaction: &mut super::output::OutputTransaction, skill: &Skill, upstream: &dyn SkillUpstream, - deadline: tokio::time::Instant, + budget: &mut std::time::Duration, roots: &[PathBuf], project: &Path, warnings: &mut Vec, @@ -1595,7 +1604,7 @@ async fn stage_documents( let mut reason = Some("authored in this repository; no upstream".to_owned()); let mut provenance = Vec::new(); if skill.record.origin == Origin::Embedded { - match skill.fetch_documents(upstream, deadline).await { + match skill.fetch_documents(upstream, budget).await { Ok(fetched) => { documents = fetched.documents; provenance = fetched.provenance; diff --git a/crates/devup-mcp/src/server/skills/fetch_tests.rs b/crates/devup-mcp/src/server/skills/fetch_tests.rs index 15ca97c5..7ea7b280 100644 --- a/crates/devup-mcp/src/server/skills/fetch_tests.rs +++ b/crates/devup-mcp/src/server/skills/fetch_tests.rs @@ -208,6 +208,31 @@ async fn the_entire_install_has_one_four_second_fetch_budget() { std::fs::remove_dir_all(project).unwrap(); } +/// The budget is for waiting on upstream. Writing what was fetched is local +/// work, and a slow disk used to spend the budget on it: on a slow Windows +/// runner the later skills of an install reported the budget elapsed - never +/// having asked upstream - instead of why they really could not be fetched. +#[tokio::test(start_paused = true)] +async fn time_spent_between_fetches_is_not_charged_to_the_fetch_budget() { + let skill = find_by_name("devup-ui").unwrap(); + let offline = SkillFetchError::Network("DEVUP_MCP_SKILLS_OFFLINE disables fetching".to_owned()); + let upstream = FakeUpstream::new(Err(offline.clone())); + let mut budget = FETCH_TIMEOUT; + // Staging the skills before this one took longer than the whole budget. + tokio::time::advance(FETCH_TIMEOUT * 2).await; + let (_, error) = skill + .fetch_documents(&upstream, &mut budget) + .await + .err() + .unwrap(); + assert_eq!(error, offline); + assert_eq!(upstream.urls.lock().unwrap().len(), 1, "upstream was asked"); + assert_eq!( + budget, FETCH_TIMEOUT, + "an answer that came at once cost nothing" + ); +} + #[tokio::test] async fn nested_upstream_documents_are_fetched_whole_and_references_stay_byte_exact() { let mut record = find_by_name("devup-ui").unwrap().record.clone(); @@ -225,10 +250,8 @@ async fn nested_upstream_documents_are_fetched_whole_and_references_stay_byte_ex contents: b"# current\n".to_vec(), etag: "current".to_owned(), })); - let result = skill - .fetch_documents(&upstream, tokio::time::Instant::now() + FETCH_TIMEOUT) - .await - .unwrap(); + let mut budget = FETCH_TIMEOUT; + let result = skill.fetch_documents(&upstream, &mut budget).await.unwrap(); assert_eq!(result.documents.len(), 2); assert!(result.documents[0].1.contains("Fetched from")); assert_eq!(result.documents[1].1, "# current\n"); @@ -255,11 +278,9 @@ async fn nested_upstream_documents_are_fetched_whole_and_references_stay_byte_ex } } // The caller receives an error, never a partial set to mix with the binary. + let mut budget = FETCH_TIMEOUT; let failure = skill - .fetch_documents( - &MissingReference, - tokio::time::Instant::now() + FETCH_TIMEOUT, - ) + .fetch_documents(&MissingReference, &mut budget) .await .err() .unwrap(); diff --git a/crates/devup-mcp/tests/bridge_handover.rs b/crates/devup-mcp/tests/bridge_handover.rs index b7b96984..3337743a 100644 --- a/crates/devup-mcp/tests/bridge_handover.rs +++ b/crates/devup-mcp/tests/bridge_handover.rs @@ -177,6 +177,14 @@ impl Server { anyhow::ensure!(!failed, "{output}"); Ok(output) } + + /// Ends this devup-mcp and waits until it has exited. Dropping it only + /// starts the kill, and Windows will not remove a directory that a + /// running process has as its current one - every run used to leave its + /// scratch directories behind. + async fn stop(mut self) { + let _ = self.child.kill().await; + } } fn scratch_home() -> PathBuf { @@ -460,7 +468,8 @@ async fn every_process_reads_through_the_bridge_and_the_port_passes_on_when_its_ "the handover must finish within {DEADLINE:?}" ); - drop((second, third)); + second.stop().await; + third.stop().await; for directory in homes.iter().chain([&profile]) { let _ = std::fs::remove_dir_all(directory); } @@ -510,7 +519,7 @@ async fn a_collection_under_way_when_the_holder_exits_finishes_through_the_next_ the port over (the stand-in plugin retries every {PLUGIN_RETRY:?})" ); - drop(reader); + reader.stop().await; for directory in homes.iter().chain([&profile]) { let _ = std::fs::remove_dir_all(directory); } diff --git a/crates/devup-mcp/tests/skills_install.rs b/crates/devup-mcp/tests/skills_install.rs index 3889908e..7d82ed48 100644 --- a/crates/devup-mcp/tests/skills_install.rs +++ b/crates/devup-mcp/tests/skills_install.rs @@ -142,7 +142,8 @@ async fn a_bare_workspace_reports_the_gap_and_one_call_closes_it() -> anyhow::Re entry["reason"] .as_str() .unwrap() - .contains("DEVUP_MCP_SKILLS_OFFLINE") + .contains("DEVUP_MCP_SKILLS_OFFLINE"), + "{entry}" ); } let paths = entry["paths"]