a bot by its name, a door that answers its own failure, an alarm that tries again, and a rollback that says what it does

.agents/notes/implemented/2026-10-26-a-bot-by-its-name-a-door-that-answers-its-own-failure-an-alarm-that-tries-again.md

@@ -0,0 +1,65 @@
+---
+title: A bot by its name, a door that answers its own failure, an alarm that tries again, and a rollback that says what it does
+status: implemented
+date: 2026-10-26
+scope: stack
+---
+
+## Decision
+
+A second deployment running copies of these files met four things in a week
+that hold here too.
+
+1. **The watch scanner recognizes a bot by its name.** `WATCH_BOTS` was the only
+   way to drop a bot, so a bot nobody listed reached the digest as a message to
+   answer. `BOT_NAME` drops a sender whose display name has bot or robot as a
+   word of its own, a CamelCase `…Bot`, or 机器人; bot inside a word (Talbot,
+   Abbott) is a person. The list stays, for bots whose names say nothing.
+2. **A door answers and records a failure nobody planned for.** An exception a
+   sidecar did not expect ended the handler thread: the caller waited out its
+   own timeout, the ledger had no line, and the traceback went to stderr with
+   no time. The shared HTTP handler now answers 502 and calls the door's own
+   ledger hook (`call.failed` at the gate, `signal.failed` at the signer); the
+   egress proxy refuses with 502 into its refusal ledger unless the tunnel was
+   already spliced; every server logs an escaped error through the door's
+   logger, with the peer. The proxy also writes the request line it forwards
+   back as Latin-1, the way it read it: UTF-8 turned every raw non-ASCII byte in
+   a path into two.
+3. **An alarm tries a connection that did not happen again, in place.** The
+   investigator's, the pipe's and the judge's alarms posted once, so a moment
+   without a resolver dropped the page and only a later failure sent another.
+   Two more attempts, two seconds apart; an HTTP answer is the channel speaking
+   and is not retried; a timeout is, at the price of a possible duplicate.
+4. **The releasing page says what a rollback does with newer rows,** and a
+   release that changes a schema says it in its tag note. Read from the code for
+   0.8.0 back to 0.7.1: nothing fails to open; a silence scoped to one alert
+   quiets its whole source until it expires.
+
+Fixed while verifying: the forwarder's bind test, changed while clearing a
+CodeQL alert, clashed with a loopback socket, and a loopback socket does not
+stop a wildcard bind with SO_REUSEADDR on macOS — the local gate was red on a
+Mac while CI was green. It now clashes two forwarder binds, which fails on both.
+
+## Why
+
+Each was observed there, not reasoned: an unlisted bot became a to-do twice; a
+query string with raw non-ASCII bytes killed a handler thread with no answer and
+no ledger line; ten resolver misses in eleven days on the same kind of container
+network, every one answered by a resend half a minute later; and a schema change
+whose rollback nobody had written down. The code here had the same shapes. Each
+fix has a test that fails without it.
+
+## Consequences
+
+- A person whose display name has bot as a word of its own is dropped from the
+  watch digest. Nobody's is today; if it ever happens, the pattern is the place
+  to change, not the list.
+- `call.failed` rows can carry `reason: unexpected <Exception>` with a method and
+  path instead of a client and tools; `signal.failed` is a new signer event;
+  `egress.refused` rows can carry code 502 and `unexpected …`. The readers that
+  filter on `signal.signed` or count refusals are unaffected.
+- An alarm whose first attempts miss arrives a few seconds later, and rarely
+  twice.
+- The watch and sidecar changes reach a deployment at its next build from the
+  checkout; the alarm changes in the three services reach the published images
+  at the next release.

deploy/docker-compose.work.yml

@@ -1011,6 +1011,9 @@ services:
       WATCH_DOW: ${WATCH_DOW:-1-5}
       WATCH_EXCLUDE: ${WATCH_EXCLUDE:-}
       WATCH_ME: ${WATCH_ME:-}
+      # Only the bots whose names do not give them away: a sender whose display
+      # name has bot or robot as a word of its own, a CamelCase ...Bot, or 机器人
+      # is dropped without being listed (watch_scan.py, BOT_NAME).
       WATCH_BOTS: ${WATCH_BOTS:-}
       WATCH_JIRA_SCRIPT: /watch/jira_watch.py
       # The digest's byte budget, and it must stay well under

