Logging improvements + better brute force protection for admin

rpipe/__init__.py

@@ -1 +1 @@
-__version__: str = "9.7.0"  # Must be "<major>.<minor>.<patch>", all numbers
+__version__: str = "9.7.1"  # Must be "<major>.<minor>.<patch>", all numbers

rpipe/client/main.py

@@ -82,7 +82,7 @@ def _config_log(parsed: Namespace) -> None:
     root.setLevel(lvl := log.level(parsed.verbose))
     assert len(root.handlers) == 0, "Root logger should not have any handlers"
     root.addHandler(sh := StreamHandler())
-    sh.setFormatter(CuteFormatter(fmt=log.FORMAT, datefmt=log.DATEFMT, colored=not parsed.no_color_log))
+    sh.setFormatter(CuteFormatter(**log.CF_KWARGS, colored=not parsed.no_color_log))
     getLogger(_LOG).info(
         "Logging level set to %s with colors %sABLED",
         getLevelName(lvl),

rpipe/server/admin/verify.py

@@ -2,6 +2,7 @@
 from typing import TYPE_CHECKING, Protocol, cast
 from logging import getLogger
 from base64 import b85decode
+from threading import Lock
 from pathlib import Path
 from json import loads
 from time import sleep
@@ -10,7 +11,7 @@
 from cryptography.exceptions import InvalidSignature, UnsupportedAlgorithm
 from flask import request
 
-from ...shared import AdminMessage, AdminStats, AdminEC, Version, remote_addr
+from ...shared import TRACE, AdminMessage, AdminStats, AdminEC, Version, remote_addr
 from .uid import UID
 
 
@@ -31,14 +32,17 @@ class Verify:
     A class to manage signature verification of Admin requests
     """
 
-    __slots__ = ("uid", "_verifiers", "_log")
+    _BRUTE_FORCE_DELAY = 0.02
+
+    __slots__ = ("uid", "_verifiers", "_log", "_brute_force_lock")
 
     def __init__(self, key_files: list[Path]):
         self._log = getLogger("Verify")
         self._log.info("Loading signing keys")
         verifiers = {self._load_verifier(k): k for k in key_files}
         _ = verifiers.pop(None, None)
         self._verifiers = cast(dict[_Verifier, Path], verifiers)
+        self._brute_force_lock = Lock()
         self.uid = UID()
 
     def __call__(self, name: str, state: State) -> Response | str:
@@ -57,7 +61,7 @@ def _load_verifier(self, key_file: Path) -> _Verifier | None:
                 return None
             return cast(_Verifier | None, getattr(load_ssh_public_key(key_file.read_bytes()), "verify", None))
         except UnsupportedAlgorithm:
-            self._log.error("Signature verification is not supported for %s - Skipping", key_file)
+            self._log.error("Skipping %s - Signature verification algorithm not supported", key_file)
             return None
 
     def _verify_signature(self, signature: bytes, msg: bytes) -> Path | None:
@@ -78,25 +82,30 @@ def _verify(self, name: str, state: State) -> Response | str:
         self._log.debug("Checking version")
         version, post = request.get_data().split(b"\n", 1)
         stat.version = version.decode()
-        if Version(version) < MIN_VERSION:
+        pth = request.full_path.strip("?")
+        if (ver := Version(version)) < MIN_VERSION:
+            self._log.warning("Rejecting request; path: %s; client too old: %s < %s", pth, ver, MIN_VERSION)
             _msg = f"Minimum supported client version: {MIN_VERSION}"
             return Response(_msg, status=AdminEC.illegal_version)
         # Extract parameters
-        self._log.info("Extracting request signature and message")
+        self._log.debug("Extracting request signature and message")
         signature, msg_bytes = post.split(b"\n", 1)
         msg = AdminMessage(**loads(msg_bytes.decode()))
         stat.uid = msg.uid
         # Verify UID
-        sleep(0.01)  # Slow down brute force attacks
+        with self._brute_force_lock:  # Slow down brute force attacks
+            self._log.log(TRACE, "Sleeping %s seconds to prevent brute forcing", self._BRUTE_FORCE_DELAY)
+            sleep(self._BRUTE_FORCE_DELAY)
         if not self.uid.verify(msg.uid):
-            self._log.warning("Rejecting request due to invalid UID: %s", msg.uid)
+            self._log.error("Rejecting request; invalid UID: %s and path: %s", pth, msg.uid)
             return Response(status=AdminEC.unauthorized)
         stat.uid_valid = True
         # Verify signature
         if (key_file := self._verify_signature(b85decode(signature), msg_bytes)) is None:
-            self._log.warning("Signature verification failed.")
+            self._log.error("Signature verification failed; path: %s", pth)
             return Response(status=AdminEC.unauthorized)
         stat.signer = key_file
         # Success
-        self._log.info("Signature verified. Executing %s", request.full_path.strip("?"))
+        self._log.debug("Signature verified")
+        self._log.info("Executing %s", pth)
         return msg.body

rpipe/server/app.py

@@ -265,7 +265,7 @@ def _log_config(conf: LogConfig) -> Path:
             if conf.debug:
                 environ[rdlf_env] = str(log_file)
     # Setup logger
-    fmt = CuteFormatter(log.FORMAT, log.DATEFMT, colored=conf.colored)
+    fmt = CuteFormatter(**log.CF_KWARGS, colored=conf.colored)
     fh = FileHandler(log_file, mode="a")
     stream = StreamHandler()
     root = getLogger()

rpipe/server/blocked.py

@@ -40,6 +40,8 @@ class Blocked:  # Move into server? Move stats into Stats?
 
     def __init__(self, file: Path | None, debug: bool) -> None:
         self._log = getLogger("Blocked")
+        if file is not None:
+            self._log.info("Loading blocklist: %s", file)
         js = self._INIT if file is None or not file.is_file() else json.loads(file.read_text())
         if (old := Version(js.pop("version", ""))) < self.MIN_VERSION:
             raise ValueError(f"Blocklist version too old: {old} <= {self.MIN_VERSION}")

rpipe/shared/log.py

@@ -11,8 +11,14 @@
     from collections.abc import Sequence
 
 
-DATEFMT = "%H:%M:%S"
-FORMAT = "%(cute_asctime)s.%(msecs)03d - %(cute_levelname)-8s - %(cute_name)-10s - %(cute_message)s"
+CF_KWARGS = {
+    "fmt": "%(cute_asctime)s.%(msecs)03d - %(cute_levelname)s - %(cute_name)s - %(cute_message)s",
+    "datefmt": "%H:%M:%S",
+    "cute_widths": {
+        "cute_levelname": 8,
+        "cute_name": 13,
+    },
+}
 
 TRACE = DEBUG - 5
 assert TRACE > 0