From 584a6d93ad1fe1ba46929108f002a16a8b70e95d Mon Sep 17 00:00:00 2001 From: Ivan Alejandro Date: Fri, 5 Jun 2015 13:36:51 -0300 Subject: [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 --- src/leap/bitmask/logs/utils.py | 87 ++++++++++++++++-------------------------- 1 file changed, 32 insertions(+), 55 deletions(-) (limited to 'src/leap/bitmask/logs/utils.py') 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 -- cgit v1.2.3 From 32658ae3108bc67a102cf6e0153d468b3a8ae1b0 Mon Sep 17 00:00:00 2001 From: Ivan Alejandro Date: Fri, 12 Jun 2015 14:34:18 -0300 Subject: [feat] replace old log handler with new one Replace logging.getLogger with custom get_logger. Remove some unneeded dependencies and reorder other. --- src/leap/bitmask/logs/utils.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) (limited to 'src/leap/bitmask/logs/utils.py') diff --git a/src/leap/bitmask/logs/utils.py b/src/leap/bitmask/logs/utils.py index 72efae97..e0a5fba3 100644 --- a/src/leap/bitmask/logs/utils.py +++ b/src/leap/bitmask/logs/utils.py @@ -12,7 +12,7 @@ import logbook from logbook.more import ColorizedStderrHandler -def get_logger(debug=True, logfile=None, replace_stdout=True): +def get_logger(): level = logbook.WARNING if flags.DEBUG: level = logbook.NOTSET -- cgit v1.2.3 From 239a0ec845d53b7a0a1af5c27b5eea956ab6459a Mon Sep 17 00:00:00 2001 From: Ivan Alejandro Date: Fri, 19 Jun 2015 14:00:28 -0300 Subject: [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. --- src/leap/bitmask/logs/utils.py | 45 +++++++++++++++++++++++++++++++++++------- 1 file changed, 38 insertions(+), 7 deletions(-) (limited to 'src/leap/bitmask/logs/utils.py') 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 . +""" +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 -- cgit v1.2.3 From 8793f3ef6862ddd5a01008b2e12d1f8d910fd261 Mon Sep 17 00:00:00 2001 From: Ivan Alejandro Date: Fri, 19 Jun 2015 17:50:10 -0300 Subject: [feat] add log rotation feature Rotate bitmask.log file on each start. --- src/leap/bitmask/logs/utils.py | 12 ++++++++---- 1 file changed, 8 insertions(+), 4 deletions(-) (limited to 'src/leap/bitmask/logs/utils.py') diff --git a/src/leap/bitmask/logs/utils.py b/src/leap/bitmask/logs/utils.py index 413f6a75..d3aa322b 100644 --- a/src/leap/bitmask/logs/utils.py +++ b/src/leap/bitmask/logs/utils.py @@ -36,7 +36,7 @@ from logbook.more import ColorizedStderrHandler BITMASK_LOG_FILE = os.path.join(get_path_prefix(), "leap", 'bitmask.log') -def get_logger(): +def get_logger(perform_rollover=False): """ Push to the app stack the needed handlers and return a Logger object. @@ -56,9 +56,13 @@ def get_logger(): level=level, filter=silencer.filter) zmq_handler.push_application() - file_handler = logbook.FileHandler(BITMASK_LOG_FILE, - format_string=LOG_FORMAT, bubble=True, - filter=silencer.filter) + file_handler = logbook.RotatingFileHandler( + BITMASK_LOG_FILE, format_string=LOG_FORMAT, bubble=True, + filter=silencer.filter, max_size=sys.maxint) + + if perform_rollover: + file_handler.perform_rollover() + file_handler.push_application() # don't use simple stream, go for colored log handler instead -- cgit v1.2.3 From e7bda574b308c08dc5a61941b850442c43a17bd4 Mon Sep 17 00:00:00 2001 From: Ivan Alejandro Date: Mon, 22 Jun 2015 16:58:19 -0300 Subject: [bug] make sure log path exists The logger is the first thing to be created and on a first run the config path won't exist. This way we make sure the path always exists. --- src/leap/bitmask/logs/utils.py | 7 ++++++- 1 file changed, 6 insertions(+), 1 deletion(-) (limited to 'src/leap/bitmask/logs/utils.py') diff --git a/src/leap/bitmask/logs/utils.py b/src/leap/bitmask/logs/utils.py index d3aa322b..87d33876 100644 --- a/src/leap/bitmask/logs/utils.py +++ b/src/leap/bitmask/logs/utils.py @@ -28,12 +28,17 @@ from leap.bitmask.logs.safezmqhandler import SafeZMQHandler # from leap.bitmask.logs.streamtologger import StreamToLogger from leap.bitmask.platform_init import IS_WIN from leap.bitmask.util import get_path_prefix +from leap.common.files import mkdir_p import logbook from logbook.more import ColorizedStderrHandler -BITMASK_LOG_FILE = os.path.join(get_path_prefix(), "leap", 'bitmask.log') +# NOTE: make sure that the folder exists, the logger is created before saving +# settings on the first run. +_base = os.path.join(get_path_prefix(), "leap") +mkdir_p(_base) +BITMASK_LOG_FILE = os.path.join(_base, 'bitmask.log') def get_logger(perform_rollover=False): -- cgit v1.2.3 From 2612f7af2aa627ba4c4d680d15f54ede6402b4eb Mon Sep 17 00:00:00 2001 From: Ivan Alejandro Date: Mon, 6 Jul 2015 19:01:08 -0300 Subject: [bug] run zmq log subscriber in background Prevent locks caused by the zmq log handler reaching the zmq's HWM (High water mark / buffer limit) and causing some components to block until the buffer is empty (running the zmq handler for instance). We run the zmq handler in the background all the time to prevent this. - Resolves: #7222 --- src/leap/bitmask/logs/utils.py | 108 +++++++++++++++++++++++++++++++++++++++++ 1 file changed, 108 insertions(+) (limited to 'src/leap/bitmask/logs/utils.py') diff --git a/src/leap/bitmask/logs/utils.py b/src/leap/bitmask/logs/utils.py index 87d33876..f0e820b2 100644 --- a/src/leap/bitmask/logs/utils.py +++ b/src/leap/bitmask/logs/utils.py @@ -30,8 +30,11 @@ from leap.bitmask.platform_init import IS_WIN from leap.bitmask.util import get_path_prefix from leap.common.files import mkdir_p +from PySide import QtCore + import logbook from logbook.more import ColorizedStderrHandler +from logbook.queues import ZeroMQSubscriber # NOTE: make sure that the folder exists, the logger is created before saving @@ -107,3 +110,108 @@ def replace_stdout_stderr_with_logging(logger=None): # Replace twisted's logger to use our custom output. from twisted.python import log log.startLogging(sys.stdout) + + +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() + self.logs = [] + + 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. + self.logs.append(record) + self.logs = sorted(self.logs, 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 _LogController(object): + def __init__(self): + self._qt_handler = QtLogHandler(format_string=LOG_FORMAT) + self.new_log = self._qt_handler.qt.new_log + + def start_logbook_subscriber(self): + """ + Run in the background the log receiver. + """ + subscriber = ZeroMQSubscriber('tcp://127.0.0.1:5000', multi=True) + self._logbook_controller = subscriber.dispatch_in_background( + self._qt_handler) + + def stop_logbook_subscriber(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() + + def get_logs(self): + return self._qt_handler.logs + +# use a global variable to store received logs through different opened +# instances of the log window as well as to containing the logbook background +# handle. +LOG_CONTROLLER = _LogController() -- cgit v1.2.3 From 0d9c53c4ec182c6bf3452506351258b61bb1f739 Mon Sep 17 00:00:00 2001 From: Ivan Alejandro Date: Wed, 8 Jul 2015 16:15:09 -0300 Subject: [bug] prevent logbook subscriber to fail Fix: If the logbook controller is not started the stop call will fail. Trying to start it twice fails. --- src/leap/bitmask/logs/utils.py | 14 +++++++++----- 1 file changed, 9 insertions(+), 5 deletions(-) (limited to 'src/leap/bitmask/logs/utils.py') diff --git a/src/leap/bitmask/logs/utils.py b/src/leap/bitmask/logs/utils.py index f0e820b2..683fb542 100644 --- a/src/leap/bitmask/logs/utils.py +++ b/src/leap/bitmask/logs/utils.py @@ -188,15 +188,17 @@ class QtLogHandler(logbook.Handler, logbook.StringFormatterHandlerMixin): class _LogController(object): def __init__(self): self._qt_handler = QtLogHandler(format_string=LOG_FORMAT) + self._logbook_controller = None self.new_log = self._qt_handler.qt.new_log def start_logbook_subscriber(self): """ Run in the background the log receiver. """ - subscriber = ZeroMQSubscriber('tcp://127.0.0.1:5000', multi=True) - self._logbook_controller = subscriber.dispatch_in_background( - self._qt_handler) + if self._logbook_controller is None: + subscriber = ZeroMQSubscriber('tcp://127.0.0.1:5000', multi=True) + self._logbook_controller = subscriber.dispatch_in_background( + self._qt_handler) def stop_logbook_subscriber(self): """ @@ -205,8 +207,10 @@ class _LogController(object): 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() + if self._logbook_controller is not None: + self._logbook_controller.stop() + self._logbook_controller.subscriber.close() + self._logbook_controller = None def get_logs(self): return self._qt_handler.logs -- cgit v1.2.3