[feat] handle twisted/logging logs with logbook

Forward Twisted logs to logging and use logbook to handle logging logs.
Store the bitmask logs on the config folder.

3 files changed, 61 insertions, 9 deletions

diff --git a/src/leap/bitmask/backend_app.py b/src/leap/bitmask/backend_app.py
index 891575be..011f59fb 100644
--- a/src/leap/bitmask/backend_app.py
+++ b/src/leap/bitmask/backend_app.py
@@ -25,6 +25,7 @@ from leap.common.events import server as event_server
 from leap.bitmask.backend.leapbackend import LeapBackend
 from leap.bitmask.backend.utils import generate_zmq_certificates
 from leap.bitmask.config import flags
+from leap.bitmask.logs.utils import get_logger
 from leap.bitmask.util import dict_to_flags
 
 
@@ -54,11 +55,18 @@ def run_backend(bypass_checks=False, flags_dict=None, frontend_pid=None):
     :param flags_dict: a dict containing the flag values set on app start.
     :type flags_dict: dict
     """
+    # In the backend, we want all the components to log into logbook
+    # that is: logging handlers and twisted logs
+    from logbook.compat import redirect_logging
+    from twisted.python.log import PythonLoggingObserver
+    redirect_logging()
+    observer = PythonLoggingObserver()
+    observer.start()
+
     # NOTE: this needs to be used here, within the call since this function is
     # executed in a different process and it seems that the process/thread
     # identification isn't working 100%
-    from leap.bitmask.logs.utils import get_logger
-    logger = get_logger()
+    logger = get_logger()  # noqa
 
     # The backend is the one who always creates the certificates. Either if it
     # is run separately or in a process in the same app as the frontend.
diff --git a/src/leap/bitmask/logs/safezmqhandler.py b/src/leap/bitmask/logs/safezmqhandler.py
index 7aac6a6a..4f7aca9b 100644
--- a/src/leap/bitmask/logs/safezmqhandler.py
+++ b/src/leap/bitmask/logs/safezmqhandler.py
@@ -39,6 +39,19 @@ class SafeZMQHandler(ZeroMQHandler):
 
     def __init__(self, uri=None, level=NOTSET, filter=None, bubble=False,
                  context=None, multi=False):
+        """
+        Safe zmq handler constructor that calls the ZeroMQHandler constructor
+        and does some extra initializations.
+        """
+        # The current `SafeZMQHandler` uses the `ZeroMQHandler` constructor
+        # which creates a socket each time.
+        # The purpose of the `self._sockets` attribute is to prevent cases in
+        # which we use the same logger in different threads. For instance when
+        # we (in the same file) `deferToThread` a method/function, we are using
+        # the same logger/socket without calling get_logger again.
+        # If we want to reuse the socket, we need to rewrite this constructor
+        # instead of calling the ZeroMQHandler's one.
+        # The best approach may be to inherit directly from `logbook.Handler`.
 
         ZeroMQHandler.__init__(self, uri, level, filter, bubble, context,
                                multi)
diff --git a/src/leap/bitmask/logs/utils.py b/src/leap/bitmask/logs/utils.py
index e0a5fba3..413f6a75 100644
--- a/src/leap/bitmask/logs/utils.py
+++ b/src/leap/bitmask/logs/utils.py
@@ -1,18 +1,47 @@
-import logging
+# -*- coding: utf-8 -*-
+# utils.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/>.
+"""
+Logs utilities
+"""
+
+import os
 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.safezmqhandler import SafeZMQHandler
-from leap.bitmask.logs.streamtologger import StreamToLogger
+# from leap.bitmask.logs.streamtologger import StreamToLogger
 from leap.bitmask.platform_init import IS_WIN
+from leap.bitmask.util import get_path_prefix
 
 import logbook
 from logbook.more import ColorizedStderrHandler
 
 
+BITMASK_LOG_FILE = os.path.join(get_path_prefix(), "leap", 'bitmask.log')
+
+
 def get_logger():
+    """
+    Push to the app stack the needed handlers and return a Logger object.
+
+    :rtype: logbook.Logger
+    """
     level = logbook.WARNING
     if flags.DEBUG:
         level = logbook.NOTSET
@@ -27,8 +56,9 @@ def get_logger():
                                  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 = logbook.FileHandler(BITMASK_LOG_FILE,
+                                       format_string=LOG_FORMAT, bubble=True,
+                                       filter=silencer.filter)
     file_handler.push_application()
 
     # don't use simple stream, go for colored log handler instead
@@ -46,7 +76,7 @@ def get_logger():
     return logger
 
 
-def replace_stdout_stderr_with_logging(logger):
+def replace_stdout_stderr_with_logging(logger=None):
     """
     NOTE:
         we are not using this right now (see commented lines on app.py),
@@ -61,8 +91,9 @@ def replace_stdout_stderr_with_logging(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)
+        # logger = get_logger()
+        # sys.stdout = StreamToLogger(logger, logbook.NOTSET)
+        # sys.stderr = StreamToLogger(logger, logging.ERROR)
 
         # Replace twisted's logger to use our custom output.
         from twisted.python import log