365 lines
13 KiB
Python
365 lines
13 KiB
Python
# Copyright (C) 2019 The Electrum developers
|
|
# Distributed under the MIT software license, see the accompanying
|
|
# file LICENCE or http://www.opensource.org/licenses/mit-license.php
|
|
|
|
import logging
|
|
import logging.handlers
|
|
import datetime
|
|
import sys
|
|
import pathlib
|
|
import os
|
|
import platform
|
|
from typing import Optional, TYPE_CHECKING, Set
|
|
import copy
|
|
import subprocess
|
|
import hashlib
|
|
|
|
if TYPE_CHECKING:
|
|
from .simple_config import SimpleConfig
|
|
|
|
|
|
class LogFormatterForFiles(logging.Formatter):
|
|
|
|
def formatTime(self, record, datefmt=None):
|
|
# timestamps follow ISO 8601 UTC
|
|
date = datetime.datetime.fromtimestamp(record.created).astimezone(datetime.timezone.utc)
|
|
if not datefmt:
|
|
datefmt = "%Y%m%dT%H%M%S.%fZ"
|
|
return date.strftime(datefmt)
|
|
|
|
def format(self, record):
|
|
record = _shorten_name_of_logrecord(record)
|
|
return super().format(record)
|
|
|
|
|
|
file_formatter = LogFormatterForFiles(fmt="%(asctime)22s | %(levelname)8s | %(name)s | %(message)s")
|
|
|
|
|
|
class LogFormatterForConsole(logging.Formatter):
|
|
|
|
def formatTime(self, record, datefmt=None):
|
|
t = record.relativeCreated / 1000
|
|
return f"{t:6.2f}"
|
|
|
|
def format(self, record):
|
|
record = copy.copy(record) # avoid mutating arg
|
|
record = _shorten_name_of_logrecord(record)
|
|
text = super().format(record)
|
|
return text
|
|
|
|
|
|
# try to make console log lines short... no timestamp, short levelname, no "electrum."
|
|
console_formatter = LogFormatterForConsole(fmt="%(asctime)s | %(levelname).1s | %(name)s | %(message)s")
|
|
|
|
|
|
def _shorten_name_of_logrecord(record: logging.LogRecord) -> logging.LogRecord:
|
|
record = copy.copy(record) # avoid mutating arg
|
|
# strip the main module name from the logger name
|
|
if record.name.startswith("electrum."):
|
|
record.name = record.name[9:]
|
|
# manual map to shorten common module names
|
|
record.name = record.name.replace("interface.Interface", "interface", 1)
|
|
record.name = record.name.replace("network.Network", "network", 1)
|
|
record.name = record.name.replace("synchronizer.Synchronizer", "synchronizer", 1)
|
|
record.name = record.name.replace("verifier.SPV", "verifier", 1)
|
|
record.name = record.name.replace("gui.qt.main_window.ElectrumWindow", "gui.qt.main_window", 1)
|
|
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, *, num_files_keep: int, max_total_size: int):
|
|
"""Delete old logfiles, only keeping the latest few."""
|
|
def sortkey_oldest_first(p: pathlib.PurePath):
|
|
fname = p.name
|
|
basename, ext, counter = str(fname).partition(".log")
|
|
# - each time electrum is launched, there will be a new basename, ordered by date
|
|
# - for any given basename, there might be multiple log files, differing by counter
|
|
# - empty counter is newest, then .1 is older, .2 is even older, etc
|
|
try:
|
|
counter = int(counter[1:]) if counter else 0 # convert ".2" -> 2
|
|
except ValueError:
|
|
_logger.warning(f"failed to parse log file name: {fname}")
|
|
counter = 0
|
|
return basename, -counter
|
|
files = sorted(
|
|
list(pathlib.Path(path).glob("electrum_log_*.log*")),
|
|
key=sortkey_oldest_first,
|
|
)
|
|
total_size = sum(os.stat(f).st_size for f in files) # in bytes
|
|
num_files_remaining = len(files)
|
|
for f in files:
|
|
fsize = os.stat(f).st_size
|
|
if total_size < max_total_size and num_files_remaining <= num_files_keep:
|
|
break
|
|
total_size -= fsize
|
|
num_files_remaining -= 1
|
|
try:
|
|
os.remove(f)
|
|
except OSError as e:
|
|
_logger.warning(f"cannot delete old logfile: {e}")
|
|
|
|
|
|
_logfile_path = None
|
|
def _configure_file_logging(
|
|
log_directory: pathlib.Path,
|
|
*,
|
|
num_files_keep: int,
|
|
max_total_size: int,
|
|
):
|
|
from .util import os_chmod
|
|
|
|
global _logfile_path
|
|
assert _logfile_path is None, 'file logging already initialized'
|
|
log_directory.mkdir(exist_ok=True, mode=0o700)
|
|
|
|
_delete_old_logs(log_directory, num_files_keep=num_files_keep, max_total_size=max_total_size)
|
|
|
|
timestamp = datetime.datetime.now(datetime.timezone.utc).strftime("%Y%m%dT%H%M%SZ")
|
|
PID = os.getpid()
|
|
_logfile_path = log_directory / f"electrum_log_{timestamp}_{PID}.log"
|
|
# we create the file with restrictive perms, instead of letting FileHandler create it
|
|
with open(_logfile_path, "w+") as f:
|
|
os_chmod(_logfile_path, 0o600)
|
|
|
|
logfile_backupcount = 4
|
|
file_handler = logging.handlers.RotatingFileHandler(
|
|
_logfile_path,
|
|
maxBytes=max_total_size // (logfile_backupcount+1),
|
|
backupCount=logfile_backupcount,
|
|
encoding='utf-8')
|
|
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)
|
|
|
|
|
|
console_stderr_handler = None
|
|
def _configure_stderr_logging(*, verbosity=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 = logging.StreamHandler(sys.stderr)
|
|
console_stderr_handler.setFormatter(console_formatter)
|
|
if not verbosity:
|
|
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)
|
|
if _inmemory_startup_logs:
|
|
_inmemory_startup_logs.dump_to_target(console_stderr_handler)
|
|
|
|
|
|
def _process_verbosity_log_levels(verbosity):
|
|
if verbosity == '*' or not isinstance(verbosity, str):
|
|
return
|
|
# example verbosity:
|
|
# debug,network=error,interface=error // effectively blacklists network and interface
|
|
# warning,network=debug,interface=debug // effectively whitelists network and interface
|
|
filters = verbosity.split(',')
|
|
for filt in filters:
|
|
if not filt: continue
|
|
items = filt.split('=')
|
|
if len(items) == 1:
|
|
level = items[0]
|
|
electrum_logger.setLevel(level.upper())
|
|
elif len(items) == 2:
|
|
logger_name, level = items
|
|
logger = get_logger(logger_name)
|
|
logger.setLevel(level.upper())
|
|
else:
|
|
raise Exception(f"invalid log filter: {filt}")
|
|
|
|
|
|
class _CustomLogger(logging.getLoggerClass()):
|
|
def __init__(self, name, *args, **kwargs):
|
|
super().__init__(name, *args, **kwargs)
|
|
self.msg_hashes_seen = set() # type: Set[bytes]
|
|
# ^ note: size grows without bounds, but only for log lines using "only_once".
|
|
|
|
def _log(self, level, msg: str, *args, only_once: bool = False, **kwargs) -> None:
|
|
"""Overridden to add 'only_once' arg to logger.debug()/logger.info()/logger.warning()/etc."""
|
|
if only_once: # if set, this logger will only log this msg a single time during its lifecycle
|
|
msg_hash = hashlib.sha256(msg.encode("utf-8")).digest()
|
|
if msg_hash in self.msg_hashes_seen:
|
|
return
|
|
self.msg_hashes_seen.add(msg_hash)
|
|
super()._log(level, msg, *args, **kwargs)
|
|
|
|
logging.setLoggerClass(_CustomLogger)
|
|
|
|
|
|
# enable logs universally (including for other libraries)
|
|
root_logger = logging.getLogger()
|
|
root_logger.setLevel(logging.WARNING)
|
|
|
|
# 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")
|
|
electrum_logger.setLevel(logging.DEBUG)
|
|
|
|
|
|
# --- External API
|
|
|
|
def get_logger(name: str) -> _CustomLogger:
|
|
prefix = "electrum."
|
|
if name.startswith(prefix):
|
|
name = name[len(prefix):]
|
|
return electrum_logger.getChild(name)
|
|
|
|
|
|
_logger = get_logger(__name__)
|
|
_logger.setLevel(logging.INFO)
|
|
|
|
|
|
class Logger:
|
|
|
|
def __init__(self):
|
|
self.logger = self.__get_logger_for_obj()
|
|
|
|
def __get_logger_for_obj(self) -> logging.Logger:
|
|
cls = self.__class__
|
|
if cls.__module__:
|
|
name = f"{cls.__module__}.{cls.__name__}"
|
|
else:
|
|
name = cls.__name__
|
|
try:
|
|
diag_name = self.diagnostic_name()
|
|
except Exception as e:
|
|
raise Exception("diagnostic name not yet available?") from e
|
|
if diag_name:
|
|
name += f".[{diag_name}]"
|
|
logger = get_logger(name)
|
|
return logger
|
|
|
|
def diagnostic_name(self):
|
|
return ''
|
|
|
|
|
|
def configure_logging(config: 'SimpleConfig', *, log_to_file: Optional[bool] = None) -> None:
|
|
from .util import is_android_debug_apk
|
|
|
|
verbosity = config.get('verbosity')
|
|
if not verbosity and config.GUI_ENABLE_DEBUG_LOGS:
|
|
verbosity = '*'
|
|
_configure_stderr_logging(verbosity=verbosity)
|
|
|
|
if log_to_file is None:
|
|
log_to_file = config.WRITE_LOGS_TO_DISK
|
|
log_to_file |= is_android_debug_apk()
|
|
if log_to_file:
|
|
log_directory = pathlib.Path(config.path) / "logs"
|
|
num_files_keep = config.LOGS_NUM_FILES_KEEP
|
|
max_total_size = config.LOGS_MAX_TOTAL_SIZE_BYTES
|
|
_configure_file_logging(log_directory, num_files_keep=num_files_keep, max_total_size=max_total_size)
|
|
|
|
# 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
|
|
|
|
from . import ELECTRUM_VERSION
|
|
from .constants import GIT_REPO_URL
|
|
_logger.info(f"Electrum version: {ELECTRUM_VERSION} - https://electrum.org - {GIT_REPO_URL}")
|
|
_logger.info(f"Python version: {sys.version}. On platform: {describe_os_version()}")
|
|
_logger.info(f"Logging to file: {str(_logfile_path)}")
|
|
_logger.info(f"Log filters: verbosity {repr(verbosity)}")
|
|
|
|
|
|
def get_logfile_path() -> Optional[pathlib.Path]:
|
|
return _logfile_path
|
|
|
|
|
|
def describe_os_version() -> str:
|
|
if 'ANDROID_DATA' in os.environ:
|
|
import jnius
|
|
bv = jnius.autoclass('android.os.Build$VERSION')
|
|
b = jnius.autoclass('android.os.Build')
|
|
return "Android {} on {} {} ({})".format(bv.RELEASE, b.BRAND, b.DEVICE, b.DISPLAY)
|
|
else:
|
|
return platform.platform()
|
|
|
|
|
|
def get_git_version() -> Optional[str]:
|
|
dir = os.path.dirname(os.path.realpath(__file__))
|
|
try:
|
|
version = subprocess.check_output(
|
|
['git', 'describe', '--always', '--dirty'], cwd=dir)
|
|
version = str(version, "utf8").strip()
|
|
except Exception:
|
|
version = None
|
|
return version
|