Merge pull request #173 from segfault16/updater-fixes

Add configurable loglevel, fix updater

audioled_controller/bluetooth.py

@@ -4,10 +4,8 @@
 import traceback
 import logging
 import time
-import os
 
 from audioled_controller import midi_timestamp
-logging.basicConfig(level=os.environ.get("LOGLEVEL", "INFO"))
 logger = logging.getLogger(__name__)
 
 class BluetoothMidiLELevelCharacteristic(pybleno.Characteristic):

audioled_controller/midi_full.py

@@ -13,6 +13,7 @@
 import sys
 import threading
 import signal
+import shutil
 from collections.abc import Iterable   # drop `.abc` with Python 2.7 or lower
 
 logger = logging.getLogger(__name__)
@@ -182,17 +183,30 @@ def _handleSysex(self, data, serverconfig: serverconfiguration.ServerConfigurati
 
             if not self._isUpdating:
                 self._isUpdating = True
-                self.client.refresh()
-                app_update = self.client.update_check('Molecole', version.get_version())
-                self._isUpdating = False
-                if app_update is not None:
-                    logger.info("Update {} available".format(app_update.version))
-                    if self._sendMidiCallback is not None:
-                        self._sendMidiCallback(self._createUpdateVersionAvailableMsg(app_update.version))
-                else:
-                    logger.info("Update check returned no update")
-                    if self._sendMidiCallback is not None:
-                        self._sendMidiCallback(self._createUpdateNotAvailableMsg())
+                try:
+                    # Move version.gz to force a reload
+                    oldFile = os.path.join(self.client.data_dir, self.client.version_file)
+                    if os.path.exists(oldFile):
+                        shutil.move(oldFile, oldFile.replace('.gz', '.gz.bak'))
+
+                    oldFile = os.path.join(self.client.data_dir, self.client.version_file_compat)
+                    if os.path.exists(oldFile):
+                        shutil.move(oldFile, oldFile.replace('.gz', '.gz.bak'))
+
+                    self.client.refresh()
+                    app_update = self.client.update_check('Molecole', version.get_version())
+                    self._isUpdating = False
+                    if app_update is not None:
+                        logger.info("Update {} available".format(app_update.version))
+                        if self._sendMidiCallback is not None:
+                            self._sendMidiCallback(self._createUpdateVersionAvailableMsg(app_update.version))
+                    else:
+                        logger.info("Update check returned no update")
+                        if self._sendMidiCallback is not None:
+                            self._sendMidiCallback(self._createUpdateNotAvailableMsg())
+                except Exception as e:
+                    logger.error("Error trying to update: {}".format(e))
+                    self._isUpdating = False
             else:
                 if self._sendMidiCallback is not None:
                     self._sendMidiCallback(self._createUpdateBusyMsg())
@@ -353,8 +367,9 @@ def _updateApp(self, app_update):
             logger.debug("Starting download in background")
             threading.current_thread().name = 'UpdateThread'
             app_update.download()
-            logger.info("Update downloaded")
+
             if app_update.is_downloaded():
+                logger.info("Update downloaded")
                 if not getattr(sys, 'frozen', False):
                     logger.info("Not running from executable. Extract only")
                     logger.debug("Extracting update")
@@ -368,8 +383,10 @@ def _updateApp(self, app_update):
                     app_update.extract_overwrite()
                     logger.info("Extracting done. Killing server")
                     os.kill(os.getpid(), signal.SIGUSR1)
+            else:
+                if self._sendMidiCallback is not None:
+                    self._sendMidiCallback(self._createUpdateNotAvailableMsg())
             logger.debug("End of update")
-
         finally:
             self._isUpdating = False
 

btbridge.py

@@ -8,6 +8,7 @@
 import time
 import queue
 import argparse
+import os
 
 
 logger = logging.getLogger(__name__)
@@ -28,7 +29,7 @@ def record_factory(*args, **kwargs):
 
 logging.setLogRecordFactory(record_factory)
 logging.basicConfig(stream=sys.stdout,
-                    level=logging.INFO,
+                    level=os.environ.get("LOGLEVEL", "INFO"),
                     format='[%(relativeCreated)6d %(sthreadName)10s  ] %(sname)10s:%(levelname)s %(message)s')
 
 bt = None
@@ -84,13 +85,11 @@ def msgStream():
 def startThreading(channel):
     global thread_lock
     global grpc_client
-    print("START")
     try:
         thread_lock.acquire()
         if grpc_client is None:
             logger.info("Start receiving GRPC...")
             grpc_client = grpc_midi_pb2_grpc.MidiStub(channel)
-            print("GO!")
             thread_lock.release()
             for msg in grpc_client.MidiChat(msgStream()):
                 midi_msg = mido.Message.from_bytes(msg.data)

server.py

@@ -42,23 +42,47 @@ def record_factory(*args, **kwargs):
         record.sthreadName = record.threadName
     return record
 
+logLevel = os.environ.get("LOGLEVEL", "INFO")
+levelPerModule = {
+    "apscheduler": "ERROR",
+    "audioled": "INFO",
+    "audioled.audio": "INFO",
+    "audioled_controller": "INFO",
+    "audioled_controller.bluetooth": "INFO",
+    "root": "INFO",
+    "audioled.audio.libasound": "INFO",
+    "pyupdater": "INFO"
+}
+if len(logLevel.split(',')) > 1:
+    # Global loglevel
+    levelPerModule = {}
+    for item in logLevel.split(','):
+        print(item)
+        keyVal = item.split("=")
+        if len(keyVal) == 2:
+            levelPerModule[keyVal[0]] = keyVal[1]
+    logLevel = "INFO"
+elif logLevel == "DEBUG":
+    levelPerModule = {}
+elif '=' in logLevel:
+    levelPerModule = {}
+    keyVal = logLevel.split("=")
+
+    if len(keyVal) == 2:
+        levelPerModule[keyVal[0]] = keyVal[1]
+    logLevel = "INFO"    
 
 logging.setLogRecordFactory(record_factory)
 logging.basicConfig(stream=sys.stdout,
-                    level=logging.INFO,
+                    level=logLevel,
                     format='[%(relativeCreated)6d %(sthreadName)10s  ] %(sname)10s:%(levelname)s %(message)s')
 logging.debug("Global debug log enabled")
 # Adjust loglevels
-logging.getLogger('apscheduler').setLevel(logging.ERROR)
-logging.getLogger('audioled').setLevel(logging.INFO)
-logging.getLogger('audioled.audio').setLevel(logging.INFO)
-logging.getLogger('audioled_controller').setLevel(logging.INFO)
-logging.getLogger('audioled_controller.bluetooth').setLevel(logging.INFO)
-logging.getLogger('root').setLevel(logging.INFO)
-logging.getLogger('audioled.audio.libasound').setLevel(logging.INFO)  # Silence!
-logging.getLogger('pyupdater').setLevel(logging.INFO)
+for key, value in levelPerModule.items():
+    logging.getLogger(key).setLevel(value)
+    print("Setting loglevel for {} to {}".format(key, value))
+logging.getLogger('apscheduler').setLevel("ERROR")
 logger = logging.getLogger(__name__)
-logger.setLevel(logging.INFO)
 
 libnames = ['audioled_controller.bluetooth']
 for libname in libnames: