data: catch packet handler errors (#759)

* data: catch packet handler errors

* data: address review comments

* data: address review comments

data/mesh_ingestor/CONTRACTS.md

@@ -80,6 +80,7 @@ The `v1:` prefix lets the format evolve (e.g. add a channel-secret hash) without
 - *Sender-side clock reset.* MeshCore nodes without an RTC start `sender_timestamp` from `0` after reboot. Two messages from the same sender containing the same text within one second of power-on collapse into a single row. Acceptable trade-off given the alternative (no dedup at all).
 - *Relay-rewritten `sender_timestamp` (#756).* MeshCore has been observed delivering the same physical packet twice with a rewritten `sender_timestamp` (≈10 s later, same `from_id`/`channel`/`text`), which flips the v1 fingerprint and bypasses the `messages.id` PK collapse. To cover this, the web app runs an additional content-level dedup on insert: for `protocol = "meshcore"` with non-empty `text` and a known `from_id`, a second row matching `(from_id, to_id, channel, text)` within ±30 s of `rx_time` is dropped (window lives in `MESHCORE_CONTENT_DEDUP_WINDOW_SECONDS`). The window is ~3× the observed relay delta; legitimate rapid re-sends of identical short text (e.g. `hi`, `ack`, `ok`, `test`) from the same sender on the same channel **within 30 s** will be silently collapsed into one row. Ingestors MUST still produce deterministic v1 ids — this content-level layer is additive, not a replacement. Pre-existing duplicates are cleared once by a `PRAGMA user_version`-gated one-shot backfill on startup.
 - *Concurrent-insert race (#756).* The content-dedup SELECT and the downstream INSERT are not currently wrapped in a shared transaction, so two concurrent Puma threads carrying the same content with different ids can both pass the pre-check and both insert. Duplicates produced this way are narrow (single-node multi-threaded ingest) and are not cleaned up on subsequent boots because the backfill is one-shot. If the race is ever observed in production, tighten `insert_message` to wrap the meshcore pre-check + id-PK path in `db.transaction(:immediate)`.
+- *Upstream `meshcore` reader crash on truncated advertisements (#754).* `meshcore-py` 2.3.6 (latest at the time of writing) raises `IndexError` from `MessageReader.handle_rx` at `reader.py:365` when a `DEVICE_INFO`/advertisement frame declares `fw_ver >= 10` but omits the trailing `path_hash_mode` byte. Because the frame is parsed inside a detached `asyncio.create_task(...)`, the exception surfaces as `Task exception was never retrieved` on stderr and the event for that frame is lost. The ingestor installs a runtime patch (`data/mesh_ingestor/protocols/_meshcore_patches.py`) that wraps `handle_rx`, logs one line with the first 32 bytes of the offending frame under `context=meshcore.reader.patch`, and lets the task exit cleanly; a loop-level handler (`context=asyncio.unhandled`) catches anything the targeted patch misses. Both shims are additive and will be removed once upstream ships a defensive length check.
 
 #### `POST /api/positions`
 

data/mesh_ingestor/protocols/_meshcore_patches.py

@@ -0,0 +1,161 @@
+# Copyright © 2025-26 l5yth & contributors
+#
+# Licensed under the Apache License, Version 2.0 (the "License");
+# you may not use this file except in compliance with the License.
+# You may obtain a copy of the License at
+#
+#     http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS,
+# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+# See the License for the specific language governing permissions and
+# limitations under the License.
+
+"""Runtime patches applied to the upstream ``meshcore`` library.
+
+This module exists solely to paper over bugs in the third-party
+``meshcore-py`` package while we wait for upstream fixes.  Each patch is
+narrow, idempotent, and preserves the original method on the target class so
+that it can be reverted cleanly once a fix ships upstream.
+
+Current patches:
+
+* :func:`_wrap_handle_rx` — guards :meth:`meshcore.reader.MessageReader.handle_rx`
+  against unhandled exceptions raised while decoding a single radio frame.
+  Upstream 2.3.6 (latest at the time of writing) raises ``IndexError`` at
+  ``reader.py:365`` when parsing a truncated ``DEVICE_INFO`` advertisement
+  (``path_hash_mode = dbuf.read(1)[0]`` with an already-exhausted buffer).
+  Because the frame is parsed inside a detached
+  ``asyncio.create_task(...)`` the resulting exception surfaces as a noisy
+  ``Task exception was never retrieved`` stderr dump and the decoded event
+  for that frame is lost.  See GitHub issue #754.
+
+Apply the patches by calling :func:`apply` as early as possible after the
+``meshcore`` package is imported.  Re-invoking :func:`apply` is a no-op.
+"""
+
+from __future__ import annotations
+
+from typing import Any
+
+from .. import config
+
+# Sentinel attribute set on a patched method so repeated imports/tests do
+# not wrap the same function more than once.  The name intentionally
+# includes the project slug so we can grep for it while diagnosing.
+_PATCH_MARKER = "_potato_mesh_patched"
+
+# Cap on hex bytes dumped into the log per failure.  Keeps the log line
+# under a few hundred characters even for maximum-sized frames.
+_PACKET_LOG_MAX_BYTES = 32
+
+
+def apply() -> bool:
+    """Install every known-needed patch on the upstream ``meshcore`` library.
+
+    Safe to call multiple times; each patch is individually idempotent.
+
+    Implicit contract with upstream: every patch here rebinds a method on
+    the target *class*.  This only affects call sites that perform an
+    attribute lookup at call time (``reader.handle_rx(data)``) — not call
+    sites that captured an unbound reference before :func:`apply` ran
+    (``_rx = reader.handle_rx``).  As of ``meshcore-py`` 2.3.6 the library
+    always uses attribute-lookup-at-call, so this is fine; if a future
+    release flips that, the patch silently no-ops and the original bug
+    resurfaces.  Spot-check after every upstream bump.
+
+    Returns:
+        ``True`` when at least one patch was installed during this call,
+        ``False`` when every patch had already been applied (or when the
+        ``meshcore`` library is not importable in this environment, e.g. a
+        meshtastic-only test runner).
+    """
+    try:
+        import meshcore.reader as _reader  # type: ignore[import-not-found]
+    except ImportError:
+        # Meshtastic-only runtimes never load this module's caller, but
+        # imports from tests may still land here.  Nothing to patch.
+        return False
+
+    return _wrap_handle_rx(_reader.MessageReader)
+
+
+def _wrap_handle_rx(reader_cls: Any) -> bool:
+    """Wrap ``reader_cls.handle_rx`` with an exception-swallowing shim.
+
+    Parameters:
+        reader_cls: The ``MessageReader`` class to patch in place.
+
+    Returns:
+        ``True`` when the wrap was installed on this call; ``False`` when
+        the method had already been wrapped.
+    """
+    original = getattr(reader_cls, "handle_rx", None)
+    if original is None:
+        return False
+    if getattr(original, _PATCH_MARKER, False):
+        return False
+
+    async def safe_handle_rx(self, data, *args, **kwargs):  # type: ignore[no-untyped-def]
+        """Run the original ``handle_rx`` and convert hard failures to logs.
+
+        A single malformed frame would otherwise kill the
+        ``asyncio.create_task(reader.handle_rx(data))`` task spawned by the
+        upstream connection layer, surfacing as ``Task exception was never
+        retrieved`` in stderr and losing the event silently.  We log once
+        with the first few bytes of the offending frame for forensics and
+        then return ``None`` so the task exits cleanly.
+        """
+        try:
+            return await original(self, data, *args, **kwargs)
+        except Exception as exc:  # noqa: BLE001 — deliberately broad: a
+            # single malformed frame must not kill the reader.  Narrower
+            # excepts would hide future upstream failure modes (e.g.
+            # ``struct.error``) the same way the current IndexError was
+            # hidden before we added this shim.
+            config._debug_log(
+                "Suppressed meshcore reader exception on malformed frame",
+                context="meshcore.reader.patch",
+                severity="warning",
+                always=True,
+                error_class=type(exc).__name__,
+                error_message=str(exc),
+                packet_len=_safe_len(data),
+                packet_hex=_hex_preview(data, _PACKET_LOG_MAX_BYTES),
+            )
+            return None
+
+    setattr(safe_handle_rx, _PATCH_MARKER, True)
+    # Preserve the pre-patch method under a stable name so operators and
+    # future maintainers can revert the patch with one line.
+    reader_cls._orig_handle_rx = original
+    reader_cls.handle_rx = safe_handle_rx
+    return True
+
+
+def _safe_len(data: Any) -> int | None:
+    """Return ``len(data)`` or ``None`` when the object is not sized."""
+    try:
+        return len(data)
+    except TypeError:
+        return None
+
+
+def _hex_preview(data: Any, limit: int) -> str:
+    """Return the first *limit* bytes of ``data`` as a lowercase hex string.
+
+    Accepts anything that is a :class:`bytes`-like or supports ``bytes(data)``.
+    On conversion failure returns an empty string — the log caller still gets
+    the error class and message.
+    """
+    try:
+        if not isinstance(data, (bytes, bytearray, memoryview)):
+            data = bytes(data)
+    except Exception:  # noqa: BLE001 — pure diagnostic path, never raise.
+        return ""
+    prefix = bytes(data[:limit])
+    return prefix.hex()
+
+
+__all__ = ["apply"]

data/mesh_ingestor/protocols/meshcore.py

@@ -70,6 +70,21 @@ from meshcore import (
     TCPConnection,
 )
 
+from . import _meshcore_patches
+
+# Apply upstream-library patches before any ``MeshCore`` instance is built,
+# otherwise the first malformed advertisement dies inside a detached asyncio
+# task before our handler can observe it.  See
+# :mod:`data.mesh_ingestor.protocols._meshcore_patches` for the specific
+# upstream bugs covered.
+#
+# This mutates the upstream class at import time.  The blast radius is
+# narrow because ``protocols/__init__.py`` exposes this module only through
+# a lazy ``__getattr__`` and the daemon resolves it only when
+# ``PROTOCOL=meshcore`` is active.  Any future diagnostic CLI that imports
+# this module will inherit the shim.
+_meshcore_patches.apply()
+
 from .. import config, ingestors as _ingestors, queue as _queue
 from ..connection import default_serial_targets, parse_ble_target, parse_tcp_target
 from ..serialization import _iso, _node_num_from_id
@@ -1060,6 +1075,46 @@ def _make_connection(target: str, baudrate: int) -> object:
     return SerialConnection(target, baudrate)
 
 
+def _log_unhandled_loop_exception(
+    loop: asyncio.AbstractEventLoop, context: dict
+) -> None:
+    """Route asyncio's "unhandled task exception" warnings through our logger.
+
+    The upstream ``meshcore`` library spawns detached
+    ``asyncio.create_task`` tasks for every inbound radio frame.  When one
+    of those tasks raises and nobody awaits the future, asyncio's default
+    handler writes ``Task exception was never retrieved`` to stderr.  That
+    bypasses our structured log pipeline and clutters container logs.
+    This handler preserves the same information under
+    ``context=asyncio.unhandled`` so operators grep for one place.
+
+    Parameters:
+        loop: Event loop that surfaced the exception (unused but required
+            by the asyncio handler signature).
+        context: Asyncio exception-context dictionary.  Fields we care
+            about: ``message`` (human summary) and ``exception`` (the raw
+            exception object, when available).
+    """
+    del loop
+    exception = context.get("exception")
+    task = context.get("task")
+    task_name = None
+    if task is not None:
+        # Prefer the friendly ``get_name()``; fall back to ``repr`` for any
+        # future Task-like object that does not implement it.
+        get_name = getattr(task, "get_name", None)
+        task_name = get_name() if callable(get_name) else repr(task)
+    config._debug_log(
+        context.get("message") or "Unhandled asyncio task exception",
+        context="asyncio.unhandled",
+        severity="error",
+        always=True,
+        error_class=type(exception).__name__ if exception else None,
+        error_message=str(exception) if exception else None,
+        task=task_name,
+    )
+
+
 async def _run_meshcore(
     iface: _MeshcoreInterface,
     target: str,
@@ -1254,6 +1309,12 @@ class MeshcoreProvider:
         def _run_loop() -> None:
             loop = asyncio.new_event_loop()
             asyncio.set_event_loop(loop)
+            # Second line of defence around issue #754: if a detached task
+            # inside the upstream ``meshcore`` library ever raises an
+            # exception we do not anticipate in ``_meshcore_patches``, funnel
+            # it through our logger instead of the default handler (which
+            # only writes ``Task exception was never retrieved`` to stderr).
+            loop.set_exception_handler(_log_unhandled_loop_exception)
             iface._loop = loop
             try:
                 loop.run_until_complete(

tests/test_meshcore_reader_patch.py

@@ -0,0 +1,328 @@
+# Copyright © 2025-26 l5yth & contributors
+#
+# Licensed under the Apache License, Version 2.0 (the "License");
+# you may not use this file except in compliance with the License.
+# You may obtain a copy of the License at
+#
+#     http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing, software
+# distributed under the License is distributed on an "AS IS" BASIS,
+# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+# See the License for the specific language governing permissions and
+# limitations under the License.
+"""Unit tests for the runtime patch installed against the upstream ``meshcore``
+library to suppress ``MessageReader.handle_rx`` crashes on malformed frames.
+
+Covers GitHub issue #754.
+"""
+
+from __future__ import annotations
+
+import asyncio
+import sys
+from pathlib import Path
+
+REPO_ROOT = Path(__file__).resolve().parents[1]
+if str(REPO_ROOT) not in sys.path:
+    sys.path.insert(0, str(REPO_ROOT))
+
+from data.mesh_ingestor.protocols import (  # noqa: E402 - path setup
+    _meshcore_patches,
+)
+
+
+class _FakeReader:
+    """Stand-in for ``meshcore.reader.MessageReader`` that lets us control
+    what ``handle_rx`` raises without dragging in the real library's
+    framing state machine."""
+
+    def __init__(self, raise_exc: BaseException | None = None, return_value=None):
+        self._raise_exc = raise_exc
+        self._return_value = return_value
+        self.received: list[bytes] = []
+
+    async def handle_rx(self, data):
+        self.received.append(bytes(data))
+        if self._raise_exc is not None:
+            raise self._raise_exc
+        return self._return_value
+
+
+def _install_patch_on(cls) -> None:
+    """Run the real wrap helper against an arbitrary class so the tests do
+    not mutate the installed ``meshcore.reader.MessageReader``."""
+    _meshcore_patches._wrap_handle_rx(cls)
+
+
+def _run(coro):
+    return asyncio.run(coro)
+
+
+def test_apply_is_idempotent():
+    """``apply()`` wrapping twice must not double-wrap the target method."""
+
+    class Target:
+        async def handle_rx(self, data):
+            return "ok"
+
+    first_wrap = _meshcore_patches._wrap_handle_rx(Target)
+    second_wrap = _meshcore_patches._wrap_handle_rx(Target)
+
+    assert first_wrap is True
+    assert second_wrap is False
+    # Marker is present on the wrapper so future imports short-circuit.
+    assert getattr(Target.handle_rx, _meshcore_patches._PATCH_MARKER, False) is True
+    # Original is preserved for revert.
+    assert hasattr(Target, "_orig_handle_rx")
+
+
+def test_apply_returns_false_when_already_patched(monkeypatch):
+    """Once ``_wrap_handle_rx`` has been applied, ``apply()`` at module
+    level observes the sentinel and short-circuits rather than rewrapping."""
+
+    class Target:
+        async def handle_rx(self, data):
+            return None
+
+    _meshcore_patches._wrap_handle_rx(Target)
+
+    # Replace ``meshcore.reader.MessageReader`` with our pre-patched Target
+    # so ``apply()`` cannot accidentally wrap a real class in the test env.
+    import meshcore.reader as reader_module
+
+    original_cls = reader_module.MessageReader
+    monkeypatch.setattr(reader_module, "MessageReader", Target)
+    try:
+        assert _meshcore_patches.apply() is False
+    finally:
+        monkeypatch.setattr(reader_module, "MessageReader", original_cls)
+
+
+def test_index_error_swallowed_and_logged(monkeypatch):
+    """The exact failure mode reported in #754: ``IndexError`` on a malformed
+    frame must not propagate and must emit one structured warning."""
+
+    class Target(_FakeReader):
+        pass
+
+    _install_patch_on(Target)
+    instance = Target(raise_exc=IndexError("index out of range"))
+
+    # Force the debug logger to always emit so we can capture the log line
+    # regardless of the ``DEBUG`` env flag during test runs.
+    from data.mesh_ingestor import config
+
+    emitted: list[tuple[str, dict]] = []
+
+    def _capture_log(message, **kwargs):
+        emitted.append((message, kwargs))
+
+    monkeypatch.setattr(config, "_debug_log", _capture_log)
+
+    # Should return None rather than raise.
+    result = _run(instance.handle_rx(b"\x01\x02\x03\x04"))
+    assert result is None
+
+    assert emitted, "patched handle_rx should have logged the suppressed error"
+    message, kwargs = emitted[-1]
+    assert "malformed frame" in message
+    assert kwargs["context"] == "meshcore.reader.patch"
+    assert kwargs["severity"] == "warning"
+    assert kwargs["error_class"] == "IndexError"
+    assert kwargs["error_message"] == "index out of range"
+    assert kwargs["packet_len"] == 4
+    assert kwargs["packet_hex"] == "01020304"
+
+
+def test_unrelated_return_value_preserved():
+    """When the original ``handle_rx`` returns normally, the wrapper must
+    forward the exact return value and not swallow it."""
+
+    class Target(_FakeReader):
+        pass
+
+    _install_patch_on(Target)
+    sentinel = object()
+    instance = Target(return_value=sentinel)
+
+    result = _run(instance.handle_rx(b"\x00"))
+    assert result is sentinel
+    assert instance.received == [b"\x00"]
+
+
+def test_packet_dump_truncated_to_max(monkeypatch):
+    """Large frames must be truncated in the hex dump so a noisy device
+    cannot flood the log."""
+
+    class Target(_FakeReader):
+        pass
+
+    _install_patch_on(Target)
+    instance = Target(raise_exc=ValueError("boom"))
+
+    from data.mesh_ingestor import config
+
+    emitted: list[dict] = []
+
+    def _capture_log(message, **kwargs):
+        emitted.append(kwargs)
+
+    monkeypatch.setattr(config, "_debug_log", _capture_log)
+
+    payload = bytes(range(256)) * 2  # 512 bytes
+    result = _run(instance.handle_rx(payload))
+    assert result is None
+
+    kwargs = emitted[-1]
+    # Hex length is exactly 2 * cap bytes.
+    expected_len = 2 * _meshcore_patches._PACKET_LOG_MAX_BYTES
+    assert len(kwargs["packet_hex"]) == expected_len
+    # And matches the first N real bytes of the payload.
+    assert (
+        kwargs["packet_hex"] == payload[: _meshcore_patches._PACKET_LOG_MAX_BYTES].hex()
+    )
+    assert kwargs["packet_len"] == 512
+
+
+def test_hex_preview_handles_non_bytes():
+    """Defensive: ``_hex_preview`` accepts bytearray / memoryview and any
+    object convertible via ``bytes(...)`` without raising."""
+
+    assert (
+        _meshcore_patches._hex_preview(bytearray(b"\xde\xad\xbe\xef"), 4) == "deadbeef"
+    )
+    assert _meshcore_patches._hex_preview(memoryview(b"\x01\x02"), 8) == "0102"
+    assert _meshcore_patches._hex_preview("not-bytes", 4) == ""
+
+
+def test_safe_len_handles_unsized():
+    assert _meshcore_patches._safe_len(b"\x01\x02") == 2
+    assert _meshcore_patches._safe_len(12345) is None
+
+
+def test_apply_skips_gracefully_when_meshcore_missing(monkeypatch):
+    """If ``meshcore`` is not importable, ``apply()`` must return ``False``
+    instead of raising.  Simulated by injecting an ImportError into
+    ``meshcore.reader``'s import machinery."""
+
+    # Block the import by clearing both the submodule and the parent, so
+    # that ``import meshcore.reader`` inside ``apply()`` triggers a fresh
+    # resolution that fails.
+    monkeypatch.setitem(sys.modules, "meshcore.reader", None)
+    assert _meshcore_patches.apply() is False
+
+
+def test_run_loop_exception_handler_routes_to_debug_log(monkeypatch):
+    """The loop-level safety net installed in ``_run_loop`` must forward
+    asyncio's unhandled-exception contexts through ``config._debug_log``."""
+
+    from data.mesh_ingestor import config
+    from data.mesh_ingestor.protocols import meshcore
+
+    emitted: list[tuple[str, dict]] = []
+
+    def _capture_log(message, **kwargs):
+        emitted.append((message, kwargs))
+
+    monkeypatch.setattr(config, "_debug_log", _capture_log)
+
+    loop = asyncio.new_event_loop()
+    try:
+        meshcore._log_unhandled_loop_exception(
+            loop,
+            {"message": "synthetic task failure", "exception": RuntimeError("boom")},
+        )
+    finally:
+        loop.close()
+
+    assert emitted, "loop handler should forward to the structured logger"
+    message, kwargs = emitted[-1]
+    assert message == "synthetic task failure"
+    assert kwargs["context"] == "asyncio.unhandled"
+    assert kwargs["severity"] == "error"
+    assert kwargs["error_class"] == "RuntimeError"
+    assert kwargs["error_message"] == "boom"
+
+
+def test_wrap_returns_false_when_class_has_no_handle_rx():
+    """If a future upstream release renames ``handle_rx`` or we point the
+    patch at the wrong class, ``_wrap_handle_rx`` must report the no-op
+    rather than silently install nothing on a random attribute."""
+
+    class Bare:
+        pass
+
+    assert _meshcore_patches._wrap_handle_rx(Bare) is False
+    assert not hasattr(Bare, "_orig_handle_rx")
+
+
+def test_loop_handler_defaults_when_context_minimal(monkeypatch):
+    """Covers the fallback branches of ``_log_unhandled_loop_exception`` —
+    missing ``message`` (defaults to a fixed string) and missing
+    ``exception`` (``error_class``/``error_message`` come through as ``None``).
+    Both are real asyncio code paths: task-cancellation and unhandled-future
+    warnings arrive with one-or-the-other key unset."""
+
+    from data.mesh_ingestor import config
+    from data.mesh_ingestor.protocols import meshcore
+
+    emitted: list[tuple[str, dict]] = []
+
+    def _capture_log(message, **kwargs):
+        emitted.append((message, kwargs))
+
+    monkeypatch.setattr(config, "_debug_log", _capture_log)
+
+    loop = asyncio.new_event_loop()
+    try:
+        # Empty context exercises both fallbacks at once.
+        meshcore._log_unhandled_loop_exception(loop, {})
+    finally:
+        loop.close()
+
+    assert emitted, "loop handler should still emit something for a bare context"
+    message, kwargs = emitted[-1]
+    assert message == "Unhandled asyncio task exception"
+    assert kwargs["context"] == "asyncio.unhandled"
+    assert kwargs["severity"] == "error"
+    assert kwargs["error_class"] is None
+    assert kwargs["error_message"] is None
+
+
+def test_loop_handler_logs_task_name_when_present(monkeypatch):
+    """Asyncio includes the failing ``task`` object in its context dict when
+    the exception comes from ``create_task(...)``.  The handler extracts the
+    task's name so operators can correlate log lines with the frame that
+    blew up when several readers share a loop."""
+
+    from data.mesh_ingestor import config
+    from data.mesh_ingestor.protocols import meshcore
+
+    emitted: list[dict] = []
+
+    def _capture_log(message, **kwargs):
+        emitted.append(kwargs)
+
+    monkeypatch.setattr(config, "_debug_log", _capture_log)
+
+    async def _dummy():
+        return None
+
+    loop = asyncio.new_event_loop()
+    try:
+        task = loop.create_task(_dummy(), name="meshcore-reader-42")
+        # Let the task finish so we don't leak a pending future.
+        loop.run_until_complete(task)
+        meshcore._log_unhandled_loop_exception(
+            loop,
+            {
+                "message": "synthetic",
+                "exception": ValueError("bad frame"),
+                "task": task,
+            },
+        )
+    finally:
+        loop.close()
+
+    assert emitted[-1]["task"] == "meshcore-reader-42"