Add logging to sockets

Closes #124 (closed)

server/app/core/sockets.py

 import app.database.controller as dbc
 from app.core import db
-from app.database.models import Competition, Slide, Team, ViewType
+from app.database.models import Competition, Slide, Team, ViewType, Code
 from flask.globals import request
 from flask_socketio import SocketIO, emit, join_room
+import logging
 
-# Presentation is an active competition
+logger = logging.getLogger(__name__)
+logger.propagate = False
+logger.setLevel(logging.INFO)
 
+formatter = logging.Formatter('[%(levelname)s] %(funcName)s: %(message)s')
+stream_handler = logging.StreamHandler()
+stream_handler.setFormatter(formatter)
+logger.addHandler(stream_handler)
 
 sio = SocketIO(cors_allowed_origins="http://localhost:3000")
 
@@ -14,7 +21,7 @@ presentations = {}
 
 @sio.on("connect")
 def connect():
-    print(f"[Connected]: {request.sid}")
+    logger.info(f"Client '{request.sid}' connected")
 
 
 @sio.on("disconnect")
@@ -22,23 +29,22 @@ def disconnect():
     for competition_id, presentation in presentations.items():
         if request.sid in presentation["clients"]:
             del presentation["clients"][request.sid]
+            logger.debug(f"Client '{request.sid}' left presentation '{competition_id}'")
             break
 
     if presentations and not presentations[competition_id]["clients"]:
         del presentations[competition_id]
+        logger.info(f"No people left in presentation '{competition_id}', ended presentation")
 
-    print(f"{presentations=}")
-
-    print(f"[Disconnected]: {request.sid}")
+    logger.info(f"Client '{request.sid}' disconnected")
 
 
 @sio.on("start_presentation")
 def start_presentation(data):
     competition_id = data["competition_id"]
 
-    # TODO: Do proper error handling
     if competition_id in presentations:
-        print("THAT PRESENTATION IS ALREADY ACTIVE")
+        logger.error(f"Client '{request.sid}' failed to start competition '{competition_id}', presentation already active")
         return
 
     presentations[competition_id] = {
@@ -47,40 +53,44 @@ def start_presentation(data):
         "timer": {"enabled": False, "start_value": None, "value": None},
     }
 
-    print(f"{presentations=}")
-
     join_room(competition_id)
-    print(f"[start_presentation]: {request.sid} -> {competition_id}.")
+    logger.debug(f"Client '{request.sid}' joined room {competition_id}")
 
+    logger.info(f"Client '{request.sid}' started competition '{competition_id}'")
 
 @sio.on("end_presentation")
 def end_presentation(data):
     competition_id = data["competition_id"]
 
     if competition_id not in presentations:
-        print("NO PRESENTATION WITH THAT NAME EXISTS")
+        logger.error(f"Client '{request.sid}' failed to end presentation '{competition_id}', no such presentation exists")
+        return
+
+    if request.sid not in presentations[competition_id]["clients"]:
+        logger.error(f"Client '{request.sid}' failed to end presentation '{competition_id}', client not in presentation")
         return
 
     if presentations[competition_id]["clients"][request.sid]["view_type"] != "Operator":
-        print("YOU DONT HAVE ACCESS TO DO THAT")
+        logger.error(f"Client '{request.sid}' failed to end presentation '{competition_id}', client is not operator")
         return
 
     del presentations[competition_id]
-
-    print(f"{presentations=}")
+    logger.debug(f"Deleted presentation {competition_id}")
 
     emit("end_presentation", room=competition_id, include_self=True)
+    logger.debug(f"Emitting event 'end_presentation' to room {competition_id} including self")
+
+    logger.info(f"Client '{request.sid}' ended presentation '{competition_id}'")
 
 
 @sio.on("join_presentation")
 def join_presentation(data):
     team_view_id = 1
     code = data["code"]
-    item_code = dbc.get.code_by_code(code)
+    item_code = db.session.query(Code).filter(Code.code == code).first()
 
-    # TODO: Do proper error handling
     if not item_code:
-        print("CODE DOES NOT EXIST")
+        logger.error(f"Client '{request.sid}' failed to join presentation with code '{code}', no such code exists")
         return
 
     competition_id = (
@@ -90,22 +100,22 @@ def join_presentation(data):
     )
 
     if competition_id not in presentations:
