diff --git a/README.md b/README.md index 1b56144..6b73ad0 100644 --- a/README.md +++ b/README.md @@ -46,6 +46,45 @@ 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. + +### Troubleshooting: connect times out after HELLO + +If a client connects, sends `HELLO`, and then times out waiting for `WELCOME`, +check the hub logs for an error like: + +- `Packet size of ... exceeds MTU of ... bytes` + +This usually means the hub tried to send a `WELCOME` (or other message) that is +too large for the current Reticulum link MTU. + +Mitigations: + +- Keep `greeting` reasonably short if you want it to appear inside `WELCOME`. +- If `WELCOME` would exceed MTU, `rrcd` automatically sends a minimal `WELCOME` + and then delivers the full greeting as one or more `NOTICE` messages sized to + fit the link MTU. + ## 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..7a83999 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 @@ -100,6 +121,11 @@ announce_period_s = 0.0 hub_name = "rrc" greeting = "" +# Note: Some Reticulum links have low MTU. If `greeting` is very long, the hub +# may be unable to include it inside the initial WELCOME. In that case, rrcd +# will send a minimal WELCOME and then deliver the greeting afterward via NOTICE +# messages. + # Operator / moderation # # trusted_identities: list of Reticulum Identity hashes (hex) allowed to run @@ -133,6 +159,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 +330,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 +399,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..7f262aa 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,130 @@ 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 _packet_would_fit(self, link: RNS.Link, payload: bytes) -> bool: + try: + pkt = RNS.Packet(link, payload) + pkt.pack() + return True + except Exception: + return False + + def _queue_notice_chunks( + self, + outgoing: list[tuple[RNS.Link, bytes]], + link: RNS.Link, + *, + room: str | None, + text: str, + ) -> None: + if self.identity is None: + return + if not text: + return + + # Prefer splitting on lines for readability. If a single line is too + # large, further split it by characters using a pack preflight. + lines = text.splitlines() or [text] + for line in lines: + remaining = line + if not remaining: + continue + + # Start with a generous chunk size; shrink on demand. + max_chars = min(len(remaining), 512) + while remaining: + take = min(len(remaining), max_chars) + chunk = remaining[:take] + env = make_envelope( + T_NOTICE, + src=self.identity.hash, + room=room, + body=chunk, + ) + payload = encode(env) + if self._packet_would_fit(link, payload): + self._queue_payload(outgoing, link, payload) + remaining = remaining[take:] + max_chars = min(max_chars, 512) + continue + + if max_chars <= 1: + # Nothing we can do; avoid an infinite loop. + self.log.warning( + "NOTICE chunk would not fit MTU; dropping remainder (%s chars)", + len(remaining), + ) + break + + max_chars = max(1, max_chars // 2) + + def _queue_welcome( + self, + outgoing: list[tuple[RNS.Link, bytes]], + link: RNS.Link, + *, + peer_hash: Any, + greeting: str | None, + ) -> None: + if self.identity is None: + return + + g = str(greeting) if greeting else "" + + body_w: dict[int, Any] = {B_WELCOME_HUB: self.config.hub_name} + if g: + body_w[B_WELCOME_GREETING] = g + + welcome = make_envelope(T_WELCOME, src=self.identity.hash, body=body_w) + welcome_payload = encode(welcome) + + if self._packet_would_fit(link, welcome_payload): + self._queue_payload(outgoing, link, welcome_payload) + self.log.debug( + "Queued WELCOME (with greeting) peer=%s link_id=%s", + self._fmt_hash(peer_hash), + self._fmt_link_id(link), + ) + return + + # Fallback: send a minimal WELCOME, then send the greeting as NOTICE + # chunks that each fit within the link MTU. + body_min: dict[int, Any] = {B_WELCOME_HUB: self.config.hub_name} + welcome_min = make_envelope(T_WELCOME, src=self.identity.hash, body=body_min) + welcome_min_payload = encode(welcome_min) + + if not self._packet_would_fit(link, welcome_min_payload): + self.log.warning( + "WELCOME would not fit MTU even without greeting; cannot welcome peer=%s link_id=%s", + self._fmt_hash(peer_hash), + self._fmt_link_id(link), + ) + return + + self.log.warning( + "WELCOME too large for MTU; sending minimal WELCOME + NOTICE chunks peer=%s link_id=%s", + self._fmt_hash(peer_hash), + self._fmt_link_id(link), + ) + self._queue_payload(outgoing, link, welcome_min_payload) + if g: + self._queue_notice_chunks(outgoing, link, room=None, text=g) + def _inc(self, key: str, delta: int = 1) -> None: try: with self._state_lock: @@ -162,6 +287,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 +392,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 +428,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 +816,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 +2147,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 +2168,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,25 +2184,52 @@ 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 sess["welcomed"] = True - body: dict[int, Any] = {B_WELCOME_HUB: self.config.hub_name} - if self.config.greeting: - body[B_WELCOME_GREETING] = self.config.greeting - - welcome = make_envelope(T_WELCOME, src=self.identity.hash, body=body) - self._send(link, welcome) + # Prefer the queued WELCOME path so we can preflight MTU sizing. + outgoing: list[tuple[RNS.Link, bytes]] = [] + self._queue_welcome( + outgoing, + link, + peer_hash=sess.get("peer"), + greeting=self.config.greeting, + ) + for out_link, payload in outgoing: + try: + RNS.Packet(out_link, payload).send() + except Exception: + self.log.debug( + "Send failed link_id=%s bytes=%s", + self._fmt_link_id(out_link), + len(payload), + exc_info=True, + ) 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 +2238,34 @@ 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 OSError as e: + # Common failure mode on low-MTU links: packet too large. + self.log.warning( + "Send failed link_id=%s bytes=%s err=%s", + self._fmt_link_id(link), + len(payload), + e, + ) 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 @@ -2096,8 +2310,20 @@ class HubService: for out_link, payload in outgoing: try: RNS.Packet(out_link, payload).send() + except OSError as e: + self.log.warning( + "Send failed link_id=%s bytes=%s err=%s", + self._fmt_link_id(out_link), + len(payload), + e, + ) 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 +2350,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 +2365,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 +2380,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,13 +2414,20 @@ class HubService: if n is not None: sess["nick"] = n - if self.identity is not None: - sess["welcomed"] = True - body_w: dict[int, Any] = {B_WELCOME_HUB: self.config.hub_name} - if self.config.greeting: - body_w[B_WELCOME_GREETING] = self.config.greeting - welcome = make_envelope(T_WELCOME, src=self.identity.hash, body=body_w) - self._queue_env(outgoing, link, welcome) + self.log.info( + "HELLO peer=%s nick=%r link_id=%s", + self._fmt_hash(peer_hash), + sess.get("nick"), + self._fmt_link_id(link), + ) + + sess["welcomed"] = True + self._queue_welcome( + outgoing, + link, + peer_hash=peer_hash, + greeting=self.config.greeting, + ) return if t == T_HELLO: @@ -2175,21 +2438,28 @@ 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 - body_w: dict[int, Any] = {B_WELCOME_HUB: self.config.hub_name} - if self.config.greeting: - body_w[B_WELCOME_GREETING] = self.config.greeting - welcome = make_envelope(T_WELCOME, src=self.identity.hash, body=body_w) - self._queue_env(outgoing, link, welcome) + self._queue_welcome( + outgoing, + link, + peer_hash=peer_hash, + greeting=self.config.greeting, + ) return if t == T_JOIN: @@ -2255,6 +2525,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 +2612,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 +2687,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: