Merge pull request #8 from UniversityRadioYork/debugging

Add logging & debugging features.

.gitignore

@@ -31,3 +31,10 @@ dev/welcome.mp3
 
 build/build-exe-pyinstaller-command.sh
 
+logs/
+
+*.mp3
+
+*.oga
+
+*.ogg

config.py.example

@@ -1,6 +1,6 @@
 # Flask Details
 HOST: str = "localhost"
-PORT: int = 5000
+PORT: int = 13500
 
 # BAPSicle Details
 VERSION: float = 1.0

dev/pre-commit

@@ -9,9 +9,10 @@ import subprocess
 import sys
 import tempfile
 
+#See for codes https://pypi.org/project/autopep8/ #features
 # don't fill in both of these
 select_codes = []
-ignore_codes = [] #"E121", "E122", "E123", "E124", "E125", "E126", "E127", "E128", "E129", "E131", "E501"]
+ignore_codes = ["E402","E226","E24","W50","W690"] #"E121", "E122", "E123", "E124", "E125", "E126", "E127", "E128", "E129", "E131", "E501"]
 # Add things like "--max-line-length=120" below
 overrides = ["--max-line-length=120"]
 

helpers/logging_manager.py

@@ -0,0 +1,26 @@
+import logging
+from helpers.os_environment import resolve_external_file_path
+
+
+class LoggingManager():
+
+    logger = None
+
+    def __init__(self, name):
+        self.logger = logging.getLogger(name)
+
+        logging.basicConfig(
+            filename=resolve_external_file_path("/logs/" + name + ".log"),
+            format='%(asctime)s  | %(levelname)s | %(message)s',
+            level=logging.INFO,
+            filemode='a'
+        )
+        self.logger.info("** LOGGER STARTED **")
+
+    def __del__(self):
+        self.logger.info("** LOGGER EXITING **")
+        logging.shutdown()
+
+    @property
+    def log(self):
+        return self.logger

helpers/state_manager.py

@@ -0,0 +1,135 @@
+import json
+import os
+import logging
+import time
+from datetime import datetime
+from copy import copy
+
+from plan import PlanObject
+from helpers.logging_manager import LoggingManager
+from helpers.os_environment import resolve_external_file_path
+
+
+class StateManager:
+    filepath = None
+    logger = None
+    __state = {}
+    __state_in_file = {}
+    # Dict of times that params can be updated after, if the time is before current time, it can be written immediately.
+    __rate_limit_params_until = {}
+    __rate_limit_period_s = 0
+
+
+    def __init__(self, name, logger: LoggingManager, default_state=None, rate_limit_params=[], rate_limit_period_s = 5):
+        self.logger = logger
+
+        self.filepath = resolve_external_file_path("/state/" + name + ".json")
+        self._log("State file path set to: " + self.filepath)
+
+        if not os.path.isfile(self.filepath):
+            self._log("No existing state file found.")
+            try:
+                # Try creating the file.
+                open(self.filepath, "x")
+            except:
+                self._log("Failed to create state file.", logging.CRITICAL)
+                return
+
+        with open(self.filepath, 'r') as file:
+            file_state = file.read()
+
+        if file_state == "":
+            self._log("State file is empty. Setting default state.")
+            self.state = default_state
+            self.__state_in_file = copy(self.state)
+        else:
+            try:
+                file_state = json.loads(file_state)
+
+                # Turn from JSON -> PlanObject
+                file_state["loaded_item"] = PlanObject(file_state["loaded_item"]) if file_state["loaded_item"] else None
+
+                file_state["show_plan"] = [PlanObject(obj) for obj in file_state["show_plan"]]
+
+                # Now feed the loaded state into the initialised state manager.
+                self.state = file_state
+            except:
+                self._logException("Failed to parse state JSON. Resetting to default state.")
+                self.state = default_state
+                self.__state_in_file = copy(self.state)
+
+        # Now setup the rate limiting
+        # Essentially rate limit all values to "now" to start with, allowing the first update
+        # of all vars to succeed.
+        for param in rate_limit_params:
+            self.__rate_limit_params_until[param] = self._currentTimeS
+        self.__rate_limit_period_s = rate_limit_period_s
+
+    @property
+    def state(self):
+        return copy(self.__state)
+
+    @state.setter
+    def state(self, state):
+        self.__state = copy(state)
+
+    def write_to_file(self,state):
+        if self.__state_in_file == state:
+            # No change to be updated.
+            return
+
+        self.__state_in_file = state
+
+        # Make sure we're not manipulating state
+        state_to_json = copy(state)
+
+        now = datetime.now()
+
+        current_time = now.strftime("%H:%M:%S")
+        state_to_json["last_updated"] = current_time
+
+        # Not the biggest fan of this, but maybe I'll get a better solution for this later
+        state_to_json["loaded_item"] = state_to_json["loaded_item"].__dict__ if state_to_json["loaded_item"] else None
+        state_to_json["show_plan"] = [repr.__dict__ for repr in state_to_json["show_plan"]]
+        try:
+            state_json = json.dumps(state_to_json, indent=2, sort_keys=True)
+        except:
+            self._logException("Failed to dump JSON state.")
+        else:
+            with open(self.filepath, "w") as file:
+                file.write(state_json)
+
+    def update(self, key, value):
+        update_file = True
+        if (key in self.__rate_limit_params_until.keys()):
+            # The key we're trying to update is expected to be updating very often,
+            # We're therefore going to check before saving it.
+            if self.__rate_limit_params_until[key] > self._currentTimeS:
+                update_file = False
+            else:
+                self.__rate_limit_params_until[key] = self._currentTimeS + self.__rate_limit_period_s
+
+
+        state_to_update = self.state
+
+        if key in state_to_update and state_to_update[key] == value:
+            # We're trying to update the state with the same value.
+            # In this case, ignore the update
+            return
+
+        state_to_update[key] = value
+
+        self.state = state_to_update
+
+        if (update_file == True):
+            self.write_to_file(state_to_update)
+
+    def _log(self, text, level=logging.INFO):
+        self.logger.log.log(level, "State Manager: " + text)
+
+    def _logException(self, text):
+        self.logger.log.exception("State Manager: " + text)
+
+    @property
+    def _currentTimeS(self):
+        return time.time()

