ci: silence ci test output while recording in full (#30654)

* ci: silence ci test output while recording in full

* shellcheck

* Adjust --color handling place

* Dump to stderr...

* Reduce too spammy solana_metrics logs

* Clean up

* Tweak

* Stash actual command's exit_code, not echo's

.buildkite/hooks/post-command

@@ -1,11 +1,22 @@
 #!/bin/bash -e
 
+source ci/upload-ci-artifact.sh
+
 #
 # Add job_stats data point
 #
 if [[ -z $CI_BUILD_START ]]; then
   echo Error: CI_BUILD_START empty
 else
+  # make sure console outputs are uploaded as soon as possible, if any
+  (
+    shopt -s nullglob
+    for console_log in ./intercepted-console-*; do
+      gzip -f "$console_log"
+      upload-ci-artifact "$console_log.gz"
+    done
+  )
+
   CI_BUILD_DURATION=$(( $(date +%s) - CI_BUILD_START + 1 ))
 
   CI_LABEL=${BUILDKITE_LABEL:-build label missing}

ci/intercept.sh

@@ -0,0 +1,22 @@
+#!/usr/bin/env bash
+
+set -e
+
+if [[ -n $CI && -z $NO_INTERCEPT ]]; then
+  console_log="./intercepted-console-$(date '+%Yy%mm%dd%Hh%Mm%Ss%Nns').log"
+  echo "$0: Intercepting stderr into $console_log, along side tee-d stdout."
+
+  # we don't care about being racy here as was before; so disable shellcheck
+  # shellcheck disable=SC2094
+  if "$@" 2>> "$console_log" 1>> >(tee -a "$console_log"); then
+    exit_code=0
+  else
+    exit_code=$?
+    echo "$0: command failed; please see $console_log in artifacts"
+  fi
+  exit "$exit_code"
+else
+  # revert to noop so that this wrapper isn't so inconvenient to be used deep
+  # outside CI=1 land (i.e. on laptops)
+  "$@"
+fi

ci/test-coverage.sh

@@ -21,9 +21,6 @@ report=coverage-"${CI_COMMIT:0:9}".tar.gz
 mv target/cov/report.tar.gz "$report"
 upload-ci-artifact "$report"
 
-gzip -f target/cov/coverage-stderr.log
-upload-ci-artifact target/cov/coverage-stderr.log.gz
-
 annotate --style success --context lcov-report \
   "lcov report: <a href=\"artifact://$report\">$report</a>"
 

ci/test-stable.sh

@@ -65,7 +65,7 @@ test-stable)
     _ cargo test --jobs "$JOBS" --all --tests --exclude solana-local-cluster ${V:+--verbose} -- -Z unstable-options --format json --report-time | tee results.json
     exit_if_error "${PIPESTATUS[0]}"
   else
-    _ cargo test --jobs "$JOBS" --all --tests --exclude solana-local-cluster ${V:+--verbose} -- --nocapture
+    _ ci/intercept.sh cargo test --jobs "$JOBS" --all --tests --exclude solana-local-cluster ${V:+--verbose} -- --nocapture
   fi
   ;;
 test-stable-sbf)
@@ -180,7 +180,7 @@ test-local-cluster)
     _ cargo test --release --package solana-local-cluster --test local_cluster ${V:+--verbose} -- --test-threads=1 -Z unstable-options --format json --report-time | tee results.json
     exit_if_error "${PIPESTATUS[0]}"
   else
-    _ cargo test --release --package solana-local-cluster --test local_cluster ${V:+--verbose} -- --nocapture --test-threads=1
+    _ ci/intercept.sh cargo test --release --package solana-local-cluster --test local_cluster ${V:+--verbose} -- --nocapture --test-threads=1
   fi
   exit 0
   ;;
@@ -190,7 +190,7 @@ test-local-cluster-flakey)
     _ cargo test --release --package solana-local-cluster --test local_cluster_flakey ${V:+--verbose} -- --test-threads=1 -Z unstable-options --format json --report-time | tee results.json
     exit_if_error "${PIPESTATUS[0]}"
   else
