From 179e95754369eecef0874e42364ab828f87c59a6 Mon Sep 17 00:00:00 2001 From: Daniel JB Clark Date: Mon, 17 Aug 2026 15:40:41 -0400 Subject: [PATCH] Fixed process poll loops counting iterations instead of measuring elapsed time ProcessWaitUntilStopped() and ProcessWaitUntilExited() take a timeout in nanoseconds, but budgeted it by subtracting SLEEP_POLL_TIMEOUT_NS once per iteration -- assuming every nanosleep() costs exactly what was requested. nanosleep() is only guaranteed to sleep *at least* as long as requested, so this counted iterations rather than measuring a duration, and the loop overshot its timeout by whatever the platform's timer granularity is. On Darwin/arm64 a nanosleep(10ms) request routinely takes ~45ms, measured standalone at 4.4-4.7s for 100 iterations, and independently reproduced by two reviewers at 4.229/4.348/4.385s and 4.449s. So STOP_WAIT_TIMEOUT, documented and intended as "no more than ... one second", actually waited ~4.5s there. GracefulTerminate() calls ProcessWaitUntilExited() twice, so its SIGINT -> SIGTERM -> SIGKILL ladder took ~8.9s instead of ~2s. Measured with temporary instrumentation before the fix: GT: SIGINT sent at 0.000s wait: TIMED OUT after 4.459s, 100 iters -> false GT: SIGTERM sent at 4.460s wait: TIMED OUT after 4.457s, 100 iters -> false GT: SIGKILL sent at 8.917s -> true The user-visible consequence is that a commands: promise with exec_timeout takes far longer to be terminated than the configured timeout implies: with exec_timeout => "2" and a command that ignores the first signals, cf-agent spent ~11.2s before this change and ~5.2s after. This does NOT make a timed-out command report as timed out. That is a separate defect -- RepairExec() never returns ACTION_RESULT_TIMEOUT, so the promise is judged solely on the child's exit status -- and shrinking the ladder only narrows the window in which it is reached. It cannot close it, because the exit status of a command that was killed is not a reliable report of whether it was killed. Both loops now compute a deadline from a monotonic clock and re-check actual elapsed time each iteration, using the same CLOCK_MONOTONIC fallback as EvalContextEventStart() in eval_context.c. The clock is read through libntech's checked xclock_gettime() rather than clock_gettime() directly. Reading it directly and ignoring the return value leaves a struct timespec uninitialized on the failure path, which POSIX permits and which is undefined behaviour rather than merely a bad timestamp; EvalContextEventStart() has that defect and this deliberately does not copy it. Where CLOCK_MONOTONIC is unavailable the fallback reads CLOCK_REALTIME, which an NTP step can move backwards. A receding deadline would make the loop wait until the wall clock caught up -- an unbounded wait, where the iteration counting this replaces was naturally immune because it never read a clock at all. The loops therefore carry the previous timestamp and shift the deadline back by any backward step, so the remaining budget is preserved rather than extended. A clock that steps forward still ends the wait early, which is the conservative direction for a timeout. process_terminate_unix_test.c mocks nanosleep() and advances a fake clock by the requested sleep, which is precisely the accounting being removed, so it also has to drive clock_gettime() from that same fake clock. Without that the loops read real time while the fake process reacts on fake time, and test_kill_long_reacting_signal fails. Note that this mock makes nanosleep() exact by construction, so the unit test cannot demonstrate the overshoot itself; the overshoot is a property of real timer granularity and is shown by the measurements above. One semantic change worth calling out: the loops are now do/while on a deadline, so timeout_ns <= 0 enters the loop once where the previous while (timeout_ns > 0) did not. The only caller passes STOP_WAIT_TIMEOUT, so this is not reachable in production, but it means ProcessWaitUntilExited(pid, 0) on an already-exited process returns true where it previously returned false without looking. Ticket: CFE-4728 Changelog: Title --- libpromises/process_unix.c | 78 +++++++++++++++++++++--- tests/unit/process_terminate_unix_test.c | 18 ++++++ 2 files changed, 88 insertions(+), 8 deletions(-) diff --git a/libpromises/process_unix.c b/libpromises/process_unix.c index 4193d14827..4927233327 100644 --- a/libpromises/process_unix.c +++ b/libpromises/process_unix.c @@ -33,6 +33,54 @@ #define SLEEP_POLL_TIMEOUT_NS 10000000 +/* + * Monotonic timestamp in nanoseconds, for measuring how long the poll loops + * below have actually waited. + * + * nanosleep() may sleep considerably longer than requested -- on Darwin/arm64 a + * 10ms request routinely takes ~45ms -- so a loop that assumes each iteration + * costs exactly SLEEP_POLL_TIMEOUT_NS is counting iterations, not measuring a + * duration, and overshoots its timeout by whatever the platform's granularity + * happens to be. + * + * Same CLOCK_MONOTONIC fallback as EvalContextEventStart() in eval_context.c. + */ +static int64_t ProcessPollTimeNs(void) +{ + struct timespec ts; +#ifdef CLOCK_MONOTONIC + xclock_gettime(CLOCK_MONOTONIC, &ts); +#else + xclock_gettime(CLOCK_REALTIME, &ts); +#endif + return (int64_t) ts.tv_sec * 1000000000LL + ts.tv_nsec; +} + +/* + * Nanoseconds left before #deadline, given the current time, keeping the + * deadline honest across a clock that steps backwards. + * + * Without CLOCK_MONOTONIC the helper above reads CLOCK_REALTIME, which an NTP + * step can move backwards under us; the deadline would then recede and the loop + * would wait for the wall clock to catch up. Whenever time moves backwards + * between two reads we move the deadline back by the same amount, so the + * remaining budget is preserved rather than extended. + * + * #deadline and #prev are both updated in place. + */ +static int64_t ProcessPollRemainingNs(int64_t *deadline, int64_t *prev) +{ + const int64_t now = ProcessPollTimeNs(); + + if (now < *prev) + { + *deadline -= (*prev - now); + } + *prev = now; + + return *deadline - now; +} + /* * Wait until process specified by #pid is stopped due to SIGSTOP signal. @@ -45,7 +93,10 @@ */ static bool ProcessWaitUntilStopped(pid_t pid, long timeout_ns) { - while (timeout_ns > 0) + int64_t prev = ProcessPollTimeNs(); + int64_t deadline = prev + timeout_ns; + + while (true) { switch (GetProcessState(pid)) { @@ -61,9 +112,15 @@ static bool ProcessWaitUntilStopped(pid_t pid, long timeout_ns) return false; } + const int64_t remaining_ns = ProcessPollRemainingNs(&deadline, &prev); + if (remaining_ns <= 0) + { + break; + } + struct timespec ts = { .tv_sec = 0, - .tv_nsec = MIN(SLEEP_POLL_TIMEOUT_NS, timeout_ns), + .tv_nsec = (long) MIN((int64_t) SLEEP_POLL_TIMEOUT_NS, remaining_ns), }; while (nanosleep(&ts, &ts) < 0) @@ -73,8 +130,6 @@ static bool ProcessWaitUntilStopped(pid_t pid, long timeout_ns) ProgrammingError("Invalid timeout for nanosleep"); } } - - timeout_ns = MAX(0, timeout_ns - SLEEP_POLL_TIMEOUT_NS); } return false; @@ -87,7 +142,10 @@ static bool ProcessWaitUntilExited(pid_t pid, long timeout_ns) { assert(timeout_ns < 1000000000); - while (timeout_ns > 0) + int64_t prev = ProcessPollTimeNs(); + int64_t deadline = prev + timeout_ns; + + while (true) { switch (GetProcessState(pid)) { @@ -106,9 +164,15 @@ static bool ProcessWaitUntilExited(pid_t pid, long timeout_ns) return false; } + const int64_t remaining_ns = ProcessPollRemainingNs(&deadline, &prev); + if (remaining_ns <= 0) + { + break; + } + struct timespec ts = { .tv_sec = 0, - .tv_nsec = MIN(SLEEP_POLL_TIMEOUT_NS, timeout_ns), + .tv_nsec = (long) MIN((int64_t) SLEEP_POLL_TIMEOUT_NS, remaining_ns), }; Log(LOG_LEVEL_DEBUG, @@ -122,8 +186,6 @@ static bool ProcessWaitUntilExited(pid_t pid, long timeout_ns) ProgrammingError("Invalid timeout for nanosleep"); } } - - timeout_ns = MAX(0, timeout_ns - SLEEP_POLL_TIMEOUT_NS); } return false; diff --git a/tests/unit/process_terminate_unix_test.c b/tests/unit/process_terminate_unix_test.c index 3dffc6b1b4..9697a5da22 100644 --- a/tests/unit/process_terminate_unix_test.c +++ b/tests/unit/process_terminate_unix_test.c @@ -258,6 +258,24 @@ int nanosleep(const struct timespec *req, struct timespec *rem) } } +/* The poll loops in process_unix.c measure how long they have actually waited + * instead of assuming every nanosleep() costs exactly what was requested, so + * the fake clock has to drive clock_gettime() as well. Without this the mocked + * nanosleep() above advances fake time while the loops read real time, and the + * fake process reacts on a schedule the loops cannot observe. + * + * current_time is a nanosecond counter, matching the units the tests already + * use for reaction times (e.g. 2000000000 for two seconds). */ +int clock_gettime(clockid_t clk_id, struct timespec *tp) +{ + (void) clk_id; + + tp->tv_sec = current_time / 1000000000; + tp->tv_nsec = current_time % 1000000000; + + return 0; +} + /* Tests */ void test_kill_simple_process(void)