diff --git a/guest/hb b/guest/hb index d6213d5..d4a58d3 100755 --- a/guest/hb +++ b/guest/hb @@ -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 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 2>>"$launcher_log" 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; } } pause() { @@ -586,6 +638,14 @@ gateway_reload_if_requested() { return 0 fi if ! _gateway_running; then + # A supervised gateway can be between child processes during its restart + # delay. Keep the request until a child is observable: deleting it here + # would race the wrapper's automatic restart and could skip the explicit + # reload required for a concurrent config change. + if [[ -n "$(_gateway_capture_pids)" ]]; then + _release_daemon_lock "$GATEWAY_RELOAD_LOCK" + return 0 + fi rm -f "${requests[@]}" _release_daemon_lock "$GATEWAY_RELOAD_LOCK" return 0 diff --git a/guest/tx9-logs b/guest/tx9-logs index 6c6dad5..89f2467 100755 --- a/guest/tx9-logs +++ b/guest/tx9-logs @@ -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) + except (OSError, OverflowError): + 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()) diff --git a/tests/regressions-hb-workload.sh b/tests/regressions-hb-workload.sh index a851232..f3a1aa1 100755 --- a/tests/regressions-hb-workload.sh +++ b/tests/regressions-hb-workload.sh @@ -149,8 +149,8 @@ source "$(cd "$(dirname "${BASH_SOURCE[0]}")" && pwd)/lib.sh" pgrep() { printf '101\n202\n'; } ps() { case "${*: -1}" in - 101) printf 'python3 /opt/hermes-box/bin/tx9-logs capture --source hermes -- hermes gateway run --replace\n' ;; - 202) printf 'hermes gateway run --replace\n' ;; + 101) printf 'python3 /opt/hermes-box/bin/tx9-logs capture --source hermes --restart-delay 2 -- hermes gateway run --replace --external-supervisor\n' ;; + 202) printf 'hermes gateway run --replace --external-supervisor\n' ;; esac } mapfile -t gateway_pids < <(_gateway_pids) @@ -824,6 +824,33 @@ EOF [[ "$(cat "$tmp/gateway-reload.events")" == $'gateway-stop\ngateway-start' ]] ) +# A supervised wrapper can be alive while Hermes is between child processes. +# Keep pending reload intent through that restart window; the next reconcile +# will process it after the replacement child appears. +( + HB_DATA="$tmp/gateway-reload-supervisor-only-data" + # shellcheck disable=SC1090 + source "$PROJECT_ROOT/guest/hb" + init + mkdir -p "$GATEWAY_RELOAD_REQUESTS" + touch "$GATEWAY_RELOAD_REQUESTS/request.supervisor-only" + _gateway_running() { return 1; } + _gateway_capture_pids() { printf '4242\n'; } + _stop_gateway() { + echo "reload stopped a supervisor while its child was restarting" >&2 + return 1 + } + gateway_reload_if_requested + [[ -e "$GATEWAY_RELOAD_REQUESTS/request.supervisor-only" ]] + + # Preserve the pre-supervision behavior: with no wrapper and no child, the + # next ordinary gateway start will read current config, so the stale request + # can be consumed without manufacturing an extra restart. + _gateway_capture_pids() { return 0; } + gateway_reload_if_requested + [[ ! -e "$GATEWAY_RELOAD_REQUESTS/request.supervisor-only" ]] +) + # A gateway restart preserves the freshest runtime-injected remote token, # falls back to an existing exported token, and only then reads the managed # on-disk token. Disabling wiring clears every inherited credential. @@ -1034,4 +1061,290 @@ if ! flock -w 2 "$outer_lock_path" -c 'exit 0' 2>/dev/null; then fi kill -9 "$spawned_pid" 2>/dev/null || true +install_fake_hermes() { + local bin="$1" + mkdir -p "$bin" + cat >"$bin/hermes" <<'EOF' +#!/usr/bin/env bash +if [[ "${1:-}" == gateway && "${2:-}" == run ]]; then + printf '%s\n' "$$" >"${HERMES_PID_FILE:?}" + printf '%s\n' "$*" >"${HERMES_ARGS_FILE:?}" + trap 'exit 0' TERM INT + while :; do sleep 0.1; done +fi +exit 0 +EOF + chmod 0700 "$bin/hermes" +} + +wait_for_pid_change() { + local file="$1" old_pid="$2" attempt current + for ((attempt = 0; attempt < 80; attempt++)); do + current="$(cat "$file" 2>/dev/null || true)" + if [[ -n "$current" && "$current" != "$old_pid" ]] && kill -0 "$current" 2>/dev/null; then + printf '%s\n' "$current" + return 0 + fi + sleep 0.1 + done + echo "timed out waiting for a new PID in $file" >&2 + return 1 +} + +# Mirror-FD strings are an atomic pair: missing, nonnumeric, or closed values +# drop both variables so a nested capture cannot dup2 an invalid descriptor. +( + # shellcheck disable=SC1090 + source "$PROJECT_ROOT/guest/hb" + export TX9_LOG_MIRROR_STDOUT_FD=93 TX9_LOG_MIRROR_STDERR_FD=94 + _sanitize_log_mirror_fds + [[ -z "${TX9_LOG_MIRROR_STDOUT_FD+x}" ]] + [[ -z "${TX9_LOG_MIRROR_STDERR_FD+x}" ]] + + export TX9_LOG_MIRROR_STDOUT_FD=1 TX9_LOG_MIRROR_STDERR_FD=2 + _sanitize_log_mirror_fds + [[ "$TX9_LOG_MIRROR_STDOUT_FD" == 1 ]] + [[ "$TX9_LOG_MIRROR_STDERR_FD" == 2 ]] + + export TX9_LOG_MIRROR_STDOUT_FD=1 TX9_LOG_MIRROR_STDERR_FD=94 + _sanitize_log_mirror_fds + [[ -z "${TX9_LOG_MIRROR_STDOUT_FD+x}" ]] + [[ -z "${TX9_LOG_MIRROR_STDERR_FD+x}" ]] + + export TX9_LOG_MIRROR_STDOUT_FD=1 + unset TX9_LOG_MIRROR_STDERR_FD + _sanitize_log_mirror_fds + [[ -z "${TX9_LOG_MIRROR_STDOUT_FD+x}" ]] + [[ -z "${TX9_LOG_MIRROR_STDERR_FD+x}" ]] + + export TX9_LOG_MIRROR_STDOUT_FD=nope TX9_LOG_MIRROR_STDERR_FD=-1 + _sanitize_log_mirror_fds + [[ -z "${TX9_LOG_MIRROR_STDOUT_FD+x}" ]] + [[ -z "${TX9_LOG_MIRROR_STDERR_FD+x}" ]] +) + +# Closing coordination lock fds happens before mirror validation, so a lock +# that reused a stale mirror number is not treated as a live docker mirror. +( + HB_DATA="$tmp/mirror-lock-reuse-data" + # shellcheck disable=SC1090 + source "$PROJECT_ROOT/guest/hb" + init + rm -f "$GATEWAY_DISABLED" "$QUIESCE_FILE" + INSTALL_HERMES=1 + HB_GATEWAY_RESTART_DELAY=0.2 + GATEWAY_RESTART_DELAY=0.2 + bin="$tmp/mirror-lock-reuse-bin" + install_fake_hermes "$bin" + cat >"$bin/tx9-logs" <<'EOF' +#!/usr/bin/env bash +printf 'out=%s err=%s\n' "${TX9_LOG_MIRROR_STDOUT_FD-unset}" "${TX9_LOG_MIRROR_STDERR_FD-unset}" \ + >"${TX9_MIRROR_ENV_FILE:?}" +exec "$REAL_TX9_LOGS" "$@" +EOF + chmod 0700 "$bin/tx9-logs" + export PATH="$bin:$PATH" + export REAL_TX9_LOGS="$PROJECT_ROOT/guest/tx9-logs" + export TX9_MIRROR_ENV_FILE="$tmp/mirror-lock-reuse.env" + export HERMES_PID_FILE="$tmp/mirror-lock-reuse.gateway.pid" + export HERMES_ARGS_FILE="$tmp/mirror-lock-reuse.args" + _acquire_daemon_lock "$GATEWAY_LOCK" || exit 1 + _acquire_daemon_lock "$EXECUTOR_LOCK" || exit 1 + export TX9_LOG_MIRROR_STDOUT_FD="${_DAEMON_LOCK_FDS[$GATEWAY_LOCK]}" + export TX9_LOG_MIRROR_STDERR_FD="${_DAEMON_LOCK_FDS[$EXECUTOR_LOCK]}" + _spawn_without_lock_fd "$GATEWAY_LOCK" "$LOGS/hermes-gateway.log" hermes gateway run --replace + wait_for_file "$HERMES_PID_FILE" + wait_for_file "$TX9_MIRROR_ENV_FILE" + [[ "$(cat "$TX9_MIRROR_ENV_FILE")" == 'out=unset err=unset' ]] + grep -Fq -- '--external-supervisor' "$HERMES_ARGS_FILE" + mapfile -t capture_pids < <(_gateway_capture_pids) + [[ "${#capture_pids[@]}" == 1 ]] + args="$(ps -o args= -p "${capture_pids[0]}")" + [[ "$args" == *"--restart-delay 0.2"* ]] + [[ "$args" == *"--external-supervisor"* ]] + pids+=("${capture_pids[0]}" "$(cat "$HERMES_PID_FILE")") + _release_daemon_lock "$GATEWAY_LOCK" + _release_daemon_lock "$EXECUTOR_LOCK" + _stop_gateway +) + +# Nested capture under an outer tx9-logs workload still starts exactly one +# Hermes wrapper, even when the inherited mirror numbers are closed. The +# short-lived hb launcher exits; the wrapper is adopted away from it. +( + HB_DATA="$tmp/nested-capture-data" + HOME="$HB_DATA/home/agent" + mkdir -p "$HOME" "$tmp/nested-outer-logs" + bin="$tmp/nested-capture-bin" + install_fake_hermes "$bin" + ln -sf "$PROJECT_ROOT/guest/tx9-logs" "$bin/tx9-logs" + export PATH="$bin:$PATH" + export HERMES_PID_FILE="$tmp/nested-capture.gateway.pid" + export HERMES_ARGS_FILE="$tmp/nested-capture.args" + export HB_DATA HOME + export HB_GATEWAY_RESTART_DELAY=0.2 + export INSTALL_HERMES=1 + export HB_SCRIPT="$PROJECT_ROOT/guest/hb" + export WRAPPER_PID_FILE="$tmp/nested-capture.wrapper.pid" + export HB_LAUNCHER_PID_FILE="$tmp/nested-capture.hb.pid" + export WORKLOAD_PID_FILE="$tmp/nested-capture.workload.pid" + cat >"$tmp/nested-capture-hb.sh" <<'EOF' +#!/usr/bin/env bash +set -euo pipefail +printf '%s\n' "$$" >"$HB_LAUNCHER_PID_FILE" +# shellcheck disable=SC1090 +source "$HB_SCRIPT" +init +rm -f "$GATEWAY_DISABLED" "$QUIESCE_FILE" +INSTALL_HERMES=1 +export TX9_LOG_MIRROR_STDOUT_FD=93 TX9_LOG_MIRROR_STDERR_FD=94 +_start_gateway +EOF + cat >"$tmp/nested-capture-workload.sh" <<'EOF' +#!/usr/bin/env bash +set -euo pipefail +printf '%s\n' "$$" >"$WORKLOAD_PID_FILE" +bash "$1" +# shellcheck disable=SC1090 +source "$HB_SCRIPT" +mapfile -t capture_pids < <(_gateway_capture_pids) +printf '%s\n' "${capture_pids[0]}" >"$WRAPPER_PID_FILE" +trap 'exit 0' TERM INT +while :; do sleep 0.1; done +EOF + chmod 0700 "$tmp/nested-capture-hb.sh" "$tmp/nested-capture-workload.sh" + "$PROJECT_ROOT/guest/tx9-logs" capture --source agent --log-dir "$tmp/nested-outer-logs" -- \ + bash "$tmp/nested-capture-workload.sh" "$tmp/nested-capture-hb.sh" \ + >/dev/null 2>&1 & + outer_pid=$! + pids+=("$outer_pid") + wait_for_file "$HERMES_PID_FILE" + wait_for_file "$WRAPPER_PID_FILE" + wait_for_file "$HB_LAUNCHER_PID_FILE" + wrapper_pid="$(cat "$WRAPPER_PID_FILE")" + gateway_pid="$(cat "$HERMES_PID_FILE")" + hb_pid="$(cat "$HB_LAUNCHER_PID_FILE")" + pids+=("$wrapper_pid" "$gateway_pid") + kill -0 "$wrapper_pid" + kill -0 "$gateway_pid" + if kill -0 "$hb_pid" 2>/dev/null; then + echo "hb launcher was still alive after nested gateway start" >&2 + exit 1 + fi + wrapper_ppid="$(ps -o ppid= -p "$wrapper_pid" | tr -d ' ')" + [[ "$wrapper_ppid" != "$hb_pid" ]] + # shellcheck disable=SC1090 + source "$PROJECT_ROOT/guest/hb" + GATEWAY_RESTART_DELAY=0.2 + mapfile -t gateway_pids < <(_gateway_pids) + mapfile -t capture_pids < <(_gateway_capture_pids) + [[ "${gateway_pids[*]}" == "$gateway_pid" ]] + [[ "${capture_pids[*]}" == "$wrapper_pid" ]] + grep -Fq -- '--external-supervisor' "$HERMES_ARGS_FILE" + args="$(ps -o args= -p "$wrapper_pid")" + [[ "$args" == *"--restart-delay 0.2"* ]] + [[ "$args" == *"tx9-logs capture"* ]] + _start_gateway + mapfile -t gateway_pids < <(_gateway_pids) + mapfile -t capture_pids < <(_gateway_capture_pids) + [[ "${#gateway_pids[@]}" == 1 ]] + [[ "${#capture_pids[@]}" == 1 ]] + _stop_gateway + kill -TERM "$outer_pid" 2>/dev/null || true + wait "$outer_pid" 2>/dev/null || true +) + +# Killing only the Hermes child leaves the wrapper in place and starts a +# replacement inside the restart window. Explicit stop kills both and does +# not resurrect the gateway. +( + HB_DATA="$tmp/gateway-restart-data" + # shellcheck disable=SC1090 + source "$PROJECT_ROOT/guest/hb" + init + rm -f "$GATEWAY_DISABLED" "$QUIESCE_FILE" + INSTALL_HERMES=1 + HB_GATEWAY_RESTART_DELAY=0.2 + GATEWAY_RESTART_DELAY=0.2 + bin="$tmp/gateway-restart-bin" + install_fake_hermes "$bin" + ln -sf "$PROJECT_ROOT/guest/tx9-logs" "$bin/tx9-logs" + export PATH="$bin:$PATH" + export HERMES_PID_FILE="$tmp/gateway-restart.gateway.pid" + export HERMES_ARGS_FILE="$tmp/gateway-restart.args" + _start_gateway + wait_for_file "$HERMES_PID_FILE" + mapfile -t capture_pids < <(_gateway_capture_pids) + [[ "${#capture_pids[@]}" == 1 ]] + wrapper_pid="${capture_pids[0]}" + first_gateway="$(cat "$HERMES_PID_FILE")" + pids+=("$wrapper_pid") + kill -TERM "$first_gateway" + second_gateway="$(wait_for_pid_change "$HERMES_PID_FILE" "$first_gateway")" + kill -0 "$wrapper_pid" + [[ "$(_gateway_capture_pids)" == "$wrapper_pid" ]] + [[ "$second_gateway" != "$first_gateway" ]] + jq -e 'select(.type == "process_exit")' "$LOGS/hermes.jsonl" >/dev/null + jq -e 'select(.type == "process_restart")' "$LOGS/hermes.jsonl" >/dev/null + jq -e --argjson pid "$second_gateway" \ + 'select(.type == "process_start" and .data.pid == $pid)' \ + "$LOGS/hermes.jsonl" >/dev/null + gateway_disable >/dev/null + [[ -e "$GATEWAY_DISABLED" ]] + sleep 0.6 + if _gateway_or_capture_running; then + echo "disabled gateway was resurrected by the capture restart loop" >&2 + exit 1 + fi + rm -f "$GATEWAY_DISABLED" "$HERMES_PID_FILE" + _start_gateway + wait_for_file "$HERMES_PID_FILE" + mapfile -t capture_pids < <(_gateway_capture_pids) + [[ "${#capture_pids[@]}" == 1 ]] + pids+=("${capture_pids[0]}" "$(cat "$HERMES_PID_FILE")") + pause >/dev/null + sleep 0.6 + if _gateway_or_capture_running; then + echo "paused gateway was resurrected by the capture restart loop" >&2 + exit 1 + fi +) + +# A wrapper that dies before Hermes exec reports that exit status instead of +# a generic "see hb logs hermes" hint, and quiet reconcile does not flood. +( + HB_DATA="$tmp/gateway-start-failure-data" + HB_RUNTIME_STATE_DIR="$tmp/gateway-start-failure-state" + # shellcheck disable=SC1090 + source "$PROJECT_ROOT/guest/hb" + init + rm -f "$GATEWAY_DISABLED" "$QUIESCE_FILE" + INSTALL_HERMES=1 + bin="$tmp/gateway-start-failure-bin" + install_fake_hermes "$bin" + printf '#!/usr/bin/env bash\nexit 1\n' >"$bin/tx9-logs" + chmod 0700 "$bin/tx9-logs" + export PATH="$bin:$PATH" + set +e + _start_gateway >"$tmp/gateway-start-failure.stdout" 2>"$tmp/gateway-start-failure.stderr" + first_status=$? + set -e + [[ "$first_status" == 1 ]] + grep -q 'nested tx9-logs exited 1 before Hermes exec' "$tmp/gateway-start-failure.stderr" + HB_STEADY_QUIET=1 + set +e + _start_gateway >"$tmp/gateway-start-failure-quiet1.stdout" 2>"$tmp/gateway-start-failure-quiet1.stderr" + quiet_first_status=$? + _start_gateway >"$tmp/gateway-start-failure-quiet2.stdout" 2>"$tmp/gateway-start-failure-quiet2.stderr" + quiet_second_status=$? + set -e + [[ "$quiet_first_status" == 1 ]] + [[ "$quiet_second_status" == 1 ]] + grep -q 'nested tx9-logs exited 1 before Hermes exec' "$tmp/gateway-start-failure-quiet1.stderr" + [[ ! -s "$tmp/gateway-start-failure-quiet2.stderr" ]] || { + echo "quiet reconcile re-logged an unchanged gateway start failure" >&2 + exit 1 + } +) + echo "hb-workload regression checks passed" diff --git a/tests/regressions-logs.sh b/tests/regressions-logs.sh index c0054d8..e648ced 100755 --- a/tests/regressions-logs.sh +++ b/tests/regressions-logs.sh @@ -51,6 +51,230 @@ args = parser.parse_args(["capture", "--source", "agent", "--", "true"]) assert args.restart_delay is None PY +# Inherited mirror-FD metadata is not a validity contract. Closed, missing, +# half-valid, and malformed values must fall back to owned stdout/stderr dups +# instead of crashing in Capture.__init__ before the target is exec'd. +python3 - "$helper" "$tmp/mirror-fds" <<'PY' +import importlib.machinery +import importlib.util +import os +import pathlib +import sys + +loader = importlib.machinery.SourceFileLoader("tx9_logs_mirror_fds", sys.argv[1]) +spec = importlib.util.spec_from_loader(loader.name, loader) +assert spec is not None +module = importlib.util.module_from_spec(spec) +loader.exec_module(module) +root = pathlib.Path(sys.argv[2]) +root.mkdir(parents=True, exist_ok=True) + +assert module.inherited_open_fd(None) is None +assert module.inherited_open_fd("") is None +assert module.inherited_open_fd("nope") is None +assert module.inherited_open_fd("-1") is None +assert module.inherited_open_fd("93") is None +assert module.inherited_open_fd("999999999999") is None +assert module.inherited_open_fd(str(sys.stdout.fileno())) == sys.stdout.fileno() +assert module.inherited_open_fd(str(sys.stderr.fileno())) == sys.stderr.fileno() + +saved_out = os.dup(sys.stdout.fileno()) +saved_err = os.dup(sys.stderr.fileno()) + + +def restore_stdio(): + os.dup2(saved_out, sys.stdout.fileno()) + os.dup2(saved_err, sys.stderr.fileno()) + + +def run_capture(label, env_updates, *, expect_owned, expect_warning): + for name in ("TX9_LOG_MIRROR_STDOUT_FD", "TX9_LOG_MIRROR_STDERR_FD"): + os.environ.pop(name, None) + os.environ.update(env_updates) + module.WARNINGS.clear() + log_dir = root / label + try: + capture = module.Capture("agent", log_dir, 1024 * 1024, 2) + try: + assert capture.owns_mirror_fds is expect_owned + warning_text = "\n".join(module.WARNINGS) + if expect_warning: + assert "invalid inherited TX9_LOG_MIRROR" in warning_text + else: + assert "invalid inherited TX9_LOG_MIRROR" not in warning_text + assert capture.run_once(["/bin/true"]) == 0 + finally: + capture.close() + finally: + restore_stdio() + for name in ("TX9_LOG_MIRROR_STDOUT_FD", "TX9_LOG_MIRROR_STDERR_FD"): + os.environ.pop(name, None) + + +run_capture("absent", {}, expect_owned=True, expect_warning=False) + +out_read, out_write = os.pipe() +err_read, err_write = os.pipe() +try: + run_capture( + "valid", + { + "TX9_LOG_MIRROR_STDOUT_FD": str(out_write), + "TX9_LOG_MIRROR_STDERR_FD": str(err_write), + }, + expect_owned=False, + expect_warning=False, + ) + os.fstat(out_write) + os.fstat(err_write) +finally: + os.close(out_read) + os.close(out_write) + os.close(err_read) + os.close(err_write) + +closed_read, closed_write = os.pipe() +closed_out, closed_err = closed_write, closed_read +os.close(closed_write) +os.close(closed_read) +run_capture( + "closed", + { + "TX9_LOG_MIRROR_STDOUT_FD": str(closed_out), + "TX9_LOG_MIRROR_STDERR_FD": str(closed_err), + }, + expect_owned=True, + expect_warning=True, +) + +half_read, half_write = os.pipe() +try: + run_capture( + "half-valid", + { + "TX9_LOG_MIRROR_STDOUT_FD": str(half_write), + "TX9_LOG_MIRROR_STDERR_FD": "94", + }, + expect_owned=True, + expect_warning=True, + ) + os.fstat(half_write) +finally: + os.close(half_read) + os.close(half_write) + +run_capture( + "missing-err", + {"TX9_LOG_MIRROR_STDOUT_FD": str(sys.stdout.fileno())}, + expect_owned=True, + expect_warning=True, +) +run_capture( + "nonnumeric", + {"TX9_LOG_MIRROR_STDOUT_FD": "nope", "TX9_LOG_MIRROR_STDERR_FD": "also-nope"}, + expect_owned=True, + expect_warning=True, +) +run_capture( + "negative", + {"TX9_LOG_MIRROR_STDOUT_FD": "-1", "TX9_LOG_MIRROR_STDERR_FD": "-2"}, + expect_owned=True, + expect_warning=True, +) +run_capture( + "huge", + { + "TX9_LOG_MIRROR_STDOUT_FD": "999999999999", + "TX9_LOG_MIRROR_STDERR_FD": "888888888888", + }, + expect_owned=True, + expect_warning=True, +) + +os.close(saved_out) +os.close(saved_err) +PY + +invalid_mirror_dir="$tmp/invalid-mirror-repro" +mkdir -p "$invalid_mirror_dir" +set +e +env \ + TX9_LOG_MIRROR_STDOUT_FD=93 \ + TX9_LOG_MIRROR_STDERR_FD=94 \ + "$helper" capture --source repro --log-dir "$invalid_mirror_dir" -- /bin/true \ + >"$tmp/invalid-mirror.stdout" 2>"$tmp/invalid-mirror.stderr" +invalid_mirror_status=$? +set -e +[[ "$invalid_mirror_status" == 0 ]] +if grep -q 'Bad file descriptor' "$tmp/invalid-mirror.stderr"; then + echo "capture crashed on invalid inherited mirror FDs" >&2 + exit 1 +fi +grep -q 'ignoring invalid inherited TX9_LOG_MIRROR' "$tmp/invalid-mirror.stderr" +jq -e 'select(.type == "process_start")' "$invalid_mirror_dir/repro.jsonl" >/dev/null +jq -e 'select(.type == "process_exit" and .data.status == 0)' \ + "$invalid_mirror_dir/repro.jsonl" >/dev/null + +# A child exit with --restart-delay keeps the wrapper alive and records the +# restart before launching a replacement. +restart_dir="$tmp/restart-delay-child" +restart_pid_file="$tmp/restart-delay-child.pid" +restart_generation="$tmp/restart-delay-child.generation" +mkdir -p "$restart_dir" +cat >"$tmp/restart-delay-child.sh" <<'EOF' +#!/usr/bin/env bash +printf '%s\n' "$$" >"$RESTART_PID_FILE" +n=$(cat "$RESTART_GENERATION" 2>/dev/null || echo 0) +echo $((n + 1)) >"$RESTART_GENERATION" +if [[ "$n" == 0 ]]; then + exit 7 +fi +trap 'exit 0' TERM +while :; do sleep 1; done +EOF +chmod 0700 "$tmp/restart-delay-child.sh" +RESTART_PID_FILE="$restart_pid_file" RESTART_GENERATION="$restart_generation" \ + "$helper" capture --source agent --log-dir "$restart_dir" --restart-delay 0.2 -- \ + "$tmp/restart-delay-child.sh" \ + >/dev/null 2>&1 & +restart_wrapper_pid=$! +pids+=("$restart_wrapper_pid") +wait_for_file "$restart_pid_file" +first_child="$(cat "$restart_pid_file")" +for _ in {1..100}; do + [[ "$(cat "$restart_generation" 2>/dev/null || true)" == 2 ]] && break + sleep 0.05 +done +[[ "$(cat "$restart_generation")" == 2 ]] +second_child="$(cat "$restart_pid_file")" +[[ "$second_child" != "$first_child" ]] +kill -0 "$restart_wrapper_pid" +kill -0 "$second_child" +jq -e 'select(.type == "process_exit" and .data.status == 7)' \ + "$restart_dir/agent.jsonl" >/dev/null +jq -e 'select(.type == "process_restart")' "$restart_dir/agent.jsonl" >/dev/null +jq -e --argjson pid "$second_child" \ + 'select(.type == "process_start" and .data.pid == $pid)' \ + "$restart_dir/agent.jsonl" >/dev/null +kill -TERM "$restart_wrapper_pid" +set +e +wait "$restart_wrapper_pid" +restart_wrapper_status=$? +set -e +[[ "$restart_wrapper_status" == 143 ]] +for _ in {1..50}; do + if ! kill -0 "$second_child" 2>/dev/null || + [[ "$(ps -o stat= -p "$second_child" 2>/dev/null)" == Z* ]]; then + break + fi + sleep 0.02 +done +if kill -0 "$second_child" 2>/dev/null && + [[ "$(ps -o stat= -p "$second_child" 2>/dev/null)" != Z* ]]; then + echo "restarting capture left its child running after SIGTERM" >&2 + exit 1 +fi + # The parent-death re-exec shim preserves Popen's lifecycle contract: actual # exec failures are process_start_failed events, never successful starts. start_failure_root="$tmp/start-failures" diff --git a/tests/static.sh b/tests/static.sh index fa1c112..1c1fd50 100755 --- a/tests/static.sh +++ b/tests/static.sh @@ -73,6 +73,14 @@ grep -q -- '--source "service-\$name"' guest/tx9-services grep -q -- '--restart-delay' guest/tx9-services grep -q '_services_reconcile' guest/hb grep -q '_services_stop' guest/hb +grep -q 'TX9_LOG_MIRROR_STDOUT_FD' guest/hb +grep -q '_sanitize_log_mirror_fds' guest/hb +grep -q 'GATEWAY_RESTART_DELAY' guest/hb +grep -q -- '--external-supervisor' guest/hb +grep -q 'inherited_open_fd' guest/tx9-logs +grep -q 'ignoring invalid inherited TX9_LOG_MIRROR' guest/tx9-logs +grep -q '_gateway_or_capture_running' guest/hb +grep -q 'nested tx9-logs exited' guest/hb # --- provisioning / config invariants ------------------------------------ grep -q 'tools) tools_only ;;' provision/provision.sh