Merge pull request #450 from TypedDevs/feat/improve-dev-log

Improve dev log internal messages

Author: Chemaclass

CHANGELOG.md

@@ -5,6 +5,9 @@
 - Fix prevents writing in src dir during tests
 - Fix negative widths with rpad
 - Fix internal assert_line_count and call_test_functions
+- Include calling function name in dev log output for easier debugging
+- Add more internal dev log messages and prefix them with [INTERNAL]
+    - Toggle internal log messages with `BASHUNIT_INTERNAL_LOG=true|false`
 
 ## [0.22.0](https://github.com/TypedDevs/bashunit/compare/0.21.0...0.22.0) - 2025-07-20
 

docs/configuration.md

@@ -227,11 +227,16 @@ log "error" "an" "error" "message"
 log "warning" "different log level messages!"
 ```
 ```bash [Output: out.log]
-2024-10-03 21:27:23 [INFO]: I am tracing something...
-2024-10-03 21:27:23 [ERROR]: an error message
-2024-10-03 21:27:23 [WARNING]: different log level messages!
+2024-10-03 21:27:23 [INFO]: I am tracing something... #tests/sample.sh:11
+2024-10-03 21:27:23 [ERROR]: an error message #tests/sample.sh:27
+2024-10-03 21:27:24 [WARNING]: different log level messages! #tests/sample.sh:21
 ```
 :::
+When enabled, the selected log file path is printed in the header so you can
+quickly `tail -f` it while the tests run.
+
+> All internal messages emitted by bashunit are prefixed with `[INTERNAL]`.
+> You can toggle internal messages with `BASHUNIT_INTERNAL_LOG=true|false`.
 
 ## Verbose
 

docs/globals.md

@@ -5,7 +5,7 @@ You can use this list of global functions that exists to primarily to improve yo
 
 ## log
 
-Write into the `BASHUNIT_DEV_LOG` a log message.
+Write into the `BASHUNIT_DEV_LOG` a log message. The log line records the source file and line number for easier debugging.
 
 > See: [Dev log](/configuration#dev-log)
 
@@ -17,6 +17,7 @@ log "warning" "hello" "world"
 log "critical" "hello" "world"
 log "error" "hello" "world"
 ```
+Internal messages from bashunit include the `[INTERNAL]` prefix so you can easily spot them. You can enable them with `BASHUNIT_INTERNAL_LOG=true|false`.
 
 ## current_dir
 

src/console_header.sh

