fix(engine): close the divert before saying why a session stopped - #212
Conversation
Every engine stop path passed its reason to the log callback before it stopped: the duration deadline, a recv error, a dead worker, a stalled capture thread, a failed scenario timeline and a start() that failed halfway. The CLI log is a synchronous stderr write, and a console with a text selection (QuickEdit) or a pipe nobody reads holds that write. The divert then stayed open, with the network impaired, for as long as the write was held. A log callback that raised was worse: on the deadline line it killed the watchdog, so the session never stopped. - BeanEngine.log is now a method around the callback; an exception from it is recorded in the crash log and goes no further. - _stop_locked takes the lines to say and says them after every handle of the session is released, before "Stop.", so the log keeps its order. _worker_stop and _fault_stop_blocking say them when they bow out. - The deadline, the recv error and the start() failure handler hand their lines to the stop instead of saying them first. - The scenario runner tells the engine before it logs the failure. Guards: a test that holds the log on all six paths and requires the divert to close while it is held, a test with a log that raises, a runner order test, and seven mutation entries (all caught). Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
|
Navigate logical layers of code changes, visualize relationships, and explore their blast radius. No actionable comments were generated in the recent review. 🎉 ℹ️ Recent review info⚙️ Run configurationConfiguration used: Repository UI (base), Organization UI (inherited) Review profile: ASSERTIVE Plan: Advanced Run ID: 📒 Files selected for processing (6)
Included review availability: This review used your included allowance. Your plan provides up to 1 included review per hour; 0 remain after this review. 📜 Recent review details⏰ Context from checks skipped due to timeout. (9)
🧰 Additional context used📓 Path-based instructions (14)Applies to text shown to the user (labels, buttons, tooltips, placeholders, dialogs, errors, status messages, empty states, translations).⚙️ CodeRabbit configuration file Files:
Verify tests check real behavior and would fail if the implementation were broken.⚙️ CodeRabbit configuration file Files:
Domain: network condition simulator (latency, loss, throttling, disconnects) built on WinDivert via PyDivert, with a Tkinter GUI and a CLI over one engine.⚙️ CodeRabbit configuration file Files:
These are end-user desktop applications.⚙️ CodeRabbit configuration file Files:
Performance is a known weak spot of these projects.⚙️ CodeRabbit configuration file Files:
Applies only to code that builds or styles a GUI.⚙️ CodeRabbit configuration file Files:
User-facing changelog.⚙️ CodeRabbit configuration file Files:
SECURITY, HIGH PRIORITY.⚙️ CodeRabbit configuration file Files:
These apps are QA/developer tools.⚙️ CodeRabbit configuration file Files:
Check that documentation matches the actual code in this PR: commands, flags, config keys, file paths, build steps and examples must exist.⚙️ CodeRabbit configuration file Files:
Python code.⚙️ CodeRabbit configuration file Files:
All code in this repository is written by an AI coding agent (Claude Code).⚙️ CodeRabbit configuration file Files:
Source excerpt: **Flat hyphen only.**📄 CodeRabbit inference engine (.github/claude-review-rules.md) Files:
Source excerpt: **Anything visible from outside goes in the changelog.**📄 CodeRabbit inference engine (.github/claude-review-rules.md) Files:
🪛 LanguageToolCHANGELOG.md[locale-violation] ~14-~14: In American English, ‘afterward’ is the preferred variant. ‘Afterwards’ is more commonly used in British English and other dialects. (AFTERWARDS_US) 🔇 Additional comments (7)
📝 WalkthroughWalkthroughEngine stop paths now close session resources before logging stop reasons. Log sink exceptions are recorded instead of propagated. Scenario failures notify the engine before invoking the configured logger. ChangesStop teardown and failure reporting
Priority: ⬇️ Low Estimated code review effort: 3 (Moderate) | ~20 minutes Change: Bug fix Sequence Diagram(s)sequenceDiagram
participant Watchdog
participant BeanEngine
participant Divert
participant Resolver
participant SocketWatcher
participant LogSink
Watchdog->>BeanEngine: Pass duration stop message
BeanEngine->>Divert: Close divert
BeanEngine->>Resolver: Stop resolver
BeanEngine->>SocketWatcher: Stop socket watcher
BeanEngine->>LogSink: Emit stop message
BeanEngine->>BeanEngine: Record STOP event
Merge Risk: ⚪ Minimal · up to The stop and failure-reporting changes are mergeable after normal checks; no actionable issue remains. Security Architecture ReviewSecurity architecture risk: 🔵 Low · up to The changed stop paths generally close the network diversion before calling a logger that might block or fail. A concurrent-stop path still lacks that ordering guarantee, but the same exposure existed before this change. The design merits review because safe shutdown depends on this ordering, and real-driver behavior has not been established by the available evidence. Retained concerns Security review detailsSecurity Blast Radius
Security Findings and Attack Paths
Trust Boundaries and Controls
Resilience and Maintainability Implications
Hardening Proposals
🚥 Pre-merge checks | ✅ 13 | ❌ 1❌ Failed checks (1 warning)
✅ Passed checks (13 passed)
Full details: No Resource LeaksExplanation The new Resolution Complete all session cleanup before invoking any potentially blocking caller log sink. Move Thanks for using CodeRabbit! It's free for OSS, and your support helps us grow. If you like it, consider giving us a shout-out. Comment |
The reason lines were said right after the divert and the other handles were released, but before the worker joins, the release of the timer request and the thread switch interval, the queue cleanup and the atexit entry. With a log that blocks, all of those stayed held until the log moved. They are now said at the very end, just before "Stop.", so the log reads in the same order and a held log keeps nothing of the session. The blocked-log test now also requires the session to be fully torn down while the log is held, and a new mutation puts the lines back before the rest of the teardown. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
1 participant
What was wrong
Every engine stop path passed its reason to the log callback before it stopped. The CLI log is a synchronous stderr write. A console window with a text selection (QuickEdit), or a pipe nobody reads, holds that write. While it is held, the divert stays open and the network stays impaired.
Reproduced with a log callback that blocks on the line each path says, on fake diverts only (no real capture). All six paths kept the divert open for exactly as long as the log was held:
--durationdeadline (watchdog)Time limit reached (... s) - session stopped.recv error: ..., then the engine faultEngine fault: worker thread ... died unexpectedly ...Engine fault: capture thread stopped making progress ...Scenario stopped: ...start()failing after the divert openedEngine fault: ...A log callback that raised was worse. On the deadline line it killed the watchdog, so the session never stopped and nothing was left watching it. At start, the failure handler's own fault line raised before it could stop, so the divert stayed open and the caller got the log's error instead of the real one.
The fix
BeanEngine.logis now a method around the callback. An exception from it is recorded in the crash log and goes no further, so it can no longer kill a worker thread or cut a teardown short._stop_locked(reason, say=())says the reason lines at the very end of the teardown. That is after the divert and the other handles are closed, the worker threads are joined, the timer request and the thread switch interval are released, and the engine is removed from the atexit list. They still come beforeStop., so the log reads in the same order as before. If the session is already stopped, it says them straight away._worker_stopand_fault_stop_blockingtake the same lines and say them when they bow out to another stop, which is the one closing the divert._fail_stop(..., lead=())takes the recv-error line instead of the capture thread saying it first. The deadline and thestart()failure handler go throughsaytoo.engine.worker_failedbefore it logs the failure. That line stays on the runner's own log, soScenario stopped: ...now comes afterStop.. This is the one visible change in order.The GUI log was never affected: it only puts lines on a queue.
Guards
test_failsafe.py::test_a_stop_closes_the_divert_while_the_log_is_still_blockedholds the log on each of the six paths. The divert must close while the log is still held, and once the log moves the reason must come beforeStop..test_failsafe.py::test_a_log_that_raises_cannot_cancel_a_stopcovers a log that raises: the deadline still stops the session, and a failed start still closes the divert and raises its own error.test_scenario_runner.py::test_a_broken_timeline_stops_the_session_before_it_says_sochecks the runner order.tools/mutate.pyand all were caught.Review follow-up (second commit)
The first commit said the reason right after the handles were released, before the worker joins and the release of the timer request, the thread switch interval and the atexit entry. With a log held for 1.2 s at the deadline, the divert was closed, but the engine was still on the atexit list and still held the timer request and the switch interval until the log moved. The second commit moves the lines to the end of the teardown. The blocked-log test now also requires the session to be fully torn down while the log is held, and a new mutation that moves the lines back is caught.
Two other review points were considered and left as they are:
Not in this change
Start. Filter: ...) is still said while the divert is open, before the capture thread exists, under the stop lock. That window is being reworked in a separate change to the start order.Checks run locally
internal_tools/guards.py --strong --run --lint: 97 test files, ruff and mypy on the changed modules. It found two failures:test_target_resolver.py::test_repeated_start_stop_cycles_do_not_stack_resolver_threads. This is a timing flake that already exists onmaster. Under sustained CPU load, measured alternately on this branch and onmaster: 3 of 15 red here, 4 of 15 red onmaster. It passes 6 of 6 in isolation. The resolver does not wait for a scan in progress by design, and the test allows the thread only 0.2 s.🤖 Generated with Claude Code