[feat] add a zmq based logger, change log window

- Add a new handler for a zmq/thread-safe log send between components.
- Update the log window to use this new handler.
- Remove old custom handler
  We have implemented a new handler that uses logbook, so this one is no
  longer needed.
- Adapt log silencer to new handler
- Use log file always as default

- Related: #6733

1 files changed, 136 insertions, 39 deletions

diff --git a/src/leap/bitmask/gui/loggerwindow.py b/src/leap/bitmask/gui/logwindow.py
index 463d2412..123f14cc 100644
--- a/src/leap/bitmask/gui/loggerwindow.py
+++ b/src/leap/bitmask/gui/logwindow.py
@@ -1,5 +1,5 @@
 # -*- coding: utf-8 -*-
-# loggerwindow.py
+# logwindow.py
 # Copyright (C) 2013 LEAP
 #
 # This program is free software: you can redistribute it and/or modify
@@ -19,18 +19,96 @@
 History log window
 """
 import cgi
-import logging
 
 from PySide import QtCore, QtGui
 
+import logbook
+from logbook.queues import ZeroMQSubscriber
+
 from ui_loggerwindow import Ui_LoggerWindow
 
+from leap.bitmask.logs import LOG_FORMAT
+from leap.bitmask.logs.utils import get_logger
 from leap.bitmask.util.constants import PASTEBIN_API_DEV_KEY
-from leap.bitmask.logs.leap_log_handler import LeapLogHandler
 from leap.bitmask.util import pastebin
-from leap.common.check import leap_assert, leap_assert_type
 
-logger = logging.getLogger(__name__)
+logger = get_logger()
+
+# log history global variable used to store received logs through different
+# opened instances of this window
+_LOGS_HISTORY = []
+
+
+class QtLogHandler(logbook.Handler,  logbook.StringFormatterHandlerMixin):
+    """
+    Custom log handler which emits a log record with the message properly
+    formatted using a Qt Signal.
+    """
+
+    class _QtSignaler(QtCore.QObject):
+        """
+        inline class used to hold the `new_log` Signal, if this is used
+        directly in the outside class it fails due how PySide works.
+
+        This is the message we get if not use this method:
+        TypeError: Error when calling the metaclass bases
+            metaclass conflict: the metaclass of a derived class must be a
+            (non-strict) subclass of the metaclasses of all its bases
+
+        """
+        new_log = QtCore.Signal(object)
+
+        def emit(self, data):
+            """
+            emit the `new_log` Signal with the given `data` parameter.
+
+            :param data: the data to emit along with the signal.
+            :type data: object
+            """
+            # WARNING: the new-style connection does NOT work because PySide
+            # translates the emit method to self.emit, and that collides with
+            # the emit method for logging.Handler
+            # self.new_log.emit(log_item)
+            QtCore.QObject.emit(self, QtCore.SIGNAL('new_log(PyObject)'), data)
+
+    def __init__(self, level=logbook.NOTSET, format_string=None,
+                 encoding=None, filter=None, bubble=False):
+
+        logbook.Handler.__init__(self, level, filter, bubble)
+        logbook.StringFormatterHandlerMixin.__init__(self, format_string)
+
+        self.qt = self._QtSignaler()
+
+    def __enter__(self):
+        return logbook.Handler.__enter__(self)
+
+    def __exit__(self, exc_type, exc_value, tb):
+        return logbook.Handler.__exit__(self, exc_type, exc_value, tb)
+
+    def emit(self, record):
+        """
+        Emit the specified logging record using a Qt Signal.
+        Also add it to the history in order to be able to access it later.
+
+        :param record: the record to emit
+        :type record: logbook.LogRecord
+        """
+        global _LOGS_HISTORY
+        record.msg = self.format(record)
+        # NOTE: not optimal approach, we may want to look at
+        # bisect.insort with a custom approach to use key or
+        # http://code.activestate.com/recipes/577197-sortedcollection/
+        # Sort logs on arrival, logs transmitted over zmq may arrive unsorted.
+        _LOGS_HISTORY.append(record)
+        _LOGS_HISTORY = sorted(_LOGS_HISTORY, key=lambda r: r.time)
+
+        # XXX: emitting the record on arrival does not allow us to sort here so
+        # in the GUI the logs may arrive with with some time sort problem.
+        # We should implement a sort-on-arrive for the log window.
+        # Maybe we should switch to a tablewidget item that sort automatically
+        # by timestamp.
+        # As a user workaround you can close/open the log window
+        self.qt.emit(record)
 
 
 class LoggerWindow(QtGui.QDialog):
@@ -40,16 +118,11 @@ class LoggerWindow(QtGui.QDialog):
     _paste_ok = QtCore.Signal(object)
     _paste_error = QtCore.Signal(object)
 
-    def __init__(self, parent, handler):
+    def __init__(self, parent):
         """
