Added logging and fixed CPU thrashing

nxbt/controller/protocol.py

@@ -139,7 +139,6 @@ class ControllerProtocol():
 
         # Parsing the Switch's message
         message = SwitchReportParser(data)
-        # print(message.response)
 
         # Responding to the parsed message
         if message.response == SwitchResponses.REQUEST_DEVICE_INFO:

nxbt/controller/server.py

@@ -2,8 +2,8 @@ import socket
 import fcntl
 import os
 import time
-import traceback
 import queue
+import logging
 
 from .controller import Controller, ControllerTypes
 from ..bluez import BlueZ
@@ -18,6 +18,10 @@ class ControllerServer():
                  state=None, task_queue=None, lock=None, colour_body=None,
                  colour_buttons=None):
 
+        self.logger = logging.getLogger('nxbt')
+        # Cache logging level to increase performance on checks
+        self.logger_level = self.logger.level
+
         if state:
             self.state = state
         else:
@@ -100,8 +104,8 @@ class ControllerServer():
             # Attempt to get output from Switch
             try:
                 reply = itr.recv(50)
-                if len(reply) > 40:
+                if self.logger_level <= logging.DEBUG and len(reply) > 40:
-                    print(format_msg_switch(reply))
+                    self.logger.debug(format_msg_switch(reply))
             except BlockingIOError:
                 reply = None
 
@@ -125,8 +129,8 @@ class ControllerServer():
             self.input.set_protocol_input(state=self.state)
             msg = self.protocol.get_report()
 
-            if reply and len(reply) > 45:
+            if self.logger_level <= logging.DEBUG and reply and len(reply) > 45:
-                print(format_msg_controller(msg))
+                self.logger.debug(format_msg_controller(msg))
 
             try:
                 itr.sendall(msg)
@@ -155,7 +159,7 @@ class ControllerServer():
 
         while self.reconnect_counter < 2:
             try:
