From 64b30fb11f4795fbce3ddfafb7a7cadcc7f41052 Mon Sep 17 00:00:00 2001 From: itswl Date: Wed, 14 Oct 2026 10:07:41 +0800 Subject: [PATCH] sidecars: an idle keep-alive closes at DEBUG, and an upstream that never answered says so MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The shared HTTP handler logged every socket timeout as one WARNING line. Most of them were an MCP client's keep-alive connection idling past `timeout` between calls — the timeout doing its job — and a peer with a real problem, or an upstream that hung, was a line among them. Where the read was now decides: waiting for the next request line after at least one answer is the idle close, logged at DEBUG; a socket that never spoke, or a request whose headers or body never arrived, stays one line at WARNING with the count and the last request line. The gate's upstream failures were in the ledger only. They are logged at WARNING as well, and a timeout is named as one with the limit it ran into ("upstream timeout: no answer within 60s"), so it cannot be read as the client-side `timed out`. --- deploy/sidecars/common.py | 40 ++++++++++++++++++++++------ deploy/sidecars/gate.py | 23 +++++++++++++++- deploy/sidecars/tests/test_common.py | 20 ++++++++++++-- deploy/sidecars/tests/test_gate.py | 22 +++++++++++++++ 4 files changed, 94 insertions(+), 11 deletions(-) diff --git a/deploy/sidecars/common.py b/deploy/sidecars/common.py index 5d00d7b7..402723e0 100644 --- a/deploy/sidecars/common.py +++ b/deploy/sidecars/common.py @@ -139,7 +139,14 @@ def handle(self) -> None: with contextlib.suppress(ConnectionResetError, BrokenPipeError): super().handle() + def handle_one_request(self) -> None: + # Waiting for a request line: a timeout from here until one arrives is the + # connection idling, not a request going wrong (see log_error) + self._between_requests = True + super().handle_one_request() + def parse_request(self) -> bool: + self._between_requests = False parsed = super().parse_request() if parsed: self._last_request = { @@ -153,26 +160,43 @@ def parse_request(self) -> bool: return parsed def log_error(self, fmt: str, *args: Any) -> None: - """A timeout names the peer and what the connection had carried. + """A timeout says which kind it was, the peer, and what the connection + had carried. The stdlib's line is `Request timed out: TimeoutError('timed out')` and nothing else, which cannot tell a keep-alive connection that idled - past `timeout` — an MCP client holds one open per session — from a - peer that declared a body and stopped sending it. The count and the - last request line say which: nothing seen is a socket that connected - and never spoke; a request carrying a Content-Length is the one whose - body may not have arrived. One line, at WARNING, so a run of them - reads as a peer with a problem rather than as this sidecar's. + past `timeout` from a peer that declared a body and stopped sending it. + Where the read was tells them apart. Waiting for the next request line + after at least one answer is the idle close: an MCP client holds a + connection open for its session and goes quiet between calls, and + closing it is the timeout doing its job — at WARNING, those lines were + most of the log, and a real failure had to be picked out from among + them. So that one goes to DEBUG. Everything else stays one line at + WARNING, the count and the last request line saying which it was: + nothing seen is a socket that connected and never spoke; a request + carrying a Content-Length is the one whose body may not have arrived. + A failure on the far side of a sidecar is that sidecar's to log (the + gate's upstream failures are), never this line. """ if fmt == "Request timed out: %r": peer = self.client_address[0] if self.client_address else "unknown" port = self.client_address[1] if self.client_address else "unknown" + seen = getattr(self, "_request_count", 0) + if getattr(self, "_between_requests", False) and seen: + logging.getLogger(self.server_version).debug( + "idle keep-alive closed peer=%s:%s timeout=%ss requests_seen=%s", + peer, + port, + self.timeout, + seen, + ) + return logging.getLogger(self.server_version).warning( "request timeout peer=%s:%s timeout=%ss requests_seen=%s last_request=%s cause=%s", peer, port, self.timeout, - getattr(self, "_request_count", 0), + seen, getattr(self, "_last_request", None) or "none", plain(fmt % args), ) diff --git a/deploy/sidecars/gate.py b/deploy/sidecars/gate.py index dbe7a436..07881ddd 100644 --- a/deploy/sidecars/gate.py +++ b/deploy/sidecars/gate.py @@ -461,6 +461,17 @@ def _relay( opener = urllib.request.build_opener(urllib.request.ProxyHandler({}), _NoRedirect()) def failed(reason: str) -> None: + # The upstream's failure, said in the log as well as the ledger, and + # said apart from the client-side timeouts the handler logs: an idle + # keep-alive closing is routine, a server that did not answer is not + logger.warning( + "upstream failed client=%s %smethod=%s tools=%s reason=%s", + client.name, + f"route={route.name} " if route.name else "", + method, + [c["tool"] for c in calls], + reason, + ) self.ledger.write( event="call.failed", client=client.name, @@ -488,7 +499,7 @@ def failed(reason: str) -> None: except (OSError, http.client.HTTPException) as exc: # HTTPException is not an OSError: a chunked answer cut mid-chunk is # this branch, not a crash with no answer and no row. - failed(str(exc)[:200]) + failed(_failure_reason(exc)) return if len(raw) > ANSWER_MAX: failed(f"the answer is larger than {ANSWER_MAX} bytes") @@ -508,6 +519,16 @@ def failed(reason: str) -> None: self._answer(status, out, content_type, {"Mcp-Session-Id": session} if session else None) +def _failure_reason(exc: BaseException) -> str: + """What the ledger and the log say about a relay that got no answer. A + timeout says so by name, with the limit it ran into — urllib wraps one that + happens on connect in a URLError — rather than as `timed out`, which reads + the same as the client-side timeouts the handler logs.""" + if isinstance(exc, TimeoutError) or isinstance(getattr(exc, "reason", None), TimeoutError): + return f"upstream timeout: no answer within {UPSTREAM_TIMEOUT:g}s" + return str(exc)[:200] + + class _NoRedirect(urllib.request.HTTPRedirectHandler): def redirect_request(self, *args: Any, **kwargs: Any) -> None: # noqa: D102 return None diff --git a/deploy/sidecars/tests/test_common.py b/deploy/sidecars/tests/test_common.py index 0915a0a7..a6104c3f 100644 --- a/deploy/sidecars/tests/test_common.py +++ b/deploy/sidecars/tests/test_common.py @@ -53,12 +53,28 @@ def test_a_peer_that_never_speaks_is_logged_as_such(server, caplog): assert "requests_seen=0" in record.getMessage() and "last_request=none" in record.getMessage() -def test_an_idle_keep_alive_names_the_request_it_carried(server, caplog): - caplog.set_level(logging.WARNING) +def test_an_idle_keep_alive_closes_at_debug_not_as_a_warning(server, caplog): + """A client that holds its connection between calls — an MCP client does, + for its session — is closed by the timeout doing its job. At WARNING those + closes were most of the log, and a peer with a real problem was a line among + them.""" + caplog.set_level(logging.DEBUG) with socket.create_connection(server) as sock: sock.sendall(b"POST /v1/thing HTTP/1.1\r\nHost: x\r\nContent-Length: 2\r\n\r\n{}") assert sock.recv(4096).startswith(b"HTTP/1.1 200") + record = wait_for(caplog, "idle keep-alive closed") + assert record.levelno == logging.DEBUG + assert "requests_seen=1" in record.getMessage() + assert not [r for r in caplog.records if r.levelno >= logging.WARNING], "an idle close is not a warning" + + +def test_a_body_that_never_arrives_names_the_request_it_belonged_to(server, caplog): + caplog.set_level(logging.WARNING) + with socket.create_connection(server) as sock: + sock.sendall(b"POST /v1/thing HTTP/1.1\r\nHost: x\r\nContent-Length: 10\r\n\r\n{}") record = wait_for(caplog, "request timeout") message = record.getMessage() + assert record.levelno == logging.WARNING assert "requests_seen=1" in message assert "'method': 'POST'" in message and "'path': '/v1/thing'" in message + assert "'content_length': '10'" in message diff --git a/deploy/sidecars/tests/test_gate.py b/deploy/sidecars/tests/test_gate.py index 397ecb37..71757f60 100644 --- a/deploy/sidecars/tests/test_gate.py +++ b/deploy/sidecars/tests/test_gate.py @@ -16,10 +16,12 @@ from __future__ import annotations import json +import logging import os import socket import sys import threading +import time import urllib.error import urllib.request from http.server import BaseHTTPRequestHandler, ThreadingHTTPServer @@ -42,6 +44,8 @@ class Upstream(BaseHTTPRequestHandler): # Declare a body and send only part of it: the shape of a chat server that # died mid-answer. truncate = False + # Seconds to say nothing before answering: a chat server that hangs. + stall = 0.0 def log_message(self, *args) -> None: # noqa: D102 pass @@ -59,6 +63,7 @@ def _record(self, method: str) -> None: "headers": {name.lower(): value for name, value in self.headers.items()}, } ) + time.sleep(self.stall) self.send_response(200) self.send_header("Content-Type", self.content_type) self.send_header("Content-Length", str(len(self.answer) + (100 if self.truncate else 0))) @@ -85,6 +90,7 @@ def stack(tmp_path): Upstream.answer = b'{"jsonrpc":"2.0","id":1,"result":{"ok":true}}' Upstream.content_type = "application/json" Upstream.truncate = False + Upstream.stall = 0.0 upstream = ThreadingHTTPServer(("127.0.0.1", 0), Upstream) threading.Thread(target=upstream.serve_forever, kwargs={"poll_interval": 0.02}, daemon=True).start() gate_module.Gate.upstream = f"http://127.0.0.1:{upstream.server_port}/mcp/" @@ -291,6 +297,22 @@ def test_a_chat_server_that_dies_mid_answer_is_a_502_not_a_dropped_socket(stack) assert rows()[-1]["event"] == "call.failed" +def test_a_chat_server_that_hangs_is_a_502_that_says_it_timed_out(stack, monkeypatch, caplog): + """The upstream's timeout, named as one in the ledger and logged at WARNING: + the client-side timeouts the handler logs read `timed out` too, and an idle + keep-alive closing is routine where a server that never answered is not.""" + monkeypatch.setattr(gate_module, "UPSTREAM_TIMEOUT", 0.3) + Upstream.stall = 1.0 + caplog.set_level(logging.WARNING) + assert call(stack, _tool("chat.list_mentions"))[0] == 502 + failed = rows()[-1] + assert failed["event"] == "call.failed" + assert failed["reason"] == "upstream timeout: no answer within 0.3s" + lines = [r.getMessage() for r in caplog.records if r.levelno == logging.WARNING] + said = [line for line in lines if "upstream failed" in line and "upstream timeout" in line] + assert said and "chat.list_mentions" in said[0], lines + + def test_a_body_that_cannot_be_a_call_is_refused_before_it_is_read(stack): head = f"POST / HTTP/1.1\r\nHost: x\r\nAuthorization: Bearer {WATCH_TOKEN}\r\nContent-Length: abc\r\n\r\n" assert raw(stack, head).startswith(b"HTTP/1.1 400")