Improved Bash Logger (#1246)

* Improved Bash Logger

This is a first step towards having robust Bash scripts in the runner images. The changes _could_ be considered breaking, depending on our backwards compatibility definition.

* Fixed Log Formatting Issues

Co-authored-by: Callum Tait <15716903+toast-gear@users.noreply.github.com>

runner/Dockerfile

@@ -110,7 +110,9 @@ RUN mkdir /opt/hostedtoolcache \
     && chgrp docker /opt/hostedtoolcache \
     && chmod g+rwx /opt/hostedtoolcache
 
-COPY entrypoint.sh /
+# We place the scripts in `/usr/bin` so that users who extend this image can
+# override them with scripts of the same name placed in `/usr/local/bin`.
+COPY entrypoint.sh logger.bash /usr/bin/
 
 # Add the Python "User Script Directory" to the PATH
 ENV PATH="${PATH}:${HOME}/.local/bin"
@@ -122,4 +124,4 @@ RUN echo "PATH=${PATH}" > /etc/environment \
 USER runner
 
 ENTRYPOINT ["/usr/local/bin/dumb-init", "--"]
-CMD ["/entrypoint.sh"]
+CMD ["entrypoint.sh"]

runner/Dockerfile.dindrunner

@@ -98,12 +98,10 @@ RUN mkdir /opt/hostedtoolcache \
     && chgrp docker /opt/hostedtoolcache \
     && chmod g+rwx /opt/hostedtoolcache
 
-COPY modprobe startup.sh /usr/local/bin/
+# We place the scripts in `/usr/bin` so that users who extend this image can
+# override them with scripts of the same name placed in `/usr/local/bin`.
+COPY modprobe entrypoint.sh startup.sh logger.bash /usr/bin/
 COPY supervisor/ /etc/supervisor/conf.d/
-COPY logger.sh /opt/bash-utils/logger.sh
-COPY entrypoint.sh /usr/local/bin/
-
-RUN chmod +x /usr/local/bin/startup.sh /usr/local/bin/entrypoint.sh /usr/local/bin/modprobe
 
 # arch command on OS X reports "i386" for Intel CPUs regardless of bitness
 RUN export ARCH=$(echo ${TARGETPLATFORM} | cut -d / -f2) \

runner/entrypoint.sh

@@ -1,51 +1,35 @@
 #!/bin/bash
+source logger.bash
 
 RUNNER_ASSETS_DIR=${RUNNER_ASSETS_DIR:-/runnertmp}
 RUNNER_HOME=${RUNNER_HOME:-/runner}
 
-LIGHTGREEN="\e[0;32m"
-LIGHTRED="\e[0;31m"
-WHITE="\e[0;97m"
-RESET="\e[0m"
-
-log(){
-  printf "${WHITE}${@}${RESET}\n" 1>&2
-}
-
-success(){
-  printf "${LIGHTGREEN}${@}${RESET}\n" 1>&2
-}
-
-error(){
-  printf "${LIGHTRED}${@}${RESET}\n" 1>&2
-}
-
 if [ ! -z "${STARTUP_DELAY_IN_SECONDS}" ]; then
-  log "Delaying startup by ${STARTUP_DELAY_IN_SECONDS} seconds"
+  log.notice "Delaying startup by ${STARTUP_DELAY_IN_SECONDS} seconds"
   sleep ${STARTUP_DELAY_IN_SECONDS}
 fi
 
 if [[ "${DISABLE_WAIT_FOR_DOCKER}" != "true" ]] && [[ "${DOCKER_ENABLED}" == "true" ]]; then
-    log "Docker enabled runner detected and Docker daemon wait is enabled"
+    log.debug 'Docker enabled runner detected and Docker daemon wait is enabled'
-    log "Waiting until Docker is available or the timeout is reached"
+    log.debug 'Waiting until Docker is available or the timeout is reached'
     timeout 120s bash -c 'until docker ps ;do sleep 1; done'
 else
-  log "Docker wait check skipped. Either Docker is disabled or the wait is disabled, continuing with entrypoint"
+  log.notice 'Docker wait check skipped. Either Docker is disabled or the wait is disabled, continuing with entrypoint'
 fi
 
 if [ -z "${GITHUB_URL}" ]; then
-  log "Working with public GitHub"
+  log.debug 'Working with public GitHub'
   GITHUB_URL="https://github.com/"
 else
   length=${#GITHUB_URL}
   last_char=${GITHUB_URL:length-1:1}
 
   [[ $last_char != "/" ]] && GITHUB_URL="$GITHUB_URL/"; :
-  log "Github endpoint URL ${GITHUB_URL}"
+  log.debug "Github endpoint URL ${GITHUB_URL}"
 fi
 
 if [ -z "${RUNNER_NAME}" ]; then
-  error "RUNNER_NAME must be set"
+  log.error 'RUNNER_NAME must be set'
   exit 1
 fi
 
@@ -58,12 +42,12 @@ elif [ -n "${RUNNER_REPO}" ]; then
 elif [ -n "${RUNNER_ENTERPRISE}" ]; then
   ATTACH="enterprises/${RUNNER_ENTERPRISE}"
 else
-  error "At least one of RUNNER_ORG or RUNNER_REPO or RUNNER_ENTERPRISE must be set"
+  log.error 'At least one of RUNNER_ORG, RUNNER_REPO, or RUNNER_ENTERPRISE must be set'
   exit 1
 fi
 
 if [ -z "${RUNNER_TOKEN}" ]; then
-  error "RUNNER_TOKEN must be set"
+  log.error 'RUNNER_TOKEN must be set'
   exit 1
 fi
 
@@ -73,7 +57,7 @@ fi
 
 # Hack due to https://github.com/actions-runner-controller/actions-runner-controller/issues/252#issuecomment-758338483
 if [ ! -d "${RUNNER_HOME}" ]; then
-  error "${RUNNER_HOME} should be an emptyDir mount. Please fix the pod spec."
+  log.error "$RUNNER_HOME should be an emptyDir mount. Please fix the pod spec."
   exit 1
 fi
 
@@ -94,16 +78,16 @@ cd ${RUNNER_HOME}
 config_args=()
 if [ "${RUNNER_FEATURE_FLAG_EPHEMERAL:-}" == "true" -a "${RUNNER_EPHEMERAL}" == "true" ]; then
   config_args+=(--ephemeral)
-  echo "Passing --ephemeral to config.sh to enable the ephemeral runner."
+  log.debug 'Passing --ephemeral to config.sh to enable the ephemeral runner.'
 fi
 if [ "${DISABLE_RUNNER_UPDATE:-}" == "true" ]; then
   config_args+=(--disableupdate)
-  echo "Passing --disableupdate to config.sh to disable automatic runner updates."
+  log.debug 'Passing --disableupdate to config.sh to disable automatic runner updates.'
 fi
 
 retries_left=10
 while [[ ${retries_left} -gt 0 ]]; do
-  log "Configuring the runner."
+  log.debug 'Configuring the runner.'
   ./config.sh --unattended --replace \
     --name "${RUNNER_NAME}" \
     --url "${GITHUB_URL}${ATTACH}" \
@@ -113,18 +97,18 @@ while [[ ${retries_left} -gt 0 ]]; do
     --work "${RUNNER_WORKDIR}" "${config_args[@]}"
 
   if [ -f .runner ]; then
-    success "Runner successfully configured."
+    log.debug 'Runner successfully configured.'
     break
   fi
 
-  error "Configuration failed. Retrying"
+  log.debug 'Configuration failed. Retrying'
   retries_left=$((retries_left - 1))
   sleep 1
 done
 
 if [ ! -f .runner ]; then
   # we couldn't configure and register the runner; no point continuing
-  error "Configuration failed!"
+  log.error 'Configuration failed!'
   exit 2
 fi
 
@@ -159,8 +143,10 @@ fi
 args=()
 if [ "${RUNNER_FEATURE_FLAG_EPHEMERAL:-}" != "true" -a "${RUNNER_EPHEMERAL}" == "true" ]; then
   args+=(--once)
-  echo "[WARNING] Passing --once is deprecated and will be removed as an option from the image and ARC at the release of 0.24.0."
+  log.warning 'Passing --once is deprecated and will be removed as an option' \
-  echo "[WARNING] Upgrade to GHES => 3.3 to continue using actions-runner-controller. If you are using github.com ignore this warning."
+    'from the image and actions-runner-controller at the release of 0.24.0.' \
+    'Upgrade to GHES => 3.3 to continue using actions-runner-controller. If' \
+    'you are using github.com ignore this warning.'
 fi
 
 # Unset entrypoint environment variables so they don't leak into the runner environment

runner/logger.bash

@@ -0,0 +1,73 @@
+#!/usr/bin/env bash
+# We are not using `set -Eeuo pipefail` here because this file is sourced by
+# other scripts that might not be ready for a strict Bash setup. The functions
+# in this file do not require it, because they are not handling signals, have
+# no external calls that can fail (printf as well as date failures are ignored),
+# are not using any variables that need to be set, and are not using any pipes.
+
+# This logger implementation can be replaced with another logger implementation
+# by placing a script called `logger.bash` in `/usr/local/bin` of the image. The
+# only requirement for the script is that it defines the following functions:
+#
+# - `log.debug`
+# - `log.notice`
+# - `log.warning`
+# - `log.error`
+# - `log.success`
+#
+# Each function **MUST** accept an arbitrary amount of arguments that make up
+# the (unstructured) logging message.
+#
+# Additionally the following environment variables **SHOULD** be supported to
+# disable their corresponding log entries, the value of the variables **MUST**
+# not matter the mere fact that they are set is all that matters:
+#
+# - `LOG_DEBUG_DISABLED`
+# - `LOG_NOTICE_DISABLED`
+# - `LOG_WARNING_DISABLED`
+# - `LOG_ERROR_DISABLED`
+# - `LOG_SUCCESS_DISABLED`
+
+# The log format is constructed in a way that it can easily be parsed with
+# standard tools and simple string manipulations; pattern and example:
+#
+#     YYYY-MM-DD hh:mm:ss.SSS  $level --- $message
+#     2022-03-19 10:01:23.172  NOTICE --- example message
+#
+# This function is an implementation detail and **MUST NOT** be called from
+# outside this script (which is possible if the file is sourced).
+__log() {
+  local color instant level
+
+  color=${1:?missing required <color> argument}
+  shift
+
+  level=${FUNCNAME[1]} # `main` if called from top-level
+  level=${level#log.} # substring after `log.`
+  level=${level^^} # UPPERCASE
+
+  if [[ ! -v "LOG_${level}_DISABLED" ]]; then
+    instant=$(date '+%F %T.%-3N' 2>/dev/null || :)
+
+    # https://no-color.org/
+    if [[ -v NO_COLOR ]]; then
+      printf -- '%s  %s --- %s\n' "$instant" "$level" "$*" 1>&2 || :
+    else
+      printf -- '\033[0;%dm%s  %s --- %s\033[0m\n' "$color" "$instant" "$level" "$*" 1>&2 || :
+    fi
+  fi
+}
+
+# To log with a dynamic level use standard Bash capabilities:
+#
+#     level=notice
+#     command || level=error
+#     "log.$level" message
+#
+# @formatter:off
+log.debug   () { __log 37 "$@"; } # white
+log.notice  () { __log 34 "$@"; } # blue
+log.warning () { __log 33 "$@"; } # yellow
+log.error   () { __log 31 "$@"; } # red
+log.success () { __log 32 "$@"; } # green
+# @formatter:on

runner/logger.sh

@@ -1,24 +0,0 @@
-#!/bin/sh
-# Logger from this post http://www.cubicrace.com/2016/03/log-tracing-mechnism-for-shell-scripts.html
-
-function INFO(){
-    local function_name="${FUNCNAME[1]}"
-    local msg="$1"
-    timeAndDate=`date`
-    echo "[$timeAndDate] [INFO] [${0}] $msg"
-}
-
-
-function DEBUG(){
-    local function_name="${FUNCNAME[1]}"
-    local msg="$1"
-    timeAndDate=`date`
-    echo "[$timeAndDate] [DEBUG] [${0}] $msg"
-}
-
-function ERROR(){
-    local function_name="${FUNCNAME[1]}"
-    local msg="$1"
-    timeAndDate=`date`
-    echo "[$timeAndDate] [ERROR]  $msg"
-}

runner/startup.sh

@@ -1,13 +1,13 @@
 #!/bin/bash
-source /opt/bash-utils/logger.sh
+source logger.bash
 
 function wait_for_process () {
     local max_time_wait=30
     local process_name="$1"
     local waited_sec=0
     while ! pgrep "$process_name" >/dev/null && ((waited_sec < max_time_wait)); do
-        INFO "Process $process_name is not running yet. Retrying in 1 seconds"
+        log.debug "Process $process_name is not running yet. Retrying in 1 seconds"
-        INFO "Waited $waited_sec seconds of $max_time_wait seconds"
+        log.debug "Waited $waited_sec seconds of $max_time_wait seconds"
         sleep 1
         ((waited_sec=waited_sec+1))
         if ((waited_sec >= max_time_wait)); then
@@ -33,29 +33,32 @@ jq ".\"registry-mirrors\"[0] = \"${DOCKER_REGISTRY_MIRROR}\"" /etc/docker/daemon
 fi
 SCRIPT
 
-INFO "Using /etc/docker/daemon.json with the following content"
+dump() {
+  local path=${1:?missing required <path> argument}
+  shift
+  printf -- "%s\n---\n" "${*//\{path\}/"$path"}" 1>&2
+  cat "$path" 1>&2
+  printf -- '---\n' 1>&2
+}
 
-cat /etc/docker/daemon.json
+for config in /etc/docker/daemon.json /etc/supervisor/conf.d/dockerd.conf; do
+  dump "$config" 'Using {path} with the following content:'
+done
 
-INFO "Using /etc/supervisor/conf.d/dockerd.conf with the following content"
+log.debug 'Starting supervisor daemon'
-
-cat /etc/supervisor/conf.d/dockerd.conf
-
-INFO "Starting supervisor"
 sudo /usr/bin/supervisord -n >> /dev/null 2>&1 &
 
-INFO "Waiting for processes to be running"
+log.debug 'Waiting for processes to be running...'
 processes=(dockerd)
 
 for process in "${processes[@]}"; do
     wait_for_process "$process"
     if [ $? -ne 0 ]; then
-        ERROR "$process is not running after max time"
+        log.error "$process is not running after max time"
-        ERROR "Dumping /var/log/dockerd.err.log to help investigation"
+        dump /var/log/dockerd.err.log 'Dumping {path} to aid investigation'
-        cat /var/log/dockerd.err.log
         exit 1
     else
-        INFO "$process is running"
+        log.debug "$process is running"
     fi
 done