deploy/sidecars/common.py

@@ -29,7 +29,7 @@
 import socketserver
 import threading
 import time
-from http.server import BaseHTTPRequestHandler
+from http.server import BaseHTTPRequestHandler, ThreadingHTTPServer
 from pathlib import Path
 from typing import Any
 
@@ -105,11 +105,27 @@ def pump(a: socket.socket, b: socket.socket, idle_seconds: float) -> None:
         return
 
 
-class Server(socketserver.ThreadingTCPServer):
+class LoggedErrors:
+    """socketserver's own handle_error prints a bare traceback to stderr: no
+    time, no door, no peer. A handler that raised then left a line nobody could
+    place next to the ledger. This sends it through the door's logger instead,
+    which has the time, and names the peer."""
+
+    def handle_error(self, request: Any, client_address: Any) -> None:  # noqa: ARG002 — socketserver's signature
+        handler = getattr(self, "RequestHandlerClass", None)
+        name = getattr(handler, "server_version", "") or getattr(handler, "log_name", "") or "sidecar"
+        logging.getLogger(name).error("unhandled error serving %s", client_address, exc_info=True)
+
+
+class Server(LoggedErrors, socketserver.ThreadingTCPServer):
     allow_reuse_address = True
     daemon_threads = True
 
 
+class HttpServer(LoggedErrors, ThreadingHTTPServer):
+    """The HTTP doors' server (the gate, the signer), with the same error log."""
+
+
 _CONTROL_CHARS = getattr(BaseHTTPRequestHandler, "_control_char_table", None)
 
 
@@ -143,7 +159,40 @@ 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()
+        self._answer_started = False
+        try:
+            super().handle_one_request()
+        except (ConnectionResetError, BrokenPipeError):
+            raise  # nobody to answer; handle() lets these go quietly
+        except Exception as exc:  # noqa: BLE001 — a request that fails is still answered and recorded
+            # Anything a door did not plan for used to end the thread: no answer,
+            # so the caller waited out its own timeout, and no ledger line, so the
+            # record of what was asked had a hole exactly where something odd was
+            # asked. A second deployment running copies of these files found it
+            # with a query string carrying raw non-ASCII bytes.
+            self.close_connection = True
+            logging.getLogger(self.server_version).error(
+                "unexpected failure on %s %s",
+                getattr(self, "command", None) or "-",
+                plain(getattr(self, "path", "") or "")[:80],
+                exc_info=True,
+            )
+            with contextlib.suppress(Exception):
+                self.unexpected(exc)
+            if not self._answer_started:
+                with contextlib.suppress(OSError):
+                    body = json.dumps({"error": f"this door failed on the request: {type(exc).__name__}"})
+                    self._answer(502, body.encode())
+                    self.wfile.flush()
+
+    def send_response(self, code: int, message: str | None = None) -> None:
+        self._answer_started = True
+        super().send_response(code, message)
+
+    def unexpected(self, exc: BaseException) -> None:
+        """The door's own ledger line for a request that failed in a way nobody
+        planned. A door with a ledger overrides this; the log line is written
+        either way."""
 
     def parse_request(self) -> bool:
         self._between_requests = False

deploy/sidecars/gate.py

@@ -78,10 +78,9 @@
 import sys
 import urllib.error
 import urllib.request
-from http.server import ThreadingHTTPServer
 from typing import Any
 
-from common import HttpHandler, Ledger, constant_time_eq
+from common import HttpHandler, HttpServer, Ledger, constant_time_eq, plain
 
 logging.basicConfig(level=logging.INFO, format="%(asctime)s %(levelname)s %(name)s %(message)s")
 logger = logging.getLogger("mcp-gate")
@@ -319,6 +318,14 @@ class Gate(HttpHandler):
     ledger = Ledger("")
 
     # ── who is asking ──
+    def unexpected(self, exc: BaseException) -> None:
+        self.ledger.write(
+            event="call.failed",
+            method=getattr(self, "command", None) or "-",
+            path=plain(getattr(self, "path", "") or "")[:80],
+            reason=f"unexpected {type(exc).__name__}",
+        )
+
     def _caller(self) -> Client | None:
         header = self.headers.get("Authorization", "")
         token = header[7:].strip() if header[:7].lower() == "bearer " else ""
@@ -537,7 +544,7 @@ def redirect_request(self, *args: Any, **kwargs: Any) -> None:  # noqa: D102
         return None
 
 
