-
Notifications
You must be signed in to change notification settings - Fork 1
fix: recover Hermes from stale nested tx9-logs mirror FDs #27
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
Changes from 1 commit
File filter
Filter by extension
Conversations
Jump to
Diff view
Diff view
There are no files selected for viewing
| Original file line number | Diff line number | Diff line change | ||||||||||||||||||||||||||||||||||||||||
|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|
|
|
@@ -33,6 +33,7 @@ TOKEN_ENV="$AGENT_HOME/.config/hermes-box/executor-mcp.env" | |||||||||||||||||||||||||||||||||||||||||
| GATEWAY_LOCK_WAIT_SECONDS=10 | ||||||||||||||||||||||||||||||||||||||||||
| GATEWAY_START_WAIT_ATTEMPTS=50 | ||||||||||||||||||||||||||||||||||||||||||
| GATEWAY_START_WAIT_INTERVAL=0.1 | ||||||||||||||||||||||||||||||||||||||||||
| GATEWAY_RESTART_DELAY="${HB_GATEWAY_RESTART_DELAY:-2}" | ||||||||||||||||||||||||||||||||||||||||||
|
|
||||||||||||||||||||||||||||||||||||||||||
| # Remote-executor mode (Docker compose split): when EXECUTOR_HOST points away | ||||||||||||||||||||||||||||||||||||||||||
| # from loopback, Executor runs in its own container. hb then only checks | ||||||||||||||||||||||||||||||||||||||||||
|
|
@@ -155,6 +156,30 @@ _release_daemon_lock() { | |||||||||||||||||||||||||||||||||||||||||
| unset "_DAEMON_LOCK_FDS[$lock]" | ||||||||||||||||||||||||||||||||||||||||||
| } | ||||||||||||||||||||||||||||||||||||||||||
|
|
||||||||||||||||||||||||||||||||||||||||||
| _valid_open_fd() { | ||||||||||||||||||||||||||||||||||||||||||
| local candidate="$1" | ||||||||||||||||||||||||||||||||||||||||||
| [[ "$candidate" =~ ^[0-9]+$ && -e "/proc/self/fd/$candidate" ]] | ||||||||||||||||||||||||||||||||||||||||||
| } | ||||||||||||||||||||||||||||||||||||||||||
|
|
||||||||||||||||||||||||||||||||||||||||||
| # Inherited mirror-FD numbers are an atomic pair. Presence of the strings is | ||||||||||||||||||||||||||||||||||||||||||
| # not proof the descriptors are still open here: hb-workload keeps the outer | ||||||||||||||||||||||||||||||||||||||||||
| # capture's environment, then later hb subprocesses can retain the names after | ||||||||||||||||||||||||||||||||||||||||||
| # those descriptors were closed or reused for a lock. | ||||||||||||||||||||||||||||||||||||||||||
| _sanitize_log_mirror_fds() { | ||||||||||||||||||||||||||||||||||||||||||
| if ! _valid_open_fd "${TX9_LOG_MIRROR_STDOUT_FD:-}" || | ||||||||||||||||||||||||||||||||||||||||||
| ! _valid_open_fd "${TX9_LOG_MIRROR_STDERR_FD:-}"; then | ||||||||||||||||||||||||||||||||||||||||||
| unset TX9_LOG_MIRROR_STDOUT_FD TX9_LOG_MIRROR_STDERR_FD | ||||||||||||||||||||||||||||||||||||||||||
| fi | ||||||||||||||||||||||||||||||||||||||||||
| } | ||||||||||||||||||||||||||||||||||||||||||
|
|
||||||||||||||||||||||||||||||||||||||||||
| _clear_gateway_start_failure() { | ||||||||||||||||||||||||||||||||||||||||||
| rm -f "$HB_RUNTIME_STATE_DIR/gateway-start.state" 2>/dev/null || true | ||||||||||||||||||||||||||||||||||||||||||
| } | ||||||||||||||||||||||||||||||||||||||||||
|
|
||||||||||||||||||||||||||||||||||||||||||
| _report_gateway_start_failure() { | ||||||||||||||||||||||||||||||||||||||||||
| _steady_report gateway-start failed "$1" stderr | ||||||||||||||||||||||||||||||||||||||||||
| } | ||||||||||||||||||||||||||||||||||||||||||
|
|
||||||||||||||||||||||||||||||||||||||||||
| # A long-lived daemon spawned with a lock fd still open would inherit it and | ||||||||||||||||||||||||||||||||||||||||||
| # hold the underlying flock open for its entire lifetime (file description | ||||||||||||||||||||||||||||||||||||||||||
| # locks survive fork; the kernel only auto-releases once every fd referring | ||||||||||||||||||||||||||||||||||||||||||
|
|
@@ -165,24 +190,39 @@ _release_daemon_lock() { | |||||||||||||||||||||||||||||||||||||||||
| # milliseconds right after spawning. | ||||||||||||||||||||||||||||||||||||||||||
| _spawn_without_lock_fd() { | ||||||||||||||||||||||||||||||||||||||||||
| shift | ||||||||||||||||||||||||||||||||||||||||||
| local logfile="$1" fd source log_dir | ||||||||||||||||||||||||||||||||||||||||||
| local logfile="$1" fd source log_dir launcher_log | ||||||||||||||||||||||||||||||||||||||||||
| local -a capture_cmd child_cmd | ||||||||||||||||||||||||||||||||||||||||||
| shift | ||||||||||||||||||||||||||||||||||||||||||
| child_cmd=("$@") | ||||||||||||||||||||||||||||||||||||||||||
| # A daemon start can occur while a higher-level coordination lock is also | ||||||||||||||||||||||||||||||||||||||||||
| # held (for example, the MCP reload lock around a gateway restart). Close | ||||||||||||||||||||||||||||||||||||||||||
| # every tracked lock fd in the child so no long-lived daemon inherits and | ||||||||||||||||||||||||||||||||||||||||||
| # pins any of them after the spawning shell releases its copies. | ||||||||||||||||||||||||||||||||||||||||||
| # pins any of them after the spawning shell releases its copies. Validate | ||||||||||||||||||||||||||||||||||||||||||
| # inherited mirror FDs after that cleanup: a lock fd can reuse a stale | ||||||||||||||||||||||||||||||||||||||||||
| # mirror number, and closing it must not leave TX9_LOG_MIRROR_*_FD pointing | ||||||||||||||||||||||||||||||||||||||||||
| # at a now-closed descriptor. | ||||||||||||||||||||||||||||||||||||||||||
| ( | ||||||||||||||||||||||||||||||||||||||||||
| for fd in "${_DAEMON_LOCK_FDS[@]}"; do | ||||||||||||||||||||||||||||||||||||||||||
| eval "exec ${fd}>&-" | ||||||||||||||||||||||||||||||||||||||||||
| done | ||||||||||||||||||||||||||||||||||||||||||
| _sanitize_log_mirror_fds | ||||||||||||||||||||||||||||||||||||||||||
| if command -v tx9-logs >/dev/null 2>&1; then | ||||||||||||||||||||||||||||||||||||||||||
| source="$(basename "$logfile" .log)" | ||||||||||||||||||||||||||||||||||||||||||
| [[ "$source" != hermes-gateway ]] || source=hermes | ||||||||||||||||||||||||||||||||||||||||||
| log_dir="$(dirname "$logfile")" | ||||||||||||||||||||||||||||||||||||||||||
| exec nohup tx9-logs capture --source "$source" --log-dir "$log_dir" -- "$@" \ | ||||||||||||||||||||||||||||||||||||||||||
| </dev/null >/dev/null 2>&1 | ||||||||||||||||||||||||||||||||||||||||||
| 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" | ||||||||||||||||||||||||||||||||||||||||||
|
Comment on lines
+213
to
+223
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. 🔴 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 ( 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
The launcher log is a bare file: nothing in the repo rotates, truncates, or prunes it ( Prompt for agentsWas this helpful? React with 👍 or 👎 to provide feedback.
devin-ai-integration[bot] marked this conversation as resolved.
Comment on lines
+222
to
+223
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. 🟨 Gateway launcher log is created with default permissions and may hold redacted-only child output The new launcher log at Was this helpful? React with 👍 or 👎 to provide feedback. |
||||||||||||||||||||||||||||||||||||||||||
| fi | ||||||||||||||||||||||||||||||||||||||||||
| exec nohup "$@" >>"$logfile" 2>&1 | ||||||||||||||||||||||||||||||||||||||||||
| exec nohup "${child_cmd[@]}" >>"$logfile" 2>&1 | ||||||||||||||||||||||||||||||||||||||||||
| ) & | ||||||||||||||||||||||||||||||||||||||||||
| } | ||||||||||||||||||||||||||||||||||||||||||
|
|
||||||||||||||||||||||||||||||||||||||||||
|
|
@@ -240,6 +280,10 @@ _gateway_running() { | |||||||||||||||||||||||||||||||||||||||||
| [[ -n "$(_gateway_pids)" ]] | ||||||||||||||||||||||||||||||||||||||||||
| } | ||||||||||||||||||||||||||||||||||||||||||
|
|
||||||||||||||||||||||||||||||||||||||||||
| _gateway_or_capture_running() { | ||||||||||||||||||||||||||||||||||||||||||
| _gateway_running || [[ -n "$(_gateway_capture_pids)" ]] | ||||||||||||||||||||||||||||||||||||||||||
| } | ||||||||||||||||||||||||||||||||||||||||||
|
|
||||||||||||||||||||||||||||||||||||||||||
| # Print the real gateway PID and return 0 once it appears. Return 2 when the | ||||||||||||||||||||||||||||||||||||||||||
| # capture wrapper is still healthy after the short synchronous wait: it may be | ||||||||||||||||||||||||||||||||||||||||||
| # migrating a large legacy log before starting Hermes, so callers must leave it | ||||||||||||||||||||||||||||||||||||||||||
|
|
@@ -298,13 +342,14 @@ _start_gateway() { | |||||||||||||||||||||||||||||||||||||||||
| return 1 | ||||||||||||||||||||||||||||||||||||||||||
| fi | ||||||||||||||||||||||||||||||||||||||||||
| printf '%s\n' "${gateway_pids[0]}" >"$GATEWAY_PID" | ||||||||||||||||||||||||||||||||||||||||||
| _clear_gateway_start_failure | ||||||||||||||||||||||||||||||||||||||||||
| _release_daemon_lock "$GATEWAY_LOCK" | ||||||||||||||||||||||||||||||||||||||||||
| return 0 | ||||||||||||||||||||||||||||||||||||||||||
| fi | ||||||||||||||||||||||||||||||||||||||||||
| mapfile -t capture_pids < <(_gateway_capture_pids) | ||||||||||||||||||||||||||||||||||||||||||
| if ((${#capture_pids[@]} > 0)); then | ||||||||||||||||||||||||||||||||||||||||||
| if ((${#capture_pids[@]} != 1)); then | ||||||||||||||||||||||||||||||||||||||||||
| echo "Hermes gateway capture is pending but did not start cleanly" >&2 | ||||||||||||||||||||||||||||||||||||||||||
| _report_gateway_start_failure "Hermes gateway capture is pending but did not start cleanly" | ||||||||||||||||||||||||||||||||||||||||||
| _release_daemon_lock "$GATEWAY_LOCK" | ||||||||||||||||||||||||||||||||||||||||||
| return 1 | ||||||||||||||||||||||||||||||||||||||||||
| fi | ||||||||||||||||||||||||||||||||||||||||||
|
|
@@ -315,8 +360,9 @@ _start_gateway() { | |||||||||||||||||||||||||||||||||||||||||
| fi | ||||||||||||||||||||||||||||||||||||||||||
| if [[ "$wait_status" == 0 ]]; then | ||||||||||||||||||||||||||||||||||||||||||
| printf '%s\n' "$gateway_pid" >"$GATEWAY_PID" | ||||||||||||||||||||||||||||||||||||||||||
| _clear_gateway_start_failure | ||||||||||||||||||||||||||||||||||||||||||
| elif [[ "$wait_status" != 2 ]]; then | ||||||||||||||||||||||||||||||||||||||||||
| echo "Hermes gateway capture is pending but did not start cleanly" >&2 | ||||||||||||||||||||||||||||||||||||||||||
| _report_gateway_start_failure "Hermes gateway capture is pending but did not start cleanly" | ||||||||||||||||||||||||||||||||||||||||||
| _release_daemon_lock "$GATEWAY_LOCK" | ||||||||||||||||||||||||||||||||||||||||||
| return 1 | ||||||||||||||||||||||||||||||||||||||||||
| else | ||||||||||||||||||||||||||||||||||||||||||
|
|
@@ -340,13 +386,16 @@ _start_gateway() { | |||||||||||||||||||||||||||||||||||||||||
| _release_daemon_lock "$GATEWAY_LOCK" | ||||||||||||||||||||||||||||||||||||||||||
| return 0 | ||||||||||||||||||||||||||||||||||||||||||
| elif [[ "$wait_status" != 0 ]]; then | ||||||||||||||||||||||||||||||||||||||||||
| local wrapper_status=1 | ||||||||||||||||||||||||||||||||||||||||||
| kill -TERM "$wrapper_pid" 2>/dev/null || true | ||||||||||||||||||||||||||||||||||||||||||
| wait "$wrapper_pid" 2>/dev/null || true | ||||||||||||||||||||||||||||||||||||||||||
| echo "Hermes gateway failed to start; see: hb logs hermes" >&2 | ||||||||||||||||||||||||||||||||||||||||||
| 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" | ||||||||||||||||||||||||||||||||||||||||||
| _release_daemon_lock "$GATEWAY_LOCK" | ||||||||||||||||||||||||||||||||||||||||||
| return 1 | ||||||||||||||||||||||||||||||||||||||||||
| fi | ||||||||||||||||||||||||||||||||||||||||||
| printf '%s\n' "$gateway_pid" >"$GATEWAY_PID" | ||||||||||||||||||||||||||||||||||||||||||
| _clear_gateway_start_failure | ||||||||||||||||||||||||||||||||||||||||||
| _release_daemon_lock "$GATEWAY_LOCK" | ||||||||||||||||||||||||||||||||||||||||||
| } | ||||||||||||||||||||||||||||||||||||||||||
|
|
||||||||||||||||||||||||||||||||||||||||||
|
|
@@ -390,14 +439,17 @@ _stop_executor() { | |||||||||||||||||||||||||||||||||||||||||
|
|
||||||||||||||||||||||||||||||||||||||||||
| _stop_gateway() { | ||||||||||||||||||||||||||||||||||||||||||
| local attempt | ||||||||||||||||||||||||||||||||||||||||||
| # The capture argv includes `hermes gateway run`, so this TERM reaches the | ||||||||||||||||||||||||||||||||||||||||||
| # wrapper as well as the child. The wrapper must see the signal: otherwise | ||||||||||||||||||||||||||||||||||||||||||
| # --restart-delay would bring the gateway back after an intentional stop. | ||||||||||||||||||||||||||||||||||||||||||
| pkill -TERM -u "$(id -u)" -f '[h]ermes( .*)? gateway run' 2>/dev/null || true | ||||||||||||||||||||||||||||||||||||||||||
| 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; } | ||||||||||||||||||||||||||||||||||||||||||
|
Comment on lines
446
to
+452
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. 🩺 Stability & Availability | 🟡 Minor | ⚡ Quick win Add a bounded wait after
🛡️ 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
Suggested change
🤖 Prompt for AI Agents |
||||||||||||||||||||||||||||||||||||||||||
| } | ||||||||||||||||||||||||||||||||||||||||||
|
|
||||||||||||||||||||||||||||||||||||||||||
| pause() { | ||||||||||||||||||||||||||||||||||||||||||
|
|
||||||||||||||||||||||||||||||||||||||||||
| Original file line number | Diff line number | Diff line change |
|---|---|---|
|
|
@@ -844,6 +844,29 @@ def write_all(fd: int, payload: bytes) -> None: | |
| view = view[written:] | ||
|
|
||
|
|
||
| def inherited_open_fd(raw: str | None) -> int | None: | ||
| """Return a still-open FD from inherited mirror metadata, or None. | ||
|
|
||
| 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. | ||
| """ | ||
|
|
||
| if raw is None: | ||
| return None | ||
| try: | ||
| fd = int(raw) | ||
| except (TypeError, ValueError): | ||
| return None | ||
| if fd < 0: | ||
| return None | ||
| try: | ||
| os.fstat(fd) | ||
|
There was a problem hiding this comment. Choose a reason for hiding this commentThe reason will be displayed to describe this comment to others. Learn more. 🟠 High
🚀 Reply "fix it for me" or copy this AI Prompt for your agent: |
||
| except OSError: | ||
|
macroscopeapp[bot] marked this conversation as resolved.
Outdated
|
||
| return None | ||
| return fd | ||
|
|
||
|
|
||
| class Capture: | ||
| def __init__(self, source: str, log_dir: Path, max_bytes: int, max_files: int) -> None: | ||
| log_dir.mkdir(mode=0o700, parents=True, exist_ok=True) | ||
|
|
@@ -872,15 +895,20 @@ class Capture: | |
| # into a summary. State: (message, repeat count, first monotonic). | ||
| self.dedup_state: dict[str, tuple[str, int, float]] = {} | ||
|
|
||
| inherited_out = os.environ.get("TX9_LOG_MIRROR_STDOUT_FD") | ||
| inherited_err = os.environ.get("TX9_LOG_MIRROR_STDERR_FD") | ||
| self.owns_mirror_fds = inherited_out is None or inherited_err is None | ||
| if self.owns_mirror_fds: | ||
| raw_inherited_out = os.environ.get("TX9_LOG_MIRROR_STDOUT_FD") | ||
| raw_inherited_err = os.environ.get("TX9_LOG_MIRROR_STDERR_FD") | ||
| inherited_out = inherited_open_fd(raw_inherited_out) | ||
| inherited_err = inherited_open_fd(raw_inherited_err) | ||
| if inherited_out is None or inherited_err is None: | ||
| if raw_inherited_out is not None or raw_inherited_err is not None: | ||
| warn("ignoring invalid inherited TX9_LOG_MIRROR_*_FD values") | ||
| self.owns_mirror_fds = True | ||
| self.mirror_out = os.dup(sys.stdout.fileno()) | ||
| self.mirror_err = os.dup(sys.stderr.fileno()) | ||
| else: | ||
| self.mirror_out = int(inherited_out) | ||
| self.mirror_err = int(inherited_err) | ||
| self.owns_mirror_fds = False | ||
| self.mirror_out = inherited_out | ||
| self.mirror_err = inherited_err | ||
| # A nested capture must not keep its parent's stdout/stderr pipes | ||
| # open. Mirror directly to the inherited original container fds. | ||
| os.dup2(self.mirror_out, sys.stdout.fileno()) | ||
|
|
||
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
🟡 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_reportatguest/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_reportonly consults/writes$HB_RUNTIME_STATE_DIR/<key>.statewhenHB_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 defaultHB_STEADY_QUIET=0.hb-workload's loop invokeshb reconcileas a fresh process (guest/hb-workload:126) and does not exportHB_STEADY_QUIET. The regression test only exercises the suppression by settingHB_STEADY_QUIET=1by 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
Was this helpful? React with 👍 or 👎 to provide feedback.