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")