From 4ce7c87907cf46824f37745cc0dcdaecc6eface3 Mon Sep 17 00:00:00 2001 From: des Date: Wed, 5 Aug 2026 09:06:09 +0200 Subject: [PATCH] fix(api): speak the real TRMNL device protocol MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The server implemented a protocol the firmware does not use, so every piece of device data was lost while the endpoints answered 200 OK. In production this showed up as 4740 rows in `devices` (all `UNKNOWN-`, one per poll for 17 days), an empty `device_logs` after thousands of accepted `POST /api/log`, and an empty `battery_readings`. Three causes, all fixed here: * Identification: the firmware sends its MAC in the `ID` header, not `X-Device-MAC`. `_get_device_mac` now reads `ID` first and returns None for unidentified callers instead of minting a random `UNKNOWN-` identity — that fallback was what registered a new device on every request. * Log payload: current firmware posts `{"logs": [...]}` (usetrmnl/terminus doc/api.adoc). Only `{"log": {"logs_array": [...]}}` was handled, so real payloads fell through to a silent debug-level "unknown format" branch. Both shapes are now stored, and an unrecognized body is logged at WARNING with its content. * Battery: the TRMNL protocol has no battery endpoint. Devices report voltage, RSSI and firmware version in request headers and inside log entries, so telemetry is read from there, throttled to one sample per device per 15 min. `POST /api/battery` stays for manual reporting. Also: `last_seen` was written in local time while the DB defaults are UTC, skewing the two by the server's offset; log level is now configurable via `LOG_LEVEL` / `server.log_level`, since the handler diagnostics are DEBUG and the level was hardcoded to INFO. Co-Authored-By: Claude Opus 5 (1M context) --- README.md | 22 ++- config/app-config.yaml | 5 + tests/test_device_api.py | 272 +++++++++++++++++++++++++++++++ trmnl_server/config.py | 2 + trmnl_server/main.py | 29 +++- trmnl_server/routes/api.py | 323 ++++++++++++++++++++++++++++++------- 6 files changed, 593 insertions(+), 60 deletions(-) create mode 100644 tests/test_device_api.py diff --git a/README.md b/README.md index 2eb98fe..377277f 100644 --- a/README.md +++ b/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 ``` diff --git a/config/app-config.yaml b/config/app-config.yaml index e10c54d..abfc04a 100644 --- a/config/app-config.yaml +++ b/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" diff --git a/tests/test_device_api.py b/tests/test_device_api.py new file mode 100644 index 0000000..813876f --- /dev/null +++ b/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) diff --git a/trmnl_server/config.py b/trmnl_server/config.py index 5c11ad5..cb93d86 100644 --- a/trmnl_server/config.py +++ b/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"), diff --git a/trmnl_server/main.py b/trmnl_server/main.py index 61de155..2a69d18 100644 --- a/trmnl_server/main.py +++ b/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__) diff --git a/trmnl_server/routes/api.py b/trmnl_server/routes/api.py index 871e8b9..e56999f 100644 --- a/trmnl_server/routes/api.py +++ b/trmnl_server/routes/api.py @@ -2,11 +2,12 @@ import logging import uuid -from datetime import datetime, time, timedelta +from datetime import UTC, datetime, time, timedelta from zoneinfo import ZoneInfo from fastapi import APIRouter, Header, Query, Request from pydantic import BaseModel +from sqlalchemy import select from trmnl_server.config import get_config from trmnl_server.database import get_session @@ -22,6 +23,14 @@ logger = logging.getLogger(__name__) router = APIRouter(prefix="/api", tags=["api"]) +# Device MAC used for readings that arrive without any identification. +UNKNOWN_DEVICE_MAC = "UNKNOWN" + +# Minimum spacing between stored battery samples per device. The firmware reports +# telemetry on every poll (~2 min); without throttling battery_readings would grow by +# ~700 rows/day for data that only moves on an hourly scale. +BATTERY_SAMPLE_INTERVAL_SECONDS = 900 + class DisplayResponse(BaseModel): """Response for /api/display endpoint.""" @@ -74,13 +83,45 @@ class LogArray(BaseModel): model_config = {"extra": "allow"} +class TerminusLogEntry(BaseModel): + """Single log entry in the Terminus (current firmware) format. + + Field names follow usetrmnl/terminus doc/api.adoc — the payload the stock + firmware actually posts. Everything is optional: firmware versions differ in + which fields they populate. + """ + + id: int | None = None + message: str | None = None + level: str | None = None + source_path: str | None = None + source_line: int | None = None + created_at: int | None = None + firmware_version: str | None = None + battery_voltage: float | None = None + wifi_signal: int | None = None + wifi_status: str | None = None + free_heap_size: int | None = None + max_alloc_size: int | None = None + wake_reason: str | None = None + sleep_duration: int | None = None + refresh_rate: int | None = None + special_function: str | None = None + retry: int | None = None + + model_config = {"extra": "allow"} + + class LogRequest(BaseModel): """Request body for /api/log endpoint. - Accepts the TRMNL firmware log format: - {"log": {"logs_array": [...]}} + Accepts three shapes, newest first: + 1. Terminus / stock firmware: {"logs": [...]} + 2. Older firmware: {"log": {"logs_array": [...]}} + 3. Legacy flat: {"log_type": "...", "message": "..."} """ + logs: list[TerminusLogEntry] | None = None log: LogArray | None = None # Legacy format support @@ -124,19 +165,162 @@ class SetupResponse(BaseModel): message: str -def _get_device_mac(request: Request, header_mac: str | None = None) -> str: - """Extract device MAC address from request.""" - # Try header first - if header_mac: - return header_mac.upper().replace(":", "") +def _normalize_mac(raw: str) -> str: + """Normalize a MAC to bare uppercase hex (AA:BB:CC -> AABBCC).""" + return raw.strip().upper().replace(":", "").replace("-", "") + + +def _get_device_mac(request: Request, header_mac: str | None = None) -> str | None: + """Resolve the calling device's MAC, or None when it is unidentified. + + The stock TRMNL firmware identifies itself with the ``ID`` header (see + usetrmnl/terminus doc/api.adoc); ``X-Device-MAC`` and ``?mac=`` are kept for + custom clients. Returning None instead of a random ``UNKNOWN-xxxx`` id matters: + the old fallback minted a fresh identity on every poll, so an anonymous device + registered a new row in ``devices`` every couple of minutes. + """ + for raw in (header_mac, request.headers.get("ID"), request.query_params.get("mac")): + if raw and raw.strip(): + return _normalize_mac(raw) + return None + + +def _header_value(request: Request, *names: str) -> str | None: + """First non-empty value among the given (case-insensitive) header names.""" + for name in names: + value: str | None = request.headers.get(name) + if value and value.strip(): + return str(value.strip()) + return None + + +def _as_float(value: str | None) -> float | None: + """Parse a header value as float, tolerating junk from the firmware.""" + if value is None: + return None + try: + return float(value) + except ValueError: + return None + + +def _as_int(value: str | None) -> int | None: + """Parse a header value as int, tolerating floats ("-69.0") and junk.""" + if value is None: + return None + try: + return int(float(value)) + except ValueError: + return None + + +class DeviceTelemetry(BaseModel): + """Device state reported alongside a request. - # Try query param - mac = request.query_params.get("mac", "") - if mac: - return mac.upper().replace(":", "") + The TRMNL protocol has no battery endpoint — the firmware piggybacks battery, + signal and firmware version onto the headers of every /api/display call, and + repeats them inside /api/log entries. + """ + + voltage: float | None = None + rssi: int | None = None + firmware_version: str | None = None + refresh_rate: int | None = None - # Generate a unique ID for unknown devices - return f"UNKNOWN-{uuid.uuid4().hex[:8].upper()}" + def has_reading(self) -> bool: + """True when there is a battery sample worth storing.""" + return self.voltage is not None + + +def _telemetry_from_headers(request: Request) -> DeviceTelemetry: + """Read telemetry headers, accepting both dash and underscore spellings.""" + return DeviceTelemetry( + voltage=_as_float(_header_value(request, "Battery-Voltage", "BATTERY_VOLTAGE")), + rssi=_as_int(_header_value(request, "RSSI", "WIFI-RSSI")), + firmware_version=_header_value(request, "FW-Version", "FW_VERSION"), + refresh_rate=_as_int(_header_value(request, "Refresh-Rate", "REFRESH_RATE")), + ) + + +async def _raw_body_preview(request: Request, limit: int = 1000) -> str: + """Truncated raw request body, for diagnosing unrecognized payloads. + + Safe to call after FastAPI parsed the body — Starlette caches it on the request. + """ + try: + body = await request.body() + except Exception as e: # pragma: no cover - defensive + return f"" + text = bytes(body).decode("utf-8", errors="replace") + return text[:limit] + ("…" if len(text) > limit else "") + + +async def _should_sample_battery(session, mac: str) -> bool: + """True when the last stored reading for this device is old enough.""" + result = await session.execute( + select(BatteryReading.created_at) + .where(BatteryReading.device_mac == mac) + .order_by(BatteryReading.created_at.desc()) + .limit(1) + ) + last: datetime | None = result.scalar_one_or_none() + if last is None: + return True + if last.tzinfo is None: + last = last.replace(tzinfo=UTC) + age = (datetime.now(UTC) - last).total_seconds() + return bool(age >= BATTERY_SAMPLE_INTERVAL_SECONDS) + + +async def _record_device_contact( + mac: str | None, + telemetry: DeviceTelemetry, + plugin_name: str | None = None, +) -> None: + """Upsert the device row and store a throttled battery sample. + + Unidentified callers are deliberately not registered — see _get_device_mac. + Never raises: telemetry bookkeeping must not fail a device's display request. + """ + if not mac: + logger.debug("Unidentified request (no ID header), skipping device registration") + return + + try: + async with get_session() as session: + result = await session.execute(select(Device).where(Device.mac_address == mac)) + device = result.scalar_one_or_none() + + if device is None: + device = Device(mac_address=mac, current_plugin=plugin_name) + session.add(device) + logger.info(f"Registered new device {mac}") + + # UTC throughout: created_at/updated_at use the DB's func.now(), which is + # UTC in SQLite. Writing a local-time last_seen skewed the two by the + # server's UTC offset. + device.last_seen = datetime.now(UTC) + if plugin_name: + device.current_plugin = plugin_name + if telemetry.firmware_version: + device.firmware_version = telemetry.firmware_version + if telemetry.refresh_rate: + device.refresh_rate = telemetry.refresh_rate + + if telemetry.has_reading() and await _should_sample_battery(session, mac): + session.add( + BatteryReading( + device_mac=mac, + voltage=telemetry.voltage, + rssi=telemetry.rssi, + ) + ) + logger.info( + f"Battery sample from {mac}: {telemetry.voltage}V rssi={telemetry.rssi}" + ) + + except Exception as e: + logger.warning(f"Could not record device contact for {mac}: {e}") def _parse_time(time_str: str) -> time: @@ -240,6 +424,11 @@ async def get_display( """ config = get_config() mac = _get_device_mac(request, x_device_mac) + plugin_name = plugin or get_primary_plugin_name() + + # Record contact before any early return: a sleeping device still reports its + # battery, and that is the only channel the firmware has for telemetry. + await _record_device_contact(mac, _telemetry_from_headers(request), plugin_name=plugin_name) # Check if device should be sleeping if _is_in_sleep_window(config): @@ -271,9 +460,6 @@ async def get_display( special_function="sleep", ) - # Determine which plugin to use - plugin_name = plugin or get_primary_plugin_name() - if not plugin_name: logger.error("No plugin available") base_url = _public_base_url(request) @@ -312,28 +498,6 @@ async def get_display( image_url = f"{base_url}/generated/screen.bmp?v={output.content_hash}" filename = f"{output.content_hash}_screen.bmp" - # Update device last seen - try: - async with get_session() as session: - from sqlalchemy import select - - result = await session.execute(select(Device).where(Device.mac_address == mac)) - device = result.scalar_one_or_none() - - if device: - device.last_seen = datetime.now() - else: - # Register new device - device = Device( - mac_address=mac, - last_seen=datetime.now(), - current_plugin=plugin_name, - ) - session.add(device) - - except Exception as e: - logger.warning(f"Could not update device record: {e}") - logger.debug(f"Display response for {mac}: {image_url}") # Get dynamic refresh rate from plugin if available @@ -361,20 +525,48 @@ async def post_log( Called by TRMNL firmware on various events like display update, sleep, wake, etc. - Accepts two formats: - 1. TRMNL firmware format: {"log": {"logs_array": [...]}} - 2. Legacy format: {"log_type": "...", "message": "..."} + Accepts three formats: + 1. Terminus / stock firmware: {"logs": [...]} + 2. Older firmware format: {"log": {"logs_array": [...]}} + 3. Legacy format: {"log_type": "...", "message": "..."} """ mac = _get_device_mac(request, x_device_mac) + telemetry = _telemetry_from_headers(request) try: async with get_session() as session: - # Handle TRMNL firmware format - if log_data.log and log_data.log.logs_array: + # Handle Terminus format (current firmware) + if log_data.logs: + for terminus_entry in log_data.logs: + session.add( + DeviceLog( + device_mac=mac or UNKNOWN_DEVICE_MAC, + log_type=terminus_entry.level + or terminus_entry.source_path + or "firmware", + message=terminus_entry.message, + firmware_version=terminus_entry.firmware_version, + wifi_rssi=terminus_entry.wifi_signal, + battery_voltage=terminus_entry.battery_voltage, + free_heap=terminus_entry.free_heap_size, + ) + ) + # Headers win when present; otherwise fall back to the newest entry + # that carried a voltage. + if not telemetry.has_reading(): + for terminus_entry in reversed(log_data.logs): + if terminus_entry.battery_voltage is not None: + telemetry.voltage = terminus_entry.battery_voltage + telemetry.rssi = terminus_entry.wifi_signal + telemetry.firmware_version = terminus_entry.firmware_version + break + logger.info(f"Log from {mac}: {len(log_data.logs)} entries (terminus format)") + # Handle older TRMNL firmware format + elif log_data.log and log_data.log.logs_array: for entry in log_data.log.logs_array: status = entry.device_status_stamp log_entry = DeviceLog( - device_mac=mac, + device_mac=mac or UNKNOWN_DEVICE_MAC, log_type=entry.log_sourcefile or "firmware", message=entry.log_message, firmware_version=status.current_fw_version if status else None, @@ -383,11 +575,19 @@ async def post_log( free_heap=status.free_heap_size if status else None, ) session.add(log_entry) - logger.debug(f"Log from {mac}: {len(log_data.log.logs_array)} entries") + if ( + not telemetry.has_reading() + and status + and status.battery_voltage is not None + ): + telemetry.voltage = status.battery_voltage + telemetry.rssi = status.wifi_rssi_level + telemetry.firmware_version = status.current_fw_version + logger.info(f"Log from {mac}: {len(log_data.log.logs_array)} entries") # Handle legacy format elif log_data.log_type: log_entry = DeviceLog( - device_mac=mac, + device_mac=mac or UNKNOWN_DEVICE_MAC, log_type=log_data.log_type, message=log_data.message, firmware_version=log_data.firmware_version, @@ -396,15 +596,26 @@ async def post_log( free_heap=log_data.free_heap, ) session.add(log_entry) - logger.debug(f"Log from {mac}: {log_data.log_type}") + if not telemetry.has_reading() and log_data.battery_voltage is not None: + telemetry.voltage = log_data.battery_voltage + telemetry.rssi = log_data.wifi_rssi + telemetry.firmware_version = log_data.firmware_version + logger.info(f"Log from {mac}: {log_data.log_type}") else: - # Accept but don't store unknown formats - logger.debug(f"Log from {mac}: unknown format, accepted") + # Accept but don't store — and say so loudly with the payload, since + # a silent drop here is exactly how this endpoint stored nothing for + # weeks while answering 200 OK. + logger.warning( + f"Log from {mac}: unrecognized payload, nothing stored: " + f"{await _raw_body_preview(request)}" + ) except Exception as e: logger.error(f"Failed to save log: {e}") return LogResponse(status=1, message=str(e)) + await _record_device_contact(mac, telemetry) + return LogResponse(status=0, message="ok") @@ -416,9 +627,12 @@ async def post_battery( ) -> BatteryResponse: """Record battery and RSSI readings. - Called periodically by TRMNL firmware to report battery status. + Note: this endpoint is a MunichGlance extension, not part of the TRMNL protocol — + stock firmware never calls it. Real devices report battery in the headers of + /api/display and inside /api/log entries, which is where the readings come from. + Kept for manual reporting and custom clients; writes are not throttled here. """ - mac = _get_device_mac(request, x_device_mac) + mac = _get_device_mac(request, x_device_mac) or UNKNOWN_DEVICE_MAC try: async with get_session() as session: @@ -429,7 +643,7 @@ async def post_battery( ) session.add(reading) - logger.debug(f"Battery from {mac}: {battery_data.voltage}V") + logger.info(f"Battery from {mac}: {battery_data.voltage}V") except Exception as e: logger.error(f"Failed to save battery reading: {e}") @@ -453,7 +667,8 @@ async def get_setup( # Generate or retrieve API key for device api_key = config.setup_api_key or f"mg_{uuid.uuid4().hex[:16]}" - logger.info(f"Setup request from {mac}") + await _record_device_contact(mac, _telemetry_from_headers(request)) + logger.info(f"Setup request from {mac or 'unidentified device'}") return SetupResponse( status=0,