diff --git a/README.md b/README.md index 08e9e9e..7e4bafd 100644 --- a/README.md +++ b/README.md @@ -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 diff --git a/data/mesh_ingestor/config.py b/data/mesh_ingestor/config.py index e54254c..c84505f 100644 --- a/data/mesh_ingestor/config.py +++ b/data/mesh_ingestor/config.py @@ -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__ = [ diff --git a/data/mesh_ingestor/daemon.py b/data/mesh_ingestor/daemon.py index 592c559..ffad927 100644 --- a/data/mesh_ingestor/daemon.py +++ b/data/mesh_ingestor/daemon.py @@ -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) diff --git a/data/mesh_ingestor/handlers.py b/data/mesh_ingestor/handlers.py index 115e93c..54b994e 100644 --- a/data/mesh_ingestor/handlers.py +++ b/data/mesh_ingestor/handlers.py @@ -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__ = [ diff --git a/data/mesh_ingestor/interfaces.py b/data/mesh_ingestor/interfaces.py index 7fae1dd..f601b30 100644 --- a/data/mesh_ingestor/interfaces.py +++ b/data/mesh_ingestor/interfaces.py @@ -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( diff --git a/data/mesh_ingestor/queue.py b/data/mesh_ingestor/queue.py index bc882cd..fb63acc 100644 --- a/data/mesh_ingestor/queue.py +++ b/data/mesh_ingestor/queue.py @@ -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( diff --git a/tests/test_mesh.py b/tests/test_mesh.py index 014a45c..5f169d2 100644 --- a/tests/test_mesh.py +++ b/tests/test_mesh.py @@ -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): diff --git a/web/lib/potato_mesh/application.rb b/web/lib/potato_mesh/application.rb index 2fc1797..4beaf51 100644 --- a/web/lib/potato_mesh/application.rb +++ b/web/lib/potato_mesh/application.rb @@ -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 diff --git a/web/lib/potato_mesh/application/data_processing.rb b/web/lib/potato_mesh/application/data_processing.rb index dff7925..b4a4a54 100644 --- a/web/lib/potato_mesh/application/data_processing.rb +++ b/web/lib/potato_mesh/application/data_processing.rb @@ -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 diff --git a/web/lib/potato_mesh/application/database.rb b/web/lib/potato_mesh/application/database.rb index 94b1f05..1613734 100644 --- a/web/lib/potato_mesh/application/database.rb +++ b/web/lib/potato_mesh/application/database.rb @@ -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 diff --git a/web/lib/potato_mesh/application/federation.rb b/web/lib/potato_mesh/application/federation.rb index a5a6bae..35bd659 100644 --- a/web/lib/potato_mesh/application/federation.rb +++ b/web/lib/potato_mesh/application/federation.rb @@ -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 diff --git a/web/lib/potato_mesh/application/helpers.rb b/web/lib/potato_mesh/application/helpers.rb index 97d757e..9829a04 100644 --- a/web/lib/potato_mesh/application/helpers.rb +++ b/web/lib/potato_mesh/application/helpers.rb @@ -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? diff --git a/web/lib/potato_mesh/application/identity.rb b/web/lib/potato_mesh/application/identity.rb index 1feb639..ffce85d 100644 --- a/web/lib/potato_mesh/application/identity.rb +++ b/web/lib/potato_mesh/application/identity.rb @@ -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 diff --git a/web/lib/potato_mesh/application/queries.rb b/web/lib/potato_mesh/application/queries.rb index 74a8fee..8b7659e 100644 --- a/web/lib/potato_mesh/application/queries.rb +++ b/web/lib/potato_mesh/application/queries.rb @@ -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 diff --git a/web/lib/potato_mesh/application/routes/ingest.rb b/web/lib/potato_mesh/application/routes/ingest.rb index d4b93e0..68bea8f 100644 --- a/web/lib/potato_mesh/application/routes/ingest.rb +++ b/web/lib/potato_mesh/application/routes/ingest.rb @@ -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 diff --git a/web/lib/potato_mesh/logging.rb b/web/lib/potato_mesh/logging.rb new file mode 100644 index 0000000..1e299ab --- /dev/null +++ b/web/lib/potato_mesh/logging.rb @@ -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 diff --git a/web/spec/app_spec.rb b/web/spec/app_spec.rb index 0802d6c..9af10db 100644 --- a/web/spec/app_spec.rb +++ b/web/spec/app_spec.rb @@ -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) diff --git a/web/spec/logging_spec.rb b/web/spec/logging_spec.rb new file mode 100644 index 0000000..f57d1c8 --- /dev/null +++ b/web/spec/logging_spec.rb @@ -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