cloudhead/nakamoto

Client isn't Broadcasting transactions properly

rajarshimaitra opened this issue ยท 9 comments

This is a little hard to reproduce directly from this issue description as I discovered it inside the BDK testing framework. But the gist of the story is, it seems client::Handle::submit_transaction() isn't properly broadcasting transactions to connected peer.

To test this I have the following code that creates a BDK wallet, a bitcoind regtest node, and a nakamoto client that connects to the bitcoind as its peer to the p2p port.

fn test_broadcast() {
                let (wallet, nakamoto, descriptors, mut bitcoind) = init_single_sig();
                let target_addr = bitcoind.get_node_address(None);

                // Create and broadcast funding transaction
                let tx = bitcoind.receive(testutils! {
                    @tx ( (@external descriptors, 0) => 50_000 )
                });
                let _ = nakamoto.broadcast(&tx).unwrap();

                wallet.sync(&nakamoto, SyncOptions::default()).unwrap();

                // Create and broadcast spending transaction
                let mut builder = wallet.build_tx();
                builder.add_recipient(target_addr.script_pubkey(), 5_000);
                let (mut psbt, _) = builder.finish().unwrap();
                let _ = wallet.sign(&mut psbt, Default::default()).unwrap();
                let tx = psbt.extract_tx();
                let _ = nakamoto.broadcast(&tx).unwrap();

                // Check whats in the mempool
                println!("Mempool : {:?}", bitcoind.get_raw_mempool().unwrap());
            }

The code is straight forward and does the following

  • bitcoind.receive() creates a funding transaction of 50k sats to the wallet address. Broadcast this transaction via the rpc call submit_raw_transaction.
  • nakamoto.broadcast() calls the Handle::submit_transaction() and tries to broadcast the same transaction again via the p2p port.
  • Then we create and broadcast a spending transaction, spending from the initial funding utxo. But this time only via nakamoto_broadcast().
  • We print the the mempool of the bitcoind, to see what got included.

Expectation:

  • We expect both the funding and spending transaction to be included in the bitcoind mempool.

Observation:

  • After running the code we only see one transaction in the mempool.
Broadcasting txid : 479d99664deacc8987d9b8069cf55c521d56d7884425019403fb6f661104b8e8
Broacasted to : NonEmpty { head: 127.0.0.1:44941, tail: [] }
Broadcasting txid : 180e00af318f9d6ed77f74082fdadaf0c9aebc12902455a85355d20592305361
Broacasted to : NonEmpty { head: 127.0.0.1:44941, tail: [] }
Mempool : [479d99664deacc8987d9b8069cf55c521d56d7884425019403fb6f661104b8e8]

The Broadcasted to : NonEmpty .. log is coming from internal of the nakamoto.broadcast() which signifies the Handle::submit_transaction() call returned without any error.

The mempool contains only 1 transaction, which is the initial funding transaction, and that is included because of the submit_raw_tranbsaction() call of the bitcoind RPC. Not because of the nakamoto.braodacast().

To verify this I printed the debug.log of bitcoind, with debug=[net, mempool, mempoolrej]. And it seems there is no record of transaction being received by the bitcoind in p2p port.. The debug log is pasted here https://hackmd.io/@raj/HyKH0tgZi
You can search for net logging, and can verify that there isn't any record of receiving anything through the network. Yet it successfully added a peer connection with the nakamoto client. 2022-09-15T11:17:20Z connection from 127.0.0.1:51678 accepted in debug log..

Conclusion:

For some reason transactions being sent by nakamoto to p2p network isn't being registered by bitcoin core.. I tried to debug as much as possible inside nakamoto, but everything seems to be working as intended.. Any help regarding this would be much appreciated..

Thanks for the issue, will look into this.

Thanks @cloudhead , but I don't think that's the problem.. After some more debugging it seems everything in nakamoto is working as expected. The issue is arising due to following reason.

  • When we submit_transaction nakamoto announces an inv message to the peer.
  • If the peer doesn't have this transaction it asks for it via getdata.
  • Nakamoto responds back with getdata.