-    _ cargo test --release --package solana-local-cluster --test local_cluster_flakey ${V:+--verbose} -- --nocapture --test-threads=1
+    _ ci/intercept.sh cargo test --release --package solana-local-cluster --test local_cluster_flakey ${V:+--verbose} -- --nocapture --test-threads=1
   fi
   exit 0
   ;;
@@ -200,7 +200,7 @@ test-local-cluster-slow-1)
     _ cargo test --release --package solana-local-cluster --test local_cluster_slow_1 ${V:+--verbose} -- --test-threads=1 -Z unstable-options --format json --report-time | tee results.json
     exit_if_error "${PIPESTATUS[0]}"
   else
-    _ cargo test --release --package solana-local-cluster --test local_cluster_slow_1 ${V:+--verbose} -- --nocapture --test-threads=1
+    _ ci/intercept.sh cargo test --release --package solana-local-cluster --test local_cluster_slow_1 ${V:+--verbose} -- --nocapture --test-threads=1
   fi
   exit 0
   ;;
@@ -210,7 +210,7 @@ test-local-cluster-slow-2)
     _ cargo test --release --package solana-local-cluster --test local_cluster_slow_2 ${V:+--verbose} -- --test-threads=1 -Z unstable-options --format json --report-time | tee results.json
     exit_if_error "${PIPESTATUS[0]}"
   else
-    _ cargo test --release --package solana-local-cluster --test local_cluster_slow_2 ${V:+--verbose} -- --nocapture --test-threads=1
+    _ ci/intercept.sh cargo test --release --package solana-local-cluster --test local_cluster_slow_2 ${V:+--verbose} -- --nocapture --test-threads=1
   fi
   exit 0
   ;;
@@ -243,6 +243,7 @@ esac
 
 (
   export CARGO_TOOLCHAIN=+"$rust_stable"
+  export RUST_LOG="solana_metrics=warn,info,$RUST_LOG"
   echo --- ci/localnet-sanity.sh
   ci/localnet-sanity.sh -x
 

scripts/coverage.sh

@@ -78,8 +78,11 @@ fi
 NPROC=$(nproc)
 JOBS=$((JOBS>NPROC ? NPROC : JOBS))
 
-RUST_LOG=solana=trace _ "$cargo" nightly test --jobs "$JOBS" --target-dir target/cov --no-run "${packages[@]}"
-if RUST_LOG=solana=trace _ "$cargo" nightly test --jobs "$JOBS" --target-dir target/cov "${packages[@]}" -- --nocapture 2> >(tee target/cov/coverage-stderr.log >&2); then
+_ "$cargo" nightly test --jobs "$JOBS" --target-dir target/cov --no-run "${packages[@]}"
+
+# most verbose log level (trace) is enabled for all solana code to make log!
+# macro code green always
+if RUST_LOG=solana=trace _ ci/intercept.sh "$cargo" nightly test --jobs "$JOBS" --target-dir target/cov "${packages[@]}" -- --nocapture; then
   test_status=0
 else
   test_status=$?

sdk/cargo-build-sbf/tests/crates.rs

@@ -30,8 +30,8 @@ fn run_cargo_build(crate_name: &str, extra_args: &[&str], fail: bool) {
     let mut cmd = assert_cmd::Command::cargo_bin("cargo-build-sbf").unwrap();
     let assert = cmd.env("RUST_LOG", "debug").args(&args).assert();
     let output = assert.get_output();
-    println!("Test stdout\n{}\n", String::from_utf8_lossy(&output.stdout));
-    println!("Test stderr\n{}\n", String::from_utf8_lossy(&output.stderr));
+    eprintln!("Test stdout\n{}\n", String::from_utf8_lossy(&output.stdout));
+    eprintln!("Test stderr\n{}\n", String::from_utf8_lossy(&output.stderr));
     if fail {
         assert.failure();
     } else {