Tests: size wait_process_paused for the operation it waits on

[madolson]

wait_process_paused used one hardcoded 5 second budget for two different kinds of wait. That is correct for pause_process, which sends SIGSTOP itself, but the callers that arm a self-stopping debug point wait for the server to get there on its own, and for DEBUG PAUSE-AFTER-FORK that budget also has to cover the primary noticing the reconnecting replica, deciding on a full sync and completing the fork(). When that sequence takes longer than 5 seconds, under valgrind or whenever the fork start is delayed, the test throws process didn't stop against a perfectly healthy server. This defaults the budget to 30 seconds (100 under valgrind) and has pause_process pass the short 5 second budget explicitly, so signal-driven stops still fail fast.

Fixes #45.

Details

Problem

tests/support/util.tcl:741 before this change:

proc wait_process_paused pid {
    wait_for_condition 50 100 {

50 * 100ms = 5 seconds for every caller. Two shapes of caller exist:

• pause_process (tests/support/util.tcl:750) runs kill -SIGSTOP first, so the stop is near-immediate and 5 seconds is generous.

• Self-stop waiters. tests/integration/dual-channel-replication.tcl:832 arms debug pause-after-fork 1 at line 825 and then waits for the primary to raise(SIGSTOP) on itself. The hook runs after the fork, src/replication.c:1054:

  if (server.debug_pause_after_fork) debugPauseProcess();

  debugPauseProcess is raise(SIGSTOP), src/debug.c:2613. So the 5 seconds has to cover everything up to and including the fork(). tests/integration/dual-channel-replication.tcl:11 (wait_and_resume_process) and tests/integration/replication-busy-psync.tcl:29 (pause-before-psync) are the same shape.

Reproduction

The wait is not slow locally, which is why only CI saw this. Instrumented on unpatched agents/unstable, it completes in 48-53ms over 5 loops, a 100x margin. Valgrind eats that margin: #4562's message records the enclosing test at 27-31s under valgrind in CI.

To force it locally, delay the fork instead of slowing the process. Adding one line before the second arming at tests/integration/dual-channel-replication.tcl:825:

$primary config set repl-diskless-sync-delay 10 ;# REPRO45

The sync is diskless with an EOF-capable replica, so syncCommand takes the delayed branch and logs Delay next BGSAVE for diskless SYNC (src/replication.c:1294) instead of forking. replicationCron only starts the fork once max_idle >= server.repl_diskless_sync_delay (src/replication.c:5585), which puts debugPauseProcess() about 10 seconds after the wait begins, against a 5 second budget.

5/5 fail before the change:

run 1 exit=1 : 1 failures
run 2 exit=1 : 1 failures
run 3 exit=1 : 1 failures
run 4 exit=1 : 1 failures
run 5 exit=1 : 1 failures

[exception]: Executing test client: assertion:process didn't stop.
 in fail at tests/support/test.tcl:10
 in fail at tests/support/util.tcl:744
 in wait_for_condition at tests/support/test.tcl:147
 in wait_process_paused at tests/support/util.tcl:742
 in wait_process_paused at tests/integration/dual-channel-replication.tcl:834
 in start_server at tests/support/server.tcl:769
 in start_server at tests/integration/dual-channel-replication.tcl:784

Same frame shape as the reported Daily failure, no test frame, because the wait sits at start_server body level rather than inside the test block. Line 834 rather than 832 is the two injected repro lines.

5/5 pass after the change, with the measured wait now showing what the old budget was missing:

run 1 exit=0 : 0 failures, REPRO45 wait_process_paused took 10801 ms, 1 pass-banner
run 2 exit=0 : 0 failures, REPRO45 wait_process_paused took 9716 ms, 1 pass-banner
run 3 exit=0 : 0 failures, REPRO45 wait_process_paused took 9567 ms, 1 pass-banner
run 4 exit=0 : 0 failures, REPRO45 wait_process_paused took 9680 ms, 1 pass-banner
run 5 exit=0 : 0 failures, REPRO45 wait_process_paused took 9620 ms, 1 pass-banner

Decisions

Why not gate the longer budget on valgrind only. Upstream #4562 (c27cc74bc) fixes the same helper with if {$::valgrind} {set retries 1000} else {set retries 50}. That leaves 5 seconds for every non-valgrind run, and 5 seconds is not derived from anything: the operation being waited on is a full-sync fork, whose latency depends on dataset size, sync delay and machine load, none of which is valgrind-specific. The reproduction above is a non-valgrind failure of exactly this shape. The test framework has no sanitizer flag (only $::valgrind at tests/test_helper.tcl:54), so sanitizer builds get the non-valgrind budget too.

Why the default and not per call site. Three self-stop call sites exist (tests/integration/dual-channel-replication.tcl:11 and :832, tests/integration/replication-busy-psync.tcl:29) against one signal-driven caller. Putting the long budget in the default and the short one in pause_process touches one proc instead of three files, and any new self-stop waiter gets the right budget by default.

Fail-fast cost. A genuinely wedged self-stop now takes 30 seconds to report instead of 5. pause_process, where a 5 second stall really is a bug, keeps the old budget.

Testing

The reproduction above is the load-bearing part: the injected repl-diskless-sync-delay 10 fails 5/5 without this patch and passes 5/5 with it.

This was generated by AI but verified, with love, by a human.