Reorder logging helpers and handlers.

7 files changed, 630 insertions, 0 deletions

diff --git a/src/leap/bitmask/logs/__init__.py b/src/leap/bitmask/logs/__init__.py
new file mode 100644
index 00000000..0516b304
--- /dev/null
+++ b/src/leap/bitmask/logs/__init__.py
@@ -0,0 +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')
diff --git a/src/leap/bitmask/logs/leap_log_handler.py b/src/leap/bitmask/logs/leap_log_handler.py
new file mode 100644
index 00000000..24141638
--- /dev/null
+++ b/src/leap/bitmask/logs/leap_log_handler.py
@@ -0,0 +1,137 @@
+# -*- 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
new file mode 100644
index 00000000..56b290e4
--- /dev/null
+++ b/src/leap/bitmask/logs/log_silencer.py
@@ -0,0 +1,93 @@
+# -*- coding: utf-8 -*-
+# log_silencer.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/>.
+"""
+Filter for leap logs.
+"""
+import logging
+import os
+import re
+
+from leap.bitmask.util import get_path_prefix
+
+
+class SelectiveSilencerFilter(logging.Filter):
+    """
+    Configurable filter for root leap logger.
+
+    If you want to ignore components from the logging, just add them,
+    one by line, to ~/.config/leap/leap.dev.conf
+    """
+    # TODO we can augment this by properly parsing the log-silencer file
+    # and having different sections: ignore, levels, ...
+
+    # TODO use ConfigParser to unify sections [log-ignore] [log-debug] etc
+
+    CONFIG_NAME = "leap.dev.conf"
+
+    # Components to be completely silenced in the main bitmask logs.
+    # You probably should think twice before adding a component to
+    # the tuple below. Only very well tested components should go here, and
+    # only in those cases in which we gain more from silencing them than from
+    # having their logs into the main log file that the user will likely send
+    # to us.
+    SILENCER_RULES = (
+        'leap.common.events',
+        'leap.common.decorators',
+    )
+
+    def __init__(self):
+        """
+        Tries to load silencer rules from the default path,
+        or load from the SILENCER_RULES tuple if not found.
+        """
+        self.rules = None
+        if os.path.isfile(self._rules_path):
+            self.rules = self._load_rules()
+        if not self.rules:
+            self.rules = self.SILENCER_RULES
+
+    @property
+    def _rules_path(self):
+        """
+        The configuration file for custom ignore rules.
+        """
+        return os.path.join(get_path_prefix(), "leap", self.CONFIG_NAME)
+
+    def _load_rules(self):
+        """
+        Loads a list of paths to be ignored from the logging.
+        """
+        lines = open(self._rules_path).readlines()
+        return map(lambda line: re.sub('\s', '', line),
+                   lines)
+
+    def filter(self, record):
+        """
+        Implements the filter functionality for this Filter
+
+        :param record: the record to be examined
+        :type record: logging.LogRecord
+        :returns: a bool indicating whether the record should be logged or not.
+        :rtype: bool
+        """
+        if not self.rules:
+            return True
+        logger_path = record.name
+        for path in self.rules:
+            if logger_path.startswith(path):
+                return False
+        return True
diff --git a/src/leap/bitmask/logs/streamtologger.py b/src/leap/bitmask/logs/streamtologger.py
new file mode 100644
index 00000000..25a06718
--- /dev/null
+++ b/src/leap/bitmask/logs/streamtologger.py
@@ -0,0 +1,59 @@
+# -*- coding: utf-8 -*-
+# streamtologger.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/>.
+"""
+Stream object that redirects writes to a logger instance.
+"""
+import logging
+
+
+class StreamToLogger(object):
+    """
+    Fake file-like stream object that redirects writes to a logger instance.
+
+    Credits to:
+    http://www.electricmonk.nl/log/2011/08/14/\
+        redirect-stdout-and-stderr-to-a-logger-in-python/
+    """
+    def __init__(self, logger, log_level=logging.INFO):
+        """
+        Constructor, defines the logger and level to use to log messages.
+
+        :param logger: logger object to log messages.
+        :type logger: logging.Handler
+        :param log_level: the level to use to log messages through the logger.
+        :type log_level: int
+                        look at logging-levels in 'logging' docs.
+        """
+        self._logger = logger
+        self._log_level = log_level
+
+    def write(self, data):
+        """
+        Simulates the 'write' method in a file object.
+        It writes the data receibed in buf to the logger 'self._logger'.
+
+        :param data: data to write to the 'file'
+        :type data: str
+        """
+        for line in data.rstrip().splitlines():
+            self._logger.log(self._log_level, line.rstrip())
+
+    def flush(self):
+        """
+        Dummy method. Needed to replace the twisted.log output.
+        """
+        pass
diff --git a/src/leap/bitmask/logs/tests/test_leap_log_handler.py b/src/leap/bitmask/logs/tests/test_leap_log_handler.py
new file mode 100644
index 00000000..20b09aef
--- /dev/null
+++ b/src/leap/bitmask/logs/tests/test_leap_log_handler.py
@@ -0,0 +1,120 @@
+# -*- 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/tests/test_streamtologger.py b/src/leap/bitmask/logs/tests/test_streamtologger.py
new file mode 100644
index 00000000..9bbadde8
--- /dev/null
+++ b/src/leap/bitmask/logs/tests/test_streamtologger.py
@@ -0,0 +1,126 @@
+# -*- coding: utf-8 -*-
+# test_streamtologger.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 streamtologger
+"""
+
+try:
+    import unittest2 as unittest
+except ImportError:
+    import unittest
+
+import logging
+import sys
+
+from leap.bitmask.logs.streamtologger import StreamToLogger
+from leap.common.testing.basetest import BaseLeapTest
+
+
+class SimpleLogHandler(logging.Handler):
+    """
+    The simplest log handler that allows to check if the log was
+    delivered to the handler correctly.
+    """
+    def __init__(self):
+        logging.Handler.__init__(self)
+        self._last_log = ""
+        self._last_log_level = ""
+
+    def emit(self, record):
+        self._last_log = record.getMessage()
+        self._last_log_level = record.levelno
+
+    def get_last_log(self):
+        """
+        Returns the last logged message by this handler.
+
+        :return: the last logged message.
+        :rtype: str
+        """
+        return self._last_log
+
+    def get_last_log_level(self):
+        """
+        Returns the level of the last logged message by this handler.
+
+        :return: the last logged level.
+        :rtype: str
+        """
+        return self._last_log_level
+
+
+class StreamToLoggerTest(BaseLeapTest):
+    """
+    StreamToLogger's tests.
+
+    NOTE: we may need to find a way to test the use case that an exception
+    is raised. I couldn't catch the output of an exception because the
+    test failed if some exception is raised.
+    """
+    def setUp(self):
+        # Create the logger
+        level = logging.DEBUG
+        self.logger = logging.getLogger(name='test')
+        self.logger.setLevel(level)
+
+        # Simple log handler
+        self.handler = SimpleLogHandler()
+        self.logger.addHandler(self.handler)
+
+        # Preserve original values
+        self._sys_stdout = sys.stdout
+        self._sys_stderr = sys.stderr
+
+        # Create the handler
+        sys.stdout = StreamToLogger(self.logger, logging.DEBUG)
+        sys.stderr = StreamToLogger(self.logger, logging.ERROR)
+
+    def tearDown(self):
+        # Restore original values
+        sys.stdout = self._sys_stdout
+        sys.stderr = self._sys_stderr
+
+    def test_logger_starts_empty(self):
+        self.assertEqual(self.handler.get_last_log(), '')
+
+    def test_standard_output(self):
+        message = 'Test string'
+        print message
+
+        log = self.handler.get_last_log()
+        log_level = self.handler.get_last_log_level()
+
+        self.assertEqual(log, message)
+        self.assertEqual(log_level, logging.DEBUG)
+
+    def test_standard_error(self):
+        message = 'Test string'
+        sys.stderr.write(message)
+
+        log_level = self.handler.get_last_log_level()
+        log = self.handler.get_last_log()
+
+        self.assertEqual(log, message)
+        self.assertEqual(log_level, logging.ERROR)
+
+    def test_twisted_log(self):
+        from twisted.python import log
+        log.startLogging(sys.stdout)
+
+
+if __name__ == "__main__":
+    unittest.main(verbosity=2)
diff --git a/src/leap/bitmask/logs/utils.py b/src/leap/bitmask/logs/utils.py
new file mode 100644
index 00000000..06959c45
--- /dev/null
+++ b/src/leap/bitmask/logs/utils.py
@@ -0,0 +1,92 @@
+import logging
+import sys
+
+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.streamtologger import StreamToLogger
+from leap.bitmask.platform_init import IS_WIN
+
+
+def get_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)
+
+    # 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
+
+    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!')
+
+    # 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!')
+
+    if replace_stdout:
+        replace_stdout_stderr_with_logging(logger)
+
+    return logger
+
+
+def replace_stdout_stderr_with_logging(logger):
+    """
+    Replace:
+        - the standard output
+        - the standard error
+        - the twisted log output
+    with a custom one that writes to the logger.
+    """
+    # Disabling this on windows since it breaks ALL THE THINGS
+    # The issue for this is #4149
+    if not IS_WIN:
+        sys.stdout = StreamToLogger(logger, logging.DEBUG)
+        sys.stderr = StreamToLogger(logger, logging.ERROR)
+
+        # Replace twisted's logger to use our custom output.
+        from twisted.python import log
+        log.startLogging(sys.stdout)