fix: recover Hermes from stale nested tx9-logs mirror FDs - #27
Conversation
The boot workload could stay healthy while the gateway stayed down: hb launched nested tx9-logs with leftover TX9_LOG_MIRROR_*_FD values whose descriptors were already closed, so capture crashed with EBADF before exec, and the wrapper had no restart policy after a child exit. Sanitize the mirror-FD pair after closing lock descriptors, run the Hermes wrapper with --restart-delay, declare --external-supervisor, and make tx9-logs fall back to owned stdout/stderr dups when inherited FDs are missing, closed, or malformed. Co-authored-by: Ben Davis <bmdavis419@users.noreply.github.com>
|
No actionable comments were generated in the recent review. 🎉 ℹ️ Recent review info⚙️ Run configurationConfiguration used: Organization UI Review profile: CHILL Plan: Pro Plus Run ID: 📒 Files selected for processing (2)
🚧 Files skipped from review as they are similar to previous changes (1)
📝 WalkthroughWalkthroughThe change validates inherited mirror descriptors, adds configurable gateway restart supervision, reports startup failures, and makes gateway lifecycle handling aware of capture wrappers. Regression tests cover descriptor fallback, nested capture, reload retention, child replacement, shutdown, and diagnostics. ChangesGateway supervision and log capture
Possibly related PRs
🚥 Pre-merge checks | ✅ 5✅ Passed checks (5 passed)
Comment |
![macroscopeapp[bot]](https://avatars.githubusercontent.com/in/900172?s=60&v=4){kind=small}
| if fd < 0: | ||
| return None | ||
| try: | ||
| os.fstat(fd) |
There was a problem hiding this comment.
🟠 High guest/tx9-logs:864
inherited_open_fd accepts a stale FD number as valid whenever os.fstat(fd) succeeds, so FD reuse causes Capture.__init__ to dup2 unrelated files onto stdout/stderr. A reused read-only lock FD then makes mirrored writes fail, while a writable FD sends log output to the wrong file; validate that the descriptor is the expected mirror rather than only checking that it is open.
🚀 Reply "fix it for me" or copy this AI Prompt for your agent:
In file @guest/tx9-logs around line 864:
`inherited_open_fd` accepts a stale FD number as valid whenever `os.fstat(fd)` succeeds, so FD reuse causes `Capture.__init__` to `dup2` unrelated files onto stdout/stderr. A reused read-only lock FD then makes mirrored writes fail, while a writable FD sends log output to the wrong file; validate that the descriptor is the expected mirror rather than only checking that it is open.
os.fstat() raises OverflowError for values that do not fit a C int. Catch that alongside OSError so Capture falls back instead of crashing, and keep the restart-delay child fixture in a script so shellcheck stays quiet. Co-authored-by: Ben Davis <bmdavis419@users.noreply.github.com>
![devin-ai-integration[bot]](https://avatars.githubusercontent.com/in/811515?s=60&v=4){kind=small}
| launcher_log="${logfile%.log}.launcher.log" | ||
| capture_cmd=(tx9-logs capture --source "$source" --log-dir "$log_dir") | ||
| if [[ "$source" == hermes ]]; then | ||
| # The wrapper is Hermes' process manager. Restart unexpected child | ||
| # exits; --external-supervisor makes in-chat restart/update return | ||
| # here instead of daemonizing a replacement. | ||
| capture_cmd+=(--restart-delay "$GATEWAY_RESTART_DELAY") | ||
| child_cmd+=(--external-supervisor) | ||
| fi | ||
| exec nohup "${capture_cmd[@]}" -- "${child_cmd[@]}" \ | ||
| </dev/null >/dev/null 2>>"$launcher_log" |
There was a problem hiding this comment.
🔴 Every line Hermes prints is copied into a second log file that is never rotated or size-capped
The Hermes supervisor's error output is pointed at a plain, never-trimmed file (2>>"$launcher_log" at guest/hb:223) that the logging wrapper then also uses as its live mirror, so every line Hermes prints is appended there forever on the durable volume.
Impact: The box's persistent disk can slowly fill with an unbounded duplicate copy of the Hermes log, which the existing size limits and rotation never touch.
Why the launcher log receives the full Hermes stream, not just launcher errors
_spawn_without_lock_fd now runs tx9-logs capture with stdout to /dev/null and stderr appended to $LOGS/hermes-gateway.launcher.log (guest/hb:213, guest/hb:222-223). Inside Capture.__init__, when no valid TX9_LOG_MIRROR_*_FD pair is inherited — which is the normal case for a login-shell hb up, and also the exact stale-FD case this PR fixes — the wrapper dups its own stderr as the mirror descriptor (guest/tx9-logs:905-907). Capture.output unconditionally mirrors every captured chunk: write_all(self.mirror_out if stream == "stdout" else self.mirror_err, mirrored) (guest/tx9-logs:1029). So all of Hermes' stderr is written verbatim into hermes-gateway.launcher.log in addition to the rotated hermes-gateway.log/hermes.jsonl written by RotatingWriter.
The launcher log is a bare file: nothing in the repo rotates, truncates, or prunes it (rotated_paths at guest/tx9-logs:1440-1452 only matches hermes-gateway.log.<digits>, and logs() at guest/hb:925-937 only tails $LOGS/<name>.log). Before this change the same stream went to /dev/null (2>&1 into /dev/null), so nothing accumulated.
Prompt for agents
In guest/hb `_spawn_without_lock_fd`, the nested `tx9-logs capture` for Hermes is spawned with its stderr appended to `$LOGS/hermes-gateway.launcher.log`. That file is intended only to capture wrapper failures that happen before Hermes is exec'd, but `Capture` in guest/tx9-logs dups its own stderr as the docker mirror descriptor whenever no valid inherited TX9_LOG_MIRROR_*_FD pair exists (guest/tx9-logs:902-907), and `Capture.output` mirrors every captured line to that descriptor (guest/tx9-logs:1029). The result is that the entire Hermes output stream is duplicated into an unrotated, unpruned file on the durable /data volume, defeating TX9_LOG_MAX_BYTES/TX9_LOG_MAX_FILES.
Possible approaches: bound the launcher log (rotate/truncate it on each spawn, or cap it), or avoid making it the mirror target — e.g. keep the launcher log only for pre-exec diagnostics by having the wrapper stop using its inherited stderr as the mirror when it is a file rather than a terminal/pipe, or explicitly pass a distinct mirror target. Whatever is chosen, the durable log volume must not grow without bound.
Was this helpful? React with 👍 or 👎 to provide feedback.
| _report_gateway_start_failure() { | ||
| _steady_report gateway-start failed "$1" stderr | ||
| } |
There was a problem hiding this comment.
🟡 Repeated gateway start failures still print once per reconcile cycle into the durable log stream
The gateway start-failure message is routed through the repeat-suppressing reporter (_steady_report at guest/hb:180), but the periodic reconciliation never turns suppression on, so an ongoing failure is re-logged on every cycle exactly as before.
Impact: A persistently failing Hermes start floods the durable agent log with one identical line every reconcile cycle, and the new suppression state file is never used in production.
Why suppression never engages
_steady_report only consults/writes $HB_RUNTIME_STATE_DIR/<key>.state when HB_STEADY_QUIET == 1; otherwise it prints immediately and returns (guest/hb:54-57). reconcile() enables quiet mode only for the executor check — HB_STEADY_QUIET=1 _executor_up (guest/hb:426) — and then calls _start_gateway (guest/hb:427) with the default HB_STEADY_QUIET=0. hb-workload's loop invokes hb reconcile as a fresh process (guest/hb-workload:126) and does not export HB_STEADY_QUIET. The regression test only exercises the suppression by setting HB_STEADY_QUIET=1 by hand (tests/regressions-hb-workload.sh:1307), so the production path is uncovered.
Note also that both distinct failure messages share the single state value failed, so once quiet mode is enabled the second, different message would be suppressed as "unchanged".
Prompt for agents
guest/hb adds `_report_gateway_start_failure` which delegates to `_steady_report gateway-start failed ...`, but `_steady_report` only de-duplicates when HB_STEADY_QUIET=1, and `reconcile()` only sets that for `_executor_up`, not for `_start_gateway`. As a result the new suppression state file is never written in the reconcile loop and repeated gateway start failures are logged every cycle. Consider running the gateway start under quiet mode in `reconcile()` the same way the executor check is, and/or distinguish the two failure messages with different state values so quiet mode does not swallow a genuinely different failure.
Was this helpful? React with 👍 or 👎 to provide feedback.
![coderabbitai[bot]](https://avatars.githubusercontent.com/in/347564?s=60&v=4){kind=small}
There was a problem hiding this comment.
Actionable comments posted: 1
🧹 Nitpick comments (5)
guest/tx9-logs (2)
902-907: 📐 Maintainability & Code Quality | 🔵 Trivial | ⚡ Quick winDocument the nested-capture tradeoff in the fallback branch.
The inherited branch explains why it must replace stdout and stderr (lines 912-915). The fallback branch intentionally breaks that same invariant: it duplicates the inherited stdout and stderr, so under a nested capture the parent pipes stay open for the nested lifetime and each line is recorded by both captures. That is the correct choice over crashing before exec, but a reader cannot see it here.
Add a short comment stating that duplicate mirroring is accepted to keep the target exec'able.
🤖 Prompt for AI Agents
Verify each finding against current code. Fix only still-valid issues, skip the rest with a brief reason, keep changes minimal, and validate. In `@guest/tx9-logs` around lines 902 - 907, In the fallback branch that duplicates stdout and stderr when inherited descriptors are unavailable, add a short comment documenting that nested captures may duplicate mirroring because the parent pipes remain open, and that this tradeoff is accepted to keep the target exec'able. Keep the existing fallback behavior unchanged.
847-867: 📐 Maintainability & Code Quality | 🔵 Trivial | ⚡ Quick winAlign the docstring with what the check can prove.
os.fstatproves only that the FD number is currently open. It cannot prove the number still refers to the inherited mirror. If the descriptor was closed and the number was reused (for example by a lock or a log file),inherited_open_fdreturns it and capture output is then written into the unrelated file. The hb path closes lock FDs before validation, so the residual risk comes from other parents.State that limit in the docstring so later readers do not treat this as a reuse check.
📝 Proposed docstring wording
Environment presence is not a validity contract. Nested capture can retain TX9_LOG_MIRROR_*_FD strings after those descriptors were closed, reused for a lock, or never inherited into this process. + + The check only rejects values that are missing, malformed, negative, or + not open here. It cannot detect a number that was closed and then reused + by an unrelated descriptor; callers must close their own FDs first. """🤖 Prompt for AI Agents
Verify each finding against current code. Fix only still-valid issues, skip the rest with a brief reason, keep changes minimal, and validate. In `@guest/tx9-logs` around lines 847 - 867, Update the docstring for inherited_open_fd to state that os.fstat verifies only that the numeric descriptor is currently open, not that it still refers to the inherited mirror; descriptor reuse by another file or lock remains possible. Keep the existing validation logic unchanged.guest/hb (3)
179-181: 📐 Maintainability & Code Quality | 🔵 Trivial | ⚡ Quick winInclude the message in the dedup state token.
_steady_reportcompares only the state token (line 60). This reporter always passesfailed, and two different failures use it: the pending-capture message (lines 352, 365) and the nested-exit message (lines 392-393). In quiet mode the second cause is suppressed after the first one is recorded, so the operator sees a stale reason.♻️ Proposed change to keep distinct causes reportable
_report_gateway_start_failure() { - _steady_report gateway-start failed "$1" stderr + _steady_report gateway-start "failed:$1" "$1" stderr }🤖 Prompt for AI Agents
Verify each finding against current code. Fix only still-valid issues, skip the rest with a brief reason, keep changes minimal, and validate. In `@guest/hb` around lines 179 - 181, Update _report_gateway_start_failure so the message argument is included in the state token passed to _steady_report, while preserving the existing stderr reporting behavior. Ensure distinct gateway-start failure messages produce distinct deduplication states and are not suppressed as duplicates.
389-393: 📐 Maintainability & Code Quality | 🔵 Trivial | ⚡ Quick winDo not claim a pre-exec failure when the wrapper was still running.
_wait_gateway_pidreturns 1 both when the wrapper already died and when it found more than one gateway process. In the second case this code sends TERM itself, sowrapper_statusbecomes 143 and the message reports "nested tx9-logs exited 143 before Hermes exec". Hermes did exec in that case, so the reported cause is wrong.Record whether the wrapper was alive before the TERM, and report the two causes separately.
♻️ Proposed change
- local wrapper_status=1 - kill -TERM "$wrapper_pid" 2>/dev/null || true - wait "$wrapper_pid" 2>/dev/null && wrapper_status=0 || wrapper_status=$? - _report_gateway_start_failure \ - "Hermes gateway failed to start; nested tx9-logs exited ${wrapper_status} before Hermes exec; see: $LOGS/hermes-gateway.launcher.log" + local wrapper_status=1 wrapper_was_live=0 + kill -0 "$wrapper_pid" 2>/dev/null && wrapper_was_live=1 + kill -TERM "$wrapper_pid" 2>/dev/null || true + wait "$wrapper_pid" 2>/dev/null && wrapper_status=0 || wrapper_status=$? + if [[ "$wrapper_was_live" == 1 ]]; then + _report_gateway_start_failure \ + "Hermes gateway failed to start; the nested tx9-logs wrapper was stopped after an unclean launch; see: $LOGS/hermes-gateway.launcher.log" + else + _report_gateway_start_failure \ + "Hermes gateway failed to start; nested tx9-logs exited ${wrapper_status} before Hermes exec; see: $LOGS/hermes-gateway.launcher.log" + fiNote:
tests/static.shline 83 andtests/regressions-hb-workload.shline 1306 assert the "nested tx9-logs exited" text, which this change preserves for the pre-exec case.🤖 Prompt for AI Agents
Verify each finding against current code. Fix only still-valid issues, skip the rest with a brief reason, keep changes minimal, and validate. In `@guest/hb` around lines 389 - 393, Update the failure handling around _wait_gateway_pid to record whether wrapper_pid was alive before sending TERM. Report “nested tx9-logs exited … before Hermes exec” only when it had already exited; when it was still running, use a separate message indicating multiple gateway processes or the corresponding post-exec condition, while preserving the existing pre-exec text.
214-223: 🗄️ Data Integrity & Integration | 🔵 Trivial | ⚡ Quick winPin Hermes or validate the CLI contract. The provisioner installs the latest upstream Hermes; no release pin exists. A future CLI change could make the gateway exit and restart repeatedly. Pin a compatible release or validate
--external-supervisorduring provisioning.🤖 Prompt for AI Agents
Verify each finding against current code. Fix only still-valid issues, skip the rest with a brief reason, keep changes minimal, and validate. In `@guest/hb` around lines 214 - 223, Update the Hermes provisioning flow associated with the gateway launch using --external-supervisor to either pin Hermes to a known compatible release or validate that the installed CLI supports this option before launching. Ensure provisioning fails clearly or selects a compatible version when the contract is unavailable, preventing an unsupported flag from causing restart loops.
🤖 Prompt for all review comments with AI agents
Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.
Inline comments:
In `@guest/hb`:
- Around line 446-452: Add a bounded polling wait after the pkill command in the
gateway stop flow, using the existing _gateway_or_capture_running check and
sleep pattern, before the final failure check. Allow the loop to exit once no
gateway or capture process remains, then preserve the existing error handling if
the process is still reported running.
---
Nitpick comments:
In `@guest/hb`:
- Around line 179-181: Update _report_gateway_start_failure so the message
argument is included in the state token passed to _steady_report, while
preserving the existing stderr reporting behavior. Ensure distinct gateway-start
failure messages produce distinct deduplication states and are not suppressed as
duplicates.
- Around line 389-393: Update the failure handling around _wait_gateway_pid to
record whether wrapper_pid was alive before sending TERM. Report “nested
tx9-logs exited … before Hermes exec” only when it had already exited; when it
was still running, use a separate message indicating multiple gateway processes
or the corresponding post-exec condition, while preserving the existing pre-exec
text.
- Around line 214-223: Update the Hermes provisioning flow associated with the
gateway launch using --external-supervisor to either pin Hermes to a known
compatible release or validate that the installed CLI supports this option
before launching. Ensure provisioning fails clearly or selects a compatible
version when the contract is unavailable, preventing an unsupported flag from
causing restart loops.
In `@guest/tx9-logs`:
- Around line 902-907: In the fallback branch that duplicates stdout and stderr
when inherited descriptors are unavailable, add a short comment documenting that
nested captures may duplicate mirroring because the parent pipes remain open,
and that this tradeoff is accepted to keep the target exec'able. Keep the
existing fallback behavior unchanged.
- Around line 847-867: Update the docstring for inherited_open_fd to state that
os.fstat verifies only that the numeric descriptor is currently open, not that
it still refers to the inherited mirror; descriptor reuse by another file or
lock remains possible. Keep the existing validation logic unchanged.
🪄 Autofix
Fix all unresolved CodeRabbit comments on this PR:
- Push a commit to this branch (recommended)
- Create a new PR with the fixes
ℹ️ Review info
⚙️ Run configuration
Configuration used: Organization UI
Review profile: CHILL
Plan: Pro Plus
Run ID: e0bd283a-3777-4fb7-9340-7f086a4cf305
📒 Files selected for processing (5)
guest/hbguest/tx9-logstests/regressions-hb-workload.shtests/regressions-logs.shtests/static.sh
| for ((attempt = 0; attempt < 30; attempt++)); do | ||
| _gateway_running || break | ||
| _gateway_or_capture_running || break | ||
| sleep 1 | ||
| done | ||
| pkill -KILL -u "$(id -u)" -f '[h]ermes( .*)? gateway run' 2>/dev/null || true | ||
| rm -f "$GATEWAY_PID" | ||
| ! _gateway_running || { echo "Hermes gateway failed to stop" >&2; return 1; } | ||
| ! _gateway_or_capture_running || { echo "Hermes gateway failed to stop" >&2; return 1; } |
There was a problem hiding this comment.
🩺 Stability & Availability | 🟡 Minor | ⚡ Quick win
Add a bounded wait after pkill -KILL before the final check.
pkill -KILL returns before the kernel reaps the targets. During that window a zombie gateway child still appears in pgrep, and _gateway_pids keeps it: ps -o args= exits 0 with empty output for a zombie, so the *"tx9-logs capture"* filter at line 264 does not skip it. _gateway_or_capture_running is then true and _stop_gateway returns 1 with "Hermes gateway failed to stop" after a successful stop. _wait_gateway_pid line 304 already treats Z* as not running, so the file already accounts for this state elsewhere.
🛡️ Proposed fix
pkill -KILL -u "$(id -u)" -f '[h]ermes( .*)? gateway run' 2>/dev/null || true
+ for ((attempt = 0; attempt < 50; attempt++)); do
+ _gateway_or_capture_running || break
+ sleep 0.1
+ done
rm -f "$GATEWAY_PID"
! _gateway_or_capture_running || { echo "Hermes gateway failed to stop" >&2; return 1; }📝 Committable suggestion
‼️ IMPORTANT
Carefully review the code before committing. Ensure that it accurately replaces the highlighted code, contains no missing lines, and has no issues with indentation. Thoroughly test & benchmark the code to ensure it meets the requirements.
| for ((attempt = 0; attempt < 30; attempt++)); do | |
| _gateway_running || break | |
| _gateway_or_capture_running || break | |
| sleep 1 | |
| done | |
| pkill -KILL -u "$(id -u)" -f '[h]ermes( .*)? gateway run' 2>/dev/null || true | |
| rm -f "$GATEWAY_PID" | |
| ! _gateway_running || { echo "Hermes gateway failed to stop" >&2; return 1; } | |
| ! _gateway_or_capture_running || { echo "Hermes gateway failed to stop" >&2; return 1; } | |
| for ((attempt = 0; attempt < 30; attempt++)); do | |
| _gateway_or_capture_running || break | |
| sleep 1 | |
| done | |
| pkill -KILL -u "$(id -u)" -f '[h]ermes( .*)? gateway run' 2>/dev/null || true | |
| for ((attempt = 0; attempt < 50; attempt++)); do | |
| _gateway_or_capture_running || break | |
| sleep 0.1 | |
| done | |
| rm -f "$GATEWAY_PID" | |
| ! _gateway_or_capture_running || { echo "Hermes gateway failed to stop" >&2; return 1; } |
🤖 Prompt for AI Agents
Verify each finding against current code. Fix only still-valid issues, skip the
rest with a brief reason, keep changes minimal, and validate.
In `@guest/hb` around lines 446 - 452, Add a bounded polling wait after the pkill
command in the gateway stop flow, using the existing _gateway_or_capture_running
check and sleep pattern, before the final failure check. Allow the loop to exit
once no gateway or capture process remains, then preserve the existing error
handling if the process is still reported running.
Co-authored-by: Ben Davis <bmdavis419@users.noreply.github.com>
| exec nohup "${capture_cmd[@]}" -- "${child_cmd[@]}" \ | ||
| </dev/null >/dev/null 2>>"$launcher_log" |
There was a problem hiding this comment.
🟨 Gateway launcher log is created with default permissions and may hold redacted-only child output
The new launcher log at guest/hb:222-223 is created by a plain shell append redirect (2>>"$launcher_log"), so it inherits the ambient umask rather than the 0o600 mode that tx9-logs deliberately enforces on every other log file it writes (guest/tx9-logs:771-783, and os.fchmod(fd, 0o600)). Because the mirror fallback in Capture.__init__ (guest/tx9-logs:902-907) dups this descriptor into mirror_err, the gateway's stderr stream ends up in this less-protected file whenever no valid inherited mirror pair exists.
Was this helpful? React with 👍 or 👎 to provide feedback.
2 participants
The boot
hb-workloadloop could stay alive while the Hermes gateway stayed down. Nestedtx9-logs capturetrusted inheritedTX9_LOG_MIRROR_*_FDvalues even when those descriptors were closed or reused, crashed withEBADFbefore exec, and the Hermes wrapper had no--restart-delay. Login-shellhb upmasked it because that path does not inherit the outer capture environment.This ports the local mitigation into the source package:
hbunsets the mirror-FD pair after closing lock descriptors if either member is missing, nonnumeric, or closed--restart-delay(default 2s, overridable viaHB_GATEWAY_RESTART_DELAY) andhermes gateway run --replace --external-supervisorhermes-gateway.launcher.log; a wrapper that dies before Hermes exec reports that exit statushb gateway-disable/hb pausewait for the wrapper as well as the child, so the restart loop cannot defeat an intentional stoptx9-logsfalls back to owned stdout/stderr dups instead of crashing on invalid inherited FDs, including oversized values that raiseOverflowErrorRegression coverage includes absent/malformed/half-valid/closed mirror FDs, nested outer-capture →
hb→ inner-capture, unexpected child-exit recovery, disable/pause non-restart, and reload-request preservation during supervised restart.Validation:
make syntax lint testpasses locally. CI runs the completemake check, including Go 1.26 vet/build/tests.Note
Recover Hermes from stale nested tx9-logs mirror FDs by supervising restart
tx9-logscapture wrapper with--restart-delayand--external-supervisor, so the supervisor can restart crashed children without interfering with intentional stops._sanitize_log_mirror_fdsto dropTX9_LOG_MIRROR_STDOUT_FD/STDERR_FDenv vars if they reference closed or invalid FDs before spawning, andinherited_open_fdin tx9-logs to validate and fall back gracefully with a warning instead of crashing._stop_gatewayto signal both the wrapper and the Hermes child, preventing automatic restarts after an intentional stop._start_gatewayandgateway_reload_if_requestedto track wrapper lifecycle: records precise failure diagnostics, clears failure state on success, and preserves pending reload requests while the wrapper is in a restart delay with no child.--restart-delayand--external-supervisor; ps-based checks must match the new wrapper patterns.Macroscope summarized b018989.
Greptile Summary
Hermes now preserves reload requests while the supervised gateway is between child processes, applies the deferred reload after recovery, and does not restart after an intentional disable. The reviewed behavior completed successfully.
Confidence Score: 5/5
No blocking failure remains.
The exercised process-recovery, deferred-reload, intentional-disable, and static contract flows completed successfully with no actionable issue found.
What T-Rex did
Reviews (2): Last reviewed commit: "fix: preserve reload requests during gat..." | Re-trigger Greptile