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

@@ -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):
+console_stderr_handler = None
-    if not verbosity and not verbosity_shortcuts:
+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)
+    console_stderr_handler = logging.StreamHandler(sys.stderr)
-    _process_verbosity_log_levels(verbosity)
+    console_stderr_handler.setFormatter(console_formatter)
-    _process_verbosity_filter_shortcuts(verbosity_shortcuts)
+    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
+# Start collecting log messages now, into an in-memory buffer. This buffer is only
-console_stderr_handler = logging.StreamHandler(sys.stderr)
+# used until the proper log handlers are fully configured, including their verbosity,
-console_stderr_handler.setFormatter(console_formatter)
+# at which point we will dump its contents into those, and remove this log handler.
-console_stderr_handler.setLevel(logging.WARNING)
+# Note: this is set up at import-time instead of e.g. as part of a function that is
-root_logger.addHandler(console_stderr_handler)
+#       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