Merge pull request #7211 from SomberNight/202104_keep_early_logs

logging: don't lose log messages during early startup

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 = ""

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

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
 

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):
 

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