fix(api): speak the real TRMNL device protocol

README.md

@@ -261,12 +261,32 @@ The CLI helps you:
 |----------|-------------|
 | `GET /api/display` | Main TRMNL endpoint - returns current image |
 | `POST /api/log` | Device event logging |
-| `POST /api/battery` | Battery telemetry |
+| `POST /api/battery` | Battery telemetry (MunichGlance extension, not part of the TRMNL protocol) |
 | `GET /api/health` | Health check |
 | `GET /settings` | Current configuration |
 | `GET /settings/plugins` | List registered plugins |
 | `GET /docs` | OpenAPI documentation |
 
+### Device protocol notes
+
+The firmware identifies itself with the **`ID`** header (its MAC address) and
+piggybacks telemetry — `Battery-Voltage`, `RSSI`, `FW-Version`, `Refresh-Rate` —
+onto every request. Requests without `ID` are served normally but are not
+registered as devices. `X-Device-MAC` and `?mac=` work as aliases for custom
+clients.
+
+`POST /api/log` accepts the current firmware payload `{"logs": [...]}`, the older
+`{"log": {"logs_array": [...]}}`, and a flat legacy form. Anything else is answered
+`200 OK` and logged at WARNING with the raw body, so unknown shapes are visible
+instead of silently dropped.
+
+Battery readings are taken from the telemetry headers and from log entries, at most
+one sample per device per 15 minutes. `POST /api/battery` stays available for manual
+reporting; stock firmware never calls it.
+
+Set `LOG_LEVEL=DEBUG` (or `server.log_level` in the config) for per-request device
+detail.
+
 ## Architecture
 
 ```

config/app-config.yaml

@@ -23,6 +23,11 @@ server:
   # Enable debug mode for development (enables detailed error messages)
   debug: false
 
+  # Root log level: DEBUG, INFO, WARNING, ERROR
+  # DEBUG adds per-request device detail (identification, telemetry, payloads).
+  # The LOG_LEVEL environment variable overrides this.
+  log_level: "INFO"
+
   # Timezone for displaying times (IANA timezone format)
   # Examples: Europe/Berlin, America/New_York, Asia/Tokyo
   timezone: "Europe/Berlin"

tests/test_device_api.py

@@ -0,0 +1,272 @@
+"""Tests for the TRMNL device protocol handling in /api.
+
+These cover the two regressions that made the server silently lose all device
+data: the MAC arriving in the ``ID`` header (not ``X-Device-MAC``), and the
+firmware's ``{"logs": [...]}`` log payload.
+
+Assertions read the SQLite file directly rather than through the async session:
+the app owns the event loop the async engine is bound to.
+"""
+
+import sqlite3
+
+import pytest
+from fastapi import FastAPI
+from fastapi.testclient import TestClient
+from sqlalchemy import create_engine
+
+from trmnl_server import database
+from trmnl_server.config import ServerConfig
+from trmnl_server.database import Base
+from trmnl_server.routes import api
+
+DEVICE_MAC = "AA:BB:CC:DD:EE:FF"
+NORMALIZED_MAC = "AABBCCDDEEFF"
+
+
+@pytest.fixture
+def db_path(tmp_path, monkeypatch):
+    """Point the global config at a throwaway database and create the schema."""
+    config = ServerConfig(project_root=tmp_path)
+    config.ensure_directories()
+    monkeypatch.setattr("trmnl_server.config._config", config, raising=False)
+
+    # The async engine is a module-level singleton; drop it so it is rebuilt
+    # against this database, inside the app's own event loop.
+    monkeypatch.setattr(database, "_engine", None)
+    monkeypatch.setattr(database, "_session_factory", None)
+
+    sync_engine = create_engine(f"sqlite:///{config.db_path}")
+    Base.metadata.create_all(sync_engine)
+    sync_engine.dispose()
+
+    return config.db_path
+
+
+@pytest.fixture
+def client(db_path):
+    """A client for the /api router only (no lifespan, no scheduler, no plugins)."""
+    app = FastAPI()
+    app.include_router(api.router)
+    with TestClient(app) as test_client:
+        yield test_client
+
+
+def rows(db_path, table: str) -> list[sqlite3.Row]:
+    """All rows of a table, oldest first."""
+    connection = sqlite3.connect(db_path)
+    connection.row_factory = sqlite3.Row
+    try:
+        return list(connection.execute(f"SELECT * FROM {table} ORDER BY id"))
+    finally:
+        connection.close()
+
+
+def test_mac_from_id_header(client, db_path):
+    """The stock firmware identifies itself with the ID header."""
+    response = client.post(
+        "/api/log",
+        headers={"ID": DEVICE_MAC},
+        json={"logs": [{"message": "boot", "level": "info"}]},
+    )
+
+    assert response.status_code == 200
+    assert [r["mac_address"] for r in rows(db_path, "devices")] == [NORMALIZED_MAC]
+
+
+def test_x_device_mac_header_still_works(client, db_path):
+    """The legacy header stays supported for custom clients."""
+    client.post(
+        "/api/log",
+        headers={"X-Device-MAC": DEVICE_MAC},
+        json={"logs": [{"message": "boot"}]},
+    )
+
+    assert [r["mac_address"] for r in rows(db_path, "devices")] == [NORMALIZED_MAC]
+
+
+def test_unidentified_device_is_not_registered(client, db_path):
+    """No ID header must not mint a throwaway device row on every request."""
+    for _ in range(3):
+        client.post("/api/log", json={"logs": [{"message": "hello"}]})
+
+    assert rows(db_path, "devices") == []
+    # The log entries are still kept, under the shared UNKNOWN bucket.
+    device_logs = rows(db_path, "device_logs")
+    assert len(device_logs) == 3
+    assert {r["device_mac"] for r in device_logs} == {api.UNKNOWN_DEVICE_MAC}
+
+
+def test_terminus_log_payload_is_stored(client, db_path):
+    """{"logs": [...]} is the shape the current firmware posts."""
+    response = client.post(
+        "/api/log",
+        headers={"ID": DEVICE_MAC},
+        json={
+            "logs": [
+                {
+                    "id": 1,
+                    "message": "display refresh",
+                    "level": "info",
+                    "source_path": "src/display.cpp",
+                    "source_line": 597,
+                    "firmware_version": "1.7.8",
+                    "battery_voltage": 4.11,
+                    "wifi_signal": -69,
+                    "free_heap_size": 160656,
+                }
+            ]
+        },
+    )
+
+    assert response.status_code == 200
+    device_logs = rows(db_path, "device_logs")
+    assert len(device_logs) == 1
+    entry = device_logs[0]
+    assert entry["device_mac"] == NORMALIZED_MAC
+    assert entry["message"] == "display refresh"
+    assert entry["log_type"] == "info"
+    assert entry["battery_voltage"] == pytest.approx(4.11)
+    assert entry["wifi_rssi"] == -69
+    assert entry["firmware_version"] == "1.7.8"
+    assert entry["free_heap"] == 160656
+
+
+def test_battery_reading_extracted_from_log_entry(client, db_path):
+    """Battery telemetry rides along with the logs - there is no battery endpoint."""
+    client.post(
+        "/api/log",
+        headers={"ID": DEVICE_MAC},
+        json={"logs": [{"message": "wake", "battery_voltage": 4.11, "wifi_signal": -69}]},
+    )
+
+    readings = rows(db_path, "battery_readings")
+    assert len(readings) == 1
+    assert readings[0]["device_mac"] == NORMALIZED_MAC
+    assert readings[0]["voltage"] == pytest.approx(4.11)
+    assert readings[0]["rssi"] == -69
+
+
+def test_battery_sampling_is_throttled(client, db_path):
+    """A device polls every couple of minutes; only the first sample is kept."""
+    for _ in range(3):
+        client.post(
+            "/api/log",
+            headers={"ID": DEVICE_MAC},
+            json={"logs": [{"message": "wake", "battery_voltage": 4.11}]},
+        )
+
+    assert len(rows(db_path, "battery_readings")) == 1
+
+
+def test_legacy_logs_array_payload_still_works(client, db_path):
+    """Older firmware format must keep working."""
+    client.post(
+        "/api/log",
+        headers={"ID": DEVICE_MAC},
+        json={
+            "log": {
+                "logs_array": [
+                    {
+                        "log_message": "sleep",
+                        "log_sourcefile": "main.cpp",
+                        "device_status_stamp": {
+                            "current_fw_version": "1.5.2",
+                            "battery_voltage": 3.9,
+                            "wifi_rssi_level": -55,
+                        },
+                    }
+                ]
+            }
+        },
+    )
+
+    device_logs = rows(db_path, "device_logs")
+    assert len(device_logs) == 1
+    assert device_logs[0]["message"] == "sleep"
+    assert device_logs[0]["firmware_version"] == "1.5.2"
+    assert len(rows(db_path, "battery_readings")) == 1
+
+
+def test_unrecognized_payload_is_logged_not_dropped_silently(client, db_path, caplog):
+    """An unknown shape must be visible in the logs, with the payload."""
+    with caplog.at_level("WARNING"):
+        response = client.post(
+            "/api/log",
+            headers={"ID": DEVICE_MAC},
+            json={"something": "entirely different"},
+        )
+
+    assert response.status_code == 200
+    assert rows(db_path, "device_logs") == []
+    messages = [record.getMessage() for record in caplog.records]
+    assert any("unrecognized payload" in message for message in messages)
+    assert any("entirely different" in message for message in messages)
+
+
+def test_telemetry_headers_recorded(client, db_path):
+    """Battery/RSSI/firmware headers are the firmware's main telemetry channel."""
+    client.post(
+        "/api/log",
+        headers={
+            "ID": DEVICE_MAC,
+            "Battery-Voltage": "4.05",
+            "RSSI": "-71",
+            "FW-Version": "2.1.3",
+            "Refresh-Rate": "1800",
+        },
+        json={"logs": [{"message": "poll"}]},
+    )
+
+    device = rows(db_path, "devices")[0]
+    assert device["firmware_version"] == "2.1.3"
+    assert device["refresh_rate"] == 1800
+
+    reading = rows(db_path, "battery_readings")[0]
+    assert reading["voltage"] == pytest.approx(4.05)
+    assert reading["rssi"] == -71
+
+
+def test_display_records_device_and_telemetry(client, db_path, monkeypatch):
+    """/api/display is the highest-traffic endpoint and the main telemetry channel.
+
+    No plugin is registered here, so the handler takes its error branch — the point
+    is that the device is recorded before any early return.
+    """
+    monkeypatch.setattr(api, "get_primary_plugin_name", lambda: None)
+
+    response = client.get(
+        "/api/display",
+        headers={"ID": DEVICE_MAC, "Battery-Voltage": "4.2", "RSSI": "-58"},
+    )
+
+    assert response.status_code == 200
+    assert [r["mac_address"] for r in rows(db_path, "devices")] == [NORMALIZED_MAC]
+    reading = rows(db_path, "battery_readings")[0]
+    assert reading["voltage"] == pytest.approx(4.2)
+    assert reading["rssi"] == -58
+
+
+def test_display_without_id_header_registers_nothing(db_path, client, monkeypatch):
+    """The old behaviour created one device row per anonymous poll."""
+    monkeypatch.setattr(api, "get_primary_plugin_name", lambda: None)
+
+    for _ in range(5):
+        client.get("/api/display")
+
+    assert rows(db_path, "devices") == []
+
+
+def test_battery_endpoint_still_accepts_manual_readings(client, db_path):
+    """The non-standard /api/battery endpoint stays usable for custom clients."""
+    response = client.post(
+        "/api/battery",
+        headers={"ID": DEVICE_MAC},
+        json={"voltage": 3.8, "rssi": -60},
+    )
+
+    assert response.status_code == 200
+    readings = rows(db_path, "battery_readings")
+    assert len(readings) == 1
+    assert readings[0]["device_mac"] == NORMALIZED_MAC
+    assert readings[0]["voltage"] == pytest.approx(3.8)

trmnl_server/config.py

@@ -24,6 +24,7 @@ class ServerConfig:
     host: str = "0.0.0.0"
     port: int = 4567
     debug: bool = False
+    log_level: str = "INFO"  # DEBUG surfaces per-request device/telemetry detail
 
     # Paths
     project_root: Path = field(default_factory=_get_project_root)
@@ -101,6 +102,7 @@ def from_yaml(cls, config_file: str | None = None) -> "ServerConfig":
             host=loader.get("server", "host", "0.0.0.0"),
             port=int(loader.get("server", "port", 4567)),
             debug=debug_val,
+            log_level=str(loader.get("server", "log_level", "INFO")),
             refresh_time=int(loader.get("device", "refresh_time", 120)),
             setup_api_key=loader.get("device", "api_key", ""),
             setup_friendly_id=loader.get("device", "friendly_id", "munich-glance"),

trmnl_server/main.py

@@ -1,6 +1,7 @@
 """FastAPI application for TRMNL BYOS server."""
 
 import logging
+import os
 from contextlib import asynccontextmanager
 
 from fastapi import FastAPI, Request
@@ -15,11 +16,29 @@
 from trmnl_server.services.plugins import register_plugins, schedule_plugins
 from trmnl_server.services.scheduler import start_scheduler, stop_scheduler
 
-# Configure logging
-logging.basicConfig(
-    level=logging.INFO,
-    format="%(asctime)s - %(name)s - %(levelname)s - %(message)s",
-)
+
+def _configure_logging() -> None:
+    """Set the root log level from LOG_LEVEL or server.log_level (default INFO).
+
+    The device handlers log request detail at DEBUG. With the level hardcoded, the
+    only way to see any of it in a container was to rebuild the image.
+    """
+    level_name = os.getenv("LOG_LEVEL")
+    if not level_name:
+        try:
+            level_name = get_config().log_level
+        except Exception:  # pragma: no cover - config problems surface later
+            level_name = "INFO"
+
+    level = getattr(logging, level_name.strip().upper(), logging.INFO)
+    logging.basicConfig(
+        level=level,
+        format="%(asctime)s - %(name)s - %(levelname)s - %(message)s",
+    )
+    logging.getLogger().setLevel(level)
+
+
+_configure_logging()
 logger = logging.getLogger(__name__)