pytest: test_sign_and_send_psbt is flaky under elementsd

[cdecker]

The test_sign_and_send_psbt is flaking out if running against elementsd with TEST_NETWORK=liquid-regtest:

{
  'code': -1,
  'message': 'Error broadcasting transaction: error code: -26\\nerror message:\\nbad-txns-in-ne-out, value in != value out (code 16). Unsent tx discarded 020000000104c1164183df5e99cb01ccdd5d7aefa64f0c6faf20b19ee2339f699f971443aea50100000000fdffffffd9f383031bf64c50b694996fedcf44d6f873012ce9e54f85fbf62ec5302a23de0000000017160014d6b969d36dffdad9869193f663ee480dfdc73488fdffffff8646ad306a8d97fe28e79c475ad7c9cb0f974f740af66641661ba030c7725e2c0000000000fdffffff37405d7c52be9e298b4e23215b802c3c5fda9f4ee68790f6abcf5541c98e3fd30000000017160014c2ccab171c2a5be9dab52ec41b825863024c5466fdffffff01015ce7b963d37f8f2d51cafbba928aaa9e220b8bbc660571499c03628a3851b8ce0100000000002dc6c00016001494330327f78475154097c0bdff852653c3458df6000000000000024730440220650a853bd616750e79f8ee2b0c01bd6ae9975d44a25fc6f95b5ebb9ac5c7d8db02201a9494e55cdcabbd52f409a39591d28701418046ca319b8a83e7364db775c2af012102272a9a25f1ffed52fab04a2cc88aeab135b53723856a8f1481c26417f88a922e00000002473044022019758d75cdff7faa978af61e07088aebb4c037f9304f3480929be35e8ae7bc6d02204785dbb6788d8f066f022722f9ef7dee0733e3f9e280845cc76e1d2622520888012102b9c0c6844e12a531c968e55c55078ec16d9bf76be9290fd87d1cca72b4839a1700000002473044022012bc958d57473cbec4dde347a2915eb89aae76d0d91ef8056463e5a48de216de022042f41406477b1f6e7bef70e5e81ec9b3cc83c7635075c0594d845a3110296612012103d745445c9362665f22e0d96e9e766f273f3260dea39c8a76bfa05dd2684ddccf00000002473044022078f423936da7c3f988d1c43ff1b68dc82b6572d8edb991331db761e4e1812eaa022000f2048daa9ea2ec8be48102630bde67a4377807e4bc86b2582c3232b6f3e137012103914532812a440a4d766c71cd39193694a340ae11e012e5ba1ad9efba6e76ca53000000'
}

It seems that the change output is not set to the remainder of the inputs, and
thus results in an invalid transaction.

I disabled the test for the time being to get coverage of the test
configuration with elementsd working, but it'd be good to be able to
re-enable it at some time.

The full logs of this run can be found here.

Full stack trace:

