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
```
If enabled, we log to stderr, which can get inspected via logcat.
Not user-friendly at all - but previously there was no way to get logs from a release build.
closes https://github.com/spesmilo/electrum/issues/7409
When running a command, file logging is disabled as every
command-invocation would create a new logfile. However if the user
explicitly sets "-v" on the commandline, there's no reason why that
shouldn't work.
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
E.g. on Windows, files open in one process cannot be deleted by another process.
With file logging enabled, if an old logfile was open in a text editor,
Electrum could crash during startup.
```
E | __main__ |
Traceback (most recent call last):
File "...\electrum\run_electrum", line 391, in main
handle_cmd(
File "...\electrum\run_electrum", line 403, in handle_cmd
configure_logging(config)
File "...\electrum\electrum\logging.py", line 278, in configure_logging
_configure_file_logging(log_directory)
File "...\electrum\electrum\logging.py", line 107, in _configure_file_logging
_delete_old_logs(log_directory)
File "...\electrum\electrum\logging.py", line 98, in _delete_old_logs
os.remove(str(f))
PermissionError: [WinError 32] The process cannot access the file because it is being used by another process: '...\\AppData\\Roaming\\Electrum\\testnet\\logs\\electrum_log_20210414T023751Z_25008.log'
```
--- Logging error ---
Traceback (most recent call last):
File "...\Python38\lib\logging\__init__.py", line 1084, in emit
stream.write(msg + self.terminator)
File "...\Python38\lib\encodings\cp1252.py", line 19, in encode
return codecs.charmap_encode(input,self.errors,encoding_table)[0]
UnicodeEncodeError: 'charmap' codec can't encode character '\u26a1' in position 80: character maps to <undefined>
Call stack:
File ".../electrum/run_electrum", line 466, in <module>
main()
File ".../electrum/run_electrum", line 384, in main
handle_cmd(
File ".../electrum/run_electrum", line 402, in handle_cmd
d.run_gui(config, plugins)
File "...\electrum\electrum\daemon.py", line 572, in run_gui
self.gui_object.main()
File "...\electrum\electrum\gui\qt\__init__.py", line 391, in main
self.app.exec_()
File "...\electrum\electrum\gui\qt\channels_list.py", line 308, in new_channel_with_warning
self.new_channel_dialog()
File "...\electrum\electrum\gui\qt\channels_list.py", line 390, in new_channel_dialog
if not d.exec_():
File "...\electrum\electrum\gui\qt\channels_list.py", line 358, in on_suggest
nodeid = bh2u(lnworker.lnrater.suggest_peer() or b'')
File "...\electrum\electrum\lnrater.py", line 257, in suggest_peer
return self.suggest_node_channel_open()[0]
File "...\electrum\electrum\lnrater.py", line 248, in suggest_node_channel_open
self.logger.info(
Message: 'node rating for Bottlepay⚡:\nNodeStats(number_channels=20, total_capacity_msat=167455866000, median_capacity_msat=8460000000.0, mean_capacity_msat=8372793300.0, node_age_block_height=71003, mean_channel_age_block_height=48581.39999999991, blocks_since_last_channel=507, mean_fee_rate=1e-06) (score 0.5034595626052799)'
Arguments: ()
Leaking addresses/pubkeys/txids is a privacy leak...
but with lightning, logging should be enabled by default, as otherwise
issues would be sometimes impossible to debug...
Well, disable it for now.
old style "-v" still works
filtering examples:
-v=debug,network=error,interface=error // effectively blacklists network and interface
-v=warning,network=debug,interface=debug // effectively whitelists network and interface
SomberNight
Sander van Grieken
Christian Clauss
cluelessperson