-def build() -> ThreadingHTTPServer:
+def build() -> HttpServer:
     """The gate, configured from the environment and bound, not yet serving:
     doors.py runs it beside the proxy and the ingress; main() runs it alone."""
     environ = dict(os.environ)
@@ -564,7 +571,7 @@ def host(url: str) -> str:
         len(Gate.clients),
         ", ".join(f"{c.name}({sum(len(t) for t in c.tools.values())})" for c in Gate.clients),
     )
-    return ThreadingHTTPServer(("0.0.0.0", port), Gate)  # noqa: S104 — the container's own network only
+    return HttpServer(("0.0.0.0", port), Gate)  # noqa: S104 — the container's own network only
 
 
 def main() -> int:

deploy/sidecars/proxy.py

@@ -222,11 +222,29 @@ class Handler(socketserver.StreamRequestHandler):
     rbufsize = 0
 
     def handle(self) -> None:
+        self._target = ""
+        self._spliced = False
+        try:
+            self._handle()
+        except (ConnectionResetError, BrokenPipeError):
+            return
+        except Exception as exc:  # noqa: BLE001 — every request leaves a ledger line and gets an answer
+            # Anything but a Refused used to end the thread: no answer, and no
+            # line in the refusal ledger for the one request that did something
+            # odd — a name the resolver cannot even encode, say. Before the
+            # splice it is a refusal like any other; after it, the tunnel was
+            # already the answer, and the log line is what is left to say.
+            logger.error("unexpected failure on %s", self._target or "a request", exc_info=True)
+            if not self._spliced:
+                self._refuse(502, f"unexpected {type(exc).__name__}: {exc}"[:200], self._target or "?")
+
+    def _handle(self) -> None:
         try:
             line = self.rfile.readline(65536).decode("latin-1").strip()
         except OSError:
             return
         parts = line.split()
+        self._target = (parts[1] if len(parts) > 1 else line)[:80]
         if len(parts) < 3:
             self._refuse(400, "not a request line", line[:40])
             return
@@ -263,6 +281,7 @@ def handle(self) -> None:
             more = self.rfile.readline(65536)
             if more in (b"", b"\r\n", b"\n"):
                 break
+        self._spliced = True
         self.wfile.write(b"HTTP/1.1 200 Connection established\r\n\r\n")
         self.wfile.flush()
         logger.info("allowed %s", target[:80])
@@ -301,7 +320,10 @@ def _plain(self, parts: list[str]) -> None:
         # head as the client sent it. Connection: close on both sides — this
         # forwards one request per connection rather than tracking keep-alive
         # state, which is the difference between a boundary and a web server.
-        head = [f"{method} /{path if slash else ''} {parts[2]}".encode(), b"Connection: close"]
+        # Latin-1 both ways: the line was read as Latin-1 above, so encoding it
+        # back the same way hands the upstream the bytes the client sent. UTF-8
+        # here turned every raw non-ASCII byte in a path into two.
+        head = [f"{method} /{path if slash else ''} {parts[2]}".encode("latin-1"), b"Connection: close"]
         while True:
             raw = self.rfile.readline(65536)
             if raw in (b"", b"\r\n", b"\n"):
@@ -310,6 +332,7 @@ def _plain(self, parts: list[str]) -> None:
                 continue
             head.append(raw.rstrip(b"\r\n"))
         logger.info("allowed %s %s:%s", method, host, port)
+        self._spliced = True
         with upstream:
             upstream.sendall(b"\r\n".join(head) + b"\r\n\r\n")
             pump(self.connection, upstream, IDLE_SECONDS)

deploy/sidecars/signer.py

@@ -70,11 +70,10 @@
 import time
 import urllib.error
 import urllib.request
-from http.server import ThreadingHTTPServer
 from pathlib import Path
 from typing import Any
 
-from common import HttpHandler, Ledger, constant_time_eq, sign_timestamped
+from common import HttpHandler, HttpServer, Ledger, constant_time_eq, sign_timestamped
 
 logging.basicConfig(level=logging.INFO, format="%(asctime)s %(levelname)s %(name)s %(message)s")
 logger = logging.getLogger("watch-signer")
@@ -291,6 +290,9 @@ class Signer(HttpHandler):
     ledger = Ledger("")
     counter = Counter()
 
+    def unexpected(self, exc: BaseException) -> None:
+        self.ledger.write(event="signal.failed", why=f"unexpected {type(exc).__name__}")
+
     def _say(self, status: int, payload: dict[str, Any]) -> None:
         self._answer(status, json.dumps(payload, ensure_ascii=False).encode())
 
@@ -408,7 +410,7 @@ def main() -> int:
     Signer.counter = Counter()
     port = int(os.environ.get("WATCH_SIGNER_PORT", "8099"))
     logger.info("up on :%d, signing for %s, ceiling %d per round", port, Signer.door, PER_ROUND_MAX)
-    ThreadingHTTPServer(("0.0.0.0", port), Signer).serve_forever()  # noqa: S104 — the container's own network only
+    HttpServer(("0.0.0.0", port), Signer).serve_forever()  # noqa: S104 — the container's own network only
     return 0
 
 

deploy/sidecars/tests/test_allowlist.py

@@ -275,3 +275,73 @@ def handle(self) -> None:
         for server in (upstream, gateway):
             server.shutdown()
             server.server_close()
+
+
+def test_a_failure_nobody_planned_for_is_refused_and_recorded(tmp_path, monkeypatch) -> None:
+    """Anything but a Refused used to end the thread: no answer, no ledger line."""
+    import json
+    import socket
+    import threading
+
+    ledger = tmp_path / "egress.jsonl"
+    proxy = _with("example.com", ledger=str(ledger))
+
+    def boom(host, port):
+        raise RuntimeError("nobody planned for this")
+
+    monkeypatch.setattr(proxy, "decide", boom)
+    gateway = proxy.Server(("127.0.0.1", 0), proxy.Handler)
+    threading.Thread(target=gateway.serve_forever, kwargs={"poll_interval": 0.02}, daemon=True).start()
+    try:
+        with socket.create_connection(("127.0.0.1", gateway.server_address[1]), timeout=5) as client:
+            client.sendall(b"CONNECT example.com:443 HTTP/1.1\r\nHost: example.com\r\n\r\n")
+            first = client.recv(200).decode("latin-1").splitlines()[0]
+    finally:
+        gateway.shutdown()
+        gateway.server_close()
+    assert first.startswith("HTTP/1.1 502")
+    row = json.loads(ledger.read_text(encoding="utf-8").splitlines()[-1])
+    assert row["event"] == "egress.refused" and row["target"] == "example.com:443" and row["code"] == 502
+    assert "RuntimeError" in row["why"]
+
+
+def test_a_plain_request_line_reaches_the_peer_byte_for_byte() -> None:
+    """The line is read as Latin-1, so it must leave as Latin-1: a client that
+    does not percent-encode sends raw UTF-8, and UTF-8 on the way out doubled it."""
+    import socket
+    import socketserver
+    import threading
+
+    seen: list[bytes] = []
+
+    class Capture(socketserver.BaseRequestHandler):
+        def handle(self) -> None:
+            self.request.settimeout(5)
+            data = b""
+            while b"\r\n\r\n" not in data:
+                chunk = self.request.recv(4096)
+                if not chunk:
+                    break
+                data += chunk
+            seen.append(data.split(b"\r\n", 1)[0])
+            self.request.sendall(b"HTTP/1.1 200 OK\r\nContent-Length: 0\r\nConnection: close\r\n\r\n")
+
+    upstream = socketserver.TCPServer(("127.0.0.1", 0), Capture)
+    port = upstream.server_address[1]
+    proxy = _with("", str(port), internal="127.0.0.1")
+    gateway = proxy.Server(("127.0.0.1", 0), proxy.Handler)
+    for server in (upstream, gateway):
+        threading.Thread(target=server.serve_forever, kwargs={"poll_interval": 0.02}, daemon=True).start()
+    path = "/trace/告警?q=磁盘".encode()
+    try:
+        with socket.create_connection(("127.0.0.1", gateway.server_address[1]), timeout=5) as client:
+            client.sendall(b"GET http://127.0.0.1:%d%s HTTP/1.1\r\nHost: x\r\n\r\n" % (port, path))
+            answer = b""
+            while chunk := client.recv(4096):
+                answer += chunk
+    finally:
+        for server in (upstream, gateway):
+            server.shutdown()
+            server.server_close()
+    assert answer.startswith(b"HTTP/1.1 200"), answer[:80]
+    assert seen == [b"GET " + path + b" HTTP/1.1"]