Applied idiomatic Python improvements and micro-optimizations across registries and API layer.

owlbot/api/commands.py

@@ -68,11 +68,11 @@ class CommandInfo:
     requires_authenticated: bool = False
     requires_moderator: bool = False
     cooldown: int | float = 0
+    all_triggers: frozenset[str] = field(init=False, repr=False)
 
-    @property
+    def __post_init__(self) -> None:
-    def all_triggers(self) -> frozenset[str]:
+        """Compute derived fields."""
-        """All names that trigger this command (name + aliases)."""
+        self.all_triggers = frozenset({self.name}) | self.aliases
-        return frozenset({self.name}) | self.aliases
 
 
 def on_command(

owlbot/api/config.py

@@ -321,7 +321,7 @@ class Config:
 
     def load(self) -> None:
         """Load config from YAML, applying defaults for missing sections."""
-        logger.debug(f"Loading configuration from: {self.config_path.absolute()}")
+        logger.debug("Loading configuration from: %s", self.config_path.absolute())
         if self.config_path.exists():
             try:
                 with self.config_path.open() as f:
@@ -360,30 +360,32 @@ class Config:
             logger.info("Generated webhook secret and saved to config file.")
 
         logger.debug("Webhook Secret: [set]")
-        logger.debug(f"Server Bind Address: {self.host}:{self.port}")
+        logger.debug("Server Bind Address: %s:%s", self.host, self.port)
-        logger.debug(f"Owncast Server URL: {self.owncast_url}")
+        logger.debug("Owncast Server URL: %s", self.owncast_url)
         logger.debug(
-            "Owncast Access Token: "
+            "Owncast Access Token: %s",
-            f"{'[set]' if self.owncast_access_token else '[unset]'}"
+            "[set]" if self.owncast_access_token else "[unset]",
         )
-        logger.debug(f"Command Prefix: {self.command_prefix!r}")
+        logger.debug("Command Prefix: %r", self.command_prefix)
-        logger.debug(f"Handler Timeout: {self.handler_timeout}s")
+        logger.debug("Handler Timeout: %ss", self.handler_timeout)
-        logger.debug(f"Storage Directory: {self.storage_dir}")
+        logger.debug("Storage Directory: %s", self.storage_dir)
-        logger.debug(f"Modules Directory: {self.modules_dir}")
+        logger.debug("Modules Directory: %s", self.modules_dir)
-        logger.debug(f"Log Directory: {self.log_dir or '[unset]'}")
+        logger.debug("Log Directory: %s", self.log_dir or "[unset]")
-        logger.debug(f"Public Base URL: {self.public_base_url}")
+        logger.debug("Public Base URL: %s", self.public_base_url)
         logger.debug(
-            f"Admin API Enabled: {'[set]' if self.admin_enabled else '[unset]'}"
+            "Admin API Enabled: %s",
+            "[set]" if self.admin_enabled else "[unset]",
         )
         if self.admin_enabled:
-            logger.debug(f"Admin API Username: {self.admin_username}")
+            logger.debug("Admin API Username: %s", self.admin_username)
             logger.debug(
-                f"Admin API Password: {'[set]' if self.admin_password else '[unset]'}"
+                "Admin API Password: %s",
+                "[set]" if self.admin_password else "[unset]",
             )
 
     def save(self) -> None:
         """Write current configuration to the YAML file."""
-        logger.debug(f"Saving configuration to: {self.config_path.absolute()}")
+        logger.debug("Saving configuration to: %s", self.config_path.absolute())
         try:
             with self.config_path.open("w") as f:
                 yaml.safe_dump(

owlbot/api/event_types.py

@@ -23,6 +23,8 @@ from datetime import datetime
 from enum import StrEnum
 from typing import Any
 
+_NANO_RE = re.compile(r"(\.\d{6})\d+")
+
 logger = logging.getLogger("owlbot.events")
 
 
@@ -64,7 +66,7 @@ def _parse_timestamp(ts: str | None) -> datetime | None:
     # Go's time.Time emits nanosecond-precision fractional seconds (9 digits),
     # but Python's datetime only supports microseconds (6 digits).  Truncate
     # any excess fractional digits to avoid a ValueError from fromisoformat().
-    ts = re.sub(r"(\.\d{6})\d+", r"\1", ts)
+    ts = _NANO_RE.sub(r"\1", ts)
 
     try:
         return datetime.fromisoformat(ts)
@@ -86,7 +88,7 @@ class User:
     name_changed_at: datetime | None
     is_bot: bool
     is_authenticated: bool
-    scopes: list[str]
+    scopes: frozenset[str]
 
     @classmethod
     def from_dict(cls, data: dict[str, Any]) -> User:
@@ -104,7 +106,7 @@ class User:
             name_changed_at=_parse_timestamp(data.get("nameChangedAt")),
             is_bot=data.get("isBot", False),
             is_authenticated=data.get("authenticated", False),
-            scopes=data.get("scopes", []),
+            scopes=frozenset(data.get("scopes", ())),
         )
 
     @property
@@ -423,29 +425,24 @@ def log_event(event_type: EventType, event: Event) -> None:
     :param event_type: The type of event being logged.
     :param event: The parsed event instance.
     """
-    if isinstance(event, ChatEvent):
+    match event:
+        case ChatEvent(user=user, message_id=mid, body=body):
+            logger.info(f"[{event_type}] {user.display_name} ({mid}): {body}")
+        case UserJoinedEvent(user=user):
+            logger.info(f"[{event_type}] {user.display_name} joined.")
+        case UserPartedEvent(user=user):
+            logger.info(f"[{event_type}] {user.display_name} parted.")
+        case NameChangedEvent(user=user, new_name=new_name):
             logger.info(
-            f"[{event_type}] {event.user.display_name} "
+                f"[{event_type}] {user.display_name} changed name to {new_name}."
-            f"({event.message_id}): {event.body}"
             )
-    elif isinstance(event, UserJoinedEvent):
+        case StreamStartedEvent(stream_title=title):
-        logger.info(f"[{event_type}] {event.user.display_name} joined.")
+            logger.info(f'[{event_type}] Stream started: "{title}"')
-    elif isinstance(event, UserPartedEvent):
+        case StreamStoppedEvent():
-        logger.info(f"[{event_type}] {event.user.display_name} parted.")
-    elif isinstance(event, NameChangedEvent):
-        logger.info(
-            f"[{event_type}] {event.user.display_name} "
-            f"changed name to {event.new_name}."
-        )
-    elif isinstance(event, StreamStartedEvent):
-        logger.info(f'[{event_type}] Stream started: "{event.stream_title}"')
-    elif isinstance(event, StreamStoppedEvent):
             logger.info(f"[{event_type}] Stream ended.")
-    elif isinstance(event, StreamTitleUpdatedEvent):
+        case StreamTitleUpdatedEvent(stream_title=title):
-        logger.info(f'[{event_type}] Title changed to "{event.stream_title}"')
+            logger.info(f'[{event_type}] Title changed to "{title}"')
-    elif isinstance(event, VisibilityUpdateEvent):
+        case VisibilityUpdateEvent(is_visible=visible, message_ids=ids):
-        action = "shown" if event.is_visible else "hidden"
+            action = "shown" if visible else "hidden"
-        ids = ", ".join(event.message_ids)
+            id_list = ", ".join(ids)
-        logger.info(
+            logger.info(f"[{event_type}] {len(ids)} message(s) {action}: {id_list}")
-            f"[{event_type}] {len(event.message_ids)} message(s) {action}: {ids}"
-        )

owlbot/api/owncast_client.py

@@ -84,7 +84,7 @@ class OwncastClient:
             "Authorization": f"Bearer {access_token}"
         }
         self._auth: aiohttp.BasicAuth | None = None
-        self._logger.debug(f"Owncast API client initialized for: {self._base_url}")
+        self._logger.debug("Owncast API client initialized for: %s", self._base_url)
 
     @property
     def base_url(self) -> str:
@@ -207,7 +207,7 @@ class OwncastClient:
         :raises OwncastError: If the request fails.
         """
         url = f"{self._base_url}{endpoint}"
-        self._logger.debug(f"POST {endpoint}")
+        self._logger.debug("POST %s", endpoint)
         try:
             async with self._http.session.post(
                 url,
@@ -223,7 +223,7 @@ class OwncastClient:
                         f"Error {response.status} on POST {endpoint}: {message}"
                     )
                     raise OwncastError(response.status, message)
-                self._logger.debug(f"POST {endpoint} -> {response.status}")
+                self._logger.debug("POST %s -> %d", endpoint, response.status)
                 if response.content_type == "application/json":
                     try:
                         result = await response.json()
@@ -266,7 +266,7 @@ class OwncastClient:
         :raises OwncastError: If the request fails.
         """
         url = f"{self._base_url}{endpoint}"
-        self._logger.debug(f"GET {endpoint}")
+        self._logger.debug("GET %s", endpoint)
         try:
             async with self._http.session.get(
                 url,
@@ -282,7 +282,7 @@ class OwncastClient:
                         f"Error {response.status} on GET {endpoint}: {message}"
                     )
                     raise OwncastError(response.status, message)
-                self._logger.debug(f"GET {endpoint} -> {response.status}")
+                self._logger.debug("GET %s -> %d", endpoint, response.status)
                 try:
                     result = await response.json()
                 except (ValueError, ContentTypeError):

owlbot/api/storage.py

@@ -141,7 +141,9 @@ class ModuleStorage:
         :raises StorageError: If execution fails.
         """
         async with self._connection() as conn:
-            self._logger.debug(f"Execute: {sql[:80]}{'...' if len(sql) > 80 else ''}")
+            self._logger.debug(
+                "Execute: %s%s", sql[:80], "..." if len(sql) > 80 else ""
+            )
             try:
                 return await conn.execute(sql, parameters)
             except aiosqlite.Error as e:
@@ -164,8 +166,10 @@ class ModuleStorage:
         """
         async with self._connection() as conn:
             self._logger.debug(
-                f"Execute many ({len(parameters)} rows): "
+                "Execute many (%d rows): %s%s",
-                f"{sql[:80]}{'...' if len(sql) > 80 else ''}"
+                len(parameters),
+                sql[:80],
+                "..." if len(sql) > 80 else "",
             )
             try:
                 return await conn.executemany(sql, parameters)
@@ -187,7 +191,9 @@ class ModuleStorage:
         :raises StorageError: If execution fails.
         """
         async with self._connection() as conn:
-            self._logger.debug(f"Fetch one: {sql[:80]}{'...' if len(sql) > 80 else ''}")
+            self._logger.debug(
+                "Fetch one: %s%s", sql[:80], "..." if len(sql) > 80 else ""
+            )
             try:
                 cursor = await conn.execute(sql, parameters)
                 return await cursor.fetchone()
@@ -209,7 +215,9 @@ class ModuleStorage:
         :raises StorageError: If execution fails.
         """
         async with self._connection() as conn:
-            self._logger.debug(f"Fetch all: {sql[:80]}{'...' if len(sql) > 80 else ''}")
+            self._logger.debug(
+                "Fetch all: %s%s", sql[:80], "..." if len(sql) > 80 else ""
+            )
             try:
                 cursor = await conn.execute(sql, parameters)
                 return list(await cursor.fetchall())
@@ -243,7 +251,9 @@ class ModuleStorage:
         await conn.execute("PRAGMA foreign_keys = ON")
         self._all_connections.append(conn)
         self._logger.debug(
-            f"Pool connection created ({len(self._all_connections)}/{self._pool_size})."
+            "Pool connection created (%d/%d).",
+            len(self._all_connections),
+            self._pool_size,
         )
         return conn
 

owlbot/builtin_modules/clips/cache.py

@@ -287,14 +287,14 @@ async def _download_segment(
                 return False
             data = await seg_resp.read()
     except Exception:
-        ctx.logger.debug(f"Network error downloading segment {seq}.", exc_info=True)
+        ctx.logger.debug("Network error downloading segment %d.", seq, exc_info=True)
         return False
 
     chunk_path = cache.segment_path(seq)
     await asyncio.to_thread(chunk_path.write_bytes, data)
 
     cache.add_chunk(seq)
-    ctx.logger.debug(f"Cached segment {seq} ({len(data)} bytes).")
+    ctx.logger.debug("Cached segment %d (%d bytes).", seq, len(data))
     return True
 
 
@@ -344,7 +344,7 @@ async def _polling_loop(
         else 2.0
     )
     cache.set_target_duration(poll_interval)
-    ctx.logger.debug(f"Initial poll interval set to {poll_interval:.1f}s.")
+    ctx.logger.debug("Initial poll interval set to %.1fs.", poll_interval)
 
     pending_retries: set[int] = set()
 

owlbot/builtin_modules/clips/commands.py

@@ -127,7 +127,7 @@ async def delclip_command(ctx: CommandContext) -> None:
 
     row = await ctx.storage.fetch_one("SELECT id FROM clips WHERE id = ?", (clip_id,))
     if not row:
-        ctx.logger.debug(f"Clip {clip_id} not found for deletion.")
+        ctx.logger.debug("Clip %s not found for deletion.", clip_id)
         await ctx.owncast_client.send_message(f"Clip {clip_id} not found.")
         return
 

owlbot/builtin_modules/clips/processing.py

@@ -86,7 +86,7 @@ class ProcessingManager:
         async with self._ffprobe_semaphore:
             duration = await self._probe_duration(output_path)
 
-        self._logger.debug(f"Preview generated ({duration:.1f}s).")
+        self._logger.debug("Preview generated (%.1fs).", duration)
         return duration
 
     async def create_clip(
@@ -110,8 +110,11 @@ class ProcessingManager:
         """
         async with self._ffmpeg_semaphore:
             self._logger.debug(
-                f"Cutting clip {start:.1f}-{end:.1f}s "
+                "Cutting clip %.1f-%.1fs from %s -> %s.",
-                f"from {preview_path} -> {output_path}."
+                start,
+                end,
+                preview_path,
+                output_path,
             )
             await self._run_ffprocess(
                 "ffmpeg",
@@ -132,7 +135,7 @@ class ProcessingManager:
         async with self._ffprobe_semaphore:
             duration = await self._probe_duration(output_path)
 
-        self._logger.debug(f"Clip created ({duration:.1f}s).")
+        self._logger.debug("Clip created (%.1fs).", duration)
         return duration
 
     async def generate_thumbnail(
@@ -171,7 +174,7 @@ class ProcessingManager:
                 str(output_path),
             )
 
-        self._logger.debug(f"Thumbnail generated: {output_path}.")
+        self._logger.debug("Thumbnail generated: %s.", output_path)
 
     async def _run_ffprocess(
         self,

owlbot/builtin_modules/clips/routes.py

@@ -122,7 +122,7 @@ def schedule_session_expiry(
         await asyncio.sleep(delay)
         if sessions.get(token) is not session:
             return
-        logger.debug(f"Session expired: token={token[:8]}...")
+        logger.debug("Session expired: token=%s...", token[:8])
         cleanup_session(sessions, token)
 
     session.expiry_task = asyncio.create_task(_expire())
@@ -249,7 +249,7 @@ async def editor_submit(ctx: RouteContext) -> web.Response:
         max_length=max_length,
     )
     if error is not None:
-        ctx.logger.debug(f"Clip submit validation failed: {error}")
+        ctx.logger.debug("Clip submit validation failed: %s", error)
         return _error_page(ctx, 400, error)
 
     # Remove session to prevent double-submission.

owlbot/builtin_modules/custom_commands/placeholder_handlers.py

@@ -462,13 +462,12 @@ type PlaceholderHandler = Callable[
     [str, list[str], "PlaceholderContext"], Awaitable[str]
 ]
 
-HANDLERS: dict[str, PlaceholderHandler] = {}
+HANDLERS: dict[str, PlaceholderHandler] = {
-
+    **{str(i): _evaluate_arg for i in range(1, 10)},
-for _i in range(1, 10):
+    "user": _evaluate_user,
-    HANDLERS[str(_i)] = _evaluate_arg
+    "count": _evaluate_count,
-HANDLERS["user"] = _evaluate_user
+    "getcount": _evaluate_getcount,
-HANDLERS["count"] = _evaluate_count
+    "rand": _evaluate_rand,
-HANDLERS["getcount"] = _evaluate_getcount
+    "countdown": _evaluate_countdown,
-HANDLERS["rand"] = _evaluate_rand
+    "countup": _evaluate_countdown,
-HANDLERS["countdown"] = _evaluate_countdown
+}
-HANDLERS["countup"] = _evaluate_countdown

owlbot/http_server.py

@@ -109,7 +109,7 @@ class HttpServer:
         await self._runner.setup()
 
         site = web.TCPSite(self._runner, host, port)
-        logger.debug(f"Binding web server to {host}:{port}...")
+        logger.debug("Binding web server to %s:%s...", host, port)
         try:
             await site.start()
         except OSError as e:
@@ -146,7 +146,7 @@ class HttpServer:
             return web.Response(status=400)
 
         event_type = data.get("type", "unknown")
-        logger.debug(f"Received webhook: {event_type}")
+        logger.debug("Received webhook: %s", event_type)
 
         result = parse_event(data)
         if result is None:

owlbot/module_loader.py

@@ -178,9 +178,9 @@ class ModuleLoader:
 
         :return: Set of user module names.
         """
-        logger.debug(f"Scanning user modules directory: {self.modules_dir}")
+        logger.debug("Scanning user modules directory: %s", self.modules_dir)
         if not self.modules_dir.exists():
-            logger.debug(f"User modules directory does not exist: {self.modules_dir}")
+            logger.debug("User modules directory does not exist: %s", self.modules_dir)
             return set()
 
         found: set[str] = set()
@@ -290,7 +290,7 @@ class ModuleLoader:
                 f"Module name '{module_name}' is reserved and cannot be used"
             )
 
-        logger.debug(f"Attempting to load module: {module_name}")
+        logger.debug("Attempting to load module: %s", module_name)
 
         if not self.config.is_module_enabled(module_name):
             raise ModuleLoadError(f"Module '{module_name}' is disabled in config")
@@ -313,7 +313,7 @@ class ModuleLoader:
             module = importlib.util.module_from_spec(spec)
             sys.modules[f"owlbot_modules.{module_name}"] = module
 
-            logger.debug(f"Executing module: {module_name}")
+            logger.debug("Executing module: %s", module_name)
             spec.loader.exec_module(module)
 
             module_dir = module_path.parent
@@ -350,7 +350,7 @@ class ModuleLoader:
                 await self._run_module_setup(module_name)
                 logger.info(f"Loaded module '{module_name}'.")
             else:
-                logger.debug(f"Imported module '{module_name}' (setup deferred).")
+                logger.debug("Imported module '%s' (setup deferred).", module_name)
 
         except ModuleLoadError:
             raise
@@ -374,7 +374,7 @@ class ModuleLoader:
         :param module_name: The module to unload.
         :return: True if module was unloaded, False if not found.
         """
-        logger.debug(f"Unloading module '{module_name}'")
+        logger.debug("Unloading module '%s'", module_name)
         if module_name not in self.loaded_modules:
             logger.warning(f"Cannot unload '{module_name}': not loaded")
             return False
@@ -390,13 +390,13 @@ class ModuleLoader:
         if teardown_funcs and module_ctx:
             for teardown_func in teardown_funcs:
                 try:
-                    logger.debug(f"Running @on_teardown for module: {module_name}")
+                    logger.debug("Running @on_teardown for module: %s", module_name)
                     await teardown_func(module_ctx)
-                    logger.debug(f"Teardown completed for module: {module_name}")
+                    logger.debug("Teardown completed for module: %s", module_name)
                 except Exception as e:
                     logger.exception(f"Teardown failed for module '{module_name}': {e}")
         else:
-            logger.debug(f"Module '{module_name}' has no @on_teardown handlers.")
+            logger.debug("Module '%s' has no @on_teardown handlers.", module_name)
 
         if module_ctx:
             try:
@@ -438,15 +438,15 @@ class ModuleLoader:
             self._collect_lifecycle_handlers(module, "_owlbot_setup") if module else []
         )
         if not setup_funcs:
-            logger.debug(f"Module '{module_name}' has no @on_setup handlers.")
+            logger.debug("Module '%s' has no @on_setup handlers.", module_name)
             return
 
         module_ctx = self._module_contexts[module_name]
         try:
             for setup_func in setup_funcs:
-                logger.debug(f"Running @on_setup for module: {module_name}")
+                logger.debug("Running @on_setup for module: %s", module_name)
                 await setup_func(module_ctx)
-            logger.debug(f"Setup completed for module: {module_name}")
+            logger.debug("Setup completed for module: %s", module_name)
         except Exception as e:
             await module_ctx.storage._close()
             self._cleanup_module(module_name)
@@ -548,4 +548,4 @@ class ModuleLoader:
         self.event_dispatcher.unregister_by_module(module_name)
         self.command_dispatcher.unregister_by_module(module_name)
         self.route_dispatcher.unregister_by_module(module_name)
-        logger.debug(f"Cleaned up module '{module_name}'.")
+        logger.debug("Cleaned up module '%s'.", module_name)

owlbot/registries/commands.py

@@ -27,12 +27,13 @@ from collections.abc import Awaitable, Callable
 from typing import TYPE_CHECKING, cast
 
 from ..api.commands import CommandEvent, CommandHandler, CommandInfo, CommandMark
+from ..api.context import CommandContext, EventContext
 from ..api.event_types import ChatEvent
 
 if TYPE_CHECKING:
     from types import ModuleType
 
-    from ..api.context import EventContext, ModuleContext
+    from ..api.context import ModuleContext
     from ..api.owncast_client import OwncastClient
 
 type BuiltinCommandHandler = Callable[[ChatEvent, "OwncastClient"], Awaitable[None]]
@@ -61,7 +62,7 @@ class CommandRegistry:
 
         self.prefix = prefix
 
-        logger.debug(f"CommandRegistry initialized with prefix '{prefix}'.")
+        logger.debug("CommandRegistry initialized with prefix '%s'.", prefix)
 
     def register(
         self,
@@ -114,9 +115,13 @@ class CommandRegistry:
 
         module_logger = logging.getLogger(f"owlbot.modules.{module_name}.commands")
         module_logger.debug(
-            f"Registered command '{name_lower}' with aliases {sorted(alias_set)}, "
+            "Registered command '%s' with aliases %s, "
-            f"authenticated={requires_authenticated}, moderator={requires_moderator}, "
+            "authenticated=%s, moderator=%s, cooldown=%s.",
-            f"cooldown={cooldown}."
+            name_lower,
+            sorted(alias_set),
+            requires_authenticated,
+            requires_moderator,
+            cooldown,
         )
 
     def unregister(self, name: str) -> bool:
@@ -141,7 +146,7 @@ class CommandRegistry:
         del self._commands[primary]
 
         module_logger = logging.getLogger(f"owlbot.modules.{info.module_name}.commands")
-        module_logger.debug(f"Unregistered command '{primary}'.")
+        module_logger.debug("Unregistered command '%s'.", primary)
         return True
 
     def get(self, trigger: str) -> CommandInfo | None:
@@ -183,7 +188,7 @@ class CommandRegistry:
             for name, info in self._commands.items()
             if info.module_name == module_name
         ]
-        module_logger.debug(f"Unregistering all commands ({len(to_remove)} total).")
+        module_logger.debug("Unregistering all commands (%d total).", len(to_remove))
         for name in to_remove:
             self.unregister(name)
         return len(to_remove)
@@ -230,7 +235,7 @@ class CommandRegistry:
         command = parts[0].lower()
         args = parts[1] if len(parts) > 1 else ""
 
-        logger.debug(f"Parsed command: {command!r} with args: {args!r}")
+        logger.debug("Parsed command: %r with args: %r", command, args)
         return command, args
 
 
@@ -302,7 +307,7 @@ class CommandDispatcher:
             module_name="__builtin__",
             cooldown=60,
         )
-        logger.debug(f"Registered built-in command '{name_lower}'.")
+        logger.debug("Registered built-in command '%s'.", name_lower)
 
     def register(
         self,
@@ -416,8 +421,6 @@ class CommandDispatcher:
 
         :param event: The chat event to check for commands.
         """
-        from ..api.context import CommandContext, EventContext
-
         parsed = self._command_registry.parse(event.body)
 
         if parsed is None:
@@ -429,7 +432,7 @@ class CommandDispatcher:
 
         if command_info is None:
             # Log for debugging but don't spam the chat with "unknown command" errors.
-            logger.debug(f"Unknown command: {command_name}")
+            logger.debug("Unknown command: %s", command_name)
             return
 
         user = event.user
@@ -492,8 +495,9 @@ class CommandDispatcher:
                 )
                 elapsed = (time.perf_counter() - start) * 1000
                 logger.debug(
-                    f"Built-in command '{command_info.name}' "
+                    "Built-in command '%s' completed in %.1fms.",
-                    f"completed in {elapsed:.1f}ms."
+                    command_info.name,
+                    elapsed,
                 )
             except TimeoutError:
                 logger.warning(
@@ -535,7 +539,9 @@ class CommandDispatcher:
             )
             elapsed = (time.perf_counter() - start) * 1000
 
-            logger.debug(f"Command '{command_info.name}' completed in {elapsed:.1f}ms.")
+            logger.debug(
+                "Command '%s' completed in %.1fms.", command_info.name, elapsed
+            )
         except TimeoutError:
             logger.warning(
                 f"Command handler '{command_info.name}' "

owlbot/registries/events.py

@@ -20,11 +20,13 @@ Internal infrastructure for managing event handler registration and dispatch.
 from __future__ import annotations
 
 import asyncio
+import bisect
 import logging
 import time
+from collections import defaultdict
 from typing import TYPE_CHECKING, NamedTuple, cast
 
-from ..api.context import PropagationState
+from ..api.context import EventContext, PropagationState
 from ..api.event_types import ChatEvent, Event, EventType, log_event
 from ..api.events import EventHandler, EventMark, Priority
 
@@ -43,7 +45,7 @@ if TYPE_CHECKING:
     from collections.abc import Awaitable, Callable
     from types import ModuleType
 
-    from ..api.context import EventContext, ModuleContext
+    from ..api.context import ModuleContext
 
 logger = logging.getLogger("owlbot.events")
 
@@ -59,7 +61,7 @@ class EventRegistry:
         """Initialize an empty handler registry."""
         # Maps event type values (strings) to lists of
         # (handler, module_name, priority) tuples.
-        self._handlers: EventHandlerMap = {}
+        self._handlers: EventHandlerMap = defaultdict(list)
 
     def register(
         self,
@@ -82,16 +84,19 @@ class EventRegistry:
         for event_type in event_types:
             key = event_type.value
 
-            if key not in self._handlers:
+            # Insert in descending priority order so the dispatch loop
-                self._handlers[key] = []
+            # can iterate without a separate sort step. The priority is
-
+            # negated because bisect works in ascending order. bisect.insort
-            # Add the handler to the list. Multiple handlers
+            # uses bisect_right, so same-priority handlers stay in
-            # for the same event are allowed.
+            # registration (FIFO) order.
-            self._handlers[key].append(HandlerEntry(handler, module_name, priority))
+            entry = HandlerEntry(handler, module_name, priority)
+            bisect.insort(self._handlers[key], entry, key=lambda e: -e.priority)
             module_logger = logging.getLogger(f"owlbot.modules.{module_name}.events")
             module_logger.debug(
-                f"Registered handler '{handler.__name__}' for {event_type.value} "
+                "Registered handler '%s' for %s (priority=%s).",
-                f"(priority={priority})."
+                handler.__name__,
+                event_type.value,
+                priority,
             )
 
     def unregister(self, handler: EventHandler) -> bool:
@@ -116,8 +121,9 @@ class EventRegistry:
         if module_name and removed_from:
             module_logger = logging.getLogger(f"owlbot.modules.{module_name}.events")
             module_logger.debug(
-                f"Unregistered handler '{handler.__name__}' "
+                "Unregistered handler '%s' for %s.",
-                f"for {', '.join(removed_from)}."
+                handler.__name__,
+                ", ".join(removed_from),
             )
             return True
         return False
@@ -170,7 +176,7 @@ class EventRegistry:
             self._handlers[key] = kept
 
         if seen:
-            module_logger.debug(f"Unregistered all handlers ({len(seen)} total).")
+            module_logger.debug("Unregistered all handlers (%d total).", len(seen))
         return len(seen)
 
     def register_from_module(self, module: ModuleType, module_name: str) -> None:
@@ -322,27 +328,19 @@ class EventDispatcher:
         # Shared state for propagation control (all handlers see the same instance).
         propagation = PropagationState()
 
-        # Phase 1: Event handlers (sequential, sorted by priority descending).
+        # Phase 1: Event handlers (sequential, already sorted by priority descending).
         if handler_entries:
-            # Sort handlers by priority (highest first).
-            # Python's sort is stable, so handlers at the same priority
-            # run in their original registration order.
-            sorted_handlers = sorted(
-                handler_entries,
-                key=lambda entry: entry.priority,
-                reverse=True,
-            )
-
             logger.debug(
-                f"Dispatching {event_type} to {len(sorted_handlers)} handler(s)."
+                "Dispatching %s to %d handler(s).", event_type, len(handler_entries)
             )
 
-            for handler, module_name, _priority in sorted_handlers:
+            for handler, module_name, _priority in handler_entries:
                 # Has propagation been stopped by a previous handler?
                 if propagation.stopped:
                     reason = propagation.reason
                     logger.debug(
-                        f"Propagation stopped{': ' + reason if reason else '.'}"
+                        "Propagation stopped%s",
+                        ": " + reason if reason else ".",
                     )
                     break
 
@@ -350,7 +348,7 @@ class EventDispatcher:
                     handler, event, event_type, module_name, propagation
                 )
         else:
-            logger.debug(f"No handlers registered for event type: {event_type}")
+            logger.debug("No handlers registered for event type: %s", event_type)
 
         # Phase 2: Command dispatch (CHAT events only, if not cancelled).
         if event_type == EventType.CHAT and isinstance(event, ChatEvent):
@@ -358,7 +356,8 @@ class EventDispatcher:
             if propagation.stopped:
                 reason = propagation.reason
                 logger.debug(
-                    f"Command dispatch skipped{': ' + reason if reason else '.'}"
+                    "Command dispatch skipped%s",
+                    ": " + reason if reason else ".",
                 )
             else:
                 try:
@@ -382,10 +381,8 @@ class EventDispatcher:
         :param module_name: The module that owns this handler.
         :param propagation: Shared propagation state for this dispatch cycle.
         """
-        from ..api.context import EventContext
-
         handler_name = handler.__name__
-        logger.debug(f"Calling handler: {handler_name} from module: {module_name}")
+        logger.debug("Calling handler: %s from module: %s", handler_name, module_name)
 
         module_ctx = self._get_module_context(module_name)
 
@@ -400,7 +397,7 @@ class EventDispatcher:
             await asyncio.wait_for(handler(ctx), timeout=self._handler_timeout)
             elapsed = (time.perf_counter() - start) * 1000
 
-            logger.debug(f"Handler '{handler_name}' completed in {elapsed:.1f}ms.")
+            logger.debug("Handler '%s' completed in %.1fms.", handler_name, elapsed)
         except TimeoutError:
             logger.warning(
                 f"Handler '{handler_name}' from module '{module_name}' "

owlbot/registries/routes.py

@@ -22,12 +22,14 @@ from __future__ import annotations
 import asyncio
 import logging
 import time
+from collections import defaultdict
 from dataclasses import dataclass
 from typing import TYPE_CHECKING, cast, overload
 
 from aiohttp import web
 from aiohttp.web import DynamicResource
 
+from ..api.context import RouteContext
 from ..api.routes import RouteHandler, RouteInfo, RouteMark
 
 if TYPE_CHECKING:
@@ -69,7 +71,7 @@ class RouteRegistry:
         # Each group represents a unique path pattern with one or more handlers.
         self._groups: list[_RouteGroup] = []
         # Maps module_name -> list of full_paths (for cleanup).
-        self._module_routes: dict[str, list[str]] = {}
+        self._module_routes: dict[str, list[str]] = defaultdict(list)
         logger.debug("RouteRegistry initialized.")
 
     def _find_group(self, full_path: str) -> _RouteGroup | None:
@@ -139,14 +141,14 @@ class RouteRegistry:
         else:
             group.handlers.append(info)
 
-        if module_name not in self._module_routes:
-            self._module_routes[module_name] = []
         if full_path not in self._module_routes[module_name]:
             self._module_routes[module_name].append(full_path)
 
         module_logger = logging.getLogger(f"owlbot.modules.{module_name}.routes")
         module_logger.debug(
-            f"Registered route '{full_path}' [{', '.join(sorted(info.methods))}]."
+            "Registered route '%s' [%s].",
+            full_path,
+            ", ".join(sorted(info.methods)),
         )
         return info
 
@@ -179,7 +181,7 @@ class RouteRegistry:
                 module_names = {h.module_name for h in group.handlers}
                 for name in module_names:
                     module_logger = logging.getLogger(f"owlbot.modules.{name}.routes")
-                    module_logger.debug(f"Unregistered route '{full_path}'.")
+                    module_logger.debug("Unregistered route '%s'.", full_path)
                 return True
 
             # Remove only the handler for the specified method.
@@ -206,7 +208,7 @@ class RouteRegistry:
                         f"owlbot.modules.{module_name}.routes"
                     )
                     module_logger.debug(
-                        f"Unregistered route '{full_path}' [{method_upper}]."
+                        "Unregistered route '%s' [%s].", full_path, method_upper
                     )
                     return True
 
@@ -325,7 +327,7 @@ class RouteRegistry:
                 self._groups.pop(i)
 
         if count > 0:
-            module_logger.debug(f"Unregistered all routes ({count} handler(s) total).")
+            module_logger.debug("Unregistered all routes (%d handler(s) total).", count)
 
         self._module_routes.pop(module_name, None)
         return count
@@ -485,7 +487,7 @@ class RouteDispatcher:
         try:
             result = self._route_registry.match(full_path, request.method)
         except LookupError:
-            mod_logger.debug(f"No route registered for '{full_path}'.")
+            mod_logger.debug("No route registered for '%s'.", full_path)
             return web.Response(status=404)
 
         if result[0] is None:
@@ -493,8 +495,10 @@ class RouteDispatcher:
             _, allowed_methods, _ = result
             allowed = ", ".join(sorted(allowed_methods))
             mod_logger.debug(
-                f"Method {request.method} not allowed for '{full_path}' "
+                "Method %s not allowed for '%s' (allowed: %s)",
-                f"(allowed: {allowed})"
+                request.method,
+                full_path,
+                allowed,
             )
             return web.Response(status=405, headers={"Allow": allowed})
 
@@ -514,9 +518,6 @@ class RouteDispatcher:
         :param match_info: Captured path parameters from pattern matching.
         :return: HTTP response.
         """
-        # Import here to avoid circular imports at module load time.
-        from ..api.context import RouteContext
-
         module_name = route_info.module_name
         mod_logger = logging.getLogger(f"owlbot.modules.{module_name}.routes")
 
@@ -529,7 +530,9 @@ class RouteDispatcher:
         )
 
         logger.debug(
-            f"Calling route handler: {route_info.full_path} from module: {module_name}"
+            "Calling route handler: %s from module: %s",
+            route_info.full_path,
+            module_name,
         )
 
         try:
@@ -540,7 +543,9 @@ class RouteDispatcher:
             elapsed = (time.perf_counter() - start) * 1000
 
             mod_logger.debug(
-                f"Route handler '{route_info.full_path}' completed in {elapsed:.1f}ms."
+                "Route handler '%s' completed in %.1fms.",
+                route_info.full_path,
+                elapsed,
             )
 
             if result is None:

tests/test_commands.py

@@ -48,7 +48,7 @@ def _make_user(
     user_id: str = "user-1",
     display_name: str = "Alice",
     is_authenticated: bool = False,
-    scopes: list[str] | None = None,
+    scopes: frozenset[str] | None = None,
 ) -> User:
     """Build a minimal User for test events."""
     return User(
@@ -60,7 +60,7 @@ def _make_user(
         name_changed_at=None,
         is_bot=False,
         is_authenticated=is_authenticated,
-        scopes=scopes or [],
+        scopes=scopes or frozenset(),
     )
 
 
@@ -657,7 +657,7 @@ class TestCommandDispatcherDispatch:
         dispatcher.register(
             "ban", handler, requires_moderator=True, module_name="mod_a"
         )
-        user = _make_user(scopes=["MODERATOR"])
+        user = _make_user(scopes=frozenset({"MODERATOR"}))
         await dispatcher.dispatch(_make_chat_event(body="!ban", user=user))
 
         assert called is True
@@ -676,7 +676,7 @@ class TestCommandDispatcherDispatch:
         dispatcher.register(
             "ping", handler, requires_moderator=True, module_name="mod_a"
         )
-        user = _make_user(scopes=[])
+        user = _make_user(scopes=frozenset())
         with caplog.at_level(logging.INFO, logger="owlbot.commands"):
             await dispatcher.dispatch(_make_chat_event(body="!ping", user=user))
 

tests/test_event_types.py

@@ -205,7 +205,7 @@ class TestUser:
         assert user.name_changed_at == datetime(2025, 7, 1, 12, 0, tzinfo=UTC)
         assert user.is_bot is False
         assert user.is_authenticated is True
-        assert user.scopes == ["MODERATOR"]
+        assert user.scopes == frozenset({"MODERATOR"})
 
     def test_empty_dict(self) -> None:
         """An empty dict produces a User with all defaults."""
@@ -218,7 +218,7 @@ class TestUser:
         assert user.name_changed_at is None
         assert user.is_bot is False
         assert user.is_authenticated is False
-        assert user.scopes == []
+        assert user.scopes == frozenset()
 
     @pytest.mark.parametrize(
         ("scopes", "expected"),
@@ -606,7 +606,7 @@ class TestLogEvent:
                         name_changed_at=None,
                         is_bot=False,
                         is_authenticated=False,
-                        scopes=[],
+                        scopes=frozenset(),
                     ),
                     client_id=1,
                     body="Hello",
@@ -630,7 +630,7 @@ class TestLogEvent:
                         name_changed_at=None,
                         is_bot=False,
                         is_authenticated=False,
-                        scopes=[],
+                        scopes=frozenset(),
                     ),
                     client_id=1,
                     event_id="evt-001",
@@ -651,7 +651,7 @@ class TestLogEvent:
                         name_changed_at=None,
                         is_bot=False,
                         is_authenticated=False,
-                        scopes=[],
+                        scopes=frozenset(),
                     ),
                     client_id=1,
                     event_id="evt-002",
@@ -672,7 +672,7 @@ class TestLogEvent:
                         name_changed_at=None,
                         is_bot=False,
                         is_authenticated=False,
-                        scopes=[],
+                        scopes=frozenset(),
                     ),
                     client_id=1,
                     new_name="NewName",

tests/test_events.py

@@ -63,7 +63,7 @@ def _make_user(
         name_changed_at=None,
         is_bot=False,
         is_authenticated=False,
-        scopes=[],
+        scopes=frozenset(),
     )
 
 
@@ -230,7 +230,7 @@ class TestEventRegistry:
         assert joined_entries[0].handler is handler
 
     def test_register_multiple_handlers_same_type(self) -> None:
-        """Two handlers for the same type both appear in get()."""
+        """Two handlers for the same type both appear in get(), sorted by priority."""
         registry = EventRegistry()
 
         async def handler_a(ctx: EventContext[Any]) -> None:
@@ -243,8 +243,9 @@ class TestEventRegistry:
         registry.register(handler_b, (EventType.CHAT,), "mod_b", 75)
         entries = registry.get(EventType.CHAT)
         assert len(entries) == 2
-        assert entries[0].handler is handler_a
+        # Higher priority first (descending order).
-        assert entries[1].handler is handler_b
+        assert entries[0].handler is handler_b
+        assert entries[1].handler is handler_a
 
     def test_get_empty(self) -> None:
         """get() on a fresh registry returns an empty list."""