-        print("THAT COMPETITION IS CURRENTLY NOT ACTIVE")
+        logger.error(f"Client '{request.sid}' failed to join presentation '{competition_id}', no such presentation exists")
         return
 
     if request.sid in presentations[competition_id]["clients"]:
-        print("CLIENT ALREADY IN COMPETITION")
+        logger.error(f"Client '{request.sid}' failed to join presentation '{competition_id}', client already in presentation")
         return
 
     # TODO: Write function in database controller to do this
     view_type_name = db.session.query(ViewType).filter(ViewType.id == item_code.view_type_id).one().name
 
     presentations[competition_id]["clients"][request.sid] = {"view_type": view_type_name}
-    join_room(competition_id)
 
-    print(f"{presentations=}")
+    join_room(competition_id)
+    logger.debug(f"Client '{request.sid}' joined room {competition_id}")
 
-    print(f"[Join presentation]: {request.sid} -> {competition_id}. {view_type_name=}")
+    logger.info(f"Client '{request.sid}' joined competition '{competition_id}'")
 
 
 @sio.on("set_slide")
@@ -114,43 +124,52 @@ def set_slide(data):
     slide_order = data["slide_order"]
 
     if competition_id not in presentations:
-        print("CANT SET SLIDE IN NON ACTIVE COMPETITION")
+        logger.error(f"Client '{request.sid}' failed to set slide in presentation '{competition_id}', no such presentation exists")
+        return
+
+    if request.sid not in presentations[competition_id]["clients"]:
+        logger.error(f"Client '{request.sid}' failed to set slide in presentation '{competition_id}', client not in presentation")
         return
 
     if presentations[competition_id]["clients"][request.sid]["view_type"] != "Operator":
-        print("YOU DONT HAVE ACCESS TO DO THAT")
+        logger.error(f"Client '{request.sid}' failed to set slide in presentation '{competition_id}', client is not operator")
         return
 
     num_slides = db.session.query(Slide).filter(Slide.competition_id == competition_id).count()
 
     if not (0 <= slide_order < num_slides):
-        print("CANT CHANGE TO NON EXISTENT SLIDE")
+        logger.error(f"Client '{request.sid}' failed to set slide in presentation '{competition_id}', slide number {slide_order} does not exist")
         return
 
     presentations[competition_id]["slide"] = slide_order
 
-    print(f"{presentations=}")
-
     emit("set_slide", {"slide_order": slide_order}, room=competition_id, include_self=True)
-    print(f"[Set slide]: {slide_order} -> {competition_id}")
+    logger.debug(f"Emitting event 'set_slide' to room {competition_id} including self")
+
+    logger.info(f"Client '{request.sid}' set slide '{slide_order}' in competition '{competition_id}'")
 
 
 @sio.on("set_timer")
-def sync_timer(data):
+def set_timer(data):
     competition_id = data["competition_id"]
     timer = data["timer"]
 
     if competition_id not in presentations:
-        print("CANT SET TIMER IN NON EXISTENT COMPETITION")
+        logger.error(f"Client '{request.sid}' failed to set slide in presentation '{competition_id}', no such presentation exists")
+        return
+
+    if request.sid not in presentations[competition_id]["clients"]:
+        logger.error(f"Client '{request.sid}' failed to set slide in presentation '{competition_id}', client not in presentation")
         return
 
     if presentations[competition_id]["clients"][request.sid]["view_type"] != "Operator":
-        print("YOU DONT HAVE ACCESS TO DO THAT")
+        logger.error(f"Client '{request.sid}' failed to set slide in presentation '{competition_id}', client is not operator")
         return
 
     # TODO: Save timer in presentation, maybe?
 
-    print(f"{presentations=}")
-
     emit("set_timer", {"timer": timer}, room=competition_id, include_self=True)
-    print(f"[Set timer]: {timer=}, {competition_id=}")
+    logger.debug(f"Emitting event 'set_timer' to room {competition_id} including self")
+
+    logger.info(f"Client '{request.sid}' set timer '{timer}' in presentation '{competition_id}'")
+