diff --git a/CHANGELOG.md b/CHANGELOG.md index d8fabf9d..bc915cb9 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -3,6 +3,7 @@ ## Unreleased ### Changed +- Parallel reports collect worker results without per-row base64 processes, preserving values and completion order (#1371) - Data providers pass arguments without per-argument base64 processes, preserving quoting, empty values and parser isolation (#1370) - JSON reports write ordinary filenames, test names and empty messages without per-field processes, preserving existing escaping (#1369) diff --git a/src/reports/collect.sh b/src/reports/collect.sh index edfec052..d6c113c3 100644 --- a/src/reports/collect.sh +++ b/src/reports/collect.sh @@ -2,11 +2,6 @@ # Collected per-test results: the shared arrays every report writer reads, and the API the runner calls to fill them. -# Field separator for the rows parallel workers spool. ASCII unit separator: it -# cannot appear in base64 output and is not an IFS whitespace character, so a -# run of them yields empty fields instead of collapsing. -_BASHUNIT_REPORTS_FIELD_SEP=$'\037' - # Strips ANSI CSI escape sequences (color codes, cursor moves, erase-line, ...) # from $1. Shared by every writer's own escape/encode function below as their # first step, so the definition of "what is an ANSI escape sequence" for @@ -30,6 +25,10 @@ _BASHUNIT_REPORTS_TEST_OUTPUTS=() # it (JUnit ) without threading one more argument through every # wrapper; add_test consumes and clears it. _BASHUNIT_REPORTS_CURRENT_OUTPUT="" +_BASHUNIT_REPORTS_FILE_ORDINAL=0 +_BASHUNIT_REPORTS_CONTROL_RECORD_ORDINAL=0 +_BASHUNIT_REPORTS_WORKER_RECORD_ORDINAL=0 +_BASHUNIT_REPORTS_RECORD_SCOPE=control function bashunit::reports::set_current_test_output() { _BASHUNIT_REPORTS_CURRENT_OUTPUT="$1" @@ -109,41 +108,48 @@ function bashunit::reports::add_test() { "$file":*) line="${_BASHUNIT_TEST_LOCATION##*:}" ;; esac - # Under --parallel this runs inside the per-test worker, so the arrays below - # are appended to in a process that is about to exit and the parent rebuilds - # nothing -- every report came out with zero tests while the run stayed green. - # Spool the row to a run-scoped file as well, the same way - # --snapshot-report-unused crosses the fork boundary, and replay it in the - # parent before the writers run. - # - # The arrays are still filled here rather than skipped: this function is also - # called directly, in the parent, by the reports unit tests, and returning - # early left them asserting against arrays nothing had touched. The parent - # never reaches this path for a real parallel test, so replaying the spool - # cannot double-count. - # - # Only the four fields that can hold arbitrary text are base64-encoded: a - # failure message or a captured output carries newlines, and a path or a test - # name (which may end in a provider's arguments) can hold anything. The other - # five are a status word and four numbers, produced by this file's own - # callers, so the unit separator carries them as they are. - # - # Encoding all nine cost fourteen `base64` forks per test -- nine here and - # five more decoding, each with a `tr` on top -- which made `--log-junit` - # several times more expensive than the run it was reporting on. Base64 - # output is [A-Za-z0-9+/=] and the raw fields are numeric, so no field can - # contain the separator and the row stays one line. + # Sidecars avoid Bash 3's bytewise read on large diagnostics. if bashunit::parallel::is_enabled; then - local us=$_BASHUNIT_REPORTS_FIELD_SEP - local row - row="$(bashunit::helper::encode_base64 "$file")$us" - row="$row$(bashunit::helper::encode_base64 "$test_name")$us" - row="$row$status$us$duration$us$assertions$us" - row="$row$(bashunit::helper::encode_base64 "$failure_message")$us" - row="$row$line$us$retries$us" - row="$row$(bashunit::helper::encode_base64 "$test_output")" - printf '%s\n' "$row" \ - >>"${REPORTS_OUTPUT_PATH:-/dev/null}" 2>/dev/null || true + local file_order="00000000${_BASHUNIT_REPORTS_FILE_ORDINAL:-0}" + file_order="${file_order: -8}" + local row_order="00000000${_BASHUNIT_RUNNER_RESULT_ORDINAL:-0}" + row_order="${row_order: -8}" + local record_kind=0 + local record_order=00000000 + if [ "$_BASHUNIT_REPORTS_RECORD_SCOPE" = worker ]; then + _BASHUNIT_REPORTS_WORKER_RECORD_ORDINAL=$((_BASHUNIT_REPORTS_WORKER_RECORD_ORDINAL + 1)) + record_order="00000000$_BASHUNIT_REPORTS_WORKER_RECORD_ORDINAL" + record_order="${record_order: -8}" + else + record_kind=1 + _BASHUNIT_REPORTS_CONTROL_RECORD_ORDINAL=$((_BASHUNIT_REPORTS_CONTROL_RECORD_ORDINAL + 1)) + record_order="00000000$_BASHUNIT_REPORTS_CONTROL_RECORD_ORDINAL" + record_order="${record_order: -8}" + fi + local record_token="$file_order$row_order$record_kind$record_order" + local record="${REPORTS_OUTPUT_PATH:-/dev/null}.$record_token.record" + local has_failure=0 + local has_output=0 + local write_failed=false + if [ -n "$failure_message" ]; then + has_failure=1 + printf '%s_' "$failure_message" >"$record.failure" 2>/dev/null || write_failed=true + fi + if [ -n "$test_output" ]; then + has_output=1 + printf '%s_' "$test_output" >"$record.output" 2>/dev/null || write_failed=true + fi + if [ "$write_failed" = false ]; then + printf '%s\0' "$file" "$test_name" "$status" "$duration" "$assertions" "$line" "$retries" \ + "$has_failure" "$has_output" >"$record" 2>/dev/null || write_failed=true + fi + if [ "$write_failed" = false ]; then + # A 26-byte builtin append publishes the complete row in completion order. + printf '%s\n' "$record_token" >>"${REPORTS_OUTPUT_PATH:-/dev/null}" 2>/dev/null || write_failed=true + fi + if [ "$write_failed" = true ]; then + printf 'bashunit: unable to write report record %s\n' "$record" >&2 + fi fi _BASHUNIT_REPORTS_TEST_FILES[${#_BASHUNIT_REPORTS_TEST_FILES[@]}]="$file" @@ -158,12 +164,13 @@ function bashunit::reports::add_test() { } ## -# Replays rows spooled by parallel workers into the report arrays, in the order -# they were written. Called once in the parent before any report is generated; +# Replays rows spooled by parallel workers into the report arrays in publication +# order. Called once in the parent before any report is generated; # a no-op sequentially, where add_test filled the arrays directly. ## function bashunit::reports::load_spooled() { bashunit::reports::is_enabled || return 0 + bashunit::parallel::is_enabled || return 0 [ -f "${REPORTS_OUTPUT_PATH:-}" ] || return 0 # The spool is the complete record of a parallel run, so it replaces the @@ -186,22 +193,71 @@ function bashunit::reports::load_spooled() { _BASHUNIT_REPORTS_TEST_RETRIES=() _BASHUNIT_REPORTS_TEST_OUTPUTS=() - local file test_name status duration assertions failure_message line retries test_output n - # The separator is not an IFS whitespace character, so a run of them yields - # empty fields rather than collapsing -- which is what an absent failure - # message or output has to produce. - while IFS="$_BASHUNIT_REPORTS_FIELD_SEP" read -r \ - file test_name status duration assertions failure_message line retries test_output; do - [ -n "$file" ] || continue + local record_token record file test_name status duration assertions failure_message line retries test_output + local has_failure has_output + while IFS= read -r record_token; do + case "$record_token" in + *[!0-9]* | "") + printf 'bashunit: invalid report record token %s\n' "$record_token" >&2 + continue + ;; + esac + if [ "${#record_token}" -ne 25 ]; then + printf 'bashunit: invalid report record token %s\n' "$record_token" >&2 + continue + fi + record="$REPORTS_OUTPUT_PATH.$record_token.record" + if [ ! -f "$record" ]; then + printf 'bashunit: missing report record %s\n' "$record" >&2 + continue + fi + if { + IFS= read -r -d '' file && + IFS= read -r -d '' test_name && + IFS= read -r -d '' status && + IFS= read -r -d '' duration && + IFS= read -r -d '' assertions && + IFS= read -r -d '' line && + IFS= read -r -d '' retries && + IFS= read -r -d '' has_failure && + IFS= read -r -d '' has_output + } <"$record"; then + : + else + printf 'bashunit: incomplete report record %s\n' "$record" >&2 + continue + fi + failure_message="" + test_output="" + if [ "$has_failure" = 1 ] && [ -f "$record.failure" ]; then + failure_message=$(<"$record.failure") + case "$failure_message" in + *_) failure_message="${failure_message%?}" ;; + *) printf 'bashunit: incomplete report field %s\n' "$record.failure" >&2; continue ;; + esac + elif [ "$has_failure" = 1 ]; then + printf 'bashunit: missing report field %s\n' "$record.failure" >&2 + continue + fi + if [ "$has_output" = 1 ] && [ -f "$record.output" ]; then + test_output=$(<"$record.output") + case "$test_output" in + *_) test_output="${test_output%?}" ;; + *) printf 'bashunit: incomplete report field %s\n' "$record.output" >&2; continue ;; + esac + elif [ "$has_output" = 1 ]; then + printf 'bashunit: missing report field %s\n' "$record.output" >&2 + continue + fi local n=${#_BASHUNIT_REPORTS_TEST_FILES[@]} - _BASHUNIT_REPORTS_TEST_FILES[n]=$(bashunit::helper::decode_base64 "$file") - _BASHUNIT_REPORTS_TEST_NAMES[n]=$(bashunit::helper::decode_base64 "$test_name") + _BASHUNIT_REPORTS_TEST_FILES[n]=$file + _BASHUNIT_REPORTS_TEST_NAMES[n]=$test_name _BASHUNIT_REPORTS_TEST_STATUSES[n]=$status _BASHUNIT_REPORTS_TEST_DURATIONS[n]=$duration _BASHUNIT_REPORTS_TEST_ASSERTIONS[n]=$assertions - _BASHUNIT_REPORTS_TEST_FAILURES[n]=$(bashunit::helper::decode_base64 "$failure_message") + _BASHUNIT_REPORTS_TEST_FAILURES[n]=$failure_message _BASHUNIT_REPORTS_TEST_LINES[n]=$line _BASHUNIT_REPORTS_TEST_RETRIES[n]=$retries - _BASHUNIT_REPORTS_TEST_OUTPUTS[n]=$(bashunit::helper::decode_base64 "$test_output") + _BASHUNIT_REPORTS_TEST_OUTPUTS[n]=$test_output done <"$REPORTS_OUTPUT_PATH" } diff --git a/src/runner/discovery.sh b/src/runner/discovery.sh index 2020a603..393ae852 100644 --- a/src/runner/discovery.sh +++ b/src/runner/discovery.sh @@ -65,6 +65,9 @@ function bashunit::runner::load_test_files() { export BASHUNIT_CURRENT_SCRIPT_ID="$_BASHUNIT_HELPER_ID_OUT" scripts_ids[scripts_ids_count]="${BASHUNIT_CURRENT_SCRIPT_ID}" scripts_ids_count=$((scripts_ids_count + 1)) + _BASHUNIT_REPORTS_FILE_ORDINAL=$((_BASHUNIT_REPORTS_FILE_ORDINAL + 1)) + _BASHUNIT_REPORTS_CONTROL_RECORD_ORDINAL=0 + _BASHUNIT_RUNNER_RESULT_ORDINAL=0 bashunit::internal_log "Loading file" "$test_file" # Files are sourced sequentially in this loop (parallel workers fork after), # so a fixed path in the run dir is safe: `2>` truncates it per file and the diff --git a/src/runner/exec.sh b/src/runner/exec.sh index 4f2026cd..c7613ed5 100644 --- a/src/runner/exec.sh +++ b/src/runner/exec.sh @@ -96,6 +96,11 @@ function bashunit::runner::report_provider_error() { fi } +function bashunit::runner::run_test_parallel() { + _BASHUNIT_REPORTS_RECORD_SCOPE=worker + bashunit::runner::run_test "$@" +} + ## # Runs the given test functions of a script (sequentially, or one background # worker per test under --parallel). @@ -177,7 +182,7 @@ function bashunit::runner::call_test_functions() { bashunit::runner::wait_for_job_slot _test_ordinal=$((_test_ordinal + 1)) _BASHUNIT_RUNNER_RESULT_ORDINAL=$_test_ordinal - bashunit::runner::run_test "$script" "$fn_name" & + bashunit::runner::run_test_parallel "$script" "$fn_name" & _BASHUNIT_WORKER_TEST_PIDS="$_BASHUNIT_WORKER_TEST_PIDS $!" else bashunit::runner::run_test "$script" "$fn_name" @@ -255,7 +260,7 @@ function bashunit::runner::call_test_functions() { bashunit::runner::wait_for_job_slot _test_ordinal=$((_test_ordinal + 1)) _BASHUNIT_RUNNER_RESULT_ORDINAL=$_test_ordinal - bashunit::runner::run_test "$script" "$fn_name" ${parsed_data+"${parsed_data[@]}"} & + bashunit::runner::run_test_parallel "$script" "$fn_name" ${parsed_data+"${parsed_data[@]}"} & _BASHUNIT_WORKER_TEST_PIDS="$_BASHUNIT_WORKER_TEST_PIDS $!" else bashunit::runner::run_test "$script" "$fn_name" ${parsed_data+"${parsed_data[@]}"} diff --git a/tests/acceptance/bashunit_run_forks_test.sh b/tests/acceptance/bashunit_run_forks_test.sh index 0d4856df..87439ea1 100644 --- a/tests/acceptance/bashunit_run_forks_test.sh +++ b/tests/acceptance/bashunit_run_forks_test.sh @@ -277,15 +277,7 @@ function test_parallel_result_publishing_does_not_fork_per_test() { assert_equals "" "$forked" } -# Regression guard for the report spool. A worker used to base64 each of the -# nine fields of a result row separately, and the parent decoded each one the -# same way -- fourteen `base64` forks per test (and, on the encode side, a `tr` -# each), so turning on `--log-junit` cost more than running the tests. Only the -# two fields that can hold arbitrary text need encoding; the rest are a status, -# some numbers and a path, which a unit separator carries as they are. -# -# Counted with a PATH shim rather than a trace: these forks happen inside the -# `--parallel` workers, which `bash -x` on the parent cannot see. +# A PATH shim sees codec processes inside workers that the parent trace misses. function test_reports_do_not_fork_base64_per_field() { if bashunit::check_os::is_windows; then bashunit::skip "process tracing is unreliable under Git Bash" && return @@ -321,11 +313,58 @@ function test_reports_do_not_fork_base64_per_field() { calls="$(grep -c . "$count_file" || true)" fi - # Four passing tests carry no failure message and no output, so both - # arbitrary fields are empty and short-circuit: the row costs one encode for - # the file and one for the test name, and the same two decodes. Sixteen is - # that, with room for the run's own bookkeeping; it was 56. - assert_less_or_equal_than 16 "$calls" + assert_equals 0 "$calls" +} + +function test_parallel_reports_keep_lifecycle_rows_and_remove_scratch_records() { + local dir + dir="$(bashunit::temp_dir)" + mkdir "$dir/a" "$dir/b" + printf '%s\n' 'function data_spool_values() { printf "%s\n" "a:b" "a/b"; } +# @data_provider data_spool_values +function test_spool_provider_rows() { assert_true true; } +# @skip intentional +function test_spool_skip() { assert_same never ran; } +# @retry 1 +function test_spool_retry() { + if [ -f "$REPORT_RETRY_MARKER" ]; then + assert_true true + else + : >"$REPORT_RETRY_MARKER" + assert_same first second + fi +} +# @data_provider undefined_spool_provider +function test_spool_missing_provider() { assert_same never ran; } +function tear_down_after_script() { printf "worker teardown failure\n"; return 1; }' >"$dir/a/same_test.sh" + printf '%s\n' 'function set_up_before_script() { printf "parent setup failure\n"; return 1; } +function test_spool_blocked_by_setup() { assert_same never ran; } +function tear_down_after_script() { printf "parent teardown failure\n"; return 1; }' >"$dir/b/same_test.sh" + + local exit_code=0 + TMPDIR="$dir" REPORT_RETRY_MARKER="$dir/retried" ./bashunit --skip-env-file --parallel --simple \ + --report-junit "$dir/out.xml" --report-json "$dir/out.json" --report-tap "$dir/out.tap" \ + --report-html "$dir/out.html" --report-md "$dir/out.md" --log-gha "$dir/out.gha" \ + "$dir/a/same_test.sh" "$dir/b/same_test.sh" >"$dir/console" 2>&1 || exit_code=$? + + assert_same 1 "$exit_code" + assert_file_contains "$dir/out.json" '"total": 8, "passed": 3, "failed": 4, "skipped": 1' + assert_file_contains "$dir/out.json" '"flaky": 1' + assert_same 8 "$("$GREP" -c '"name":' "$dir/out.json")" + assert_same 8 "$("$GREP" -c '"$dir/release" + wait "$delayed_pid" + + bashunit::reports::load_spooled + + assert_same 3 "${#_BASHUNIT_REPORTS_TEST_NAMES[@]}" + assert_same "first published" "${_BASHUNIT_REPORTS_TEST_NAMES[0]}" + assert_same "parent failure" "${_BASHUNIT_REPORTS_TEST_NAMES[1]}" + assert_same delayed "${_BASHUNIT_REPORTS_TEST_NAMES[2]}" +} + +function test_parallel_spool_preserves_open_file_descriptors() { + local dir + dir="$(bashunit::temp_dir)" + local REPORTS_OUTPUT_PATH="$dir/records" + local BASHUNIT_REPORT_JSON="$dir/out.json" + local _BASHUNIT_PARALLEL_ENABLED=true + local _BASHUNIT_REPORTS_RECORD_SCOPE=control + local remaining="" + printf 'caller input\n' >"$dir/input" + bashunit::reports::add_test_passed "file.sh" "test" 0 1 + + { + bashunit::reports::load_spooled + IFS= read -r remaining 2>/dev/null <&9 || true + } 9<"$dir/input" + + assert_same "caller input" "$remaining" +} + +function test_parallel_spool_skips_incomplete_records_and_sidecars() { + local dir + dir="$(bashunit::temp_dir)" + local REPORTS_OUTPUT_PATH="$dir/records" + local BASHUNIT_REPORT_JSON="$dir/out.json" + local _BASHUNIT_PARALLEL_ENABLED=true + local _BASHUNIT_REPORTS_RECORD_SCOPE=control + local _BASHUNIT_RUNNER_RESULT_ORDINAL=4 + local truncated_token=0000000100000001000000001 + local missing_token=0000000100000002000000001 + local incomplete_token=0000000100000003000000001 + local truncated="$REPORTS_OUTPUT_PATH.$truncated_token.record" + local missing="$REPORTS_OUTPUT_PATH.$missing_token.record" + local incomplete="$REPORTS_OUTPUT_PATH.$incomplete_token.record" + printf '%s\0' "file.sh" "truncated" >"$truncated" + printf '%s\0' "file.sh" "missing" failed 0 0 "" 0 1 0 >"$missing" + printf '%s\0' "file.sh" "incomplete" passed 0 1 "" 0 0 1 >"$incomplete" + printf '%s' "unfinished output" >"$incomplete.output" + printf '%s' "orphaned field_" >"$REPORTS_OUTPUT_PATH.orphan.record.failure" + printf '%s\n' "$truncated_token" "$missing_token" "$incomplete_token" >"$REPORTS_OUTPUT_PATH" + bashunit::reports::add_test_passed "file.sh" "complete" 0 1 + + bashunit::reports::load_spooled 2>"$dir/warnings" + + assert_same 1 "${#_BASHUNIT_REPORTS_TEST_NAMES[@]}" + assert_same complete "${_BASHUNIT_REPORTS_TEST_NAMES[0]}" + assert_file_contains "$dir/warnings" "incomplete report record $truncated" + assert_file_contains "$dir/warnings" "missing report field $missing.failure" + assert_file_contains "$dir/warnings" "incomplete report field $incomplete.output" +} + # === Wrapper function tests === function test_add_test_snapshot_sets_snapshot_status() {