feat(doubles): dump the recorded calls when a spy assertion fails

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 <spy> <arg>...`: 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)

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 <count> <spy>` but
   `assert_have_been_called_with <spy> <expected> [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.

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:
 

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"

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
 

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

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")"
 }