From 014b4f9de6d12e9a4971eb8b5ca62dc81cc13bd6 Mon Sep 17 00:00:00 2001 From: Dale Wijnand Date: Mon, 30 Apr 2018 18:29:16 +0100 Subject: [PATCH 1/2] WIP Rebuild on mid build file modification Fails the test. Running tests with output streaming (.stream()) & enabled logs: RUST_LOG=cargo::core::compiler::fingerprint cargo test rebuild_on_mid_build_file_modification shows: running `/d/cargo/target/debug/cargo build` DEBUG 2018-04-30T17:27:20Z: cargo::core::compiler::fingerprint: fingerprint at: /d/cargo/target/cit/t0/p/target/debug/.fingerprint/root-819987bee50907ec/lib-root-819987bee50907ec INFO 2018-04-30T17:27:20Z: cargo::core::compiler::fingerprint: fingerprint error for root v0.1.0 (file:///d/cargo/target/cit/t0/p/root): failed to read `/d/cargo/target/cit/t0/p/target/debug/.fingerprint/root-819987bee50907ec/lib-root-819987bee50907ec` INFO 2018-04-30T17:27:20Z: cargo::core::compiler::fingerprint: cause: No such file or directory (os error 2) DEBUG 2018-04-30T17:27:20Z: cargo::core::compiler::fingerprint: fingerprint at: /d/cargo/target/cit/t0/p/target/debug/.fingerprint/proc_macro_dep-aae81e26f117d294/lib-proc_macro_dep-aae81e26f117d294 INFO 2018-04-30T17:27:20Z: cargo::core::compiler::fingerprint: fingerprint error for proc_macro_dep v0.1.0 (file:///d/cargo/target/cit/t0/p/proc_macro_dep): failed to read `/d/cargo/target/cit/t0/p/target/debug/.fingerprint/proc_macro_dep-aae81e26f117d294/lib-proc_macro_dep-aae81e26f117d294` INFO 2018-04-30T17:27:20Z: cargo::core::compiler::fingerprint: cause: No such file or directory (os error 2) Compiling proc_macro_dep v0.1.0 (file:///d/cargo/target/cit/t0/p/proc_macro_dep) DEBUG 2018-04-30T17:27:21Z: cargo::core::compiler::fingerprint: write fingerprint: /d/cargo/target/cit/t0/p/target/debug/.fingerprint/proc_macro_dep-aae81e26f117d294/lib-proc_macro_dep-aae81e26f117d294 Compiling root v0.1.0 (file:///d/cargo/target/cit/t0/p/root) DEBUG 2018-04-30T17:27:21Z: cargo::core::compiler::fingerprint: write fingerprint: /d/cargo/target/cit/t0/p/target/debug/.fingerprint/root-819987bee50907ec/lib-root-819987bee50907ec Finished dev [unoptimized + debuginfo] target(s) in 1.59 secs running `/d/cargo/target/debug/cargo build` DEBUG 2018-04-30T17:27:22Z: cargo::core::compiler::fingerprint: fingerprint at: /d/cargo/target/cit/t0/p/target/debug/.fingerprint/root-819987bee50907ec/lib-root-819987bee50907ec INFO 2018-04-30T17:27:22Z: cargo::core::compiler::fingerprint: fingerprint error for root v0.1.0 (file:///d/cargo/target/cit/t0/p/root): mtime based components have changed: previously Some(FileTime { seconds: 1525109240, nanos: 821138000 }) now Some(FileTime { seconds: 1525109241, nanos: 943469455 }), paths are ".fingerprint/root-819987bee50907ec/dep-lib-root-819987bee50907ec" and ".fingerprint/root-819987bee50907ec/dep-lib-root-819987bee50907ec" DEBUG 2018-04-30T17:27:22Z: cargo::core::compiler::fingerprint: fingerprint at: /d/cargo/target/cit/t0/p/target/debug/.fingerprint/proc_macro_dep-aae81e26f117d294/lib-proc_macro_dep-aae81e26f117d294 INFO 2018-04-30T17:27:22Z: cargo::core::compiler::fingerprint: fingerprint error for proc_macro_dep v0.1.0 (file:///d/cargo/target/cit/t0/p/proc_macro_dep): mtime based components have changed: previously Some(FileTime { seconds: 1525109240, nanos: 821138000 }) now Some(FileTime { seconds: 1525109241, nanos: 635532764 }), paths are ".fingerprint/proc_macro_dep-aae81e26f117d294/dep-lib-proc_macro_dep-aae81e26f117d294" and ".fingerprint/proc_macro_dep-aae81e26f117d294/dep-lib-proc_macro_dep-aae81e26f117d294" Compiling proc_macro_dep v0.1.0 (file:///d/cargo/target/cit/t0/p/proc_macro_dep) DEBUG 2018-04-30T17:27:22Z: cargo::core::compiler::fingerprint: write fingerprint: /d/cargo/target/cit/t0/p/target/debug/.fingerprint/proc_macro_dep-aae81e26f117d294/lib-proc_macro_dep-aae81e26f117d294 Compiling root v0.1.0 (file:///d/cargo/target/cit/t0/p/root) DEBUG 2018-04-30T17:27:23Z: cargo::core::compiler::fingerprint: write fingerprint: /d/cargo/target/cit/t0/p/target/debug/.fingerprint/root-819987bee50907ec/lib-root-819987bee50907ec Finished dev [unoptimized + debuginfo] target(s) in 1.19 secs --- src/cargo/core/compiler/custom_build.rs | 4 +- src/cargo/core/compiler/fingerprint.rs | 59 +++++++----- src/cargo/core/compiler/mod.rs | 8 +- tests/testsuite/build.rs | 115 +++++++++++++++++++++++- 4 files changed, 162 insertions(+), 24 deletions(-) diff --git a/src/cargo/core/compiler/custom_build.rs b/src/cargo/core/compiler/custom_build.rs index ff28c0e065a..c5afd1c73dd 100644 --- a/src/cargo/core/compiler/custom_build.rs +++ b/src/cargo/core/compiler/custom_build.rs @@ -4,6 +4,7 @@ use std::fs; use std::path::{Path, PathBuf}; use std::str; use std::sync::{Arc, Mutex}; +use std::time::SystemTime; use core::PackageId; use util::errors::{CargoResult, CargoResultExt}; @@ -79,6 +80,7 @@ pub struct BuildDeps { pub fn prepare<'a, 'cfg>( cx: &mut Context<'a, 'cfg>, unit: &Unit<'a>, + build_start_time: SystemTime, ) -> CargoResult<(Work, Work, Freshness)> { let _p = profile::start(format!( "build script prepare: {}/{}", @@ -96,7 +98,7 @@ pub fn prepare<'a, 'cfg>( // Now that we've prep'd our work, build the work needed to manage the // fingerprint and then start returning that upwards. - let (freshness, dirty, fresh) = fingerprint::prepare_build_cmd(cx, unit)?; + let (freshness, dirty, fresh) = fingerprint::prepare_build_cmd(cx, unit, build_start_time)?; Ok((work_dirty.then(dirty), work_fresh.then(fresh), freshness)) } diff --git a/src/cargo/core/compiler/fingerprint.rs b/src/cargo/core/compiler/fingerprint.rs index 73bd44bf3eb..df409b864a1 100644 --- a/src/cargo/core/compiler/fingerprint.rs +++ b/src/cargo/core/compiler/fingerprint.rs @@ -3,6 +3,7 @@ use std::fs; use std::hash::{self, Hasher}; use std::path::{Path, PathBuf}; use std::sync::{Arc, Mutex}; +use std::time::SystemTime; use filetime::FileTime; use serde::de::{self, Deserialize}; @@ -50,6 +51,7 @@ pub type Preparation = (Freshness, Work, Work); pub fn prepare_target<'a, 'cfg>( cx: &mut Context<'a, 'cfg>, unit: &Unit<'a>, + build_start_time: SystemTime, ) -> CargoResult { let _p = profile::start(format!( "fingerprint: {} / {}", @@ -61,7 +63,7 @@ pub fn prepare_target<'a, 'cfg>( debug!("fingerprint at: {}", loc.display()); - let fingerprint = calculate(cx, unit)?; + let fingerprint = calculate(cx, unit, build_start_time)?; let compare = compare_old_fingerprint(&loc, &*fingerprint); log_compare(unit, &compare); @@ -103,9 +105,8 @@ pub fn prepare_target<'a, 'cfg>( } let allow_failure = cx.extra_args_for(unit).is_some(); - let target_root = cx.files().target_root().to_path_buf(); let write_fingerprint = Work::new(move |_| { - match fingerprint.update_local(&target_root) { + match fingerprint.update_local() { Ok(()) => {} Err(..) if allow_failure => return Ok(()), Err(e) => return Err(e), @@ -199,30 +200,33 @@ where #[derive(Serialize, Deserialize, Hash)] enum LocalFingerprint { Precalculated(String), - MtimeBased(MtimeSlot, PathBuf), + MtimeBased(MtimeSlot, PathBuf, SystemTime), EnvBased(String, Option), } impl LocalFingerprint { - fn mtime(root: &Path, mtime: Option, path: &Path) -> LocalFingerprint { + fn mtime( + root: &Path, + mtime: Option, + path: &Path, + build_start_time: SystemTime, + ) -> LocalFingerprint { let mtime = MtimeSlot(Mutex::new(mtime)); assert!(path.is_absolute()); let path = path.strip_prefix(root).unwrap_or(path); - LocalFingerprint::MtimeBased(mtime, path.to_path_buf()) + LocalFingerprint::MtimeBased(mtime, path.to_path_buf(), build_start_time) } } struct MtimeSlot(Mutex>); impl Fingerprint { - fn update_local(&self, root: &Path) -> CargoResult<()> { + fn update_local(&self) -> CargoResult<()> { let mut hash_busted = false; for local in self.local.iter() { match *local { - LocalFingerprint::MtimeBased(ref slot, ref path) => { - let path = root.join(path); - let mtime = paths::mtime(&path)?; - *slot.0.lock().unwrap() = Some(mtime); + LocalFingerprint::MtimeBased(ref slot, _, build_start_time) => { + *slot.0.lock().unwrap() = Some(FileTime::from_system_time(build_start_time)); } LocalFingerprint::EnvBased(..) | LocalFingerprint::Precalculated(..) => continue, } @@ -284,8 +288,8 @@ impl Fingerprint { } } ( - &LocalFingerprint::MtimeBased(ref on_disk_mtime, ref ap), - &LocalFingerprint::MtimeBased(ref previously_built_mtime, ref bp), + &LocalFingerprint::MtimeBased(ref on_disk_mtime, ref ap, _), + &LocalFingerprint::MtimeBased(ref previously_built_mtime, ref bp, _), ) => { let on_disk_mtime = on_disk_mtime.0.lock().unwrap(); let previously_built_mtime = previously_built_mtime.0.lock().unwrap(); @@ -413,6 +417,7 @@ impl<'de> de::Deserialize<'de> for MtimeSlot { fn calculate<'a, 'cfg>( cx: &mut Context<'a, 'cfg>, unit: &Unit<'a>, + build_start_time: SystemTime, ) -> CargoResult> { if let Some(s) = cx.fingerprints.get(unit) { return Ok(Arc::clone(s)); @@ -429,7 +434,7 @@ fn calculate<'a, 'cfg>( let deps = deps.iter() .filter(|u| !u.target.is_custom_build() && !u.target.is_bin()) .map(|dep| { - calculate(cx, dep).and_then(|fingerprint| { + calculate(cx, dep, build_start_time).and_then(|fingerprint| { let name = cx.extern_crate_name(unit, dep)?; Ok((dep.pkg.package_id().to_string(), name, fingerprint)) }) @@ -440,7 +445,7 @@ fn calculate<'a, 'cfg>( let local = if use_dep_info(unit) { let dep_info = dep_info_loc(cx, unit); let mtime = dep_info_mtime_if_fresh(unit.pkg, &dep_info)?; - LocalFingerprint::mtime(cx.files().target_root(), mtime, &dep_info) + LocalFingerprint::mtime(cx.files().target_root(), mtime, &dep_info, build_start_time) } else { let fingerprint = pkg_fingerprint(cx, unit.pkg)?; LocalFingerprint::Precalculated(fingerprint) @@ -505,6 +510,7 @@ fn use_dep_info(unit: &Unit) -> bool { pub fn prepare_build_cmd<'a, 'cfg>( cx: &mut Context<'a, 'cfg>, unit: &Unit<'a>, + build_start_time: SystemTime, ) -> CargoResult { let _p = profile::start(format!("fingerprint build cmd: {}", unit.pkg.package_id())); let new = cx.files().fingerprint_dir(unit); @@ -512,7 +518,7 @@ pub fn prepare_build_cmd<'a, 'cfg>( debug!("fingerprint at: {}", loc.display()); - let (local, output_path) = build_script_local_fingerprints(cx, unit)?; + let (local, output_path) = build_script_local_fingerprints(cx, unit, build_start_time)?; let mut fingerprint = Fingerprint { rustc: 0, target: 0, @@ -548,8 +554,9 @@ pub fn prepare_build_cmd<'a, 'cfg>( let outputs = &outputs[&key]; if !outputs.rerun_if_changed.is_empty() || !outputs.rerun_if_env_changed.is_empty() { let deps = BuildDeps::new(&output_path, Some(outputs)); - fingerprint.local = local_fingerprints_deps(&deps, &target_root, &pkg_root); - fingerprint.update_local(&target_root)?; + fingerprint.local = + local_fingerprints_deps(&deps, &target_root, &pkg_root, build_start_time); + fingerprint.update_local()?; } } write_fingerprint(&loc, &fingerprint) @@ -565,6 +572,7 @@ pub fn prepare_build_cmd<'a, 'cfg>( fn build_script_local_fingerprints<'a, 'cfg>( cx: &mut Context<'a, 'cfg>, unit: &Unit<'a>, + build_start_time: SystemTime, ) -> CargoResult<(Vec, Option)> { let state = cx.build_state.outputs.lock().unwrap(); // First up, if this build script is entirely overridden, then we just @@ -599,7 +607,12 @@ fn build_script_local_fingerprints<'a, 'cfg>( // dependencies as well as env vars listed as dependencies. Process them all // here. Ok(( - local_fingerprints_deps(deps, cx.files().target_root(), unit.pkg.root()), + local_fingerprints_deps( + deps, + cx.files().target_root(), + unit.pkg.root(), + build_start_time, + ), Some(output), )) } @@ -608,6 +621,7 @@ fn local_fingerprints_deps( deps: &BuildDeps, target_root: &Path, pkg_root: &Path, + build_start_time: SystemTime, ) -> Vec { debug!("new local fingerprints deps"); let mut local = Vec::new(); @@ -615,7 +629,12 @@ fn local_fingerprints_deps( let output = &deps.build_script_output; let deps = deps.rerun_if_changed.iter().map(|p| pkg_root.join(p)); let mtime = mtime_if_fresh(output, deps); - local.push(LocalFingerprint::mtime(target_root, mtime, output)); + local.push(LocalFingerprint::mtime( + target_root, + mtime, + output, + build_start_time, + )); } for var in deps.rerun_if_env_changed.iter() { diff --git a/src/cargo/core/compiler/mod.rs b/src/cargo/core/compiler/mod.rs index 28718a67f78..f7935339946 100644 --- a/src/cargo/core/compiler/mod.rs +++ b/src/cargo/core/compiler/mod.rs @@ -5,6 +5,7 @@ use std::fs; use std::io::{self, Write}; use std::path::{self, Path, PathBuf}; use std::sync::Arc; +use std::time::SystemTime; use same_file::is_same_file; use serde_json; @@ -302,13 +303,16 @@ fn compile<'a, 'cfg: 'a>( fingerprint::prepare_init(cx, unit)?; cx.links.validate(cx.resolve, unit)?; + let build_start_time = SystemTime::now(); + let (dirty, fresh, freshness) = if unit.mode.is_run_custom_build() { - custom_build::prepare(cx, unit)? + custom_build::prepare(cx, unit, build_start_time)? } else if unit.mode == CompileMode::Doctest { // we run these targets later, so this is just a noop for now (Work::noop(), Work::noop(), Freshness::Fresh) } else { - let (mut freshness, dirty, fresh) = fingerprint::prepare_target(cx, unit)?; + let (mut freshness, dirty, fresh) = + fingerprint::prepare_target(cx, unit, build_start_time)?; let work = if unit.mode.is_doc() { rustdoc(cx, unit)? } else { diff --git a/tests/testsuite/build.rs b/tests/testsuite/build.rs index 12cdd8ae766..3b303daa792 100644 --- a/tests/testsuite/build.rs +++ b/tests/testsuite/build.rs @@ -1,6 +1,8 @@ use std::env; -use std::fs::{self, File}; +use std::fs::{self, File, OpenOptions}; use std::io::prelude::*; +use std::net::TcpListener; +use std::thread; use cargo::util::paths::dylib_path_envvar; use cargo::util::{process, ProcessBuilder}; @@ -2809,6 +2811,117 @@ fn rebuild_preserves_out_dir() { ); } +#[test] +fn rebuild_on_mid_build_file_modification() { + let server = TcpListener::bind("127.0.0.1:0").unwrap(); + let addr = server.local_addr().unwrap(); + + let p = project("p") + .file( + "Cargo.toml", + r#" + [workspace] + members = ["root", "proc_macro_dep"] + "#, + ) + .file( + "root/Cargo.toml", + r#" + [project] + name = "root" + version = "0.1.0" + authors = [] + + [dependencies] + proc_macro_dep = { path = "../proc_macro_dep" } + "#, + ) + .file( + "root/src/lib.rs", + r#" + #[macro_use] + extern crate proc_macro_dep; + + #[derive(Noop)] + pub struct X; + "#, + ) + .file( + "proc_macro_dep/Cargo.toml", + r#" + [project] + name = "proc_macro_dep" + version = "0.1.0" + authors = [] + + [lib] + proc-macro = true + "#, + ) + .file( + "proc_macro_dep/src/lib.rs", + &format!( + r#" + extern crate proc_macro; + + use std::io::Read; + use std::net::TcpStream; + use proc_macro::TokenStream; + + #[proc_macro_derive(Noop)] + pub fn noop(_input: TokenStream) -> TokenStream {{ + let mut stream = TcpStream::connect("{}").unwrap(); + let mut v = Vec::new(); + stream.read_to_end(&mut v).unwrap(); + "".parse().unwrap() + }} + "#, + addr + ), + ) + .build(); + let root = p.root(); + + let t = thread::spawn(move || { + let socket = server.accept().unwrap().0; + let mut file = OpenOptions::new() + .write(true) + .append(true) + .open(root.join("root/src/lib.rs")) + .unwrap(); + writeln!(file, "// modified").expect("Failed to append to root sources"); + drop(file); + drop(socket); + drop(server.accept().unwrap()); + }); + + assert_that( + p.cargo("build"), + execs().stream().with_status(0) +// .with_stderr(&format!( +// "\ +//[COMPILING] proc_macro_dep v0.1.0 ({url}/proc_macro_dep) +//[COMPILING] root v0.1.0 ({url}/root) +//[FINISHED] dev [unoptimized + debuginfo] target(s) in [..] +//", +// url = p.url() +// )), + ); + + assert_that( + p.cargo("build"), + execs().stream().with_status(0).with_stderr(&format!( + "\ +[COMPILING] root v0.1.0 ({url}/root) +[FINISHED] dev [unoptimized + debuginfo] target(s) in [..] +", + url = p.url() + )), + ); + + t.join().ok().unwrap(); +} + #[test] fn dep_no_libs() { let foo = project("foo") From fb35120644a3dc2a5c8d71f25db1a887876dca02 Mon Sep 17 00:00:00 2001 From: Dale Wijnand Date: Mon, 30 Apr 2018 21:35:51 +0100 Subject: [PATCH 2/2] Add log message for fingerprint updating & comparing --- src/cargo/core/compiler/fingerprint.rs | 53 +++++++++++++++++++------- 1 file changed, 39 insertions(+), 14 deletions(-) diff --git a/src/cargo/core/compiler/fingerprint.rs b/src/cargo/core/compiler/fingerprint.rs index df409b864a1..7fcb07ad656 100644 --- a/src/cargo/core/compiler/fingerprint.rs +++ b/src/cargo/core/compiler/fingerprint.rs @@ -105,8 +105,9 @@ pub fn prepare_target<'a, 'cfg>( } let allow_failure = cx.extra_args_for(unit).is_some(); + let target_root = cx.files().target_root().to_path_buf(); let write_fingerprint = Work::new(move |_| { - match fingerprint.update_local() { + match fingerprint.update_local(&target_root) { Ok(()) => {} Err(..) if allow_failure => return Ok(()), Err(e) => return Err(e), @@ -221,12 +222,25 @@ impl LocalFingerprint { struct MtimeSlot(Mutex>); impl Fingerprint { - fn update_local(&self) -> CargoResult<()> { + fn update_local(&self, root: &Path) -> CargoResult<()> { let mut hash_busted = false; for local in self.local.iter() { match *local { - LocalFingerprint::MtimeBased(ref slot, _, build_start_time) => { - *slot.0.lock().unwrap() = Some(FileTime::from_system_time(build_start_time)); + LocalFingerprint::MtimeBased(ref slot, ref path, build_start_time) => { + let path = root.join(path); + let mtime = paths::mtime(&path)?; + let time = FileTime::from_system_time(build_start_time); + let mtime_str = match *slot.0.lock().unwrap() { + None => "".to_string(), + Some(ft) => format!("{}", ft), + }; + debug!("updating fingerprint at {}, from {} to {} (rather than mtime {})", + path.display(), + mtime_str, + time, + mtime, + ); + *slot.0.lock().unwrap() = Some(time); } LocalFingerprint::EnvBased(..) | LocalFingerprint::Precalculated(..) => continue, } @@ -291,23 +305,34 @@ impl Fingerprint { &LocalFingerprint::MtimeBased(ref on_disk_mtime, ref ap, _), &LocalFingerprint::MtimeBased(ref previously_built_mtime, ref bp, _), ) => { - let on_disk_mtime = on_disk_mtime.0.lock().unwrap(); - let previously_built_mtime = previously_built_mtime.0.lock().unwrap(); + let on_disk_mtime = *on_disk_mtime.0.lock().unwrap(); + let previously_built_mtime = *previously_built_mtime.0.lock().unwrap(); - let should_rebuild = match (*on_disk_mtime, *previously_built_mtime) { + let should_rebuild = match (on_disk_mtime, previously_built_mtime) { (None, None) => false, (Some(_), None) | (None, Some(_)) => true, (Some(on_disk), Some(previously_built)) => on_disk > previously_built, }; if should_rebuild { + let mtime1 = match previously_built_mtime { + None => "".to_string(), + Some(ft) => format!("{}", ft), + }; + let mtime2 = match on_disk_mtime { + None => "".to_string(), + Some(ft) => format!("{}", ft), + }; + let paths_are = if ap == bp { + format!("path: {}", ap.display()) + } else { + format!("paths are {} and {}", ap.display(), bp.display()) + }; bail!( - "mtime based components have changed: previously {:?} now {:?}, \ - paths are {:?} and {:?}", - *previously_built_mtime, - *on_disk_mtime, - ap, - bp + "mtime based components have changed: previously {} now {}, {}", + mtime1, + mtime2, + paths_are, ) } } @@ -556,7 +581,7 @@ pub fn prepare_build_cmd<'a, 'cfg>( let deps = BuildDeps::new(&output_path, Some(outputs)); fingerprint.local = local_fingerprints_deps(&deps, &target_root, &pkg_root, build_start_time); - fingerprint.update_local()?; + fingerprint.update_local(&target_root)?; } } write_fingerprint(&loc, &fingerprint)