From 9a38c4d2a100f2951059fb152c1298a7587b5a2d Mon Sep 17 00:00:00 2001 From: SomberNight Date: Wed, 14 Apr 2021 07:01:23 +0200 Subject: [PATCH] logging: don't lose log messages during early startup Previously, during early-startup (until configure_logging(config) is called in run_electrum), - the stderr log handler lost all log messages below warning level, and - the file log handler lost all log messages regardless of log level We now instead start buffering log messages in memory as soon as electrum.logging is imported. The buffer is dumped into the stderr and file log handlers when they are fully set up, and then the buffer is discarded (and the temporary log handler is removed). Note that messages are not logged until configure_logging() is called. Previously WARNING/ERROR messages would get logged immediately to stderr, but not anymore. This was changed so that the order of the log messages can be kept intact. (if we log WARNINGs immediately, but need to delay INFOs until the config is available, messages would either be out of order or alternatively there would be duplicates) Relatedly, we now follow the recommendation of the python docs re logging for libraries [0]: we try to only configure logging if running via run_electrum (the main script) and not when e.g. a 3rd party script imports electrum. [0]: https://docs.python.org/3/howto/logging.html#configuring-logging-for-a-library --- electrum/gui/stdio.py | 3 - electrum/gui/text.py | 2 - electrum/logging.py | 112 ++++++++++++++++++++++++++++++++----- electrum/tests/__init__.py | 5 ++ run_electrum | 4 +- 5 files changed, 107 insertions(+), 19 deletions(-) diff --git a/electrum/gui/stdio.py b/electrum/gui/stdio.py index 343998dfa..f39de82d5 100644 --- a/electrum/gui/stdio.py +++ b/electrum/gui/stdio.py @@ -10,7 +10,6 @@ from electrum.util import format_satoshis from electrum.bitcoin import is_address, COIN from electrum.transaction import PartialTxOutput from electrum.network import TxBroadcastError, BestEffortRequestFailed -from electrum.logging import console_stderr_handler _ = lambda x:x # i18n @@ -36,8 +35,6 @@ class ElectrumGui: self.done = 0 self.last_balance = "" - console_stderr_handler.setLevel(logging.CRITICAL) - self.str_recipient = "" self.str_description = "" self.str_amount = "" diff --git a/electrum/gui/text.py b/electrum/gui/text.py index e6c3c1e2f..6c6b27957 100644 --- a/electrum/gui/text.py +++ b/electrum/gui/text.py @@ -18,7 +18,6 @@ from electrum.wallet_db import WalletDB from electrum.storage import WalletStorage from electrum.network import NetworkParameters, TxBroadcastError, BestEffortRequestFailed from electrum.interface import ServerAddr -from electrum.logging import console_stderr_handler if TYPE_CHECKING: from electrum.daemon import Daemon @@ -64,7 +63,6 @@ class ElectrumGui: self.set_cursor(0) self.w = curses.newwin(10, 50, 5, 5) - console_stderr_handler.setLevel(logging.CRITICAL) self.tab = 0 self.pos = 0 self.popup_pos = 0 diff --git a/electrum/logging.py b/electrum/logging.py index 1759be368..ea949645f 100644 --- a/electrum/logging.py +++ b/electrum/logging.py @@ -3,6 +3,7 @@ # file LICENCE or http://www.opensource.org/licenses/mit-license.php import logging +import logging.handlers import datetime import sys import pathlib @@ -59,6 +60,56 @@ def _shorten_name_of_logrecord(record: logging.LogRecord) -> logging.LogRecord: return record +class TruncatingMemoryHandler(logging.handlers.MemoryHandler): + """An in-memory log handler that only keeps the first N log messages + and discards the rest. + """ + target: Optional['logging.Handler'] + + def __init__(self): + logging.handlers.MemoryHandler.__init__( + self, + capacity=1, # note: this is the flushing frequency, ~unused by us + flushLevel=logging.DEBUG, + ) + self.max_size = 100 # max num of messages we keep + self.num_messages_seen = 0 + self.__never_dumped = True + + # note: this flush implementation *keeps* the buffer as-is, instead of clearing it + def flush(self): + self.acquire() + try: + if self.target: + for record in self.buffer: + if record.levelno >= self.target.level: + self.target.handle(record) + finally: + self.release() + + def dump_to_target(self, target: 'logging.Handler'): + self.acquire() + try: + self.setTarget(target) + self.flush() + self.setTarget(None) + finally: + self.__never_dumped = False + self.release() + + def emit(self, record): + self.num_messages_seen += 1 + if len(self.buffer) < self.max_size: + super().emit(record) + + def close(self) -> None: + # Check if captured log lines were never to dumped to e.g. stderr, + # and if so, try to do it now. This is useful e.g. in case of sys.exit(). + if self.__never_dumped: + _configure_stderr_logging() + super().close() + + def _delete_old_logs(path, keep=10): files = sorted(list(pathlib.Path(path).glob("electrum_log_*.log")), reverse=True) for f in files[keep:]: @@ -84,14 +135,29 @@ def _configure_file_logging(log_directory: pathlib.Path): file_handler.setFormatter(file_formatter) file_handler.setLevel(logging.DEBUG) root_logger.addHandler(file_handler) + if _inmemory_startup_logs: + _inmemory_startup_logs.dump_to_target(file_handler) -def _configure_verbosity(*, verbosity, verbosity_shortcuts): - if not verbosity and not verbosity_shortcuts: +console_stderr_handler = None +def _configure_stderr_logging(*, verbosity=None, verbosity_shortcuts=None): + # log to stderr; by default only WARNING and higher + global console_stderr_handler + if console_stderr_handler is not None: + _logger.warning("stderr handler already exists") return - console_stderr_handler.setLevel(logging.DEBUG) - _process_verbosity_log_levels(verbosity) - _process_verbosity_filter_shortcuts(verbosity_shortcuts) + console_stderr_handler = logging.StreamHandler(sys.stderr) + console_stderr_handler.setFormatter(console_formatter) + if not verbosity and not verbosity_shortcuts: + console_stderr_handler.setLevel(logging.WARNING) + root_logger.addHandler(console_stderr_handler) + else: + console_stderr_handler.setLevel(logging.DEBUG) + root_logger.addHandler(console_stderr_handler) + _process_verbosity_log_levels(verbosity) + _process_verbosity_filter_shortcuts(verbosity_shortcuts, handler=console_stderr_handler) + if _inmemory_startup_logs: + _inmemory_startup_logs.dump_to_target(console_stderr_handler) def _process_verbosity_log_levels(verbosity): @@ -115,7 +181,7 @@ def _process_verbosity_log_levels(verbosity): raise Exception(f"invalid log filter: {filt}") -def _process_verbosity_filter_shortcuts(verbosity_shortcuts): +def _process_verbosity_filter_shortcuts(verbosity_shortcuts, *, handler: 'logging.Handler'): if not isinstance(verbosity_shortcuts, str): return if len(verbosity_shortcuts) < 1: @@ -130,7 +196,7 @@ def _process_verbosity_filter_shortcuts(verbosity_shortcuts): # apply filter directly (and only!) on stderr handler # note that applying on one of the root loggers directly would not work, # see https://docs.python.org/3/howto/logging.html#logging-flow - console_stderr_handler.addFilter(filt) + handler.addFilter(filt) class ShortcutInjectingFilter(logging.Filter): @@ -178,11 +244,20 @@ class ShortcutFilteringFilter(logging.Filter): root_logger = logging.getLogger() root_logger.setLevel(logging.WARNING) -# log to stderr; by default only WARNING and higher -console_stderr_handler = logging.StreamHandler(sys.stderr) -console_stderr_handler.setFormatter(console_formatter) -console_stderr_handler.setLevel(logging.WARNING) -root_logger.addHandler(console_stderr_handler) +# Start collecting log messages now, into an in-memory buffer. This buffer is only +# used until the proper log handlers are fully configured, including their verbosity, +# at which point we will dump its contents into those, and remove this log handler. +# Note: this is set up at import-time instead of e.g. as part of a function that is +# called from run_electrum (the main script). This is to have this run as early +# as possible. +# Note: some users might use Electrum as a python library and not use run_electrum, +# in which case these logs might never get redirected or cleaned up. +# Also, the python docs recommend libraries not to set a handler, to +# avoid interfering with the user's logging. +_inmemory_startup_logs = None +if getattr(sys, "_ELECTRUM_RUNNING_VIA_RUNELECTRUM", False): + _inmemory_startup_logs = TruncatingMemoryHandler() + root_logger.addHandler(_inmemory_startup_logs) # creates a logger specifically for electrum library electrum_logger = logging.getLogger("electrum") @@ -234,7 +309,7 @@ class Logger: def configure_logging(config): verbosity = config.get('verbosity') verbosity_shortcuts = config.get('verbosity_shortcuts') - _configure_verbosity(verbosity=verbosity, verbosity_shortcuts=verbosity_shortcuts) + _configure_stderr_logging(verbosity=verbosity, verbosity_shortcuts=verbosity_shortcuts) log_to_file = config.get('log_to_file', False) is_android = 'ANDROID_DATA' in os.environ @@ -246,6 +321,17 @@ def configure_logging(config): log_directory = pathlib.Path(config.path) / "logs" _configure_file_logging(log_directory) + # clean up and delete in-memory logs + global _inmemory_startup_logs + if _inmemory_startup_logs: + num_discarded = _inmemory_startup_logs.num_messages_seen - _inmemory_startup_logs.max_size + if num_discarded > 0: + _logger.warning(f"Too many log messages! Some have been discarded. " + f"(discarded {num_discarded} messages)") + _inmemory_startup_logs.close() + root_logger.removeHandler(_inmemory_startup_logs) + _inmemory_startup_logs = None + # if using kivy, avoid kivy's own logs to get printed twice logging.getLogger('kivy').propagate = False diff --git a/electrum/tests/__init__.py b/electrum/tests/__init__.py index b5788bbaf..dbfc9ada0 100644 --- a/electrum/tests/__init__.py +++ b/electrum/tests/__init__.py @@ -3,6 +3,8 @@ import threading import tempfile import shutil +import electrum +import electrum.logging from electrum import constants @@ -13,6 +15,9 @@ from electrum import constants FAST_TESTS = False +electrum.logging._configure_stderr_logging() + + # some unit tests are modifying globals... class SequentialTestCase(unittest.TestCase): diff --git a/run_electrum b/run_electrum index beef12d2e..c44650a3a 100755 --- a/run_electrum +++ b/run_electrum @@ -78,7 +78,9 @@ if not is_android: check_imports() -from electrum.logging import get_logger, configure_logging +sys._ELECTRUM_RUNNING_VIA_RUNELECTRUM = True # used by logging.py + +from electrum.logging import get_logger, configure_logging # import logging submodule first from electrum import util from electrum import constants from electrum import SimpleConfig