install/install.bat

@@ -5,7 +5,7 @@ set service_name="BAPSicle"
 
 mkdir %install_path%
 mkdir %install_path%\state
-
+mkdir %install_path%\logs
 
 cd %~dp0\nssm
 nssm stop %service_name%

player.py

@@ -25,27 +25,30 @@ import setproctitle
 import copy
 import json
 import time
+import sys
 
 from typing import Callable, Dict, List
 
 from plan import PlanObject
 
+# Stop the Pygame Hello message.
 import os
-import sys
-
+os.environ['PYGAME_HIDE_SUPPORT_PROMPT'] = "hide"
 from pygame import mixer
 from mutagen.mp3 import MP3
 
-from state_manager import StateManager
 from helpers.os_environment import isMacOS
+from helpers.state_manager import StateManager
+from helpers.logging_manager import LoggingManager
+
 
-os.environ['PYGAME_HIDE_SUPPORT_PROMPT'] = "hide"
 
 class Player():
     state = None
     running = False
     out_q = None
     last_msg = None
+    logger = None
 
     __default_state = {
         "initialised": False,
@@ -66,6 +69,13 @@ class Player():
         "show_plan": []
     }
 
+    __rate_limited_params = [
+        "pos",
+        "pos_offset",
+        "pos_true",
+        "remaining"
+    ]
+
     @property
     def isInit(self):
         try:
@@ -103,6 +113,7 @@ class Player():
             try:
                 mixer.music.set_volume(1)
             except:
+                self.logger.log.exception("Failed to reset volume after attempting loaded test.")
                 pass
             return False
         if position > 0:
@@ -126,32 +137,31 @@ class Player():
     ### Audio Playout Related Methods
 
     def play(self, pos=0):
-        # if not self.isPlaying:
         try:
             mixer.music.play(0, pos)
             self.state.update("pos_offset", pos)
         except:
+            self.logger.log.exception("Failed to play at pos: " + str(pos))
             return False
         self.state.update("paused", False)
         return True
-        # return False
 
     def pause(self):
