Fix ingestor debug timestamps for structured logging (#296)

2026-08-07 17:33:26 +02:00 · 2025-10-12 09:40:57 +02:00
parent f04e917cd9
commit 772c5888c3
18 changed files with 591 additions and 121 deletions
@@ -133,12 +133,11 @@ Check out `mesh.sh` ingestor script in the `./data` directory.

 ```bash
 POTATOMESH_INSTANCE=http://127.0.0.1:41447 API_TOKEN=1eb140fd-cab4-40be-b862-41c607762246 MESH_SERIAL=/dev/ttyACM0 DEBUG=1 ./mesh.sh
-Mesh daemon: nodes+messages → http://127.0.0.1 | port=41447 | channel=0
+[2025-02-20T12:34:56.789012Z] [potato-mesh] [info] channel=0 context=daemon.main port='41447' target='http://127.0.0.1' Mesh daemon starting
 [...]
-[debug] upserted node !849b7154 shortName='7154'
-[debug] upserted node !ba653ae8 shortName='3ae8'
-[debug] upserted node !16ced364 shortName='Pat'
-[debug] stored message from '!9ee71c38' to '^all' ch=0 text='Guten Morgen!'
+[2025-02-20T12:34:57.012345Z] [potato-mesh] [debug] context=handlers.upsert_node node_id=!849b7154 short_name='7154' long_name='7154' Queued node upsert payload
+[2025-02-20T12:34:57.456789Z] [potato-mesh] [debug] context=handlers.upsert_node node_id=!ba653ae8 short_name='3ae8' long_name='3ae8' Queued node upsert payload
+[2025-02-20T12:34:58.001122Z] [potato-mesh] [debug] context=handlers.store_packet_dict channel=0 from_id='!9ee71c38' payload='Guten Morgen!' to_id='^all' Queued message payload
 ```

 Run the script with `POTATOMESH_INSTANCE` and `API_TOKEN` to keep updating
@@ -17,7 +17,8 @@
 from __future__ import annotations

 import os
-import time
+from datetime import datetime, timezone
+from typing import Any

 PORT = os.environ.get("MESH_SERIAL")
 SNAPSHOT_SECS = int(os.environ.get("MESH_SNAPSHOT_SECS", "60"))
@@ -39,18 +40,38 @@ _ENERGY_ONLINE_DURATION_SECS = float(
 _ENERGY_SLEEP_SECS = float(os.environ.get("ENERGY_SLEEP_SECS", str(6 * 60 * 60)))


-def _debug_log(message: str) -> None:
+def _debug_log(
+    message: str,
+    *,
+    context: str | None = None,
+    severity: str = "debug",
+    always: bool = False,
+    **metadata: Any,
+) -> None:
    """Print ``message`` with a UTC timestamp when ``DEBUG`` is enabled.

    Parameters:
        message: Text to display when debug logging is active.
+        context: Optional logical component emitting the message.
+        severity: Log level label to embed in the formatted output.
+        always: When ``True``, bypasses the :data:`DEBUG` guard.
+        **metadata: Additional structured log metadata.
    """

-    if not DEBUG:
+    normalized_severity = severity.lower()
+
+    if not DEBUG and not always and normalized_severity == "debug":
        return

-    timestamp = time.strftime("%Y-%m-%dT%H:%M:%SZ", time.gmtime())
-    print(f"[{timestamp}] [debug] {message}")
+    timestamp = datetime.now(timezone.utc).isoformat(timespec="milliseconds")
+    timestamp = timestamp.replace("+00:00", "Z")
+    parts = [f"[{timestamp}]", "[potato-mesh]", f"[{normalized_severity}]"]
+    if context:
+        parts.append(f"context={context}")
+    for key, value in sorted(metadata.items()):
+        parts.append(f"{key}={value!r}")
+    parts.append(message)
+    print(" ".join(parts))


 __all__ = [
@@ -131,7 +131,13 @@ def _close_interface(iface_obj) -> None:
            iface_obj.close()
        except Exception as exc:  # pragma: no cover
            if config.DEBUG:
-                config._debug_log(f"error while closing mesh interface: {exc}")
+                config._debug_log(
+                    "Error closing mesh interface",
+                    context="daemon.close",
+                    severity="warn",
+                    error_class=exc.__class__.__name__,
+                    error_message=str(exc),
+                )

    if config._CLOSE_TIMEOUT_SECS <= 0 or not _event_wait_allows_default_timeout():
        _do_close()
@@ -141,9 +147,11 @@ def _close_interface(iface_obj) -> None:
    close_thread.start()
    close_thread.join(config._CLOSE_TIMEOUT_SECS)
    if close_thread.is_alive():
-        print(
-            "[warn] mesh interface did not close within "
-            f"{config._CLOSE_TIMEOUT_SECS:g}s; continuing shutdown"
+        config._debug_log(
+            "Mesh interface close timed out",
+            context="daemon.close",
+            severity="warn",
+            timeout_seconds=config._CLOSE_TIMEOUT_SECS,
        )


@@ -163,8 +171,13 @@ def main() -> None:
    """Run the mesh ingestion daemon until interrupted."""

    subscribed = _subscribe_receive_topics()
-    if config.DEBUG and subscribed:
-        config._debug_log(f"subscribed to receive topics: {', '.join(subscribed)}")
+    if subscribed:
+        config._debug_log(
+            "Subscribed to receive topics",
+            context="daemon.subscribe",
+            severity="info",
+            topics=subscribed,
+        )

    iface = None
    resolved_target = None
@@ -209,8 +222,13 @@ def main() -> None:
    configured_port = config.PORT
    active_candidate = configured_port
    announced_target = False
-    print(
-        f"Mesh daemon: nodes+messages → {target} | port={configured_port or 'auto'} | channel={config.CHANNEL_INDEX}"
+    config._debug_log(
+        "Mesh daemon starting",
+        context="daemon.main",
+        severity="info",
+        target=target,
+        port=configured_port or "auto",
+        channel=config.CHANNEL_INDEX,
    )
    try:
        while not stop.is_set():
@@ -226,7 +244,12 @@ def main() -> None:
                    retry_delay = max(0.0, config._RECONNECT_INITIAL_DELAY_SECS)
                    initial_snapshot_sent = False
                    if not announced_target and resolved_target:
-                        print(f"[info] using mesh interface: {resolved_target}")
+                        config._debug_log(
+                            "Using mesh interface",
+                            context="daemon.interface",
+                            severity="info",
+                            target=resolved_target,
+                        )
                        announced_target = True
                    if energy_saving_enabled and energy_online_secs > 0:
                        energy_session_deadline = time.monotonic() + energy_online_secs
@@ -239,13 +262,23 @@ def main() -> None:
                    last_seen_packet_monotonic = iface_connected_at
                    last_inactivity_reconnect = None
                except interfaces.NoAvailableMeshInterface as exc:
-                    print(f"[error] {exc}")
+                    config._debug_log(
+                        "No mesh interface available",
+                        context="daemon.interface",
+                        severity="error",
+                        error_message=str(exc),
+                    )
                    _close_interface(iface)
                    raise SystemExit(1) from exc
                except Exception as exc:
                    candidate_desc = active_candidate or "auto"
-                    print(
-                        f"[warn] failed to create mesh interface ({candidate_desc}): {exc}"
+                    config._debug_log(
+                        "Failed to create mesh interface",
+                        context="daemon.interface",
+                        severity="warn",
+                        candidate=candidate_desc,
+                        error_class=exc.__class__.__name__,
+                        error_message=str(exc),
                    )
                    if configured_port is None:
                        active_candidate = None
@@ -267,7 +300,11 @@ def main() -> None:
                    energy_session_deadline is not None
                    and time.monotonic() >= energy_session_deadline
                ):
-                    print("[info] energy saving: disconnecting mesh interface")
+                    config._debug_log(
+                        "Energy saving disconnect",
+                        context="daemon.energy",
+                        severity="info",
+                    )
                    _close_interface(iface)
                    iface = None
                    announced_target = False
@@ -279,8 +316,10 @@ def main() -> None:
                    _is_ble_interface(iface)
                    and getattr(iface, "client", object()) is None
                ):
-                    print(
-                        "[info] energy saving: BLE client disconnected; sleeping before retry"
+                    config._debug_log(
+                        "Energy saving BLE disconnect",
+                        context="daemon.energy",
+                        severity="info",
                    )
                    _close_interface(iface)
                    iface = None
@@ -296,7 +335,8 @@ def main() -> None:
                    node_items = _node_items_snapshot(nodes)
                    if node_items is None:
                        config._debug_log(
-                            "skipping node snapshot; nodes changed during iteration"
+                            "Skipping node snapshot due to concurrent modification",
+                            context="daemon.snapshot",
                        )
                    else:
                        processed_snapshot_item = False
@@ -305,15 +345,30 @@ def main() -> None:
                            try:
                                handlers.upsert_node(node_id, node)
                            except Exception as exc:
-                                print(
-                                    f"[warn] failed to update node snapshot for {node_id}: {exc}"
+                                config._debug_log(
+                                    "Failed to update node snapshot",
+                                    context="daemon.snapshot",
+                                    severity="warn",
+                                    node_id=node_id,
+                                    error_class=exc.__class__.__name__,
+                                    error_message=str(exc),
                                )
                                if config.DEBUG:
-                                    config._debug_log(f"node object: {node!r}")
+                                    config._debug_log(
+                                        "Snapshot node payload",
+                                        context="daemon.snapshot",
+                                        node=node,
+                                    )
                        if processed_snapshot_item:
                            initial_snapshot_sent = True
                except Exception as exc:
-                    print(f"[warn] failed to update node snapshot: {exc}")
+                    config._debug_log(
+                        "Snapshot refresh failed",
+                        context="daemon.snapshot",
+                        severity="warn",
+                        error_class=exc.__class__.__name__,
+                        error_message=str(exc),
+                    )
                    _close_interface(iface)
                    iface = None
                    stop.wait(retry_delay)
@@ -377,9 +432,11 @@ def main() -> None:
                            if believed_disconnected
                            else f"no data for {inactivity_elapsed:.0f}s"
                        )
-                        print(
-                            "[warn] mesh interface inactivity detected "
-                            f"({reason}); reconnecting"
+                        config._debug_log(
+                            "Mesh interface inactivity detected",
+                            context="daemon.interface",
+                            severity="warn",
+                            reason=reason,
                        )
                        last_inactivity_reconnect = now_monotonic
                        _close_interface(iface)
@@ -393,7 +450,11 @@ def main() -> None:
            retry_delay = max(0.0, config._RECONNECT_INITIAL_DELAY_SECS)
            stop.wait(config.SNAPSHOT_SECS)
    except KeyboardInterrupt:  # pragma: no cover - interactive only
-        config._debug_log("received KeyboardInterrupt; shutting down")
+        config._debug_log(
+            "Received KeyboardInterrupt; shutting down",
+            context="daemon.main",
+            severity="info",
+        )
        stop.set()
    finally:
        _close_interface(iface)
@@ -61,7 +61,11 @@ def upsert_node(node_id, node) -> None:
        short = _get(user, "shortName")
        long = _get(user, "longName")
        config._debug_log(
-            f"upserted node {node_id} shortName={short!r} longName={long!r}"
+            "Queued node upsert payload",
+            context="handlers.upsert_node",
+            node_id=node_id,
+            short_name=short,
+            long_name=long,
        )


@@ -244,7 +248,12 @@ def store_position_packet(packet: Mapping, decoded: Mapping) -> None:

    if config.DEBUG:
        config._debug_log(
-            f"stored position for {node_id} lat={latitude!r} lon={longitude!r}"
+            "Queued position payload",
+            context="handlers.store_position",
+            node_id=node_id,
+            latitude=latitude,
+            longitude=longitude,
+            position_time=position_time,
        )


@@ -441,7 +450,11 @@ def store_telemetry_packet(packet: Mapping, decoded: Mapping) -> None:

    if config.DEBUG:
        config._debug_log(
-            f"stored telemetry for {node_id!r} battery={battery_level!r} voltage={voltage!r}"
+            "Queued telemetry payload",
+            context="handlers.store_telemetry",
+            node_id=node_id,
+            battery_level=battery_level,
+            voltage=voltage,
        )


@@ -604,7 +617,11 @@ def store_nodeinfo_packet(packet: Mapping, decoded: Mapping) -> None:
            short = user_dict.get("shortName")
            long_name = user_dict.get("longName")
        config._debug_log(
-            f"stored nodeinfo for {node_id} shortName={short!r} longName={long_name!r}"
+            "Queued nodeinfo payload",
+            context="handlers.store_nodeinfo",
+            node_id=node_id,
+            short_name=short,
+            long_name=long_name,
        )


@@ -707,7 +724,10 @@ def store_neighborinfo_packet(packet: Mapping, decoded: Mapping) -> None:

    if config.DEBUG:
        config._debug_log(
-            f"stored neighborinfo for {node_id} neighbors={len(neighbor_entries)}"
+            "Queued neighborinfo payload",
+            context="handlers.store_neighborinfo",
+            node_id=node_id,
+            neighbors=len(neighbor_entries),
        )


@@ -783,7 +803,11 @@ def store_packet_dict(packet: Mapping) -> None:
            raw = json.dumps(packet, default=str)
        except Exception:
            raw = str(packet)
-        config._debug_log(f"packet missing from_id: {raw}")
+        config._debug_log(
+            "Packet missing from_id",
+            context="handlers.store_packet_dict",
+            packet=raw,
+        )

    snr = _first(packet, "snr", "rx_snr", "rxSnr", default=None)
    rssi = _first(packet, "rssi", "rx_rssi", "rxRssi", default=None)
@@ -812,7 +836,12 @@ def store_packet_dict(packet: Mapping) -> None:
        to_label = _canonical_node_id(to_id) or to_id
        payload_desc = "Encrypted" if text is None and encrypted else text
        config._debug_log(
-            f"stored message from {from_label!r} to {to_label!r} ch={channel} text={payload_desc!r}"
+            "Queued message payload",
+            context="handlers.store_packet_dict",
+            from_id=from_label,
+            to_id=to_label,
+            channel=channel,
+            payload=payload_desc,
        )


@@ -859,7 +888,14 @@ def on_receive(packet, interface) -> None:
        info = (
            list(packet_dict.keys()) if isinstance(packet_dict, dict) else type(packet)
        )
-        print(f"[warn] failed to store packet: {exc} | info: {info}")
+        config._debug_log(
+            "Failed to store packet",
+            context="handlers.on_receive",
+            severity="warn",
+            error_class=exc.__class__.__name__,
+            error_message=str(exc),
+            packet_info=info,
+        )


 __all__ = [
@@ -317,21 +317,38 @@ def _create_serial_interface(port: str) -> tuple[object, str]:

    port_value = (port or "").strip()
    if port_value.lower() in {"", "mock", "none", "null", "disabled"}:
-        config._debug_log(f"using dummy serial interface for port={port_value!r}")
+        config._debug_log(
+            "Using dummy serial interface",
+            context="interfaces.serial",
+            port=port_value,
+        )
        return _DummySerialInterface(), "mock"
    ble_target = _parse_ble_target(port_value)
    if ble_target:
-        config._debug_log(f"using BLE interface for address={ble_target}")
+        config._debug_log(
+            "Using BLE interface",
+            context="interfaces.ble",
+            address=ble_target,
+        )
        return _load_ble_interface()(address=ble_target), ble_target
    network_target = _parse_network_target(port_value)
    if network_target:
        host, tcp_port = network_target
-        config._debug_log(f"using TCP interface for host={host!r} port={tcp_port!r}")
+        config._debug_log(
+            "Using TCP interface",
+            context="interfaces.tcp",
+            host=host,
+            port=tcp_port,
+        )
        return (
            TCPInterface(hostname=host, portNumber=tcp_port),
            f"tcp://{host}:{tcp_port}",
        )
-    config._debug_log(f"using serial interface for port={port_value!r}")
+    config._debug_log(
+        "Using serial interface",
+        context="interfaces.serial",
+        port=port_value,
+    )
    return SerialInterface(devPath=port_value), port_value


@@ -370,12 +387,24 @@ def _create_default_interface() -> tuple[object, str]:
            return _create_serial_interface(candidate)
        except Exception as exc:  # pragma: no cover - hardware dependent
            errors.append((candidate, exc))
-            config._debug_log(f"failed to open serial candidate {candidate!r}: {exc}")
+            config._debug_log(
+                "Failed to open serial candidate",
+                context="interfaces.auto_discovery",
+                target=candidate,
+                error_class=exc.__class__.__name__,
+                error_message=str(exc),
+            )
    try:
        return _create_serial_interface(_DEFAULT_TCP_TARGET)
    except Exception as exc:  # pragma: no cover - network dependent
        errors.append((_DEFAULT_TCP_TARGET, exc))
-        config._debug_log(f"failed to open TCP fallback {_DEFAULT_TCP_TARGET!r}: {exc}")
+        config._debug_log(
+            "Failed to open TCP fallback",
+            context="interfaces.auto_discovery",
+            target=_DEFAULT_TCP_TARGET,
+            error_class=exc.__class__.__name__,
+            error_message=str(exc),
+        )
    if errors:
        summary = "; ".join(f"{target}: {error}" for target, error in errors)
        raise NoAvailableMeshInterface(
@@ -81,7 +81,14 @@ def _post_json(
        with urllib.request.urlopen(req, timeout=10) as resp:
            resp.read()
    except Exception as exc:  # pragma: no cover - exercised in production
-        config._debug_log(f"[warn] POST {url} failed: {exc}")
+        config._debug_log(
+            "POST request failed",
+            context="queue.post_json",
+            severity="warn",
+            url=url,
+            error_class=exc.__class__.__name__,
+            error_message=str(exc),
+        )


 def _enqueue_post_json(
@@ -14,6 +14,7 @@

 import base64
 import importlib
+import re
 import sys
 import threading
 import types
@@ -1335,7 +1336,8 @@ def test_on_receive_logs_when_store_fails(mesh_module, monkeypatch, capsys):
    mesh.on_receive(object(), interface=None)

    captured = capsys.readouterr()
-    assert "failed to store packet" in captured.out
+    assert "context=handlers.on_receive" in captured.out
+    assert "Failed to store packet" in captured.out


 def test_node_items_snapshot_iterable_without_items(mesh_module):
@@ -1369,7 +1371,14 @@ def test_debug_log_emits_when_enabled(mesh_module, monkeypatch, capsys):
    mesh._debug_log("hello world")

    captured = capsys.readouterr()
-    assert "[debug] hello world" in captured.out
+    lines = [line for line in captured.out.splitlines() if "hello world" in line]
+    assert lines, "expected debug log output"
+    log_line = lines[-1]
+    pattern = (
+        r"\[\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{3}Z\] \[potato-mesh\] \[debug\] "
+    )
+    assert re.match(pattern, log_line), f"unexpected log format: {log_line}"
+    assert log_line.endswith("hello world")


 def test_event_wait_allows_default_timeout_handles_short_signature(
@@ -1503,7 +1512,8 @@ def test_post_json_logs_failures(mesh_module, monkeypatch, capsys):
    mesh._post_json("/api/test", {"foo": "bar"})

    captured = capsys.readouterr()
-    assert "[warn] POST https://example.invalid/api/test failed" in captured.out
+    assert "context=queue.post_json" in captured.out
+    assert "POST request failed" in captured.out


 def test_queue_post_json_skips_when_active(mesh_module, monkeypatch):
@@ -1557,7 +1567,8 @@ def test_upsert_node_logs_in_debug(mesh_module, monkeypatch, capsys):

    assert captured
    out = capsys.readouterr().out
-    assert "upserted node !node" in out
+    assert "context=handlers.upsert_node" in out
+    assert "Queued node upsert payload" in out


 def test_coerce_int_and_float_cover_edge_cases(mesh_module):
@@ -1783,7 +1794,8 @@ def test_store_nodeinfo_packet_debug(mesh_module, monkeypatch, capsys):
    mesh.store_packet_dict(packet)

    out = capsys.readouterr().out
-    assert "stored nodeinfo" in out
+    assert "context=handlers.store_nodeinfo" in out
+    assert "Queued nodeinfo payload" in out


 def test_store_neighborinfo_packet_debug(mesh_module, monkeypatch, capsys):
@@ -1815,7 +1827,8 @@ def test_store_neighborinfo_packet_debug(mesh_module, monkeypatch, capsys):

    assert captured
    out = capsys.readouterr().out
-    assert "stored neighborinfo" in out
+    assert "context=handlers.store_neighborinfo" in out
+    assert "Queued neighborinfo payload" in out


 def test_store_packet_dict_debug_message(mesh_module, monkeypatch, capsys):
@@ -1841,7 +1854,8 @@ def test_store_packet_dict_debug_message(mesh_module, monkeypatch, capsys):

    assert captured
    out = capsys.readouterr().out
-    assert "stored message" in out
+    assert "context=handlers.store_packet_dict" in out
+    assert "Queued message payload" in out


 def test_on_receive_skips_seen_packets(mesh_module):
@@ -37,6 +37,7 @@ require "digest"
 require_relative "config"
 require_relative "sanitizer"
 require_relative "meta"
+require_relative "logging"
 require_relative "application/helpers"
 require_relative "application/errors"
 require_relative "application/database"
@@ -106,7 +107,7 @@ module PotatoMesh
      set :federation_thread, nil
      set :port, resolve_port

-      app_logger = Logger.new($stdout)
+      app_logger = PotatoMesh::Logging.build_logger($stdout)
      set :logger, app_logger
      use Rack::CommonLogger, app_logger
      use Rack::Deflater
@@ -129,9 +130,17 @@ module PotatoMesh
        start_initial_federation_announcement!
        start_federation_announcer!
      elsif federation_enabled?
-        debug_log("Federation announcements disabled in test environment")
+        debug_log(
+          "Federation announcements disabled",
+          context: "federation",
+          reason: "test environment",
+        )
      else
-        debug_log("Federation announcements disabled by configuration or private mode")
+        debug_log(
+          "Federation announcements disabled",
+          context: "federation",
+          reason: "configuration",
+        )
      end
    end
  end
@@ -137,8 +137,12 @@ module PotatoMesh

        if inserted
          debug_log(
-            "ensure_unknown_node created hidden node_id=#{node_id} from=#{node_ref.inspect} " \
-            "fallback=#{fallback_num.inspect} heard_time=#{heard_time.inspect}",
+            "Created hidden placeholder node",
+            context: "data_processing.ensure_unknown_node",
+            node_id: node_id,
+            reference: node_ref,
+            fallback: fallback_num,
+            heard_time: heard_time,
          )
        end

@@ -182,8 +186,11 @@ module PotatoMesh

        if updated
          debug_log(
-            "touch_node_last_seen updated last_heard node_id=#{node_id} timestamp=#{timestamp} " \
-            "source=#{(source || :unknown).inspect}",
+            "Updated node last seen timestamp",
+            context: "data_processing.touch_node_last_seen",
+            node_id: node_id,
+            timestamp: timestamp,
+            source: source || :unknown,
          )
        end

@@ -78,7 +78,12 @@ module PotatoMesh
          db.execute_batch(File.read(sql_file))
        end
      rescue SQLite3::SQLException, Errno::ENOENT => e
-        warn "[warn] failed to apply schema upgrade: #{e.message}"
+        warn_log(
+          "Failed to apply schema upgrade",
+          context: "database.schema",
+          error_class: e.class.name,
+          error_message: e.message,
+        )
      ensure
        db&.close
      end
@@ -71,7 +71,10 @@ module PotatoMesh
        db = open_database
        upsert_instance_record(db, attributes, signature)
        debug_log(
-          "Registered self instance record #{attributes[:domain]} (id: #{attributes[:id]})",
+          "Registered self instance record",
+          context: "federation.instances",
+          domain: attributes[:domain],
+          instance_id: attributes[:id],
        )
        [attributes, signature]
      ensure
@@ -119,14 +122,28 @@ module PotatoMesh
              connection.request(request)
            end
            if response.is_a?(Net::HTTPSuccess)
-              debug_log("Announced instance to #{uri}")
+              debug_log(
+                "Published federation announcement",
+                context: "federation.announce",
+                target: uri.to_s,
+                status: response.code,
+              )
              return true
            end
            debug_log(
-              "Federation announcement to #{uri} failed with status #{response.code}",
+              "Federation announcement failed",
+              context: "federation.announce",
+              target: uri.to_s,
+              status: response.code,
            )
          rescue StandardError => e
-            debug_log("Federation announcement to #{uri} failed: #{e.message}")
+            warn_log(
+              "Federation announcement raised exception",
+              context: "federation.announce",
+              target: uri.to_s,
+              error_class: e.class.name,
+              error_message: e.message,
+            )
          end
        end

@@ -142,9 +159,13 @@ module PotatoMesh
        domains.each do |domain|
          announce_instance_to_domain(domain, payload_json)
        end
-        debug_log(
-          "Federation announcement cycle complete (targets: #{domains.join(", ")})",
-        ) unless domains.empty?
+        unless domains.empty?
+          debug_log(
+            "Federation announcement cycle complete",
+            context: "federation.announce",
+            targets: domains,
+          )
+        end
      end

      def start_federation_announcer!
@@ -157,7 +178,12 @@ module PotatoMesh
            begin
              announce_instance_to_all_domains
            rescue StandardError => e
-              debug_log("Federation announcement loop error: #{e.message}")
+              warn_log(
+                "Federation announcement loop error",
+                context: "federation.announce",
+                error_class: e.class.name,
+                error_message: e.message,
+              )
            end
          end
        end
@@ -174,7 +200,12 @@ module PotatoMesh
          begin
            announce_instance_to_all_domains
          rescue StandardError => e
-            debug_log("Initial federation announcement failed: #{e.message}")
+            warn_log(
+              "Initial federation announcement failed",
+              context: "federation.announce",
+              error_class: e.class.name,
+              error_message: e.message,
+            )
          ensure
            set(:initial_federation_thread, nil)
          end
@@ -199,9 +199,26 @@ module PotatoMesh
        end
      end

-      def debug_log(message)
-        logger = settings.logger if respond_to?(:settings)
-        logger&.debug(message)
+      # Emit a structured debug log entry tagged with the calling context.
+      #
+      # @param message [String] text to emit.
+      # @param context [String] logical source of the message.
+      # @param metadata [Hash] additional structured key/value data.
+      # @return [void]
+      def debug_log(message, context: "app", **metadata)
+        logger = PotatoMesh::Logging.logger_for(self)
+        PotatoMesh::Logging.log(logger, :debug, message, context: context, **metadata)
+      end
+
+      # Emit a structured warning log entry tagged with the calling context.
+      #
+      # @param message [String] text to emit.
+      # @param context [String] logical source of the message.
+      # @param metadata [Hash] additional structured key/value data.
+      # @return [void]
+      def warn_log(message, context: "app", **metadata)
+        logger = PotatoMesh::Logging.logger_for(self)
+        PotatoMesh::Logging.log(logger, :warn, message, context: context, **metadata)
      end

      def private_mode?
@@ -53,7 +53,12 @@ module PotatoMesh
        end
        [key, true]
      rescue OpenSSL::PKey::PKeyError, ArgumentError => e
-        warn "[warn] failed to load instance private key, generating a new key: #{e.message}"
+        warn_log(
+          "Failed to load instance private key",
+          context: "identity.keys",
+          error_class: e.class.name,
+          error_message: e.message,
+        )
        key = OpenSSL::PKey::RSA.new(2048)
        File.open(keyfile_path, File::WRONLY | File::CREAT | File::TRUNC, 0o600) do |file|
          file.write(key.export)
@@ -124,9 +129,19 @@ module PotatoMesh
          file.write("\n") unless json_output.end_with?("\n")
        end

-        debug_log("Updated #{PotatoMesh::Config.well_known_relative_path} content: #{json_output}")
        debug_log(
-          "Updated #{PotatoMesh::Config.well_known_relative_path} signature (#{PotatoMesh::Config.instance_signature_algorithm}): #{signature}",
+          "Refreshed well-known document content",
+          context: "identity.well_known",
+          path: PotatoMesh::Config.well_known_relative_path,
+          bytes: json_output.bytesize,
+          document: json_output,
+        )
+        debug_log(
+          "Refreshed well-known document signature",
+          context: "identity.well_known",
+          path: PotatoMesh::Config.well_known_relative_path,
+          algorithm: PotatoMesh::Config.instance_signature_algorithm,
+          signature: signature,
        )
      end

@@ -145,31 +160,28 @@ module PotatoMesh
      end

      def log_instance_public_key
-        debug_log("Instance public key (PEM):\n#{app_constant(:INSTANCE_PUBLIC_KEY_PEM)}")
+        debug_log(
+          "Loaded instance public key",
+          context: "identity.keys",
+          public_key_pem: app_constant(:INSTANCE_PUBLIC_KEY_PEM),
+        )
        if app_constant(:INSTANCE_KEY_GENERATED)
          debug_log(
-            "Generated new instance private key at #{PotatoMesh::Config.keyfile_path}",
+            "Generated new instance private key",
+            context: "identity.keys",
+            path: PotatoMesh::Config.keyfile_path,
          )
        end
      end

      def log_instance_domain_resolution
-        message = case app_constant(:INSTANCE_DOMAIN_SOURCE)
-          when :environment
-            "Instance domain configured from INSTANCE_DOMAIN environment variable: #{app_constant(:INSTANCE_DOMAIN).inspect}"
-          when :reverse_dns
-            "Instance domain resolved via reverse DNS lookup: #{app_constant(:INSTANCE_DOMAIN).inspect}"
-          when :public_ip
-            "Instance domain resolved using public IP address: #{app_constant(:INSTANCE_DOMAIN).inspect}"
-          when :protected_ip
-            "Instance domain resolved using protected network IP address: #{app_constant(:INSTANCE_DOMAIN).inspect}"
-          when :local_ip
-            "Instance domain defaulted to local IP address: #{app_constant(:INSTANCE_DOMAIN).inspect}"
-          else
-            "Instance domain could not be determined from the environment or local network."
-          end
-
-        debug_log(message)
+        source = app_constant(:INSTANCE_DOMAIN_SOURCE) || :unknown
+        debug_log(
+          "Resolved instance domain",
+          context: "identity.domain",
+          source: source,
+          domain: app_constant(:INSTANCE_DOMAIN),
+        )
      end
    end
  end
@@ -188,8 +188,18 @@ module PotatoMesh
        rows.each do |r|
          if PotatoMesh::Config.debug? && (r["from_id"].nil? || r["from_id"].to_s.empty?)
            raw = db.execute("SELECT * FROM messages WHERE id = ?", [r["id"]]).first
-            Kernel.warn "[debug] messages row before join: #{raw.inspect}"
-            Kernel.warn "[debug] row after join: #{r.inspect}"
+            debug_log(
+              "Message join produced empty sender",
+              context: "queries.messages",
+              stage: "before_join",
+              row: raw,
+            )
+            debug_log(
+              "Message join produced empty sender",
+              context: "queries.messages",
+              stage: "after_join",
+              row: r,
+            )
          end
          node = {}
          r.keys.each do |k|
@@ -233,7 +243,12 @@ module PotatoMesh
          end

          if PotatoMesh::Config.debug? && (r["from_id"].nil? || r["from_id"].to_s.empty?)
-            Kernel.warn "[debug] row after processing: #{r.inspect}"
+            debug_log(
+              "Message row missing sender after processing",
+              context: "queries.messages",
+              stage: "after_processing",
+              row: r,
+            )
          end
        end
        rows
@@ -63,13 +63,23 @@ module PotatoMesh
            content_type :json
            begin
              payload = JSON.parse(read_json_body)
-            rescue JSON::ParserError
-              warn "[warn] instance registration rejected: invalid JSON"
+            rescue JSON::ParserError => e
+              warn_log(
+                "Instance registration rejected",
+                context: "ingest.register",
+                reason: "invalid JSON",
+                error_class: e.class.name,
+                error_message: e.message,
+              )
              halt 400, { error: "invalid JSON" }.to_json
            end

            unless payload.is_a?(Hash)
-              warn "[warn] instance registration rejected: payload is not an object"
+              warn_log(
+                "Instance registration rejected",
+                context: "ingest.register",
+                reason: "payload is not an object",
+              )
              halt 400, { error: "invalid payload" }.to_json
            end

@@ -102,23 +112,43 @@ module PotatoMesh
            }

            if [attributes[:id], attributes[:domain], attributes[:pubkey], signature, attributes[:last_update_time]].any?(&:nil?)
-              warn "[warn] instance registration rejected: missing required fields"
+              warn_log(
+                "Instance registration rejected",
+                context: "ingest.register",
+                reason: "missing required fields",
+              )
              halt 400, { error: "missing required fields" }.to_json
            end

            unless verify_instance_signature(attributes, signature, attributes[:pubkey])
-              warn "[warn] instance registration rejected for #{attributes[:domain]}: invalid signature"
+              warn_log(
+                "Instance registration rejected",
+                context: "ingest.register",
+                domain: attributes[:domain],
+                reason: "invalid signature",
+              )
              halt 400, { error: "invalid signature" }.to_json
            end

            if attributes[:is_private]
-              warn "[warn] instance registration rejected for #{attributes[:domain]}: instance marked private"
+              warn_log(
+                "Instance registration rejected",
+                context: "ingest.register",
+                domain: attributes[:domain],
+                reason: "instance marked private",
+              )
              halt 403, { error: "instance marked private" }.to_json
            end

            ip = ip_from_domain(attributes[:domain])
            if ip && restricted_ip_address?(ip)
-              warn "[warn] instance registration rejected for #{attributes[:domain]}: restricted IP address"
+              warn_log(
+                "Instance registration rejected",
+                context: "ingest.register",
+                domain: attributes[:domain],
+                reason: "restricted IP address",
+                resolved_ip: ip,
+              )
              halt 400, { error: "restricted domain" }.to_json
            end

@@ -126,13 +156,24 @@ module PotatoMesh
            unless well_known
              details_list = Array(well_known_meta).map(&:to_s)
              details = details_list.empty? ? "no response" : details_list.join("; ")
-              warn "[warn] instance registration rejected for #{attributes[:domain]}: failed to fetch well-known document (#{details})"
+              warn_log(
+                "Instance registration rejected",
+                context: "ingest.register",
+                domain: attributes[:domain],
+                reason: "failed to fetch well-known document",
+                details: details,
+              )
              halt 400, { error: "failed to verify well-known document" }.to_json
            end

            valid, reason = validate_well_known_document(well_known, attributes[:domain], attributes[:pubkey])
            unless valid
-              warn "[warn] instance registration rejected for #{attributes[:domain]}: #{reason}"
+              warn_log(
+                "Instance registration rejected",
+                context: "ingest.register",
+                domain: attributes[:domain],
+                reason: reason || "invalid well-known document",
+              )
              halt 400, { error: reason || "invalid well-known document" }.to_json
            end

@@ -140,19 +181,35 @@ module PotatoMesh
            unless remote_nodes
              details_list = Array(node_source).map(&:to_s)
              details = details_list.empty? ? "no response" : details_list.join("; ")
-              warn "[warn] instance registration rejected for #{attributes[:domain]}: failed to fetch nodes (#{details})"
+              warn_log(
+                "Instance registration rejected",
+                context: "ingest.register",
+                domain: attributes[:domain],
+                reason: "failed to fetch nodes",
+                details: details,
+              )
              halt 400, { error: "failed to fetch nodes" }.to_json
            end

            fresh, freshness_reason = validate_remote_nodes(remote_nodes)
            unless fresh
-              warn "[warn] instance registration rejected for #{attributes[:domain]}: #{freshness_reason}"
+              warn_log(
+                "Instance registration rejected",
+                context: "ingest.register",
+                domain: attributes[:domain],
+                reason: freshness_reason || "stale node data",
+              )
              halt 400, { error: freshness_reason || "stale node data" }.to_json
            end

            db = open_database
            upsert_instance_record(db, attributes, signature)
-            debug_log("Registered instance #{attributes[:domain]} (id: #{attributes[:id]})")
+            debug_log(
+              "Registered remote instance",
+              context: "ingest.register",
+              domain: attributes[:domain],
+              instance_id: attributes[:id],
+            )
            status 201
            { status: "registered" }.to_json
          ensure
@@ -0,0 +1,87 @@
+# frozen_string_literal: true
+
+require "logger"
+require "time"
+
+module PotatoMesh
+  # Logging utilities shared across the web application.
+  module Logging
+    LOGGER_NAME = "potato-mesh" # :nodoc:
+
+    module_function
+
+    # Build a logger configured with the potato-mesh formatter.
+    #
+    # @param io [#write] destination for log output.
+    # @return [Logger] configured logger instance.
+    def build_logger(io = $stdout)
+      logger = Logger.new(io)
+      logger.progname = LOGGER_NAME
+      logger.formatter = method(:formatter)
+      logger
+    end
+
+    # Format log entries with a consistent structure understood by the UI.
+    #
+    # @param severity [String] Ruby logger severity constant (e.g., "DEBUG").
+    # @param time [Time] timestamp when the log entry was created.
+    # @param progname [String, nil] optional application name emitting the log.
+    # @param message [String] body of the log message.
+    # @return [String] formatted log entry.
+    def formatter(severity, time, progname, message)
+      timestamp = time.utc.iso8601(3)
+      body = message.is_a?(String) ? message : message.inspect
+      "[#{timestamp}] [#{progname || LOGGER_NAME}] [#{severity.downcase}] #{body}\n"
+    end
+
+    # Emit a structured log entry to the provided logger instance.
+    #
+    # @param logger [Logger, nil] logger to emit against.
+    # @param severity [Symbol] target severity (e.g., :debug, :info).
+    # @param message [String] primary message text.
+    # @param context [String, nil] logical component generating the entry.
+    # @param metadata [Hash] supplemental structured data for the log.
+    # @return [void]
+    def log(logger, severity, message, context: nil, **metadata)
+      return unless logger
+
+      parts = []
+      parts << "context=#{context}" if context
+      metadata.each do |key, value|
+        parts << format_metadata_pair(key, value)
+      end
+      parts << message
+
+      logger.public_send(severity, parts.join(" "))
+    end
+
+    # Retrieve the canonical logger for the web application.
+    #
+    # @param target [Object, nil] object with optional +settings.logger+ accessor.
+    # @return [Logger, nil] logger instance when available.
+    def logger_for(target = nil)
+      if target.respond_to?(:settings) && target.settings.respond_to?(:logger)
+        return target.settings.logger
+      end
+
+      if defined?(PotatoMesh::Application) &&
+         PotatoMesh::Application.respond_to?(:settings) &&
+         PotatoMesh::Application.settings.respond_to?(:logger)
+        return PotatoMesh::Application.settings.logger
+      end
+
+      nil
+    end
+
+    # Format metadata key/value pairs for structured logging output.
+    #
+    # @param key [Symbol, String]
+    # @param value [Object]
+    # @return [String]
+    def format_metadata_pair(key, value)
+      "#{key}=#{value.inspect}"
+    end
+
+    private_class_method :format_metadata_pair
+  end
+end
@@ -980,7 +980,12 @@ RSpec.describe "Potato Mesh Sinatra app" do
    it "rejects registrations with invalid signatures" do
      invalid_payload = instance_payload.merge("signature" => Base64.strict_encode64("invalid"))

-      expect_any_instance_of(Object).to receive(:warn).with(/invalid signature/).at_least(:once)
+      expect_any_instance_of(Sinatra::Application).to receive(:warn_log).with(
+        "Instance registration rejected",
+        context: "ingest.register",
+        domain: domain,
+        reason: "invalid signature",
+      ).at_least(:once)

      post "/api/instances", invalid_payload.to_json, { "CONTENT_TYPE" => "application/json" }

@@ -1005,7 +1010,13 @@ RSpec.describe "Potato Mesh Sinatra app" do
        "signature" => restricted_signature,
      )

-      expect_any_instance_of(Object).to receive(:warn).with(/restricted IP address/).at_least(:once)
+      expect_any_instance_of(Sinatra::Application).to receive(:warn_log).with(
+        "Instance registration rejected",
+        context: "ingest.register",
+        domain: restricted_domain,
+        reason: "restricted IP address",
+        resolved_ip: an_instance_of(IPAddr),
+      ).at_least(:once)

      post "/api/instances", restricted_payload.to_json, { "CONTENT_TYPE" => "application/json" }

@@ -2386,7 +2397,7 @@ RSpec.describe "Potato Mesh Sinatra app" do
    context "when DEBUG logging is enabled" do
      it "logs diagnostics for messages missing a sender" do
        allow(PotatoMesh::Config).to receive(:debug?).and_return(true)
-        allow(Kernel).to receive(:warn)
+        allow(PotatoMesh::Logging).to receive(:log).and_call_original

        message_id = 987_654
        payload = {
@@ -2402,14 +2413,29 @@ RSpec.describe "Potato Mesh Sinatra app" do
        get "/api/messages"
        expect(last_response).to be_ok

-        expect(Kernel).to have_received(:warn).with(
-          a_string_matching(/\[debug\] messages row before join: .*"id"\s*=>\s*#{message_id}/),
+        expect(PotatoMesh::Logging).to have_received(:log).with(
+          kind_of(Logger),
+          :debug,
+          "Message join produced empty sender",
+          context: "queries.messages",
+          stage: "before_join",
+          row: a_hash_including("id" => message_id),
        )
-        expect(Kernel).to have_received(:warn).with(
-          a_string_matching(/\[debug\] row after join: .*"id"\s*=>\s*#{message_id}/),
+        expect(PotatoMesh::Logging).to have_received(:log).with(
+          kind_of(Logger),
+          :debug,
+          "Message join produced empty sender",
+          context: "queries.messages",
+          stage: "after_join",
+          row: a_hash_including("id" => message_id),
        )
-        expect(Kernel).to have_received(:warn).with(
-          a_string_matching(/\[debug\] row after processing: .*"id"\s*=>\s*#{message_id}/),
+        expect(PotatoMesh::Logging).to have_received(:log).with(
+          kind_of(Logger),
+          :debug,
+          "Message row missing sender after processing",
+          context: "queries.messages",
+          stage: "after_processing",
+          row: a_hash_including("id" => message_id),
        )

        messages = JSON.parse(last_response.body)
@@ -0,0 +1,37 @@
+# frozen_string_literal: true
+
+require "spec_helper"
+require "potato_mesh/logging"
+
+describe PotatoMesh::Logging do
+  describe ".formatter" do
+    it "generates structured log entries" do
+      timestamp = Time.utc(2024, 1, 2, 3, 4, 5, 678_000)
+      formatted = described_class.formatter("DEBUG", timestamp, "potato-mesh", "hello")
+
+      expect(formatted).to eq("[2024-01-02T03:04:05.678Z] [potato-mesh] [debug] hello\n")
+    end
+  end
+
+  describe ".log" do
+    it "passes structured metadata to the logger" do
+      logger = instance_double(Logger)
+
+      expect(logger).to receive(:debug).with("context=test foo=\"bar\" hello")
+
+      described_class.log(logger, :debug, "hello", context: "test", foo: "bar")
+    end
+  end
+
+  describe ".logger_for" do
+    it "returns the logger from an object with settings" do
+      container = Class.new do
+        def settings
+          Struct.new(:logger).new(:logger)
+        end
+      end
+
+      expect(described_class.logger_for(container.new)).to eq(:logger)
+    end
+  end
+end