Skip to content

CFE-4728: Fixed process poll loops counting iterations instead of measuring elapsed time - #6300

Open
djbclark wants to merge 1 commit into
cfengine:masterfrom
djbclark:fix/exec-timeout-poll-deadline
Open

CFE-4728: Fixed process poll loops counting iterations instead of measuring elapsed time#6300
djbclark wants to merge 1 commit into
cfengine:masterfrom
djbclark:fix/exec-timeout-poll-deadline

Conversation

@djbclark

@djbclark djbclark commented Aug 17, 2026

Copy link
Copy Markdown

ProcessWaitUntilStopped() and ProcessWaitUntilExited() in
libpromises/process_unix.c 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 asked, so the loops counted iterations rather
than measuring a duration, and overshot by whatever the platform's timer
granularity happens to be.

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.

What this does not fix

It does not make a timed-out commands: promise report as timed out. An
earlier version of this report claimed it did; that claim is withdrawn.

Shrinking the ladder only narrows the window in which the real defect is
reached — RepairExec() never returns ACTION_RESULT_TIMEOUT, so the promise
is judged solely on the child's exit status. That is filed separately as
CFE-4726 and offered as
#6299. The two are independent and touch disjoint files; this one stands on its
own as a timing defect.

Measurement

Re-measured on this branch before offering it, macOS 26.6.1 arm64, three runs
each. A single-process command that ignores SIGINT and SIGTERM under
exec_timeout => "2", so only SIGKILL ends it and the full ladder has to run:

stock 17eb78e6d   11.36s / 10.80s / 10.90s
this branch        4.54s /  4.48s /  4.41s

Subtracting the 2s timeout, that is an ~8.9s ladder becoming ~2.4s.

The command has to be a single process. sh -c "trap '' INT TERM; sleep 30"
does not measure this: the shell is killed but its sleep grandchild survives
holding the pipe, so cf_pclose() blocks for the full 30s. That measures a
different defect (CFE-4729,
descendants not signalled), not this ladder.

The change

Both loops 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 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; 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 carry the previous timestamp and shift the deadline back by any backward
step, so the remaining budget is preserved rather than extended. A forward step
still ends the wait early, the conservative direction for a timeout.

Things to push back on

  1. timeout_ns <= 0 now enters the loop once. The loops became do/while on
    a deadline, where while (timeout_ns > 0) did not enter at all. The only
    caller passes STOP_WAIT_TIMEOUT, so this is not reachable in production,
    but it is a real semantic change: ProcessWaitUntilExited(pid, 0) on an
    already-exited process now returns true where it returned false without
    looking. Happy to restore the guard.
  2. The unit test cannot demonstrate the overshoot.
    process_terminate_unix_test.c mocks nanosleep() and advances a fake clock
    by the requested sleep — precisely the accounting being removed — so it now
    also has to drive clock_gettime() from that same fake clock, or the loops
    read real time while the fake process reacts on fake time and
    test_kill_long_reacting_signal fails. The mock makes nanosleep() exact by
    construction, so the test is a regression guard for the new code path, not
    evidence of the bug. The measurements above are the evidence.
  3. Mocking clock_gettime() overrides libc for that whole test binary. It
    mirrors what the file already does for nanosleep(), and all three reviewers
    accepted it, but it is fragile: libutils' mutex.c also calls
    clock_gettime(CLOCK_REALTIME), so a future timed pthread_cond_timedwait
    in that binary would see 1970. -Wl,--wrap=clock_gettime is the less
    invasive alternative; not taken here, to keep the production helper plain.
    Happy to switch.
  4. assert(timeout_ns < 1000000000) and the "only timeouts < 1s are
    supported" comments are arguably stale
    — the deadline arithmetic is
    int64_t and no longer cares. Left untouched to keep the diff minimal;
    reviewers split on whether the assert still usefully documents the API. Say
    the word and they go.

Tests

make -j2                              rc=0, 0 warnings
tests/unit make check                 rc=0, 64 PASS + 4 XFAIL = 68
process_terminate_unix_test           PASS

The four XFAILs are pre-existing and unrelated (process_test — Darwin has no
process_darwin.c, so GetProcessState() cannot report STOPPED or ZOMBIE — and
the non-deterministic mon_processes_test). The process_unix.c change was
reverted to stock and restored byte-identical by sha256, with a clean tree and a
clean rebuild.

Built and tested against the stock libntech submodule pointer 5b5d04e1, which
is what master 17eb78e6d records.

Notes

Cut from master 17eb78e6d. The only drift to current master is the libntech
submodule bump in #6297, which does not touch any path in this change.

Tracked as CFE-4728.

…psed 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
djbclark added a commit to frdminc/tendcf that referenced this pull request Aug 17, 2026
…ith #6299

B-1 shipped with the withdrawn fail-open claim stripped from the commit
message -- 26634ac1f's body still asserted the patch stops a timed-out
command being reported as kept, which the panel retracted on 2026-08-17.
The upstream commit and PR body both state the withdrawal instead.

Re-measured the ladder independently rather than citing the old numbers:
stock 11.36/10.80/10.90s vs branch 4.54/4.48/4.41s. The measurement needs
a SINGLE-process command -- sh -c "trap '' INT TERM; sleep 30" measures
B-2 instead, because the surviving sleep grandchild holds the pipe for the
full 30s.

B-2 is recorded as blocked rather than pending: it conflicts with #6299
(merge-tree rc=1, 10 markers) because both edit SetTimeOut()/TimeOut().
The changes are complementary, but resolving them is new C in a signal
path and needs fable-deep.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Development

Successfully merging this pull request may close these issues.

1 participant