This back and forth of p2p communication takes some time to complete.. So I successfully managed to get the transaction in mempool just by simply waiting for it.

But now I am seeing a different issue.. The first broadcasts to mempool insertion is quite fast, but it slows down progressively as we have more broadcast calls. This is weird.. And I timed it by a simple broadcast loop of sequentially broadcasting a chain of related transaction and wait until they are found in peer's mempool.

Observation:

Transaction takes longer time to get in mempool in subsequent calls.. Heres the output for first 3 transactions in the chain

Broadcasting txid : 8b101a43a034a4006b114c9ca0b0b03c128894dc0edb65c5d8b64c091a0820e5
Got it in mempool after : 5secs
Broadcasting txid : 7e7b614f956afd91b6d0460826e07d1be8c63540c391cfd0c3250e9607999e2c
Got it in mempool after : 60secs
Broadcasting txid : d009dd5e5e7d6e1ba9f5723015c17ed3f32269a099759e5ba1a0c7cddd445da3
Got it in mempool after : 65secs
Broadcasting txid : 55d3c2eb56cc82615a4cd55c3e632f3fe99543ed6d333122253b6fe17ca0770e

The fourth transaction 55d3c2eb56cc82615a4cd55c3e632f3fe99543ed6d333122253b6fe17ca0770e got in the broadcast call, but never got into mempool.. I waited for an hour..

Not only that, for first three, the communication logs with core is quite instantaneous. The time for core to get the inv message, then ask with getdata, and finally getting the full transaction in mempool is quite fast and sequential..

2022-09-23T16:38:47Z received: inv (73 bytes) peer=0
2022-09-23T16:38:47Z got inv: wtx f514cd09b7879d39a03e437241b7eae4aa6f4c2b07a354a7bdde2b01488c717c  new peer=0
2022-09-23T16:38:49Z Requesting wtx f514cd09b7879d39a03e437241b7eae4aa6f4c2b07a354a7bdde2b01488c717c peer=0
2022-09-23T16:38:49Z sending getdata (37 bytes) peer=0
2022-09-23T16:38:49Z received: tx (222 bytes) peer=0
2022-09-23T16:38:49Z Checking mempool with 2 transactions and 2 inputs
2022-09-23T16:38:49Z AcceptToMemoryPool: peer=0: accepted 8b101a43a034a4006b114c9ca0b0b03c128894dc0edb65c5d8b64c091a0820e5 (poolsz 2 txn, 2 kB)

From the time stamps its clear the whole process took less than a minute to finish..

The 4th transaction never got inv announced.. The log in core is clear with no network update after the 3rd broadcast..

So I am inclining to make the following observation about nakamoto's broadcast logic.

  • Something is delaying the inv announcement inside nakamoto. The inv doesn't go out immediately after calling submit_transaction. It takes some time..
  • This time delay progressively increases.
  • Eventually the delay becomes so big that the inv never gets announced.

So if you have any idea or suggestion regarding this, or any more direction to debug that would be very helpful..

Thanks for the detailed report. Is the above with the cloudhead/remove-needless-rate-limit branch or not? It's exactly the type of thing that would be delaying inv broadcasts. If it is, I'll take another look at the broadcast logic.

The inventory re-broadcast timeout is exactly 60 seconds, so I think that's what we're seeing. Perhaps there is a bug there.

Okay, I've made another small change to the branch, found in f0788b0, that might help situations where txs are queued. I'll try to reproduce the issue as well, but it would help if you tried this recent change.

Is the above with the cloudhead/remove-needless-rate-limit branch or not?

Yes it was with the above branch..

Okay, I've made another small change to the branch, found in f0788b0, that might help situations where txs are queued.

Thanks I will try with this and report back..

Great news @cloudhead .. It worked.. ๐Ÿš€ Thanks for the help.. I think we need to get the changes in master too.. I am very close to completing the rest of the integration.. Closing this issue on that note..

Amazing, will merge.