-        # if self.isPlaying:
-
         try:
             mixer.music.pause()
         except:
+            self.logger.log.exception("Failed to pause.")
             return False
         self.state.update("paused", True)
         return True
-        # return False
 
     def unpause(self):
         if not self.isPlaying:
+            position = self.state.state["pos_true"]
             try:
-                self.play(self.state.state["pos_true"])
+                self.play(position)
             except:
+                self.logger.log.exception("Failed to unpause from pos: " + str(position))
                 return False
             self.state.update("paused", False)
             return True
@@ -161,8 +171,8 @@ class Player():
         # if self.isPlaying or self.isPaused:
         try:
             mixer.music.stop()
-        except Exception as e:
-            print("Couldn't Stop Player:", e)
+        except:
+            self.logger.log.exception("Failed to stop playing.")
             return False
         self.state.update("pos", 0)
         self.state.update("pos_offset", 0)
@@ -176,6 +186,7 @@ class Player():
             try:
                 self.play(pos)
             except:
+                self.logger.log.exception("Failed to seek to pos: " + str(pos))
                 return False
             return True
         else:
@@ -234,7 +245,7 @@ class Player():
             self.unload()
 
             updated: bool = False
-            
+
             for i in range(len(self.state.state["show_plan"])):
                 if self.state.state["show_plan"][i].timeslotitemid == timeslotitemid:
                     self.state.update("loaded_item", self.state.state["show_plan"][i])
@@ -249,10 +260,11 @@ class Player():
 
 
             try:
+                self.logger.log.info("Loading file: " + str(filename))
                 mixer.music.load(filename)
             except:
                 # We couldn't load that file.
-                print("Couldn't load file:", filename)
+                self.logger.log.exception("Couldn't load file: " + str(filename))
                 return False
 
             try:
@@ -262,6 +274,7 @@ class Player():
                 else:
                     self.state.update("length", mixer.Sound(filename).get_length()/1000)
             except:
+                self.logger.log.exception("Failed to update the length of item.")
                 return False
         return True
 
@@ -272,40 +285,53 @@ class Player():
                 self.state.update("paused", False)
                 self.state.update("loaded_item", None)
             except:
+                self.logger.log.exception("Failed to unload channel.")
                 return False
         return not self.isLoaded
 
     def quit(self):
-        mixer.quit()
-        self.state.update("paused", False)
+        try:
+            mixer.quit()
+            self.state.update("paused", False)
+        except:
+            self.logger.log.exception("Failed to quit mixer.")
 
     def output(self, name=None):
+        wasPlaying = self.state.state["playing"]
+        name = None if name == "none" else name
+
         self.quit()
         self.state.update("output", name)
-        self.state.update("loaded_item", None)
         try:
             if name:
-                mixer.init(44100, -16, 1, 1024, devicename=name)
+                mixer.init(44100, -16, 2, 1024, devicename=name)
             else:
-                mixer.init(44100, -16, 1, 1024)
+                mixer.init(44100, -16, 2, 1024)
         except:
+            self.logger.log.exception("Failed to init mixer with device name: " + str(name))
             return False
 
+        loadedItem = self.state.state["loaded_item"]
+        if (loadedItem):
+            self.load(loadedItem.timeslotitemid)
+        if wasPlaying:
+            self.unpause()
+
         return True
 
     def _updateState(self, pos=None):
+
         self.state.update("initialised", self.isInit)
         if self.isInit:
-            # TODO: get_pos returns the time since the player started playing
-            # This is NOT the same as the position through the song.
-            if self.isPlaying:
+            if (pos):
+                self.state.update("pos", max(0, pos))
+            elif self.isPlaying:
                 # Get one last update in, incase we're about to pause/stop it.
                 self.state.update("pos", max(0, mixer.music.get_pos()/1000))
             self.state.update("playing", self.isPlaying)
             self.state.update("loaded", self.isLoaded)
 
-            if (pos):
-                self.state.update("pos", max(0, pos))
+
 
             self.state.update("pos_true", self.state.state["pos"] + self.state.state["pos_offset"])
 
