From e11b3c1e9af412012deab9bc13858e2d272a5065 Mon Sep 17 00:00:00 2001 From: Blasius Patrick Date: Mon, 20 Jul 2026 17:05:00 +0700 Subject: [PATCH 1/2] fix: use print() for auto-start logging, log before socket check The plugin logger may filter INFO messages in the gateway runtime. Switch to print() (goes to stdout/journalctl) and add logging at every decision point: auto-start check, config load, port check result, thread creation, and errors with tracebacks. Signed-off-by: Blasius Patrick --- __init__.py | 54 ++++++++++++++++++++++++++++++++--------------------- 1 file changed, 33 insertions(+), 21 deletions(-) diff --git a/__init__.py b/__init__.py index fc21d88..e95a423 100644 --- a/__init__.py +++ b/__init__.py @@ -151,12 +151,17 @@ def _node_handler_lazy(args) -> None: import os if os.environ.get("HERMES_NODES_AUTO_START", "1") == "1": + print("hermes-node-plugin: auto-start check running", flush=True) # Load config to get the actual port for the socket check. from .config import load_config cfg = load_config() _check_host = cfg.connect_host _check_port = cfg.port + print( + f"hermes-node-plugin: config loaded host={_check_host} port={_check_port}", + flush=True, + ) # Quick socket check: if the configured port is already bound, # the server is already running (e.g. from a previous gateway @@ -170,18 +175,25 @@ def _node_handler_lazy(args) -> None: s.setsockopt(socket.SOL_SOCKET, socket.SO_REUSEADDR, 1) s.bind((_check_host, _check_port)) s.close() - except OSError: + print( + f"hermes-node-plugin: port {_check_port} is free, will start server", + flush=True, + ) + except OSError as e: _port_free = False + print( + f"hermes-node-plugin: port {_check_port} is in use ({e}), skipping", + flush=True, + ) if _port_free: def _start_server() -> None: import asyncio - log.info( - "hermes-node-plugin: starting WSS server on port %d" - " (background thread)", - _check_port, + print( + f"hermes-node-plugin: _start_server thread running on port {_check_port}", + flush=True, ) loop = asyncio.new_event_loop() asyncio.set_event_loop(loop) @@ -189,18 +201,19 @@ def _start_server() -> None: from .lifecycle import _on_session_start loop.run_until_complete(_on_session_start()) - log.info( - "hermes-node-plugin: WSS server started on port %d" - " (background thread)", - _check_port, + print( + f"hermes-node-plugin: WSS server started on port {_check_port}", + flush=True, ) # Keep the loop alive so uvicorn tasks continue running. loop.run_forever() except Exception as exc: - log.warning( - "hermes-node-plugin: server background thread failed: %s", - exc, + print( + f"hermes-node-plugin: server background thread failed: {exc}", + flush=True, ) + import traceback + traceback.print_exc() finally: loop.close() @@ -211,17 +224,16 @@ def _start_server() -> None: target=_start_server, daemon=True, name="hermes-node-wss" ) t.start() + print("hermes-node-plugin: daemon thread started", flush=True) except Exception as exc: - log.warning( - "hermes-node-plugin: could not start server thread: %s", exc + print( + f"hermes-node-plugin: could not start server thread: {exc}", + flush=True, ) else: - log.debug( - "hermes-node-plugin: port %d already bound — " - "server likely already running. Skipping auto-start.", - _check_port, + print( + f"hermes-node-plugin: port {_check_port} already bound — skipping", + flush=True, ) else: - log.debug( - "hermes-node-plugin: auto-start disabled (HERMES_NODES_AUTO_START=0)" - ) + print("hermes-node-plugin: auto-start disabled (HERMES_NODES_AUTO_START=0)", flush=True) From 0037acbf39737d4023c4c31c7c92e1ca3bbe113a Mon Sep 17 00:00:00 2001 From: Blasius Patrick Date: Mon, 20 Jul 2026 17:10:40 +0700 Subject: [PATCH 2/2] fix: log auto-start diagnostics to hermes-node-plugin.log file Replace all print() with _log() that writes to both stdout and ~/.hermes/profiles/kate/hermes-node-plugin.log. Includes timestamps and traceback formatting on failure. Signed-off-by: Blasius Patrick --- __init__.py | 66 ++++++++++++++++++++++++----------------------------- 1 file changed, 30 insertions(+), 36 deletions(-) diff --git a/__init__.py b/__init__.py index e95a423..2f4a6f2 100644 --- a/__init__.py +++ b/__init__.py @@ -149,19 +149,32 @@ def _node_handler_lazy(args) -> None: # Disabled in test/CI environments by setting the env var to ``0``. import os + import datetime as _datetime + + _LOG_DIR = os.environ.get("HERMES_HOME", os.path.expanduser("~/.hermes")) + _LOG_FILE = os.path.join(_LOG_DIR, "hermes-node-plugin.log") + + def _log(msg: str) -> None: + ts = _datetime.datetime.now().strftime("%Y-%m-%d %H:%M:%S") + line = f"[{ts}] {msg}" + print(line, flush=True) + try: + with open(_LOG_FILE, "a") as _f: + _f.write(line + "\n") + _f.flush() + except Exception: + pass + + _log("auto-start check running") if os.environ.get("HERMES_NODES_AUTO_START", "1") == "1": - print("hermes-node-plugin: auto-start check running", flush=True) # Load config to get the actual port for the socket check. from .config import load_config cfg = load_config() _check_host = cfg.connect_host _check_port = cfg.port - print( - f"hermes-node-plugin: config loaded host={_check_host} port={_check_port}", - flush=True, - ) + _log(f"config loaded host={_check_host} port={_check_port}") # Quick socket check: if the configured port is already bound, # the server is already running (e.g. from a previous gateway @@ -175,46 +188,33 @@ def _node_handler_lazy(args) -> None: s.setsockopt(socket.SOL_SOCKET, socket.SO_REUSEADDR, 1) s.bind((_check_host, _check_port)) s.close() - print( - f"hermes-node-plugin: port {_check_port} is free, will start server", - flush=True, - ) + _log(f"port {_check_port} is free, will start server") except OSError as e: _port_free = False - print( - f"hermes-node-plugin: port {_check_port} is in use ({e}), skipping", - flush=True, - ) + _log(f"port {_check_port} is in use ({e}), skipping") if _port_free: def _start_server() -> None: import asyncio - print( - f"hermes-node-plugin: _start_server thread running on port {_check_port}", - flush=True, - ) + _log(f"_start_server thread running on port {_check_port}") loop = asyncio.new_event_loop() asyncio.set_event_loop(loop) try: from .lifecycle import _on_session_start loop.run_until_complete(_on_session_start()) - print( - f"hermes-node-plugin: WSS server started on port {_check_port}", - flush=True, - ) + _log(f"WSS server started on port {_check_port}") # Keep the loop alive so uvicorn tasks continue running. loop.run_forever() except Exception as exc: - print( - f"hermes-node-plugin: server background thread failed: {exc}", - flush=True, - ) + _log(f"server background thread failed: {exc}") import traceback - traceback.print_exc() + + _log(traceback.format_exc()) finally: + _log("event loop closed") loop.close() try: @@ -224,16 +224,10 @@ def _start_server() -> None: target=_start_server, daemon=True, name="hermes-node-wss" ) t.start() - print("hermes-node-plugin: daemon thread started", flush=True) + _log("daemon thread started") except Exception as exc: - print( - f"hermes-node-plugin: could not start server thread: {exc}", - flush=True, - ) + _log(f"could not start server thread: {exc}") else: - print( - f"hermes-node-plugin: port {_check_port} already bound — skipping", - flush=True, - ) + _log(f"port {_check_port} already bound — skipping") else: - print("hermes-node-plugin: auto-start disabled (HERMES_NODES_AUTO_START=0)", flush=True) + _log("auto-start disabled (HERMES_NODES_AUTO_START=0)")