ci: introduce io::log_cmdline (#6264)

Add `io::log_cmdline` for logging command execution. It prefixes
the command with `${PS4}`, just like `set -x` would in the shell.
This helps to delineate the command from normal output.

Also print the command in a bold typeface when possible, making
it even easier to distinguish.

Author: devbww

ci/kokoro/docker/build-in-docker-bazel.sh

@@ -32,9 +32,7 @@ readonly BINARY_DIR="$2"
 # This script is designed to work in the context created by the
 # ci/Dockerfile.* build scripts.
 
-echo
 io::log_yellow "Starting docker build with ${NCPU} cores"
-echo
 
 echo "================================================================"
 readonly BAZEL_BIN="/usr/local/bin/bazel"
@@ -110,7 +108,7 @@ io::log_yellow "Verify generator golden file md5 hashes"
 
 echo "================================================================"
 io::log "Compiling and running unit tests"
-echo "bazel ${BAZEL_VERB}" "${bazel_args[@]}"
+io::log_cmdline "bazel ${BAZEL_VERB}" "${bazel_args[@]}"
 "${BAZEL_BIN}" ${BAZEL_VERB} \
   "${bazel_args[@]}" "--test_tag_filters=-integration-test" ...
 

ci/kokoro/docker/build-in-docker-cmake.sh

@@ -29,9 +29,7 @@ fi
 readonly SOURCE_DIR="$1"
 readonly BINARY_DIR="$2"
 
-echo
 io::log_yellow "Starting docker build with ${NCPU} cores"
-echo
 
 # Run the configure / compile / test cycle inside a docker image.
 # This script is designed to work in the context created by the
@@ -586,7 +584,7 @@ if [[ "${CHECK_STYLE:-}" == "yes" && "${RUNNING_CI}" == "yes" ]]; then
   git diff --ignore-submodules=all --color --exit-code .
 fi
 
-if command -v ccache; then
+if command -v ccache >/dev/null 2>&1; then
   echo "================================================================"
   io::log_yellow "ccache stats"
   ccache --show-stats

ci/kokoro/docker/build.sh

@@ -364,13 +364,13 @@ fi
 
 echo "================================================================"
 io::log_yellow "Creating Docker image with all the development tools."
-echo "    docker build ${docker_build_flags[*]} ci"
-io::log_yellow "Logging to ${BUILD_OUTPUT}/create-build-docker-image.log"
 # We do not want to print the log unless there is an error, so disable the -e
 # flag. Later, we will want to print out the emulator(s) logs *only* if there
 # is an error, so disabling from this point on is the right choice.
 set +e
 mkdir -p "${BUILD_OUTPUT}"
+io::log_yellow "Logging to ${BUILD_OUTPUT}/create-build-docker-image.log"
+io::log_cmdline "docker build ${docker_build_flags[*]} ci"
 if timeout 3600s docker build "${docker_build_flags[@]}" ci \
   >"${BUILD_OUTPUT}/create-build-docker-image.log" 2>&1 </dev/null; then
   update_cache="true"
@@ -637,7 +637,7 @@ else
 fi
 
 # Run the docker image with that giant collection of flags.
-echo docker run "${docker_flags[@]}" "${IMAGE}:latest" "${commands[@]}"
+io::log_cmdline docker run "${docker_flags[@]}" "${IMAGE}:latest" "${commands[@]}"
 docker run "${docker_flags[@]}" "${IMAGE}:latest" "${commands[@]}"
 
 exit_status=$?
@@ -684,7 +684,6 @@ else
   io::log_yellow "Not a CI build; skipping artifact cleanup"
 fi
 
-echo
 echo "================================================================"
 if [[ ${exit_status} -eq 0 ]]; then
   io::log_green "Build script finished successfully."

ci/lib/io.sh

@@ -26,36 +26,38 @@ if ((CI_LIB_IO_SH__++ != 0)); then
   return 0
 fi # include guard
 
-# Callers may use these IO_COLOR_* variables directly, but it is recommended to
-# use the logging functions below instead. For example, prefer io::log_green
-# over IO_COLOR_GREEN.
+# Callers may use these IO_* variables directly, but should prefer to use the
+# logging functions below instead. For example, prefer `io::log_green "..."`
+# over `echo "${IO_COLOR_GREEN}...${IO_RESET}"`.
 if [ -t 0 ] && command -v tput >/dev/null; then
+  readonly IO_BOLD="$(tput bold)"
   readonly IO_COLOR_RED="$(tput setaf 1)"
   readonly IO_COLOR_GREEN="$(tput setaf 2)"
   readonly IO_COLOR_YELLOW="$(tput setaf 3)"
-  readonly IO_COLOR_RESET="$(tput sgr0)"
+  readonly IO_RESET="$(tput sgr0)"
 else
+  readonly IO_BOLD=""
   readonly IO_COLOR_RED=""
   readonly IO_COLOR_GREEN=""
   readonly IO_COLOR_YELLOW=""
-  readonly IO_COLOR_RESET=""
+  readonly IO_RESET=""
 fi
 
-# Logs a message using the given color. The first argument must be one of the
-# IO_COLOR_* variables defined above, such as "${IO_COLOR_YELLOW}". The
-# remaining arguments will be logged in the given color. The log message will
-# also have an RFC-3339 timestamp prepended (in UTC).
+# Logs a message using the given terminal capability. The first argument
+# must be one of the IO_* variables defined above, such as "${IO_COLOR_RED}".
+# The remaining arguments will be logged using the given capability. The
+# log message will also have an RFC-3339 timestamp prepended (in UTC).
 function io::internal::log_impl() {
-  local color="$1"
+  local termcap="$1"
   shift
   local timestamp
   timestamp="$(date -u "+%Y-%m-%dT%H:%M:%SZ")"
-  echo "${color}${timestamp}:" "$@" "${IO_COLOR_RESET}"
+  echo "${termcap}${timestamp}: $*${IO_RESET}"
 }
 
 # Logs the given message with normal coloring and a timestamp.
 function io::log() {
-  io::internal::log_impl "${IO_COLOR_RESET}" "$@"
+  io::internal::log_impl "${IO_RESET}" "$@"
 }
 
 # Logs the given message in green with a timestamp.
@@ -73,6 +75,12 @@ function io::log_red() {
   io::internal::log_impl "${IO_COLOR_RED}" "$@"
 }
 
+# Logs the arguments, in bold with a timestamp, like they were a command
+# executed under "set -x" in the shell (i.e., with a ${PS4} prefix).
+function io::log_cmdline() {
+  io::internal::log_impl "${IO_BOLD}" "${PS4}$*"
+}
+
 # Logs an "H1" heading. This looks like a blank line, followed by the message
 # in a double-lined box.
 #

google/cloud/storage/tools/run_emulator_utils.sh

@@ -29,12 +29,12 @@ EMULATOR_PID=0
 #   None
 ################################################
 kill_emulator() {
-  echo "${IO_COLOR_GREEN}[ -------- ]${IO_COLOR_RESET} Integration test environment tear-down."
+  echo "${IO_COLOR_GREEN}[ -------- ]${IO_RESET} Integration test environment tear-down."
   echo -n "Killing emulator server [${EMULATOR_PID}] ... "
   kill "${EMULATOR_PID}"
   wait "${EMULATOR_PID}" >/dev/null 2>&1
   echo "done."
-  echo "${IO_COLOR_GREEN}[ ======== ]${IO_COLOR_RESET} Integration test environment tear-down."
+  echo "${IO_COLOR_GREEN}[ ======== ]${IO_RESET} Integration test environment tear-down."
 
 }
 
@@ -55,7 +55,7 @@ kill_emulator() {
 start_emulator() {
   local port="${1:-0}"
 
-  echo "${IO_COLOR_GREEN}[ -------- ]${IO_COLOR_RESET} Integration test environment set-up"
+  echo "${IO_COLOR_GREEN}[ -------- ]${IO_RESET} Integration test environment set-up"
   echo "Launching Cloud Storage emulator in the background"
   trap kill_emulator EXIT
 
@@ -79,7 +79,7 @@ start_emulator() {
   done
 
   if [[ -z "${emulator_port}" ]]; then
-    echo "${IO_COLOR_RED}Cannot find listening port for emulator.${IO_COLOR_RESET}" >&2
+    echo "${IO_COLOR_RED}Cannot find listening port for emulator.${IO_RESET}" >&2
     cat gcs_emulator.log
     exit 1
   fi
@@ -99,7 +99,7 @@ start_emulator() {
   done
 
   if [[ "${connected}" = "no" ]]; then
-    echo "${IO_COLOR_RED}Cannot connect to emulator; aborting test.${IO_COLOR_RESET}" >&2
+    echo "${IO_COLOR_RED}Cannot connect to emulator; aborting test.${IO_RESET}" >&2
     cat gcs_emulator.log
     exit 1
   else
@@ -114,11 +114,11 @@ start_emulator() {
     echo "Successfully connected to gRPC server at port ${grpc_port}"
   else
     echo "${IO_COLOR_RED}${grpc_port} must be an integer" >&2
-    echo "${IO_COLOR_RED}Cannot connect to gRPC server; aborting test.${IO_COLOR_RESET}" >&2
+    echo "${IO_COLOR_RED}Cannot connect to gRPC server; aborting test.${IO_RESET}" >&2
     cat gcs_emulator.log
     exit 1
   fi
   export CLOUD_STORAGE_GRPC_ENDPOINT="localhost:${grpc_port}"
 
-  echo "${IO_COLOR_GREEN}[ ======== ]${IO_COLOR_RESET} Integration test environment set-up."
+  echo "${IO_COLOR_GREEN}[ ======== ]${IO_RESET} Integration test environment set-up."
 }