From c959843ea1940f19f357f594b967d72f2c9b9401 Mon Sep 17 00:00:00 2001
From: Sebastian Pietras <spietras1998@gmail.com>
Date: Fri, 20 May 2022 15:27:01 +0200
Subject: [PATCH] Added logging (#8)

---
 theatre/src/theatre/log.py           | 30 ++++++++++++++++++++++++++++
 theatre/src/theatre/models/data.py   |  3 +++
 theatre/src/theatre/server/room.py   | 28 ++++++++++++++++++++++++++
 theatre/src/theatre/server/server.py |  5 ++++-
 4 files changed, 65 insertions(+), 1 deletion(-)
 create mode 100644 theatre/src/theatre/log.py

diff --git a/theatre/src/theatre/log.py b/theatre/src/theatre/log.py
new file mode 100644
index 0000000..44b8138
--- /dev/null
+++ b/theatre/src/theatre/log.py
@@ -0,0 +1,30 @@
+import logging
+from logging.config import dictConfig
+
+from pydantic import BaseModel
+
+
+class LogConfig(BaseModel):
+    version = 1
+    disable_existing_loggers = False
+    formatters = {
+        "default": {
+            "()": "uvicorn.logging.DefaultFormatter",
+            "fmt": "%(levelprefix)s | %(asctime)s | %(message)s",
+            "datefmt": "%Y-%m-%d %H:%M:%S",
+        },
+    }
+    handlers = {
+        "default": {
+            "formatter": "default",
+            "class": "logging.StreamHandler",
+            "stream": "ext://sys.stderr",
+        },
+    }
+    loggers = {
+        "theatre": {"handlers": ["default"], "level": "DEBUG"},
+    }
+
+
+dictConfig(LogConfig().dict())
+logger = logging.getLogger("theatre")
diff --git a/theatre/src/theatre/models/data.py b/theatre/src/theatre/models/data.py
index fa0ea5c..f7e74c8 100644
--- a/theatre/src/theatre/models/data.py
+++ b/theatre/src/theatre/models/data.py
@@ -10,6 +10,9 @@ class Session(FrozenModel):
 class Emoji(FrozenModel):
     id: str
 
+    def __str__(self) -> str:
+        return chr(int(self.id, 16))
+
 
 class CodeEntry(FrozenModel):
     emoji: Emoji
diff --git a/theatre/src/theatre/server/room.py b/theatre/src/theatre/server/room.py
index deb8063..7f8de57 100644
--- a/theatre/src/theatre/server/room.py
+++ b/theatre/src/theatre/server/room.py
@@ -1,5 +1,7 @@
+import logging
 import random
 import uuid
+from asyncio import AbstractEventLoop
 from dataclasses import dataclass
 from typing import Dict, Optional, Set, Union
 
@@ -7,8 +9,10 @@
 from pyee.asyncio import AsyncIOEventEmitter
 
 from theatre.constants import AVAILABLE_AVATAR_EMOJI_IDS
+from theatre.log import logger
 from theatre.models.data import (
     Avatar,
+    Code,
     Emoji,
     IncomingUserMessage,
     OutgoingServerMessage,
@@ -23,6 +27,16 @@ class NotEnoughResourcesError(Exception):
     pass
 
 
+class RoomLoggerAdapter(logging.LoggerAdapter):
+    def __init__(self, base_logger, code: Code) -> None:
+        super().__init__(base_logger, {})
+        self.code = code
+
+    def process(self, msg, kwargs):
+        prefix = " ".join([str(entry.emoji) for entry in self.code.entries])
+        return f"[ {prefix} ] {msg}", kwargs
+
+
 @dataclass
 class UserInfo:
     data: User
@@ -30,9 +44,15 @@ class UserInfo:
 
 
 class Room(AsyncIOEventEmitter):
+    _code: Code
     _users: Dict[str, UserInfo] = {}
     _connected_users: Set[str] = set()
 
+    def __init__(self, code: Code, loop: Optional[AbstractEventLoop] = None):
+        super().__init__(loop)
+        self._code = code
+        self._logger = RoomLoggerAdapter(logger, code=code)
+
     @property
     def users(self) -> Set[User]:
         users = set()
@@ -102,6 +122,8 @@ def handle_connect(self, user_id: str) -> None:
         self.broadcast(user_id, data)
 
     def add(self, connection: Connection) -> User:
+        self._logger.info("New connection.")
+
         user = self.create_user()
 
         def cleanup() -> None:
@@ -112,23 +134,29 @@ def cleanup() -> None:
 
         async def timeout() -> None:
             if user.id not in self._connected_users:
+                self._logger.info(
+                    f"User {user.avatar.emoji} didn't connect on time."
+                )
                 cleanup()
 
         timer = Timer(60, timeout)
 
         @connection.on("connected")
         def on_connected() -> None:
+            self._logger.info(f"User {user.avatar.emoji} connected.")
             timer.cancel()
             self._connected_users.add(user.id)
             self.handle_connect(user.id)
 
         @connection.on("disconnected")
         def on_disconnected() -> None:
+            self._logger.info(f"User {user.avatar.emoji} disconnected.")
             self.handle_disconnect(user.id)
             cleanup()
 
         @connection.on("data")
         def on_data(message: Union[bytes, str]) -> None:
+            self._logger.info(f"User {user.avatar.emoji} sent message.")
             self.handle_data(user.id, message)
 
         self._users[user.id] = UserInfo(data=user, connection=connection)
diff --git a/theatre/src/theatre/server/server.py b/theatre/src/theatre/server/server.py
index 8a8780e..0466bb7 100644
--- a/theatre/src/theatre/server/server.py
+++ b/theatre/src/theatre/server/server.py
@@ -13,6 +13,9 @@ class InternalCode(FrozenModel):
     def new(cls, code: Code) -> "InternalCode":
         return cls(entries=tuple(code.entries))
 
+    def code(self) -> Code:
+        return Code(entries=list(self.entries))
+
 
 class Server:
     rooms: Dict[InternalCode, Room] = {}
@@ -22,7 +25,7 @@ async def cleanup(self) -> None:
             await room.close()
 
     def create_room(self, code: InternalCode) -> Room:
-        room = Room()
+        room = Room(code.code())
 
         async def close() -> None:
             await room.close()