diff --git a/CHANGELOG.md b/CHANGELOG.md index 93da0a58..3e23d39c 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -3,6 +3,10 @@ ## [Unreleased] +### Fixed + +- WebUI now logs structured shutdown diagnostics when the server exits or `/api/shutdown` is called, including active stream IDs to help diagnose interrupted turns after restarts. + ## [v0.51.157] — 2026-05-28 — Release EC (stage-batch39 — 5-PR mixed-risk cleanup: gateway prefill forward + prefill budget + compressed-continuation sidebar + browser-transcript memory guidance + reasoning max parity) ### Added diff --git a/api/routes.py b/api/routes.py index 768b499b..d95f65aa 100644 --- a/api/routes.py +++ b/api/routes.py @@ -3852,8 +3852,39 @@ def _serve_shell_unavailable(handler, exc: Exception) -> bool: return True +_SHUTDOWN_LOG_VALUE_RE = re.compile(r"[\x00-\x1f\x7f]+") + + +def _shutdown_log_value(value, *, default: str = "unknown", max_len: int = 160) -> str: + """Return a bounded single-line value safe for shutdown diagnostics.""" + if value is None: + return default + try: + text = str(value) + except Exception: + return default + text = _SHUTDOWN_LOG_VALUE_RE.sub("?", text).strip() + if not text: + return default + if len(text) > max_len: + text = f"{text[:max_len]}…" + return text + + def _handle_shutdown(handler) -> bool: """Shut down the WebUI server process.""" + headers = getattr(handler, "headers", {}) + ua = headers.get("User-Agent", "no-ua") if hasattr(headers, "get") else "no-ua" + remote = "unknown" + if getattr(handler, "client_address", None): + remote = getattr(handler, "client_address", ("unknown",))[0] + logger.info( + "[shutdown-request] remote=%s method=%s path=%s ua=%s", + _shutdown_log_value(remote), + _shutdown_log_value(getattr(handler, "command", None)), + _shutdown_log_value(getattr(handler, "path", None), max_len=240), + _shutdown_log_value(ua, default="no-ua", max_len=240), + ) j(handler, {"status": "shutting_down"}) import signal import threading diff --git a/server.py b/server.py index 8d82f4ce..9f481799 100644 --- a/server.py +++ b/server.py @@ -8,6 +8,7 @@ import os import re import socket import sys +import threading import time import traceback from http.server import BaseHTTPRequestHandler, ThreadingHTTPServer @@ -403,6 +404,63 @@ def _raise_fd_soft_limit(target: int = 4096) -> dict: return {"status": "raised", "soft": desired, "hard": hard, "previous_soft": soft} +_SHUTDOWN_AUDIT_LOGGED = False +_SHUTDOWN_LOG_VALUE_RE = re.compile(r"[\x00-\x1f\x7f]+") + + +def _shutdown_log_value(value, *, default: str = "unknown", max_len: int = 160) -> str: + """Return a bounded single-line value safe for shutdown diagnostics.""" + if value is None: + return default + try: + text = str(value) + except Exception: + return default + text = _SHUTDOWN_LOG_VALUE_RE.sub("?", text).strip() + if not text: + return default + if len(text) > max_len: + text = f"{text[:max_len]}…" + return text + + +def _log_shutdown_audit(reason: str = "serve_forever_exit") -> None: + """Log runtime context when the WebUI server is exiting.""" + global _SHUTDOWN_AUDIT_LOGGED + if _SHUTDOWN_AUDIT_LOGGED: + return + + active_sessions = [] + try: + from api.models import LOCK, SESSIONS + with LOCK: + session_items = list(SESSIONS.items()) + for sid, session in session_items: + stream_id = getattr(session, "active_stream_id", None) + if stream_id: + pending = bool(getattr(session, "pending_user_message", None)) + active_sessions.append( + "sid=%s stream=%s pending=%s" + % ( + _shutdown_log_value(sid), + _shutdown_log_value(stream_id), + pending, + ) + ) + except Exception: + logger.debug("Failed to collect active-session shutdown audit state", exc_info=True) + + _SHUTDOWN_AUDIT_LOGGED = True + logger.info( + "[shutdown-audit] reason=%s pid=%s thread=%s(%s) active_sessions=[%s]", + _shutdown_log_value(reason), + os.getpid(), + _shutdown_log_value(threading.current_thread().name), + threading.current_thread().ident, + "; ".join(active_sessions) if active_sessions else "none", + ) + + def main() -> None: from api.config import print_startup_config, verify_hermes_imports, _HERMES_FOUND @@ -516,6 +574,7 @@ def main() -> None: try: httpd.serve_forever() finally: + _log_shutdown_audit() # Stop the gateway watcher on shutdown try: from api.gateway_watcher import stop_watcher diff --git a/tests/test_shutdown_audit_logging.py b/tests/test_shutdown_audit_logging.py new file mode 100644 index 00000000..3f1b726f --- /dev/null +++ b/tests/test_shutdown_audit_logging.py @@ -0,0 +1,71 @@ +import logging +import types +import threading + + +def test_server_shutdown_audit_logs_active_stream_context(monkeypatch, caplog): + import server + from api import models + + monkeypatch.setattr(server, "_SHUTDOWN_AUDIT_LOGGED", False) + monkeypatch.setitem( + models.SESSIONS, + "session-1\nforged", + types.SimpleNamespace(active_stream_id="stream-1\rforged", pending_user_message="hello"), + ) + monkeypatch.setitem( + models.SESSIONS, + "session-2", + types.SimpleNamespace(active_stream_id=None, pending_user_message=None), + ) + + caplog.set_level(logging.INFO, logger="server") + server._log_shutdown_audit(reason="test-exit") + + logged = "\n".join(record.getMessage() for record in caplog.records) + assert "[shutdown-audit]" in logged + assert "reason=test-exit" in logged + assert "sid=session-1?forged stream=stream-1?forged pending=True" in logged + assert "session-1\nforged" not in logged + assert "stream-1\rforged" not in logged + assert "session-2" not in logged + + +def test_shutdown_route_logs_request_context_without_starting_real_shutdown(monkeypatch, caplog): + from api import routes + + responses = [] + monkeypatch.setattr(routes, "j", lambda handler, payload, **kw: responses.append(payload) or True) + + started_threads = [] + + class FakeThread: + def __init__(self, target, daemon=False): + self.target = target + self.daemon = daemon + + def start(self): + started_threads.append((self.target, self.daemon)) + + monkeypatch.setattr(threading, "Thread", FakeThread) + + handler = types.SimpleNamespace( + client_address=("127.0.0.1", 12345), + command="POST", + path="/api/shutdown\nforged", + headers={"User-Agent": "pytest-agent\r\nforged"}, + ) + + caplog.set_level(logging.INFO, logger="api.routes") + assert routes._handle_shutdown(handler) is True + + logged = "\n".join(record.getMessage() for record in caplog.records) + assert "[shutdown-request]" in logged + assert "remote=127.0.0.1" in logged + assert "method=POST" in logged + assert "path=/api/shutdown?forged" in logged + assert "ua=pytest-agent?forged" in logged + assert "/api/shutdown\nforged" not in logged + assert "pytest-agent\r\nforged" not in logged + assert responses == [{"status": "shutting_down"}] + assert started_threads and started_threads[0][1] is True