an idle keep-alive closes at DEBUG, and an upstream that never answered says so

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

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

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

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