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