Merge pull request #279 from TypedDevs/feat/171-logs

Add logging

Author: Chemaclass

.env.example

@@ -4,3 +4,4 @@ SIMPLE_OUTPUT=
 STOP_ON_FAILURE=
 SHOW_EXECUTION_TIME=
 DEFAULT_PATH=
+LOG_JUNIT=

.gitignore

@@ -11,3 +11,6 @@ docs/.vitepress/dist
 bin/bashunit
 bin/checksum
 lib/bashunit
+
+# logger
+log-junit.xml

CHANGELOG.md

@@ -4,7 +4,9 @@
 
 - Fix echo does not break test execution results
 - Add bashunit facade to enable custom assertions
-- Document how to verify the sha256sum of the final executable
+- Document how to verify the `sha256sum` of the final executable
+- Enable display execution time on MacOS with `SHOW_EXECUTION_TIME`
+- Add `-l|--log-junit <output.xml>` option
 
 ## [0.13.0](https://github.com/TypedDevs/bashunit/compare/0.12.0...0.13.0) - 2024-06-23
 

bashunit

@@ -8,6 +8,7 @@ export BASHUNIT_ROOT_DIR
 
 source "$BASHUNIT_ROOT_DIR/src/default_env_config.sh"
 source "$BASHUNIT_ROOT_DIR/src/env_configuration.sh"
+source "$BASHUNIT_ROOT_DIR/src/clock.sh"
 source "$BASHUNIT_ROOT_DIR/src/check_os.sh"
 source "$BASHUNIT_ROOT_DIR/src/state.sh"
 source "$BASHUNIT_ROOT_DIR/src/colors.sh"
@@ -16,6 +17,7 @@ source "$BASHUNIT_ROOT_DIR/src/console_results.sh"
 source "$BASHUNIT_ROOT_DIR/src/helpers.sh"
 source "$BASHUNIT_ROOT_DIR/src/upgrade.sh"
 source "$BASHUNIT_ROOT_DIR/src/assertions.sh"
+source "$BASHUNIT_ROOT_DIR/src/logger.sh"
 source "$BASHUNIT_ROOT_DIR/src/runner.sh"
 source "$BASHUNIT_ROOT_DIR/src/bashunit.sh"
 source "$BASHUNIT_ROOT_DIR/src/main.sh"
@@ -55,6 +57,11 @@ while [[ $# -gt 0 ]]; do
       shift
       shift
       ;;
+    -l|--log-junit)
+      LOG_JUNIT="$2";
+      shift
+      shift
+      ;;
     --version)
       console_header::print_version
       trap '' EXIT && exit 0

docs/command-line.md

