From 111043f8b42f6864125834d21ca7bef08adf69f1 Mon Sep 17 00:00:00 2001 From: SomberNight Date: Wed, 24 Aug 2022 11:42:55 +0000 Subject: [PATCH] logging: add a relative timestamp to stderr console logs In the past we decided not to put a timestamp into the stderr logs to have shorter log lines (to save column width in a terminal). However over time I at least have found that it would be valuable to have timestamps also in the stderr - e.g. when users provide logs. Often I am only interested in the time taken between logged events, so as a compromise to still save some length, I propose adding relative timestamps (relative to process startup time). Compare these log lines from the file logger: ``` 20220816T120601.882003Z | INFO | gui.qt.ElectrumGui | starting Qt main loop 20220816T120601.905619Z | INFO | gui.qt.history_list.HistoryModel | refreshing... reason: update_tabs 20220816T120601.911908Z | DEBUG | util.profiler | Abstract_Wallet.get_full_history 0.0059 sec 20220816T120602.095670Z | INFO | interface.[testnet.hsmiths.com:53012] | connection established. version: ['ElectrumX 1.16.0', '1.4'] ``` With these from the existing stderr logger: ``` I/w | wallet.Standard_Wallet.[test_segwit_3] | set_up_to_date: True I/i | interface.[testnet.aranguren.org:51002] | set blockchain with height 2343721 D | util.profiler | ElectrumWindow.load_wallet 0.0778 sec I | gui.qt.ElectrumGui | starting Qt main loop ``` With these re what I propose for the stderr logger: ``` 3.20 | D | util.profiler | Abstract_Wallet.get_full_history 0.0029 sec 5.70 | I | i/interface.[testnet1.bauerj.eu:50002] | disconnecting due to: ConnectError(ConnectionRefusedError(22, 'The remote computer refused the network connection', None, 1225, None)) 38.63 | I | w/wallet.Standard_Wallet.[9dk] | starting taskgroup. 38.84 | D | util.profiler | WalletDB._write 0.0059 sec 62.96 | I | i/interface.[blockstream.info:993] | set blockchain with height 2343722 150.65 | I | exchange_rate.CoinGecko | getting fx quotes for EUR ``` --- electrum/logging.py | 16 ++++++++++++---- 1 file changed, 12 insertions(+), 4 deletions(-) diff --git a/electrum/logging.py b/electrum/logging.py index b7cbe23e5..5e362f203 100644 --- a/electrum/logging.py +++ b/electrum/logging.py @@ -12,11 +12,15 @@ import platform from typing import Optional, TYPE_CHECKING import copy import subprocess +import time if TYPE_CHECKING: from .simple_config import SimpleConfig +_time_zero = time.time() + + class LogFormatterForFiles(logging.Formatter): def formatTime(self, record, datefmt=None): @@ -36,17 +40,21 @@ file_formatter = LogFormatterForFiles(fmt="%(asctime)22s | %(levelname)8s | %(na class LogFormatterForConsole(logging.Formatter): + def formatTime(self, record, datefmt=None): + t = record.created - _time_zero + return f"{t:6.2f}" + def format(self, record): + record = copy.copy(record) # avoid mutating arg record = _shorten_name_of_logrecord(record) + if shortcut := getattr(record, 'custom_shortcut', None): + record.name = f"{shortcut}/{record.name}" text = super().format(record) - shortcut = getattr(record, 'custom_shortcut', None) - if shortcut: - text = text[:1] + f"/{shortcut}" + text[1:] return text # try to make console log lines short... no timestamp, short levelname, no "electrum." -console_formatter = LogFormatterForConsole(fmt="%(levelname).1s | %(name)s | %(message)s") +console_formatter = LogFormatterForConsole(fmt="%(asctime)s | %(levelname).1s | %(name)s | %(message)s") def _shorten_name_of_logrecord(record: logging.LogRecord) -> logging.LogRecord: