From 81c52909cbd6986be43164eac6f2c80187397eaa Mon Sep 17 00:00:00 2001 From: Rene Cannao Date: Sun, 9 Aug 2026 12:02:18 +0000 Subject: [PATCH 1/2] test: make TEST_TAP_TIMEOUT actually fire, and enable it by default TEST_TAP_TIMEOUT could not catch the failure it exists for. The read loop was: line = fop.stdout.readline() # blocks ... if tap_timeout > 0 and (time.time() - start_time) > tap_timeout: readline() blocks until a full line arrives, so a test that hangs while producing no output never reached the deadline check at all. Verified directly: with tap_timeout=3 against 'sleep 300', the old loop was still blocked after 25 seconds; the new one raises at 3.0s. That is the exact profile of the CI-mysql84-g9 stall on #5991, where test_ssl_fast_forward-3_libmariadb-t ran for hours. Replaces the blocking readline() with select() on a bounded wait plus raw os.read() chunking. select() guarantees the deadline check runs even when the child is silent; chunking rather than line-reading means a test that stops mid-line cannot wedge the loop either. Output order and content are unchanged, a trailing partial line is now flushed instead of dropped, and decoding uses errors='replace' so a stray non-UTF-8 byte no longer throws. Verified against four cases: normal chatty test (all lines, in order), silent hang (timeout fires), partial-line-then-hang (timeout fires), and clean exit. Also flips the default from 0 (disabled) to 1800s. 1800 is ~2.4x the slowest single test measured across 47 groups: reg_test_3765_ssl_pollout-t 12.5 min test_cluster_sync-t 10.5 min set_testing-240-t 7.8 min test_auth_methods-t 7.7 min Only 4 of 401 tests exceed 5 minutes, so this cannot fire on a merely slow test, while still stopping a hang well inside the 90-minute step budget added in the companion CI PRs -- and, unlike a step or job timeout, it identifies WHICH test hung and lets the run continue to its archive steps. --- test/infra/control/env-isolated.bash | 9 ++++++- test/scripts/bin/proxysql-tester.py | 40 ++++++++++++++++++++++------ 2 files changed, 40 insertions(+), 9 deletions(-) diff --git a/test/infra/control/env-isolated.bash b/test/infra/control/env-isolated.bash index 4e23f3c5ee..880f1d040e 100755 --- a/test/infra/control/env-isolated.bash +++ b/test/infra/control/env-isolated.bash @@ -104,7 +104,14 @@ export TEST_PY_TAP_REPEAT="${TEST_PY_TAP_REPEAT:-1}" export TEST_PY_TAP_SHUFFLE_LIMIT="${TEST_PY_TAP_SHUFFLE_LIMIT:-0}" export TEST_PY_TAP_DUMP_RUNTIME="${TEST_PY_TAP_DUMP_RUNTIME:-1}" export TEST_PY_TAP_DUMP_STATS="${TEST_PY_TAP_DUMP_STATS:-1}" -export TEST_TAP_TIMEOUT="${TEST_TAP_TIMEOUT:-0}" +# Per-test wall-clock budget, in seconds. 0 disables it entirely, which was +# the previous default: a hung TAP test then ran until the CI job itself was +# killed. 1800 is ~2.4x the slowest single test measured across 47 groups +# (reg_test_3765_ssl_pollout-t, 12.5 min; then test_cluster_sync-t 10.5, +# set_testing-240-t 7.8, test_auth_methods-t 7.7 -- only 4 tests exceed 5 +# minutes at all), so it cannot fire on a merely slow test while still +# catching a hang long before the 90-minute step budget. +export TEST_TAP_TIMEOUT="${TEST_TAP_TIMEOUT:-1800}" # Cluster sync test support — expose first cluster node admin port for replica validation if [ "${NUM_CLUSTER_NODES}" -gt 0 ]; then diff --git a/test/scripts/bin/proxysql-tester.py b/test/scripts/bin/proxysql-tester.py index 8efbf47e1d..23cf65699f 100755 --- a/test/scripts/bin/proxysql-tester.py +++ b/test/scripts/bin/proxysql-tester.py @@ -5,6 +5,7 @@ import os import pymysql import sys +import select import subprocess import random import time @@ -842,19 +843,42 @@ def disk_usage(): sys.exit(1) continue - # Run test with timeout if specified + # Run test with timeout if specified. + # + # The read has to be non-blocking for tap_timeout to mean + # anything. readline() blocks until a full line arrives, so on + # a test that hangs while producing no output -- precisely the + # case this timeout exists to catch -- the deadline check below + # it was simply never reached, and the test ran until CI killed + # the job. select() bounds the wait so the check always runs, + # and reading raw chunks rather than lines means a test that + # stops mid-line cannot wedge us either. try: start_time = time.time() + buf = b'' while True: - line = fop.stdout.readline() - if not line and fop.poll() is not None: - break - if line: - log.debug(f"msg: {line.decode('utf-8').strip()}") - if tap_timeout > 0 and (time.time() - start_time) > tap_timeout: raise subprocess.TimeoutExpired(fop.args, tap_timeout) - + + wait = 1.0 + if tap_timeout > 0: + wait = max(0.0, min(1.0, tap_timeout - (time.time() - start_time))) + ready, _, _ = select.select([fop.stdout], [], [], wait) + + if ready: + chunk = os.read(fop.stdout.fileno(), 65536) + if not chunk: + break # EOF: test finished + buf += chunk + while b'\n' in buf: + line, buf = buf.split(b'\n', 1) + log.debug(f"msg: {line.decode('utf-8', 'replace').strip()}") + elif fop.poll() is not None: + break + + if buf: # trailing partial line + log.debug(f"msg: {buf.decode('utf-8', 'replace').strip()}") + fop.wait() except subprocess.TimeoutExpired: fop.kill() From 6b32b70e36371012545d32a5d7e46977990dc2f0 Mon Sep 17 00:00:00 2001 From: Rene Cannao Date: Sun, 9 Aug 2026 12:18:33 +0000 Subject: [PATCH 2/2] test: reap the timed-out test before its return code is used Review catch. The TimeoutExpired handler called kill() and drained stdout but never wait()ed, so fop.returncode stayed None -- and the shared exit path below evaluates: rc += abs(int(fop.returncode)) which raises TypeError on None. The first timed-out test would therefore abort the whole group as a Python exception instead of failing one test. Latent until now: the timeout could never fire while the read loop blocked in readline(), so this path was unreachable. Enabling the timeout in the previous commit makes it reachable, so it has to be fixed in the same PR. wait() after the drain yields -SIGKILL, so abs(int(...)) contributes 9 and the timed-out test is correctly scored as failed. Verified directly: returncode None before wait(), -9 after. Also switches the drain's decode to errors='replace', matching the main read loop -- a hung test is exactly the case likely to emit a truncated multi-byte sequence, which would otherwise throw inside the handler. --- test/scripts/bin/proxysql-tester.py | 10 +++++++++- 1 file changed, 9 insertions(+), 1 deletion(-) diff --git a/test/scripts/bin/proxysql-tester.py b/test/scripts/bin/proxysql-tester.py index 23cf65699f..39550c31d3 100755 --- a/test/scripts/bin/proxysql-tester.py +++ b/test/scripts/bin/proxysql-tester.py @@ -886,7 +886,15 @@ def disk_usage(): self.padmin_command(f"LOGENTRY '{TAP} test {fo_num+1}/{len(tap_tests)} \'{os.path.basename(fo_cmd)}\' timed out after {tap_timeout} seconds'") # Drain any remaining output for line in fop.stdout: - log.debug(f"msg: {line.decode('utf-8').strip()}") + log.debug(f"msg: {line.decode('utf-8', 'replace').strip()}") + # Reap the child. kill() signals but does not wait, so + # returncode stays None until we do -- and the shared exit + # path below evaluates abs(int(fop.returncode)), which + # raises TypeError on None. That path was unreachable while + # the timeout could never fire; now that it can, a timed-out + # test would abort the whole group instead of failing one + # test. wait() yields -SIGKILL, so the test scores non-zero. + fop.wait() except Exception as e: log.critical(f"TAP test {fo_num+1}/{len(tap_tests)} '{os.path.basename(fo_cmd)}' - test threw an exception !!!: {e}") self.padmin_command(f"LOGENTRY '{TAP} test {fo_num+1}/{len(tap_tests)} \'{os.path.basename(fo_cmd)}\' - test threw an exception !!!'")