-        Initialize the widget with the custom handler.
-
-        :param handler: Custom handler that supports history and signal.
-        :type handler: LeapLogHandler.
+        Initialize the widget.
         """
         QtGui.QDialog.__init__(self, parent)
-        leap_assert(handler, "We need a handler for the logger window")
-        leap_assert_type(handler, LeapLogHandler)
 
         # Load UI
         self.ui = Ui_LoggerWindow()
@@ -72,36 +145,38 @@ class LoggerWindow(QtGui.QDialog):
         self._current_filter = ""
         self._current_history = ""
 
-        # Load logging history and connect logger with the widget
-        self._logging_handler = handler
-        self._connect_to_handler()
+        self._set_logs_to_display()
+
+        self._my_handler = QtLogHandler(format_string=LOG_FORMAT)
+        self._my_handler.qt.new_log.connect(self._add_log_line)
+
         self._load_history()
+        self._connect_to_logbook()
 
-    def _connect_to_handler(self):
+    def _connect_to_logbook(self):
         """
-        This method connects the loggerwindow with the handler through a
-        signal communicate the logger events.
+        Run in the background the log receiver.
         """
-        self._logging_handler.new_log.connect(self._add_log_line)
+        subscriber = ZeroMQSubscriber('tcp://127.0.0.1:5000', multi=True)
+        self._logbook_controller = subscriber.dispatch_in_background(
+            self._my_handler)
 
     def _add_log_line(self, log):
         """
         Adds a line to the history, only if it's in the desired levels to show.
 
         :param log: a log record to be inserted in the widget
-        :type log: a dict with RECORD_KEY and MESSAGE_KEY.
-            the record contains the LogRecord of the logging module,
-            the message contains the formatted message for the log.
+        :type log: Logbook.LogRecord.
         """
         html_style = {
-            logging.DEBUG: "background: #CDFFFF;",
-            logging.INFO: "background: white;",
-            logging.WARNING: "background: #FFFF66;",
-            logging.ERROR: "background: red; color: white;",
-            logging.CRITICAL: "background: red; color: white; font: bold;"
+            logbook.DEBUG: "background: #CDFFFF;",
+            logbook.INFO: "background: white;",
+            logbook.WARNING: "background: #FFFF66;",
+            logbook.ERROR: "background: red; color: white;",
+            logbook.CRITICAL: "background: red; color: white; font: bold;"
         }
-        level = log[LeapLogHandler.RECORD_KEY].levelno
-        message = cgi.escape(log[LeapLogHandler.MESSAGE_KEY])
+        level = log.level
+        message = cgi.escape(log.msg)
 
         if self._logs_to_display[level]:
             open_tag = "<tr style='" + html_style[level] + "'>"
@@ -125,12 +200,10 @@ class LoggerWindow(QtGui.QDialog):
         """
         self._set_logs_to_display()
         self.ui.txtLogHistory.clear()
-        history = self._logging_handler.log_history
         current_history = []
-        for line in history:
-            self._add_log_line(line)
-            message = line[LeapLogHandler.MESSAGE_KEY]
-            current_history.append(message)
+        for record in _LOGS_HISTORY:
+            self._add_log_line(record)
+            current_history.append(record.msg)
 
         self._current_history = "\n".join(current_history)
 
@@ -139,11 +212,11 @@ class LoggerWindow(QtGui.QDialog):
         Sets the logs_to_display dict getting the toggled options from the ui
         """
         self._logs_to_display = {
-            logging.DEBUG: self.ui.btnDebug.isChecked(),
-            logging.INFO: self.ui.btnInfo.isChecked(),
-            logging.WARNING: self.ui.btnWarning.isChecked(),
-            logging.ERROR: self.ui.btnError.isChecked(),
-            logging.CRITICAL: self.ui.btnCritical.isChecked()
+            logbook.DEBUG: self.ui.btnDebug.isChecked(),
+            logbook.INFO: self.ui.btnInfo.isChecked(),
+            logbook.WARNING: self.ui.btnWarning.isChecked(),
+            logbook.ERROR: self.ui.btnError.isChecked(),
+            logbook.CRITICAL: self.ui.btnCritical.isChecked()
         }
 
     def _filter_by(self, text):
@@ -261,3 +334,27 @@ class LoggerWindow(QtGui.QDialog):
         self._paste_thread = QtCore.QThread()
         self._paste_thread.run = lambda: do_pastebin()
         self._paste_thread.start()
+
+    def closeEvent(self, e):
+        """
+        Disconnect logger on close.
+        """
+        self._disconnect_logger()
+        e.accept()
+
+    def reject(self):
+        """
+        Disconnect logger on reject.
+        """
+        self._disconnect_logger()
+        QtGui.QDialog.reject(self)
+
+    def _disconnect_logger(self):
+        """
+        Stop the background thread that receives messages through zmq, also
+        close the subscriber socket.
+        This allows us to re-create the subscriber when we reopen this window
+        without getting an error at trying to connect twice to the zmq port.
+        """
+        self._logbook_controller.stop()
+        self._logbook_controller.subscriber.close()