Repository navigation
[MOD-19365] Bound the default Redis shutdown wait - #259
Conversation
|
Fix looks right: it bounds the wait and records the -9. One concern: in RedisJSON's regular nightly lanes, the forced kill won't fail the test.
Suggestion, either of:
I'd prefer (1): it covers every module repo that uses RLTest, not just RedisJSON. Nice to have: on SIGKILL, also print the end of the server log file (like |
gabsow
left a comment
There was a problem hiding this comment.
Review findings on 2ffaacc, to address before un-drafting.
The bound itself works: the 5 tests pass (py3.14/macOS), and master does hang in the post-30s communicate(). Two issues come from how it's bounded: communicate() waits for pipe EOF, not just process exit, and Redis fork children (AOFRW/BGSAVE) inherit stdout/stderr.
Probe with Python stand-ins for Redis (Linux code path, timeouts patched to 2s/1s):
| case | master | this PR |
|---|---|---|
| A: ignores SIGTERM, fork child still alive | hangs | TimeoutExpired escapes stopEnv; parent reaped with -9 but slaveExitCode=None, slaveProcess not cleared |
| B: exits 0 on SIGTERM, fork child still alive | returns in 0.10s, exit 0 | waits the full grace, logs "did not exit on SIGTERM; sending SIGKILL", then TimeoutExpired |
Case A is the slow initial-AOFRW case (rewrite > 30s): SIGKILL doesn't kill the rewrite child. The repro in the description resumed the rewrite before the kill, so it never exercised this.
Suggested shape:
process.wait(timeout)instead ofcommunicate()(bounded on the process, not the pipes).- Re-send SIGTERM ~1/s during the grace. A refused shutdown is reset, so a later SIGTERM should succeed once the rewrite finishes -> clean exit 0 instead of -9 (worth confirming against 8.8
prepareForShutdown). This also helps with @LiranAbir's point: fewer forced kills, and the remaining ones are real. - Then
kill()+wait(_KILL_TIMEOUT), withTimeoutExpiredcaught and logged sostopEnvstill clears state and cluster teardown continues.
Also still unbounded and untouched: the Darwin child loop's p.wait() (L476). My first macOS probe hung there.
| except subprocess.TimeoutExpired: | ||
| print(Colors.Bred('[TERMINATING] {0} server id {1} did not exit on SIGTERM; sending SIGKILL'.format(role, serverId))) | ||
| process.kill() | ||
| process_out, process_err = process.communicate(timeout=_KILL_TIMEOUT) |
There was a problem hiding this comment.
This runs after SIGKILL but still waits for pipe EOF. If Redis had a fork child alive (AOFRW > 30s), the child keeps stdout/stderr open and this raises TimeoutExpired. Only OSError is caught (L509), so it escapes stopEnv: slaveProcess isn't cleared, and in redis_cluster.stopEnv the shard loop aborts, leaving the remaining shards running. Reproduced with a stand-in (case A in the review). process.wait(timeout=_KILL_TIMEOUT) plus catch-and-log would bound it on the process only.
There was a problem hiding this comment.
Addressed in 1f7b82a. The post-SIGKILL path now uses process.wait(timeout=5) and catches/logs TimeoutExpired, so inherited pipe handles cannot delay parent reaping or abort remaining shard teardown. The regression verifies that the process reference is cleared and the next shard is stopped even when the kill wait times out. A real Redis 8.8 replica with its initial AOF rewrite child kept paused through escalation returned in 30.01 seconds, recorded exit -9, cleared slaveProcess, and marked shutdown failure.
| process_out, process_err = process.communicate() | ||
| print(Colors.Bred(f'\t[TERMINATING] out ({process_out}), error ({process_err})')) | ||
| try: | ||
| process.communicate(timeout=_TERMINATE_TIMEOUT) |
There was a problem hiding this comment.
communicate() completes on pipe EOF + exit, not on exit alone. A process that exits cleanly while a child still holds the pipes now costs the full 30s + 5s and raises (case B; master returned in 0.1s), with a misleading "did not exit on SIGTERM" line. process.wait(timeout=...) keeps the old poll() semantics; draining shouldn't be needed since Redis logs to --logfile.
There was a problem hiding this comment.
Addressed in 1f7b82a. The grace period now waits on the process rather than communicate()/pipe EOF. Added real fork-child regressions for both a clean parent exit and an ignored SIGTERM while the child keeps stdout/stderr open. Both return within the bounded test deadline; the clean case records exit 0 without a forced-shutdown failure. The 11 focused shutdown cases pass on Python 3.7/Linux and 3.14/macOS.
| process.kill.assert_called_once_with() | ||
| assert [call[1] for call in process.communicate.call_args_list] == [ | ||
| {'timeout': 30}, {'timeout': 5}] | ||
| assert env.masterProcess is process |
There was a problem hiding this comment.
This pins TimeoutExpired propagating out of _stopProcess as intended behaviour. I'd rather assert the opposite: stopEnv returns, logs, and clears masterProcess. Also worth a case with a fork child holding the pipes (A/B in the review): all current cases use a childless process, where pipe EOF == exit, so they can't see the difference.
There was a problem hiding this comment.
Replaced that expectation in 1f7b82a. The timeout regression now asserts that teardown returns, clears the process reference, records shutdown failure, and continues to the next shard. Added both inherited-pipe cases from the review, plus SIGTERM retry and runner-level checks proving a forced shutdown fails standalone and cluster tests without --check-exitcode. All 11 shutdown regressions pass on Python 3.7 and 3.14; the isolated full unit suite passed 172 tests (5 skipped).
|
@LiranAbir Addressed your comment in 1f7b82a using option 1. A forced shutdown in the default path now sets a persistent shutdown-failure flag, propagated through the standalone/cluster environment to the runner. Also added a bounded tail of the server log (last 8 KiB) on SIGKILL, with read errors logged without interrupting teardown. SIGTERM is retried during the grace period to avoid a forced kill when the initial refusal is temporary: the real Redis 8.8 replica/AOF check exited cleanly in 1.07 seconds after its rewrite resumed; keeping the rewrite paused required SIGKILL and returned in 30.01 seconds with failure recorded. Validation: 11 shutdown regressions passed on Python 3.7 and 3.14; isolated full unit suite: 172 passed, 5 skipped. Updated CI is still running. This proves the teardown behavior, not the missing historical nightly trigger. |
|
Follow-up to the review summary: addressed in 1f7b82a, with individual replies on all three inline threads. The default path now uses process waits, retries SIGTERM about once per second within the 30-second grace period, and catches the 5-second post-SIGKILL timeout so teardown continues. The macOS child handling is restricted to interactive debuggers and uses bounded group waits (30 seconds, then 5 seconds after escalation); a regression covers the previous unbounded wait. Verified the SIGTERM retry behavior against real Redis 8.8: resuming the initial AOF rewrite yielded a clean exit in 1.07 seconds. Keeping the child paused through the entire grace period yielded exit -9 in 30.01 seconds, without waiting on inherited pipe EOF. Both stand-in inherited-pipe cases are also covered. All 11 focused regressions pass on Python 3.7/Linux and 3.14/macOS, and the isolated full unit suite passed 172 tests (5 skipped). The PR remains a draft while updated CI and review are pending. |
|
Thanks, 1f7b82a addresses my comment: a forced SIGKILL now records The cause of the original nightly hangs is still open in MOD-19365. With this change, a recurrence will show up as a failed test with the server log, instead of a job timeout. |
gabsow
left a comment
There was a problem hiding this comment.
Re-review of 1f7b82a: the earlier findings are fixed.
Verified locally (py3.14/macOS):
- 11/11 shutdown tests pass.
- Inherited-pipe probes, Linux code path: (A) ignores SIGTERM + live fork child: returns in 3.0s, exit -9, process cleared,
hasShutdownFailure()True (previously raised). (B) clean exit + live fork child: returns in 0.00s, exit 0 (previously full grace + raise). - Full unit suite: no PR-only failures. The ~12 failing tests here also fail on master (local environment).
Remaining, inline:
- Medium: 30s is now a hard kill + test failure, where master only started draining at 30s and then waited unbounded.
- Low:
_print_shutdown_logruns beforekill()and only catchesOSError. - Low:
shutdownFailedis never reset (misattribution under--env-reuse). - Note: the macOS lldb behaviour change.
(1) is the one to decide before un-drafting.
| print(Colors.Bred(f'\t[TERMINATING] out ({process_out}), error ({process_err})')) | ||
| # Wait on the process, not pipe EOF: Redis fork children can | ||
| # inherit stdout/stderr and outlive their parent. | ||
| deadline = time.monotonic() + _TERMINATE_TIMEOUT |
There was a problem hiding this comment.
On master, 30s was only where the old loop started communicate(), which then waited unbounded, so a slow but successful shutdown still passed. Now it's SIGKILL + redis process failure in every lane.
RLTest doesn't pass --save, so Redis's default save points apply and SIGTERM saves an RDB when the dataset is dirty. Under valgrind, that save plus --leak-check=full at exit could exceed 30s. That's reasoning, not measured.
Suggest scaling the grace under --use-valgrind/--sanitizer or making it configurable. Alternatively, run one module valgrind nightly (RTS/JSON) on this branch and grep for sending SIGKILL before merging.
There was a problem hiding this comment.
Addressed in 304834d by scaling the default grace to 300 seconds for Valgrind and sanitizer runs; normal runs retain 30 seconds, and the post-SIGKILL wait remains 5 seconds. Explicit terminateRetries/terminateRetrySecs settings retain their existing behavior. Added regressions for both instrumentation modes showing a process still exits cleanly after the old 30-second boundary (using a simulated clock), and documented the policy in README. The 17 focused shutdown/teardown tests pass on Python 3.7 and 3.14; the isolated full unit suite passes 176 tests (5 skipped).
I have not run a full module Valgrind nightly on this branch. The 300-second allowance addresses the overly tight instrumented default while keeping teardown bounded; it is not a measured worst-case limit for all workloads. Updated CI is pending.
| if process.poll() is None: | ||
| self.shutdownFailed = True | ||
| print(Colors.Bred('[TERMINATING] {0} server id {1} did not exit on SIGTERM; sending SIGKILL'.format(role, serverId))) | ||
| self._print_shutdown_log(role) |
There was a problem hiding this comment.
This runs before process.kill(), and _print_shutdown_log only catches OSError. _getFileName raises TypeError when outputFilesFormat is None (a StandardEnv built directly rather than via Env), and that escapes before the kill, leaving Redis running. Move it after kill()/wait(), or catch Exception there.
There was a problem hiding this comment.
Addressed in 304834d. Log-tail printing now happens after kill/wait, and both path construction and file reading are inside an Exception guard. The regression injects a TypeError from _getFileName and verifies that the Redis stand-in is reaped with -9, its process reference is cleared, the shutdown failure remains recorded, and the diagnostic error is logged. This protects against path-format failures without relying on the direct-constructor example.
| self.masterProcess = None | ||
| self.masterStdout = None | ||
| self.masterStderr = None | ||
| self.shutdownFailed = False |
There was a problem hiding this comment.
Never reset. With --env-reuse, a forced kill during test X (e.g. a mid-test env.stop()/restart) is reported at the final takeEnvDown under whichever test is current then. Minor; resetting it in startEnv would keep the attribution tight.
There was a problem hiding this comment.
Addressed attribution in 304834d, but did not reset the flag in startEnv: doing that could erase a forced-shutdown failure when the test immediately restarts Redis. Instead, _runTest records and consumes the failure under the originating test name at the end of that test, before reuse changes the name. Final teardown also consumes the flag when reporting it. Cluster aggregation visits every shard so resetting cannot short-circuit after the first failure.
A regression uses two failed shards and a following test in the reused environment: only the original test is marked failed, all flags are consumed, and final teardown does not blame the following test.
| p0 = psutil.Process(pid=process.pid) | ||
| pchi = p0.children(recursive=True) | ||
| for p in pchi: | ||
| if platform.system() == 'Darwin' and self.has_interactive_debugger: |
There was a problem hiding this comment.
Note: narrowing this to interactive debuggers is fine for plain macOS runs. But in an lldb session still at a breakpoint during teardown (e.g. debugging module shutdown), the inferior now gets SIGKILLed after 30s and the test is marked failed. Previously it waited for the user. Worth a line in the PR description.
There was a problem hiding this comment.
Documented in README and the PR description in 304834d. On macOS, debugger-child teardown allows 30 seconds after SIGTERM and then 5 seconds after SIGKILL. An inferior left paused at a breakpoint can now be killed and reported as a failure; teardown no longer waits indefinitely for debugger input. The existing bounded-debugger-wait regression remains passing.
|
Addressed all four points from the second review in new commit 304834d, with individual inline replies:
Validation: 17 focused shutdown/teardown cases pass on Python 3.7 and 3.14; the isolated Redis 8.8/Linux full unit suite passed 176 tests, 5 skipped. A full module Valgrind nightly was not run. Updated CI is pending and the PR remains a draft. @LiranAbir, your failure-reporting and server-log-tail requirements are preserved in this follow-up. Your approval was on the previous commit; this update still needs review. |
|
Natural stress reproduction now confirms the shutdown mechanism in both affected tests, without pausing children or changing the RedisJSON tests. Setup: RedisJSON
Representative original-code timeline: the master finished synchronization and exited at 12:46:55.998. The replica refused SIGTERM at 12:46:56.020 ( The pinned Redis source explains this: initial AOF rewrite refusal follows the error path into Master/replica logs, snapshots, stacks, runner output, binary hashes, and reproduction scripts are preserved in the stress evidence bundle. The different worker counts are not a controlled rate comparison. Historical Redis logs remain unavailable, so this reproduces a matching failure on the pinned failing setup rather than proving every past incident had the same cause. No further code change was needed for this reproduced case. |
|
@LiranAbir We reproduced the hang naturally under stress and confirmed that the latest version fixes the root cause of the reproduced hang, beyond just bounding the wait or killing Redis. Redis refuses SIGTERM while writing its initial AOF to protect the dataset. The old RLTest sends SIGTERM only once and then waits indefinitely, even after the AOF rewrite finishes. The updated shutdown code retries SIGTERM, allowing Redis to exit cleanly after the rewrite completes. Evidence:
The logs establish this cause for the reproduced hangs; missing historical Redis logs mean we cannot claim every previous nightly timeout had the same cause. The detailed evidence is in #259 (comment). Your earlier approval was dismissed after the follow-up review fixes. Could you please re-review and approve the current head so we can merge? The PR is now ready for review. |
|
@LiranAbir Both Bugbot findings are fixed in new commit 3938c1c, with replies on both threads. The three new regression cases reproduce the failures on the previous head and pass with the fixes; all 20 focused shutdown/teardown tests pass. The full Linux comparison shows the same 11 existing failures before and after, with three additional passing regressions. Fresh CI is starting; please re-review this head for approval. |
|
Pre-release verification of approved head 3938c1c: all CI test jobs passed. An additional 32 RedisJSON stress tests passed against the pinned failing-nightly image and module source; three natural initial-AOF shutdown refusals occurred, with no SIGKILL. The disposable test container has been removed. Waiting for the current Bugbot run before merge/release. |
|
@LiranAbir The final Bugbot run found one additional low-severity skip-test attribution issue. Fixed in follow-up commit ef02f7d, with four regression cases; all 24 focused tests pass. Please re-approve this small follow-up once CI is green. After merge I will publish 0.7.31 and open the module dependency-update PRs. |
|
@LiranAbir The final Bugbot pass found constructor-skip failure leakage and premature PASS output before teardown. Both are fixed in 14345f0; replies and regression evidence are on the threads. All 28 focused tests pass, with the new cases verified against the previous head. Please re-review this follow-up once CI completes; merge and 0.7.31 publication remain on hold until approval and checks pass. |
|
@LiranAbir The remaining low-severity Bugbot finding is fixed in 21c01ba: SKIP now waits for teardown just like PASS. Expanded coverage includes body and constructor skips with clean/forced shutdown; all 32 focused tests pass. Please review the latest follow-up when CI completes. Release and module update PRs are still waiting for this approval/check cycle. |
|
@LiranAbir Please give final approval on the current head, 21c01ba. Per Tom, we are stopping further changes for non-blocking Bugbot suggestions; those can be follow-ups. The shutdown fix and regression coverage are in place (32 focused tests pass). Once the current head is approved and required CI is green, I will merge and release, unless a genuine blocking issue is identified. |
There was a problem hiding this comment.
Cursor Bugbot has reviewed your changes using high effort and found 1 potential issue.
❌ Bugbot Autofix is OFF. To automatically fix reported issues with cloud agents, have a team admin enable autofix in the Cursor dashboard.
Reviewed by Cursor Bugbot for commit 21c01ba. Configure here.
| self.runner._pendingResults = None | ||
| if type is None and not self.runner._teardownFailed: | ||
| for printer, name in pending: | ||
| printer(name) |
There was a problem hiding this comment.
Class results print late or vanish
Medium Severity
EnvScopeGuard now holds every [PASS] and [SKIP] until the guard exits, but one guard wraps an entire test class. Failures still print immediately, so later method [FAIL] lines appear before earlier passes, and a forced class teardown sets _teardownFailed and drops queued passes for methods that already succeeded. Function tests are unaffected because each has its own guard.
Additional Locations (2)
Reviewed by Cursor Bugbot for commit 21c01ba. Configure here.


RLTest's default shutdown path can enter an unbounded wait when Redis refuses SIGTERM. The nightly can therefore pass its assertions but spend the entire job timeout in replica teardown.
Bound the default shutdown to a 30-second grace period (300 seconds under Valgrind or sanitizers), followed by SIGKILL and a 5-second process wait. Retry SIGTERM once per second during the grace period so Redis can shut down cleanly after a temporary refusal. Wait for process exit rather than pipe EOF, since Redis fork children can keep stdout/stderr open after the parent exits. Catch the kill timeout so remaining shards still get teardown and process references are cleared.
Forced shutdowns are recorded as test failures even without
--check-exitcode, through the standalone/cluster environment and test runner. A bounded tail of the server log is printed after kill/reap, and diagnostic errors cannot interrupt teardown. Mid-test shutdown failures are attributed and consumed at the end of that test, before environment reuse can change the test name. The macOS debugger child wait is also bounded to 30 seconds before SIGKILL and a further 5 seconds: an inferior paused at a breakpoint can be killed and reported as a failure instead of waiting indefinitely for input; ordinary Redis children are left to Redis's own shutdown handling. ExplicitterminateRetriesbehavior remains unchanged.Tracking: MOD-19365.
Validation after review:
--check-exitcodein standalone and cluster environments.git diff --checkpassed. CI reruns on the follow-up commit.The historical artifacts lack the relevant Redis server logs. Subsequent natural stress reproduced a matching failure on the pinned failing setup, as detailed below; this does not prove that every historical incident shared the same cause. The nightly stacks show replica teardown blocked in
communicate(): Sep 30, Oct 1, Oct 6. Kept as a draft for review.Natural stress reproduction
Natural stress reproduction now confirms the shutdown mechanism in both affected tests, without pausing children or changing the RedisJSON tests.
Setup: RedisJSON
fbe6eaed5f2cc3d80fc54c9fc840469a6cd840f3, the exact Oct-06 failed-run image digestsha256:20c5071155911763c7b739aff8e4de01bd305dadd64d4bd990ae8383a4f2ffa2(Redis unstableb540ca49), and RLTest304834d. Linux amd64 Docker on Apple Silicon, limited to 2 CPUs. The original_stopProcessfrom the PR base was verified to match the method installed in that nightly image.test_mset_replication_in_aof --use-slaves, 4 intestEveryWriteCommandIsCovered --use-aof). Every affected replica exited with code 0 after the next SIGTERM, in 1.035–1.071 seconds. No SIGKILL. Four additional sequential pilot executions passed.paella; that worker stopped early. All three hung replicas had finished AOF rewriting, had no remaining fork child, and were still alive at 37 seconds. Python stacks were in_stopProcess -> communicate -> selector.poll, matching the historical stacks. Only after capturing this evidence did the watchdog send a recovery SIGTERM; each replica then exited cleanly. The eventual baseline runner exit codes must not be interpreted as unassisted passes.Representative original-code timeline: the master finished synchronization and exited at 12:46:55.998. The replica refused SIGTERM at 12:46:56.020 (
Writing initial AOF, can't exit.), processed rewrite-child completion at 12:46:56.021, and finished the rewrite at 12:46:56.035. At 37.009 seconds it was still alive withaof_rewrite_in_progress=0, while Python was blocked incommunicate(). A recovery SIGTERM ended it immediately.The pinned Redis source explains this: initial AOF rewrite refusal follows the error path into
cancelShutdown(), clearing the pending shutdown request. Finishing the rewrite does not reinstate it. The old RLTest sends SIGTERM only once; the current retry handles this refusal and completes graceful shutdown. SIGKILL remains the fallback.Master/replica logs, snapshots, stacks, runner output, binary hashes, and reproduction scripts are preserved in the stress evidence bundle. The different worker counts are not a controlled rate comparison. Historical Redis logs remain unavailable, so this reproduces a matching failure on the pinned failing setup rather than proving every past incident had the same cause. No further code change was needed for this reproduced case.
Note
Medium Risk
Changes core process lifecycle and test pass/fail semantics for all Redis-backed runs; behavior is intentional but affects teardown timing and when tests fail without --check-exitcode.
Overview
Bounds default Redis teardown so nightlies cannot hang indefinitely when a server ignores SIGTERM (e.g. during initial AOF rewrite). The default path retries SIGTERM once per second for 30s (300s under Valgrind/sanitizers), then SIGKILL with a 5s exit wait; teardown waits on process exit instead of pipe EOF so fork children cannot block shutdown. Forced shutdowns set a
shutdownFailedflag surfaced viahasShutdownFailure()on standalone, OSS cluster, and enterprise cluster envs.Runner behavior treats forced shutdown as a test failure even without
--check-exitcode, attributes mid-test shutdown problems to the current test (including across env reuse/replacement), and defers [PASS]/[SKIP] printing until after env teardown so a late shutdown failure can flip the result. Skipped tests still run teardown and consume shutdown flags; macOS interactive debugger inferior waits are similarly bounded.README documents the policy;
tests/unit/test_shutdown.pyadds regression coverage for these paths.Reviewed by Cursor Bugbot for commit 21c01ba. Bugbot is set up for automated code reviews on this repo. Configure here.