@@ -9,6 +9,10 @@ function console_header::print_version_with_env() {
   fi
 
   console_header::print_version "$filter" "${files[@]}"
+
+  if env::is_dev_mode_enabled; then
+    printf "%sDev log:%s %s\n" "${_COLOR_INCOMPLETE}" "${_COLOR_DEFAULT}" "$BASHUNIT_DEV_LOG"
+  fi
 }
 
 function console_header::print_version() {

src/env.sh

@@ -29,6 +29,7 @@ _DEFAULT_SHOW_EXECUTION_TIME="true"
 _DEFAULT_VERBOSE="false"
 _DEFAULT_BENCH_MODE="false"
 _DEFAULT_NO_OUTPUT="false"
+_DEFAULT_INTERNAL_LOG="false"
 
 : "${BASHUNIT_PARALLEL_RUN:=${PARALLEL_RUN:=$_DEFAULT_PARALLEL_RUN}}"
 : "${BASHUNIT_SHOW_HEADER:=${SHOW_HEADER:=$_DEFAULT_SHOW_HEADER}}"
@@ -39,6 +40,7 @@ _DEFAULT_NO_OUTPUT="false"
 : "${BASHUNIT_VERBOSE:=${VERBOSE:=$_DEFAULT_VERBOSE}}"
 : "${BASHUNIT_BENCH_MODE:=${BENCH_MODE:=$_DEFAULT_BENCH_MODE}}"
 : "${BASHUNIT_NO_OUTPUT:=${NO_OUTPUT:=$_DEFAULT_NO_OUTPUT}}"
+: "${BASHUNIT_INTERNAL_LOG:=${INTERNAL_LOG:=$_DEFAULT_INTERNAL_LOG}}"
 
 function env::is_parallel_run_enabled() {
   [[ "$BASHUNIT_PARALLEL_RUN" == "true" ]]
@@ -68,6 +70,10 @@ function env::is_dev_mode_enabled() {
   [[ -n "$BASHUNIT_DEV_LOG" ]]
 }
 
+function env::is_internal_log_enabled() {
+  [[ "$BASHUNIT_INTERNAL_LOG" == "true" ]]
+}
+
 function env::is_verbose_enabled() {
   [[ "$BASHUNIT_VERBOSE" == "true" ]]
 }
@@ -104,6 +110,7 @@ function env::find_terminal_width() {
 }
 
 function env::print_verbose() {
+  internal_log "Printing verbose environment variables"
   local keys=(
     "BASHUNIT_DEFAULT_PATH"
     "BASHUNIT_DEV_LOG"
@@ -128,6 +135,7 @@ function env::print_verbose() {
   done
 
   for key in "${keys[@]}"; do
+    internal_log "$key=${!key}"
     printf "%s:%*s%s\n" "$key" $((max_length - ${#key} + 1)) "" "${!key}"
   done
 }
@@ -140,3 +148,7 @@ TEMP_FILE_PARALLEL_STOP_ON_FAILURE="$TEMP_DIR_PARALLEL_TEST_SUITE/.stop-on-failu
 TERMINAL_WIDTH="$(env::find_terminal_width)"
 FAILURES_OUTPUT_PATH=$(mktemp)
 CAT="$(which cat)"
+
+if env::is_dev_mode_enabled; then
+  internal_log "info" "Dev log enabled" "file:$BASHUNIT_DEV_LOG"
+fi

src/globals.sh

@@ -58,6 +58,7 @@ function temp_dir() {
 }
 
 function cleanup_temp_files() {
+  internal_log "cleanup_temp_files"
   if [[ -n "${BASHUNIT_CURRENT_TEST_ID:-}" ]]; then
     rm -rf /tmp/bashunit/tmp/"${BASHUNIT_CURRENT_TEST_ID}"_*
   else
@@ -83,9 +84,15 @@ function log() {
     *) set -- "$level $@"; level="INFO" ;;
   esac
 
-  local GRAY='\033[1;30m'
-  local RESET='\033[0m'
-  echo -e "$(current_timestamp) [$level]: $@ ${GRAY}#${BASH_SOURCE[1]}:${BASH_LINENO[0]}${RESET}" >> "$BASHUNIT_DEV_LOG"
+  echo "$(current_timestamp) [$level]: $* #${BASH_SOURCE[1]}:${BASH_LINENO[0]}" >> "$BASHUNIT_DEV_LOG"
+}
+
+function internal_log() {
+  if ! env::is_dev_mode_enabled || ! env::is_internal_log_enabled; then
+    return
+  fi
+
+  echo "$(current_timestamp) [INTERNAL]: $* #${BASH_SOURCE[1]}:${BASH_LINENO[0]}" >> "$BASHUNIT_DEV_LOG"
 }
 
 function print_line() {

src/main.sh

@@ -9,6 +9,8 @@ function main::exec_tests() {
     test_files+=("$line")
   done < <(helper::load_test_files "$filter" "${files[@]}")
 
+  internal_log "exec_tests" "filter:$filter" "files:${test_files[*]}"
+
   if [[ ${#test_files[@]} -eq 0 || -z "${test_files[0]}" ]]; then
     printf "%sError: At least one file path is required.%s\n" "${_COLOR_FAILED}" "${_COLOR_DEFAULT}"
     console_header::print_help
@@ -69,6 +71,7 @@ function main::exec_tests() {
   fi
 
   cleanup_temp_files
+  internal_log "Finished tests" "exit_code:$exit_code"
   exit $exit_code
 }
 
@@ -81,6 +84,8 @@ function main::exec_benchmarks() {
     bench_files+=("$line")
   done < <(helper::load_bench_files "$filter" "${files[@]}")
 
+  internal_log "exec_benchmarks" "filter:$filter" "files:${bench_files[*]}"
+
   if [[ ${#bench_files[@]} -eq 0 || -z "${bench_files[0]}" ]]; then
     printf "%sError: At least one file path is required.%s\n" "${_COLOR_FAILED}" "${_COLOR_DEFAULT}"
     console_header::print_help
@@ -94,6 +99,7 @@ function main::exec_benchmarks() {
   benchmark::print_results
 
   cleanup_temp_files
+  internal_log "Finished benchmarks"
 }
 
 function main::cleanup() {

src/parallel.sh

@@ -3,6 +3,8 @@
 function parallel::aggregate_test_results() {
   local temp_dir_parallel_test_suite=$1
 
+  internal_log "aggregate_test_results" "dir:$temp_dir_parallel_test_suite"
+
   local total_failed=0
   local total_passed=0
   local total_skipped=0
@@ -78,6 +80,13 @@ function parallel::aggregate_test_results() {
   export _ASSERTIONS_SKIPPED=$total_skipped
   export _ASSERTIONS_INCOMPLETE=$total_incomplete
   export _ASSERTIONS_SNAPSHOT=$total_snapshot
+
+  internal_log "aggregate_totals" \
+    "failed:$total_failed" \
+    "passed:$total_passed" \
+    "skipped:$total_skipped" \
+    "incomplete:$total_incomplete" \
+    "snapshot:$total_snapshot"
 }
 
 function parallel::mark_stop_on_failure() {
@@ -96,6 +105,8 @@ function parallel::reset() {
 }
 
 function parallel::is_enabled() {
+  internal_log "parallel::is_enabled" "requested:$BASHUNIT_PARALLEL_RUN" "os:${_OS:-Unknown}"
+
   if env::is_parallel_run_enabled && \
     (check_os::is_macos || check_os::is_ubuntu || check_os::is_windows); then
     return 0

src/runner.sh

@@ -10,6 +10,7 @@ function runner::load_test_files() {
     if [[ ! -f $test_file ]]; then
       continue
     fi
+    internal_log "Loading file" "$test_file"
     # shellcheck source=/dev/null
     source "$test_file"
     runner::run_set_up_before_script
@@ -20,6 +21,7 @@ function runner::load_test_files() {
     fi
     runner::run_tear_down_after_script
     runner::clean_set_up_and_tear_down_after_script
+    internal_log "Finished file" "$test_file"
   done
 
   if parallel::is_enabled; then
@@ -161,6 +163,8 @@ function runner::call_bench_functions() {
 function runner::render_running_file_header() {
   local script="$1"
 
+  internal_log "Running file" "$script"
+
   if parallel::is_enabled; then
     return
   fi
@@ -190,6 +194,7 @@ function runner::run_test() {
   # race conditions when running tests in parallel.
   local sanitized_fn_name
   sanitized_fn_name="$(helper::normalize_variable_name "$fn_name")"
+  internal_log "Running test" "$fn_name" "$*"
   if env::is_parallel_run_enabled; then
     export BASHUNIT_CURRENT_TEST_ID="${sanitized_fn_name}_$$_$(random_str 6)"
   else
@@ -208,8 +213,11 @@ function runner::run_test() {
   exec 3>&1
 
   local test_execution_result=$(
+    # shellcheck disable=SC2154
     trap '
-      state::set_test_exit_code $?
+      exit_code=$?
+      set +e
+      state::set_test_exit_code "$exit_code"
       runner::run_tear_down
       runner::clear_mocks
       state::export_subshell_context
@@ -288,6 +296,7 @@ function runner::run_test() {
     console_results::print_error_test "$fn_name" "$runtime_error"
     reports::add_test_failed "$test_file" "$fn_name" "$duration" "$total_assertions"
     runner::write_failure_result_output "$test_file" "$runtime_error"
+    internal_log "Test error" "$fn_name" "$runtime_error"
     return
   fi
 
@@ -296,6 +305,8 @@ function runner::run_test() {
     reports::add_test_failed "$test_file" "$fn_name" "$duration" "$total_assertions"
     runner::write_failure_result_output "$test_file" "$subshell_output"
 
+    internal_log "Test failed" "$fn_name"
+
     if env::is_stop_on_failure_enabled; then
       if parallel::is_enabled; then
         parallel::mark_stop_on_failure
@@ -310,18 +321,21 @@ function runner::run_test() {
     state::add_tests_snapshot
     console_results::print_snapshot_test "$fn_name"
     reports::add_test_snapshot "$test_file" "$fn_name" "$duration" "$total_assertions"
+    internal_log "Test snapshot" "$fn_name"
     return
   fi
 
   if [[ "$current_assertions_incomplete" != "$(state::get_assertions_incomplete)" ]]; then
     state::add_tests_incomplete
     reports::add_test_incomplete "$test_file" "$fn_name" "$duration" "$total_assertions"
+    internal_log "Test incomplete" "$fn_name"
     return
   fi
 
   if [[ "$current_assertions_skipped" != "$(state::get_assertions_skipped)" ]]; then
     state::add_tests_skipped
     reports::add_test_skipped "$test_file" "$fn_name" "$duration" "$total_assertions"
+    internal_log "Test skipped" "$fn_name"
     return
   fi
 
@@ -334,6 +348,7 @@ function runner::run_test() {
   fi
   state::add_tests_passed
   reports::add_test_passed "$test_file" "$fn_name" "$duration" "$total_assertions"
+  internal_log "Test passed" "$fn_name"
 }
 
 function runner::decode_subshell_output() {
@@ -392,7 +407,7 @@ function runner::parse_result_parallel() {
   mv "$unique_test_result_file" "${unique_test_result_file}.result"
   unique_test_result_file="${unique_test_result_file}.result"
 
-  log "debug" "[PARA]" "fn_name:$fn_name" "execution_result:$execution_result"
+  internal_log "[PARA]" "fn_name:$fn_name" "execution_result:$execution_result"
 
   runner::parse_result_sync "$fn_name" "$execution_result"
 
@@ -431,14 +446,22 @@ function runner::parse_result_sync() {
     test_exit_code="${BASH_REMATCH[6]}"
   fi
 
-  log "debug" "[SYNC]" "fn_name:$fn_name" "execution_result:$execution_result"
+  internal_log "[SYNC]" "fn_name:$fn_name" "execution_result:$execution_result"
 
   ((_ASSERTIONS_PASSED += assertions_passed)) || true
   ((_ASSERTIONS_FAILED += assertions_failed)) || true
   ((_ASSERTIONS_SKIPPED += assertions_skipped)) || true
   ((_ASSERTIONS_INCOMPLETE += assertions_incomplete)) || true
   ((_ASSERTIONS_SNAPSHOT += assertions_snapshot)) || true
   ((_TEST_EXIT_CODE += test_exit_code)) || true
+
+  internal_log "result_summary" \
+    "failed:$assertions_failed" \
+    "passed:$assertions_passed" \
+    "skipped:$assertions_skipped" \
+    "incomplete:$assertions_incomplete" \
+    "snapshot:$assertions_snapshot" \
+    "exit_code:$test_exit_code"
 }
 
 function runner::write_failure_result_output() {
@@ -454,14 +477,17 @@ function runner::write_failure_result_output() {
 }
 
 function runner::run_set_up() {
+  internal_log "run_set_up"
   helper::execute_function_if_exists 'set_up'
 }
 
 function runner::run_set_up_before_script() {
+  internal_log "run_set_up_before_script"
   helper::execute_function_if_exists 'set_up_before_script'
 }
 
 function runner::run_tear_down() {
+  internal_log "run_tear_down"
   helper::execute_function_if_exists 'tear_down'
 }
 
@@ -472,10 +498,12 @@ function runner::clear_mocks() {
 }
 
 function runner::run_tear_down_after_script() {
+  internal_log "run_tear_down_after_script"
   helper::execute_function_if_exists 'tear_down_after_script'
 }
 
 function runner::clean_set_up_and_tear_down_after_script() {
+  internal_log "clean_set_up_and_tear_down_after_script"
   helper::unset_if_exists 'set_up'
   helper::unset_if_exists 'tear_down'
   helper::unset_if_exists 'set_up_before_script'