Attribute log entries to the client IP

Entries gain an "ip" field, rendered between the time and the source as asked.
The buffer is shared by every viewer, so without attribution a log of keypresses
from two people is unreadable.

Resolving the address matters more than it looks: behind the nginx reverse proxy
REMOTE_ADDR is always 127.0.0.1, so the first hop of X-Forwarded-For is what
identifies the real client. Only the first entry is trusted -- the rest of the
chain is set by the caller and a test covers that.

Power actions are logged at the route rather than in the supervisor, which has no
request context, so "who powered it off" is recorded.

Entries with no client behind them keep ip=None and render as "-": firmware serial
and QEMU stderr are not caused by a request.

The sharing and history the user asked for already worked and needed no change --
verified rather than assumed. The front end starts at logCursor=0, so a page
opened now receives the full buffer, including lines produced before it connected
and lines from other people. Confirmed live through the proxy: a new reader saw
entries attributed to 172.21.91.140, fd3c:3f9b:6424:2::5 and "-".

tools/test_webui.py

@@ -607,5 +607,73 @@ class TestIdleKeepalive(unittest.TestCase):
         self.assertGreater(webui.IDLE_FRAME_INTERVAL_S, 1.0 / webui.TARGET_FPS)
 
 
+class TestClientIpInLogs(unittest.TestCase):
+    """Entries carry the client IP, so a shared log says who did what."""
+
+    def test_key_entry_records_the_client_ip(self):
+        client, sup, http = make_supervised()
+        log = http.application.config["LOG"]
+        http.post("/api/key", json={"key": "MENU", "hold_ms": 60},
+                  environ_overrides={"REMOTE_ADDR": "172.21.91.137"})
+        entries = [e for e in log.entries() if e["source"] == "key"]
+        self.assertTrue(entries)
+        self.assertEqual(entries[-1]["ip"], "172.21.91.137")
+
+    def test_power_entry_records_the_client_ip(self):
+        client, sup, http = make_supervised()
+        log = http.application.config["LOG"]
+        http.post("/api/power/reset",
+                  environ_overrides={"REMOTE_ADDR": "172.21.91.137"})
+        entries = [e for e in log.entries() if e["source"] == "power"]
+        self.assertTrue(entries)
+        self.assertEqual(entries[-1]["ip"], "172.21.91.137")
+
+    def test_ipv6_is_recorded(self):
+        client, sup, http = make_supervised()
+        log = http.application.config["LOG"]
+        http.post("/api/key", json={"key": "UP", "hold_ms": 60},
+                  environ_overrides={"REMOTE_ADDR": "fd3c:3f9b:6424:2::99"})
+        entries = [e for e in log.entries() if e["source"] == "key"]
+        self.assertEqual(entries[-1]["ip"], "fd3c:3f9b:6424:2::99")
+
+    def test_x_forwarded_for_is_preferred_behind_a_proxy(self):
+        """nginx reverse-proxies this, so REMOTE_ADDR is always 127.0.0.1."""
+        client, sup, http = make_supervised()
+        log = http.application.config["LOG"]
+        http.post("/api/key", json={"key": "UP", "hold_ms": 60},
+                  environ_overrides={"REMOTE_ADDR": "127.0.0.1",
+                                     "HTTP_X_FORWARDED_FOR": "172.21.91.137"})
+        entries = [e for e in log.entries() if e["source"] == "key"]
+        self.assertEqual(entries[-1]["ip"], "172.21.91.137")
+
+    def test_only_the_first_hop_of_x_forwarded_for_is_used(self):
+        """The rest of the chain is attacker-controlled and must be ignored."""
+        client, sup, http = make_supervised()
+        log = http.application.config["LOG"]
+        http.post("/api/key", json={"key": "UP", "hold_ms": 60},
+                  environ_overrides={
+                      "REMOTE_ADDR": "127.0.0.1",
+                      "HTTP_X_FORWARDED_FOR": "172.21.91.137, 10.0.0.1"})
+        entries = [e for e in log.entries() if e["source"] == "key"]
+        self.assertEqual(entries[-1]["ip"], "172.21.91.137")
+
+    def test_entries_without_a_request_have_no_ip(self):
+        """Firmware serial and qemu output come from no client at all."""
+        from uvk5_logs import LogBuffer
+        log = LogBuffer()
+        log.add("serial", "boot banner")
+        self.assertIsNone(log.entries()[-1]["ip"])
+
+    def test_page_renders_the_ip_between_time_and_source(self):
+        _, http = make_app()
+        body = http.get("/").get_data(as_text=True)
+        # e.time + ip + source, in that order
+        line = [l for l in body.splitlines() if "e.source" in l and "e.time" in l]
+        self.assertTrue(line, "log line template not found")
+        tmpl = line[0]
+        self.assertLess(tmpl.index("e.time"), tmpl.index("ip"))
+        self.assertLess(tmpl.index("ip"), tmpl.index("e.source"))
+
+
 if __name__ == "__main__":
     unittest.main()

