Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add timeout support #491

Merged
merged 28 commits into from
Aug 14, 2022
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
28 commits
Select commit Hold shift + click to select a range
e2d2aed
Add timeout support
TApplencourt Aug 24, 2021
67fd203
Fix Timeout test
Aug 26, 2021
fddea44
Use BATS_TIMEOUT as var instead of -E
martin-schulze-vireso Jul 25, 2022
18a479b
Fix shellcheck
martin-schulze-vireso Jul 25, 2022
18d2334
ps does not work as intended on busybox
martin-schulze-vireso Jul 25, 2022
75c7787
Make timing more robust against slow CI runners
martin-schulze-vireso Jul 25, 2022
70bcb1b
Rename BATS_TIMEOUT -> BATS_TEST_TIMEOUT
martin-schulze-vireso Jul 25, 2022
177228e
pretty: Remove duplicate timing information from test name
martin-schulze-vireso Jul 26, 2022
36260fe
Use ALRM/USR1 signals for timeout communikation
martin-schulze-vireso Jul 26, 2022
be758f3
Fix trace on timeout
martin-schulze-vireso Jul 26, 2022
599cc72
pretty: Deal with timeout directive in TAP
martin-schulze-vireso Jul 26, 2022
2ac38fe
Make tests more stirct
martin-schulze-vireso Jul 26, 2022
5890bfd
Improve debug output
martin-schulze-vireso Jul 26, 2022
d4d8fc9
Only terminate the test, not the timeout watchdog
martin-schulze-vireso Jul 26, 2022
32e37b1
Fix shellcheck
martin-schulze-vireso Jul 26, 2022
2effcfb
Make test expectation less dependent on env
martin-schulze-vireso Jul 26, 2022
54d9b5c
Fix signal propagation
martin-schulze-vireso Aug 5, 2022
1fd16ae
Give more tolerance for slow CI systems
martin-schulze-vireso Aug 5, 2022
0c0297c
Doc/changelog entry for BATS_TEST_TIMEOUT (#491)
martin-schulze-vireso Aug 5, 2022
3245ba6
Hide error message if countdown process is gone
martin-schulze-vireso Aug 5, 2022
bdcb6c9
Fix timeout on Windows
martin-schulze-vireso Aug 5, 2022
d995a81
Don't require "Terminated" but ensure timeout cuts off
martin-schulze-vireso Aug 7, 2022
74492c1
Emulate pkill if it is not present
martin-schulze-vireso Aug 7, 2022
d32ad97
pretty: Improve output on timeout
martin-schulze-vireso Aug 9, 2022
da19709
Fix typo
martin-schulze-vireso Aug 10, 2022
475326e
Fix timing info on skipped tests
martin-schulze-vireso Aug 10, 2022
b1e7fed
Add timeout to all formatters, simplify interface
martin-schulze-vireso Aug 12, 2022
d15d67d
CI: Add retries to brittle test (on Windows)
martin-schulze-vireso Aug 14, 2022
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Jump to
Jump to file
Failed to load files.
Diff view
Diff view
1 change: 1 addition & 0 deletions docs/CHANGELOG.md
Original file line number Diff line number Diff line change
Expand Up @@ -20,6 +20,7 @@ The format is based on [Keep a Changelog][kac] and this project adheres to
* Docker tags `latest-no-faccessat2` and `<bats-version\>-no-faccessat2` for
avoiding `bash: bats: No such file or directory` on `docker<20.10` (or
`runc<v1.0.0-rc93`) (#622)
* `BATS_TEST_TIMEOUT` variable to force a timeout on test (including `setup()`) (#491)

#### Documentation

Expand Down
3 changes: 2 additions & 1 deletion docs/source/faq.rst
Original file line number Diff line number Diff line change
Expand Up @@ -145,7 +145,8 @@ If you need the library inside `setup_file` or `teardown_file` you need to load
How to set a test timeout in bats?
----------------------------------
Unfortunately, this is not possible yet. Please contribute to issue `#396 <https://github.com/bats-core/bats-core/issues/396>`_ for further progress.
Set the variable `$BATS_TEST_TIMEOUT` before `setup()` starts. This means you can set it either on the command line,
in free code in the test file or in `setup_file()`.
How can I lint/shell-format my bats tests?
------------------------------------------
Expand Down
4 changes: 4 additions & 0 deletions docs/source/writing-tests.md
Original file line number Diff line number Diff line change
Expand Up @@ -379,6 +379,10 @@ There are several global variables you can use to introspect on Bats tests:
- `BATS_TEST_RETRIES` is the maximum number of additional attempts that will be
made on a failed test before it is finally considered failed.
The default of 0 means the test must pass on the first attempt.
- `BATS_TEST_TIMEOUT` is the number of seconds after which a test (including setup)
will be aborted and marked as failed. Updates to this value in `setup()` or `@test`
cannot change the running timeout countdown, so the latest useful update location
is `setup_file()`.
- `$BATS_TEST_NUMBER` is the (1-based) index of the current test case in the test file.
- `$BATS_SUITE_TEST_NUMBER` is the (1-based) index of the current test case in the test suite (over all files).
- `$BATS_TMPDIR` is the base temporary directory used by bats to create its
Expand Down
45 changes: 36 additions & 9 deletions lib/bats-core/formatter.bash
Original file line number Diff line number Diff line change
@@ -1,14 +1,25 @@
#!/usr/bin/env bash

# reads (extended) bats tap streams from stdin and calls callback functions for each line
#
# Segmenting functions
# ====================
# bats_tap_stream_plan <number of tests> -> when the test plan is encountered
# bats_tap_stream_suite <file name> -> when a new file is begun WARNING: extended only
# bats_tap_stream_begin <test index> <test name> -> when a new test is begun WARNING: extended only
# bats_tap_stream_ok [--duration <milliseconds] <test index> <test name> -> when a test was successful
# bats_tap_stream_not_ok [--duration <milliseconds>] <test index> <test name> -> when a test has failed
#
# Test result functions
# =====================
# If timing was enabled, BATS_FORMATTER_TEST_DURATION will be set to their duration in milliseconds
# bats_tap_stream_ok <test index> <test name> -> when a test was successful
# bats_tap_stream_not_ok <test index> <test name> -> when a test has failed. If the failure was due to a timeout,
# BATS_FORMATTER_TEST_TIMEOUT is set to the timeout duration in seconds
# bats_tap_stream_skipped <test index> <test name> <skip reason> -> when a test was skipped
#
# Context functions
# =================
# bats_tap_stream_comment <comment text without leading '# '> <scope> -> when a comment line was encountered,
# scope tells the last encountered of plan, begin, ok, not_ok, skipped, suite
# bats_tap_stream_suite <file name> -> when a new file is begun WARNING: extended only
# bats_tap_stream_unknown <full line> <scope> -> when a line is encountered that does not match the previous entries,
# scope @see bats_tap_stream_comment
# forwards all input as is, when there is no TAP test plan header
Expand All @@ -26,6 +37,7 @@ function bats_parse_internal_extended_tap() {

ok_line_regexpr="ok ([0-9]+) (.*)"
skip_line_regexpr="ok ([0-9]+) (.*) # skip( (.*))?$"
timeout_line_regexpr="not ok ([0-9]+) (.*) # timeout after ([0-9]+)s$"
not_ok_line_regexpr="not ok ([0-9]+) (.*)"

timing_expr="in ([0-9]+)ms$"
Expand All @@ -34,6 +46,7 @@ function bats_parse_internal_extended_tap() {
index=0
scope=plan
while IFS= read -r line; do
unset BATS_FORMATTER_TEST_DURATION BATS_FORMATTER_TEST_TIMEOUT
case "$line" in
'begin '*) # this might only be called in extended tap output
((++begin_index))
Expand All @@ -50,11 +63,18 @@ function bats_parse_internal_extended_tap() {
scope=skipped
test_name="${BASH_REMATCH[2]}" # cut off name before "# skip"
local skip_reason="${BASH_REMATCH[4]}"
bats_tap_stream_skipped "$ok_index" "$test_name" "$skip_reason"
if [[ "$test_name" =~ $timing_expr ]]; then
local BATS_FORMATTER_TEST_DURATION="${BASH_REMATCH[1]}"
test_name="${test_name% in "${BATS_FORMATTER_TEST_DURATION}"ms}"
bats_tap_stream_skipped "$ok_index" "$test_name" "$skip_reason"
else
bats_tap_stream_skipped "$ok_index" "$test_name" "$skip_reason"
fi
else
scope=ok
if [[ "$line" =~ $timing_expr ]]; then
bats_tap_stream_ok --duration "${BASH_REMATCH[1]}" "$ok_index" "$test_name"
local BATS_FORMATTER_TEST_DURATION="${BASH_REMATCH[1]}"
bats_tap_stream_ok "$ok_index" "${test_name% in "${BASH_REMATCH[1]}"ms}"
else
bats_tap_stream_ok "$ok_index" "$test_name"
fi
Expand All @@ -70,11 +90,18 @@ function bats_parse_internal_extended_tap() {
if [[ "$line" =~ $not_ok_line_regexpr ]]; then
not_ok_index="${BASH_REMATCH[1]}"
test_name="${BASH_REMATCH[2]}"
if [[ "$line" =~ $timing_expr ]]; then
bats_tap_stream_not_ok --duration "${BASH_REMATCH[1]}" "$not_ok_index" "$test_name"
else
bats_tap_stream_not_ok "$not_ok_index" "$test_name"
if [[ "$line" =~ $timeout_line_regexpr ]]; then
not_ok_index="${BASH_REMATCH[1]}"
test_name="${BASH_REMATCH[2]}"
# shellcheck disable=SC2034 # used in bats_tap_stream_ok
local BATS_FORMATTER_TEST_TIMEOUT="${BASH_REMATCH[3]}"
fi
if [[ "$test_name" =~ $timing_expr ]]; then
# shellcheck disable=SC2034 # used in bats_tap_stream_ok
local BATS_FORMATTER_TEST_DURATION="${BASH_REMATCH[1]}"
test_name="${test_name% in "${BASH_REMATCH[1]}"ms}"
fi
bats_tap_stream_not_ok "$not_ok_index" "$test_name"
else
printf "ERROR: could not match not ok line: %s" "$line" >&2
exit 1
Expand Down
10 changes: 9 additions & 1 deletion lib/bats-core/tracing.bash
Original file line number Diff line number Diff line change
Expand Up @@ -102,6 +102,12 @@ bats_print_failed_command() {
bats_quote_code quoted_failed_command "$failed_command"
printf '# %s ' "${quoted_failed_command}"

if [[ "${BATS_TIMED_OUT-NOTSET}" != NOTSET ]]; then
# the other values can be safely overwritten here,
# as the timeout is the primary reason for failure
BATS_ERROR_SUFFIX=" due to timeout"
fi

if [[ "$BATS_ERROR_STATUS" -eq 1 ]]; then
printf 'failed%s\n' "$BATS_ERROR_SUFFIX"
else
Expand Down Expand Up @@ -251,7 +257,9 @@ bats_debug_trap() {

# don't update the trace within library functions or we get backtraces from inside traps
# also don't record new stack traces while handling interruptions, to avoid overriding the interrupted command
if [[ -z "$file_excluded" && "${BATS_INTERRUPTED-NOTSET}" == NOTSET ]]; then
if [[ -z "$file_excluded" &&
"${BATS_INTERRUPTED-NOTSET}" == NOTSET &&
"${BATS_TIMED_OUT-NOTSET}" == NOTSET ]]; then
BATS_DEBUG_LASTLAST_STACK_TRACE=(
${BATS_DEBUG_LAST_STACK_TRACE[@]+"${BATS_DEBUG_LAST_STACK_TRACE[@]}"}
)
Expand Down
117 changes: 106 additions & 11 deletions libexec/bats-core/bats-exec-test
Original file line number Diff line number Diff line change
Expand Up @@ -86,6 +86,12 @@ source "$BATS_ROOT/lib/bats-core/tracing.bash"
bats_teardown_trap() {
bats_check_status_from_trap
local bats_teardown_trap_status=0

# `bats_teardown_trap` is always called with one parameter (BATS_TEARDOWN_STARTED)
# The second parameter is optional and corresponds for to the killer pid
# that will be forwarded to the exit trap to kill it if necesary
local killer_pid=${2:-}

# mark the start of this function to distinguish where skip is called
# parameter 1 will signify the reason why this function was called
# this is used to identify when this is called as exit trap function
Expand All @@ -99,26 +105,33 @@ bats_teardown_trap() {
BATS_ERROR_STATUS="$bats_teardown_trap_status"
fi

bats_exit_trap
bats_exit_trap "$killer_pid"
}

# shellcheck source=lib/bats-core/common.bash
source "$BATS_ROOT/lib/bats-core/common.bash"

bats_exit_trap() {
local status
local skipped=''
local exit_metadata=''
local killer_pid=${1:-}
trap - ERR EXIT
if [[ -n "${BATS_TEST_TIMEOUT:-}" ]]; then
# Kill the watchdog in the case of of kernel finished before the timeout
bats_abort_timeout_countdown "$killer_pid" || status=1
fi

if [[ -n "$BATS_TEST_SKIPPED" ]]; then
skipped=' # skip'
exit_metadata=' # skip'
if [[ "$BATS_TEST_SKIPPED" != '1' ]]; then
skipped+=" $BATS_TEST_SKIPPED"
exit_metadata+=" $BATS_TEST_SKIPPED"
fi
elif [[ "${BATS_TIMED_OUT-NOTSET}" != NOTSET ]]; then
exit_metadata=" # timeout after ${BATS_TEST_TIMEOUT}s"
fi

BATS_TEST_TIME=''
if [[ -z "${skipped}" && -n "$BATS_ENABLE_TIMING" ]]; then
if [[ -n "$BATS_ENABLE_TIMING" ]]; then
BATS_TEST_TIME=" in "$(( $(get_mills_since_epoch) - BATS_TEST_START_TIME ))"ms"
fi

Expand All @@ -143,7 +156,7 @@ bats_exit_trap() {
status=126 # signify retry
rm -r "$BATS_TEST_TMPDIR" # clean up for retry
else
printf 'not ok %d %s\n' "$BATS_SUITE_TEST_NUMBER" "${BATS_TEST_NAME_PREFIX:-}${BATS_TEST_DESCRIPTION}${BATS_TEST_TIME}" >&3
printf 'not ok %d %s%s\n' "$BATS_SUITE_TEST_NUMBER" "${BATS_TEST_NAME_PREFIX:-}${BATS_TEST_DESCRIPTION}${BATS_TEST_TIME}" "$exit_metadata" >&3
local stack_trace
bats_get_failure_stack_trace stack_trace
bats_print_stack_trace "${stack_trace[@]}" >&3
Expand All @@ -159,7 +172,7 @@ bats_exit_trap() {
fi
else
printf 'ok %d %s%s\n' "$BATS_SUITE_TEST_NUMBER" "${BATS_TEST_NAME_PREFIX:-}${BATS_TEST_DESCRIPTION}${BATS_TEST_TIME}" \
"$skipped" >&3
"$exit_metadata" >&3
status=0
local state=passed
fi
Expand All @@ -182,6 +195,81 @@ bats_exit_trap() {
exit "$status"
}

# Marks the test as failed due to timeout.
# The actual termination of subprocesses is done via pkill in the background
# process in bats_start_timeout_countdown
bats_timeout_trap() {
BATS_TIMED_OUT=1
BATS_DEBUG_LAST_STACK_TRACE_IS_VALID=
exit 1
}

bats_get_child_processes_of() { # <parent-pid>
local -ri parent_pid=${1?}
{
read -ra header
local pid_col ppid_col
for (( i = 0; i < ${#header[@]}; ++i )); do
if [[ ${header[$i]} == "PID" ]]; then
pid_col=$i
fi
if [[ ${header[$i]} == "PPID" ]]; then
ppid_col=$i
fi
done
while read -ra row; do
if (( ${row[$ppid_col]} == parent_pid )); then
printf "%d\n" "${row[$pid_col]}"
fi
done
} < <(ps -ef "$parent_pid")
}

bats_kill_childprocesses_of() { # <parent-pid>
local -ir parent_pid="${1?}"
if command -v pkill; then
pkill -P "$parent_pid"
else
# kill in reverse order (latest first)
while read -r pid; do
kill "$pid"
done < <(bats_get_child_processes_of "$parent_pid" | sort -r)
fi &>/dev/null
}

# sets a timeout for this process
#
# using SIGABRT for interprocess communication.
# Ruled out:
# USR1/2 - not available on Windows
# SIGALRM - interferes with sleep:
# "sleep(3) may be implemented using SIGALRM; mixing calls to alarm()
# and sleep(3) is a bad idea." ~ https://linux.die.net/man/2/alarm
bats_start_timeout_countdown() { # <timeout>
local -ri timeout=$1
local -ri target_pid=$$
# shellcheck disable=SC2064
trap "bats_timeout_trap $target_pid" ABRT
# Start another process to kill the children of this process
(
sleep "$timeout" &
# sleep won't recieve signals, so we use wait below
# and kill sleep explicitly when signalled to do so
# shellcheck disable=SC2064
trap "kill $!; exit 0" ABRT
wait
if kill -ABRT "$target_pid"; then
# get rid of signal blocking child processes (like sleep)
bats_kill_childprocesses_of "$target_pid"
fi &> /dev/null
) &
}

bats_abort_timeout_countdown() {
# kill the countdown process, don't care if its still there
kill -ABRT "$1" &>/dev/null || true
}

get_mills_since_epoch() {
local ms_since_epoch
ms_since_epoch=$(date +%s%N)
Expand All @@ -202,20 +290,27 @@ bats_perform_test() {
exit 1
fi

local BATS_killer_pid=''
if [[ -n "${BATS_TEST_TIMEOUT:-}" ]]; then
bats_start_timeout_countdown "$BATS_TEST_TIMEOUT"
BATS_killer_pid=$!
fi
BATS_TEST_COMPLETED=
BATS_TEST_SKIPPED=
BATS_TEARDOWN_COMPLETED=
BATS_ERROR_STATUS=
bats_setup_tracing
# mark this call as trap call
trap 'bats_teardown_trap as-exit-trap' EXIT
# use parameter to mark this call as trap call
# shellcheck disable=SC2064
trap "bats_teardown_trap as-exit-trap $BATS_killer_pid" EXIT

BATS_TEST_START_TIME=$(get_mills_since_epoch)
"$BATS_TEST_NAME" >>"$BATS_OUT" 2>&1 4>&1

BATS_TEST_COMPLETED=1
trap 'bats_exit_trap' EXIT
bats_teardown_trap "" # pass empty parameter to signify call outside trap
# shellcheck disable=SC2064
trap "bats_exit_trap $BATS_killer_pid" EXIT
bats_teardown_trap "" "$BATS_killer_pid" # pass empty parameter to signify call outside trap
}

trap bats_interrupt_trap INT
Expand Down
17 changes: 5 additions & 12 deletions libexec/bats-core/bats-format-junit
Original file line number Diff line number Diff line change
Expand Up @@ -186,34 +186,27 @@ bats_tap_stream_begin() { # <test index> <test name>
name="$2"
}

bats_tap_stream_ok() { # [--duration <milliseconds] <test index> <test name>
if [[ "$1" == "--duration" ]]; then
test_exec_time="${BASH_REMATCH[1]}"
else
test_exec_time=0
fi
bats_tap_stream_ok() { # <test index> <test name>
test_exec_time=${BATS_FORMATTER_TEST_DURATION:-0}
((file_count += 1))
test_result_state='ok'
file_exec_time="$((file_exec_time + test_exec_time))"
suite_test_exec_time=$((suite_test_exec_time + test_exec_time))
}

bats_tap_stream_skipped() { # <test index> <test name> <skip reason>
test_exec_time=${BATS_FORMATTER_TEST_DURATION:-0}
((file_count += 1))
((file_skipped += 1))
test_result_state='skipped'
test_exec_time=0
test_skip_message="$3"
}

bats_tap_stream_not_ok() { # [--duration <milliseconds>] <test index> <test name>
bats_tap_stream_not_ok() { # <test index> <test name>
test_exec_time=${BATS_FORMATTER_TEST_DURATION:-0}
((file_count += 1))
((file_failures += 1))
if [[ "$1" == "--duration" ]]; then
test_exec_time="${BASH_REMATCH[1]}"
else
test_exec_time=0
fi
test_result_state=not_ok
file_exec_time="$((file_exec_time + test_exec_time))"
suite_test_exec_time=$((suite_test_exec_time + test_exec_time))
Expand Down