Begin adding in logging configuration support

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.

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()

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

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)

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}
@@ -2183,6 +2315,13 @@ class HubService:
                     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}
@@ -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: