fix(gateway): timestamp launchd error log lines
This commit is contained in:
+27
-23
@@ -4202,14 +4202,28 @@ def _gateway_run_command() -> list[str]:
|
||||
return cmd
|
||||
|
||||
|
||||
def _timestamped_stderr_gateway_command(error_log: Path) -> list[str]:
|
||||
"""Wrap gateway run so raw stderr lines are timestamped before file write."""
|
||||
return [
|
||||
get_python_path(),
|
||||
"-m",
|
||||
"hermes_cli.stderr_timestamp",
|
||||
"--error-log",
|
||||
str(error_log),
|
||||
"--",
|
||||
*_gateway_run_command(),
|
||||
]
|
||||
|
||||
|
||||
def _spawn_detached_gateway() -> bool:
|
||||
"""Launch the gateway as a detached background process (launchd fallback).
|
||||
|
||||
Used when launchctl can no longer bootstrap/kickstart the gateway on
|
||||
macOS 26+ (issue #23387). Mirrors the `nohup hermes gateway run --replace`
|
||||
workaround but keeps it CLI-managed: stdout/stderr go to the profile's
|
||||
gateway logs and the PID is tracked via the gateway.pid file that
|
||||
`run_gateway` writes, so stop/status/restart keep working.
|
||||
workaround but keeps it CLI-managed: stdout goes to gateway.log, stderr is
|
||||
timestamped into gateway.error.log, and the PID is tracked via the
|
||||
gateway.pid file that `run_gateway` writes, so stop/status/restart keep
|
||||
working.
|
||||
"""
|
||||
from hermes_cli._subprocess_compat import windows_detach_popen_kwargs
|
||||
|
||||
@@ -4219,16 +4233,15 @@ def _spawn_detached_gateway() -> bool:
|
||||
err_path = log_dir / "gateway.error.log"
|
||||
try:
|
||||
out = open(out_path, "ab")
|
||||
err = open(err_path, "ab")
|
||||
except OSError:
|
||||
return False
|
||||
try:
|
||||
with out, err:
|
||||
with out:
|
||||
subprocess.Popen(
|
||||
_gateway_run_command(),
|
||||
_timestamped_stderr_gateway_command(err_path),
|
||||
stdin=subprocess.DEVNULL,
|
||||
stdout=out,
|
||||
stderr=err,
|
||||
stderr=subprocess.DEVNULL,
|
||||
**windows_detach_popen_kwargs(),
|
||||
)
|
||||
except OSError:
|
||||
@@ -4264,7 +4277,6 @@ def _launchd_fallback_to_detached(reason: str, *, exit_on_failure: bool = True)
|
||||
|
||||
|
||||
def generate_launchd_plist() -> str:
|
||||
python_path = get_python_path()
|
||||
# Stable cwd anchor — never the volatile source checkout. See
|
||||
# _stable_service_working_dir() for the rationale (same rot risk applies
|
||||
# to launchd's WorkingDirectory as to systemd's).
|
||||
@@ -4273,7 +4285,6 @@ def generate_launchd_plist() -> str:
|
||||
log_dir = get_hermes_home() / "logs"
|
||||
log_dir.mkdir(parents=True, exist_ok=True)
|
||||
label = get_launchd_label()
|
||||
profile_arg = _profile_arg(hermes_home)
|
||||
# Build a sane PATH for the launchd plist. launchd provides only a
|
||||
# minimal default (/usr/bin:/bin:/usr/sbin:/sbin) which misses Homebrew,
|
||||
# nvm, cargo, etc. We prepend venv/bin and node_modules/.bin (matching
|
||||
@@ -4291,22 +4302,15 @@ def generate_launchd_plist() -> str:
|
||||
)
|
||||
)
|
||||
|
||||
# Build ProgramArguments array, including --profile when using a named profile
|
||||
err_path = log_dir / "gateway.error.log"
|
||||
|
||||
# Build ProgramArguments array, including --profile when using a named profile.
|
||||
# The stderr wrapper preserves launchd's restart semantics while adding
|
||||
# timestamps to raw stderr lines before they land in gateway.error.log.
|
||||
prog_args = [
|
||||
f"<string>{python_path}</string>",
|
||||
"<string>-m</string>",
|
||||
"<string>hermes_cli.main</string>",
|
||||
f"<string>{part}</string>"
|
||||
for part in _timestamped_stderr_gateway_command(err_path)
|
||||
]
|
||||
if profile_arg:
|
||||
for part in profile_arg.split():
|
||||
prog_args.append(f"<string>{part}</string>")
|
||||
prog_args.extend(
|
||||
[
|
||||
"<string>gateway</string>",
|
||||
"<string>run</string>",
|
||||
"<string>--replace</string>",
|
||||
]
|
||||
)
|
||||
prog_args_xml = "\n ".join(prog_args)
|
||||
|
||||
# Persist the configured RLIMIT_NOFILE floor into the service definition
|
||||
|
||||
@@ -0,0 +1,101 @@
|
||||
"""Run a child process while prefixing each stderr line with a timestamp."""
|
||||
|
||||
from __future__ import annotations
|
||||
|
||||
import argparse
|
||||
import signal
|
||||
import subprocess
|
||||
import sys
|
||||
from datetime import datetime
|
||||
from pathlib import Path
|
||||
from typing import BinaryIO, Sequence, TextIO
|
||||
|
||||
|
||||
def _timestamp() -> str:
|
||||
"""Match logging.Formatter's default ``%(asctime)s`` timestamp shape."""
|
||||
return datetime.now().strftime("%Y-%m-%d %H:%M:%S,%f")[:23]
|
||||
|
||||
|
||||
def _write_timestamped_line(log_file: TextIO, line: str) -> None:
|
||||
log_file.write(f"{_timestamp()} {line.rstrip(chr(10))}\n")
|
||||
log_file.flush()
|
||||
|
||||
|
||||
def _copy_stderr_with_timestamps(stderr: BinaryIO, log_path: Path) -> None:
|
||||
log_path.parent.mkdir(parents=True, exist_ok=True)
|
||||
with log_path.open("a", encoding="utf-8", buffering=1) as log_file:
|
||||
for raw_line in iter(stderr.readline, b""):
|
||||
line = raw_line.decode("utf-8", errors="replace")
|
||||
_write_timestamped_line(log_file, line)
|
||||
|
||||
|
||||
def _command_exit_code(returncode: int) -> int:
|
||||
if returncode < 0:
|
||||
return 128 + abs(returncode)
|
||||
return returncode
|
||||
|
||||
|
||||
def _install_signal_forwarders(proc: subprocess.Popen[bytes]) -> dict[int, object]:
|
||||
def _forward(signum: int, _frame: object) -> None:
|
||||
try:
|
||||
proc.send_signal(signum)
|
||||
except ProcessLookupError:
|
||||
pass
|
||||
|
||||
previous: dict[int, object] = {}
|
||||
for signum in (signal.SIGTERM, signal.SIGINT, getattr(signal, "SIGHUP", None)):
|
||||
if signum is not None:
|
||||
try:
|
||||
previous[signum] = signal.getsignal(signum)
|
||||
signal.signal(signum, _forward)
|
||||
except (OSError, RuntimeError, ValueError):
|
||||
previous.pop(signum, None)
|
||||
return previous
|
||||
|
||||
|
||||
def _restore_signal_handlers(previous: dict[int, object]) -> None:
|
||||
for signum, handler in previous.items():
|
||||
signal.signal(signum, handler)
|
||||
|
||||
|
||||
def _parse_args(argv: Sequence[str] | None) -> argparse.Namespace:
|
||||
parser = argparse.ArgumentParser(
|
||||
description="Run a command and timestamp each stderr line into a log file."
|
||||
)
|
||||
parser.add_argument("--error-log", required=True, type=Path)
|
||||
parser.add_argument("command", nargs=argparse.REMAINDER)
|
||||
args = parser.parse_args(argv)
|
||||
if args.command and args.command[0] == "--":
|
||||
args.command = args.command[1:]
|
||||
if not args.command:
|
||||
parser.error("missing command after --")
|
||||
return args
|
||||
|
||||
|
||||
def main(argv: Sequence[str] | None = None) -> int:
|
||||
args = _parse_args(argv)
|
||||
log_path: Path = args.error_log
|
||||
|
||||
try:
|
||||
proc = subprocess.Popen(args.command, stderr=subprocess.PIPE)
|
||||
except OSError as exc:
|
||||
log_path.parent.mkdir(parents=True, exist_ok=True)
|
||||
with log_path.open("a", encoding="utf-8", buffering=1) as log_file:
|
||||
_write_timestamped_line(
|
||||
log_file,
|
||||
f"failed to start stderr-timestamped command: {exc}",
|
||||
)
|
||||
return 127
|
||||
|
||||
assert proc.stderr is not None
|
||||
previous_handlers = _install_signal_forwarders(proc)
|
||||
try:
|
||||
_copy_stderr_with_timestamps(proc.stderr, log_path)
|
||||
finally:
|
||||
proc.stderr.close()
|
||||
_restore_signal_handlers(previous_handlers)
|
||||
return _command_exit_code(proc.wait())
|
||||
|
||||
|
||||
if __name__ == "__main__":
|
||||
sys.exit(main())
|
||||
@@ -221,8 +221,42 @@ class TestContainerSystemdSupport:
|
||||
assert gateway.supports_systemd_services() is True
|
||||
|
||||
|
||||
def test_spawn_detached_gateway_timestamps_stderr(monkeypatch, tmp_path):
|
||||
calls = []
|
||||
child_cmd = [
|
||||
"/usr/bin/python3",
|
||||
"-m",
|
||||
"hermes_cli.main",
|
||||
"gateway",
|
||||
"run",
|
||||
"--replace",
|
||||
]
|
||||
|
||||
def fake_popen(cmd, **kwargs):
|
||||
calls.append((cmd, kwargs))
|
||||
return SimpleNamespace()
|
||||
|
||||
monkeypatch.setattr(gateway, "get_hermes_home", lambda: tmp_path)
|
||||
monkeypatch.setattr(gateway, "get_python_path", lambda: "/usr/bin/python3")
|
||||
monkeypatch.setattr(gateway, "_gateway_run_command", lambda: child_cmd)
|
||||
monkeypatch.setattr(gateway.subprocess, "Popen", fake_popen)
|
||||
|
||||
assert gateway._spawn_detached_gateway() is True
|
||||
|
||||
assert len(calls) == 1
|
||||
cmd, kwargs = calls[0]
|
||||
assert cmd == [
|
||||
"/usr/bin/python3",
|
||||
"-m",
|
||||
"hermes_cli.stderr_timestamp",
|
||||
"--error-log",
|
||||
str(tmp_path / "logs" / "gateway.error.log"),
|
||||
"--",
|
||||
*child_cmd,
|
||||
]
|
||||
assert kwargs["stdin"] is gateway.subprocess.DEVNULL
|
||||
assert kwargs["stderr"] is gateway.subprocess.DEVNULL
|
||||
assert kwargs["stdout"].name == str(tmp_path / "logs" / "gateway.log")
|
||||
|
||||
|
||||
@pytest.mark.skipif(
|
||||
|
||||
@@ -1,6 +1,7 @@
|
||||
"""Tests for gateway service management helpers."""
|
||||
|
||||
import os
|
||||
import plistlib
|
||||
import subprocess
|
||||
from pathlib import Path
|
||||
from types import SimpleNamespace
|
||||
@@ -1222,7 +1223,33 @@ class TestProfileArg:
|
||||
assert "--profile mybot gateway run" in unit
|
||||
assert f'HERMES_HOME={target_home / ".hermes" / "profiles" / "mybot"}' in unit
|
||||
|
||||
def test_launchd_plist_wraps_gateway_stderr_with_timestamps(self, tmp_path, monkeypatch):
|
||||
profile_dir = tmp_path / ".hermes" / "profiles" / "mybot"
|
||||
profile_dir.mkdir(parents=True)
|
||||
monkeypatch.setattr(Path, "home", lambda: tmp_path)
|
||||
monkeypatch.setenv("HERMES_HOME", str(profile_dir))
|
||||
monkeypatch.setattr(gateway_cli, "get_hermes_home", lambda: profile_dir)
|
||||
monkeypatch.setattr(gateway_cli, "get_python_path", lambda: "/usr/bin/python3")
|
||||
|
||||
plist = gateway_cli.generate_launchd_plist()
|
||||
program_args = plistlib.loads(plist.encode("utf-8"))["ProgramArguments"]
|
||||
|
||||
assert program_args == [
|
||||
"/usr/bin/python3",
|
||||
"-m",
|
||||
"hermes_cli.stderr_timestamp",
|
||||
"--error-log",
|
||||
str(profile_dir / "logs" / "gateway.error.log"),
|
||||
"--",
|
||||
"/usr/bin/python3",
|
||||
"-m",
|
||||
"hermes_cli.main",
|
||||
"--profile",
|
||||
"mybot",
|
||||
"gateway",
|
||||
"run",
|
||||
"--replace",
|
||||
]
|
||||
|
||||
def test_launchd_plist_path_uses_real_user_home_not_profile_home(self, tmp_path, monkeypatch):
|
||||
profile_dir = tmp_path / ".hermes" / "profiles" / "orcha"
|
||||
@@ -2003,7 +2030,6 @@ class TestRetryLaunchctlBootstrapUntilRegistered:
|
||||
)
|
||||
assert ok is True
|
||||
assert attempts["bootstrap"] >= 2 # the timeout was retried, not raised
|
||||
|
||||
def test_registered_but_not_running_is_not_success(self, monkeypatch):
|
||||
"""A definition with no PID must not end the loop.
|
||||
|
||||
@@ -2034,4 +2060,3 @@ class TestRetryLaunchctlBootstrapUntilRegistered:
|
||||
)
|
||||
assert ok is False
|
||||
assert list_calls["n"] >= 1
|
||||
|
||||
|
||||
@@ -0,0 +1,34 @@
|
||||
"""Tests for hermes_cli.stderr_timestamp."""
|
||||
|
||||
import re
|
||||
import sys
|
||||
|
||||
from hermes_cli import stderr_timestamp
|
||||
|
||||
|
||||
def test_main_timestamps_each_stderr_line(tmp_path):
|
||||
log_path = tmp_path / "gateway.error.log"
|
||||
code = (
|
||||
"import sys\n"
|
||||
"sys.stderr.write('first failure\\n')\n"
|
||||
"sys.stderr.write('second failure without newline')\n"
|
||||
"sys.exit(7)\n"
|
||||
)
|
||||
|
||||
rc = stderr_timestamp.main(
|
||||
[
|
||||
"--error-log",
|
||||
str(log_path),
|
||||
"--",
|
||||
sys.executable,
|
||||
"-c",
|
||||
code,
|
||||
]
|
||||
)
|
||||
|
||||
assert rc == 7
|
||||
lines = log_path.read_text(encoding="utf-8").splitlines()
|
||||
timestamp = r"\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2},\d{3}"
|
||||
assert len(lines) == 2
|
||||
assert re.fullmatch(f"{timestamp} first failure", lines[0])
|
||||
assert re.fullmatch(f"{timestamp} second failure without newline", lines[1])
|
||||
Reference in New Issue
Block a user