@@ -314,7 +340,7 @@ class Player():
             if self.state.state["remaining"] == 0 and self.state.state["loaded_item"]:
                 # Track has ended
                 print("Finished", self.state.state["loaded_item"].name)
-                
+
                 # Repeat 1
                 if self.state.state["repeat"] == "ONE":
                     self.play()
@@ -330,11 +356,11 @@ class Player():
                             # Repeat All
                             elif self.state.state["repeat"] == "ALL":
                                 self.load(self.state.state["show_plan"][0].timeslotitemid)
-                
+
                 # Play on Load
                 if self.state.state["play_on_load"]:
                     self.play()
-                
+
 
     def _retMsg(self, msg, okay_str=False):
         response = self.last_msg + ":"
@@ -351,37 +377,41 @@ class Player():
             self.out_q.put(response)
 
     def __init__(self, channel, in_q, out_q):
+
+        process_title = "Player: Channel " + str(channel)
+        setproctitle.setproctitle(process_title)
+        multiprocessing.current_process().name = process_title
+
         self.running = True
         self.out_q = out_q
 
-        setproctitle.setproctitle("BAPSicle - Player " + str(channel))
-
-        self.state = StateManager("channel" + str(channel), self.__default_state)
+        self.logger = LoggingManager("channel" + str(channel))
 
+        self.state = StateManager("channel" + str(channel), self.logger, self.__default_state, self.__rate_limited_params)
         self.state.update("channel", channel)
 
         loaded_state = copy.copy(self.state.state)
 
         if loaded_state["output"]:
-            print("Setting output to: " + loaded_state["output"])
+            self.logger.log.info("Setting output to: " + loaded_state["output"])
             self.output(loaded_state["output"])
         else:
-            print("Using default output device.")
+            self.logger.log.info("Using default output device.")
             self.output()
 
         if loaded_state["loaded_item"]:
-            print("Loading filename: " + loaded_state["loaded_item"].filename)
+            self.logger.log.info("Loading filename: " + loaded_state["loaded_item"].filename)
             self.load(loaded_state["loaded_item"].timeslotitemid)
 
             if loaded_state["pos_true"] != 0:
-                print("Seeking to pos_true: " + str(loaded_state["pos_true"]))
+                self.logger.log.info("Seeking to pos_true: " + str(loaded_state["pos_true"]))
                 self.seek(loaded_state["pos_true"])
 
             if loaded_state["playing"] == True:
-                print("Resuming.")
+                self.logger.log.info("Resuming.")
                 self.unpause()
         else:
-            print("No file was previously loaded.")
+            self.logger.log.info("No file was previously loaded.")
 
         while self.running:
             time.sleep(0.1)
@@ -406,7 +436,7 @@ class Player():
 
                         message_types: Dict[str, Callable[any, bool]] = { # TODO Check Types
                             "STATUS":       lambda: self._retMsg(self.status, True),
-                            
+
                             # Audio Playout
                             "PLAY":         lambda: self._retMsg(self.play()),
                             "PAUSE":        lambda: self._retMsg(self.pause()),
@@ -445,13 +475,16 @@ class Player():
 
             # Catch the player being killed externally.
             except KeyboardInterrupt:
+                self.logger.log.info("Received KeyboardInterupt")
                 break
             except SystemExit:
+                self.logger.log.info("Received SystemExit")
                 break
             except:
-                raise
+                self.logger.log.exception("Received unexpected exception.")
+                break
 
-        print("Quiting player ", channel)
+        self.logger.log.info("Quiting player ", channel)
         self.quit()
         self._retMsg("EXIT")
         sys.exit(0)
@@ -466,7 +499,7 @@ def showOutput(in_q, out_q):
 
 
 if __name__ == "__main__":
-    if isMacOS:
+    if isMacOS():
         multiprocessing.set_start_method("spawn", True)
 
     in_q = multiprocessing.Queue()
@@ -485,7 +518,6 @@ if __name__ == "__main__":
     # Do some testing
     in_q.put("LOADED?")
     in_q.put("PLAY")
-
     in_q.put("LOAD:dev/test.mp3")
     in_q.put("LOADED?")
     in_q.put("PLAY")

server.py

@@ -33,7 +33,13 @@ setproctitle.setproctitle("BAPSicle - Server")
 
 
 class BAPSicleServer():
+
     def __init__(self):
+
+        process_title = "Server"
+        setproctitle.setproctitle(process_title)
+        multiprocessing.current_process().name = process_title
+
         startServer()
 
     def __del__(self):
@@ -195,7 +201,7 @@ def add_to_plan(channel: int):
 @app.route("/player/<int:channel>/move/<int:timeslotitemid>/<int:position>")
 def move_plan(channel: int, timeslotitemid: int, position: int):
     channel_to_q[channel].put("MOVE:" + json.dumps({"timeslotitemid": timeslotitemid, "position": position}))
-    
+
     #TODO Return
     return True
 
@@ -248,7 +254,7 @@ def all_stop():
 @app.route("/player/all/clear")
 def clear_all_channels():
     for channel in channel_to_q:
-        channel.put("CLEAR") 
+        channel.put("CLEAR")
     return ui_status()
 
 
@@ -300,8 +306,8 @@ def startServer():
     }
 
     channel_to_q[0].put("ADD:" + json.dumps(new_item))
