fix: Rettungsstation loggt auch abgelehnte Methoden und Protokollfehler

do_POST (und PUT/DELETE/HEAD) riefen reject() auf, ohne eine Logzeile zu
schreiben, und das ueberschriebene log_message() legte damit unbeabsichtigt
auch log_error() lahm (BaseHTTPRequestHandler ruft es standardmaessig auf,
z.B. bei einer kaputten Request-Zeile oder einem Timeout, bevor ueberhaupt
ein Handler wie do_GET erreicht wird). Fuer das einzige Diagnosewerkzeug im
Rettungsfall darf keine Anfrage stumm bleiben.

do_POST loggt jetzt wie do_GET explizit, und log_error() ist separat
ueberschrieben statt implizit mit log_message() stillgelegt zu werden.

Die neuen Tests fuer den 405-Fall lesen den rohen Datei-Deskriptor des
Server-Prozesses statt ueber TextIOWrapper.readline() zu gehen - Letzteres
kann mehr Zeilen aus der Pipe in den eigenen Puffer lesen, als es
zurueckgibt, was select() auf dem naechsten Datei-Deskriptor faelschlich
"nichts da" melden liess. Der Test fuer die kaputte Request-Zeile ruft
log_error() direkt auf: ein echter kaputter Rohsocket wird in dieser
Sandbox von einer Netzwerkschicht abgefangen, bevor er den Server erreicht
(sichtbar an einem untergeschobenen "Server: aiohttp"-Header).

Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>

tools/station/server.py

@@ -138,12 +138,26 @@ class Handler(BaseHTTPRequestHandler):
     def log_message(self, fmt: str, *args) -> None:  # noqa: D102 - quieter default log
         pass
 
+    def log_error(self, fmt: str, *args) -> None:
+        # BaseHTTPRequestHandler.log_error() calls log_message() by default, which we
+        # silence above in favour of our own log() calls - but that also silences it for
+        # requests that never reach do_GET/do_POST (a malformed request line, a client
+        # timeout mid-request). The station is the only diagnostic tool available during a
+        # rescue, so those cases must still produce a line instead of nothing.
+        try:
+            client = self.client_address[0]
+        except (AttributeError, IndexError):
+            client = "?"
+        print(f"{now_iso()} {client} ERROR {fmt % args}", flush=True)
+
     def log(self, status: int, nbytes: int, started: float) -> None:
         print(f"{now_iso()} {self.client_address[0]} {self.path} {status} "
               f"{nbytes}B {time.monotonic() - started:.1f}s", flush=True)
 
     def do_POST(self) -> None:
+        started = time.monotonic()
         self.reject(405, "method not allowed")
+        self.log(405, 0, started)
 
     do_PUT = do_DELETE = do_HEAD = do_POST
 

tools/station/tests/test_server.py

@@ -2,6 +2,7 @@ import hashlib
 import http.client
 import json
 import os
+import select
 import socket
 import stat
 import subprocess
@@ -92,6 +93,44 @@ class Station:
         self.proc.terminate()
         self.proc.wait(timeout=5)
 
+    def wait_for_log_line(self, contains, timeout=3.0):
+        """Reads the server's merged stdout/stderr (see __init__) until a line containing
+        `contains` shows up, skipping unrelated lines (e.g. the startup banner) - used to
+        check that a request actually produced a log line (F3: every request must,
+        including rejected ones and errors the base handler catches before routing).
+
+        Reads the raw fd directly with os.read() instead of self.proc.stdout.readline():
+        readline() goes through TextIOWrapper's internal BufferedReader, whose underlying
+        read() can slurp everything currently sitting in the pipe (banner *and* the log
+        line we're waiting for) into its own buffer on the very first call, while only
+        handing back the first line. select() then reports the fd as not-readable on the
+        next iteration - the data isn't gone, it is just buffered somewhere select() can't
+        see - and a fixed-size test timeout would flake on exactly the line it's checking
+        for.
+        """
+        fd = self.proc.stdout.fileno()
+        buf = getattr(self, "_log_buf", "")
+        deadline = time.time() + timeout
+        while True:
+            while "\n" in buf:
+                line, buf = buf.split("\n", 1)
+                self._log_buf = buf
+                if contains in line:
+                    return line + "\n"
+            remaining = deadline - time.time()
+            if remaining <= 0:
+                self._log_buf = buf
+                return None
+            r, _, _ = select.select([fd], [], [], remaining)
+            if not r:
+                self._log_buf = buf
+                return None
+            chunk = os.read(fd, 65536)
+            if not chunk:
+                self._log_buf = buf
+                return None
+            buf += chunk.decode("utf-8", "replace")
+
 
 @pytest.fixture
 def station(tmp_path):
@@ -139,6 +178,43 @@ def test_other_methods_are_405(station):
     assert c.getresponse().status == 405
 
 
+def test_rejected_method_produces_a_log_line(station):
+    """F3: do_POST (and PUT/DELETE/HEAD) used to call reject() without logging anything -
+    the station is the only diagnostic tool during a rescue, and the spec requires a line
+    per request, rejections included."""
+    c = station.conn()
+    c.request("POST", "/ninlight_evk_ota.img", body=b"")
+    assert c.getresponse().status == 405
+    line = station.wait_for_log_line(" 405 ")
+    assert line is not None, "kein Log-Eintrag fuer die abgelehnte POST-Anfrage"
+    assert "/ninlight_evk_ota.img" in line
+
+
+def test_log_error_is_not_silenced_by_log_message(capsys):
+    """F3: BaseHTTPRequestHandler.log_error() calls log_message() by default (used e.g. for
+    a malformed request line or a client timeout, cases that never reach do_GET/do_POST).
+    server.py silences log_message() in favour of its own per-request log() calls - which
+    used to silence log_error() right along with it, since it wasn't overridden separately.
+    This exercises Handler.log_error() directly rather than over a raw socket: this
+    sandbox's network layer intercepts/rewrites malformed non-HTTP payloads before they
+    reach the server (observed via a spoofed 'Server: aiohttp' response), which makes a
+    genuine malformed-request-line test unreliable here."""
+    import importlib.util
+
+    spec = importlib.util.spec_from_file_location("ninlight_station_server", SERVER)
+    module = importlib.util.module_from_spec(spec)
+    spec.loader.exec_module(module)
+
+    class _Stub:
+        client_address = ("203.0.113.5", 54321)
+
+    module.Handler.log_error(_Stub(), "code %d, message %s", 400, "Bad request version")
+    out = capsys.readouterr().out
+    assert "ERROR" in out
+    assert "203.0.113.5" in out
+    assert "code 400, message Bad request version" in out
+
+
 def test_range_request_returns_206_and_the_right_slice(station):
     data = make_image(station.image_dir / "ninlight_e27_rgb_ota.img", "e27_rgb", "2.0.0", b"abc" * 2000)
     c = station.conn()