From ed72fc0315da4df3b3199c1752a4fdb3654cce6c Mon Sep 17 00:00:00 2001 From: helly25 <6420169+helly25@users.noreply.github.com> Date: Sun, 25 Oct 2026 20:20:38 +0000 Subject: [PATCH 1/2] Stream test output and preserve interruption checkpoints --- CHANGELOG.md | 4 + README.md | 6 +- bashtest/README.md | 37 ++- bashtest/bashtest.sh | 293 +++++++++++++++++++++-- bashtest/tests/external_consumer_test.sh | 54 +++++ bashtest/tests/junit_test.sh | 57 ++++- tools/junit_test.py | 161 ++++++++++++- 7 files changed, 574 insertions(+), 38 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index a3113c8..70f1ca0 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,5 +1,9 @@ # 0.7.1 +* Stream stdout/stderr live while capturing JUnit output without losing shared + test state. Write provisional active-function reports for interrupted runs, + drain capture workers before final results, and fail on capture/report errors. + * Report source locations for failed expectations, including user helpers and subshells. Print golden-file diffs on stderr by default and capture them in JUnit failure reports, without duplicating diffs in verbose mode. diff --git a/README.md b/README.md index 721d986..e9e5daf 100644 --- a/README.md +++ b/README.md @@ -50,7 +50,8 @@ for filter precedence, shard assignment, and teardown behavior. Failed expectations include their source file and line. Golden-file failures print unified diffs on stderr and include them in JUnit reports without requiring -`--verbose`; see [failure diagnostics](bashtest/README.md#failure-diagnostics). +`--verbose`. Output streams live while reports capture it, and an interrupted run +leaves a provisional report identifying the last active function; see [failure diagnostics](bashtest/README.md#failure-diagnostics). ### Example @@ -109,7 +110,8 @@ hand-rolled pipelines. ## Installation and requirements Linux and macOS require Bash and Unix utilities (`coreutils`, `diff`, `sed`, and -`grep`); PCRE assertions need a supported PCRE tool. +`grep`); JUnit reporting also uses `head`, `tail`, `tee`, and `wc` (plus the system +`ps` on macOS). PCRE assertions need a supported PCRE tool. On Windows x86-64, `bashtest` automatically downloads a pinned MSYS2 runtime, including Bash, coreutils, diffutils, grep with PCRE support, sed, and their DLLs. diff --git a/bashtest/README.md b/bashtest/README.md index 7d6a626..404b15f 100644 --- a/bashtest/README.md +++ b/bashtest/README.md @@ -80,7 +80,8 @@ A failed expectation remains a failure even if its return status is handled or followed by a successful command. This includes expectations in command substitutions, `(subshells)`, and background jobs that the test waits for. `test_has_error` sees these failures in the parent shell. Tests must wait for -background work before returning. Each test and lifecycle hook starts with a +background assertion work before returning; long-lived services may instead +be stopped in teardown. Each test and lifecycle hook starts with a fresh error state; failures do not leak into subsequent cases. By default, ordinary commands follow Bash's final-return-status semantics. @@ -207,10 +208,19 @@ keep the location independent of Bazel's working directory. An empty `GTEST_OUTPUT` or `--gtest_output=` disables reporting. JSON output is unsupported; an unsupported format or failure to write a report makes the test fail. -With reporting enabled, function output is buffered and replayed after each -function, while functions continue to run in the same shell. Setup and teardown -state remains visible to the tests. Failed `test_init` and `test_done` hooks appear -as additional error cases; successful hooks do not count as test cases. Filters +With reporting enabled, function output streams to its original stdout/stderr +while a copy is captured for the report. Standard `head`, `tail`, `tee`, and `wc` tools +must be available on `PATH`; they are included in the managed Windows runtime. +macOS also uses its system `ps` to detect an exited, unreaped coordinator. +Functions still run in the same shell, and setup/teardown state remains visible +to the tests. Capture workers do not +join a test's `wait` or `wait -n`. Background services may keep writing across +setup, cases, and teardown; captured output is attributed to the function active +when it was written. Output between functions is still streamed. Tests should +wait for background assertions before returning and stop services in teardown. +A capture failure makes the test fail as a reporting error rather than silently +losing output. Failed `test_init` and `test_done` hooks appear as additional error +cases; successful hooks do not count as test cases. Filters produce skipped cases, and `--no-skip` turns runtime skip requests into failures. An assertion failure or nonzero function return always takes precedence over a skip request, even if the skip happens after the failure. Invalid extended @@ -219,9 +229,20 @@ syntax-error diagnostic. The existing exit code 2 for no passing or failing cases is retained and recorded as a `test_runner` error. An early exit or a catchable signal during a function records that function as an error and retains a nonzero exit status; `exit 0` -inside a function is also an error because it aborts the runner. SIGKILL and -machine termination cannot be handled; Bazel supplies its fallback reporting when -no custom report exists. Reporting begins when `test_runner` is called. +inside a function is also an error because it aborts the runner. + +Before each setup, test, or teardown function, the runner atomically writes a +provisional report containing completed cases and an error for the function +about to run. Its message explicitly labels the report provisional. A completed +run replaces that checkpoint with final results. Termination without cleanup, +such as SIGKILL, leaves the last written checkpoint identifying the function +whose completion was not yet recorded. Readers detect coordinator death, drain +a finite snapshot, and exit even without a stop request. Output already streamed +remains in Bazel's test log; use +`--test_output=streamed` to see output while Bazel runs. Catchable signals finalize +the report with available output. A failed progress-report write prevents the +function from running and fails the target. Reporting begins at `test_runner`; +if termination happens before any report exists, Bazel supplies its fallback. Nested runner/verifier scripts should select their own output file, or disable reporting with `GTEST_OUTPUT=`, so an expected failure does not become the parent diff --git a/bashtest/bashtest.sh b/bashtest/bashtest.sh index 9fabbbd..ab05156 100644 --- a/bashtest/bashtest.sh +++ b/bashtest/bashtest.sh @@ -281,6 +281,9 @@ _BASHTEST_XML_TESTS=0 _BASHTEST_XML_FAILURES=0 _BASHTEST_XML_ERRORS=0 _BASHTEST_XML_SKIPPED=0 +_BASHTEST_CAPTURE_RUNNING=0 +_BASHTEST_CAPTURE_FAILED=0 +_BASHTEST_CAPTURE_BROKEN=0 function _bashtest_cleanup () { # Capture FIRST and re-exit with it at the end: a trap's own last command otherwise becomes the @@ -292,7 +295,7 @@ function _bashtest_cleanup () { if [[ -n "${_BASHTEST_XML_ACTIVE}" ]]; then # A fatal exit runs this trap inside the function's log redirection. exec 1>&198 2>&199 - _bashtest_xml_replay + _bashtest_capture_case_finish _bashtest_xml_case error "${_BASHTEST_XML_ACTIVE}" "Test program exited before the function completed (exit ${status})." [[ "${status}" != 0 ]] || status=1 elif [[ "${_BASHTEST_XML_RUNNING}" == 1 ]]; then @@ -301,6 +304,12 @@ function _bashtest_cleanup () { elif [[ "${status}" != 0 && "${_BASHTEST_XML_STARTED}" == 1 && "${_BASHTEST_XML_FAILURES}" == 0 && "${_BASHTEST_XML_ERRORS}" == 0 ]]; then _bashtest_xml_case error test_program "Test program exited with status ${status}." fi + if ! _bashtest_capture_stop; then + if [[ "${_BASHTEST_XML_ERRORS}" == 0 ]]; then + _bashtest_xml_case error test_runner "Output capture did not complete." + fi + [[ "${status}" != 0 ]] || status=1 + fi if [[ "${_BASHTEST_XML_STARTED}" == 1 ]] && ! _bashtest_xml_write; then echo >&2 "ERROR: Cannot write JUnit report: ${_BASHTEST_XML_PATH}" [[ "${status}" != 0 ]] || status=1 @@ -423,6 +432,14 @@ _bashtest_xml_init() { /*|[a-zA-Z]:/*|[a-zA-Z]:\\*) ;; *) _BASHTEST_XML_PATH="${PWD}/${_BASHTEST_XML_PATH}" ;; esac + _BASHTEST_HEAD="$(type -P head)" || die "JUnit reporting requires head on PATH." + _BASHTEST_TAIL="$(type -P tail)" || die "JUnit reporting requires tail on PATH." + _BASHTEST_WC="$(type -P wc)" || die "JUnit reporting requires wc on PATH." + _BASHTEST_TEE="$(type -P tee)" || die "JUnit reporting requires tee on PATH." + _BASHTEST_PS= + case "${OSTYPE}" in + darwin*) _BASHTEST_PS="$(type -P ps)" || die "JUnit reporting requires ps on macOS." ;; + esac mkdir -p "$(dirname "${_BASHTEST_XML_PATH}")" || die "Cannot create test report directory." _BASHTEST_XML_CASES="${BASHTEST_TMPDIR}/junit-cases.xml" : > "${_BASHTEST_XML_CASES}" @@ -505,31 +522,227 @@ expect_success() { expect_exit_code 0 ${@+"${@}"} } -# Execute in this shell: state set by setup and test functions must remain visible. -# Only report-enabled runs buffer output, replaying it after each function. +# Copy a bounded byte range and retain the exact bytes written. A completed +# prefix intentionally closes tail's pipe; with SIGPIPE ignored tail returns a +# write error instead of 141. Validate the copied length, head, and tee so that +# expected upstream closure cannot hide an incomplete read or failed output. +_bashtest_capture_range() { + local statuses=() actual + : > "${4}" || return 1 + [[ "${3}" != 0 ]] || return 0 + (( ${3} >= 0 )) || return 1 + "${_BASHTEST_TAIL}" -c "+$(( ${2} + 1 ))" "${1}" 2> "${4}.source-error" | "${_BASHTEST_HEAD}" -c "${3}" | "${_BASHTEST_TEE}" "${4}" + statuses=("${PIPESTATUS[@]}") + actual="$("${_BASHTEST_WC}" -c < "${4}")" || return 1 + if [[ "${statuses[1]}" == 0 && "${statuses[2]}" == 0 ]] && (( actual == ${3} )); then + return 0 + fi + printf >&2 'ERROR: Incomplete captured output: expected %s bytes, copied %s (tail=%s, head=%s, tee=%s).\n' "${3}" "$((actual))" "${statuses[0]}" "${statuses[1]}" "${statuses[2]}" + cat "${4}.source-error" >&2 + return 1 +} + +# Signal 0 also succeeds for Unix zombies. A caller collecting output may not +# reap the coordinator until our pipes close, so detect that state explicitly. +_bashtest_capture_parent_alive() { + kill -0 "${1}" 2>/dev/null || return 1 + local field state rest + if [[ -r "/proc/${1}/status" ]]; then + while IFS=$' \t' read -r field state rest; do + if [[ "${field}" == State: ]]; then + [[ "${state}" != Z && "${state}" != X && "${state}" != x ]] + return + fi + done < "/proc/${1}/status" 2>/dev/null + elif [[ -n "${_BASHTEST_PS}" ]]; then + # A process can disappear during this optional query. The next signal-0 + # check handles that race; sandboxed ps can also lack inspection rights. + state="$("${_BASHTEST_PS}" -p "${1}" -o stat= 2>/dev/null)" || return 0 + [[ "${state}" != *Z* && "${state}" != *X* ]] || return 1 + fi + return 0 +} + +# Readers remain shell children (and are reaped), but are disowned from its job +# list so a user's wait/wait -n never waits for infrastructure. Journals avoid +# waiting for EOF from a long-lived service started in setup. +_bashtest_capture_worker() { + trap - EXIT + local position=0 target count stopping status=0 cancelled=0 orphan_target="" checked=-1 alive + trap 'cancelled=1' HUP INT QUIT TERM + printf '0\n' > "${2}" || return 1 + while :; do + if [[ "${cancelled}" == 1 ]]; then status=1; break; fi + stopping=0 + if [[ -n "${orphan_target}" ]]; then + target="${orphan_target}" + stopping=1 + elif [[ -s "${3}" ]] && IFS= read -r target < "${3}"; then + stopping=1 + else + target="$("${_BASHTEST_WC}" -c < "${1}")" || { status=1; break; } + target=$((target)) + alive=1 + if ! kill -0 "${5}" 2>/dev/null; then + alive=0 + elif [[ "${checked}" != "${SECONDS}" ]]; then + checked="${SECONDS}" + _bashtest_capture_parent_alive "${5}" || alive=0 + fi + if [[ "${alive}" == 0 ]]; then + # A hard-killed coordinator cannot send a stop request. Flush + # one finite snapshot, then exit instead of leaving a reader. + orphan_target="${target}" + stopping=1 + status=1 + fi + fi + if (( target < position && stopping == 0 )); then status=1; break; fi + if (( position < target )); then + count=$((target - position)) + # Bounded copies keep cancellation responsive even for large output. + if (( count > 1048576 )); then count=1048576; fi + if ! _bashtest_capture_range "${1}" "${position}" "${count}" "${2}.chunk"; then + status=1 + break + fi + ((position+=count)) + printf '%s\n' "${position}" > "${2}" || { status=1; break; } + if (( position < target )); then continue; fi + fi + [[ "${stopping}" != 1 ]] || break + sleep 0.02 + done + printf '%s\n' "${status}" > "${4}" +} + +_bashtest_capture_start() { + _BASHTEST_CAPTURE_OUT="${BASHTEST_TMPDIR}/stdout.journal" + _BASHTEST_CAPTURE_ERR="${BASHTEST_TMPDIR}/stderr.journal" + : > "${_BASHTEST_CAPTURE_OUT}" || return 1 + : > "${_BASHTEST_CAPTURE_ERR}" || return 1 + _BASHTEST_CAPTURE_OUT_PID= + _BASHTEST_CAPTURE_ERR_PID= + # $$ is not the actual PID in a Bash 3.2 subshell. Query a fresh child so + # readers can detect coordinator death even there, without running BASH_ENV. + # shellcheck disable=SC2016 # PPID expands in the child, not in this shell. + BASH_ENV="" "${BASH}" -c 'builtin printf "%s\n" "${PPID}"' > "${BASHTEST_TMPDIR}/capture-parent.pid" || return 1 + IFS= read -r _BASHTEST_CAPTURE_PARENT < "${BASHTEST_TMPDIR}/capture-parent.pid" || return 1 + [[ "${_BASHTEST_CAPTURE_PARENT}" =~ ^[1-9][0-9]*$ ]] || return 1 + _BASHTEST_CAPTURE_RUNNING=1 + _bashtest_capture_worker "${_BASHTEST_CAPTURE_OUT}" "${BASHTEST_TMPDIR}/stdout.progress" "${BASHTEST_TMPDIR}/stdout.stop" "${BASHTEST_TMPDIR}/stdout.done" "${_BASHTEST_CAPTURE_PARENT}" & + _BASHTEST_CAPTURE_OUT_PID="${!}" + disown "${_BASHTEST_CAPTURE_OUT_PID}" || return 1 + _bashtest_capture_worker "${_BASHTEST_CAPTURE_ERR}" "${BASHTEST_TMPDIR}/stderr.progress" "${BASHTEST_TMPDIR}/stderr.stop" "${BASHTEST_TMPDIR}/stderr.done" "${_BASHTEST_CAPTURE_PARENT}" >&2 & + _BASHTEST_CAPTURE_ERR_PID="${!}" + disown "${_BASHTEST_CAPTURE_ERR_PID}" || return 1 + _bashtest_capture_wait "${_BASHTEST_CAPTURE_OUT_PID}" "${BASHTEST_TMPDIR}/stdout.progress" "${BASHTEST_TMPDIR}/stdout.done" 0 || return 1 + _bashtest_capture_wait "${_BASHTEST_CAPTURE_ERR_PID}" "${BASHTEST_TMPDIR}/stderr.progress" "${BASHTEST_TMPDIR}/stderr.done" 0 +} + +_bashtest_capture_wait() { + local position + while :; do + # A completed worker is unexpected until the runner requests shutdown. + [[ ! -s "${3}" ]] || return 1 + kill -0 "${1}" 2>/dev/null || return 1 + # A concurrent progress update can briefly truncate this file. Retry an + # incomplete read while the worker is alive, rather than losing output. + if [[ -s "${2}" ]] && IFS= read -r position < "${2}"; then + if (( position >= ${4} )); then return 0; fi + fi + sleep 0.01 + done +} + +_bashtest_capture_error() { + if [[ "${_BASHTEST_CAPTURE_BROKEN}" == 0 ]]; then + echo >&2 'ERROR: Cannot capture test output completely.' + fi + _BASHTEST_CAPTURE_FAILED=1 + _BASHTEST_CAPTURE_BROKEN=1 + _BASHTEST_RUNNER_FAILED=1 + _bashtest_record_failure +} + +_bashtest_capture_case_finish() { + local out_end err_end status=0 + out_end="$("${_BASHTEST_WC}" -c < "${_BASHTEST_CAPTURE_OUT}")" || status=1 + err_end="$("${_BASHTEST_WC}" -c < "${_BASHTEST_CAPTURE_ERR}")" || status=1 + out_end=$((out_end)) + err_end=$((err_end)) + _bashtest_capture_wait "${_BASHTEST_CAPTURE_OUT_PID}" "${BASHTEST_TMPDIR}/stdout.progress" "${BASHTEST_TMPDIR}/stdout.done" "${out_end}" || status=1 + _bashtest_capture_wait "${_BASHTEST_CAPTURE_ERR_PID}" "${BASHTEST_TMPDIR}/stderr.progress" "${BASHTEST_TMPDIR}/stderr.done" "${err_end}" || status=1 + _bashtest_capture_range "${_BASHTEST_CAPTURE_OUT}" "${_BASHTEST_CAPTURE_OUT_START}" "$((out_end - _BASHTEST_CAPTURE_OUT_START))" "${_BASHTEST_XML_STDOUT}" > /dev/null || status=1 + _bashtest_capture_range "${_BASHTEST_CAPTURE_ERR}" "${_BASHTEST_CAPTURE_ERR_START}" "$((err_end - _BASHTEST_CAPTURE_ERR_START))" "${_BASHTEST_XML_STDERR}" > /dev/null || status=1 + cat "${_BASHTEST_XML_STDOUT}" "${_BASHTEST_XML_STDERR}" > "${_BASHTEST_XML_LOG}" || status=1 + if [[ "${status}" != 0 ]]; then _bashtest_capture_error; fi +} + +_bashtest_capture_stop() { + [[ "${_BASHTEST_CAPTURE_RUNNING}" == 1 ]] || return 0 + local stream pid target status=0 result + # Request both streams before waiting. EXIT cleanup may interrupt this + # function; keep requests stable and let cleanup finish the same shutdown. + for stream in stdout stderr; do + if [[ -s "${BASHTEST_TMPDIR}/${stream}.stop" ]]; then continue; fi + if [[ "${stream}" == stdout ]]; then pid="${_BASHTEST_CAPTURE_OUT_PID}"; else pid="${_BASHTEST_CAPTURE_ERR_PID}"; fi + target="$("${_BASHTEST_WC}" -c < "${BASHTEST_TMPDIR}/${stream}.journal")" || status=1 + if ! printf '%s\n' "$((target))" > "${BASHTEST_TMPDIR}/${stream}.stop"; then + status=1 + [[ -z "${pid}" ]] || kill "${pid}" 2>/dev/null || true + fi + done + for stream in stdout stderr; do + if [[ "${stream}" == stdout ]]; then pid="${_BASHTEST_CAPTURE_OUT_PID}"; else pid="${_BASHTEST_CAPTURE_ERR_PID}"; fi + while [[ ! -s "${BASHTEST_TMPDIR}/${stream}.done" ]]; do + if ! kill -0 "${pid}" 2>/dev/null; then break; fi + sleep 0.01 + done + result=1 + if [[ -s "${BASHTEST_TMPDIR}/${stream}.done" ]]; then + IFS= read -r result < "${BASHTEST_TMPDIR}/${stream}.done" || status=1 + else + status=1 + fi + [[ "${result}" == 0 ]] || status=1 + done + _BASHTEST_CAPTURE_RUNNING=0 + if [[ "${status}" != 0 ]]; then _bashtest_capture_error; fi + return "${status}" +} + +# Execute in this shell. Append-only journals also accept output from services +# that remain alive across setup/test/teardown. Report each function's byte window. _bashtest_invoke() { _BASHTEST_RESULT=0 + _BASHTEST_CAPTURE_FAILED=0 if [[ "${_BASHTEST_XML_STARTED}" == 0 ]]; then _bashtest_execute "${1}" else - _BASHTEST_XML_ACTIVE="${1#test::}" - _BASHTEST_XML_CASE_START="${SECONDS}" - _BASHTEST_XML_LOG="${BASHTEST_TMPDIR}/junit-current.log" - _BASHTEST_XML_STDOUT="${BASHTEST_TMPDIR}/junit-stdout.log" - _BASHTEST_XML_STDERR="${BASHTEST_TMPDIR}/junit-stderr.log" - _bashtest_execute "${1}" 198>&1 199>&2 > "${_BASHTEST_XML_STDOUT}" 2> "${_BASHTEST_XML_STDERR}" - _bashtest_xml_replay - fi - # A successful final command must not erase a failure in a descendant shell. - if test_has_error; then - _BASHTEST_HAS_ERROR=1 + { + _BASHTEST_CAPTURE_OUT_START="$("${_BASHTEST_WC}" -c < "${_BASHTEST_CAPTURE_OUT}")" + _BASHTEST_CAPTURE_ERR_START="$("${_BASHTEST_WC}" -c < "${_BASHTEST_CAPTURE_ERR}")" + _BASHTEST_XML_CASE_START="${SECONDS}" + _BASHTEST_XML_LOG="${BASHTEST_TMPDIR}/junit-current.log" + _BASHTEST_XML_STDOUT="${BASHTEST_TMPDIR}/junit-stdout.log" + _BASHTEST_XML_STDERR="${BASHTEST_TMPDIR}/junit-stderr.log" + : > "${_BASHTEST_XML_LOG}" + : > "${_BASHTEST_XML_STDOUT}" + : > "${_BASHTEST_XML_STDERR}" + _BASHTEST_XML_ACTIVE="${1#test::}" + if ! _bashtest_xml_write 1; then + _BASHTEST_CAPTURE_FAILED=1 + _BASHTEST_RUNNER_FAILED=1 + _bashtest_record_failure + echo >&2 "ERROR: Cannot write JUnit progress report: ${_BASHTEST_XML_PATH}" + else + _bashtest_execute "${1}" >> "${_BASHTEST_CAPTURE_OUT}" 2>> "${_BASHTEST_CAPTURE_ERR}" + _bashtest_capture_case_finish + fi + } 198>&1 199>&2 fi -} - -_bashtest_xml_replay() { - cat "${_BASHTEST_XML_STDOUT}" - cat "${_BASHTEST_XML_STDERR}" >&2 - cat "${_BASHTEST_XML_STDOUT}" "${_BASHTEST_XML_STDERR}" > "${_BASHTEST_XML_LOG}" + if test_has_error; then _BASHTEST_HAS_ERROR=1; fi } # Append one case. Hooks are recorded only on failure, leaving test counts useful. @@ -571,14 +784,23 @@ _bashtest_xml_case() { _bashtest_xml_write() { [[ "${_BASHTEST_XML_STARTED}" == 1 ]] || return 0 - local temporary elapsed="$((SECONDS - _BASHTEST_XML_START))" + local temporary elapsed="$((SECONDS - _BASHTEST_XML_START))" provisional="${1:-0}" + local tests="${_BASHTEST_XML_TESTS}" errors="${_BASHTEST_XML_ERRORS}" + if [[ "${provisional}" == 1 ]]; then + ((tests+=1)) + ((errors+=1)) + fi temporary="$(mktemp "${_BASHTEST_XML_PATH}.XXXXXX")" || return 1 { printf '\n\n' \ - "${_BASHTEST_XML_TESTS}" "${_BASHTEST_XML_FAILURES}" "${_BASHTEST_XML_ERRORS}" "${_BASHTEST_XML_SKIPPED}" "${elapsed}" + "${tests}" "${_BASHTEST_XML_FAILURES}" "${errors}" "${_BASHTEST_XML_SKIPPED}" "${elapsed}" printf ' \n' \ - "$(_bashtest_xml_attribute "${_BASHTEST_XML_SUITE}")" "${_BASHTEST_XML_TESTS}" "${_BASHTEST_XML_FAILURES}" "${_BASHTEST_XML_ERRORS}" "${_BASHTEST_XML_SKIPPED}" "${elapsed}" + "$(_bashtest_xml_attribute "${_BASHTEST_XML_SUITE}")" "${tests}" "${_BASHTEST_XML_FAILURES}" "${errors}" "${_BASHTEST_XML_SKIPPED}" "${elapsed}" cat "${_BASHTEST_XML_CASES}" + if [[ "${provisional}" == 1 ]]; then + printf ' \n' \ + "$(_bashtest_xml_attribute "${_BASHTEST_XML_ACTIVE}")" "$(_bashtest_xml_attribute "${_BASHTEST_XML_SUITE}")" + fi printf ' \n\n' } > "${temporary}" && mv -f "${temporary}" "${_BASHTEST_XML_PATH}" } @@ -656,7 +878,11 @@ function _bashtest_handler() { _BASHTEST_SKIP_REASON= _bashtest_invoke "${FUNC_NAME}" # A skip request cannot erase an assertion failure or a nonzero return. - if [[ "${_BASHTEST_RESULT}" != "0" || "${_BASHTEST_HAS_ERROR}" != "0" ]]; then + if [[ "${_BASHTEST_CAPTURE_FAILED}" == 1 ]]; then + echo >&2 "[ FAIL ] ${TEST_NAME} (test output/reporting error)" + ((_BASHTEST_NUM_FAIL+=1)) + _bashtest_xml_case error "${TEST_NAME}" "Test output capture or progress reporting failed." + elif [[ "${_BASHTEST_RESULT}" != "0" || "${_BASHTEST_HAS_ERROR}" != "0" ]]; then echo >&2 "[ FAIL ] ${TEST_NAME}" ((_BASHTEST_NUM_FAIL+=1)) _bashtest_xml_case failure "${TEST_NAME}" "Test failed (exit ${_BASHTEST_RESULT}, expectation error ${_BASHTEST_HAS_ERROR})." @@ -732,6 +958,15 @@ function test_runner() { _bashtest_xml_write || return 1 return 1 fi + if [[ "${_BASHTEST_XML_STARTED}" == 1 ]] && ! _bashtest_capture_start; then + _bashtest_capture_stop || true + _BASHTEST_RUNNER_FAILED=1 + echo >&2 'ERROR: Cannot start test output capture.' + _bashtest_xml_case error test_runner "Cannot start test output capture." + _BASHTEST_XML_RUNNING=0 + _bashtest_xml_write || return 1 + return 1 + fi if [[ -n "${_BASHTEST_FILTER_GLOB}" ]]; then echo "Test filter glob: '${_BASHTEST_FILTER_GLOB}'." fi @@ -793,6 +1028,11 @@ function test_runner() { fi echo "----------" fi + if ! _bashtest_capture_stop; then + if [[ "${_BASHTEST_XML_ERRORS}" == 0 ]]; then + _bashtest_xml_case error test_runner "Output capture did not complete." + fi + fi if [[ "${empty_shard}" == 0 && "${_BASHTEST_NUM_PASS}" == 0 && "${_BASHTEST_NUM_FAIL}" == 0 && "${_BASHTEST_INIT_FAILED}" == 0 ]]; then _bashtest_xml_case error test_runner "No tests were run." fi @@ -806,6 +1046,11 @@ function test_runner() { echo "SKIP: ${_BASHTEST_NUM_SKIP}" echo >&2 "FAIL: ${_BASHTEST_NUM_FAIL}" echo "----------" + if [[ "${_BASHTEST_CAPTURE_BROKEN}" == 1 ]]; then + _BASHTEST_RUNNER_FAILED=1 + echo >&2 'ERROR: Test output capture failed.' + return 1 + fi if [[ "${_BASHTEST_INIT_FAILED}" -ne "0" ]]; then _BASHTEST_RUNNER_FAILED=1 echo >&2 "ERROR: Test initialization failed." diff --git a/bashtest/tests/external_consumer_test.sh b/bashtest/tests/external_consumer_test.sh index 02c1fda..96ea552 100755 --- a/bashtest/tests/external_consumer_test.sh +++ b/bashtest/tests/external_consumer_test.sh @@ -217,3 +217,57 @@ for target in "${selection_targets[@]}"; do fi echo "[EXPECTED FAILURE: fail-fast fixture] ${target}: later cases skipped and teardown ran" done + +# Verify an actual Bazel timeout keeps the active function's custom report and +# the last live diagnostic, on managed Windows as well as Unix. +cat >> BUILD.bazel <<'EOF' +bashtest( + name = "interrupted_test", + srcs = ["interrupted.sh"], + tags = ["manual"], +) +EOF +cat > interrupted.sh <<'EOF' +#!/usr/bin/env bash +set -euo pipefail +# shellcheck disable=SC1090,SC1091,SC2154 +source "${mboworks_bashtest}" +# shellcheck disable=SC2317 +test::a_completed() { expect_eq ok ok; } +# shellcheck disable=SC2317 +test::b_hanging() { + echo last_diagnostic_before_timeout >&2 + while :; do sleep 1; done +} +test_runner +EOF +chmod +x interrupted.sh +interrupted_targets=(//:interrupted_test) +case "${OSTYPE}" in + msys*|cygwin*) ;; + *) + cat >> BUILD.bazel <<'EOF' +sh_test( + name = "interrupted_sh_test", + srcs = ["interrupted.sh"], + data = ["@framework//bashtest:bashtest_sh"], + env = {"mboworks_bashtest": "$(rootpath @framework//bashtest:bashtest_sh)"}, + tags = ["manual"], +) +EOF + interrupted_targets+=(//:interrupted_sh_test) + ;; +esac +if bazel test --enable_runfiles=no --test_timeout=10 "${interrupted_targets[@]}" > interrupted.log 2>&1; then + echo >&2 'ERROR: intentionally hanging fixtures passed' + exit 1 +fi +for target in "${interrupted_targets[@]}"; do + grep -F "${target}" interrupted.log | grep -F TIMEOUT >/dev/null + report="${junit_logs}/${target#//:}/test.xml" + grep -F 'name="a_completed"' "${report}" >/dev/null + grep -F 'name="b_hanging"' "${report}" >/dev/null + grep -F '/dev/null + grep -F last_diagnostic_before_timeout "${junit_logs}/${target#//:}/test.log" >/dev/null + echo "[EXPECTED FAILURE: timeout fixture] ${target}: active-case error report and live diagnostic retained" +done diff --git a/bashtest/tests/junit_test.sh b/bashtest/tests/junit_test.sh index 20ddba4..a2e96c0 100755 --- a/bashtest/tests/junit_test.sh +++ b/bashtest/tests/junit_test.sh @@ -233,7 +233,7 @@ test::body() { case "${PROBE}" in failure) expect_eq yes no ;; abort) exit 42 ;; - report) rmdir "${REPORT_DIRECTORY}" ;; + report) mv "${REPORT_DIRECTORY}" "${REPORT_DIRECTORY}.moved" ;; esac } test::test_done() { if [[ "${PROBE}" == teardown ]]; then return 7; fi; } @@ -267,4 +267,59 @@ PROBE done } +# shellcheck disable=SC2317 # Functions are discovered by test_runner. +test::live_output_and_progress_report() { + local root pid attempt output observed=0 status=0 + root="$(test_tmpdir live)" + cat > "${root}/probe.sh" <<'PROBE' +set -euo pipefail +# shellcheck disable=SC1090,SC1091,SC2154 +source "${mboworks_bashtest}" +test::live() { + # Framework capture workers must not cause an unqualified wait to hang. + wait + if (( BASH_VERSINFO[0] > 4 || (BASH_VERSINFO[0] == 4 && BASH_VERSINFO[1] >= 3) )); then + local status=0 + wait -n || status="${?}" + expect_eq 127 "${status}" + fi + printf '%s' live_stdout_token + printf '%s' live_stderr_token >&2 + while [[ ! -e "${RELEASE}" ]]; do sleep 0.02; done +} +test::server_start() { + "${BASH}" -c 'exec sleep 10' & + server_pid="${!}" +} +test::server_use() { kill -0 "${server_pid}"; echo service_alive; } +test::test_done() { kill "${server_pid}"; wait "${server_pid}" || :; } +test_runner +PROBE + _junit_probe "GTEST_OUTPUT=xml:${root}/result.xml" "RELEASE=${root}/release" \ + "${BASH}" "${root}/probe.sh" > "${root}/stdout" 2> "${root}/stderr" & + pid="${!}" + for ((attempt=0; attempt<200; attempt++)); do + if grep -F live_stdout_token "${root}/stdout" >/dev/null && grep -F live_stderr_token "${root}/stderr" >/dev/null; then + observed=1 + break + fi + sleep 0.05 + done + expect_eq 1 "${observed}" + output="$(cat "${root}/result.xml")" + expect_output_contains 'provisional while it is running' "${output}" + expect_output_contains 'tests="1" failures="0" errors="1"' "${output}" + # Always release the fixture, including after a failed expectation above. + : > "${root}/release" + wait "${pid}" || status="${?}" + expect_eq 0 "${status}" + expect_eq 1 "$(grep -c live_stdout_token "${root}/stdout")" + expect_eq 1 "$(grep -c live_stderr_token "${root}/stderr")" + output="$(cat "${root}/result.xml")" + expect_output_contains 'tests="3" failures="0" errors="0"' "${output}" + expect_output_contains service_alive "$(cat "${root}/stdout")" + expect_output_contains live_stdout_token "${output}" + expect_output_contains live_stderr_token "${output}" +} + test_runner diff --git a/tools/junit_test.py b/tools/junit_test.py index 6b82a1a..be9f83d 100644 --- a/tools/junit_test.py +++ b/tools/junit_test.py @@ -3,6 +3,9 @@ """Parse actual runner reports and verify JUnit/GoogleTest output contracts.""" import os +import selectors +import signal +import time from pathlib import Path import subprocess import tempfile @@ -20,7 +23,7 @@ def setUp(self): self.root = Path(temporary.name) self.xml = self.root / 'bazel result.xml' - def run_probe(self, body, *args, output=True, runner='test_runner', **environment): + def run_probe(self, body, *args, output=True, runner='test_runner', background=False, **environment): script = self.root / 'probe.sh' script.write_text('set -euo pipefail\nsource "$LIBRARY"\n' + body + '\n' + runner + '\n') env = {key: value for key, value in os.environ.items() @@ -31,6 +34,9 @@ def run_probe(self, body, *args, output=True, runner='test_runner', **environmen if output: env['XML_OUTPUT_FILE'] = str(self.xml) env.update(environment) + if background: + return subprocess.Popen(['bash', str(script), *args], cwd=self.root, env=env, + stdout=subprocess.PIPE, stderr=subprocess.PIPE, start_new_session=True) return subprocess.run(['bash', str(script), *args], cwd=self.root, env=env, capture_output=True, timeout=10) @@ -241,6 +247,155 @@ def test_golden_diff_is_in_stderr_and_xml_without_verbose(self): self.assertIn('+new & text', case.find('system-err').text) self.assertIn('+new & text', Path(str(actual) + '.diff').read_text()) + def observe_live_output(self, process): + captured = {'stdout': b'', 'stderr': b''} + deadline = time.monotonic() + 5 + with selectors.DefaultSelector() as selector: + selector.register(process.stdout, selectors.EVENT_READ, 'stdout') + selector.register(process.stderr, selectors.EVENT_READ, 'stderr') + while time.monotonic() < deadline: + for key, _ in selector.select(timeout=0.1): + chunk = os.read(key.fd, 65536) + if chunk: + captured[key.data] += chunk + else: + selector.unregister(key.fileobj) + if b'live_stdout_token' in captured['stdout'] and b'live_stderr_token' in captured['stderr']: + return captured + if process.poll() is not None: + break + self.fail(f'Output was not live: {captured}; process status={process.poll()}') + + def stop_probe(self, process): + try: + os.killpg(process.pid, signal.SIGKILL) + except ProcessLookupError: + pass + process.communicate(timeout=5) + + @unittest.skipUnless(os.name == 'posix', 'requires POSIX pipe selectors and process groups') + def test_output_is_live_and_provisional_report_becomes_final(self): + release = self.root / 'release' + process = self.run_probe(''' +state=initial +test::test_init() { state=setup; } +test::a_live() { + wait + if (( BASH_VERSINFO[0] > 4 || (BASH_VERSINFO[0] == 4 && BASH_VERSINFO[1] >= 3) )); then + local status=0 + wait -n || status=$? + expect_eq 127 "$status" + fi + expect_eq setup "$state" + state=changed + printf '%s' live_stdout_token + printf '%s' live_stderr_token >&2 + while [[ ! -e "$RELEASE" ]]; do sleep 0.02; done +} +test::b_after() { expect_eq changed "$state"; } +''', background=True, RELEASE=str(release)) + self.addCleanup(self.stop_probe, process) + captured = self.observe_live_output(process) + self.assertIsNone(process.poll()) + provisional = self.report() + self.assertEqual(set(provisional), {'a_live'}) + self.assertIn('provisional', provisional['a_live'].find('error').attrib['message']) + release.touch() + out, err = process.communicate(timeout=5) + self.assertEqual(process.returncode, 0, captured['stderr'] + err) + self.assertEqual((captured['stdout'] + out).count(b'live_stdout_token'), 1) + self.assertEqual((captured['stderr'] + err).count(b'live_stderr_token'), 1) + final = self.report() + self.assertEqual(set(final), {'a_live', 'b_after'}) + self.assertIsNone(final['a_live'].find('error')) + self.assertIn('live_stdout_token', final['a_live'].find('system-out').text) + self.assertIn('live_stderr_token', final['a_live'].find('system-err').text) + + @unittest.skipUnless(os.name == 'posix', 'requires POSIX pipe selectors and process groups') + def test_sigkill_leaves_active_case_error_and_live_diagnostics(self): + for active in ('b_hanging', 'test_init', 'test_done'): + with self.subTest(active=active): + process = self.run_probe(f''' +test::a_done() {{ :; }} +test::{active}() {{ + echo live_stdout_token + echo live_stderr_token >&2 + while :; do sleep 1; done +}} +''', background=True) + self.addCleanup(self.stop_probe, process) + captured = self.observe_live_output(process) + self.assertIsNone(process.poll()) + os.kill(process.pid, signal.SIGKILL) + process.communicate(timeout=5) + self.assertEqual(process.returncode, -signal.SIGKILL) + cases = self.report() + expected = {active} if active == 'test_init' else {'a_done', active} + self.assertEqual(set(cases), expected) + if active != 'test_init': + self.assertIsNone(cases['a_done'].find('error')) + self.assertIn('completion was not recorded', cases[active].find('error').attrib['message']) + self.assertIn(b'live_stdout_token', captured['stdout']) + self.assertIn(b'live_stderr_token', captured['stderr']) + + @unittest.skipUnless(os.name == 'posix', 'requires POSIX process-group cleanup') + def test_setup_service_can_keep_logging_until_teardown(self): + ready = self.root / 'service ready' + process = self.run_probe(''' +test::test_init() { + "$BASH" -c 'echo service_started; : > "$READY"; exec sleep 30' & + service_pid=$! + while [[ ! -e "$READY" ]]; do sleep 0.02; done +} +test::a_alive() { kill -0 "$service_pid"; } +test::b_alive() { kill -0 "$service_pid"; } +test::test_done() { kill "$service_pid"; wait "$service_pid" || :; } +''', background=True, READY=str(ready)) + self.addCleanup(self.stop_probe, process) + out, err = process.communicate(timeout=5) + self.assertEqual(process.returncode, 0, err) + self.assertEqual(out.count(b'service_started'), 1) + cases = self.report() + self.assertEqual(set(cases), {'a_alive', 'b_alive'}) + self.assertTrue(all(case.find('error') is None for case in cases.values())) + + def test_large_output_is_exact_when_sigpipe_is_ignored(self): + payload = (b'x' * 127 + b'\n') * 16384 + path = self.root / 'large output' + path.write_bytes(payload) + result = self.run_probe("trap '' PIPE\ntest::large() { cat \"$PAYLOAD\"; }", PAYLOAD=str(path)) + self.assertEqual(result.returncode, 0, result.stderr) + self.assertEqual(result.stdout.count(b'x' * 127 + b'\n'), 16384) + self.assertNotIn(b'Broken pipe', result.stderr) + self.assertEqual(self.report()['large'].find('system-out').text, payload.decode()) + + def test_capture_worker_failure_is_a_reported_error(self): + tools = self.root / 'fake bin' + tools.mkdir() + head = tools / 'head' + head.write_text('#!/usr/bin/env bash\ncat > /dev/null\nexit 3\n') + head.chmod(0o755) + result = self.run_probe('PATH="$FAKE_BIN:$PATH"\ntest::body() { echo payload; }', FAKE_BIN=str(tools)) + self.assertEqual(result.returncode, 1, result.stderr) + self.assertIn(b'Cannot capture test output completely', result.stderr) + self.assertIn(b'head=3', result.stderr) + self.assertIsNotNone(self.report()['body'].find('error')) + + def test_capture_worker_without_acknowledgement_does_not_hang(self): + # Fault injection: a worker exits before it can publish completion. + result = self.run_probe('_bashtest_capture_worker() { trap - EXIT; sleep 0.05; return 7; }\n' + 'test::body() { :; }') + self.assertEqual(result.returncode, 1, result.stderr) + self.assertIn(b'Cannot start test output capture', result.stderr) + self.assertIsNotNone(self.report()['test_runner'].find('error')) + + def test_progress_report_failure_stops_the_case(self): + result = self.run_probe('mktemp() { return 1; }\ntest::body() { echo must_not_run; }') + self.assertEqual(result.returncode, 1, result.stderr) + self.assertIn(b'Cannot write JUnit progress report', result.stderr) + self.assertNotIn(b'must_not_run', result.stdout) + self.assertIn(b'Preserved test scratch directory:', result.stderr) + def test_native_bazel_filter_and_explicit_override(self): body = 'test::alpha() { echo alpha_body; }\ntest::beta() { echo beta_body; }' for args, expected in (((), 'alpha'), (('--test_filter=^beta$',), 'beta'), @@ -427,7 +582,7 @@ def test_duration_and_relative_destination_survive_directory_changes(self): def test_write_failure_after_passing_tests_remains_failure(self): directory = self.root / 'deleted directory' - result = self.run_probe('test::pass() { rmdir "$REPORT_DIRECTORY"; }', + result = self.run_probe('test::pass() { mv "$REPORT_DIRECTORY" "$REPORT_DIRECTORY.moved"; }', f'--gtest_output=xml:{directory}/result.xml', REPORT_DIRECTORY=str(directory)) self.assertEqual(result.returncode, 1, result.stderr) @@ -482,7 +637,7 @@ def test_scratch_retained_for_report_write_errors(self): record = self.root / 'scratch.path' directory = self.root / 'report directory' prefix = 'printf "%s" "$BASHTEST_TMPDIR" > "$SCRATCH_RECORD"\n' - result = self.run_probe(prefix + 'test::body() { rmdir "$REPORT_DIRECTORY"; }', + result = self.run_probe(prefix + 'test::body() { mv "$REPORT_DIRECTORY" "$REPORT_DIRECTORY.moved"; }', f'--gtest_output=xml:{directory}/result.xml', SCRATCH_RECORD=str(record), REPORT_DIRECTORY=str(directory)) self.assertEqual(result.returncode, 1, result.stderr) From a973bdc18ad2da0874a5e09b034183dbfcac31b9 Mon Sep 17 00:00:00 2001 From: helly25 <6420169+helly25@users.noreply.github.com> Date: Sun, 25 Oct 2026 20:33:07 +0000 Subject: [PATCH 2/2] Run teardown even when its progress report cannot be written --- bashtest/README.md | 5 +++-- bashtest/bashtest.sh | 6 ++++++ bashtest/tests/junit_test.sh | 6 +++++- tools/junit_test.py | 12 ++++++++++++ 4 files changed, 26 insertions(+), 3 deletions(-) diff --git a/bashtest/README.md b/bashtest/README.md index 404b15f..40c0ef8 100644 --- a/bashtest/README.md +++ b/bashtest/README.md @@ -240,8 +240,9 @@ whose completion was not yet recorded. Readers detect coordinator death, drain a finite snapshot, and exit even without a stop request. Output already streamed remains in Bazel's test log; use `--test_output=streamed` to see output while Bazel runs. Catchable signals finalize -the report with available output. A failed progress-report write prevents the -function from running and fails the target. Reporting begins at `test_runner`; +the report with available output. A failed progress-report write prevents a new +setup/test body from running and fails the target. Teardown still runs so a +reporting failure cannot prevent cleanup. Reporting begins at `test_runner`; if termination happens before any report exists, Bazel supplies its fallback. Nested runner/verifier scripts should select their own output file, or disable diff --git a/bashtest/bashtest.sh b/bashtest/bashtest.sh index ab05156..a670462 100644 --- a/bashtest/bashtest.sh +++ b/bashtest/bashtest.sh @@ -736,6 +736,12 @@ _bashtest_invoke() { _BASHTEST_RUNNER_FAILED=1 _bashtest_record_failure echo >&2 "ERROR: Cannot write JUnit progress report: ${_BASHTEST_XML_PATH}" + # Reporting must not prevent user cleanup from releasing a + # service or fixture after a report destination becomes invalid. + if [[ "${1}" == test::test_done ]]; then + _bashtest_execute "${1}" >> "${_BASHTEST_CAPTURE_OUT}" 2>> "${_BASHTEST_CAPTURE_ERR}" + _bashtest_capture_case_finish + fi else _bashtest_execute "${1}" >> "${_BASHTEST_CAPTURE_OUT}" 2>> "${_BASHTEST_CAPTURE_ERR}" _bashtest_capture_case_finish diff --git a/bashtest/tests/junit_test.sh b/bashtest/tests/junit_test.sh index a2e96c0..668eb37 100755 --- a/bashtest/tests/junit_test.sh +++ b/bashtest/tests/junit_test.sh @@ -236,7 +236,7 @@ test::body() { report) mv "${REPORT_DIRECTORY}" "${REPORT_DIRECTORY}.moved" ;; esac } -test::test_done() { if [[ "${PROBE}" == teardown ]]; then return 7; fi; } +test::test_done() { printf done > "${DONE_RECORD}"; if [[ "${PROBE}" == teardown ]]; then return 7; fi; } test_runner PROBE for probe in pass failure setup teardown abort report; do @@ -247,11 +247,15 @@ PROBE [[ "${probe}" != abort ]] || expected=42 output="$(_junit_probe PROBE="${probe}" SCRATCH_RECORD="${root}/scratch.path" \ REPORT_DIRECTORY="${root}/reports-${probe}-${mode}" GTEST_OUTPUT="xml:${root}/reports-${probe}-${mode}/result.xml" \ + DONE_RECORD="${root}/done-${probe}-${mode}" \ "${BASH}" "${root}/probe.sh" --keep-tmpdir="${mode}" 2>&1)" || status="${?}" expect_eq "${expected}" "${status}" if [[ "${probe}" == report ]]; then expect_output_contains 'Cannot write JUnit report' "${output}" fi + if [[ "${probe}" != abort ]]; then + expect_success test -f "${root}/done-${probe}-${mode}" + fi scratch="$(cat "${root}/scratch.path")" retained=0 if [[ "${mode}" == always || ( "${mode}" == failure && "${expected}" != 0 ) ]]; then retained=1; fi diff --git a/tools/junit_test.py b/tools/junit_test.py index be9f83d..1120263 100644 --- a/tools/junit_test.py +++ b/tools/junit_test.py @@ -389,6 +389,18 @@ def test_capture_worker_without_acknowledgement_does_not_hang(self): self.assertIn(b'Cannot start test output capture', result.stderr) self.assertIsNotNone(self.report()['test_runner'].find('error')) + def test_teardown_runs_when_its_progress_report_cannot_be_written(self): + directory = self.root / 'report directory' + cleaned = self.root / 'cleanup completed' + result = self.run_probe(''' +test::body() { mv "$REPORT_DIRECTORY" "$REPORT_DIRECTORY.moved"; } +test::test_done() { printf cleaned > "$CLEANED"; } +''', f'--gtest_output=xml:{directory}/result.xml', + REPORT_DIRECTORY=str(directory), CLEANED=str(cleaned)) + self.assertEqual(result.returncode, 1, result.stderr) + self.assertEqual(cleaned.read_text(), 'cleaned') + self.assertIn(b'Cannot write JUnit progress report', result.stderr) + def test_progress_report_failure_stops_the_case(self): result = self.run_probe('mktemp() { return 1; }\ntest::body() { echo must_not_run; }') self.assertEqual(result.returncode, 1, result.stderr)