diff --git a/CHANGELOG.md b/CHANGELOG.md index 93526da9..ad381de6 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -3,6 +3,7 @@ ## Unreleased ### Added +- A failed call assertion now prints the calls recorded for that spy, capped at 10 with an explicit `… and N more` (#896) - `assert_have_been_called_with_args ...`: compares the recorded arguments one by one, so `cmd "a b"` no longer matches `cmd a b` (#894) - `BASHUNIT_COVERAGE_ENGINE=auto|xtrace|trap`: a new `xtrace` coverage engine, ~4x cheaper per captured line. Needs Bash 4.1+, so `auto` (the default) falls back to `trap` below that (#860) - `BASHUNIT_COVERAGE_SHOW_LINE_HITS=true` prints per-line execution counts in the text coverage report (#856) diff --git a/docs/ai-agents.md b/docs/ai-agents.md index 04941214..d0bf5c27 100644 --- a/docs/ai-agents.md +++ b/docs/ai-agents.md @@ -114,6 +114,8 @@ actually make against this API: - Spy assertion argument order is inconsistent — check, don't guess: `assert_have_been_called_times ` but `assert_have_been_called_with [call_index]`. +- A failed call assertion prints the spy's recorded calls under the diff — read that block + before guessing why it failed, it is usually enough to fix the test in one pass. - A call assertion on a name that was never passed to `bashunit::spy` fails with `was never registered as a spy`. Spies do not survive across tests, so register the spy inside the test that asserts on it. diff --git a/docs/test-doubles.md b/docs/test-doubles.md index fbf1be6f..333cd14a 100644 --- a/docs/test-doubles.md +++ b/docs/test-doubles.md @@ -127,6 +127,21 @@ function test_example() { ``` ::: +::: tip Failures list the recorded calls +When a call assertion fails, the recorded calls are printed below the failure, so you can tell "called with other arguments" from "called in another order" or "called more often than expected" without re-running: + +``` +✗ Failed: My test + Expected 'first' + but got 'second' + Recorded calls to 'touch' (2): + 1: first + 2: second +``` + +Long logs stop after 10 entries and end with `… and N more`. +::: + ::: tip Call assertions require a registered spy Every `assert_have_been_called*` / `assert_not_called` assertion fails when the name it targets was never passed to `bashunit::spy` — or was removed by `bashunit::unmock`, or belongs to a previous test: diff --git a/src/console_results.sh b/src/console_results.sh index 45348949..f0ebc1d2 100644 --- a/src/console_results.sh +++ b/src/console_results.sh @@ -335,6 +335,9 @@ function bashunit::console_results::print_failed_test() { local actual=$4 local extra_key=${5-} local extra_value=${6-} + # Free-form block appended verbatim below the failure (already indented by the + # caller). The spy assertions use it to dump the recorded call log. + local details=${7-} # For multiline values, render a unified diff below the header (git required, # opt out with BASHUNIT_NO_DIFF). Single-line output stays byte-identical. @@ -379,6 +382,11 @@ $(bashunit::console_results::render_diff "$_expected_file" "$_actual_file")" "${extra_key}" "${extra_value}")" fi + if [ -n "$details" ]; then + line="$line +$details" + fi + line="$line$(bashunit::console_results::test_location_suffix)" bashunit::console_results::print_line "failed" "$line" diff --git a/src/test_doubles.sh b/src/test_doubles.sh index e73ddc88..a53e53ea 100644 --- a/src/test_doubles.sh +++ b/src/test_doubles.sh @@ -29,6 +29,61 @@ function bashunit::spy::times_to_slot() { fi } +_BASHUNIT_SPY_CALL_LOG_MAX=10 +_BASHUNIT_SPY_CALL_LOG_OUT="" + +# Renders the calls recorded for $1 into _BASHUNIT_SPY_CALL_LOG_OUT, one per +# line, capped at _BASHUNIT_SPY_CALL_LOG_MAX with an explicit "and N more". +# Empty when $1 is not a spy or was never called. Failure path only: reading the +# params file on every assertion would break the per-test fork budget. +# Arguments: $1 - command, $2 - "raw" (space-joined, default) or "args" +# (per-argument, boundaries kept) +function bashunit::spy::call_log_to_slot() { + local command=$1 + local field=${2:-raw} + _BASHUNIT_SPY_CALL_LOG_OUT="" + + local variable + variable="$(bashunit::helper::normalize_variable_name "$command")" + local file_var="_BASHUNIT_SPY_${variable}_PARAMS_FILE" + if [ -z "${!file_var-}" ] || [ ! -f "${!file_var}" ]; then + return + fi + + local entries="" + local total=0 + local shown=0 + local line value + while IFS= read -r line; do + total=$((total + 1)) + if [ "$shown" -lt "$_BASHUNIT_SPY_CALL_LOG_MAX" ]; then + if [ "$field" = args ]; then + value=${line#*$'\x1e'} + value=${value//$'\x1f'/ } + else + value=${line%%$'\x1e'*} + fi + entries="$entries + ${_BASHUNIT_COLOR_FAINT}${total}:${_BASHUNIT_COLOR_DEFAULT} ${value}" + shown=$((shown + 1)) + fi + done <"${!file_var}" + + if [ "$total" -eq 0 ]; then + return + fi + + _BASHUNIT_SPY_CALL_LOG_OUT="\ + ${_BASHUNIT_COLOR_FAINT}Recorded calls to '${command}' (${total}):\ +${_BASHUNIT_COLOR_DEFAULT}${entries}" + + local remaining=$((total - shown)) + if [ "$remaining" -gt 0 ]; then + _BASHUNIT_SPY_CALL_LOG_OUT="$_BASHUNIT_SPY_CALL_LOG_OUT + ${_BASHUNIT_COLOR_FAINT}… and ${remaining} more${_BASHUNIT_COLOR_DEFAULT}" + fi +} + # Fails the calling assertion because $1 is not a registered spy. Reporting # "never called" for a name that was never spied — a typo, or a spy that was # unmocked — makes the assertion vacuous while still printing green. @@ -160,7 +215,9 @@ function assert_have_been_called() { if [ "$times" -eq 0 ]; then bashunit::state::add_assertions_failed - bashunit::console_results::print_failed_test "${label}" "${command}" "to have been called" "once" + bashunit::spy::call_log_to_slot "$command" + bashunit::console_results::print_failed_test "${label}" "${command}" "to have been called" "once" \ + "" "" "$_BASHUNIT_SPY_CALL_LOG_OUT" return fi @@ -209,7 +266,9 @@ function assert_have_been_called_with() { if [ "$expected" != "$raw" ]; then bashunit::state::add_assertions_failed - bashunit::console_results::print_failed_test "$label" "$expected" "but got " "$raw" + bashunit::spy::call_log_to_slot "$command" + bashunit::console_results::print_failed_test "$label" "$expected" "but got " "$raw" \ + "" "" "$_BASHUNIT_SPY_CALL_LOG_OUT" return fi @@ -244,8 +303,10 @@ function assert_have_been_called_with_args() { if [ "$expected" != "$actual" ]; then bashunit::state::add_assertions_failed + bashunit::spy::call_log_to_slot "$command" args bashunit::console_results::print_failed_test "$label" \ - "${expected//$'\x1f'/ }" "but got " "${actual//$'\x1f'/ }" + "${expected//$'\x1f'/ }" "but got " "${actual//$'\x1f'/ }" \ + "" "" "$_BASHUNIT_SPY_CALL_LOG_OUT" return fi @@ -266,9 +327,10 @@ function assert_have_been_called_times() { if [ "$times" -ne "$expected_count" ]; then bashunit::state::add_assertions_failed + bashunit::spy::call_log_to_slot "$command" bashunit::console_results::print_failed_test "${label}" "${command}" \ "to have been called" "${expected_count} times" \ - "actual" "${times} times" + "actual" "${times} times" "$_BASHUNIT_SPY_CALL_LOG_OUT" return fi @@ -297,8 +359,10 @@ function assert_have_been_called_nth_with() { if [ "$nth" -gt "$times" ]; then bashunit::state::add_assertions_failed + bashunit::spy::call_log_to_slot "$command" bashunit::console_results::print_failed_test "${label}" \ - "expected call" "at index ${nth} but" "only called ${times} times" + "expected call" "at index ${nth} but" "only called ${times} times" \ + "" "" "$_BASHUNIT_SPY_CALL_LOG_OUT" return fi @@ -312,8 +376,9 @@ function assert_have_been_called_nth_with() { if [ "$expected" != "$raw" ]; then bashunit::state::add_assertions_failed + bashunit::spy::call_log_to_slot "$command" bashunit::console_results::print_failed_test "${label}" \ - "$expected" "but got " "$raw" + "$expected" "but got " "$raw" "" "" "$_BASHUNIT_SPY_CALL_LOG_OUT" return fi diff --git a/tests/functional/doubles_test.sh b/tests/functional/doubles_test.sh index f4128314..6b4cb5de 100644 --- a/tests/functional/doubles_test.sh +++ b/tests/functional/doubles_test.sh @@ -120,10 +120,12 @@ function test_spy_call_with_args_detects_wrong_argument_boundaries() { spy_boundary_command "a b" + bashunit::spy::call_log_to_slot spy_boundary_command args + assert_same \ "$(bashunit::console_results::print_failed_test \ "Spy call with args detects wrong argument boundaries" \ - "a b" "but got " "a\\ b")" \ + "a b" "but got " "a\\ b" "" "" "$_BASHUNIT_SPY_CALL_LOG_OUT")" \ "$(assert_have_been_called_with_args spy_boundary_command "a" "b")" } @@ -169,6 +171,42 @@ function test_assert_not_called_still_passes_on_a_registered_spy() { assert_empty "$(assert_have_been_called_times 0 spy_never_invoked)" } +function test_failed_call_assertions_dump_the_recorded_calls() { + bashunit::spy spy_with_a_call_log + + spy_with_a_call_log first + spy_with_a_call_log second + + bashunit::spy::call_log_to_slot spy_with_a_call_log + local log=$_BASHUNIT_SPY_CALL_LOG_OUT + local label="Failed call assertions dump the recorded calls" + + assert_same \ + "$(bashunit::console_results::print_failed_test "$label" \ + "first" "but got " "second" "" "" "$log")" \ + "$(assert_have_been_called_with spy_with_a_call_log "first")" + + assert_same \ + "$(bashunit::console_results::print_failed_test "$label" \ + "spy_with_a_call_log" "to have been called" "0 times" "actual" "2 times" "$log")" \ + "$(assert_not_called spy_with_a_call_log)" + + assert_same \ + "$(bashunit::console_results::print_failed_test "$label" \ + "first" "but got " "second" "" "" "$log")" \ + "$(assert_have_been_called_nth_with 2 spy_with_a_call_log "first")" +} + +function test_passing_call_assertions_print_nothing() { + bashunit::spy spy_with_a_passing_assertion + + spy_with_a_passing_assertion first + + assert_empty "$(assert_have_been_called spy_with_a_passing_assertion)" + assert_empty "$(assert_have_been_called_times 1 spy_with_a_passing_assertion)" + assert_empty "$(assert_have_been_called_with spy_with_a_passing_assertion "first")" +} + function test_spy_on_echo_does_not_hang() { source ./tests/functional/fixtures/echo_function.sh bashunit::spy echo diff --git a/tests/unit/test_doubles_test.sh b/tests/unit/test_doubles_test.sh index f30521ad..3420cc4e 100644 --- a/tests/unit/test_doubles_test.sh +++ b/tests/unit/test_doubles_test.sh @@ -61,9 +61,11 @@ function test_unsuccessful_spy_called_times() { ps ps + bashunit::spy::call_log_to_slot ps + assert_same "$(bashunit::console_results::print_failed_test "Unsuccessful spy called times" "ps" \ "to have been called" "1 times" \ - "actual" "2 times")" \ + "actual" "2 times" "$_BASHUNIT_SPY_CALL_LOG_OUT")" \ "$(assert_have_been_called_times 1 ps)" } @@ -85,11 +87,13 @@ function test_unsuccessful_spy_with_source_function_have_been_called() { function_to_be_spied_on function_to_be_spied_on + bashunit::spy::call_log_to_slot function_to_be_spied_on + assert_same "$(bashunit::console_results::print_failed_test \ "Unsuccessful spy with source function have been called" \ "function_to_be_spied_on" \ "to have been called" "1 times" \ - "actual" "2 times")" \ + "actual" "2 times" "$_BASHUNIT_SPY_CALL_LOG_OUT")" \ "$(assert_have_been_called_times 1 function_to_be_spied_on)" } @@ -141,6 +145,58 @@ function test_spy_serialize_args_joins_quoted_arguments_with_a_unit_separator() assert_same "a\\ b"$'\x1f'"c" "$_BASHUNIT_SPY_SERIALIZED_OUT" } +function test_spy_call_log_renders_every_recorded_call() { + bashunit::spy spy_with_two_calls + + spy_with_two_calls first + spy_with_two_calls second a + + bashunit::spy::call_log_to_slot spy_with_two_calls + + assert_same " ${_BASHUNIT_COLOR_FAINT}Recorded calls to 'spy_with_two_calls' (2):\ +${_BASHUNIT_COLOR_DEFAULT} + ${_BASHUNIT_COLOR_FAINT}1:${_BASHUNIT_COLOR_DEFAULT} first + ${_BASHUNIT_COLOR_FAINT}2:${_BASHUNIT_COLOR_DEFAULT} second a" \ + "$_BASHUNIT_SPY_CALL_LOG_OUT" +} + +function test_spy_call_log_caps_the_dump_with_an_explicit_marker() { + bashunit::spy spy_called_many_times + + local i=1 + while [ "$i" -le 13 ]; do + spy_called_many_times "call$i" + i=$((i + 1)) + done + + bashunit::spy::call_log_to_slot spy_called_many_times + + assert_contains " ${_BASHUNIT_COLOR_FAINT}10:${_BASHUNIT_COLOR_DEFAULT} call10" \ + "$_BASHUNIT_SPY_CALL_LOG_OUT" + assert_not_contains "call11" "$_BASHUNIT_SPY_CALL_LOG_OUT" + assert_contains "… and 3 more" "$_BASHUNIT_SPY_CALL_LOG_OUT" +} + +function test_spy_call_log_is_empty_without_recorded_calls() { + bashunit::spy spy_without_calls + + bashunit::spy::call_log_to_slot spy_without_calls + assert_empty "$_BASHUNIT_SPY_CALL_LOG_OUT" + + bashunit::spy::call_log_to_slot never_spied_at_all + assert_empty "$_BASHUNIT_SPY_CALL_LOG_OUT" +} + +function test_spy_call_log_keeps_argument_boundaries_in_args_mode() { + bashunit::spy spy_with_spaced_argument + + spy_with_spaced_argument "a b" + + bashunit::spy::call_log_to_slot spy_with_spaced_argument args + + assert_contains "1:${_BASHUNIT_COLOR_DEFAULT} a\\ b" "$_BASHUNIT_SPY_CALL_LOG_OUT" +} + function test_spy_called_with_different_arguments() { bashunit::spy ps @@ -162,10 +218,12 @@ function test_spy_unsuccessful_not_called() { ps + bashunit::spy::call_log_to_slot ps + assert_same \ "$(bashunit::console_results::print_failed_test "Spy unsuccessful not called" "ps" \ "to have been called" "0 times" \ - "actual" "1 times")" \ + "actual" "1 times" "$_BASHUNIT_SPY_CALL_LOG_OUT")" \ "$(assert_not_called ps)" } @@ -202,10 +260,12 @@ function test_unsuccessful_spy_nth_called_with() { ps first ps second + bashunit::spy::call_log_to_slot ps + assert_same \ "$(bashunit::console_results::print_failed_test \ "Unsuccessful spy nth called with" \ - "wrong" "but got " "first")" \ + "wrong" "but got " "first" "" "" "$_BASHUNIT_SPY_CALL_LOG_OUT")" \ "$(assert_have_been_called_nth_with 1 ps "wrong")" } @@ -214,10 +274,13 @@ function test_unsuccessful_spy_nth_called_with_invalid_index() { ps first + bashunit::spy::call_log_to_slot ps + assert_same \ "$(bashunit::console_results::print_failed_test \ "Unsuccessful spy nth called with invalid index" \ - "expected call" "at index 5 but" "only called 1 times")" \ + "expected call" "at index 5 but" "only called 1 times" \ + "" "" "$_BASHUNIT_SPY_CALL_LOG_OUT")" \ "$(assert_have_been_called_nth_with 5 ps "first")" }