Browse Source

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
```
master
SomberNight 3 years ago
parent
commit
111043f8b4
No known key found for this signature in database
GPG Key ID: B33B5F232C6271E9
  1. 16
      electrum/logging.py

16
electrum/logging.py

@ -12,11 +12,15 @@ import platform
from typing import Optional, TYPE_CHECKING from typing import Optional, TYPE_CHECKING
import copy import copy
import subprocess import subprocess
import time
if TYPE_CHECKING: if TYPE_CHECKING:
from .simple_config import SimpleConfig from .simple_config import SimpleConfig
_time_zero = time.time()
class LogFormatterForFiles(logging.Formatter): class LogFormatterForFiles(logging.Formatter):
def formatTime(self, record, datefmt=None): def formatTime(self, record, datefmt=None):
@ -36,17 +40,21 @@ file_formatter = LogFormatterForFiles(fmt="%(asctime)22s | %(levelname)8s | %(na
class LogFormatterForConsole(logging.Formatter): class LogFormatterForConsole(logging.Formatter):
def formatTime(self, record, datefmt=None):
t = record.created - _time_zero
return f"{t:6.2f}"
def format(self, record): def format(self, record):
record = copy.copy(record) # avoid mutating arg
record = _shorten_name_of_logrecord(record) record = _shorten_name_of_logrecord(record)
if shortcut := getattr(record, 'custom_shortcut', None):
record.name = f"{shortcut}/{record.name}"
text = super().format(record) text = super().format(record)
shortcut = getattr(record, 'custom_shortcut', None)
if shortcut:
text = text[:1] + f"/{shortcut}" + text[1:]
return text return text
# try to make console log lines short... no timestamp, short levelname, no "electrum." # 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: def _shorten_name_of_logrecord(record: logging.LogRecord) -> logging.LogRecord:

Loading…
Cancel
Save