@@ -70,6 +70,19 @@ Filters the tests to be run based on the `test name`.
 ```
 :::
 
+## Logging
+s
+> `bashunit -l|--log-junit log-junit.xml`
+
+Create a report XML file that follows the JUnit XML format and contains information about the test results of your bashunit tests.
+
+::: code-group
+```bash [Example]
+./bashunit ./tests --log-junit log-junit.xml
+```
+:::
+
+
 ## Output
 
 > `bashunit -s|--simple`

src/clock.sh

@@ -0,0 +1,11 @@
+#!/bin/bash
+
+function clock::now() {
+  perl -MTime::HiRes -e 'printf("%.0f\n",Time::HiRes::time()*1000)'
+}
+
+_START_TIME=$(clock::now)
+
+function clock::runtime_in_milliseconds() {
+  echo $(( $(clock::now) - _START_TIME ))
+}

src/console_results.sh

@@ -1,6 +1,5 @@
 #!/bin/bash
 
-_START_TIME=$(date +%s%N);
 _SUCCESSFUL_TEST_COUNT=0
 
 function console_results::render_result() {
@@ -9,7 +8,7 @@ function console_results::render_result() {
     printf "%s%s%s\n" "${_COLOR_RETURN_ERROR}" "Duplicate test functions found" "${_COLOR_DEFAULT}"
     printf "File with duplicate functions: %s\n" "$(state::get_file_with_duplicated_function_names)"
     printf "Duplicate functions: %s\n" "$(state::get_duplicated_function_names)"
-    exit 1
+    return 1
   fi
 
   echo ""
@@ -67,47 +66,45 @@ function console_results::render_result() {
   if [[ "$(state::get_tests_failed)" -gt 0 ]]; then
     printf "\n%s%s%s\n" "$_COLOR_RETURN_ERROR" " Some tests failed " "$_COLOR_DEFAULT"
     console_results::print_execution_time
-    exit 1
+    return 1
   fi
 
   if [[ "$(state::get_tests_incomplete)" -gt 0 ]]; then
     printf "\n%s%s%s\n" "$_COLOR_RETURN_INCOMPLETE" " Some tests incomplete " "$_COLOR_DEFAULT"
     console_results::print_execution_time
-    exit 0
+    return 0
   fi
 
   if [[ "$(state::get_tests_skipped)" -gt 0 ]]; then
     printf "\n%s%s%s\n" "$_COLOR_RETURN_SKIPPED" " Some tests skipped " "$_COLOR_DEFAULT"
     console_results::print_execution_time
-    exit 0
+    return 0
   fi
 
   if [[ "$(state::get_tests_snapshot)" -gt 0 ]]; then
     printf "\n%s%s%s\n" "$_COLOR_RETURN_SNAPSHOT" " Some snapshots created " "$_COLOR_DEFAULT"
     console_results::print_execution_time
-    exit 0
+    return 0
   fi
 
   if [[ $total_tests -eq 0 ]]; then
     printf "\n%s%s%s\n" "$_COLOR_RETURN_ERROR" " No tests found " "$_COLOR_DEFAULT"
     console_results::print_execution_time
-    exit 1
+    return 1
   fi
 
   printf "\n%s%s%s\n" "$_COLOR_RETURN_SUCCESS" " All tests passed " "$_COLOR_DEFAULT"
   console_results::print_execution_time
-  exit 0
+  return 0
 }
 
 function console_results::print_execution_time() {
   if [[ $SHOW_EXECUTION_TIME == false ]]; then
     return
   fi
 
-  if [[ "$_OS" != "OSX" ]]; then
-    _EXECUTION_TIME=$((($(date +%s%N) - "$_START_TIME") / 1000000))
-    printf "${_COLOR_BOLD}%s${_COLOR_DEFAULT}\n" "Time taken: ${_EXECUTION_TIME} ms"
-  fi
+  _EXECUTION_TIME=$(clock::runtime_in_milliseconds)
+  printf "${_COLOR_BOLD}%s${_COLOR_DEFAULT}\n" "Time taken: ${_EXECUTION_TIME} ms"
 }
 
 function console_results::print_successful_test() {

src/default_env_config.sh

@@ -8,4 +8,5 @@ _DEFAULT_SIMPLE_OUTPUT=false
 _DEFAULT_STOP_ON_FAILURE=false
 _DEFAULT_SHOW_EXECUTION_TIME=true
 _DEFAULT_DEFAULT_PATH=
+_DEFAULT_LOG_JUNIT=
 CAT="$(which cat)"

src/env_configuration.sh

@@ -32,3 +32,7 @@ fi
 if [[ -z "$DEFAULT_PATH" ]]; then
   DEFAULT_PATH=$_DEFAULT_DEFAULT_PATH
 fi
+
+if [[ -z "$LOG_JUNIT" ]]; then
+  LOG_JUNIT=$_DEFAULT_LOG_JUNIT
+fi

src/logger.sh

@@ -0,0 +1,82 @@
+#!/bin/bash
+
+TEST_NAMES=()
+TEST_STATUSES=()
+TEST_DURATIONS=()
+TEST_ERRORS=()
+
+function logger::test_snapshot() {
+  logger::log "$1" "$2" "snapshot" "$3"
+}
+
+function logger::test_incomplete() {
+  logger::log "$1" "$2" "incomplete" "$3"
+}
+
+function logger::test_skipped() {
+  logger::log "$1" "$2" "skipped" "$3"
+}
+
+function logger::test_passed() {
+  logger::log "$1" "$2" "passed" "$3"
+}
+
+function logger::test_failed() {
+  logger::log "$1" "$2" "failed" "$3"
+}
+
+function logger::log() {
+  local test_name="$1"
+  local start_time="$2"
+  local status="$3"
+  local error_msg="${4:-}"
+
+  local end_time
+  end_time=$(clock::now)
+  local duration=$((end_time - start_time))
+
+  TEST_NAMES+=("$test_name")
+  TEST_STATUSES+=("$status")
+  TEST_DURATIONS+=("$duration")
+  TEST_ERRORS+=("$error_msg")
+}
+
+function logger::generate_junit_xml() {
+  local output_file="$1"
+  local test_passed
+  test_passed=$(state::get_tests_passed)
+  local tests_skipped
+  tests_skipped=$(state::get_tests_skipped)
+  local tests_incomplete
+  tests_incomplete=$(state::get_tests_incomplete)
+  local tests_snapshot
+  tests_snapshot=$(state::get_tests_snapshot)
+  local tests_failed
+  tests_failed=$(state::get_tests_failed)
+  local time
+  time=$(clock::runtime_in_milliseconds)
+
+  {
+    echo "<?xml version=\"1.0\" encoding=\"UTF-8\"?>"
+    echo "<testsuites>"
+    echo "  <testsuite name=\"bashunit\" tests=\"${#TEST_NAMES[@]}\" time=\"$time\""
+    echo "             passed=\"$test_passed\" failures=\"$tests_failed\" incomplete=\"$tests_incomplete\""
+    echo "             skipped=\"$tests_skipped\" snapshot=\"$tests_snapshot\">"
+
+    for i in "${!TEST_NAMES[@]}"; do
+      local name="${TEST_NAMES[$i]}"
+      local status="${TEST_STATUSES[$i]}"
+      local test_time="${TEST_DURATIONS[$i]}"
+      local msg="${TEST_ERRORS[$i]}"
+
+      echo "    <testcase name=\"$name\" time=\"$test_time\" status=\"$status\">"
+      if [[ -n $msg ]]; then
+        echo "      <message>$msg<message/>"
+      fi
+      echo "    </testcase>"
+    done
+
+    echo "  </testsuite>"
+    echo "</testsuites>"
+  } > "$output_file"
+}

src/main.sh

@@ -7,7 +7,13 @@ function main::exec_tests() {
   console_header::print_version_with_env
   runner::load_test_files "$filter" "${files[@]}"
   console_results::render_result
-  exit 0
+  exit_code=$?
+
+  if [[ -n "$LOG_JUNIT" ]]; then
+    logger::generate_junit_xml "$LOG_JUNIT"
+  fi
+
+  exit $exit_code
 }
 
 function main::exec_assert() {

src/runner.sh

@@ -142,6 +142,9 @@ function runner::parse_execution_result() {
 }
 
 function runner::run_test() {
+  local start_time
+  start_time=$(clock::now)
+
   local function_name="$1"
   shift
   local current_assertions_failed
@@ -188,11 +191,13 @@ function runner::run_test() {
   if [[ -n $runtime_error ]]; then
     state::add_tests_failed
     console_results::print_error_test "$function_name" "$runtime_error"
+    logger::test_failed "$function_name" "$start_time"
     return
   fi
 
   if [[ "$current_assertions_failed" != "$(state::get_assertions_failed)" ]]; then
     state::add_tests_failed
+    logger::test_failed "$function_name" "$start_time"
 
     if [ "$STOP_ON_FAILURE" = true ]; then
       exit 1
@@ -204,16 +209,19 @@ function runner::run_test() {
   if [[ "$current_assertions_snapshot" != "$(state::get_assertions_snapshot)" ]]; then
     state::add_tests_snapshot
     console_results::print_snapshot_test "$function_name"
+    logger::test_snapshot "$function_name" "$start_time"
     return
   fi
 
   if [[ "$current_assertions_incomplete" != "$(state::get_assertions_incomplete)" ]]; then
     state::add_tests_incomplete
+    logger::test_incomplete "$function_name" "$start_time"
     return
   fi
 
   if [[ "$current_assertions_skipped" != "$(state::get_assertions_skipped)" ]]; then
     state::add_tests_skipped
+    logger::test_skipped "$function_name" "$start_time"
     return
   fi
 
@@ -222,6 +230,7 @@ function runner::run_test() {
 
   console_results::print_successful_test "${label}" "$@"
   state::add_tests_passed
+  logger::test_passed "$function_name" "$start_time"
 }
 
 function runner::run_set_up() {

tests/acceptance/bashunit_log_junit_test.sh

@@ -0,0 +1,22 @@
+#!/bin/bash
+
+function set_up_before_script() {
+  TEST_ENV_FILE="tests/acceptance/fixtures/.env.default"
+  TEST_ENV_FILE_LOG_JUNIT="tests/acceptance/fixtures/.env.log_junit"
+}
+
+function test_bashunit_when_log_junit_option() {
+  local test_file=./tests/acceptance/fixtures/test_bashunit_when_log_junit.sh
+
+  assert_match_snapshot "$(./bashunit --env "$TEST_ENV_FILE" --log-junit custom.xml "$test_file")"
+  assert_file_exists custom.xml
+  rm custom.xml
+}
+
+function test_bashunit_when_log_junit_env() {
+  local test_file=./tests/acceptance/fixtures/test_bashunit_when_log_junit.sh
+
+  assert_match_snapshot "$(./bashunit --env "$TEST_ENV_FILE_LOG_JUNIT" "$test_file")"
+  assert_file_exists log-junit.xml
+  rm log-junit.xml
+}

tests/acceptance/fixtures/.env.default

@@ -4,3 +4,4 @@ SIMPLE_OUTPUT=false
 STOP_ON_FAILURE=false
 SHOW_EXECUTION_TIME=false
 DEFAULT_PATH=
+LOG_JUNIT=

tests/acceptance/fixtures/.env.log_junit

@@ -0,0 +1,7 @@
+SHOW_HEADER=false
+HEADER_ASCII_ART=false
+SIMPLE_OUTPUT=false
+STOP_ON_FAILURE=true
+SHOW_EXECUTION_TIME=false
+DEFAULT_PATH=
+LOG_JUNIT=log-junit.xml

tests/acceptance/fixtures/test_bashunit_when_log_junit.sh

@@ -0,0 +1,9 @@
+#!/bin/bash
+
+function test_a() {
+  assert_equals 1 1
+}
+
+function test_b() {
+  assert_equals 2 2
+}

tests/acceptance/snapshots/bashunit_log_junit_test_sh.test_bashunit_when_log_junit_env.snapshot

@@ -0,0 +1,8 @@
+Running ./tests/acceptance/fixtures/test_bashunit_when_log_junit.sh
+✓ Passed: A
+✓ Passed: B
+
+Tests:      2 passed, 2 total
+Assertions: 2 passed, 2 total
+
+ All tests passed 

tests/acceptance/snapshots/bashunit_log_junit_test_sh.test_bashunit_when_log_junit_option.snapshot

@@ -0,0 +1,8 @@
+Running ./tests/acceptance/fixtures/test_bashunit_when_log_junit.sh
+✓ Passed: A
+✓ Passed: B
+
+Tests:      2 passed, 2 total
+Assertions: 2 passed, 2 total
+
+ All tests passed 

tests/acceptance/snapshots/bashunit_log_junit_test_sh.test_bashunit_when_stop_on_failure_env.snapshot

@@ -0,0 +1,5 @@
+Running ./tests/acceptance/fixtures/test_bashunit_when_log_junit.sh
+✓ Passed: A success
+✗ Failed: B error
+    Expected '1'
+    but got '2'