___________________________ test_sign_and_send_psbt ____________________________
2181[gw2] linux -- Python 3.7.6 /opt/python/3.7.6/bin/python3.7
2182
2183node_factory = <pyln.testing.utils.NodeFactory object at 0x7f6e6f3bf0d0>
2184bitcoind = <pyln.testing.utils.ElementsD object at 0x7f6e6ccdfb90>
2185chainparams = {'bip173_prefix': 'ert', 'chain_hash': '9f87eb580b9e5f11dc211e9fb66abb3699999044f8fe146801162393364286c6', 'elements': True, 'example_addr': 'ert1qjsesxflhs3632syhcz7llpfx20p5tr0kpllfve', ...}
2186
2187    def test_sign_and_send_psbt(node_factory, bitcoind, chainparams):
2188        """
2189        Tests for the sign + send psbt RPCs
2190        """
2191        amount = 1000000
2192        total_outs = 12
2193        coin_mvt_plugin = os.path.join(os.getcwd(), 'tests/plugins/coin_movements.py')
2194        l1 = node_factory.get_node(options={'plugin': coin_mvt_plugin},
2195                                   feerates=(7500, 7500, 7500, 7500))
2196        l2 = node_factory.get_node()
2197        addr = chainparams['example_addr']
2198    
2199        # Add a medley of funds to withdraw later, bech32 + p2sh-p2wpkh
2200        for i in range(total_outs // 2):
2201            bitcoind.rpc.sendtoaddress(l1.rpc.newaddr()['bech32'],
2202                                       amount / 10**8)
2203            bitcoind.rpc.sendtoaddress(l1.rpc.newaddr('p2sh-segwit')['p2sh-segwit'],
2204                                       amount / 10**8)
2205        bitcoind.generate_block(1)
2206        wait_for(lambda: len(l1.rpc.listfunds()['outputs']) == total_outs)
2207    
2208        # Make a PSBT out of our inputs
2209        funding = l1.rpc.fundpsbt(satoshi=Millisatoshi(3 * amount * 1000),
2210                                  feerate=7500,
2211                                  startweight=42,
2212                                  reserve=True)
2213        assert len([x for x in l1.rpc.listfunds()['outputs'] if x['reserved']]) == 4
2214        psbt = bitcoind.rpc.decodepsbt(funding['psbt'])
2215        saved_input = psbt['tx']['vin'][0]
2216    
2217        # Go ahead and unreserve the UTXOs, we'll use a smaller
2218        # set of them to create a second PSBT that we'll attempt to sign
2219        # and broadcast (to disastrous results)
2220        l1.rpc.unreserveinputs(funding['psbt'])
2221    
2222        # Re-reserve one of the utxos we just unreserved
2223        psbt = bitcoind.rpc.createpsbt([{'txid': saved_input['txid'],
2224                                         'vout': saved_input['vout']}], [])
2225        l1.rpc.reserveinputs(psbt)
2226    
2227        # We require the utxos be reserved before signing them
2228        with pytest.raises(RpcError, match=r"Aborting PSBT signing. UTXO .* is not reserved"):
2229            l1.rpc.signpsbt(funding['psbt'])['signed_psbt']
2230    
2231        # Now we unreserve the singleton, so we can reserve it again
2232        l1.rpc.unreserveinputs(psbt)
2233    
2234        # Now add an output.
2235        output_pbst = bitcoind.rpc.createpsbt([],
2236                                              [{addr: 3 * amount / 10**8}])
2237        fullpsbt = bitcoind.rpc.joinpsbts([funding['psbt'], output_pbst])
2238    
2239        # We re-reserve the first set...
2240        l1.rpc.reserveinputs(fullpsbt)
2241    
2242        # Sign + send the PSBT we've created
2243        signed_psbt = l1.rpc.signpsbt(fullpsbt)['signed_psbt']
2244>       broadcast_tx = l1.rpc.sendpsbt(signed_psbt)
2245
2246tests/test_wallet.py:705: 
2247_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
2248contrib/pyln-client/pyln/client/lightning.py:1175: in sendpsbt
2249    return self.call("sendpsbt", payload)
2250_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
2251
2252self = <pyln.client.lightning.LightningRpc object at 0x7f6e6eb2f450>
2253method = 'sendpsbt'
2254payload = {'psbt': 'cHNldP8BAPECAAAAAATBFkGD316ZywHM3V1676ZPDG+vILGe4jOfaZ+XFEOupQEAAAAA/f///9nzgwMb9kxQtpSZb+3PRNb4cwEs6eVPhfv2...luhrZ77pudspTCMLMqxcAAAAAC/wIZWxlbWVudHMACEBCDwAAAAAAC/wIZWxlbWVudHMCIFznuWPTf48tUcr7upKKqp4iC4u8ZgVxSZwDYoo4UbjOAAA='}
2255
2256    def call(self, method, payload=None):
2257        self.logger.debug("Calling %s with payload %r", method, payload)
2258    
2259        if payload is None:
2260            payload = {}
2261        # Filter out arguments that are None
2262        if isinstance(payload, dict):
2263            payload = {k: v for k, v in payload.items() if v is not None}
2264    
2265        # FIXME: we open a new socket for every readobj call...
2266        sock = UnixSocket(self.socket_path)
2267        self._writeobj(sock, {
2268            "jsonrpc": "2.0",
2269            "method": method,
2270            "params": payload,
2271            "id": self.next_id,
2272        })
2273        self.next_id += 1
2274        resp, _ = self._readobj(sock)
2275        sock.close()
2276    
2277        self.logger.debug("Received response for %s call: %r", method, resp)
2278        if not isinstance(resp, dict):
2279            raise ValueError("Malformed response, response is not a dictionary %s." % resp)
2280        elif "error" in resp:
2281>           raise RpcError(method, payload, resp['error'])
2282E           pyln.client.lightning.RpcError: RPC call failed: method: sendpsbt, payload: {'psbt': 'cHNldP8BAPECAAAAAATBFkGD316ZywHM3V1676ZPDG+vILGe4jOfaZ+XFEOupQEAAAAA/f///9nzgwMb9kxQtpSZb+3PRNb4cwEs6eVPhfv2LsUwKiPeAAAAAAD9////hkatMGqNl/4o55xHWtfJyw+XT3QK9mZBZhugMMdyXiwAAAAAAP3///83QF18Ur6eKYtOIyFbgCw8X9qfTuaHkParz1VByY4/0wAAAAAA/f///wEBXOe5Y9N/jy1Ryvu6koqqniILi7xmBXFJnANiijhRuM4BAAAAAAAtxsAAFgAUlDMDJ/eEdRVAl8C9/4UmU8NFjfYAAAAAAAEBQgFc57lj03+PLVHK+7qSiqqeIguLvGYFcUmcA2KKOFG4zgEAAAAAAA9CQAAWABTVXEk5g9tlHhBHdFWx1AjDHn6eMSICAicqmiXx/+1S+rBKLMiK6rE1tTcjhWqPFIHCZBf4ipIuRzBEAiBlCoU71hZ1Dnn47isMAb1q6ZddRKJfxvlbXruaxcfY2wIgGpSU5Vzcq71S9AmjlZHShwFBgEbKMZuKg+c2Tbd1wq8BIgYCJyqaJfH/7VL6sEosyIrqsTW1NyOFao8UgcJkF/iKki4I1VxJOQAAAAAL/AhlbGVtZW50cwAIQEIPAAAAAAAL/AhlbGVtZW50cwIgXOe5Y9N/jy1Ryvu6koqqniILi7xmBXFJnANiijhRuM4AAQFDAVznuWPTf48tUcr7upKKqp4iC4u8ZgVxSZwDYoo4UbjOAQAAAAAAD0JAABepFGVXKPNs/jbQGqUNMjZwRGn4SlVAhyICArnAxoROEqUxyWjlXFUHjsFtm/dr6SkP2H0cynK0g5oXRzBEAiAZdY11zf9/qpeK9h4HCIrrtMA3+TBPNICSm+Neiue8bQIgR4XbtniNjwZvAici+e997gcz4/nigIRcx24dJiJSCIgBAQQWABTWuWnTbf/a2YaRk/Zj7kgN/cc0iCIGArnAxoROEqUxyWjlXFUHjsFtm/dr6SkP2H0cynK0g5oXCNa5adMAAAAAC/wIZWxlbWVudHMACEBCDwAAAAAAC/wIZWxlbWVudHMCIFznuWPTf48tUcr7upKKqp4iC4u8ZgVxSZwDYoo4UbjOAAEBQgFc57lj03+PLVHK+7qSiqqeIguLvGYFcUmcA2KKOFG4zgEAAAAAAA9CQAAWABQB+tkKvNZml+JZIWRyLeSpXr7hZSICA9dFRFyTYmZfIuDZbp52byc/MmDeo5yKdr+gXdJoTdzPRzBEAiASvJWNV0c8vsTd40eikV64mq520Nke+AVkY+WkjeIW3gIgQvQUBkd7H25773Dl6B7Js8yDx2NQdcBZTYRaMRApZhIBIgYD10VEXJNiZl8i4NlunnZvJz8yYN6jnIp2v6Bd0mhN3M8IAfrZCgAAAAAL/AhlbGVtZW50cwAIQEIPAAAAAAAL/AhlbGVtZW50cwIgXOe5Y9N/jy1Ryvu6koqqniILi7xmBXFJnANiijhRuM4AAQFDAVznuWPTf48tUcr7upKKqp4iC4u8ZgVxSZwDYoo4UbjOAQAAAAAAD0JAABepFAsh6xf51eXrXYNfrC19tKMolxLThyICA5FFMoEqRApNdmxxzTkZNpSjQK4R4BLluhrZ77pudspTRzBEAiB49COTbafD+YjRxD/xto3IK2Vy2O25kTMdt2Hk4YEuqgIgAPIEjaqeouyL5IECYwveZ6Q3eAfkvIayWCwyMrbz4TcBAQQWABTCzKsXHCpb6dq1LsQbglhjAkxUZiIGA5FFMoEqRApNdmxxzTkZNpSjQK4R4BLluhrZ77pudspTCMLMqxcAAAAAC/wIZWxlbWVudHMACEBCDwAAAAAAC/wIZWxlbWVudHMCIFznuWPTf48tUcr7upKKqp4iC4u8ZgVxSZwDYoo4UbjOAAA='}, error: {'code': -1, 'message': 'Error broadcasting transaction: error code: -26\\nerror message:\\nbad-txns-in-ne-out, value in != value out (code 16). Unsent tx discarded 020000000104c1164183df5e99cb01ccdd5d7aefa64f0c6faf20b19ee2339f699f971443aea50100000000fdffffffd9f383031bf64c50b694996fedcf44d6f873012ce9e54f85fbf62ec5302a23de0000000017160014d6b969d36dffdad9869193f663ee480dfdc73488fdffffff8646ad306a8d97fe28e79c475ad7c9cb0f974f740af66641661ba030c7725e2c0000000000fdffffff37405d7c52be9e298b4e23215b802c3c5fda9f4ee68790f6abcf5541c98e3fd30000000017160014c2ccab171c2a5be9dab52ec41b825863024c5466fdffffff01015ce7b963d37f8f2d51cafbba928aaa9e220b8bbc660571499c03628a3851b8ce0100000000002dc6c00016001494330327f78475154097c0bdff852653c3458df6000000000000024730440220650a853bd616750e79f8ee2b0c01bd6ae9975d44a25fc6f95b5ebb9ac5c7d8db02201a9494e55cdcabbd52f409a39591d28701418046ca319b8a83e7364db775c2af012102272a9a25f1ffed52fab04a2cc88aeab135b53723856a8f1481c26417f88a922e00000002473044022019758d75cdff7faa978af61e07088aebb4c037f9304f3480929be35e8ae7bc6d02204785dbb6788d8f066f022722f9ef7dee0733e3f9e280845cc76e1d2622520888012102b9c0c6844e12a531c968e55c55078ec16d9bf76be9290fd87d1cca72b4839a1700000002473044022012bc958d57473cbec4dde347a2915eb89aae76d0d91ef8056463e5a48de216de022042f41406477b1f6e7bef70e5e81ec9b3cc83c7635075c0594d845a3110296612012103d745445c9362665f22e0d96e9e766f273f3260dea39c8a76bfa05dd2684ddccf00000002473044022078f423936da7c3f988d1c43ff1b68dc82b6572d8edb991331db761e4e1812eaa022000f2048daa9ea2ec8be48102630bde67a4377807e4bc86b2582c3232b6f3e137012103914532812a440a4d766c71cd39193694a340ae11e012e5ba1ad9efba6e76ca53000000'}
2283
2284contrib/pyln-client/pyln/client/lightning.py:301: RpcError

A secondary failure may also provide some more information about why this is failing:

self = <bitcoin.rpc.RawProxy object at 0x7f8fea81de90>
service_name = 'decodepsbt'
args = ('cHNidP8BAK4CAAAABDoklY5jT1FUm/9T0e52Rj/ZK85Yz7hirZLzomb0VdbHAAAAAAD9////ydE+Fe3IbhgpfABhC28Vq2N5DKWKUb9eqWx00Hbhpl0B...YLbr6s/cZQAAAAEBIEBCDwAAAAAAF6kUkzp1unOXtbYl0VFwJKSOB7RqWgSHAQQWABQ9Q9ImvMJwGa3lLXo9xSp6wb4ouAz8CWxpZ2h0bmluZwICAGoA',)
postdata = '{"version": "1.1", "method": "decodepsbt", "params": ["cHNidP8BAK4CAAAABDoklY5jT1FUm/9T0e52Rj/ZK85Yz7hirZLzomb0VdbHAA...AAAAEBIEBCDwAAAAAAF6kUkzp1unOXtbYl0VFwJKSOB7RqWgSHAQQWABQ9Q9ImvMJwGa3lLXo9xSp6wb4ouAz8CWxpZ2h0bmluZwICAGoA"], "id": 1}'
headers = {'Authorization': b'Basic cnBjdXNlcjpycGNwYXNz', 'Content-type': 'application/json', 'Host': 'localhost', 'User-Agent': 'AuthServiceProxy/0.1'}
response = {'error': {'code': -22, 'message': 'TX decode failed PSBT is not sane.: iostream error'}, 'id': 1, 'result': None}

    def _call(self, service_name, *args):
        self.__id_count += 1
    
        postdata = json.dumps({'version': '1.1',
                               'method': service_name,
                               'params': args,
                               'id': self.__id_count})
    
        headers = {
            'Host': self.__url.hostname,
            'User-Agent': DEFAULT_USER_AGENT,
            'Content-type': 'application/json',
        }
    
        if self.__auth_header is not None:
            headers['Authorization'] = self.__auth_header
    
        self.__conn.request('POST', self.__url.path, postdata, headers)
    
        response = self._get_response()
        if response['error'] is not None:
>           raise JSONRPCError(response['error'])
E           bitcoin.rpc.JSONRPCError: {'code': -22, 'message': 'TX decode failed PSBT is not sane.: iostream error'}

../../../.local/lib/python3.7/site-packages/bitcoin/rpc.py:238: JSONRPCError

Though I'm not sure they're related. Full logs here