Skip to content

Commit 0d5841b

Browse files
authored
Merge pull request #110 from mbland/log-test-helpers-#40
Extract `lib/testing/log`, refactor `lib/log` and `lib/bats/assertions`
2 parents 4b562d9 + 7a24d78 commit 0d5841b

File tree

15 files changed

+393
-205
lines changed

15 files changed

+393
-205
lines changed

lib/bats/assertions

Lines changed: 9 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -279,7 +279,7 @@ assert_output_matches() {
279279
local pattern="$1"
280280

281281
if [[ "$#" -ne 1 ]]; then
282-
echo "ERROR: ${FUNCNAME[0]} takes exactly one argument" >&2
282+
printf 'ERROR: %s takes exactly one argument\n' "${FUNCNAME[0]}" >&2
283283
return_from_bats_assertion '1'
284284
else
285285
assert_matches "$pattern" "$output" 'output'
@@ -568,20 +568,21 @@ __assert_lines() {
568568

569569
if [[ "$lines_diff" -gt '0' ]]; then
570570
if [[ "$lines_diff" -eq '1' ]]; then
571-
echo "There is one more line of output than expected:" >&2
571+
printf 'There is one more line of output than expected:\n' >&2
572572
else
573-
echo "There are $lines_diff more lines of output than expected:" >&2
573+
printf 'There are %d more lines of output than expected:\n' \
574+
"$lines_diff" >&2
574575
fi
575-
local IFS=$'\n'
576-
echo "${lines[*]:$num_lines}" >&2
576+
printf '%s\n' "${lines[@]:$num_lines}" >&2
577577
((++num_errors))
578578

579579
elif [[ "$lines_diff" -lt '0' ]]; then
580580
lines_diff="$((-lines_diff))"
581581
if [[ "$lines_diff" -eq '1' ]]; then
582-
echo "There is one fewer line of output than expected." >&2
582+
printf 'There is one fewer line of output than expected.\n' >&2
583583
else
584-
echo "There are $lines_diff fewer lines of output than expected." >&2
584+
printf 'There are %d fewer lines of output than expected.\n' \
585+
"$lines_diff" >&2
585586
fi
586587
((++num_errors))
587588
fi
@@ -610,7 +611,7 @@ __assert_file() {
610611

611612
if [[ "$assertion" == 'assert_matches' ]]; then
612613
if [[ "$#" -ne '1' ]]; then
613-
echo "ERROR: ${FUNCNAME[1]} takes exactly two arguments" >&2
614+
printf 'ERROR: %s takes exactly two arguments\n' "${FUNCNAME[1]}" >&2
614615
return '1'
615616
fi
616617
constraints=("$1" "$output" "The content of '$file_path'")

lib/log

Lines changed: 17 additions & 49 deletions
Original file line numberDiff line numberDiff line change
@@ -251,10 +251,10 @@ readonly __GO_LOG_COMMAND_EXIT_PATTERN='^@go.log_command (exit|fatal):([0-9]+)$'
251251

252252
local __go_log_timestamp
253253
if @go.log_timestamp; then
254-
log_msg="$__go_log_timestamp "
254+
__go_log_timestamp+=' '
255255
fi
256-
log_msg+="${__GO_LOG_LEVELS_FORMATTED[$__go_log_level_index]} "
257-
log_msg+="${args[*]}\\e[0m"
256+
printf -v log_msg -- '%s%s %b' "$__go_log_timestamp" \
257+
"${__GO_LOG_LEVELS_FORMATTED[$__go_log_level_index]}" "${args[*]}\\e[0m"
258258

259259
local __go_log_level_file_descriptors=('1')
260260
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]+)$'
271271
fi
272272
printf '%s\n' "$stripped_log_msg" >&"$level_fd"
273273
else
274-
printf '%b\n' "$log_msg" >&"$level_fd"
274+
printf '%s\n' "$log_msg" >&"$level_fd"
275275
fi
276276

277277
if [[ "$log_level" == 'FATAL' ]]; then
@@ -460,6 +460,7 @@ readonly __GO_LOG_COMMAND_EXIT_PATTERN='^@go.log_command (exit|fatal):([0-9]+)$'
460460
local __go_log_command_args=("$@")
461461
local cmd_string="${__go_log_command_args[*]}"
462462
local line
463+
local stripped_line
463464
local exit_state
464465
local exit_status=1
465466

@@ -482,6 +483,7 @@ readonly __GO_LOG_COMMAND_EXIT_PATTERN='^@go.log_command (exit|fatal):([0-9]+)$'
482483

483484
while IFS= read -r line; do
484485
line="${line%$'\r'}"
486+
stripped_line=''
485487

486488
if [[ "$line" =~ $__GO_LOG_COMMAND_EXIT_PATTERN ]]; then
487489
# 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]+)$'
497499

498500
for fd in "${__go_log_level_file_descriptors[@]}"; do
499501
if [[ -t "$fd" || -n "$_GO_LOG_FORMATTING" ]]; then
500-
printf '%b\n' "$line" >&"$fd"
501-
else
502502
printf '%s\n' "$line" >&"$fd"
503+
else
504+
if [[ -z "$stripped_line" ]]; then
505+
@go.strip_formatting_codes "$line" stripped_line
506+
fi
507+
printf '%s\n' "$stripped_line" >&"$fd"
503508
fi
504509
done
505510
done < <(_@go.log_command_invoke)
@@ -651,57 +656,20 @@ _@go.log_init() {
651656

652657
# Assigns formatted log level labels to __GO_LOG_LEVELS_FORMATTED.
653658
#
654-
# If `_GO_LOG_FORMATTING` is not empty, or the file descriptor corresponding to
655-
# a log level corresponds to a terminal, this will assign a corresponding value
656-
# wrapped by terminal formatting codes to __GO_LOG_LEVELS_FORMATTED. Otherwise
657-
# the original label value is assigned.
658-
#
659659
# Each element of `__GO_LOG_LEVELS_FORMATTED` will also be padded with trailing
660660
# spaces so that each element will be the same length.
661661
#
662662
# Globals:
663663
# _GO_LOG_LEVELS: List of valid log level labels
664-
# _GO_LOG_FORMATTING If set, always produce formatted labels
665664
# __GO_LOG_LEVELS_FORMAT_CODES: Terminal format codes for each log level
666-
# __GO_LOG_LEVELS_FILE_DESCRIPTORS: Output descriptors for each log level
667665
# __GO_LOG_LEVELS_FORMATTED: Formatted labels
668666
_@go.log_format_level_labels() {
669-
local num_levels="${#_GO_LOG_LEVELS[@]}"
670-
local label_length
671-
local longest_label_length
672-
local padding=''
673-
local log_level
674-
local padding_len
675-
local level_var
676-
local level_fd
677-
local i
678-
679-
for ((i=0; i != num_levels; ++i)); do
680-
label_length="${#_GO_LOG_LEVELS[$i]}"
681-
if [[ "$label_length" -gt "$longest_label_length" ]]; then
682-
longest_label_length="$label_length"
683-
fi
684-
done
685-
686-
for ((i=0; i != longest_label_length; ++i)); do
687-
padding+=' '
688-
done
689-
690-
for ((i=0; i != num_levels; ++i)); do
691-
log_level="${_GO_LOG_LEVELS[$i]}"
692-
padding_len="$((${#padding} - ${#log_level}))"
693-
694-
local __go_log_level_file_descriptors=()
695-
_@go.log_level_file_descriptors "$i"
696-
697-
for level_fd in "${__go_log_level_file_descriptors[@]}"; do
698-
if [[ -n "$_GO_LOG_FORMATTING" || -t "$level_fd" ]]; then
699-
log_level="${__GO_LOG_LEVELS_FORMAT_CODES[$i]}$log_level\e[0m"
700-
break
701-
fi
702-
done
703-
__GO_LOG_LEVELS_FORMATTED[$i]="${log_level}${padding:0:$padding_len}"
704-
done
667+
__GO_LOG_LEVELS_FORMATTED=("${_GO_LOG_LEVELS[@]/%/\\e[0m}")
668+
@go.pad_items __GO_LOG_LEVELS_FORMATTED "${__GO_LOG_LEVELS_FORMATTED[@]}"
669+
@go.zip_items __GO_LOG_LEVELS_FORMAT_CODES __GO_LOG_LEVELS_FORMATTED '' \
670+
__GO_LOG_LEVELS_FORMATTED
671+
@go.array_printf __GO_LOG_LEVELS_FORMATTED '%b' \
672+
"${__GO_LOG_LEVELS_FORMATTED[@]}"
705673
}
706674

707675
# Returns the set of file descriptors for the specified log level index.

lib/testing/environment

Lines changed: 13 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -62,6 +62,19 @@ create_test_go_script() {
6262
fi
6363
}
6464

65+
# Sets `_GO_CMD` to make for neater test output when running `TEST_GO_SCRIPT`
66+
#
67+
# Use `run test-go` instead of `run "$TEST_GO_SCRIPT"` to achieve the effect.
68+
#
69+
# Useful for tests that contain `_GO_CMD` in the output, to avoid clouding the
70+
# output with the full `TEST_GO_SCRIPT` path.
71+
#
72+
# Arguments:
73+
# ...: Command line arguments for `TEST_GO_SCRIPT`
74+
test-go() {
75+
_GO_CMD="$FUNCNAME" "$TEST_GO_SCRIPT" "$@"
76+
}
77+
6578
# Creates an executable `./go` command script in `TEST_GO_SCRIPTS_DIR`
6679
#
6780
# The script will be created as `$TEST_GO_SCRIPTS_DIR/$script_name`.

lib/testing/log

Lines changed: 181 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -5,7 +5,152 @@
55
# You must source `_GO_CORE_DIR/lib/testing/environment` before this file.
66

77
. "${BASH_SOURCE[0]%/*}/stack-trace"
8+
. "$_GO_CORE_DIR/lib/bats/assertions"
89

10+
# Log timestamps are disabled by for testing by default.
11+
export _GO_LOG_TIMESTAMP_FORMAT=
12+
13+
# Creates a `./go` script that imports the `log` module
14+
#
15+
# If `TEST_LOG_FILE` is defined, it will add that file for logging output as
16+
# well.
17+
#
18+
# Globals:
19+
# TEST_LOG_FILE: (Optional) Path to the log file to add for all log levels
20+
#
21+
# Arguments:
22+
# ...: Lines comprising the `./go` script
23+
create_log_script(){
24+
create_test_go_script \
25+
". \"\$_GO_USE_MODULES\" 'log'" \
26+
'if [[ -n "$TEST_LOG_FILE" ]]; then' \
27+
' @go.log_add_output_file "$TEST_LOG_FILE"' \
28+
'fi' \
29+
"$@"
30+
}
31+
32+
# Creates and executes a `./go` script that imports the `log` module
33+
#
34+
# Globals and arguments are identical to `create_log_script`.
35+
run_log_script() {
36+
create_log_script "$@"
37+
run "$TEST_GO_SCRIPT"
38+
}
39+
40+
# Format a `log` module log level label
41+
#
42+
# Arguments:
43+
# label: Log level label to format
44+
format_log_label() {
45+
local label="$1"
46+
47+
. "$_GO_USE_MODULES" 'log'
48+
_@go.log_init
49+
50+
local __go_log_level_index=0
51+
if ! _@go.log_level_index "$label"; then
52+
printf 'Unknown log level label: %s\n' "$label" >&2
53+
exit 1
54+
fi
55+
printf '%s' "${__GO_LOG_LEVELS_FORMATTED[$__go_log_level_index]}"
56+
}
57+
58+
# Validates that `output` matches the expected `@go.log` output
59+
#
60+
# Each line can be expressed one of two ways:
61+
# - As a pair of strings: first the log level label, then the log message
62+
# - As a single string without a log level label prefix
63+
#
64+
# Each log level label must exist within `_GO_LOG_LEVELS`, and can be either a
65+
# plaintext label or a label formatted with `format_log_label`. Any unknown
66+
# labels will be parsed as "a single string without a log label prefix".
67+
#
68+
# If you aren't looking for exact log output, consider using one of the standard
69+
# assertions from `_GO_CORE_DIR/lib/bats/assertions` instead.
70+
#
71+
# Note that this does NOT handle timestamps. If you wish to validate specific
72+
# timestamps, see `_GO_CORE_DIR/tests/log/timestamp.bats` for ideas.
73+
#
74+
# Arguments:
75+
# ...: Lines of expected log output
76+
assert_log_equals() {
77+
set "$BATS_ASSERTION_DISABLE_SHELL_OPTIONS"
78+
local __log_level_label
79+
local expected=()
80+
local i
81+
82+
. "$_GO_USE_MODULES" 'format' 'log'
83+
_@go.log_init
84+
85+
for ((i=0; $# != 0; ++i)); do
86+
if __parse_log_level_label "$1"; then
87+
expected+=("$__log_level_label $2")
88+
89+
if [[ "${__log_level_label:0:1}" == $'\e' ]]; then
90+
expected["$((${#expected[@]} - 1))"]+=$'\e[0m'
91+
fi
92+
93+
if ! shift 2; then
94+
printf 'ERROR: Wrong number of arguments for log line %d.\n' "$i" >&2
95+
return_from_bats_assertion 1
96+
return
97+
fi
98+
else
99+
expected+=("$1")
100+
shift
101+
fi
102+
done
103+
104+
if ! assert_lines_equal "${expected[@]}"; then
105+
return_from_bats_assertion '1'
106+
else
107+
return_from_bats_assertion
108+
fi
109+
}
110+
111+
# Validates that a file matches the expected `@go.log` output
112+
#
113+
# Aside from the first file path argument, the remaining arguments and semantics
114+
# are exactly the same as `assert_log_equals`.
115+
#
116+
# In cases where `@go.log_add_output_file` is used to add a `TEST_LOG_FILE` to
117+
# all levels, and all test output comes from `@go.log`, this may be invoked
118+
# following `assert_log_equals` like so to ensure the log file output matches
119+
# standard output and standard error:
120+
#
121+
# assert_log_file_equals "$TEST_LOG_FILE" "${lines[@]}"
122+
#
123+
# If you aren't looking for exact log output, consider using one of the standard
124+
# assertions from `_GO_CORE_DIR/lib/bats/assertions` instead.
125+
#
126+
# Arguments:
127+
# log_file: Path to the log file to validate
128+
# ...: Lines of expected log output
129+
assert_log_file_equals() {
130+
set "$BATS_ASSERTION_DISABLE_SHELL_OPTIONS"
131+
local log_file="$1"
132+
shift
133+
134+
if ! set_bats_output_and_lines_from_file "$log_file"; then
135+
return_from_bats_assertion '1'
136+
else
137+
assert_log_equals "$@"
138+
return_from_bats_assertion "$?"
139+
fi
140+
}
141+
142+
# Creates `LOG_COMMAND_STACK_TRACE_ITEMS` to help validate stack trace output.
143+
#
144+
# Call this before using "${LOG_COMMAND_STACK_TRACE_ITEMS[@]}" to inject
145+
# entries from `@go.log_command` into your expected stack trace output. This
146+
# helps validate stack trace output generated by logged commands, and ensures
147+
# that your stack trace validation stays up-to-date even when the internal
148+
# structure of `lib/log` changes.
149+
#
150+
# Globals:
151+
# LOG_COMMAND_STACK_TRACE_ITEMS:
152+
# Stack trace lines from `@go.log_command` comprising the command logging
153+
# mechanism
9154
set_log_command_stack_trace_items() {
10155
if [[ "${#LOG_COMMAND_STACK_TRACE_ITEMS[@]}" -eq '0' ]]; then
11156
export LOG_COMMAND_STACK_TRACE_ITEMS
@@ -18,3 +163,39 @@ set_log_command_stack_trace_items() {
18163
"$(stack_trace_item "$_GO_CORE_DIR/lib/log" '@go.log_command')")
19164
fi
20165
}
166+
167+
# --------------------------------
168+
# IMPLEMENTATION - HERE BE DRAGONS
169+
#
170+
# None of the functions below this line are part of the public interface.
171+
# --------------------------------
172+
173+
# Determines whether a log level label is a valid member of `_GO_LOG_LEVELS`.
174+
#
175+
# If so, pads the label and assigns it to `__log_level_label`.
176+
#
177+
# Arguments:
178+
# level_label: Log level label to examine
179+
#
180+
# Returns:
181+
# zero if `level_label` exists in `_GO_LOG_LEVELS`, nonzero otherwise
182+
# __log_level_label: Assigned the padded version of `level_label` if valid
183+
__parse_log_level_label() {
184+
local level_label="$1"
185+
local try_level
186+
local __go_log_level_index
187+
188+
@go.strip_formatting_codes "$level_label" 'try_level'
189+
if [[ "$try_level" =~ \ +$ ]]; then
190+
try_level="${try_level%${BASH_REMATCH[0]}}"
191+
fi
192+
193+
if ! _@go.log_level_index "$try_level"; then
194+
return 1
195+
elif [[ "$level_label" != "$try_level" ]]; then
196+
__log_level_label="$level_label"
197+
else
198+
@go.strip_formatting_codes \
199+
"${__GO_LOG_LEVELS_FORMATTED[$__go_log_level_index]}" __log_level_label
200+
fi
201+
}

tests/log/add-output-file.bats

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -1,7 +1,7 @@
11
#! /usr/bin/env bats
22

33
load ../environment
4-
load helpers
4+
load "$_GO_CORE_DIR/lib/testing/log"
55

66
teardown() {
77
remove_test_go_rootdir
@@ -66,7 +66,7 @@ run_log_script_and_assert_status_and_output() {
6666
"@go.log_add_output_file '$TEST_GO_ROOTDIR/info.log' 'INFO'" \
6767
"@go.log INFO Hello, World!"
6868
assert_success
69-
assert_log_equals "$(format_label INFO)" 'Hello, World!'
69+
assert_log_equals "$(format_log_label INFO)" 'Hello, World!'
7070
assert_file_equals "$TEST_GO_ROOTDIR/info.log" "${lines[@]}"
7171
}
7272

0 commit comments

Comments
 (0)