fix: log WebUI shutdown diagnostics

This commit is contained in:
ai-ag2026
2026-05-28 22:55:38 +02:00
parent cf003ae986
commit 53f16c4ee6
4 changed files with 165 additions and 0 deletions

View File

@@ -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

View File

@@ -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

View File

@@ -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

View File

@@ -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