diff --git a/lib/bats/assertions b/lib/bats/assertions index dbfbd3e..1f0c1d8 100644 --- a/lib/bats/assertions +++ b/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'") diff --git a/lib/log b/lib/log index 191f861..793a9a0 100644 --- a/lib/log +++ b/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. diff --git a/lib/testing/environment b/lib/testing/environment index e52a949..315f406 100644 --- a/lib/testing/environment +++ b/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`. diff --git a/lib/testing/log b/lib/testing/log index b3bb6c8..ba11dbe 100644 --- a/lib/testing/log +++ b/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 +} diff --git a/tests/log/add-output-file.bats b/tests/log/add-output-file.bats index f0155ab..4d57104 100644 --- a/tests/log/add-output-file.bats +++ b/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[@]}" } diff --git a/tests/log/add-update.bats b/tests/log/add-update.bats index e3268dc..92109c2 100644 --- a/tests/log/add-update.bats +++ b/tests/log/add-update.bats @@ -1,7 +1,7 @@ #! /usr/bin/env bats load ../environment -load helpers +load "$_GO_CORE_DIR/lib/testing/log" INFO_FORMAT='\e[1m\e[36m' START_FORMAT='\e[1m\e[32m' diff --git a/tests/log/filters.bats b/tests/log/filters.bats index e833c0a..6d4248a 100644 --- a/tests/log/filters.bats +++ b/tests/log/filters.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 diff --git a/tests/log/helpers.bash b/tests/log/helpers.bash deleted file mode 100644 index a9a447a..0000000 --- a/tests/log/helpers.bash +++ /dev/null @@ -1,132 +0,0 @@ -#! /bin/bash -# -# Helper functions for `lib/log` tests. - -load "$_GO_CORE_DIR/lib/testing/log" - -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' \ - "$@" -} - -run_log_script() { - create_log_script "$@" - run "$TEST_GO_SCRIPT" -} - -# For tests that run command scripts via @go, set _GO_CMD to make sure that's -# the variable included in the log. -test-go() { - env _GO_CMD="$FUNCNAME" "$TEST_GO_SCRIPT" "$@" -} - -# Note that this must be called before any other log assertion, because it needs -# to set _GO_LOG_FORMATTING before importing the `log` module. -format_label() { - local label="$1" - - if [[ -n "$__GO_LOG_INIT" ]]; then - echo "$FUNCNAME must be called before any other function or assertion" \ - "that calls \`. \$_GO_USE_MODULES 'log'\` because it needs to set" \ - "\`_GO_LOG_FORMATTING\`." >&2 - return 1 - fi - - _GO_LOG_FORMATTING='true' - . "$_GO_USE_MODULES" 'log' - _@go.log_init - - local __go_log_level_index=0 - if ! _@go.log_level_index "$label"; then - echo "Unknown log level label: $label" >&2 - return 1 - fi - echo "${__GO_LOG_LEVELS_FORMATTED[$__go_log_level_index]}" -} - -__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%% *}" - 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" - else - printf '%b\n' "$level $message" - fi -} - -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 - - for ((i=0; $# != 0; ++i)); do - if __parse_log_level_label "$1"; then - expected+=("$(__expected_log_line "$__log_level_label" "$2")") - if ! shift 2; then - echo "ERROR: Wrong number of arguments for log line $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 -} - -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 -} diff --git a/tests/log/log-command.bats b/tests/log/log-command.bats index 4824877..3b95b4d 100644 --- a/tests/log/log-command.bats +++ b/tests/log/log-command.bats @@ -1,7 +1,7 @@ #! /usr/bin/env bats load ../environment -load helpers +load "$_GO_CORE_DIR/lib/testing/log" setup() { test_filter @@ -101,7 +101,7 @@ teardown() { @test "$SUITE: log single failing command to standard error" { run_log_script \ 'function failing_function() {' \ - ' printf "%s\n" "\e[1m$*\e[0m" >&2' \ + ' printf "%b\n" "\e[1m$*\e[0m" >&2' \ ' exit 127' \ '}' \ '@go.log_command failing_function foo bar baz' @@ -109,27 +109,24 @@ teardown() { assert_failure assert_log_equals \ RUN 'failing_function foo bar baz' \ - '\e[1mfoo bar baz\e[0m' \ + 'foo bar baz' \ ERROR 'failing_function foo bar baz (exit status 127)' assert_log_file_equals "$TEST_LOG_FILE" "${lines[@]}" } @test "$SUITE: log failing command to standard error with formatting" { - local formatted_run_level_label="$(format_label RUN)" - local formatted_error_level_label="$(format_label ERROR)" - _GO_LOG_FORMATTING='true' run_log_script \ 'function failing_function() {' \ - ' printf "%s\n" "\e[1m$*\e[0m" >&2' \ + ' printf "%b\n" "\e[1m$*\e[0m" >&2' \ ' exit 127' \ '}' \ '@go.log_command failing_function foo bar baz' 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[@]}" } diff --git a/tests/log/main.bats b/tests/log/main.bats index 76ed3ed..9fa5dde 100644 --- a/tests/log/main.bats +++ b/tests/log/main.bats @@ -1,7 +1,7 @@ #! /usr/bin/env bats load ../environment -load helpers +load "$_GO_CORE_DIR/lib/testing/log" setup() { test_filter @@ -23,7 +23,7 @@ teardown() { 'echo Goodbye, World!' assert_success assert_log_equals \ - "$(format_label INFO)" '\e[1m\e[36mHello, World!' \ + "$(format_log_label INFO)" "$(printf '%b' '\e[1m\e[36mHello, World!')" \ 'Goodbye, World!' } diff --git a/tests/log/setup-project.bats b/tests/log/setup-project.bats index 6608f91..0bac75a 100644 --- a/tests/log/setup-project.bats +++ b/tests/log/setup-project.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 diff --git a/tests/log/timestamp.bats b/tests/log/timestamp.bats index fba1eda..951ca0d 100644 --- a/tests/log/timestamp.bats +++ b/tests/log/timestamp.bats @@ -1,6 +1,7 @@ #! /usr/bin/env bats load ../environment +load "$_GO_CORE_DIR/lib/testing/log" HAS_TIMESTAMP_BUILTIN= DATE_CMD= diff --git a/tests/testing/environment.bats b/tests/testing/environment.bats index ab5ef9c..60ddc47 100644 --- a/tests/testing/environment.bats +++ b/tests/testing/environment.bats @@ -87,3 +87,9 @@ teardown() { [ -x "$TEST_GO_SCRIPTS_DIR/foo.d/bar.d/xyzzy" ] [ -x "$TEST_GO_SCRIPTS_DIR/foo.d/bar.d/plugh" ] } + +@test "$SUITE: run TEST_GO_SCRIPT via test-go" { + create_test_go_script 'printf "_GO_CMD: %s\n" "$_GO_CMD"' + run test-go + assert_success '_GO_CMD: test-go' +} diff --git a/tests/testing/log.bats b/tests/testing/log.bats index 6c7634e..99bddc7 100644 --- a/tests/testing/log.bats +++ b/tests/testing/log.bats @@ -11,6 +11,30 @@ teardown() { remove_test_go_rootdir } +@test "$SUITE: log timestamps are disabled for testing by default" { + assert_equal '' "$_GO_LOG_TIMESTAMP_FORMAT" + _GO_LOG_TIMESTAMP_FORMAT='%Y:%m:%d %H:%M:%S' + . "$_GO_CORE_DIR/lib/testing/log" + assert_equal '' "$_GO_LOG_TIMESTAMP_FORMAT" +} + +@test "$SUITE: create_log_script and run_log_script without log file" { + export TEST_LOG_FILE="$TEST_GO_ROOTDIR/test-script.log" + TEST_LOG_FILE= run_log_script '@go.log INFO Hello, World!' + assert_success + assert_output_matches '^INFO +Hello, World!$' + [ ! -e "$TEST_LOG_FILE" ] +} + +@test "$SUITE: create_log_script and run_log_script with log file" { + export TEST_LOG_FILE="$TEST_GO_ROOTDIR/test-script.log" + run_log_script '@go.log INFO Hello, World!' + assert_success + assert_output_matches '^INFO +Hello, World!$' + [ -e "$TEST_LOG_FILE" ] + assert_file_matches "$TEST_LOG_FILE" '^INFO +Hello, World!$' +} + @test "$SUITE: set_log_command_stack_trace_items" { assert_equal '' "${LOG_COMMAND_STACK_TRACE_ITEMS[*]}" set_log_command_stack_trace_items @@ -19,3 +43,19 @@ teardown() { "^ $_GO_CORE_DIR/lib/log:[0-9]+ _@go.log_command_invoke$" \ "^ $_GO_CORE_DIR/lib/log:[0-9]+ @go.log_command$" } + +@test "$SUITE: format_log_label" { + run format_log_label INFO + assert_success + + local expected_message + printf -v expected_message '%b' "$output Hello, World!\e[0m" + + _GO_LOG_FORMATTING='true' run_log_script '@go.log INFO Hello, World!' + assert_success "$expected_message" +} + +@test "$SUITE: format_log_label exits if log level label invalid" { + run format_log_label FOOBAR + assert_failure 'Unknown log level label: FOOBAR' +} diff --git a/tests/testing/log/assertions.bats b/tests/testing/log/assertions.bats new file mode 100644 index 0000000..5c817ba --- /dev/null +++ b/tests/testing/log/assertions.bats @@ -0,0 +1,113 @@ +#! /usr/bin/env bats + +load ../../environment + +ASSERTION_SOURCE="$_GO_CORE_DIR/lib/testing/log" +load "$_GO_CORE_DIR/lib/bats/assertion-test-helpers" + +setup() { + test_filter + mkdir -p "$TEST_GO_ROOTDIR" +} + +teardown() { + remove_test_go_rootdir +} + +@test "$SUITE: assert_log_equals empty output" { + expect_assertion_success ':' 'assert_log_equals' +} + +@test "$SUITE: assert_log_equals single non-@go.log line" { + expect_assertion_success 'printf "Hello, World!\n"' \ + 'assert_log_equals "Hello, World!"' +} + +@test "$SUITE: assert_log_equals single @go.log line" { + create_log_script '@go.log INFO Hello, World!' + expect_assertion_success "'$TEST_GO_SCRIPT'" \ + 'assert_log_equals INFO "Hello, World!"' +} + +@test "$SUITE: assert_log_equals single formatted @go.log line" { + create_log_script '@go.log INFO Hello, World!' + _GO_LOG_FORMATTING='true' expect_assertion_success "'$TEST_GO_SCRIPT'" \ + "assert_log_equals \"\$(format_log_label INFO)\" 'Hello, World!'" +} + +@test "$SUITE: assert_log_equals multiple mixed lines" { + create_log_script '@go.log INFO Hello, World!' \ + 'printf "%s\n" "Not a @go.log line."' \ + '@go.log WARN Goodbye, World!' \ + 'printf "%s\n" "Also not a @go.log line."' + + local args=("'INFO' 'Hello, World!'" + "'Not a @go.log line.'" + "'WARN' 'Goodbye, World!'" + "'Also not a @go.log line.'") + expect_assertion_success "'$TEST_GO_SCRIPT'" \ + "assert_log_equals ${args[*]}" +} + +@test "$SUITE: assert_log_equals multiple mixed lines with formatting" { + create_log_script '@go.log INFO Hello, World!' \ + 'printf "%s\n" "Not a @go.log line."' \ + '@go.log WARN Goodbye, World!' \ + 'printf "%s\n" "Also not a @go.log line."' + + local args=("\"\$(format_log_label INFO)\" 'Hello, World!'" + "'Not a @go.log line.'" + "\"\$(format_log_label WARN)\" 'Goodbye, World!'" + "'Also not a @go.log line.'") + _GO_LOG_FORMATTING='true' expect_assertion_success "'$TEST_GO_SCRIPT'" \ + "assert_log_equals ${args[*]}" +} + +@test "$SUITE: assert_log_equals error if wrong number of log line args" { + create_log_script '@go.log INFO Hello, World!' + expect_assertion_failure "'$TEST_GO_SCRIPT'" \ + "assert_log_equals 'INFO' 'Hello, World!' 'INFO'" \ + 'ERROR: Wrong number of arguments for log line 1.' +} + +@test "$SUITE: assert_log_equals fails if line doesn't match" { + local info_label="$(format_log_label INFO)" + local end_format_code="$(printf '%b' '\e[0m')" + + create_log_script '@go.log INFO Goodbye, World!' + _GO_LOG_FORMATTING='true' expect_assertion_failure "'$TEST_GO_SCRIPT'" \ + "assert_log_equals \"\$(format_log_label INFO)\" 'Hello, World!'" \ + 'line 0 not equal to expected value:' \ + " expected: '$info_label Hello, World!$end_format_code'" \ + " actual: '$info_label Goodbye, World!$end_format_code'" \ + 'OUTPUT:' \ + "$info_label Goodbye, World!$end_format_code" +} + +@test "$SUITE: assert_log_file_equals returns error if file doesn't exist" { + expect_assertion_failure ':' "assert_log_file_equals 'nonexistent.log'" \ + "'nonexistent.log' doesn't exist or isn't a regular file." +} + +@test "$SUITE: assert_log_file_equals empty output" { + expect_assertion_success "printf '' >'$TEST_GO_ROOTDIR/empty.log'" \ + "assert_log_file_equals '$TEST_GO_ROOTDIR/empty.log'" +} + +@test "$SUITE: assert_log_file_equals multiple mixed lines with formatting" { + export TEST_LOG_FILE="$TEST_GO_ROOTDIR/test.log" + + # We need to clear the `TEST_LOG_FILE` between the two runs performed by + # `expect_assertion_success`, since `@go.log` will append to the file. + create_log_script "printf '' >'$TEST_LOG_FILE'" \ + '@go.log INFO Hello, World!' \ + 'printf "%s\n" "Not a @go.log line."' \ + '@go.log WARN Goodbye, World!' \ + 'printf "%s\n" "Also not a @go.log line."' + + # Note that the file should only get the `@go.log` lines. + local args=("\"\$(format_log_label INFO)\" 'Hello, World!'" + "\"\$(format_log_label WARN)\" 'Goodbye, World!'") + _GO_LOG_FORMATTING='true' expect_assertion_success "'$TEST_GO_SCRIPT'" \ + "assert_log_file_equals \"\$TEST_LOG_FILE\" ${args[*]}" +}