We added some code in 0b3a283586
to explicitly hold strong refs for all tasks/futures. At the time I was uncertain if that also solves
GC issues with asyncio.run_coroutine_threadsafe.
ref https://github.com/spesmilo/electrum/pull/9608#issuecomment-2703681663
Looks like it does. run_coroutine_threadsafe *is* going through the custom task factory.
See the unit test.
The somewhat confusing thing is that we need a few event loop iterations for the task factory to run,
due to how run_coroutine_threadsafe is implemented. And also, the task that we will hold as strong ref
in the global set is not the concurrent.futures.Future that run_coroutine_threadsafe returns.
So this commit simply "fixes" the unit test so that it showcases this, and removes related, older, plumbing
from util.py that we now know is no longer needed because of this.
```
$ export ELECTRUM_LINTERS=E9,E101,E129,E273,E274,E703,E71,E722,F5,F6,F7,F8,W191,W29,B
$ export ELECTRUM_LINTERS_IGNORE=B007,B009,B010,B019,B036,F541,F841
$ flake8 . --count --select="$ELECTRUM_LINTERS" --ignore="$ELECTRUM_LINTERS_IGNORE" --show-source --statistics --exclude "*_pb2.py,electrum/_vendor/"
./electrum/commands.py:98:1: F811 redefinition of unused 'format_satoshis' from line 48
def format_satoshis(x):
^
./electrum/commands.py:437:9: F811 redefinition of unused 'Mnemonic' from line 62
from .mnemonic import Mnemonic
^
./electrum/gui/qt/wizard/wallet.py:37:5: F811 redefinition of unused 'Daemon' from line 14
from electrum.daemon import Daemon
^
./electrum/lntransport.py:14:1: F811 redefinition of unused 'Optional' from line 12
from typing import NamedTuple, List, Tuple, Mapping, Optional, TYPE_CHECKING, Union, Dict, Set, Sequence
^
./electrum/lntransport.py:14:1: F811 redefinition of unused 'TYPE_CHECKING' from line 12
from typing import NamedTuple, List, Tuple, Mapping, Optional, TYPE_CHECKING, Union, Dict, Set, Sequence
^
./electrum/plugin.py:966:13: F811 redefinition of unused 'hid' from line 593
import hid
^
./electrum/plugin.py:1040:13: F811 redefinition of unused 'hid' from line 593
import hid
^
./electrum/util.py:44:1: F811 redefinition of unused 'json' from line 26
import json
^
./electrum/util.py:46:1: F811 redefinition of unused 'NamedTuple' from line 29
from typing import NamedTuple, Optional
^
./electrum/util.py:46:1: F811 redefinition of unused 'Optional' from line 29
from typing import NamedTuple, Optional
^
./electrum/util.py:1456:56: F811 redefinition of unused 'traceback' from line 34
async def __aexit__(self, exc_type, exc_value, traceback):
^
./electrum/wallet_db.py:536:9: F811 redefinition of unused 'LOCAL' from line 46
LOCAL = 1
^
./electrum/wallet_db.py:537:9: F811 redefinition of unused 'REMOTE' from line 46
REMOTE = -1
^
./tests/test_bitcoin.py:28:1: F811 redefinition of unused 'bitcoin' from line 9
from electrum import crypto, constants, bitcoin
^
./tests/test_txbatcher.py:11:1: F811 redefinition of unused 'Transaction' from line 7
from electrum.transaction import Transaction, PartialTxInput, PartialTxOutput, TxOutpoint
^
./tests/test_wallet_vertical.py:20:1: F811 redefinition of unused 'Transaction' from line 10
from electrum.transaction import Transaction, PartialTxOutput, tx_from_any, Sighash
^
16 F811 redefinition of unused 'format_satoshis' from line 48
16
```
- on my PC, with Tor Browser running (socks proxy on port 9150), detect_tor_socks_proxy took ~4.01 seconds
- this was because we probed port 9050, 2 sec timeout, 9051, 2 sec timeout, 9150, ~few ms to succeed
- instead we now probe all ports concurrently
allow enable/disable proxy without nuking proxy mode, host and port (explicit enable_proxy config setting),
move tor probe from frontend to backend code, add probe buttons for Qt and QML
- reduce number of methods
- use nametuples instead of dicts
- only two types: OnchainHistoryItem and LightningHistoryItem
- channel open/closes are groups
- move capital gains into separate RPC
* sets the weight of htlc transactions to zero, thereby putting a zero
fee for the htlc transactions
* add inputs to htlc-tx for fee bumping
* switches feature flags
* disable anchor test vectors, which are now partially invalid
The messages are sometimes logged and sometimes shown to the user,
- for logging we might not want to truncate or have higher limits,
- but when shown to the user, we definitely want to truncate the error text.
It is simplest to just do the truncation here, at the lowest level.
Note that we usually prepend the error text with a header e.g. "[DO NOT TRUST THIS MESSAGE]"
and if the error text is too long, this header at the beginning might get "lost" in some way.
Hence we should truncate the error text.
Previously, generally, in case of any error, commands would raise a generic "Exception()" and the CLI/RPC would convert that and return it as `str(e)`.
With this change, we now distinguish "user-facing exceptions" (e.g. "Password required" or "wallet not loaded") and "internal errors" (e.g. bugs).
- for "user-facing exceptions", the behaviour is unchanged
- for "internal errors", we now pass around the traceback (e.g. from daemon server to rpc client) and show it to the user (previously, assuming there was a daemon running, the user could only retrieve the exception from the log of that daemon). These errors use a new jsonrpc error code int (code 2).
As the logic only changes for "internal errors", I deem this change not to be compatibility-breaking.
----------
Examples follow.
Consider the following two commands:
```
@command('')
async def errorgood(self):
from electrum.util import UserFacingException
raise UserFacingException("heyheyhey")
@command('')
async def errorbad(self):
raise Exception("heyheyhey")
```
----------
(before change)
CLI with daemon:
```
$ ./run_electrum --testnet daemon -d
starting daemon (PID 9221)
$ ./run_electrum --testnet errorgood
heyheyhey
$ ./run_electrum --testnet errorbad
heyheyhey
$ ./run_electrum --testnet stop
Daemon stopped
```
CLI without daemon:
```
$ ./run_electrum --testnet -o errorgood
heyheyhey
$ ./run_electrum --testnet -o errorbad
heyheyhey
```
RPC:
```
$ curl --data-binary '{"id":"curltext","jsonrpc":"2.0","method":"errorgood","params":[]}' http://user:pass@127.0.0.1:7777
{"id": "curltext", "jsonrpc": "2.0", "error": {"code": 1, "message": "heyheyhey"}}
$ curl --data-binary '{"id":"curltext","jsonrpc":"2.0","method":"errorbad","params":[]}' http://user:pass@127.0.0.1:7777
{"id": "curltext", "jsonrpc": "2.0", "error": {"code": 1, "message": "heyheyhey"}}
```
----------
(after change)
CLI with daemon:
```
$ ./run_electrum --testnet daemon -d
starting daemon (PID 9254)
$ ./run_electrum --testnet errorgood
heyheyhey
$ ./run_electrum --testnet errorbad
(inside daemon): Traceback (most recent call last):
File "/home/user/wspace/electrum/electrum/daemon.py", line 254, in handle
response['result'] = await f(*params)
File "/home/user/wspace/electrum/electrum/daemon.py", line 361, in run_cmdline
result = await func(*args, **kwargs)
File "/home/user/wspace/electrum/electrum/commands.py", line 163, in func_wrapper
return await func(*args, **kwargs)
File "/home/user/wspace/electrum/electrum/commands.py", line 217, in errorbad
raise Exception("heyheyhey")
Exception: heyheyhey
internal error while executing RPC
$ ./run_electrum --testnet stop
Daemon stopped
```
CLI without daemon:
```
$ ./run_electrum --testnet -o errorgood
heyheyhey
$ ./run_electrum --testnet -o errorbad
0.78 | E | __main__ | error running command (without daemon)
Traceback (most recent call last):
File "/home/user/wspace/electrum/./run_electrum", line 534, in handle_cmd
result = fut.result()
File "/usr/lib/python3.10/concurrent/futures/_base.py", line 458, in result
return self.__get_result()
File "/usr/lib/python3.10/concurrent/futures/_base.py", line 403, in __get_result
raise self._exception
File "/home/user/wspace/electrum/./run_electrum", line 255, in run_offline_command
result = await func(*args, **kwargs)
File "/home/user/wspace/electrum/electrum/commands.py", line 163, in func_wrapper
return await func(*args, **kwargs)
File "/home/user/wspace/electrum/electrum/commands.py", line 217, in errorbad
raise Exception("heyheyhey")
Exception: heyheyhey
```
RPC:
```
$ curl --data-binary '{"id":"curltext","jsonrpc":"2.0","method":"errorgood","params":[]}' http://user:pass@127.0.0.1:7777
{"id": "curltext", "jsonrpc": "2.0", "error": {"code": 1, "message": "heyheyhey"}}
$ curl --data-binary '{"id":"curltext","jsonrpc":"2.0","method":"errorbad","params":[]}' http://user:pass@127.0.0.1:7777
{"id": "curltext", "jsonrpc": "2.0", "error": {"code": 2, "message": "internal error while executing RPC", "data": {"exception": "Exception('heyheyhey')", "traceback": "Traceback (most recent call last):\n File \"/home/user/wspace/electrum/electrum/daemon.py\", line 254, in handle\n response['result'] = await f(*params)\n File \"/home/user/wspace/electrum/electrum/commands.py\", line 163, in func_wrapper\n return await func(*args, **kwargs)\n File \"/home/user/wspace/electrum/electrum/commands.py\", line 217, in errorbad\n raise Exception(\"heyheyhey\")\nException: heyheyhey\n"}}}
```
was getting log spam when running the pycharm debugger in certain cases:
```
3.29 | E | concurrent.futures | exception calling callback for <Future at 0x1d4987bcc70 state=cancelled>
Traceback (most recent call last):
File "...\Python310\lib\concurrent\futures\_base.py", line 342, in _invoke_callbacks
callback(self)
File "...\electrum\electrum\util.py", line 1785, in on_done
if exc := fut_.exception():
File "...\Python310\lib\concurrent\futures\_base.py", line 485, in exception
raise CancelledError()
concurrent.futures._base.CancelledError
```
- rename globals
- also rm hardcoded strings from qml
- use consistent unit names in qml
(previously mixed sat/vB and sat/byte (latter coming from core lib))
...\electrum\electrum\logging.py:137: DeprecationWarning: datetime.datetime.utcnow() is deprecated and scheduled for removal in a future version. Use timezone-aware objects to represent datetimes in UTC: datetime.datetime.now(datetime.UTC).
...\electrum\electrum\x509.py:310: DeprecationWarning: datetime.datetime.utcfromtimestamp() is deprecated and scheduled for removal in a future version. Use timezone-aware objects to represent datetimes in UTC: datetime.datetime.fromtimestamp(timestamp, datetime.UTC).
```
32.40 | E | gui.qt.exception_window.Exception_Hook | exception caught by crash reporter
Traceback (most recent call last):
File "/home/user/wspace/electrum/electrum/gui/qt/wizard/wallet.py", line 709, in <lambda>
button.clicked.connect(lambda: Bip39RecoveryDialog(self, get_account_xpub, on_account_select))
File "/home/user/wspace/electrum/electrum/gui/qt/bip39_recovery_dialog.py", line 40, in __init__
fut = asyncio.run_coroutine_threadsafe(coro, network.asyncio_loop)
AttributeError: 'NoneType' object has no attribute 'asyncio_loop'
```
Somewhat a follow-up to 649ce979ab.
This adds some safety belts so we don't accidentally sign a tx that
contains a dummy address.
Specifically we check that tx does not contain output for dummy addr:
- in wallet.sign_transaction
- in network.broadcast_transaction
The second one is perhaps redundant, but I think it does not hurt.
Plugins.stop() is now part of the normal shutdown flow (since 90f39bce88),
so this shaves up to 100 ms off that (avg: 50 ms).
It is also waited on in around ~60 unit tests: this saves 3 sec.
Plugins.stop was never called, so the Plugins thread only stopped
because of the is_running() check in run(), which triggers too late:
the Plugins thread was stopping after the main thread stopped.
E.g. playing around in the qt wizard with wallet creation for a Trezor,
and closing the wizard (only window):
``` 24.85 | E | p/plugin.Plugins |
Traceback (most recent call last):
File "/home/user/wspace/electrum/electrum/util.py", line 386, in run_jobs
job.run()
File "/home/user/wspace/electrum/electrum/plugin.py", line 430, in run
client.timeout(cutoff)
File "/home/user/wspace/electrum/electrum/plugin.py", line 363, in wrapper
return run_in_hwd_thread(partial(func, *args, **kwargs))
File "/home/user/wspace/electrum/electrum/plugin.py", line 355, in run_in_hwd_thread
fut = _hwd_comms_executor.submit(func)
File "/usr/lib/python3.10/concurrent/futures/thread.py", line 167, in submit
raise RuntimeError('cannot schedule new futures after shutdown')
RuntimeError: cannot schedule new futures after shutdown
```
This clears up log spam for regtest tests.
related:
- https://bugs.python.org/issue44665
- https://github.com/python/cpython/issues/88831
- https://textual.textualize.io/blog/2023/02/11/the-heisenbug-lurking-in-your-async-code/
- https://github.com/python/cpython/issues/91887#issuecomment-1434816045
- "Task was destroyed but it is pending!"
Perhaps we should inspect all our usages of
- asyncio.create_task
- loop.create_task
- asyncio.ensure_future
- asyncio.run_coroutine_threadsafe
?
Example log for running a regtest test:
```
$ python3 -m unittest electrum.tests.regtest.TestLightningAB.test_collaborative_close
***** test_collaborative_close ******
initializing alice
--- Logging error ---
Traceback (most recent call last):
File "/usr/lib/python3.10/logging/__init__.py", line 1100, in emit
msg = self.format(record)
File "/usr/lib/python3.10/logging/__init__.py", line 943, in format
return fmt.format(record)
File "/home/user/wspace/electrum/electrum/logging.py", line 44, in format
record = copy.copy(record) # avoid mutating arg
File "/usr/lib/python3.10/copy.py", line 92, in copy
rv = reductor(4)
ImportError: sys.meta_path is None, Python is likely shutting down
Call stack:
File "/usr/lib/python3.10/asyncio/base_events.py", line 1781, in call_exception_handler
self._exception_handler(self, context)
File "/home/user/wspace/electrum/electrum/util.py", line 1535, in on_exception
loop.default_exception_handler(context)
File "/usr/lib/python3.10/asyncio/base_events.py", line 1744, in default_exception_handler
logger.error('\n'.join(log_lines), exc_info=exc_info)
Message: "Task was destroyed but it is pending!\ntask: <Task pending name='Task-2' coro=<Abstract_Wallet.on_event_adb_set_up_to_date() running at /home/user/wspace/electrum/electrum/wallet.py:485> wait_for=<Future finished result=0> cb=[_chain_future.<locals>._call_set_state() at /usr/lib/python3.10/asyncio/futures.py:392]>"
Arguments: ()
[--- SNIP --- more of the same --- SNIP ---]
--- Logging error ---
Traceback (most recent call last):
File "/usr/lib/python3.10/logging/__init__.py", line 1100, in emit
msg = self.format(record)
File "/usr/lib/python3.10/logging/__init__.py", line 943, in format
return fmt.format(record)
File "/home/user/wspace/electrum/electrum/logging.py", line 44, in format
record = copy.copy(record) # avoid mutating arg
File "/usr/lib/python3.10/copy.py", line 92, in copy
rv = reductor(4)
ImportError: sys.meta_path is None, Python is likely shutting down
Call stack:
File "/usr/lib/python3.10/asyncio/base_events.py", line 1781, in call_exception_handler
self._exception_handler(self, context)
File "/home/user/wspace/electrum/electrum/util.py", line 1535, in on_exception
loop.default_exception_handler(context)
File "/usr/lib/python3.10/asyncio/base_events.py", line 1744, in default_exception_handler
logger.error('\n'.join(log_lines), exc_info=exc_info)
Message: "Task was destroyed but it is pending!\ntask: <Task pending name='Task-31' coro=<Abstract_Wallet.on_event_adb_set_up_to_date() running at /home/user/wspace/electrum/electrum/wallet.py:485> wait_for=<Future pending cb=[_chain_future.<locals>._call_check_cancel() at /usr/lib/python3.10/asyncio/futures.py:385, Task.task_wakeup()]> cb=[_chain_future.<locals>._call_set_state() at /usr/lib/python3.10/asyncio/futures.py:392]>"
Arguments: ()
true
true
true
true
funding alice
```
- standardize_path is made more lenient: it no longer calls os.path.realpath,
as that was causing issues on Windows with some mounted drives
- daemon._wallets is still keyed on the old strict standardize_path, but
filesystem operations in WalletStorage use the new lenient standardize_path.
- daemon._wallets is strict to forbid opening the same logical file twice concurrently
- fs operations however work better on the non-resolved paths, so they use those
closes https://github.com/spesmilo/electrum/issues/8495
decorators (instead of overloading JsonDB._convert_dict and
_convert_value)
- stored_in for elements of a StoreDict
- stored_as for singletons
- extra register methods are defined for key conversions
This commit was adapted from the jsonpatch branch
A new config API is introduced, and ~all of the codebase is adapted to it.
The old API is kept but mainly only for dynamic usage where its extra flexibility is needed.
Using examples, the old config API looked this:
```
>>> config.get("request_expiry", 86400)
604800
>>> config.set_key("request_expiry", 86400)
>>>
```
The new config API instead:
```
>>> config.WALLET_PAYREQ_EXPIRY_SECONDS
604800
>>> config.WALLET_PAYREQ_EXPIRY_SECONDS = 86400
>>>
```
The old API operated on arbitrary string keys, the new one uses
a static ~enum-like list of variables.
With the new API:
- there is a single centralised list of config variables, as opposed to
these being scattered all over
- no more duplication of default values (in the getters)
- there is now some (minimal for now) type-validation/conversion for
the config values
closes https://github.com/spesmilo/electrum/pull/5640
closes https://github.com/spesmilo/electrum/pull/5649
Note: there is yet a third API added here, for certain niche/abstract use-cases,
where we need a reference to the config variable itself.
It should only be used when needed:
```
>>> var = config.cv.WALLET_PAYREQ_EXPIRY_SECONDS
>>> var
<ConfigVarWithConfig key='request_expiry'>
>>> var.get()
604800
>>> var.set(3600)
>>> var.get_default_value()
86400
>>> var.is_set()
True
>>> var.is_modifiable()
True
```
