feat(log): improve SignalR log

.gitignore

@@ -215,3 +215,4 @@ bancho.py-master/*
 storage/
 replays/
 osu-master/*
+logs/

app/log.py

@@ -127,6 +127,16 @@ logger.add(
     level=settings.log_level,
     diagnose=settings.debug,
 )
+logger.add(
+    "logs/{time:YYYY-MM-DD}.log",
+    rotation="00:00",
+    retention="30 days",
+    colorize=False,
+    format="{time:YYYY-MM-DD HH:mm:ss} {level} | {message}",
+    level=settings.log_level,
+    diagnose=settings.debug,
+    encoding="utf8",
+)
 logging.basicConfig(handlers=[InterceptHandler()], level=settings.log_level, force=True)
 
 uvicorn_loggers = [
@@ -140,3 +150,5 @@ for logger_name in uvicorn_loggers:
     uvicorn_logger = logging.getLogger(logger_name)
     uvicorn_logger.handlers = [InterceptHandler()]
     uvicorn_logger.propagate = False
+
+logging.getLogger("httpx").setLevel("WARNING")

app/signalr/hub/hub.py

@@ -273,6 +273,10 @@ class Hub[TState: UserState]:
                 result = await self.invoke_method(client, packet.target, args)
             except InvokeException as e:
                 error = e.message
+                logger.debug(
+                    f"Client {client.connection_token} call {packet.target}"
+                    f" failed: {error}"
+                )
             except Exception as e:
                 logger.exception(
                     f"Error invoking method {packet.target} for "

app/signalr/hub/multiplayer.py

@@ -364,7 +364,10 @@ class MultiplayerHub(Hub[MultiplayerClientState]):
         user = next((u for u in room.users if u.user_id == client.user_id), None)
         if user is None:
             raise InvokeException("You are not in this room")
-
+        logger.info(
+            f"[MultiplayerHub] {client.user_id} adding "
+            f"beatmap {item.beatmap_id} to room {room.room_id}"
+        )
         await server_room.queue.add_item(
             item,
             user,
@@ -383,6 +386,10 @@ class MultiplayerHub(Hub[MultiplayerClientState]):
         if user is None:
             raise InvokeException("You are not in this room")
 
+        logger.info(
+            f"[MultiplayerHub] {client.user_id} editing "
+            f"item {item.id} in room {room.room_id}"
+        )
         await server_room.queue.edit_item(
             item,
             user,
@@ -401,6 +408,10 @@ class MultiplayerHub(Hub[MultiplayerClientState]):
         if user is None:
             raise InvokeException("You are not in this room")
 
+        logger.info(
+            f"[MultiplayerHub] {client.user_id} removing "
+            f"item {item_id} from room {room.room_id}"
+        )
         await server_room.queue.remove_item(
             item_id,
             user,
@@ -666,6 +677,10 @@ class MultiplayerHub(Hub[MultiplayerClientState]):
 
         if user.state == state:
             return
+        logger.info(
+            f"[MultiplayerHub] {user.user_id}'s state "
+            f"changed from {user.state} to {state}"
+        )
         match state:
             case MultiplayerUserState.IDLE:
                 if user.state.is_playing:
@@ -684,6 +699,7 @@ class MultiplayerHub(Hub[MultiplayerClientState]):
             or room.state == MultiplayerRoomState.WAITING_FOR_LOAD
         ):
             await self.call_noblock(client, "LoadRequested")
+
         await self.update_room_state(server_room)
 
     async def change_user_state(
@@ -767,6 +783,10 @@ class MultiplayerHub(Hub[MultiplayerClientState]):
     async def change_room_state(
         self, room: ServerMultiplayerRoom, state: MultiplayerRoomState
     ):
+        logger.debug(
+            f"[MultiplayerHub] Room {room.room.room_id} state "
+            f"changed from {room.room.state} to {state}"
+        )
         room.room.state = state
         await self.broadcast_group_call(
             self.group_id(room.room.room_id),
@@ -799,6 +819,7 @@ class MultiplayerHub(Hub[MultiplayerClientState]):
         if all(u.state != MultiplayerUserState.READY for u in room.users):
             raise InvokeException("Can't start match when no users are ready.")
 
+        logger.info(f"[MultiplayerHub] Room {room.room_id} match started")
         await self.start_match(server_room)
 
     async def start_match(self, room: ServerMultiplayerRoom):
@@ -971,6 +992,7 @@ class MultiplayerHub(Hub[MultiplayerClientState]):
             room.room.host.user_id,
         )
         del self.rooms[room.room.room_id]
+        logger.info(f"[MultiplayerHub] Room {room.room.room_id} ended")
 
     async def LeaveRoom(self, client: Client):
         store = self.get_or_create_state(client)
@@ -989,6 +1011,7 @@ class MultiplayerHub(Hub[MultiplayerClientState]):
             user.user_id,
         )
         await self.make_user_leave(client, server_room, user)
+        logger.info(f"[MultiplayerHub] {client.user_id} left room {room.room_id}")
 
     async def KickUser(self, client: Client, user_id: int):
         store = self.get_or_create_state(client)
@@ -1017,6 +1040,10 @@ class MultiplayerHub(Hub[MultiplayerClientState]):
         if target_client is None:
             return
         await self.make_user_leave(target_client, server_room, user, kicked=True)
+        logger.info(
+            f"[MultiplayerHub] {user.user_id} was kicked from room {room.room_id}"
+            f"by {client.user_id}"
+        )
 
     async def set_host(self, room: ServerMultiplayerRoom, user: MultiplayerRoomUser):
         room.room.host = user
@@ -1046,6 +1073,10 @@ class MultiplayerHub(Hub[MultiplayerClientState]):
             new_host.user_id,
         )
         await self.set_host(server_room, new_host)
+        logger.info(
+            f"[MultiplayerHub] {client.user_id} transferred host to {new_host.user_id}"
+            f" in room {room.room_id}"
+        )
 
     async def AbortGameplay(self, client: Client):
         store = self.get_or_create_state(client)
@@ -1100,6 +1131,9 @@ class MultiplayerHub(Hub[MultiplayerClientState]):
             GameplayAbortReason.HOST_ABORTED,
         )
         await self.update_room_state(server_room)
+        logger.info(
+            f"[MultiplayerHub] {client.user_id} aborted match in room {room.room_id}"
+        )
 
     async def change_user_match_state(
         self, room: ServerMultiplayerRoom, user: MultiplayerRoomUser

app/signalr/hub/spectator.py

@@ -6,6 +6,7 @@ import lzma
 import struct
 import time
 from typing import override
+from venv import logger
 
 from app.config import settings
 from app.database import Beatmap, User
@@ -217,6 +218,7 @@ class SpectatorHub(Hub[StoreClientState]):
                         maximum_statistics=state.maximum_statistics,
                     )
                 )
+        logger.info(f"[SpectatorHub] {client.user_id} began playing {state.beatmap_id}")
         await self.broadcast_group_call(
             self.group_id(user_id),
             "UserBeganPlaying",
@@ -320,6 +322,10 @@ class SpectatorHub(Hub[StoreClientState]):
     async def _end_session(self, user_id: int, state: SpectatorState) -> None:
         if state.state == SpectatedUserState.Playing:
             state.state = SpectatedUserState.Quit
+        logger.info(
+            f"[SpectatorHub] {user_id} finished playing {state.beatmap_id} "
+            f"with {state.state}"
+        )
         await self.broadcast_group_call(
             self.group_id(user_id),
             "UserFinishedPlaying",
@@ -330,7 +336,9 @@ class SpectatorHub(Hub[StoreClientState]):
     async def StartWatchingUser(self, client: Client, target_id: int) -> None:
         user_id = int(client.connection_id)
         target_store = self.state.get(target_id)
+        logger.info(f"[SpectatorHub] {user_id} started watching {target_id}")
         if target_store and target_store.state:
+            logger.debug(f"[SpectatorHub] {target_id} is {target_store.state}")
             await self.call_noblock(
                 client,
                 "UserBeganPlaying",
@@ -361,3 +369,4 @@ class SpectatorHub(Hub[StoreClientState]):
         store.watched_user.discard(target_id)
         if (target_client := self.get_client_by_id(str(target_id))) is not None:
             await self.call_noblock(target_client, "UserEndedWatching", user_id)
+        logger.info(f"[SpectatorHub] {user_id} ended watching {target_id}")