Extract lib/testing/log, refactor lib/log and lib/bats/assertions

lib/bats/assertions

@@ -279,7 +279,7 @@ assert_output_matches() {
   local pattern="$1"
 
   if [[ "$#" -ne 1 ]]; then
-    echo "ERROR: ${FUNCNAME[0]} takes exactly one argument" >&2
+    printf 'ERROR: %s takes exactly one argument\n' "${FUNCNAME[0]}" >&2
     return_from_bats_assertion '1'
   else
     assert_matches "$pattern" "$output" 'output'
@@ -568,20 +568,21 @@ __assert_lines() {
 
   if [[ "$lines_diff" -gt '0' ]]; then
     if [[ "$lines_diff" -eq '1' ]]; then
-      echo "There is one more line of output than expected:" >&2
+      printf 'There is one more line of output than expected:\n' >&2
     else
-      echo "There are $lines_diff more lines of output than expected:" >&2
+      printf 'There are %d more lines of output than expected:\n' \
+        "$lines_diff" >&2
     fi
-    local IFS=$'\n'
-    echo "${lines[*]:$num_lines}" >&2
+    printf '%s\n' "${lines[@]:$num_lines}" >&2
     ((++num_errors))
 
   elif [[ "$lines_diff" -lt '0' ]]; then
     lines_diff="$((-lines_diff))"
     if [[ "$lines_diff" -eq '1' ]]; then
-      echo "There is one fewer line of output than expected." >&2
+      printf 'There is one fewer line of output than expected.\n' >&2
     else
-      echo "There are $lines_diff fewer lines of output than expected." >&2
+      printf 'There are %d fewer lines of output than expected.\n' \
+        "$lines_diff" >&2
     fi
     ((++num_errors))
   fi
@@ -610,7 +611,7 @@ __assert_file() {
 
   if [[ "$assertion" == 'assert_matches' ]]; then
     if [[ "$#" -ne '1' ]]; then
-      echo "ERROR: ${FUNCNAME[1]} takes exactly two arguments" >&2
+      printf 'ERROR: %s takes exactly two arguments\n' "${FUNCNAME[1]}" >&2
       return '1'
     fi
     constraints=("$1" "$output" "The content of '$file_path'")

lib/log

@@ -251,10 +251,10 @@ readonly __GO_LOG_COMMAND_EXIT_PATTERN='^@go.log_command (exit|fatal):([0-9]+)$'
 
   local __go_log_timestamp
   if @go.log_timestamp; then
-    log_msg="$__go_log_timestamp "
+    __go_log_timestamp+=' '
   fi
-  log_msg+="${__GO_LOG_LEVELS_FORMATTED[$__go_log_level_index]} "
-  log_msg+="${args[*]}\\e[0m"
+  printf -v log_msg -- '%s%s %b' "$__go_log_timestamp" \
+    "${__GO_LOG_LEVELS_FORMATTED[$__go_log_level_index]}" "${args[*]}\\e[0m"
 
   local __go_log_level_file_descriptors=('1')
   if [[ "$__GO_LOG_COMMAND_DEPTH" == '0' || "$log_level" != 'RUN' ]]; then
@@ -271,7 +271,7 @@ readonly __GO_LOG_COMMAND_EXIT_PATTERN='^@go.log_command (exit|fatal):([0-9]+)$'
       fi
       printf '%s\n' "$stripped_log_msg" >&"$level_fd"
     else
-      printf '%b\n' "$log_msg" >&"$level_fd"
+      printf '%s\n' "$log_msg" >&"$level_fd"
     fi
 
     if [[ "$log_level" == 'FATAL' ]]; then
@@ -460,6 +460,7 @@ readonly __GO_LOG_COMMAND_EXIT_PATTERN='^@go.log_command (exit|fatal):([0-9]+)$'
   local __go_log_command_args=("$@")
   local cmd_string="${__go_log_command_args[*]}"
   local line
+  local stripped_line
   local exit_state
   local exit_status=1
 
@@ -482,6 +483,7 @@ readonly __GO_LOG_COMMAND_EXIT_PATTERN='^@go.log_command (exit|fatal):([0-9]+)$'
 
   while IFS= read -r line; do
     line="${line%$'\r'}"
+    stripped_line=''
 
     if [[ "$line" =~ $__GO_LOG_COMMAND_EXIT_PATTERN ]]; then
       # If the line immediately previous was fatal, keep the fatal state.
@@ -497,9 +499,12 @@ readonly __GO_LOG_COMMAND_EXIT_PATTERN='^@go.log_command (exit|fatal):([0-9]+)$'
 
     for fd in "${__go_log_level_file_descriptors[@]}"; do
       if [[ -t "$fd" || -n "$_GO_LOG_FORMATTING" ]]; then
-        printf '%b\n' "$line" >&"$fd"
-      else
         printf '%s\n' "$line" >&"$fd"
+      else
+        if [[ -z "$stripped_line" ]]; then
+          @go.strip_formatting_codes "$line" stripped_line
+        fi
+        printf '%s\n' "$stripped_line" >&"$fd"
       fi
     done
   done < <(_@go.log_command_invoke)
@@ -651,57 +656,20 @@ _@go.log_init() {
 
 # Assigns formatted log level labels to __GO_LOG_LEVELS_FORMATTED.
 #
-# If `_GO_LOG_FORMATTING` is not empty, or the file descriptor corresponding to
-# a log level corresponds to a terminal, this will assign a corresponding value
-# wrapped by terminal formatting codes to __GO_LOG_LEVELS_FORMATTED. Otherwise
-# the original label value is assigned.
-#
 # Each element of `__GO_LOG_LEVELS_FORMATTED` will also be padded with trailing
 # spaces so that each element will be the same length.
 #
 # Globals:
 #   _GO_LOG_LEVELS:                    List of valid log level labels
-#   _GO_LOG_FORMATTING                 If set, always produce formatted labels
 #   __GO_LOG_LEVELS_FORMAT_CODES:      Terminal format codes for each log level
-#   __GO_LOG_LEVELS_FILE_DESCRIPTORS:  Output descriptors for each log level
 #   __GO_LOG_LEVELS_FORMATTED:         Formatted labels
 _@go.log_format_level_labels() {
-  local num_levels="${#_GO_LOG_LEVELS[@]}"
-  local label_length
-  local longest_label_length
-  local padding=''
-  local log_level
-  local padding_len
-  local level_var
-  local level_fd
-  local i
-
-  for ((i=0; i != num_levels; ++i)); do
-    label_length="${#_GO_LOG_LEVELS[$i]}"
-    if [[ "$label_length" -gt "$longest_label_length" ]]; then
-      longest_label_length="$label_length"
-    fi
-  done
-
-  for ((i=0; i != longest_label_length; ++i)); do
-    padding+=' '
-  done
-
-  for ((i=0; i != num_levels; ++i)); do
-    log_level="${_GO_LOG_LEVELS[$i]}"
-    padding_len="$((${#padding} - ${#log_level}))"
-
-    local __go_log_level_file_descriptors=()
-    _@go.log_level_file_descriptors "$i"
-
-    for level_fd in "${__go_log_level_file_descriptors[@]}"; do
-      if [[ -n "$_GO_LOG_FORMATTING" || -t "$level_fd" ]]; then
-        log_level="${__GO_LOG_LEVELS_FORMAT_CODES[$i]}$log_level\e[0m"
-        break
-      fi
-    done
-    __GO_LOG_LEVELS_FORMATTED[$i]="${log_level}${padding:0:$padding_len}"
-  done
+  __GO_LOG_LEVELS_FORMATTED=("${_GO_LOG_LEVELS[@]/%/\\e[0m}")
+  @go.pad_items __GO_LOG_LEVELS_FORMATTED "${__GO_LOG_LEVELS_FORMATTED[@]}"
+  @go.zip_items __GO_LOG_LEVELS_FORMAT_CODES __GO_LOG_LEVELS_FORMATTED '' \
+    __GO_LOG_LEVELS_FORMATTED
+  @go.array_printf __GO_LOG_LEVELS_FORMATTED '%b' \
+    "${__GO_LOG_LEVELS_FORMATTED[@]}"
 }
 
 # Returns the set of file descriptors for the specified log level index.

lib/testing/environment

@@ -62,6 +62,19 @@ create_test_go_script() {
   fi
 }
 
+# Sets `_GO_CMD` to make for neater test output when running `TEST_GO_SCRIPT`
+#
+# Use `run test-go` instead of `run "$TEST_GO_SCRIPT"` to achieve the effect.
+#
+# Useful for tests that contain `_GO_CMD` in the output, to avoid clouding the
+# output with the full `TEST_GO_SCRIPT` path.
+#
+# Arguments:
+#    ...:  Command line arguments for `TEST_GO_SCRIPT`
+test-go() {
+  _GO_CMD="$FUNCNAME" "$TEST_GO_SCRIPT" "$@"
+}
+
 # Creates an executable `./go` command script in `TEST_GO_SCRIPTS_DIR`
 #
 # The script will be created as `$TEST_GO_SCRIPTS_DIR/$script_name`.

lib/testing/log

@@ -5,7 +5,152 @@
 # You must source `_GO_CORE_DIR/lib/testing/environment` before this file.
 
 . "${BASH_SOURCE[0]%/*}/stack-trace"
+. "$_GO_CORE_DIR/lib/bats/assertions"
 
+# Log timestamps are disabled by for testing by default.
+export _GO_LOG_TIMESTAMP_FORMAT=
+
+# Creates a `./go` script that imports the `log` module
+#
+# If `TEST_LOG_FILE` is defined, it will add that file for logging output as
+# well.
+#
+# Globals:
+#   TEST_LOG_FILE:  (Optional) Path to the log file to add for all log levels
+#
+# Arguments:
+#   ...:  Lines comprising the `./go` script
+create_log_script(){
+  create_test_go_script \
+    ". \"\$_GO_USE_MODULES\" 'log'" \
+    'if [[ -n "$TEST_LOG_FILE" ]]; then' \
+    '  @go.log_add_output_file "$TEST_LOG_FILE"' \
+    'fi' \
+    "$@"
+}
+
+# Creates and executes a `./go` script that imports the `log` module
+#
+# Globals and arguments are identical to `create_log_script`.
+run_log_script() {
+  create_log_script "$@"
+  run "$TEST_GO_SCRIPT"
+}
+
+# Format a `log` module log level label
+#
+# Arguments:
+#   label:  Log level label to format
+format_log_label() {
+  local label="$1"
+
+  . "$_GO_USE_MODULES" 'log'
+  _@go.log_init
+
+  local __go_log_level_index=0
+  if ! _@go.log_level_index "$label"; then
+    printf 'Unknown log level label: %s\n' "$label" >&2
+    exit 1
+  fi
+  printf '%s' "${__GO_LOG_LEVELS_FORMATTED[$__go_log_level_index]}"
+}
+
+# Validates that `output` matches the expected `@go.log` output
+#
+# Each line can be expressed one of two ways:
+# - As a pair of strings: first the log level label, then the log message
+# - As a single string without a log level label prefix
+#
+# Each log level label must exist within `_GO_LOG_LEVELS`, and can be either a
+# plaintext label or a label formatted with `format_log_label`. Any unknown
+# labels will be parsed as "a single string without a log label prefix".
+#
+# If you aren't looking for exact log output, consider using one of the standard
+# assertions from `_GO_CORE_DIR/lib/bats/assertions` instead.
+#
+# Note that this does NOT handle timestamps. If you wish to validate specific
+# timestamps, see `_GO_CORE_DIR/tests/log/timestamp.bats` for ideas.
+#
+# Arguments:
+#   ...:  Lines of expected log output
+assert_log_equals() {
+  set "$BATS_ASSERTION_DISABLE_SHELL_OPTIONS"
+  local __log_level_label
+  local expected=()
+  local i
+
+  . "$_GO_USE_MODULES" 'format' 'log'
+  _@go.log_init
+
+  for ((i=0; $# != 0; ++i)); do
+    if __parse_log_level_label "$1"; then
+      expected+=("$__log_level_label $2")
+
+      if [[ "${__log_level_label:0:1}" == $'\e' ]]; then
+        expected["$((${#expected[@]} - 1))"]+=$'\e[0m'
+      fi
+
+      if ! shift 2; then
+        printf 'ERROR: Wrong number of arguments for log line %d.\n' "$i" >&2
+        return_from_bats_assertion 1
+        return
+      fi
+    else
+      expected+=("$1")
+      shift
+    fi
+  done
+
+  if ! assert_lines_equal "${expected[@]}"; then
+    return_from_bats_assertion '1'
+  else
+    return_from_bats_assertion
+  fi
+}
+
+# Validates that a file matches the expected `@go.log` output
+#
+# Aside from the first file path argument, the remaining arguments and semantics
+# are exactly the same as `assert_log_equals`.
+#
+# In cases where `@go.log_add_output_file` is used to add a `TEST_LOG_FILE` to
+# all levels, and all test output comes from `@go.log`, this may be invoked
+# following `assert_log_equals` like so to ensure the log file output matches
+# standard output and standard error:
+#
+#   assert_log_file_equals "$TEST_LOG_FILE" "${lines[@]}"
+#
+# If you aren't looking for exact log output, consider using one of the standard
+# assertions from `_GO_CORE_DIR/lib/bats/assertions` instead.
+#
+# Arguments:
+#   log_file:  Path to the log file to validate
+#   ...:       Lines of expected log output
+assert_log_file_equals() {
+  set "$BATS_ASSERTION_DISABLE_SHELL_OPTIONS"
+  local log_file="$1"
+  shift
+
+  if ! set_bats_output_and_lines_from_file "$log_file"; then
+    return_from_bats_assertion '1'
+  else
+    assert_log_equals "$@"
+    return_from_bats_assertion "$?"
+  fi
+}
+
+# Creates `LOG_COMMAND_STACK_TRACE_ITEMS` to help validate stack trace output.
+#
+# Call this before using "${LOG_COMMAND_STACK_TRACE_ITEMS[@]}" to inject
+# entries from `@go.log_command` into your expected stack trace output. This
+# helps validate stack trace output generated by logged commands, and ensures
+# that your stack trace validation stays up-to-date even when the internal
+# structure of `lib/log` changes.
+#
+# Globals:
+#   LOG_COMMAND_STACK_TRACE_ITEMS:
+#     Stack trace lines from `@go.log_command` comprising the command logging
+#     mechanism
 set_log_command_stack_trace_items() {
   if [[ "${#LOG_COMMAND_STACK_TRACE_ITEMS[@]}" -eq '0' ]]; then
     export LOG_COMMAND_STACK_TRACE_ITEMS
@@ -18,3 +163,39 @@ set_log_command_stack_trace_items() {
       "$(stack_trace_item "$_GO_CORE_DIR/lib/log" '@go.log_command')")
   fi
 }
+
+# --------------------------------
+# IMPLEMENTATION - HERE BE DRAGONS
+#
+# None of the functions below this line are part of the public interface.
+# --------------------------------
+
+# Determines whether a log level label is a valid member of `_GO_LOG_LEVELS`.
+#
+# If so, pads the label and assigns it to `__log_level_label`.
+#
+# Arguments:
+#   level_label:  Log level label to examine
+#
+# Returns:
+#   zero if `level_label` exists in `_GO_LOG_LEVELS`, nonzero otherwise
+#   __log_level_label:  Assigned the padded version of `level_label` if valid
+__parse_log_level_label() {
+  local level_label="$1"
+  local try_level
+  local __go_log_level_index
+
+  @go.strip_formatting_codes "$level_label" 'try_level'
+  if [[ "$try_level" =~ \ +$ ]]; then
+    try_level="${try_level%${BASH_REMATCH[0]}}"
+  fi
+
+  if ! _@go.log_level_index "$try_level"; then
+    return 1
+  elif [[ "$level_label" != "$try_level" ]]; then
+    __log_level_label="$level_label"
+  else
+    @go.strip_formatting_codes \
+      "${__GO_LOG_LEVELS_FORMATTED[$__go_log_level_index]}" __log_level_label
+  fi
+}

tests/log/add-output-file.bats

@@ -1,7 +1,7 @@
 #! /usr/bin/env bats
 
 load ../environment
-load helpers
+load "$_GO_CORE_DIR/lib/testing/log"
 
 teardown() {
   remove_test_go_rootdir
@@ -66,7 +66,7 @@ run_log_script_and_assert_status_and_output() {
     "@go.log_add_output_file '$TEST_GO_ROOTDIR/info.log' 'INFO'" \
     "@go.log INFO Hello, World!"
   assert_success
-  assert_log_equals "$(format_label INFO)" 'Hello, World!'
+  assert_log_equals "$(format_log_label INFO)" 'Hello, World!'
   assert_file_equals "$TEST_GO_ROOTDIR/info.log" "${lines[@]}"
 }