Improved logging mechanism (and a few minor goodies) (#54)

* Improved logging mechanism

* Allow for suppression of any errors regarding failed device updates

gateway.py

@@ -1,48 +1,59 @@
 #!/usr/bin/env python3
 
-import logging
 import sys
 
 if sys.version_info < (3, 5):
   print("To use this script you need python 3.5 or newer! got %s" % sys.version_info)
   sys.exit(1)
 
-from logger import _LOGGER
+import logger
+logger.setup()
+
+import logging
 import argparse
+import queue
+
 from workers_queue import _WORKERS_QUEUE
 from config import settings
 from mqtt import MqttClient
 from workers_manager import WorkersManager
 
+
 parser = argparse.ArgumentParser()
 group = parser.add_mutually_exclusive_group()
-group.add_argument('-d', '--debug', action='store_true', default=False)
-group.add_argument('-q', '--quiet', action='store_true', default=False)
+group.add_argument('-d', '--debug', action='store_true', default=False, help='Set logging to output debug information')
+group.add_argument('-q', '--quiet', action='store_true', default=False, help='Set logging to just output warnings and errors')
+parser.add_argument('-s', '--suppress-update-failures', dest='suppress', action='store_true', default=False, help='Suppress any errors regarding failed device updates')
 parsed = parser.parse_args()
 
-if parsed.debug:
+_LOGGER = logger.get()
+if parsed.quiet:
+  _LOGGER.setLevel(logging.WARNING)
+elif parsed.debug:
   _LOGGER.setLevel(logging.DEBUG)
+  logger.enable_debug_formatter()
 else:
   _LOGGER.setLevel(logging.INFO)
+logger.suppress_update_failures(parsed.suppress)
 
-_LOGGER.debug('Starting')
+_LOGGER.info('Starting')
 
 mqtt = MqttClient(settings['mqtt'])
 manager = WorkersManager()
 manager.register_workers(settings['manager']).start(mqtt)
 
 running = True
 
-try:
-  while running:
-      try:
-        mqtt.publish(_WORKERS_QUEUE.get(block=True).execute())
-      except (KeyboardInterrupt, SystemExit):
-        raise
-      except Exception as e:
-        if not parsed.quiet:
-          _LOGGER.exception(e)
-except KeyboardInterrupt:
-  running = False
-  _LOGGER.info('Exiting allowing jobs to finish. If you need force exit use kill')
-
+while running:
+  try:
+    mqtt.publish(_WORKERS_QUEUE.get(timeout=10).execute())
+  except queue.Empty: # Allow for SIGINT processing
+    pass
+  except TimeoutError:
+    logger.log_exception(_LOGGER, "Timeout while executing worker command", suppress=True)
+  except (KeyboardInterrupt, SystemExit):
+    running = False
+    _LOGGER.info('Finish current jobs and shut down. If you need force exit use kill')
+  except Exception as e:
+    logger.log_exception(_LOGGER, "Fatal error while executing worker command: %s", type(e).__name__)
+    raise e

logger.py

@@ -1,6 +1,50 @@
 import logging
+import logging.config
+import yaml
 
-import sys
+APP_ROOT = 'bt-mqtt-gw'
+SUPPRESSION_ENABLED = False
 
-_LOGGER = logging.getLogger('bt-mqtt-gw')
-_LOGGER.addHandler(logging.StreamHandler(sys.stdout))
+
+def setup():
+  with open('logger.yaml', 'rt') as f:
+    config = yaml.safe_load(f.read())
+    logging.config.dictConfig(config)
+
+
+def get(name=None):
+  if name:
+    logger_name = '{}.{}'.format(APP_ROOT, name)
+  else:
+    logger_name = APP_ROOT
+  return logging.getLogger(logger_name)
+
+
+def enable_debug_formatter():
+  logging.getLogger().handlers[0].setFormatter(logging.getLogger('dummy_debug').handlers[0].formatter)
+
+
+def reset():
+  app_level = get().getEffectiveLevel()
+
+  root = logging.getLogger()
+  map(root.removeHandler, root.handlers[:])
+  map(root.removeFilter, root.filters[:])
+
+  setup()
+  get().setLevel(app_level)
+  if app_level <= logging.DEBUG:
+    enable_debug_formatter()
+
+
+def suppress_update_failures(suppress):
+  global SUPPRESSION_ENABLED
+  SUPPRESSION_ENABLED = suppress
+
+
+def log_exception(logger, message, *args, **kwargs):
+  if not ('suppress' in kwargs and kwargs.pop('suppress') and SUPPRESSION_ENABLED):
+    if logger.isEnabledFor(logging.DEBUG):
+      logger.exception(message, *args, **kwargs)
+    elif logger.isEnabledFor(logging.WARNING):
+      logger.warning(message, *args, **kwargs)

logger.yaml

@@ -0,0 +1,29 @@
+version: 1
+disable_existing_loggers: True
+
+formatters:
+  default:
+    format: '%(asctime)s %(message)s'
+    datefmt: '%X'
+  minimal:
+    format: '%(message)s'
+  debug:
+    format: '%(asctime)s %(levelname)s %(name)s %(filename)s:%(lineno)d:%(funcName)s - %(message)s'
+
+handlers:
+  console:
+    class: logging.StreamHandler
+    formatter: default
+    stream: ext://sys.stdout
+  dummy_debug:
+    class: logging.NullHandler
+    formatter: debug
+
+loggers:
+  bt-mqtt-gw:
+    level: INFO
+  dummy_debug:
+    handlers: [dummy_debug]
+
+root:
+  handlers: [console]

mqtt.py

@@ -1,8 +1,9 @@
 import paho.mqtt.client as mqtt
-from logger import _LOGGER
+import logger
 
 LWT_ONLINE = 'online'
 LWT_OFFLINE = 'offline'
+_LOGGER = logger.get(__name__)
 
 class MqttClient:
 

workers/base.py

@@ -9,3 +9,6 @@ def _setup(self):
 
   def format_topic(self, *args):
     return '/'.join([self.topic_prefix, *args])
+
+  def __repr__(self):
+    return self.__module__.split(".")[-1]

workers/blescanmulti.py

@@ -1,12 +1,15 @@
 import time
-from interruptingcow import timeout
+
 from bluepy.btle import Scanner, DefaultDelegate
 from mqtt import MqttMessage
-from utils import booleanize
+
 from workers.base import BaseWorker
-from logger import _LOGGER
+from utils import booleanize
+import logger
 
 REQUIREMENTS = ['bluepy']
+_LOGGER = logger.get(__name__)
+
 
 
 class ScanDelegate(DefaultDelegate):

workers/linakdesk.py

@@ -15,7 +15,7 @@ def status_update(self):
     return [MqttMessage(topic=self.format_topic('height/cm'), payload=self._get_height())]
 
   def _get_height(self):
-    with timeout(20):
+    with timeout(20, exception=TimeoutError):
       self.desk.read_dpg_data()
       return self.desk.current_height_with_offset.cm
 

workers/miflora.py

@@ -1,29 +1,37 @@
-from interruptingcow import timeout
+import logging
+
 from mqtt import MqttMessage
+
 from workers.base import BaseWorker
+import logger
 
 REQUIREMENTS = ['git+https://github.com/open-homeautomation/miflora.git@84f39432082796412d05b754c948499a1ad710e7#egg=miflora', 'bluepy']
-
 monitoredAttrs = ["temperature", "moisture", "light", "conductivity", "battery"]
+_LOGGER = logger.get(__name__)
+
 
 class MifloraWorker(BaseWorker):
   def _setup(self):
     from miflora.miflora_poller import MiFloraPoller
     from btlewrap.bluepy import BluepyBackend
 
+    _LOGGER.info("Adding %d %s devices", len(self.devices), repr(self))
     for name, mac in self.devices.items():
+      _LOGGER.debug("Adding %s device '%s' (%s)", repr(self), name, mac)
       self.devices[name] = MiFloraPoller(mac, BluepyBackend)
 
   def status_update(self):
+    from btlewrap.base import BluetoothBackendException
+    _LOGGER.info("Updating %d %s devices", len(self.devices), repr(self))
     ret = []
     for name, poller in self.devices.items():
+      _LOGGER.debug("Updating %s device '%s' (%s)", repr(self), name, poller._mac)
       try:
         ret += self.update_device_state(name, poller)
-      except RuntimeError:
-        pass
+      except BluetoothBackendException as e:
+        logger.log_exception(_LOGGER, "Error during update of %s device '%s' (%s): %s", repr(self), name, poller._mac, type(e).__name__, suppress=True)
     return ret
 
-  @timeout(8.0)
   def update_device_state(self, name, poller):
     ret = []
     poller.clear_cache()

workers/miscale.py

@@ -21,7 +21,7 @@ def _get_weight(self):
     scanner = btle.Scanner().withDelegate(scan_processor)
     scanner.scan(5, passive=True)
 
-    with timeout(5):
+    with timeout(5, exception=TimeoutError):
       while scan_processor.weight is None:
         time.sleep(1)
       return scan_processor.weight

workers/mithermometer.py

@@ -1,31 +1,37 @@
-from interruptingcow import timeout
+import logging
+
 from mqtt import MqttMessage
+
 from workers.base import BaseWorker
+import logger
 
 REQUIREMENTS = ['mithermometer==0.1.2']
-
 monitoredAttrs = ["temperature", "humidity", "battery"]
+_LOGGER = logger.get(__name__)
+
 
 class MithermometerWorker(BaseWorker):
   def _setup(self):
     from mithermometer.mithermometer_poller import MiThermometerPoller
     from btlewrap.bluepy import BluepyBackend
 
-
+    _LOGGER.info("Adding %d %s devices", len(self.devices), repr(self))
     for name, mac in self.devices.items():
+      _LOGGER.debug("Adding %s device '%s' (%s)", repr(self), name, mac)
       self.devices[name] = MiThermometerPoller(mac, BluepyBackend)
 
   def status_update(self):
+    from btlewrap.base import BluetoothBackendException
+    _LOGGER.info("Updating %d %s devices", len(self.devices), repr(self))
     ret = []
     for name, poller in self.devices.items():
+      _LOGGER.debug("Updating %s device '%s' (%s)", repr(self), name, poller._mac)
       try:
         ret += self.update_device_state(name, poller)
-      except RuntimeError:
-        pass
-
+      except BluetoothBackendException as e:
+        logger.log_exception(_LOGGER, "Error during update of %s device '%s' (%s): %s", repr(self), name, poller._mac, type(e).__name__, suppress=True)
     return ret
 
-  @timeout(8.0)
   def update_device_state(self, name, poller):
     ret = []
     poller.clear_cache()

workers/mysensors.py

@@ -1,9 +1,11 @@
+import serial
 from mqtt import MqttMessage
+
 from workers.base import BaseWorker
-from logger import _LOGGER
-import serial
+import logger
 
 REQUIREMENTS = ['pyserial']
+_LOGGER = logger.get(__name__)
 
 
 class MysensorsWorker(BaseWorker):

workers/thermostat.py

@@ -1,12 +1,14 @@
 from builtins import staticmethod
+import logging
 
-from interruptingcow import timeout
 from mqtt import MqttMessage
+
 from workers.base import BaseWorker
+import logger
 
 REQUIREMENTS = ['python-eq3bt']
-
 monitoredAttrs = ["low_battery", "valve_state", "target_temperature", "window_open", "locked"]
+_LOGGER = logger.get(__name__)
 
 STATE_AWAY = 'away'
 STATE_ECO  = 'eco'
@@ -15,6 +17,7 @@
 STATE_ON = 'on'
 STATE_OFF = 'off'
 
+
 class ThermostatWorker(BaseWorker):
   class ModesMapper():
     def __init__(self):
@@ -57,7 +60,9 @@ def on_off_to_mode(on_off):
   def _setup(self):
     from eq3bt import Thermostat
 
+    _LOGGER.info("Adding %d %s devices", len(self.devices), repr(self))
     for name, mac in self.devices.items():
+      _LOGGER.debug("Adding %s device '%s' (%s)", repr(self), name, mac)
       self.devices[name] = Thermostat(mac)
 
     self._modes_mapper = self.ModesMapper()
@@ -66,15 +71,17 @@ def status_update(self):
     from bluepy import btle
 
     ret = []
+    _LOGGER.info("Updating %d %s devices", len(self.devices), repr(self))
     for name, thermostat in self.devices.items():
+      _LOGGER.debug("Updating %s device '%s' (%s)", repr(self), name, thermostat._conn._mac)
       try:
         ret += self.update_device_state(name, thermostat)
-      except (RuntimeError, btle.BTLEException):
-        pass
-
+      except btle.BTLEException as e:
+        logger.log_exception(_LOGGER, "Error during update of %s device '%s' (%s): %s", repr(self), name, thermostat._conn._mac, type(e).__name__, suppress=True)
     return ret
 
   def on_command(self, topic, value):
+    from bluepy import btle
     _, device_name, method, _ = topic.split('/')
 
     thermostat = self.devices[device_name]
@@ -91,10 +98,19 @@ def on_command(self, topic, value):
     elif method == "target_temperature":
       value = float(value)
 
-    setattr(thermostat, method, value)
-    return self.update_device_state(device_name, thermostat)
+    _LOGGER.info("Setting %s to %s on %s device '%s' (%s)", method, value, repr(self), device_name, thermostat._conn._mac)
+    try:
+      setattr(thermostat, method, value)
+    except btle.BTLEException as e:
+      logger.log_exception(_LOGGER, "Error setting %s to %s on %s device '%s' (%s): %s", method, value, repr(self), device_name, thermostat._conn._mac, type(e).__name__)
+      return []
+
+    try:
+      return self.update_device_state(device_name, thermostat)
+    except btle.BTLEException as e:
+      logger.log_exception(_LOGGER, "Error during update of %s device '%s' (%s): %s", repr(self), device_name, thermostat._conn._mac, type(e).__name__, suppress=True)
+      return []
 
-  @timeout(8.0)
   def update_device_state(self, name, thermostat):
     thermostat.update()