ci: Improve log output (mainly Travis).

* Bring back colors on Travis, which was disabled since #39036.
  Append --color=always to cargo when running in CI environment.
* Removed `set -x` in the shell scripts. The `retry` function already
  prints which command it is running, add `-x` just add noise to the
  output.
* 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.

.travis.yml

@@ -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,6 +124,7 @@ 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");
@@ -148,6 +149,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 +280,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 +296,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 +330,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);
@@ -384,6 +390,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 \

src/ci/init_repo.sh

@@ -13,11 +13,11 @@ set -o errexit
 set -o pipefail
 set -o nounset
 
-set -o xtrace
-
 ci_dir=$(cd $(dirname $0) && pwd)
 . "$ci_dir/shared.sh"
 
+travis_fold start init_repo
+
 REPO_DIR="$1"
 CACHE_DIR="$2"
 
@@ -38,6 +38,7 @@ fi
 
 # Wipe the cache if it's not valid, or mark it as invalid while we update it
 if [ ! -f "$cache_valid_file" ]; then
+    echo "Invalid cache, wiping ($cache_valid_file missing)"
     rm -rf "$CACHE_DIR"
     mkdir "$CACHE_DIR"
 else
@@ -54,10 +55,14 @@ else
         rm -rf "$CACHE_DIR"
         mkdir "$CACHE_DIR"
     else
+        echo "Valid cache ($cache_valid_file exists)"
         rm "$cache_valid_file"
     fi
 fi
 
+travis_fold start update_cache
+travis_time_start
+
 # Update the cache (a pristine copy of the rust source master)
 if [ ! -d "$cache_src_dir/.git" ]; then
     retry sh -c "rm -rf $cache_src_dir && mkdir -p $cache_src_dir && \
@@ -69,8 +74,15 @@ retry sh -c "cd $cache_src_dir && \
     git submodule deinit -f . && git submodule sync && git submodule update --init"
 
 # Cache was updated without errors, mark it as valid
+echo "Refreshed cache (touch $cache_valid_file)"
 touch "$cache_valid_file"
 
+travis_fold end update_cache
+travis_time_finish
+
+travis_fold start update_submodules
+travis_time_start
+
 # Update the submodules of the repo we're in, using the pristine repo as
 # a cache for any object files
 # No, `git submodule foreach` won't work:
@@ -94,3 +106,8 @@ for module in $modules; do
     retry sh -c "git submodule deinit -f $module && \
         git submodule update --init --reference $cache_src_dir/$module $module"
 done
+
+travis_fold end update_submodules
+travis_time_finish
+
+travis_fold end init_repo

src/ci/run.sh

@@ -58,8 +58,17 @@ else
   fi
 fi
 
+travis_fold start configure
+travis_time_start
 $SRC/configure $RUST_CONFIGURE_ARGS
+travis_fold end configure
+travis_time_finish
+
+travis_fold start make-prepare
+travis_time_start
 retry make prepare
+travis_fold end make-prepare
+travis_time_finish
 
 if [ "$TRAVIS_OS_NAME" = "osx" ]; then
     ncpus=$(sysctl -n hw.ncpu)
@@ -67,12 +76,21 @@ else
     ncpus=$(grep processor /proc/cpuinfo | wc -l)
 fi
 
-set -x
-
 if [ ! -z "$SCRIPT" ]; then
   sh -x -c "$SCRIPT"
 else
-  make -j $ncpus tidy
-  make -j $ncpus
-  make $RUST_CHECK_TARGET -j $ncpus
+  do_make() {
+    travis_fold start "make-$1"
+    travis_time_start
+    echo "make -j $ncpus $1"
+    make -j $ncpus "$1"
+    local retval=$?
+    travis_fold end "make-$1"
+    travis_time_finish
+    return $retval
+  }
+
+  do_make tidy
+  do_make all
+  do_make "$RUST_CHECK_TARGET"
 fi

src/ci/shared.sh

@@ -30,3 +30,37 @@ function retry {
     }
   done
 }
+
+if ! declare -F travis_fold; then
+  if [ "${TRAVIS-false}" = 'true' ]; then
+    # This is a trimmed down copy of
+    # https://github.com/travis-ci/travis-build/blob/master/lib/travis/build/templates/header.sh
+    travis_fold() {
+      echo -en "travis_fold:$1:$2\r\033[0K"
+    }
+    travis_time_start() {
+      travis_timer_id=$(printf %08x $(( RANDOM * RANDOM )))
+      travis_start_time=$(travis_nanoseconds)
+      echo -en "travis_time:start:$travis_timer_id\r\033[0K"
+    }
+    travis_time_finish() {
+      travis_end_time=$(travis_nanoseconds)
+      local duration=$(($travis_end_time-$travis_start_time))
+      local msg="travis_time:end:$travis_timer_id"
+      echo -en "\n$msg:start=$travis_start_time,finish=$travis_end_time,duration=$duration\r\033[0K"
+    }
+    if [ $(uname) = 'Darwin' ]; then
+      travis_nanoseconds() {
+        date -u '+%s000000000'
+      }
+    else
+      travis_nanoseconds() {
+        date -u '+%s%N'
+      }
+    fi
+  else
+    travis_fold() { return 0; }
+    travis_time_start() { return 0; }
+    travis_time_finish() { return 0; }
+  fi
+fi