tools/uvk5_logs.py

@@ -22,12 +22,19 @@ class LogBuffer:
         self._lock = threading.Lock()
         self._seq = 0
 
-    def add(self, source: str, text: str):
+    def add(self, source: str, text: str, ip: str = None):
+        """Record one line. `ip` identifies the client that caused it.
+
+        The buffer is shared by every viewer, so without an attributed IP a log of
+        keypresses from two people is unreadable. Entries with no client behind
+        them -- firmware serial, QEMU stderr -- carry None.
+        """
         with self._lock:
             self._seq += 1
             self._entries.append({
                 "seq": self._seq,
                 "time": time.strftime("%H:%M:%S"),
+                "ip": ip,
                 "source": source,
                 "text": text,
             })

tools/webui.py

@@ -124,6 +124,20 @@ def create_app(client, frame_addr: int, status_addr: int, scale: int = 4,
     app.config["PUMP"] = pump
     app.config["SUPERVISOR"] = supervisor
 
+    def client_ip():
+        """The address of whoever made this request.
+
+        Behind the nginx reverse proxy REMOTE_ADDR is always 127.0.0.1, so the
+        first hop of X-Forwarded-For is what identifies the real client. Only the
+        first entry is trusted: the rest of the chain can be set by the caller.
+        """
+        forwarded = request.headers.get("X-Forwarded-For", "")
+        if forwarded:
+            first = forwarded.split(",")[0].strip()
+            if first:
+                return first
+        return request.remote_addr
+
     def active_client():
         """The live QMP client, or None when the emulator is off.
 
@@ -179,6 +193,10 @@ def create_app(client, frame_addr: int, status_addr: int, scale: int = 4,
                       "so it will not stop it. Restart without --attach to "
                       "manage the process here."), 409
 
+        # Attribute the action here: the supervisor has no request context, and on
+        # a shared log "who powered it off" is the useful part.
+        log.add("power", f"{action} requested", ip=client_ip())
+
         {"on": supervisor.power_on,
          "off": supervisor.power_off,
          "reset": supervisor.reset,
@@ -200,7 +218,8 @@ def create_app(client, frame_addr: int, status_addr: int, scale: int = 4,
         if not is_valid(key):
             # Log refusals too: a silently dropped key is indistinguishable from
             # a dead button in the browser.
-            log.add("key", f"{body.get('key')!r} rejected: not a key on this model")
+            log.add("key", f"{body.get('key')!r} rejected: not a key on this model",
+                    ip=client_ip())
             return jsonify(error=f"unknown key {body.get('key')!r}",
                            valid=list(KEYS)), 400
         if action not in ("down", "up", "tap"):
@@ -222,10 +241,10 @@ def create_app(client, frame_addr: int, status_addr: int, scale: int = 4,
 
         try:
             if action == "down":
-                log.add("key", f"{key} down")
+                log.add("key", f"{key} down", ip=client_ip())
                 set_press(key)
             elif action == "up":
-                log.add("key", f"{key} up")
+                log.add("key", f"{key} up", ip=client_ip())
                 set_press("")
             else:
                 # Label by what the FIRMWARE will conclude, so the log says what
@@ -233,14 +252,14 @@ def create_app(client, frame_addr: int, status_addr: int, scale: int = 4,
                 # not the UI's hold threshold -- conflating the two is what caused
                 # the tap+held double send in the first place.
                 kind = "held" if hold_ms >= FIRMWARE_HELD_MS else "tap"
-                log.add("key", f"{key} {kind} {hold_ms}ms")
+                log.add("key", f"{key} {kind} {hold_ms}ms", ip=client_ip())
                 # Hold here, locally. See the note on TAP_MS: doing this as two
                 # requests puts the network round trip inside the press duration.
                 set_press(key)
                 time.sleep(hold_ms / 1000)
                 set_press("")
         except LookupError:
-            log.add("key", f"{key} ignored: emulator is off")
+            log.add("key", f"{key} ignored: emulator is off", ip=client_ip())
             return jsonify(error="emulator is off; press On first"), 409
         return jsonify(ok=True, key=key, action=action, hold_ms=hold_ms)
 
@@ -548,7 +567,13 @@ async function pollLogs() {{
       pre.scrollHeight - pre.scrollTop - pre.clientHeight < 24;
 
     for (const e of j.entries) {{
-      pre.textContent += e.time + ' [' + e.source + '] ' + e.text + '\\n';
+      // IP sits between the time and the source. The log is shared by everyone
+      // who opens the page, so attribution is what makes it readable when two
+      // people are pressing keys. Entries with no client behind them -- firmware
+      // serial, qemu output -- show a dash.
+      const ip = e.ip ? e.ip : '-';
+      pre.textContent += e.time + ' ' + ip + ' [' + e.source + '] '
+                       + e.text + '\\n';
     }}
     const lines = pre.textContent.split('\\n');
     if (lines.length > MAX_LOG_LINES) {{