diff --git a/tools/station/server.py b/tools/station/server.py index 849b0a9..e941fd3 100755 --- a/tools/station/server.py +++ b/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 diff --git a/tools/station/tests/test_server.py b/tools/station/tests/test_server.py index 3196c60..dbda832 100644 --- a/tools/station/tests/test_server.py +++ b/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()