Auto merge of #42128 - kennytm:travis-folder, r=alexcrichton

Improve Travis CI log (travis_fold, colors)

Result looks like (https://travis-ci.org/rust-lang/rust/jobs/234614611):

<details><summary>Full page screenshot</summary>

![1-fullpage](https://cloud.githubusercontent.com/assets/103023/26302841/2627c354-3f18-11e7-9299-52a2088639af.jpg)

</details>

---

* Bring back colors on Travis, which was disabled since #39036. Append `--color=always` to cargo when running in CI environment.
* Removed `set -x` from the shell scripts. The `retry` function already prints which command it is running, adding `-x` just adds noise to the output. Interesting information can be manually `echo`ed.
* Support `travis_fold`/`travis_time`. Matching pairs of these allow Travis CI to collapse the output in between. This greatly cut down the unnecessary "successful" output one need to scroll through before finding the failed statement.
* Passed `--quiet` to all tests, so tests not failing will not occupy a line of log, reducing bloat in the report.

Also include some minor changes, like changing the `script` of `.travis.yml` to execute a single-line command, so the log won't write the extremely long multi-line
`The command "if [ "$ALLOW_PR" = "" ] && [ "$TRAVIS_BRANCH" != "auto" ]; then … " exited with 0` at the end.

Author: bors

.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 \