[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

6 files changed, 159 insertions, 319 deletions

diff --git a/src/leap/bitmask/logs/__init__.py b/src/leap/bitmask/logs/__init__.py
index 0516b304..837a5ed9 100644
--- a/src/leap/bitmask/logs/__init__.py
+++ b/src/leap/bitmask/logs/__init__.py
@@ -1,3 +1,3 @@
-# levelname length == 8, since 'CRITICAL' is the longest
-LOG_FORMAT = ('%(asctime)s - %(levelname)-8s - '
-              'L#%(lineno)-4s : %(name)s:%(funcName)s() - %(message)s')
+LOG_FORMAT = (u'[{record.time:%Y-%m-%d %H:%M:%S}] '
+              u'{record.level_name: <8} - L#{record.lineno: <4} : '
+              u'{record.module}:{record.func_name} - {record.message}')
diff --git a/src/leap/bitmask/logs/leap_log_handler.py b/src/leap/bitmask/logs/leap_log_handler.py
deleted file mode 100644
index 24141638..00000000
--- a/src/leap/bitmask/logs/leap_log_handler.py
+++ /dev/null
@@ -1,137 +0,0 @@
-# -*- coding: utf-8 -*-
-# leap_log_handler.py
-# Copyright (C) 2013 LEAP
-#
-# This program is free software: you can redistribute it and/or modify
-# it under the terms of the GNU General Public License as published by
-# the Free Software Foundation, either version 3 of the License, or
-# (at your option) any later version.
-#
-# This program is distributed in the hope that it will be useful,
-# but WITHOUT ANY WARRANTY; without even the implied warranty of
-# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
-# GNU General Public License for more details.
-#
-# You should have received a copy of the GNU General Public License
-# along with this program.  If not, see <http://www.gnu.org/licenses/>.
-"""
-Custom handler for the logger window.
-"""
-import logging
-
-from PySide import QtCore
-
-from leap.bitmask.logs import LOG_FORMAT
-
-
-class LogHandler(logging.Handler):
-    """
-    This is the custom handler that implements our desired formatting
-    and also keeps a history of all the logged events.
-    """
-
-    MESSAGE_KEY = 'message'
-    RECORD_KEY = 'record'
-
-    def __init__(self, qtsignal):
-        """
-        LogHander initialization.
-        Calls parent method and keeps a reference to the qtsignal
-        that will be used to fire the gui update.
-        """
-        # TODO This is going to eat lots of memory after some time.
-        # Should be pruned at some moment.
-        self._log_history = []
-
-        logging.Handler.__init__(self)
-        self._qtsignal = qtsignal
-
-    def _get_format(self, logging_level):
-        """
-        Sets the log format depending on the parameter.
-        It uses html and css to set the colors for the logs.
-
-        :param logging_level: the debug level to define the color.
-        :type logging_level: str.
-        """
-        formatter = logging.Formatter(LOG_FORMAT)
-        return formatter
-
-    def emit(self, logRecord):
-        """
-        This method is fired every time that a record is logged by the
-        logging module.
-        This method reimplements logging.Handler.emit that is fired
-        in every logged message.
-
-        :param logRecord: the record emitted by the logging module.
-        :type logRecord: logging.LogRecord.
-        """
-        self.setFormatter(self._get_format(logRecord.levelname))
-        log = self.format(logRecord)
-        log_item = {self.RECORD_KEY: logRecord, self.MESSAGE_KEY: log}
-        self._log_history.append(log_item)
-        self._qtsignal(log_item)
-
-
-class HandlerAdapter(object):
-    """
-    New style class that accesses all attributes from the LogHandler.
-
-    Used as a workaround for a problem with multiple inheritance with Pyside
-    that surfaced under OSX with pyside 1.1.0.
-    """
-    MESSAGE_KEY = 'message'
-    RECORD_KEY = 'record'
-
-    def __init__(self, qtsignal):
-        self._handler = LogHandler(qtsignal=qtsignal)
-
-    def setLevel(self, *args, **kwargs):
-        return self._handler.setLevel(*args, **kwargs)
-
-    def addFilter(self, *args, **kwargs):
-        return self._handler.addFilter(*args, **kwargs)
-
-    def handle(self, *args, **kwargs):
-        return self._handler.handle(*args, **kwargs)
-
-    @property
-    def level(self):
-        return self._handler.level
-
-
-class LeapLogHandler(QtCore.QObject, HandlerAdapter):
-    """
-    Custom logging handler. It emits Qt signals so it can be plugged to a gui.
-
-    Its inner handler also stores an history of logs that can be fetched after
-    having been connected to a gui.
-    """
-    # All dicts returned are of the form
-    # {'record': LogRecord, 'message': str}
-    new_log = QtCore.Signal(dict)
-
-    def __init__(self):
-        """
-        LeapLogHandler initialization.
-        Initializes parent classes.
-        """
-        QtCore.QObject.__init__(self)
-        HandlerAdapter.__init__(self, qtsignal=self.qtsignal)
-
-    def qtsignal(self, log_item):
-        # 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)'), log_item)
-
-    @property
-    def log_history(self):
-        """
-        Returns the history of the logged messages.
-        """
-        return self._handler._log_history
diff --git a/src/leap/bitmask/logs/log_silencer.py b/src/leap/bitmask/logs/log_silencer.py
index 56b290e4..540532cb 100644
--- a/src/leap/bitmask/logs/log_silencer.py
+++ b/src/leap/bitmask/logs/log_silencer.py
@@ -17,14 +17,13 @@
 """
 Filter for leap logs.
 """
-import logging
 import os
 import re
 
 from leap.bitmask.util import get_path_prefix
 
 
-class SelectiveSilencerFilter(logging.Filter):
+class SelectiveSilencerFilter(object):
     """
     Configurable filter for root leap logger.
 
@@ -75,7 +74,7 @@ class SelectiveSilencerFilter(logging.Filter):
         return map(lambda line: re.sub('\s', '', line),
                    lines)
 
-    def filter(self, record):
+    def filter(self, record, handler):
         """
         Implements the filter functionality for this Filter
 
@@ -86,7 +85,10 @@ class SelectiveSilencerFilter(logging.Filter):
         """
         if not self.rules:
             return True
-        logger_path = record.name
+        logger_path = record.module
+        if logger_path is None:
+            return True
+
         for path in self.rules:
             if logger_path.startswith(path):
                 return False
diff --git a/src/leap/bitmask/logs/safezmqhandler.py b/src/leap/bitmask/logs/safezmqhandler.py
new file mode 100644
index 00000000..7aac6a6a
--- /dev/null
+++ b/src/leap/bitmask/logs/safezmqhandler.py
@@ -0,0 +1,118 @@
+# -*- coding: utf-8 -*-
+# safezmqhandler.py
+# Copyright (C) 2013, 2014, 2015 LEAP
+#
+# This program is free software: you can redistribute it and/or modify
+# it under the terms of the GNU General Public License as published by
+# the Free Software Foundation, either version 3 of the License, or
+# (at your option) any later version.
+#
+# This program is distributed in the hope that it will be useful,
+# but WITHOUT ANY WARRANTY; without even the implied warranty of
+# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+# GNU General Public License for more details.
+#
+# You should have received a copy of the GNU General Public License
+# along with this program.  If not, see <http://www.gnu.org/licenses/>.
+"""
+A thread-safe zmq handler for LogBook.
+"""
+import json
+import threading
+
+from logbook.queues import ZeroMQHandler
+from logbook import NOTSET
+
+import zmq
+
+
+class SafeZMQHandler(ZeroMQHandler):
+    """
+    A ZMQ log handler for LogBook that is thread-safe.
+
+    This log handler makes use of the existing zmq handler and if the user
+    tries to log something from a different thread than the one used to
+    create the handler a new socket is created for that thread.
+
+    Note: In ZMQ, Contexts are threadsafe objects, but Sockets are not.
+    """
+
+    def __init__(self, uri=None, level=NOTSET, filter=None, bubble=False,
+                 context=None, multi=False):
+
+        ZeroMQHandler.__init__(self, uri, level, filter, bubble, context,
+                               multi)
+
+        current_id = self._get_caller_id()
+        # we store the socket created on the parent
+        self._sockets = {current_id: self.socket}
+
+        # store the settings for new socket creation
+        self._multi = multi
+        self._uri = uri
+
+    def _get_caller_id(self):
+        """
+        Return an id for the caller that depends on the current thread.
+        Thanks to this we can detect if we are running in a thread different
+        than the one who created the socket and create a new one for it.
+
+        :rtype: int
+        """
+        # NOTE it makes no sense to use multiprocessing id since the sockets
+        # list can't/shouldn't be shared between processes. We only use
+        # thread id. The user needs to make sure that the handler is created
+        # inside each process.
+        return threading.current_thread().ident
+
+    def _get_new_socket(self):
+        """
+        Return a new socket using the `uri` and `multi` parameters given in the
+        constructor.
+
+        :rtype: zmq.Socket
+        """
+        socket = None
+
+        if self._multi:
+            socket = self.context.socket(zmq.PUSH)
+            if self._uri is not None:
+                socket.connect(self._uri)
+        else:
+            socket = self.context.socket(zmq.PUB)
+            if self._uri is not None:
+                socket.bind(self._uri)
+
+        return socket
+
+    def emit(self, record):
+        """
+        Emit the given `record` through the socket.
+
+        :param record: the record to emit
+        :type record: Logbook.LogRecord
+        """
+        current_id = self._get_caller_id()
+        socket = None
+
+        if current_id in self._sockets:
+            socket = self._sockets[current_id]
+        else:
+            # TODO: create new socket
+            socket = self._get_new_socket()
+            self._sockets[current_id] = socket
+
+        socket.send(json.dumps(self.export_record(record)).encode("utf-8"))
+
+    def close(self, linger=-1):
+        """
+        Close all the sockets and linger `linger` time.
+
+        This reimplements the ZeroMQHandler.close method that is used by
+        context methods.
+
+        :param linger: time to linger, -1 to not to.
+        :type linger: int
+        """
+        for socket in self._sockets.values():
+            socket.close(linger)
diff --git a/src/leap/bitmask/logs/tests/test_leap_log_handler.py b/src/leap/bitmask/logs/tests/test_leap_log_handler.py
deleted file mode 100644
index 20b09aef..00000000
--- a/src/leap/bitmask/logs/tests/test_leap_log_handler.py
+++ /dev/null
@@ -1,120 +0,0 @@
-# -*- coding: utf-8 -*-
-# test_leap_log_handler.py
-# Copyright (C) 2013 LEAP
-#
-# This program is free software: you can redistribute it and/or modify
-# it under the terms of the GNU General Public License as published by
-# the Free Software Foundation, either version 3 of the License, or
-# (at your option) any later version.
-#
-# This program is distributed in the hope that it will be useful,
-# but WITHOUT ANY WARRANTY; without even the implied warranty of
-# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
-# GNU General Public License for more details.
-#
-# You should have received a copy of the GNU General Public License
-# along with this program.  If not, see <http://www.gnu.org/licenses/>.
-"""
-tests for leap_log_handler
-"""
-try:
-    import unittest2 as unittest
-except ImportError:
-    import unittest
-
-import logging
-
-from leap.bitmask.logs.leap_log_handler import LeapLogHandler
-from leap.bitmask.util.pyside_tests_helper import BasicPySlotCase
-from leap.common.testing.basetest import BaseLeapTest
-
-from mock import Mock
-
-
-class LeapLogHandlerTest(BaseLeapTest, BasicPySlotCase):
-    """
-    LeapLogHandlerTest's tests.
-    """
-    def _callback(self, *args):
-        """
-        Simple callback to track if a signal was emitted.
-        """
-        self.called = True
-        self.emitted_msg = args[0][LeapLogHandler.MESSAGE_KEY]
-
-    def setUp(self):
-        BasicPySlotCase.setUp(self)
-
-        # Create the logger
-        level = logging.DEBUG
-        self.logger = logging.getLogger(name='test')
-        self.logger.setLevel(level)
-
-        # Create the handler
-        self.leap_handler = LeapLogHandler()
-        self.leap_handler.setLevel(level)
-        self.logger.addHandler(self.leap_handler)
-
-    def tearDown(self):
-        BasicPySlotCase.tearDown(self)
-        try:
-            self.leap_handler.new_log.disconnect()
-        except Exception:
-            pass
-
-    def test_history_starts_empty(self):
-        self.assertEqual(self.leap_handler.log_history, [])
-
-    def test_one_log_captured(self):
-        self.logger.debug('test')
-        self.assertEqual(len(self.leap_handler.log_history), 1)
-
-    def test_history_records_order(self):
-        self.logger.debug('test 01')
-        self.logger.debug('test 02')
-        self.logger.debug('test 03')
-
-        logs = []
-        for message in self.leap_handler.log_history:
-            logs.append(message[LeapLogHandler.RECORD_KEY].msg)
-
-        self.assertIn('test 01', logs)
-        self.assertIn('test 02', logs)
-        self.assertIn('test 03', logs)
-
-    def test_history_messages_order(self):
-        self.logger.debug('test 01')
-        self.logger.debug('test 02')
-        self.logger.debug('test 03')
-
-        logs = []
-        for message in self.leap_handler.log_history:
-            logs.append(message[LeapLogHandler.MESSAGE_KEY])
-
-        self.assertIn('test 01', logs[0])
-        self.assertIn('test 02', logs[1])
-        self.assertIn('test 03', logs[2])
-
-    def test_emits_signal(self):
-        log_format = '%(name)s - %(levelname)s - %(message)s'
-        formatter = logging.Formatter(log_format)
-        get_format = Mock(return_value=formatter)
-        self.leap_handler._handler._get_format = get_format
-
-        self.leap_handler.new_log.connect(self._callback)
-        self.logger.debug('test')
-
-        expected_log_msg = "test - DEBUG - test"
-
-        # signal emitted
-        self.assertTrue(self.called)
-
-        # emitted message
-        self.assertEqual(self.emitted_msg, expected_log_msg)
-
-        # Mock called
-        self.assertTrue(get_format.called)
-
-
-if __name__ == "__main__":
-    unittest.main()
diff --git a/src/leap/bitmask/logs/utils.py b/src/leap/bitmask/logs/utils.py
index 8367937a..72efae97 100644
--- a/src/leap/bitmask/logs/utils.py
+++ b/src/leap/bitmask/logs/utils.py
@@ -1,80 +1,57 @@
 import logging
 import sys
 
+from leap.bitmask.config import flags
 from leap.bitmask.logs import LOG_FORMAT
 from leap.bitmask.logs.log_silencer import SelectiveSilencerFilter
-from leap.bitmask.logs.leap_log_handler import LeapLogHandler
+from leap.bitmask.logs.safezmqhandler import SafeZMQHandler
 from leap.bitmask.logs.streamtologger import StreamToLogger
 from leap.bitmask.platform_init import IS_WIN
 
+import logbook
+from logbook.more import ColorizedStderrHandler
 
-def create_logger(debug=False, logfile=None, replace_stdout=True):
-    """
-    Create the logger and attach the handlers.
-
-    :param debug: the level of the messages that we should log
-    :type debug: bool
-    :param logfile: the file name of where we should to save the logs
-    :type logfile: str
-    :return: the new logger with the attached handlers.
-    :rtype: logging.Logger
-    """
-    # TODO: get severity from command line args
-    if debug:
-        level = logging.DEBUG
-    else:
-        level = logging.WARNING
 
-    # Create logger and formatter
-    logger = logging.getLogger(name='leap')
-    logger.setLevel(level)
-    formatter = logging.Formatter(LOG_FORMAT)
+def get_logger(debug=True, logfile=None, replace_stdout=True):
+    level = logbook.WARNING
+    if flags.DEBUG:
+        level = logbook.NOTSET
 
-    # Console handler
-    try:
-        import coloredlogs
-        console = coloredlogs.ColoredStreamHandler(level=level)
-    except ImportError:
-        console = logging.StreamHandler()
-        console.setLevel(level)
-        console.setFormatter(formatter)
-        using_coloredlog = False
-    else:
-        using_coloredlog = True
-
-    if using_coloredlog:
-        replace_stdout = False
+    # This handler consumes logs not handled by the others
+    null_handler = logbook.NullHandler(bubble=False)
+    null_handler.push_application()
 
     silencer = SelectiveSilencerFilter()
-    console.addFilter(silencer)
-    logger.addHandler(console)
-    logger.debug('Console handler plugged!')
 
-    # LEAP custom handler
-    leap_handler = LeapLogHandler()
-    leap_handler.setLevel(level)
-    leap_handler.addFilter(silencer)
-    logger.addHandler(leap_handler)
-    logger.debug('Leap handler plugged!')
+    zmq_handler = SafeZMQHandler('tcp://127.0.0.1:5000', multi=True,
+                                 level=level, filter=silencer.filter)
+    zmq_handler.push_application()
+
+    file_handler = logbook.FileHandler('bitmask.log', format_string=LOG_FORMAT,
+                                       bubble=True, filter=silencer.filter)
+    file_handler.push_application()
 
-    # File handler
-    if logfile is not None:
-        logger.debug('Setting logfile to %s ', logfile)
-        fileh = logging.FileHandler(logfile)
-        fileh.setLevel(logging.DEBUG)
-        fileh.setFormatter(formatter)
-        fileh.addFilter(silencer)
-        logger.addHandler(fileh)
-        logger.debug('File handler plugged!')
+    # don't use simple stream, go for colored log handler instead
+    # stream_handler = logbook.StreamHandler(sys.stdout,
+    #                                        format_string=LOG_FORMAT,
+    #                                        bubble=True)
+    # stream_handler.push_application()
+    stream_handler = ColorizedStderrHandler(
+        level=level, format_string=LOG_FORMAT, bubble=True,
+        filter=silencer.filter)
+    stream_handler.push_application()
 
-    if replace_stdout:
-        replace_stdout_stderr_with_logging(logger)
+    logger = logbook.Logger('leap')
 
     return logger
 
 
 def replace_stdout_stderr_with_logging(logger):
     """
+    NOTE:
+        we are not using this right now (see commented lines on app.py),
+        this needs to be reviewed since the log handler has changed.
+
     Replace:
         - the standard output
         - the standard error