From 89d0141643e1da6a4157dffe7f4b4c398cfeedc9 Mon Sep 17 00:00:00 2001 From: kc1awv Date: Wed, 31 Dec 2025 10:43:18 -0500 Subject: [PATCH] Begin adding in logging configuration support --- README.md | 22 ++++++ rrcd/cli.py | 61 +++++++++++++-- rrcd/config.py | 17 ++-- rrcd/logging_config.py | 103 ++++++++++++++++++++++++ rrcd/service.py | 172 ++++++++++++++++++++++++++++++++++++++++- 5 files changed, 354 insertions(+), 21 deletions(-) create mode 100644 rrcd/logging_config.py diff --git a/README.md b/README.md index 1b56144..a9330dd 100644 --- a/README.md +++ b/README.md @@ -46,6 +46,28 @@ Optional: You need a working Reticulum configuration (see Reticulum docs). +## Logging + +By default, `rrcd` logs to stderr (good for systemd/journald). You can configure +logging in `~/.rrcd/rrcd.toml`: + +```toml +[logging] +level = "INFO" # set to DEBUG for connection/packet tracing +rns_level = "WARNING" # python-logging level for the "RNS" logger (if used) +console = true +file = "" # e.g. "~/.rrcd/rrcd.log" (empty disables) +format = "%(asctime)s %(levelname)s %(name)s[%(threadName)s]: %(message)s" +datefmt = "" +``` + +CLI overrides are also available: + +- `rrcd --log-level DEBUG` +- `rrcd --log-file ~/.rrcd/rrcd.log` + +If you use `/reload`, logging settings are applied immediately. + ## Compatibility `rrcd` implements the core RRC protocol as described in the RRC docs. diff --git a/rrcd/cli.py b/rrcd/cli.py index 0f3af73..8c7e92a 100644 --- a/rrcd/cli.py +++ b/rrcd/cli.py @@ -1,7 +1,6 @@ from __future__ import annotations import argparse -import logging import os import sys from dataclasses import asdict, replace @@ -9,6 +8,7 @@ from dataclasses import asdict, replace import RNS from .config import HubRuntimeConfig +from .logging_config import configure_logging from .paths import ( default_config_path, default_identity_path, @@ -32,6 +32,23 @@ def _apply_config_file(cfg: HubRuntimeConfig, path: str) -> HubRuntimeConfig: if isinstance(hub, dict): data = {**data, **hub} + log_table = data.get("logging") if isinstance(data, dict) else None + if isinstance(log_table, dict): + mapped: dict[str, object] = {} + if "level" in log_table: + mapped["log_level"] = log_table.get("level") + if "rns_level" in log_table: + mapped["log_rns_level"] = log_table.get("rns_level") + if "console" in log_table: + mapped["log_console"] = log_table.get("console") + if "file" in log_table: + mapped["log_file"] = log_table.get("file") + if "format" in log_table: + mapped["log_format"] = log_table.get("format") + if "datefmt" in log_table: + mapped["log_datefmt"] = log_table.get("datefmt") + data = {**data, **mapped} + allowed = set(asdict(cfg).keys()) # This identifies where to reload/persist from; do not let the file override it. allowed.discard("config_path") @@ -50,6 +67,10 @@ def _apply_config_file(cfg: HubRuntimeConfig, path: str) -> HubRuntimeConfig: updates["configdir"] = None if "greeting" in updates and updates["greeting"] == "": updates["greeting"] = None + if "log_file" in updates and updates["log_file"] == "": + updates["log_file"] = None + if "log_datefmt" in updates and updates["log_datefmt"] == "": + updates["log_datefmt"] = None return replace(cfg, **updates) if updates else cfg @@ -133,6 +154,24 @@ rate_limit_msgs_per_minute = 240 # Hub-initiated liveness checks (0 disables). ping_interval_s = 0.0 ping_timeout_s = 0.0 + +[logging] + +# Log level for rrcd itself. +level = "INFO" + +# Log level for Reticulum/RNS Python logging (if used by your install). +rns_level = "WARNING" + +# Log to stderr (systemd/journald friendly). +console = true + +# Optional file path for logs (leave empty to disable). +file = "" + +# Log format and optional date format. +format = "%(asctime)s %(levelname)s %(name)s[%(threadName)s]: %(message)s" +datefmt = "" """ with open(config_path, "w", encoding="utf-8") as f: @@ -286,8 +325,14 @@ def _build_arg_parser() -> argparse.ArgumentParser: p.add_argument( "--log-level", - default="INFO", - help="Logging level (DEBUG, INFO, WARNING, ERROR)", + default=None, + help="Logging level override (DEBUG, INFO, WARNING, ERROR). Default comes from config.", + ) + + p.add_argument( + "--log-file", + default=None, + help="Log file path override (empty disables file logging). Default comes from config.", ) return p @@ -349,10 +394,12 @@ def main(argv: list[str] | None = None) -> None: if args.ping_timeout is not None: cfg = replace(cfg, ping_timeout_s=float(args.ping_timeout)) - logging.basicConfig( - level=getattr(logging, str(args.log_level).upper(), logging.INFO), - format="%(asctime)s %(levelname)s %(name)s: %(message)s", - ) + if args.log_level is not None: + cfg = replace(cfg, log_level=str(args.log_level)) + if args.log_file is not None: + cfg = replace(cfg, log_file=str(args.log_file) if str(args.log_file) else None) + + configure_logging(cfg, override_level=args.log_level, override_file=args.log_file) svc = HubService(cfg) svc.start() diff --git a/rrcd/config.py b/rrcd/config.py index 789c461..b58c200 100644 --- a/rrcd/config.py +++ b/rrcd/config.py @@ -14,26 +14,21 @@ class HubRuntimeConfig: announce_period_s: float = 0.0 hub_name: str = "rrc" greeting: str | None = None - # Hex-encoded Reticulum identity hashes trusted as operators. trusted_identities: tuple[str, ...] = () - # Hex-encoded Reticulum identity hashes banned from connecting. banned_identities: tuple[str, ...] = () - - # Room registry maintenance (registered rooms are stored in room_registry_path). - # Pruning only applies to registered rooms with no connected members. room_registry_prune_after_s: float = 30 * 24 * 3600 room_registry_prune_interval_s: float = 3600.0 - # Invite timeout for keyed rooms (+k). Invites are removed on join or expiry. room_invite_timeout_s: float = 900.0 include_joined_member_list: bool = False - - # Optional policy controls. - # Maximum accepted/stored nickname length (Unicode characters). 0 disables - # length limiting. nick_max_chars: int = 32 - max_rooms_per_session: int = 32 max_room_name_len: int = 64 rate_limit_msgs_per_minute: int = 240 ping_interval_s: float = 0.0 ping_timeout_s: float = 0.0 + log_level: str = "INFO" + log_rns_level: str = "WARNING" + log_console: bool = True + log_file: str | None = None + log_format: str = "%(asctime)s %(levelname)s %(name)s[%(threadName)s]: %(message)s" + log_datefmt: str | None = None diff --git a/rrcd/logging_config.py b/rrcd/logging_config.py new file mode 100644 index 0000000..202c702 --- /dev/null +++ b/rrcd/logging_config.py @@ -0,0 +1,103 @@ +from __future__ import annotations + +import logging +import os +from pathlib import Path +from typing import Any + +from .config import HubRuntimeConfig + + +def _parse_level(value: Any, default: int) -> int: + if value is None: + return default + if isinstance(value, int): + return value + text = str(value).strip().upper() + if not text: + return default + + mapping: dict[str, int] = { + "CRITICAL": logging.CRITICAL, + "ERROR": logging.ERROR, + "WARN": logging.WARNING, + "WARNING": logging.WARNING, + "INFO": logging.INFO, + "DEBUG": logging.DEBUG, + "NOTSET": logging.NOTSET, + } + if text in mapping: + return mapping[text] + + try: + return int(text) + except Exception: + return default + + +def _clean_optional_path(value: Any) -> str | None: + if value is None: + return None + s = str(value) + if not s.strip(): + return None + return s + + +def configure_logging( + cfg: HubRuntimeConfig, + *, + override_level: str | None = None, + override_file: str | None = None, +) -> None: + """Configure Python logging for rrcd. + + Intended to be safe to call multiple times (e.g., on /reload). + """ + + level = _parse_level(override_level or cfg.log_level, logging.INFO) + rns_level = _parse_level(cfg.log_rns_level, logging.WARNING) + + handlers: list[logging.Handler] = [] + + if bool(cfg.log_console): + handlers.append(logging.StreamHandler()) + + log_file = _clean_optional_path(override_file) if override_file is not None else None + if log_file is None: + log_file = _clean_optional_path(cfg.log_file) + + if log_file: + p = Path(os.path.expanduser(log_file)) + if p.parent: + p.parent.mkdir(parents=True, exist_ok=True) + file_handler = logging.FileHandler(p, encoding="utf-8") + try: + os.chmod(p, 0o600) + except Exception: + pass + handlers.append(file_handler) + + fmt = str(cfg.log_format).strip() if str(cfg.log_format).strip() else None + if not fmt: + fmt = "%(asctime)s %(levelname)s %(name)s: %(message)s" + + datefmt = _clean_optional_path(cfg.log_datefmt) + + formatter = logging.Formatter(fmt=fmt, datefmt=datefmt) + for h in handlers: + h.setFormatter(formatter) + + root = logging.getLogger() + for h in list(root.handlers): + root.removeHandler(h) + + for h in handlers: + root.addHandler(h) + + root.setLevel(level) + + # Library loggers + logging.getLogger("RNS").setLevel(rns_level) + + logging.captureWarnings(True) diff --git a/rrcd/service.py b/rrcd/service.py index 9c0e108..e1b0486 100644 --- a/rrcd/service.py +++ b/rrcd/service.py @@ -35,6 +35,7 @@ from .constants import ( T_WELCOME, ) from .envelope import make_envelope, validate_envelope +from .logging_config import configure_logging from .util import expand_path, normalize_nick @@ -100,6 +101,21 @@ class HubService: "announces": 0, } + def _fmt_hash(self, h: Any, *, prefix: int = 12) -> str: + if isinstance(h, (bytes, bytearray)): + s = bytes(h).hex() + return s if prefix <= 0 else s[: min(prefix, len(s))] + return "-" + + def _fmt_link_id(self, link: RNS.Link) -> str: + lid = getattr(link, "link_id", None) + if isinstance(lid, (bytes, bytearray)): + return bytes(lid).hex() + h = getattr(link, "hash", None) + if isinstance(h, (bytes, bytearray)): + return bytes(h).hex() + return "-" + def _inc(self, key: str, delta: int = 1) -> None: try: with self._state_lock: @@ -162,6 +178,13 @@ class HubService: self.config.dest_name, self.destination.hash.hex() if self.destination else "-", ) + self.log.info( + "Policy nick_max_chars=%s max_rooms=%s max_room_name_len=%s rate_limit_msgs_per_minute=%s", + self.config.nick_max_chars, + self.config.max_rooms_per_session, + self.config.max_room_name_len, + self.config.rate_limit_msgs_per_minute, + ) if self.config.ping_interval_s and self.config.ping_interval_s > 0: self._ping_thread = threading.Thread(target=self._ping_loop, daemon=True) @@ -260,6 +283,23 @@ class HubService: if isinstance(hub, dict): data = {**data, **hub} + log_table = data.get("logging") if isinstance(data, dict) else None + if isinstance(log_table, dict): + mapped: dict[str, object] = {} + if "level" in log_table: + mapped["log_level"] = log_table.get("level") + if "rns_level" in log_table: + mapped["log_rns_level"] = log_table.get("rns_level") + if "console" in log_table: + mapped["log_console"] = log_table.get("console") + if "file" in log_table: + mapped["log_file"] = log_table.get("file") + if "format" in log_table: + mapped["log_format"] = log_table.get("format") + if "datefmt" in log_table: + mapped["log_datefmt"] = log_table.get("datefmt") + data = {**data, **mapped} + allowed = set(asdict(base).keys()) # This identifies where to reload from; do not let the file override it. allowed.discard("config_path") @@ -279,6 +319,10 @@ class HubService: updates["configdir"] = None if "greeting" in updates and updates["greeting"] == "": updates["greeting"] = None + if "log_file" in updates and updates["log_file"] == "": + updates["log_file"] = None + if "log_datefmt" in updates and updates["log_datefmt"] == "": + updates["log_datefmt"] = None return replace(base, **updates) if updates else base @@ -663,6 +707,12 @@ class HubService: self._ensure_worker_threads() + # Apply logging changes immediately. + try: + configure_logging(self.config) + except Exception: + self.log.exception("Failed to reconfigure logging") + cfg_changes = self._diff_config_summary(old_cfg, new_cfg) room_changes = self._diff_room_registry_summary(old_registry, new_registry) @@ -1988,6 +2038,8 @@ class HubService: lambda identified_link, ident: self._on_remote_identified(identified_link, ident) ) + self.log.info("Link established link_id=%s", self._fmt_link_id(link)) + def _on_remote_identified( self, link: RNS.Link, identity: RNS.Identity | None ) -> None: @@ -2007,6 +2059,11 @@ class HubService: ) if banned: + self.log.warning( + "Disconnecting banned peer peer=%s link_id=%s", + self._fmt_hash(peer_hash), + self._fmt_link_id(link), + ) if self.identity is not None: try: self._error(link, src=self.identity.hash, text="banned") @@ -2018,6 +2075,13 @@ class HubService: pass return + if identity is not None: + self.log.info( + "Remote identified peer=%s link_id=%s", + self._fmt_hash(identity.hash), + self._fmt_link_id(link), + ) + def _welcome(self, link: RNS.Link, sess: dict[str, Any]) -> None: if self.identity is None: return @@ -2029,14 +2093,27 @@ class HubService: welcome = make_envelope(T_WELCOME, src=self.identity.hash, body=body) self._send(link, welcome) + self.log.debug( + "Sent WELCOME peer=%s link_id=%s", + self._fmt_hash(sess.get("peer")), + self._fmt_link_id(link), + ) def _on_close(self, link: RNS.Link) -> None: + peer = None + nick = None + rooms_count = 0 + with self._state_lock: sess = self.sessions.pop(link, None) self._rate.pop(link, None) if not sess: return + peer = sess.get("peer") + nick = sess.get("nick") + rooms_count = len(sess.get("rooms") or ()) + for room in list(sess["rooms"]): self.rooms.get(room, set()).discard(link) if room in self.rooms and not self.rooms[room]: @@ -2045,13 +2122,26 @@ class HubService: if st is not None and not st.get("registered"): self._room_state.pop(room, None) + self.log.info( + "Link closed peer=%s nick=%r rooms=%s link_id=%s", + self._fmt_hash(peer), + nick, + rooms_count, + self._fmt_link_id(link), + ) + def _send(self, link: RNS.Link, env: dict) -> None: payload = encode(env) self._inc("bytes_out", len(payload)) try: RNS.Packet(link, payload).send() except Exception: - pass + self.log.debug( + "Send failed link_id=%s bytes=%s", + self._fmt_link_id(link), + len(payload), + exc_info=True, + ) def _error( self, link: RNS.Link, src: bytes, text: str, room: str | None = None @@ -2097,7 +2187,12 @@ class HubService: try: RNS.Packet(out_link, payload).send() except Exception: - pass + self.log.debug( + "Send failed link_id=%s bytes=%s", + self._fmt_link_id(out_link), + len(payload), + exc_info=True, + ) def _on_packet_locked( self, @@ -2124,6 +2219,12 @@ class HubService: if not self._refill_and_take(link, 1.0): self._inc("rate_limited") + if self.log.isEnabledFor(logging.DEBUG): + self.log.debug( + "Rate limited peer=%s link_id=%s", + self._fmt_hash(peer_hash), + self._fmt_link_id(link), + ) if self.identity is not None: self._emit_error(outgoing, link, src=self.identity.hash, text="rate limited") return @@ -2133,6 +2234,13 @@ class HubService: validate_envelope(env) except Exception as e: self._inc("pkts_bad") + self.log.debug( + "Bad packet peer=%s link_id=%s bytes=%s err=%s", + self._fmt_hash(peer_hash), + self._fmt_link_id(link), + len(data), + e, + ) if self.identity is not None: self._emit_error(outgoing, link, src=self.identity.hash, text=f"bad message: {e}") return @@ -2141,6 +2249,23 @@ class HubService: room = env.get(K_ROOM) body = env.get(K_BODY) + if self.log.isEnabledFor(logging.DEBUG): + body_len = None + if isinstance(body, (bytes, bytearray)): + body_len = len(body) + elif isinstance(body, str): + body_len = len(body) + self.log.debug( + "RX peer=%s link_id=%s t=%s room=%r bytes=%s body_type=%s body_len=%s", + self._fmt_hash(peer_hash), + self._fmt_link_id(link), + t, + room, + len(data), + type(body).__name__, + body_len, + ) + if t == T_PONG: self._inc("pongs_in") sess["awaiting_pong"] = None @@ -2158,6 +2283,13 @@ class HubService: if n is not None: sess["nick"] = n + self.log.info( + "HELLO peer=%s nick=%r link_id=%s", + self._fmt_hash(peer_hash), + sess.get("nick"), + self._fmt_link_id(link), + ) + if self.identity is not None: sess["welcomed"] = True body_w: dict[int, Any] = {B_WELCOME_HUB: self.config.hub_name} @@ -2175,13 +2307,20 @@ class HubService: sess["welcomed"] = False sess["rooms"] = set() sess["nick"] = None - + # Process the HELLO message if isinstance(body, dict): nick = body.get(B_HELLO_NICK) n = normalize_nick(nick, max_chars=self.config.nick_max_chars) if n is not None: sess["nick"] = n + + self.log.info( + "Re-HELLO peer=%s nick=%r link_id=%s", + self._fmt_hash(peer_hash), + sess.get("nick"), + self._fmt_link_id(link), + ) # Send WELCOME sess["welcomed"] = True @@ -2255,6 +2394,14 @@ class HubService: sess["rooms"].add(r) self.rooms.setdefault(r, set()).add(link) + self.log.info( + "JOIN peer=%s nick=%r room=%s link_id=%s", + self._fmt_hash(peer_hash), + sess.get("nick"), + r, + self._fmt_link_id(link), + ) + self._touch_room(r) joined_body = None @@ -2334,6 +2481,14 @@ class HubService: if self.identity is not None: parted = make_envelope(T_PARTED, src=self.identity.hash, room=r, body=parted_body) self._queue_env(outgoing, link, parted) + + self.log.info( + "PART peer=%s nick=%r room=%s link_id=%s", + self._fmt_hash(peer_hash), + sess.get("nick"), + r, + self._fmt_link_id(link), + ) return if t in (T_MSG, T_NOTICE): @@ -2401,6 +2556,17 @@ class HubService: for other in list(self.rooms.get(r, set())): self._queue_payload(outgoing, other, payload) + if self.log.isEnabledFor(logging.DEBUG): + self.log.debug( + "Forwarded t=%s peer=%s nick=%r room=%s recipients=%s body_type=%s", + t, + self._fmt_hash(peer_hash), + sess.get("nick"), + r, + len(self.rooms.get(r, set())), + type(body).__name__, + ) + if t == T_MSG: self._inc("msgs_forwarded") else: