23.2.6: wallet_elements_regression_1259.py test failure: JSONRPCException: Unable to blind transaction: Are you sure each asset type to blind is represented in the inputs? (-8)

[whitslack]

./configure \
	--prefix=/usr --build=x86_64-pc-linux-gnu --host=x86_64-pc-linux-gnu \
	--mandir=/usr/share/man --infodir=/usr/share/info --datadir=/usr/share \
	--sysconfdir=/etc --localstatedir=/var/lib --datarootdir=/usr/share \
	--disable-dependency-tracking --disable-silent-rules --disable-static \
	--docdir=/usr/share/doc/elements-23.2.6 \
	--htmldir=/usr/share/doc/elements-23.2.6/html --with-sysroot=/ \
	--libdir=/usr/lib64 --disable-static --enable-wallet --with-sqlite \
	--with-bdb --disable-usdt --without-miniupnpc --without-natpmp \
	--enable-tests --disable-bench --disable-fuzz --disable-fuzz-binary \
	--without-qrencode --disable-ccache --enable-asm --disable-zmq \
	--enable-man --enable-external-signer --with-utils --enable-util-cli \
	--enable-util-tx --enable-util-wallet --disable-util-util \
	--without-seccomp --without-libs --with-daemon --with-gui=qt5 \
	--with-qtdbus --with-system-libsecp256k1

2025-02-11T15:21:33.232000Z TestFramework (DEBUG): PRNG seed is: 1232519480871284039
2025-02-11T15:21:33.232000Z TestFramework (DEBUG): Setting up network thread
2025-02-11T15:21:33.233000Z TestFramework (INFO): Initializing test directory /var/tmp/portage/net-p2p/elements-23.2.6/temp/test_runner_₿_🏃_20250211_151911/wallet_elements_regression_1259_233
2025-02-11T15:21:33.242000Z TestFramework.node0 (DEBUG): bitcoind started, waiting for RPC to come up
2025-02-11T15:21:33.249000Z TestFramework.node1 (DEBUG): bitcoind started, waiting for RPC to come up
2025-02-11T15:21:33.255000Z TestFramework.node2 (DEBUG): bitcoind started, waiting for RPC to come up
2025-02-11T15:21:33.807000Z TestFramework.node0 (DEBUG): RPC successfully started
2025-02-11T15:21:33.810000Z TestFramework.node1 (DEBUG): RPC successfully started
2025-02-11T15:21:33.812000Z TestFramework.node2 (DEBUG): RPC successfully started
2025-02-11T15:21:34.443000Z TestFramework.node0 (DEBUG): TestNode.generate() dispatches `generate` call to `generatetoaddress`
2025-02-11T15:21:35.768000Z TestFramework (INFO): Send some policy asset to node 1
2025-02-11T15:21:36.151000Z TestFramework.node0 (DEBUG): TestNode.generate() dispatches `generate` call to `generatetoaddress`
2025-02-11T15:21:36.268000Z TestFramework (INFO): Issuing an asset from node 0
2025-02-11T15:21:37.077000Z TestFramework.node0 (DEBUG): TestNode.generate() dispatches `generate` call to `generatetoaddress`
2025-02-11T15:21:37.162000Z TestFramework (INFO): Asset ID is 0c2260c615ccc4a503f9a5ddb10d1ed0da56196d6602a95adf4379899cceb236
2025-02-11T15:21:37.162000Z TestFramework (INFO): Sending 45 utxos of asset to node 1
2025-02-11T15:21:37.758000Z TestFramework.node0 (DEBUG): TestNode.generate() dispatches `generate` call to `generatetoaddress`
2025-02-11T15:21:38.348000Z TestFramework.node0 (DEBUG): TestNode.generate() dispatches `generate` call to `generatetoaddress`
2025-02-11T15:21:39.101000Z TestFramework.node0 (DEBUG): TestNode.generate() dispatches `generate` call to `generatetoaddress`
2025-02-11T15:21:39.936000Z TestFramework.node0 (DEBUG): TestNode.generate() dispatches `generate` call to `generatetoaddress`
2025-02-11T15:21:41.664000Z TestFramework.node0 (DEBUG): TestNode.generate() dispatches `generate` call to `generatetoaddress`
2025-02-11T15:21:43.375000Z TestFramework.node0 (DEBUG): TestNode.generate() dispatches `generate` call to `generatetoaddress`
2025-02-11T15:21:45.080000Z TestFramework.node0 (DEBUG): TestNode.generate() dispatches `generate` call to `generatetoaddress`
2025-02-11T15:21:45.773000Z TestFramework.node0 (DEBUG): TestNode.generate() dispatches `generate` call to `generatetoaddress`
2025-02-11T15:21:46.384000Z TestFramework.node0 (DEBUG): TestNode.generate() dispatches `generate` call to `generatetoaddress`
2025-02-11T15:21:47.012000Z TestFramework.node0 (DEBUG): TestNode.generate() dispatches `generate` call to `generatetoaddress`
2025-02-11T15:21:47.660000Z TestFramework.node0 (DEBUG): TestNode.generate() dispatches `generate` call to `generatetoaddress`
2025-02-11T15:21:48.264000Z TestFramework.node0 (DEBUG): TestNode.generate() dispatches `generate` call to `generatetoaddress`
2025-02-11T15:21:49.809000Z TestFramework.node0 (DEBUG): TestNode.generate() dispatches `generate` call to `generatetoaddress`
2025-02-11T15:21:50.447000Z TestFramework.node0 (DEBUG): TestNode.generate() dispatches `generate` call to `generatetoaddress`
2025-02-11T15:21:51.058000Z TestFramework.node0 (DEBUG): TestNode.generate() dispatches `generate` call to `generatetoaddress`
2025-02-11T15:21:52.529000Z TestFramework.node0 (DEBUG): TestNode.generate() dispatches `generate` call to `generatetoaddress`
2025-02-11T15:21:53.054000Z TestFramework.node0 (DEBUG): TestNode.generate() dispatches `generate` call to `generatetoaddress`
2025-02-11T15:21:53.575000Z TestFramework.node0 (DEBUG): TestNode.generate() dispatches `generate` call to `generatetoaddress`
2025-02-11T15:21:55.071000Z TestFramework.node0 (DEBUG): TestNode.generate() dispatches `generate` call to `generatetoaddress`
2025-02-11T15:21:55.629000Z TestFramework.node0 (DEBUG): TestNode.generate() dispatches `generate` call to `generatetoaddress`
2025-02-11T15:21:56.310000Z TestFramework.node0 (DEBUG): TestNode.generate() dispatches `generate` call to `generatetoaddress`
2025-02-11T15:21:56.885000Z TestFramework.node0 (DEBUG): TestNode.generate() dispatches `generate` call to `generatetoaddress`
2025-02-11T15:21:57.988000Z TestFramework.node0 (DEBUG): TestNode.generate() dispatches `generate` call to `generatetoaddress`
2025-02-11T15:21:59.259000Z TestFramework.node0 (DEBUG): TestNode.generate() dispatches `generate` call to `generatetoaddress`
2025-02-11T15:22:00.141000Z TestFramework.node0 (DEBUG): TestNode.generate() dispatches `generate` call to `generatetoaddress`
2025-02-11T15:22:01.094000Z TestFramework.node0 (DEBUG): TestNode.generate() dispatches `generate` call to `generatetoaddress`
2025-02-11T15:22:02.966000Z TestFramework.node0 (DEBUG): TestNode.generate() dispatches `generate` call to `generatetoaddress`
2025-02-11T15:22:03.884000Z TestFramework.node0 (DEBUG): TestNode.generate() dispatches `generate` call to `generatetoaddress`
2025-02-11T15:22:04.759000Z TestFramework.node0 (DEBUG): TestNode.generate() dispatches `generate` call to `generatetoaddress`
2025-02-11T15:22:05.467000Z TestFramework.node0 (DEBUG): TestNode.generate() dispatches `generate` call to `generatetoaddress`
2025-02-11T15:22:06.020000Z TestFramework.node0 (DEBUG): TestNode.generate() dispatches `generate` call to `generatetoaddress`
2025-02-11T15:22:07.617000Z TestFramework.node0 (DEBUG): TestNode.generate() dispatches `generate` call to `generatetoaddress`
2025-02-11T15:22:08.236000Z TestFramework.node0 (DEBUG): TestNode.generate() dispatches `generate` call to `generatetoaddress`
2025-02-11T15:22:08.930000Z TestFramework.node0 (DEBUG): TestNode.generate() dispatches `generate` call to `generatetoaddress`
2025-02-11T15:22:09.588000Z TestFramework.node0 (DEBUG): TestNode.generate() dispatches `generate` call to `generatetoaddress`
2025-02-11T15:22:10.277000Z TestFramework.node0 (DEBUG): TestNode.generate() dispatches `generate` call to `generatetoaddress`
2025-02-11T15:22:10.976000Z TestFramework.node0 (DEBUG): TestNode.generate() dispatches `generate` call to `generatetoaddress`
2025-02-11T15:22:12.671000Z TestFramework.node0 (DEBUG): TestNode.generate() dispatches `generate` call to `generatetoaddress`
2025-02-11T15:22:13.439000Z TestFramework.node0 (DEBUG): TestNode.generate() dispatches `generate` call to `generatetoaddress`
2025-02-11T15:22:15.157000Z TestFramework.node0 (DEBUG): TestNode.generate() dispatches `generate` call to `generatetoaddress`
2025-02-11T15:22:16.786000Z TestFramework.node0 (DEBUG): TestNode.generate() dispatches `generate` call to `generatetoaddress`
2025-02-11T15:22:17.673000Z TestFramework.node0 (DEBUG): TestNode.generate() dispatches `generate` call to `generatetoaddress`
2025-02-11T15:22:18.408000Z TestFramework.node0 (DEBUG): TestNode.generate() dispatches `generate` call to `generatetoaddress`
2025-02-11T15:22:20.057000Z TestFramework.node0 (DEBUG): TestNode.generate() dispatches `generate` call to `generatetoaddress`
2025-02-11T15:22:21.624000Z TestFramework.node0 (DEBUG): TestNode.generate() dispatches `generate` call to `generatetoaddress`
2025-02-11T15:22:21.769000Z TestFramework (INFO): Create the raw consolidation transaction
2025-02-11T15:22:21.791000Z TestFramework (INFO): Fund the raw transaction
2025-02-11T15:22:23.653000Z TestFramework (INFO): Blind and sign the raw transaction
2025-02-11T15:22:23.711000Z TestFramework (ERROR): JSONRPC error
Traceback (most recent call last):
  File "/var/tmp/portage/net-p2p/elements-23.2.6/work/elements-23.2.6/test/functional/test_framework/test_framework.py", line 132, in main
    self.run_test()
    ~~~~~~~~~~~~~^^
  File "/var/tmp/portage/net-p2p/elements-23.2.6/work/elements-23.2.6/test/functional/wallet_elements_regression_1259.py", line 70, in run_test
    hex = self.nodes[1].blindrawtransaction(raw_tx['hex'])
  File "/var/tmp/portage/net-p2p/elements-23.2.6/work/elements-23.2.6/test/functional/test_framework/coverage.py", line 49, in __call__
    return_val = self.auth_service_proxy_instance.__call__(*args, **kwargs)
  File "/var/tmp/portage/net-p2p/elements-23.2.6/work/elements-23.2.6/test/functional/test_framework/authproxy.py", line 144, in __call__
    raise JSONRPCException(response['error'], status)
test_framework.authproxy.JSONRPCException: Unable to blind transaction: Are you sure each asset type to blind is represented in the inputs? (-8)
2025-02-11T15:22:23.719000Z TestFramework (DEBUG): Closing down network thread
2025-02-11T15:22:23.770000Z TestFramework (INFO): Stopping nodes
2025-02-11T15:22:23.770000Z TestFramework.node0 (DEBUG): Stopping node
2025-02-11T15:22:23.772000Z TestFramework.node1 (DEBUG): Stopping node
2025-02-11T15:22:23.776000Z TestFramework.node2 (DEBUG): Stopping node
2025-02-11T15:22:23.980000Z TestFramework.node0 (DEBUG): Node stopped
2025-02-11T15:22:23.981000Z TestFramework.node1 (DEBUG): Node stopped
2025-02-11T15:22:23.981000Z TestFramework.node2 (DEBUG): Node stopped
2025-02-11T15:22:23.981000Z TestFramework (WARNING): Not cleaning up dir /var/tmp/portage/net-p2p/elements-23.2.6/temp/test_runner_₿_🏃_20250211_151911/wallet_elements_regression_1259_233
2025-02-11T15:22:23.981000Z TestFramework (ERROR): Test failed. Test logging available at /var/tmp/portage/net-p2p/elements-23.2.6/temp/test_runner_₿_🏃_20250211_151911/wallet_elements_regression_1259_233/test_framework.log
2025-02-11T15:22:23.981000Z TestFramework (ERROR): 
2025-02-11T15:22:23.981000Z TestFramework (ERROR): Hint: Call /var/tmp/portage/net-p2p/elements-23.2.6/work/elements-23.2.6/test/functional/combine_logs.py '/var/tmp/portage/net-p2p/elements-23.2.6/temp/test_runner_₿_🏃_20250211_151911/wallet_elements_regression_1259_233' to consolidate all logs
2025-02-11T15:22:23.982000Z TestFramework (ERROR): 
2025-02-11T15:22:23.982000Z TestFramework (ERROR): If this failure happened unexpectedly or intermittently, please file a bug and provide a link or upload of the combined log.
2025-02-11T15:22:23.982000Z TestFramework (ERROR): https://github.com/ElementsProject/elements/issues
2025-02-11T15:22:23.982000Z TestFramework (ERROR): 

