Print external commands that ruby-build executes

ruby-build now prints the full invocation of (almost) every external
command that it runs. Typically that is something like:

    -> ./configure --prefix=/path/to/ruby
    -> make -j 2
    -> make install

All output of these commands still goes to the log file by default.

This changes the behavior of `--verbose` mode to simply redirect all
command output to the stdout & stderr of the parent process instead of
writing to and then tailing the log file. This allows implementations of
commands like `./configure` or `make` to detect a terminal and output
color.

bin/ruby-build

@@ -18,9 +18,16 @@ RUBY_BUILD_VERSION="20231025"
 
 OLDIFS="$IFS"
 
+# Have shell functions inherit the ERR trap.
 set -E
-exec 3<&2 # preserve original stderr at fd 3
 
+# Some functions need to be able to write to the original process stderr
+# stream, since fd 2 would often have been redirected elsewhere. To enable
+# this, ruby-build initializes two additional file descriptors:
+#
+#  3: the original stderr
+#  4: the log file
+exec 3<&2
 
 lib() {
   parse_options() {
@@ -98,6 +105,78 @@ colorize() {
   fi
 }
 
+print_command() {
+  local arg
+  local tmpdir="${TMPDIR%/}"
+  for arg; do
+    arg="${arg//$tmpdir\//\$TMPDIR/}"
+    arg="${arg//$HOME\//\$HOME/}"
+    case "$arg" in
+    *\'* | *\$* )
+      printf ' "%s"' "$arg" ;;
+    *' '* )
+      printf " '%s'" "$arg" ;;
+    * )
+      printf ' %s' "$arg" ;;
+    esac
+  done
+  printf '\n'
+}
+
+# Log the full invocation of an external command.
+log_command() {
+  local msg
+  msg="->$(print_command "$@")"
+
+  colorize 36 "$msg"
+  echo
+  [ -n "$VERBOSE" ] || printf "%s\n" "$msg" >&4
+
+  local status=0
+  "$@" || status="$?"
+  if [ "$status" -ne 0 ]; then
+    echo "external command failed with status $status" >&4
+  fi
+  return "$status"
+}
+
+# Log the full invocation of an external command and capture its output.
+capture_command() {
+  local msg
+  msg="->$(print_command "$@")"
+
+  colorize 36 "$msg"
+  echo
+
+  # In verbose mode, connect the subcommand to original stdout & stderr.
+  local cmd_stdout=1
+  local cmd_stderr=3
+  if [ -z "$VERBOSE" ]; then
+    printf "%s\n" "$msg" >&4
+    # In normal mode, redirect all subcommand output to LOG_PATH.
+    cmd_stdout=4
+    cmd_stderr=4
+  fi
+
+  local status=0
+  # shellcheck disable=SC2261
+  "$@" 2>&$cmd_stderr >&$cmd_stdout || status="$?"
+  if [ "$status" -ne 0 ]; then
+    echo "external command failed with status $status" >&4
+  fi
+  return "$status"
+}
+
+log_info() {
+  colorize 1 "==> $*"
+  echo
+  [ -n "$VERBOSE" ] || echo "==> $*" >&4
+}
+
+log_notice() {
+  echo "ruby-build: $*"
+}
+
 os_information() {
   if type -p lsb_release >/dev/null; then
     lsb_release -sir | xargs echo
@@ -533,7 +612,7 @@ build_package() {
     local commands="$*"
   fi
 
-  echo "Installing ${package_name}..." >&2
+  log_info "Installing ${package_name}..."
 
   [ -n "$HAS_PATCH" ] && apply_ruby_patch "$package_name"
 
@@ -622,14 +701,15 @@ build_package_standard_build() {
     if [ -z "$CC" ] && is_mac 1010; then
       export CC=clang
     fi
+    # ./configure --prefix=/path/to/ruby
     # shellcheck disable=SC2086,SC2153
-    ${!PACKAGE_CONFIGURE:-./configure} --prefix="${!PACKAGE_PREFIX_PATH:-$PREFIX_PATH}" \
-      "${!PACKAGE_CONFIGURE_OPTS_ARRAY}" $CONFIGURE_OPTS ${!PACKAGE_CONFIGURE_OPTS} || return 1
-  ) >&4 2>&1
+    capture_command ${!PACKAGE_CONFIGURE:-./configure} --prefix="${!PACKAGE_PREFIX_PATH:-$PREFIX_PATH}" \
+      "${!PACKAGE_CONFIGURE_OPTS_ARRAY}" $CONFIGURE_OPTS ${!PACKAGE_CONFIGURE_OPTS}
+  ) || return $?
 
+  # make -j <num_cpu_cores>
   # shellcheck disable=SC2086
-  { "$MAKE" "${!PACKAGE_MAKE_OPTS_ARRAY}" $MAKE_OPTS ${!PACKAGE_MAKE_OPTS}
-  } >&4 2>&1
+  capture_command "$MAKE" "${!PACKAGE_MAKE_OPTS_ARRAY}" $MAKE_OPTS ${!PACKAGE_MAKE_OPTS}
 }
 
 build_package_standard_install() {
@@ -640,15 +720,14 @@ build_package_standard_install() {
   local PACKAGE_MAKE_INSTALL_OPTS="${package_var_name}_MAKE_INSTALL_OPTS"
   local PACKAGE_MAKE_INSTALL_OPTS_ARRAY="${package_var_name}_MAKE_INSTALL_OPTS_ARRAY[@]"
 
+  # make install
   # shellcheck disable=SC2086
-  { "$MAKE" ${MAKE_INSTALL_TARGET:-install} "${!PACKAGE_MAKE_INSTALL_OPTS_ARRAY}" $MAKE_INSTALL_OPTS ${!PACKAGE_MAKE_INSTALL_OPTS}
-  } >&4 2>&1
+  capture_command "$MAKE" ${MAKE_INSTALL_TARGET:-install} "${!PACKAGE_MAKE_INSTALL_OPTS_ARRAY}" $MAKE_INSTALL_OPTS ${!PACKAGE_MAKE_INSTALL_OPTS}
 }
 
 build_package_standard_install_with_bundled_gems() {
-  { "$MAKE" update-gems
-    "$MAKE" extract-gems
-  } >&4 2>&1
+  capture_command "$MAKE" update-gems
+  capture_command "$MAKE" extract-gems
 
   build_package_standard_install "$@"
 }
@@ -660,15 +739,11 @@ build_package_standard() {
 }
 
 build_package_autoconf() {
-  { autoreconf -i
-  } >&4 2>&1
+  capture_command autoreconf -i
 }
 
 build_package_ruby() {
-  local package_name="$1"
-
-  { "$RUBY_BIN" setup.rb
-  } >&4 2>&1
+  capture_command "$RUBY_BIN" setup.rb
 }
 
 build_package_ree_installer() {
@@ -686,8 +761,7 @@ build_package_ree_installer() {
   mkdir -p "$PREFIX_PATH/lib/ruby/gems/1.8/gems"
 
   # shellcheck disable=SC2086
-  { ./installer --auto "$PREFIX_PATH" --dont-install-useful-gems "${options[@]}" $CONFIGURE_OPTS
-  } >&4 2>&1
+  capture_command ./installer --auto "$PREFIX_PATH" --dont-install-useful-gems "${options[@]}" $CONFIGURE_OPTS
 }
 
 build_package_rbx() {
@@ -720,21 +794,19 @@ build_package_rbx() {
 }
 
 build_package_mruby() {
-  { ./minirake
-    mkdir -p "$PREFIX_PATH"
-    cp -fR build/host/* include "$PREFIX_PATH"
-    ln -fs mruby "$PREFIX_PATH/bin/ruby"
-    ln -fs mirb "$PREFIX_PATH/bin/irb"
-  } >&4 2>&1
+  capture_command ./minirake
+  mkdir -p "$PREFIX_PATH"
+  cp -fR build/host/* include "$PREFIX_PATH"
+  ln -fs mruby "$PREFIX_PATH/bin/ruby"
+  ln -fs mirb "$PREFIX_PATH/bin/irb"
 }
 
 build_package_picoruby() {
-  { ./minirake
-    mkdir -p "$PREFIX_PATH"
-    cp -fR build/host/* include "$PREFIX_PATH"
-    ln -fs picoruby "$PREFIX_PATH/bin/ruby"
-    ln -fs picoirb "$PREFIX_PATH/bin/irb"
-  } >&4 2>&1
+  capture_command ./minirake
+  mkdir -p "$PREFIX_PATH"
+  cp -fR build/host/* include "$PREFIX_PATH"
+  ln -fs picoruby "$PREFIX_PATH/bin/ruby"
+  ln -fs picoirb "$PREFIX_PATH/bin/irb"
 }
 
 build_package_jruby() {
@@ -755,9 +827,8 @@ install_jruby_launcher() {
   local jruby_version
   jruby_version="$(./ruby -e 'puts JRUBY_VERSION' 2>/dev/null)"
   [[ $jruby_version != "9.2."* ]] ||
-    ./ruby gem update -q --silent --system 3.3.26 --no-document --no-post-install-message >&4 2>&1
-  { ./ruby gem install jruby-launcher --no-document
-  } >&4 2>&1
+    capture_command ./ruby gem update -q --silent --system 3.3.26 --no-document --no-post-install-message
+  capture_command ./ruby gem install jruby-launcher --no-document
 }
 
 fix_jruby_shebangs() {
@@ -775,7 +846,7 @@ build_package_truffleruby() {
 
   # shellcheck disable=SC2164
   cd "${PREFIX_PATH}"
-  "${PREFIX_PATH}/lib/truffle/post_install_hook.sh"
+  capture_command ./lib/truffle/post_install_hook.sh
 }
 
 build_package_truffleruby_graalvm() {
@@ -791,7 +862,7 @@ build_package_truffleruby_graalvm() {
   fi
 
   if [ -e bin/gu ]; then
-    bin/gu install ruby || return $?
+    capture_command bin/gu install ruby
   fi
 
   local ruby_home
@@ -802,9 +873,9 @@ build_package_truffleruby_graalvm() {
 
   # shellcheck disable=SC2164
   cd "${PREFIX_PATH}"
-  ln -s "${ruby_home#"$PREFIX_PATH/"}/bin" . || return $?
+  ln -s "${ruby_home#"$PREFIX_PATH/"}/bin" .
 
-  "$ruby_home/lib/truffle/post_install_hook.sh"
+  capture_command "$ruby_home/lib/truffle/post_install_hook.sh"
 }
 
 build_package_artichoke() {
@@ -876,7 +947,7 @@ fix_rbx_gem_binstubs() {
 fix_rbx_irb() {
   local prefix="$1"
   "${prefix}/bin/irb" --version &>/dev/null ||
-    "${prefix}/bin/gem" install rubysl-tracer -v '~> 2.0' --no-rdoc --no-ri &>/dev/null ||
+    capture_command "${prefix}/bin/gem" install rubysl-tracer -v '~> 2.0' --no-rdoc --no-ri ||
     true
 }
 
@@ -924,7 +995,7 @@ use_homebrew_yaml() {
   local libdir
   libdir="$(brew --prefix libyaml 2>/dev/null || true)"
   if [ -d "$libdir" ]; then
-    echo "ruby-build: using libyaml from homebrew"
+    log_notice "using libyaml from homebrew"
     package_option ruby configure --with-libyaml-dir="$libdir"
   else
     return 1
@@ -945,7 +1016,7 @@ use_homebrew_gmp() {
   local libdir
   libdir="$(brew --prefix gmp 2>/dev/null || true)"
   if [ -d "$libdir" ]; then
-    echo "ruby-build: using gmp from homebrew"
+    log_notice "using gmp from homebrew"
     package_option ruby configure --with-gmp-dir="$libdir"
   else
     return 1
@@ -970,7 +1041,7 @@ use_homebrew_readline() {
   local libdir
   libdir="$(brew --prefix readline 2>/dev/null || true)"
   if [ -d "$libdir" ]; then
-    echo "ruby-build: using readline from homebrew"
+    log_notice "using readline from homebrew"
     package_option ruby configure --with-readline-dir="$libdir"
   else
     return 1
@@ -1070,7 +1141,7 @@ needs_openssl() {
     (( homebrew_version >= lower_bound && homebrew_version < upper_bound )) || continue
     while read -r formula version prefix; do
       [ "$version" = "${versions[index]}" ] || continue
-      echo "ruby-build: using $formula from homebrew"
+      log_notice "using $formula from homebrew"
       package_option ruby configure --with-openssl-dir="$prefix"
       return 1
     done <<<"$brew_installs"
@@ -1100,7 +1171,7 @@ use_homebrew_openssl() {
   local ssldir
   ssldir="$(brew --prefix openssl@1.1 2>/dev/null || true)"
   if [ -d "$ssldir" ]; then
-    echo "ruby-build: using openssl@1.1 from homebrew"
+    log_notice "using openssl@1.1 from homebrew"
     package_option ruby configure --with-openssl-dir="$ssldir"
   else
     colorize 1 "ERROR openssl@1.1 from Homebrew is required, run 'brew install openssl@1.1'"
@@ -1260,7 +1331,7 @@ apply_ruby_patch() {
 
     local striplevel=0
     grep -q '^--- a/' "$patchfile" && striplevel=1
-    patch -p$striplevel --force -i "$patchfile"
+    log_command patch -p$striplevel --force -i "$patchfile"
   fi
 }
 
@@ -1506,15 +1577,12 @@ else
   BUILD_PATH="$RUBY_BUILD_BUILD_PATH"
 fi
 
-exec 4<> "$LOG_PATH" # open the log file at fd 4
 if [ -n "$VERBOSE" ]; then
-  tail -f "$LOG_PATH" &
-  TAIL_PID=$!
-  trap 'kill $TAIL_PID' SIGINT SIGTERM EXIT
+  # open the original stdout at fd 4
+  exec 4<&1
 else
-  if [ -z "$RUBY_BUILD_TESTING" ]; then
-    echo "To follow progress, use 'tail -f $LOG_PATH' or pass --verbose" >&2
-  fi
+  # open the log file at fd 4
+  exec 4<> "$LOG_PATH"
 fi
 
 unset RUBYOPT

test/compiler.bats

@@ -14,21 +14,22 @@ export -n RUBY_CONFIGURE_OPTS
   stub_repeated uname '-s : echo Darwin'
   stub sw_vers '-productVersion : echo 10.10'
   stub_repeated brew 'false'
-  stub_repeated make 'echo "make $(inspect_args "$@")"'
+  # shellcheck disable=SC2016
+  stub_repeated make 'echo "make $(inspect_args "$@")" >> build.log'
 
   cat > ./configure <<CON
 #!${BASH}
-echo ./configure "\$@"
-echo CC=\$CC
-echo CFLAGS=\${CFLAGS-no}
+echo ./configure "\$@" > build.log
+echo CC=\$CC >> build.log
+echo CFLAGS=\${CFLAGS-no} >> build.log
 CON
   chmod +x ./configure
 
   run_inline_definition <<DEF
-exec 4<&1
 build_package_standard ruby
 DEF
   assert_success
+  run cat build.log
   assert_output <<OUT
 ./configure --prefix=$INSTALL_ROOT
 CC=clang

test/test_helper.bash

@@ -1,7 +1,6 @@
 export TMP="$BATS_TMPDIR"/ruby-build-test
 export RUBY_BUILD_CURL_OPTS=
 export RUBY_BUILD_HTTP_CLIENT="curl"
-export RUBY_BUILD_TESTING=true
 
 if [ "$FIXTURE_ROOT" != "$BATS_TEST_DIRNAME/fixtures" ]; then
   export FIXTURE_ROOT="$BATS_TEST_DIRNAME/fixtures"