Improve Travis CI log (travis_fold, colors)

.gitignore

@@ -101,3 +101,4 @@ version.ml
 version.texi
 .cargo
 !src/vendor/**
+/src/target/

.travis.yml

@@ -1,4 +1,4 @@
-language: minimal
+language: generic
 sudo: required
 dist: trusty
 services:
@@ -152,20 +152,21 @@ before_script:
       echo "#### Disk usage before running script:";
       df -h;
       du . | sort -nr | head -n100
-
-script:
   - >
       if [ "$ALLOW_PR" = "" ] && [ "$TRAVIS_BRANCH" != "auto" ]; then
-          echo skipping, not a full build
+          export RUN_SCRIPT="echo 'skipping, not a full build'";
       else
-          stamp src/ci/init_repo.sh . "$HOME/rustsrc" &&
+          RUN_SCRIPT="stamp src/ci/init_repo.sh . $HOME/rustsrc";
           if [ "$TRAVIS_OS_NAME" = "osx" ]; then
-              stamp src/ci/run.sh;
+              export RUN_SCRIPT="$RUN_SCRIPT && stamp src/ci/run.sh";
           else
-              stamp src/ci/docker/run.sh $IMAGE;
+              export RUN_SCRIPT="$RUN_SCRIPT && stamp src/ci/docker/run.sh $IMAGE";
           fi
       fi
 
+script:
+  - sh -x -c "$RUN_SCRIPT"
+
 after_success:
   - >
       echo "#### Build successful; Disk usage after running script:";

src/bootstrap/check.rs

@@ -124,13 +124,17 @@ pub fn cargo(build: &Build, stage: u32, host: &str) {
 /// otherwise just implements a few lint-like checks that are specific to the
 /// compiler itself.
 pub fn tidy(build: &Build, host: &str) {
+    let _folder = build.fold_output(|| "tidy");
     println!("tidy check ({})", host);
     let compiler = Compiler::new(0, host);
     let mut cmd = build.tool_cmd(&compiler, "tidy");
     cmd.arg(build.src.join("src"));
     if !build.config.vendor {
         cmd.arg("--no-vendor");
     }
+    if build.config.quiet_tests {
+        cmd.arg("--quiet");
+    }
     build.run(&mut cmd);
 }
 
@@ -148,6 +152,7 @@ pub fn compiletest(build: &Build,
                    target: &str,
                    mode: &str,
                    suite: &str) {
+    let _folder = build.fold_output(|| format!("test_{}", suite));
     println!("Check compiletest suite={} mode={} ({} -> {})",
              suite, mode, compiler.host, target);
     let mut cmd = Command::new(build.tool(&Compiler::new(0, compiler.host),
@@ -278,6 +283,8 @@ pub fn compiletest(build: &Build,
         cmd.arg("--android-cross-path").arg("");
     }
 
+    build.ci_env.force_coloring_in_ci(&mut cmd);
+
     let _time = util::timeit();
     build.run(&mut cmd);
 }
@@ -292,6 +299,7 @@ pub fn docs(build: &Build, compiler: &Compiler) {
     // tests for all files that end in `*.md`
     let mut stack = vec![build.src.join("src/doc")];
     let _time = util::timeit();
+    let _folder = build.fold_output(|| "test_docs");
 
     while let Some(p) = stack.pop() {
         if p.is_dir() {
@@ -325,6 +333,7 @@ pub fn docs(build: &Build, compiler: &Compiler) {
 /// generate a markdown file from the error indexes of the code base which is
 /// then passed to `rustdoc --test`.
 pub fn error_index(build: &Build, compiler: &Compiler) {
+    let _folder = build.fold_output(|| "test_error_index");
     println!("Testing error-index stage{}", compiler.stage);
 
     let dir = testdir(build, compiler.host);
@@ -349,13 +358,14 @@ fn markdown_test(build: &Build, compiler: &Compiler, markdown: &Path) {
     cmd.arg(markdown);
     cmd.env("RUSTC_BOOTSTRAP", "1");
 
-    let mut test_args = build.flags.cmd.test_args().join(" ");
-    if build.config.quiet_tests {
-        test_args.push_str(" --quiet");
-    }
+    let test_args = build.flags.cmd.test_args().join(" ");
     cmd.arg("--test-args").arg(test_args);
 
-    build.run(&mut cmd);
+    if build.config.quiet_tests {
+        build.run_quiet(&mut cmd);
+    } else {
+        build.run(&mut cmd);
+    }
 }
 
 /// Run all unit tests plus documentation tests for an entire crate DAG defined
@@ -384,6 +394,9 @@ pub fn krate(build: &Build,
         }
         _ => panic!("can only test libraries"),
     };
+    let _folder = build.fold_output(|| {
+        format!("{}_stage{}-{}", test_kind.subcommand(), compiler.stage, name)
+    });
     println!("{} {} stage{} ({} -> {})", test_kind, name, compiler.stage,
              compiler.host, target);
 

src/bootstrap/compile.rs

@@ -41,6 +41,7 @@ pub fn std(build: &Build, target: &str, compiler: &Compiler) {
     let libdir = build.sysroot_libdir(compiler, target);
     t!(fs::create_dir_all(&libdir));
 
+    let _folder = build.fold_output(|| format!("stage{}-std", compiler.stage));
     println!("Building stage{} std artifacts ({} -> {})", compiler.stage,
              compiler.host, target);
 
@@ -192,6 +193,7 @@ pub fn build_startup_objects(build: &Build, for_compiler: &Compiler, target: &st
 /// the build using the `compiler` targeting the `target` architecture. The
 /// artifacts created will also be linked into the sysroot directory.
 pub fn test(build: &Build, target: &str, compiler: &Compiler) {
+    let _folder = build.fold_output(|| format!("stage{}-test", compiler.stage));
     println!("Building stage{} test artifacts ({} -> {})", compiler.stage,
              compiler.host, target);
     let out_dir = build.cargo_out(compiler, Mode::Libtest, target);
@@ -228,6 +230,7 @@ pub fn test_link(build: &Build,
 /// the `compiler` targeting the `target` architecture. The artifacts
 /// created will also be linked into the sysroot directory.
 pub fn rustc(build: &Build, target: &str, compiler: &Compiler) {
+    let _folder = build.fold_output(|| format!("stage{}-rustc", compiler.stage));
     println!("Building stage{} compiler artifacts ({} -> {})",
              compiler.stage, compiler.host, target);
 
@@ -435,6 +438,7 @@ pub fn maybe_clean_tools(build: &Build, stage: u32, target: &str, mode: Mode) {
 /// This will build the specified tool with the specified `host` compiler in
 /// `stage` into the normal cargo output directory.
 pub fn tool(build: &Build, stage: u32, target: &str, tool: &str) {
+    let _folder = build.fold_output(|| format!("stage{}-{}", stage, tool));
     println!("Building stage{} tool {} ({})", stage, tool, target);
 
     let compiler = Compiler::new(stage, &build.config.build);

src/bootstrap/lib.rs

@@ -90,7 +90,7 @@ use std::process::Command;
 
 use build_helper::{run_silent, run_suppressed, output, mtime};
 
-use util::{exe, libdir, add_lib_path};
+use util::{exe, libdir, add_lib_path, OutputFolder, CiEnv};
 
 mod cc;
 mod channel;
@@ -179,6 +179,7 @@ pub struct Build {
     crates: HashMap<String, Crate>,
     is_sudo: bool,
     src_is_git: bool,
+    ci_env: CiEnv,
 }
 
 #[derive(Debug)]
@@ -272,6 +273,7 @@ impl Build {
             lldb_python_dir: None,
             is_sudo: is_sudo,
             src_is_git: src_is_git,
+            ci_env: CiEnv::current(),
         }
     }
 
@@ -507,6 +509,9 @@ impl Build {
         if self.config.vendor || self.is_sudo {
             cargo.arg("--frozen");
         }
+
+        self.ci_env.force_coloring_in_ci(&mut cargo);
+
         return cargo
     }
 
@@ -1011,6 +1016,19 @@ impl Build {
             "nightly" | _ => true,
         }
     }
+
+    /// Fold the output of the commands after this method into a group. The fold
+    /// ends when the returned object is dropped. Folding can only be used in
+    /// the Travis CI environment.
+    pub fn fold_output<D, F>(&self, name: F) -> Option<OutputFolder>
+        where D: Into<String>, F: FnOnce() -> D
+    {
+        if self.ci_env == CiEnv::Travis {
+            Some(OutputFolder::new(name().into()))
+        } else {
+            None
+        }
+    }
 }
 
 impl<'a> Compiler<'a> {

src/bootstrap/native.rs

@@ -63,6 +63,7 @@ pub fn llvm(build: &Build, target: &str) {
         drop(fs::remove_dir_all(&out_dir));
     }
 
+    let _folder = build.fold_output(|| "llvm");
     println!("Building LLVM for {}", target);
     let _time = util::timeit();
     t!(fs::create_dir_all(&out_dir));
@@ -218,6 +219,7 @@ pub fn test_helpers(build: &Build, target: &str) {
         return
     }
 
+    let _folder = build.fold_output(|| "build_test_helpers");
     println!("Building test helpers");
     t!(fs::create_dir_all(&dst));
     let mut cfg = gcc::Config::new();

src/bootstrap/util.rs

@@ -16,10 +16,10 @@
 use std::env;
 use std::ffi::OsString;
 use std::fs;
-use std::io;
+use std::io::{self, Write};
 use std::path::{Path, PathBuf};
 use std::process::Command;
-use std::time::Instant;
+use std::time::{SystemTime, Instant};
 
 use filetime::{self, FileTime};
 
@@ -324,3 +324,102 @@ pub fn symlink_dir(src: &Path, dest: &Path) -> io::Result<()> {
         }
     }
 }
+
+/// An RAII structure that indicates all output until this instance is dropped
+/// is part of the same group.
+///
+/// On Travis CI, these output will be folded by default, together with the
+/// elapsed time in this block. This reduces noise from unnecessary logs,
+/// allowing developers to quickly identify the error.
+///
+/// Travis CI supports folding by printing `travis_fold:start:<name>` and
+/// `travis_fold:end:<name>` around the block. Time elapsed is recognized
+/// similarly with `travis_time:[start|end]:<name>`. These are undocumented, but
+/// can easily be deduced from source code of the [Travis build commands].
+///
+/// [Travis build commands]:
+/// https://github.com/travis-ci/travis-build/blob/f603c0089/lib/travis/build/templates/header.sh
+pub struct OutputFolder {
+    name: String,
+    start_time: SystemTime, // we need SystemTime to get the UNIX timestamp.
+}
+
+impl OutputFolder {
+    /// Creates a new output folder with the given group name.
+    pub fn new(name: String) -> OutputFolder {
+        // "\r" moves the cursor to the beginning of the line, and "\x1b[0K" is
+        // the ANSI escape code to clear from the cursor to end of line.
+        // Travis seems to have trouble when _not_ using "\r\x1b[0K", that will
+        // randomly put lines to the top of the webpage.
+        print!("travis_fold:start:{0}\r\x1b[0Ktravis_time:start:{0}\r\x1b[0K", name);
+        OutputFolder {
+            name,
+            start_time: SystemTime::now(),
+        }
+    }
+}
+
+impl Drop for OutputFolder {
+    fn drop(&mut self) {
+        use std::time::*;
+        use std::u64;
+
+        fn to_nanos(duration: Result<Duration, SystemTimeError>) -> u64 {
+            match duration {
+                Ok(d) => d.as_secs() * 1_000_000_000 + d.subsec_nanos() as u64,
+                Err(_) => u64::MAX,
+            }
+        }
+
+        let end_time = SystemTime::now();
+        let duration = end_time.duration_since(self.start_time);
+        let start = self.start_time.duration_since(UNIX_EPOCH);
+        let finish = end_time.duration_since(UNIX_EPOCH);
+        println!(
+            "travis_fold:end:{0}\r\x1b[0K\n\
+                travis_time:end:{0}:start={1},finish={2},duration={3}\r\x1b[0K",
+            self.name,
+            to_nanos(start),
+            to_nanos(finish),
+            to_nanos(duration)
+        );
+        io::stdout().flush().unwrap();
+    }
+}
+
+/// The CI environment rustbuild is running in. This mainly affects how the logs
+/// are printed.
+#[derive(Copy, Clone, PartialEq, Eq, Debug)]
+pub enum CiEnv {
+    /// Not a CI environment.
+    None,
+    /// The Travis CI environment, for Linux (including Docker) and macOS builds.
+    Travis,
+    /// The AppVeyor environment, for Windows builds.
+    AppVeyor,
+}
+
+impl CiEnv {
+    /// Obtains the current CI environment.
+    pub fn current() -> CiEnv {
+        if env::var("TRAVIS").ok().map_or(false, |e| &*e == "true") {
+            CiEnv::Travis
+        } else if env::var("APPVEYOR").ok().map_or(false, |e| &*e == "True") {
+            CiEnv::AppVeyor
+        } else {
+            CiEnv::None
+        }
+    }
+
+    /// If in a CI environment, forces the command to run with colors.
+    pub fn force_coloring_in_ci(self, cmd: &mut Command) {
+        if self != CiEnv::None {
+            // Due to use of stamp/docker, the output stream of rustbuild is not
+            // a TTY in CI, so coloring is by-default turned off.
+            // The explicit `TERM=xterm` environment is needed for
+            // `--color always` to actually work. This env var was lost when
+            // compiling through the Makefile. Very strange.
+            cmd.env("TERM", "xterm").args(&["--color", "always"]);
+        }
+    }
+}

src/ci/docker/run.sh

@@ -21,6 +21,9 @@ root_dir="`dirname $src_dir`"
 
 source "$ci_dir/shared.sh"
 
+travis_fold start build_docker
+travis_time_start
+
 if [ -f "$docker_dir/$image/Dockerfile" ]; then
     retry docker \
       build \
@@ -44,6 +47,9 @@ else
     exit 1
 fi
 
+travis_fold end build_docker
+travis_time_finish
+
 objdir=$root_dir/obj
 
 mkdir -p $HOME/.cargo
@@ -72,6 +78,7 @@ exec docker \
   --env DEPLOY=$DEPLOY \
   --env DEPLOY_ALT=$DEPLOY_ALT \
   --env LOCAL_USER_ID=`id -u` \
+  --env TRAVIS=${TRAVIS-false} \
   --volume "$HOME/.cargo:/cargo" \
   --volume "$HOME/rustsrc:$HOME/rustsrc" \
   --privileged \