-    channel_to_q[0].put("LOAD:0")
-    channel_to_q[0].put("PLAY")
+    #channel_to_q[0].put("LOAD:0")
+    #channel_to_q[0].put("PLAY")
 
     # Don't use reloader, it causes Nested Processes!
 

state_manager.py

@@ -1,73 +0,0 @@
-import copy
-import json
-import os
-from helpers.os_environment import resolve_external_file_path
-from plan import PlanObject
-
-
-class StateManager:
-    filepath = None
-    __state = {}
-
-    def __init__(self, name, default_state=None):
-        try:
-            os.mkdir(resolve_external_file_path("/state"))
-        except FileExistsError:
-            pass
-
-        self.filepath = resolve_external_file_path("/state/" + name + ".json")
-        if not os.path.isfile(self.filepath):
-            self.log("No file found for " + self.filepath)
-            try:
-                # Try creating the file.
-                open(self.filepath, "x")
-            except:
-                self.log("failed to create state file")
-                return
-
-        self.log("Saving state to " + self.filepath)
-
-        file = open(self.filepath, 'r')
-
-        file_state = file.read()
-        file.close()
-
-        # TODO: also check for invalid JSON state
-        if file_state == "":
-            print("file empty")
-
-            self.state = default_state
-
-        else:
-            self.__state = json.loads(file_state)
-
-            # Turn from JSON -> PlanObject
-            self.__state["loaded_item"] = PlanObject(self.__state["loaded_item"]) if self.__state["loaded_item"] else None
-            self.__state["show_plan"] = [PlanObject(obj) for obj in self.__state["show_plan"]]
-
-    @property
-    def state(self):
-        return self.__state
-
-    @state.setter
-    def state(self, state):
-        self.__state = state
-
-        file = open(self.filepath, "w")
-        
-        # Not the biggest fan of this, but maybe I'll get a better solution for this later
-        state_to_json = copy.copy(state)
-        state_to_json["loaded_item"] = state_to_json["loaded_item"].__dict__ if state_to_json["loaded_item"] else None
-        state_to_json["show_plan"] = [repr.__dict__ for repr in state_to_json["show_plan"]]
-
-        file.write(json.dumps(state_to_json, indent=2, sort_keys=True))
-
-        file.close()
-
-    def update(self, key, value):
-        state = self.state
-        state[key] = value
-        self.state = state
-
-    def log(self, msg):
-        print(msg)

templates/config.html

@@ -1,8 +1,9 @@
 {% extends 'base.html' %}
 {% block content_inner %}
 <code>
+  <a href="/player/0/output/none">Set Channel 0</a> <a href="/player/1/output/none">Set Channel 1</a> <a href="/player/2/output/none">Set Channel 2</a> - System Default Output<br>
   {% for output in data.outputs %}
     <a href="/player/0/output/{{output.name}}">Set Channel 0</a> <a href="/player/1/output/{{output.name}}">Set Channel 1</a> <a href="/player/2/output/{{output.name}}">Set Channel 2</a> - {{output.name}}<br>
   {% endfor %}
 </code>
-{% endblock %}
+{% endblock %}