-                print("Attempting to reconnect")
+                self.logger.debug("Attempting to reconnect")
                 # Reinitialize the protocol
                 self.protocol = ControllerProtocol(
                     self.controller_type,
@@ -172,12 +176,12 @@ class ControllerServer():
                         self.lock.release()
             except OSError:
                 self.reconnect_counter += 1
-                print(error)
+                self.logger.exception(error)
                 time.sleep(0.5)
 
         # If we can't reconnect, transition to attempting
         # to connect to any Switch.
-        print("Connecting")
+        self.logger.debug("Connecting to any Switch")
         self.reconnect_counter = 0
 
         # Reinitialize the protocol
@@ -189,9 +193,14 @@ class ControllerServer():
         self.input.reassign_protocol(self.protocol)
 
         # Since we were forced to attempt a reconnection
-        # we need to press the L and R buttons before
+        # we need to press the L/SL and R/SR buttons before
         # we can proceed with any input.
-        self.input.current_macro_commands = "L R 0.0s".strip(" ").split(" ")
+        if self.controller_type == ControllerTypes.PRO_CONTROLLER:
+            self.input.current_macro_commands = "L R 0.0s".strip(" ").split(" ")
+        elif self.controller_type == ControllerTypes.JOYCON_L:
+            self.input.current_macro_commands = "JCL_SL JCL_SR 0.0s".strip(" ").split(" ")
+        elif self.controller_type == ControllerTypes.JOYCON_R:
+            self.input.current_macro_commands = "JCR_SL JCR_SR 0.0s".strip(" ").split(" ")
 
         if self.lock:
             self.lock.acquire()
@@ -255,16 +264,16 @@ class ControllerServer():
             # Attempt to get output from Switch
             try:
                 reply = itr.recv(50)
-                if len(reply) > 40:
+                if self.logger_level <= logging.DEBUG and len(reply) > 40:
-                    print(format_msg_switch(reply))
+                    self.logger.debug(format_msg_switch(reply))
             except BlockingIOError:
                 reply = None
 
             self.protocol.process_commands(reply)
             msg = self.protocol.get_report()
 
-            if reply:
+            if self.logger_level <= logging.DEBUG and reply:
-                print(format_msg_controller(msg))
+                self.logger.debug(format_msg_controller(msg))
 
             try:
                 itr.sendall(msg)

nxbt/logging.py

@@ -0,0 +1,30 @@
+import logging
+from datetime import datetime
+
+
+def create_logger(debug=False, log_to_file=False, disable_logging=False):
+
+    logger = logging.getLogger('nxbt')
+
+    if disable_logging:
+        null_handler = logging.NullHandler()
+        logger.addHandler(null_handler)
+        return logger
+
+    if debug:
+        logger.setLevel(logging.DEBUG)
+
+    if log_to_file:
+        file_handler = logging.FileHandler(f'./nxbt {datetime.now()}.log')
+        file_handler.setFormatter(
+            logging.Formatter("[%(asctime)s] %(levelname)s in %(module)s: %(message)s")
+        )
+        logger.addHandler(file_handler)
+    else:
+        stream_handler = logging.StreamHandler()
+        stream_handler.setFormatter(
+            logging.Formatter("[%(asctime)s] %(levelname)s in %(module)s: %(message)s")
+        )
+        logger.addHandler(stream_handler)
+
+    return logger

nxbt/nxbt.py

@@ -4,6 +4,8 @@ from enum import Enum
 import atexit
 import signal
 import os
+import sys
+import time
 
 import dbus
 
@@ -12,6 +14,7 @@ from .controller import ControllerTypes
 from .bluez import find_objects, toggle_input_plugin
 from .bluez import find_devices_by_alias
 from .bluez import SERVICE_NAME, ADAPTER_INTERFACE
+from .logging import create_logger
 
 
 JOYCON_L = ControllerTypes.JOYCON_L
@@ -82,7 +85,23 @@ class Nxbt():
     This allows for thread-safe control of emulated controllers.
     """
 
-    def __init__(self):
+    def __init__(self, debug=False, log_to_file=False, disable_logging=False):
+        """Initializes the necessary multiprocessing resources and starts
+        the multiprocessing processes.
+
+        :param debug: Enables the debugging functionality of
+        nxbt, defaults to False
+        :type debug: bool, optional
+        :param log_to_file: A boolean value that indiciates whether or not
+        a log should be saved to the current working directory, defaults to False
+        :type log_to_file: bool, optional
+        :param disable_logging: Routes all logging calls to a null log handler.
+        :type disable_logging: bool, optional, defaults to False.
+        """
+
+        self.debug = debug
+        self.logger = create_logger(
+            debug=self.debug, log_to_file=log_to_file, disable_logging=disable_logging)
 
         # Main queue for nbxt tasks
         self.task_queue = Queue()
@@ -93,7 +112,7 @@ class Nxbt():
         # Creates/manages shared resources
         self.resource_manager = Manager()
         # Shared dictionary for viewing overall nxbt state.
-        # Should only be read by threads and wrote to by
+        # Should treated as read-only except by
         # the main nxbt multiprocessing process.
         self.manager_state = self.resource_manager.dict()
         self.manager_state_lock = Lock()
@@ -156,12 +175,12 @@ class Nxbt():
         cm = __ControllerManager__(state, self.__bluetooth_lock__)
         # Ensure a SystemExit exception is raised on SIGTERM
         # so that we can gracefully shutdown.
-        signal.signal(signal.SIGTERM, lambda sigterm_handler: quit())
+        signal.signal(signal.SIGTERM, lambda sigterm_handler: sys.exit(0))
 
         try:
             while True:
                 try:
-                    msg = task_queue.get_nowait()
+                    msg = task_queue.get(timeout=5)
                 except queue.Empty:
                     msg = None
 
@@ -192,7 +211,7 @@ class Nxbt():
 
         finally:
             cm.shutdown()
-            quit()
+            sys.exit(0)
 
     def macro(self, controller_index, macro, block=True):
         """Used to input a given macro on a specified controller.
@@ -241,6 +260,8 @@ class Nxbt():
                 if macro_id in finished:
                     break
 
+                time.sleep(1/120)  # Wait one Pro Controller cycle
+
         return macro_id
 
     def press_buttons(self, controller_index, buttons, down=0.1, up=0.1, block=True):
@@ -358,6 +379,8 @@ class Nxbt():
                 if macro_id in finished:
                     break
 
+                time.sleep(1/120)
+
     def clear_macros(self, controller_index):
         """Clears all running and queued macros on a specified
         controller.
@@ -468,6 +491,8 @@ class Nxbt():
                                 state["state"] == "reconnecting" or
                                 state["state"] == "crashed"):
                             break
+
+                    time.sleep(1/30)
         finally:
             self.__controller_lock__.release()