From daeb9041abcfe22dbbe8e87747602e01f0d35ee1 Mon Sep 17 00:00:00 2001 From: Rongsong Shen Date: Fri, 2 Oct 2026 04:24:07 +0000 Subject: [PATCH] fix(harness): pty CLI tests time their waits with a real clock (bug-1902) clitest_wait_for_exit/clitest_wait_for_text added CLITEST_POLL_SLICE_MS per loop instead of measuring time. Once xce_test closes its pty after 'quit', poll() returns at once on every call, so the 5 s budget was used up within milliseconds while the (ASAN, loaded) child was not yet reapable -- measured: real exit within 6 ms while the counter reached 58800 ms. The waits now use a CLOCK_MONOTONIC deadline, and clitest_pump_once naps 10 ms when poll wakes with nothing to read. Under 16 parallel runs: 12/48 runs failed before, 0/96 after. Co-Authored-By: Claude Opus 5.5 (1M context) --- src/harness/testsuite/test_test_cli.c | 34 ++++++++++++++++++++++----- 1 file changed, 28 insertions(+), 6 deletions(-) diff --git a/src/harness/testsuite/test_test_cli.c b/src/harness/testsuite/test_test_cli.c index c09972b5..bd6f4b72 100644 --- a/src/harness/testsuite/test_test_cli.c +++ b/src/harness/testsuite/test_test_cli.c @@ -478,6 +478,19 @@ static int clitest_send_signal(clitest_session_t* sess, int signo) * as "nothing [more] available right now", not an error -- callers loop * this via clitest_wait_for_text()/clitest_wait_for_exit() until their own * condition or timeout is met. */ +/* bug-1902: the wait loops below measure real (monotonic) time. They used + * to add CLITEST_POLL_SLICE_MS per iteration, but once the child closes + * the pty, poll() returns at once on every call, so a "5000 ms" budget + * ran out within milliseconds while the child (an ASAN build tearing + * down under load) was not yet reapable. */ +static long clitest_now_ms(void) +{ + struct timespec ts; + + clock_gettime(CLOCK_MONOTONIC, &ts); + return (long)ts.tv_sec * 1000 + ts.tv_nsec / 1000000; +} + static void clitest_pump_once(clitest_session_t* sess, clitest_buf_t* out_stdout, clitest_buf_t* out_stderr, int timeout_ms) @@ -494,6 +507,8 @@ static void clitest_pump_once(clitest_session_t* sess, pfds[1].events = POLLIN; pfds[1].revents = 0; + bool got = false; + n = poll(pfds, 2, timeout_ms); if (n <= 0) { return; @@ -503,14 +518,23 @@ static void clitest_pump_once(clitest_session_t* sess, r = read(sess->master_fd, tmp, sizeof(tmp)); if (r > 0) { clitest_buf_append(out_stdout, tmp, (size_t)r); + got = true; } } if (pfds[1].revents & (POLLIN | POLLHUP | POLLERR)) { r = read(sess->err_fd, tmp, sizeof(tmp)); if (r > 0) { clitest_buf_append(out_stderr, tmp, (size_t)r); + got = true; } } + + /* bug-1902: a hung-up pty polls ready with nothing to read; don't spin */ + if (!got && (timeout_ms > 0)) { + struct timespec nap = { 0, 10 * 1000000L }; + + nanosleep(&nap, NULL); + } } static bool clitest_wait_for_text(clitest_session_t* sess, @@ -519,12 +543,11 @@ static bool clitest_wait_for_text(clitest_session_t* sess, const char* needle, bool in_stderr, int overall_timeout_ms) { - int elapsed = 0; + long deadline = clitest_now_ms() + overall_timeout_ms; - while (elapsed < overall_timeout_ms) { + while (clitest_now_ms() < deadline) { clitest_pump_once(sess, out_stdout, out_stderr, CLITEST_POLL_SLICE_MS); - elapsed += CLITEST_POLL_SLICE_MS; if (strstr(in_stderr ? out_stderr->data : out_stdout->data, needle) != NULL) { return true; @@ -551,14 +574,13 @@ static int clitest_wait_for_exit(clitest_session_t* sess, clitest_buf_t* out_stderr, int timeout_ms, int* exit_code) { - int elapsed = 0; + long deadline = clitest_now_ms() + timeout_ms; pid_t w; int status; - while (elapsed < timeout_ms) { + while (clitest_now_ms() < deadline) { clitest_pump_once(sess, out_stdout, out_stderr, CLITEST_POLL_SLICE_MS); - elapsed += CLITEST_POLL_SLICE_MS; w = waitpid(sess->pid, &status, WNOHANG); if (w == sess->pid) {