Expected behavior

All tests pass.

Actual behavior

wallet_elements_regression_1259.py had an assertion failure.

System information

Elements 23.2.6 compiled with GCC Gentoo 15.0.0_pre20241222 p34.

Linux x86_64

Combined log: http://www.mattwhitlock.com/wallet_elements_regression_1259_233_20250311.log

[psgreco]

@whitslack I'm unable to reproduce this, any theory onto what could be producing it?

[whitslack]

The test sends coins from node 0 to node 1 and then mines a block on node 0 but does not wait for node 1 to see the new block before the test attempts to fund a raw transaction on node 1.

Edit: It appears as though the generate method handles waiting for the new block to be processed by the other nodes, so that's probably not the problem. Looking at the combined log (linked above), the last block generated by node 0 is indeed logged by UpdateTip on node 1 (and an AddToWallet … new is also logged) before the "Fund the raw transaction" step. However, this does look suspect: node1 2025-02-11T15:22:23.466642Z [httpworker.0] [wallet/coinselection.cpp:312] [KnapsackSolver] Not enough funds to create target 45000000000 for asset 0c2260c615ccc4a503f9a5ddb10d1ed0da56196d6602a95adf4379899cceb236. Are coins considered spendable by fundrawtransaction when they have only 1 confirmation?

It would be helpful if the test logged more information about the state of the wallet in the event of a failure. In particular, it would be good to see the output of listunspent so we can tell whether all 45 UTxOs are in fact present and spendable.