lib/log: Expand format codes on @go.log_init

This also precipitated a refactor of `assert_log_equals` and its
implementation functions to handle the expanded code, which actually
simplified the logic a bit.

By the same token, it's no longer required that `format_log_label` be
called before other `lib/log` functions, as `__GO_LOG_LEVELS_FORMATTED`
will always contain expanded format codes and `@go.log` will strip them
out if need be.

Author: mbland

lib/log

@@ -253,7 +253,7 @@ readonly __GO_LOG_COMMAND_EXIT_PATTERN='^@go.log_command (exit|fatal):([0-9]+)$'
   if @go.log_timestamp; then
     __go_log_timestamp+=' '
   fi
-  printf -v log_msg -- '%s%b %b' "$__go_log_timestamp" \
+  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')
@@ -668,6 +668,8 @@ _@go.log_format_level_labels() {
   @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/log

@@ -35,23 +35,11 @@ run_log_script() {
 
 # Format a `log` module log level label
 #
-# Note that this must be called before any other log assertion, because it needs
-# to set _GO_LOG_FORMATTING before importing the `log` module.
-#
 # Arguments:
 #   label:  Log level label to format
 format_log_label() {
   local label="$1"
 
-  if [[ -n "$__GO_LOG_INIT" ]]; then
-    local err_format=("\`%s\` must be called before any other function"
-      "or assertion that calls \`. \"\$_GO_USE_MODULES\" 'log'\`"
-      'because it needs to set `_GO_LOG_FORMATTING`.')
-    printf "${err_format[*]}" "$FUNCNAME" >&2
-    exit 1
-  fi
-
-  _GO_LOG_FORMATTING='true'
   . "$_GO_USE_MODULES" 'log'
   _@go.log_init
 
@@ -65,24 +53,21 @@ format_log_label() {
 
 assert_log_equals() {
   set "$BATS_ASSERTION_DISABLE_SHELL_OPTIONS"
-  local level
-  local __padding=''
   local __log_level_label
   local expected=()
   local i
-  local result=0
 
-  . "$_GO_USE_MODULES" 'log'
-
-  for level in "${_GO_LOG_LEVELS[@]}"; do
-    while [[ "${#__padding}" -lt "${#level}" ]]; do
-      __padding+=' '
-    done
-  done
+  . "$_GO_USE_MODULES" 'format' 'log'
+  _@go.log_init
 
   for ((i=0; $# != 0; ++i)); do
     if __parse_log_level_label "$1"; then
-      expected+=("$(__expected_log_line "$__log_level_label" "$2")")
+      expected+=("$__log_level_label $2")
+
+      if [[ "${__log_level_label:0:1}" == $'\e' ]]; then
+        expected["$((${#expected[@]} - 1))"]+=$'\e[0m'
+      fi
+
       if ! shift 2; then
         echo "ERROR: Wrong number of arguments for log line $i." >&2
         return_from_bats_assertion 1
@@ -146,33 +131,21 @@ set_log_command_stack_trace_items() {
 # --------------------------------
 
 __parse_log_level_label() {
-  local level="$1"
-  local try_level="$level"
-  if [[ "${level:0:3}" == '\e[' ]]; then
-    try_level="${try_level//\\e\[[0-9]m}"
-    try_level="${try_level//\\e\[[0-9][0-9]m}"
-    try_level="${try_level//\\e\[[0-9][0-9][0-9]m}"
-    try_level="${try_level%% *}"
+  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
-  fi
-  __log_level_label="$level"
-
-  # If it's a label formatted with `format_label`, it's already padded.
-  if [[ "${level:0:3}" != '\e[' ]]; then
-    __log_level_label+="${__padding:0:$((${#__padding} - ${#try_level}))}"
-  fi
-}
-
-__expected_log_line() {
-  local level="$1"
-  local message="$2"
-
-  if [[ "${level:0:3}" == '\e[' ]]; then
-    printf '%b\n' "$level $message\e[0m"
+  elif [[ "$level_label" != "$try_level" ]]; then
+    __log_level_label="$level_label"
   else
-    printf '%b\n' "$level $message"
+    @go.strip_formatting_codes \
+      "${__GO_LOG_LEVELS_FORMATTED[$__go_log_level_index]}" __log_level_label
   fi
 }

tests/log/log-command.bats

@@ -115,9 +115,6 @@ teardown() {
 }
 
 @test "$SUITE: log failing command to standard error with formatting" {
-  local formatted_run_level_label="$(format_log_label RUN)"
-  local formatted_error_level_label="$(format_log_label ERROR)"
-
   _GO_LOG_FORMATTING='true' run_log_script \
       'function failing_function() {' \
       '  printf "%b\n" "\e[1m$*\e[0m" >&2' \
@@ -127,9 +124,9 @@ teardown() {
 
   assert_failure
   assert_log_equals \
-    "$formatted_run_level_label" 'failing_function foo bar baz' \
+    "$(format_log_label RUN)" 'failing_function foo bar baz' \
     "$(printf '%b' '\e[1mfoo bar baz\e[0m')" \
-    "$formatted_error_level_label" \
+    "$(format_log_label ERROR)" \
       'failing_function foo bar baz (exit status 127)'
   assert_log_file_equals "$TEST_LOG_FILE" "${lines[@]}"
 }

tests/log/main.bats

@@ -23,7 +23,7 @@ teardown() {
     'echo Goodbye, World!'
   assert_success
   assert_log_equals \
-    "$(format_log_label INFO)" '\e[1m\e[36mHello, World!' \
+    "$(format_log_label INFO)" "$(printf '%b' '\e[1m\e[36mHello, World!')" \
     'Goodbye, World!'
 }
 

tests/testing/log.bats

@@ -48,12 +48,6 @@ teardown() {
   assert_success "$expected_message"
 }
 
-@test "$SUITE: format_log_label exits if log module already initialized" {
-  __GO_LOG_INIT='true' run format_log_label INFO
-  assert_failure
-  assert_output_matches '^`format_log_label` must be called before any other '
-}
-
 @test "$SUITE: format_log_label exits if log level label invalid" {
   run format_log_label FOOBAR
   assert_failure 'Unknown log level label: FOOBAR'