stacks-network / stacks-core

The Stacks blockchain implementation
https://docs.stacks.co
GNU General Public License v3.0
3.01k stars 664 forks source link

[TESTNET BUG] Some miners only mine every other blocks #1783

Closed psq closed 4 years ago

psq commented 4 years ago

While analyzing the blocks produced by the miners, I noticed that some miners were mining only every other block. For example, with the help of Discord, we have identified the miners from from phillip and @friedger were behaving that way. My miner has not exhibited this behavior, and this is still not clear to me why only some would behave that way (maybe the fact that they are both on different continents may be a factor...).

From the logs (from @friedger, but the logs from phillip look similar), we see the following (excerpt with the relevant bits around the start of each new block):

# 1
DEBUG [1596103298.523] [testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs:792] [ThreadId(6)] BitcoinRPC builder: None:None@http://35.221.35.47:18443/
INFO [1596103299.118] [testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs:328] [ThreadId(6)] Miner node: submitting leader_key_register op - 03aefb4c3b0584fae094e64c6903f81cac9355868542e8af0eb72919d513a5aa34
DEBUG [1596103299.119] [testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs:792] [ThreadId(6)] BitcoinRPC builder: None:None@http://35.221.35.47:18443/

# 2
DEBUG [1596103325.109] [testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs:792] [ThreadId(6)] BitcoinRPC builder: None:None@http://35.221.35.47:18443/
INFO [1596103325.704] [testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs:378] [ThreadId(6)] Miner node: submitting leader_block_commit op - 03aefb4c3b0584fae094e64c6903f81cac9355868542e8af0eb72919d513a5aa34
DEBUG [1596103325.705] [testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs:792] [ThreadId(6)] BitcoinRPC builder: None:None@http://35.221.35.47:18443/
DEBUG [1596103325.921] [testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs:792] [ThreadId(6)] BitcoinRPC builder: None:None@http://35.221.35.47:18443/
DEBUG [1596103326.330] [testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs:792] [ThreadId(6)] BitcoinRPC builder: None:None@http://35.221.35.47:18443/
DEBUG [1596103327.546] [testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs:792] [ThreadId(6)] BitcoinRPC builder: None:None@http://35.221.35.47:18443/
DEBUG [1596103327.927] [testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs:392] [ThreadId(6)] No UTXOs for 03aefb4c3b0584fae094e64c6903f81cac9355868542e8af0eb72919d513a5aa34

# 3
DEBUG [1596103356.573] [testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs:792] [ThreadId(6)] BitcoinRPC builder: None:None@http://35.221.35.47:18443/
INFO [1596103357.197] [testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs:328] [ThreadId(6)] Miner node: submitting leader_key_register op - 03aefb4c3b0584fae094e64c6903f81cac9355868542e8af0eb72919d513a5aa34
DEBUG [1596103357.199] [testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs:792] [ThreadId(6)] BitcoinRPC builder: None:None@http://35.221.35.47:18443/

# 4
DEBUG [1596103388.862] [testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs:792] [ThreadId(6)] BitcoinRPC builder: None:None@http://35.221.35.47:18443/
INFO [1596103389.455] [testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs:378] [ThreadId(6)] Miner node: submitting leader_block_commit op - 03aefb4c3b0584fae094e64c6903f81cac9355868542e8af0eb72919d513a5aa34
DEBUG [1596103389.456] [testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs:792] [ThreadId(6)] BitcoinRPC builder: None:None@http://35.221.35.47:18443/
DEBUG [1596103389.670] [testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs:792] [ThreadId(6)] BitcoinRPC builder: None:None@http://35.221.35.47:18443/
DEBUG [1596103390.051] [testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs:792] [ThreadId(6)] BitcoinRPC builder: None:None@http://35.221.35.47:18443/
DEBUG [1596103396.134] [testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs:792] [ThreadId(6)] BitcoinRPC builder: None:None@http://35.221.35.47:18443/
DEBUG [1596103396.501] [testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs:392] [ThreadId(6)] No UTXOs for 03aefb4c3b0584fae094e64c6903f81cac9355868542e8af0eb72919d513a5aa34

# 5
DEBUG [1596103417.861] [testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs:792] [ThreadId(6)] BitcoinRPC builder: None:None@http://35.221.35.47:18443/
INFO [1596103418.463] [testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs:328] [ThreadId(6)] Miner node: submitting leader_key_register op - 03aefb4c3b0584fae094e64c6903f81cac9355868542e8af0eb72919d513a5aa34
DEBUG [1596103418.464] [testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs:792] [ThreadId(6)] BitcoinRPC builder: None:None@http://35.221.35.47:18443/

# 6
DEBUG [1596103445.135] [testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs:792] [ThreadId(6)] BitcoinRPC builder: None:None@http://35.221.35.47:18443/
INFO [1596103445.759] [testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs:378] [ThreadId(6)] Miner node: submitting leader_block_commit op - 03aefb4c3b0584fae094e64c6903f81cac9355868542e8af0eb72919d513a5aa34
DEBUG [1596103445.760] [testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs:792] [ThreadId(6)] BitcoinRPC builder: None:None@http://35.221.35.47:18443/
DEBUG [1596103445.986] [testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs:792] [ThreadId(6)] BitcoinRPC builder: None:None@http://35.221.35.47:18443/
DEBUG [1596103446.376] [testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs:792] [ThreadId(6)] BitcoinRPC builder: None:None@http://35.221.35.47:18443/
DEBUG [1596103452.218] [testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs:792] [ThreadId(6)] BitcoinRPC builder: None:None@http://35.221.35.47:18443/
DEBUG [1596103452.602] [testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs:392] [ThreadId(6)] No UTXOs for 03aefb4c3b0584fa

In #1 the miner registers a key. So far, so good

In #2, there was a key registered, so the node will commit a block:

DEBUG [1596103325.109] [testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs:792] [ThreadId(6)] BitcoinRPC builder: None:None@http://35.221.35.47:18443/
INFO [1596103325.704] [testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs:378] [ThreadId(6)] Miner node: submitting leader_block_commit op - 03aefb4c3b0584fae094e64c6903f81cac9355868542e8af0eb72919d513a5aa34
DEBUG [1596103325.705] [testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs:792] [ThreadId(6)] BitcoinRPC builder: None:None@http://35.221.35.47:18443/

the 2 calls to BitcoinRPC builder should be listunspent and sendrawtransaction

Then the miners tries to register a key for next block:

DEBUG [1596103325.921] [testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs:792] [ThreadId(6)] BitcoinRPC builder: None:None@http://35.221.35.47:18443/
DEBUG [1596103326.330] [testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs:792] [ThreadId(6)] BitcoinRPC builder: None:None@http://35.221.35.47:18443/
DEBUG [1596103327.546] [testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs:792] [ThreadId(6)] BitcoinRPC builder: None:None@http://35.221.35.47:18443/
DEBUG [1596103327.927] [testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs:392] [ThreadId(6)] No UTXOs for 03aefb4c3b0584fae094e64c6903f81cac9355868542e8af0eb72919d513a5aa34

but this fails because the node could not find UTXOs (spoiler alert, there are still some!). The 3 calls to BitcoinRPC builder should be respectively listunspent, importaddress, and listunspent (from https://github.com/blockstack/stacks-blockchain/blob/master/testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs#L206). Note that the the 3 calls can take up to 6-7 seconds (not visible in #2, but check #6).

So the above seems to explain why the node only mines every other blocks as the leader key registration fails every other time.

But now the question is: why do the UTXOs disappear?

My best theory so far is that spending some UTXOs for the commit transaction forces a rescan on the bitcoin node (an other possibility is that the utxos get kicked out of the cache), and even though get_utxos uses a sleep(1000) before the second call to listunspent, this does not seem to be enough, but 30 seconds later, when it is time to register a new key, the rescan has completed, and the node will find utxos.

Now one reason why the the rescan takes so long is that there are a lot of them after a miner has been mining for a while. In the case of @friedger when I queried the argon bitcoin node, there were about 3,400 and counting. Here are a few:

    {
      "txid": "b3906443a1795cfa6228325525d086287b6e42c2c82e249daebe73d1e3820100",
      "vout": 1,
      "address": "mmoSjCkyJFMRPPf9xriVbTAWF9jmALqekD",
      "label": "",
      "scriptPubKey": "76a91444ef2530c93d3b0196131fc365d6e5c4c86f1c9988ac",
      "amount": 0.00005500,
      "confirmations": 6909,
      "spendable": false,
      "solvable": false,
      "safe": true
    },
    {
      "txid": "247c1fde898bbaabcfd143bdfe4c4d847248aa57f8fd47243d20f1e350a40200",
      "vout": 1,
      "address": "mmoSjCkyJFMRPPf9xriVbTAWF9jmALqekD",
      "label": "",
      "scriptPubKey": "76a91444ef2530c93d3b0196131fc365d6e5c4c86f1c9988ac",
      "amount": 0.00005500,
      "confirmations": 1622,
      "spendable": false,
      "solvable": false,
      "safe": true
    },
    {
      "txid": "c760e0dfe8ea58f6200dea3edb9d7cd0fc32644e1b1c702b650f50b4969d0400",
      "vout": 1,
      "address": "mmoSjCkyJFMRPPf9xriVbTAWF9jmALqekD",
      "label": "",
      "scriptPubKey": "76a91444ef2530c93d3b0196131fc365d6e5c4c86f1c9988ac",
      "amount": 0.00005500,
      "confirmations": 10701,
      "spendable": false,
      "solvable": false,
      "safe": true
    },
    {
      "txid": "1353dca0ae6c32b0a130e3931252495cc864255b75984b63758fa8a8b4560600",
      "vout": 1,
      "address": "mmoSjCkyJFMRPPf9xriVbTAWF9jmALqekD",
      "label": "",
      "scriptPubKey": "76a91444ef2530c93d3b0196131fc365d6e5c4c86f1c9988ac",
      "amount": 0.00005500,
      "confirmations": 10045,
      "spendable": false,
      "solvable": false,
      "safe": true
    },
    {
      "txid": "229ac48eb5d4830c5fd806d01a078965b5f4933e44d5f751a36bab95b20e0e00",
      "vout": 1,
      "address": "mmoSjCkyJFMRPPf9xriVbTAWF9jmALqekD",
      "label": "",
      "scriptPubKey": "76a91444ef2530c93d3b0196131fc365d6e5c4c86f1c9988ac",
      "amount": 0.00005500,
      "confirmations": 7282,
      "spendable": false,
      "solvable": false,
      "safe": true
    },
    {
      "txid": "712add5f6986a4663fd67f985243cdab2caedce4e7062432a01482517af61500",
      "vout": 1,
      "address": "mmoSjCkyJFMRPPf9xriVbTAWF9jmALqekD",
      "label": "",
      "scriptPubKey": "76a91444ef2530c93d3b0196131fc365d6e5c4c86f1c9988ac",
      "amount": 0.00005500,
      "confirmations": 9808,
      "spendable": false,
      "solvable": false,
      "safe": true
    },
    {
      "txid": "93fa19f2b00d95fe9ead9f4f3b354b301262b22e81868c1b770812b404152b00",
      "vout": 1,
      "address": "mmoSjCkyJFMRPPf9xriVbTAWF9jmALqekD",
      "label": "",
      "scriptPubKey": "76a91444ef2530c93d3b0196131fc365d6e5c4c86f1c9988ac",
      "amount": 0.00005500,
      "confirmations": 6705,
      "spendable": false,
      "solvable": false,
      "safe": true
    },
    {
      "txid": "4a702bc5345073158197e7e05da3adff5b5c6f3f198623390bc5c5cbb8084700",
      "vout": 1,
      "address": "mmoSjCkyJFMRPPf9xriVbTAWF9jmALqekD",
      "label": "",
      "scriptPubKey": "76a91444ef2530c93d3b0196131fc365d6e5c4c86f1c9988ac",
      "amount": 0.00005500,
      "confirmations": 2363,
      "spendable": false,
      "solvable": false,
      "safe": true
    },
    {
      "txid": "d522fdb486114cc9a6e725858aa137e6d235cb01da3cf396aad94da4c5e75a00",
      "vout": 1,
      "address": "mmoSjCkyJFMRPPf9xriVbTAWF9jmALqekD",
      "label": "",
      "scriptPubKey": "76a91444ef2530c93d3b0196131fc365d6e5c4c86f1c9988ac",
      "amount": 0.00005500,
      "confirmations": 2654,
      "spendable": false,
      "solvable": false,
      "safe": true
    },
    {
      "txid": "6278964194504d6b91dcd82786c6833d2598b3f58f2c67cc6464e5e7d4fd6300",
      "vout": 1,
      "address": "mmoSjCkyJFMRPPf9xriVbTAWF9jmALqekD",
      "label": "",
      "scriptPubKey": "76a91444ef2530c93d3b0196131fc365d6e5c4c86f1c9988ac",
      "amount": 0.00005500,
      "confirmations": 1510,
      "spendable": false,
      "solvable": false,
      "safe": true
    },
    {
      "txid": "0e0419f29b7b06a52cb89fc15b905cd4a27cd726e8405f02ccb1347114466400",
      "vout": 1,
      "address": "mmoSjCkyJFMRPPf9xriVbTAWF9jmALqekD",
      "label": "",
      "scriptPubKey": "76a91444ef2530c93d3b0196131fc365d6e5c4c86f1c9988ac",
      "amount": 0.00005500,
      "confirmations": 3886,
      "spendable": false,
      "solvable": false,
      "safe": true
    },
    {
      "txid": "4643f06b7ba57319908a046ec00607c860f8f8ffcc3a829ed0b95c1d1e907000",
      "vout": 1,
      "address": "mmoSjCkyJFMRPPf9xriVbTAWF9jmALqekD",
      "label": "",
      "scriptPubKey": "76a91444ef2530c93d3b0196131fc365d6e5c4c86f1c9988ac",
      "amount": 0.00005500,
      "confirmations": 3725,
      "spendable": false,
      "solvable": false,
      "safe": true
    },
    {
      "txid": "c2cb2ea5b69f868728860bace9e466daaad6f0c5e5d6b5b8d46b4653618e8600",
      "vout": 1,
      "address": "mmoSjCkyJFMRPPf9xriVbTAWF9jmALqekD",
      "label": "",
      "scriptPubKey": "76a91444ef2530c93d3b0196131fc365d6e5c4c86f1c9988ac",
      "amount": 0.00005500,
      "confirmations": 1574,
      "spendable": false,
      "solvable": false,
      "safe": true
    },
    {
      "txid": "49a8b7e20151c50a230871fdfc0e33133f2ccdba91a8ff74f98d92d75e028700",
      "vout": 1,
      "address": "mmoSjCkyJFMRPPf9xriVbTAWF9jmALqekD",
      "label": "",
      "scriptPubKey": "76a91444ef2530c93d3b0196131fc365d6e5c4c86f1c9988ac",
      "amount": 0.00005500,
      "confirmations": 9410,
      "spendable": false,
      "solvable": false,
      "safe": true
    },

Only 1 of them meets the requirement (> 11000 sat). My current thinking is that the miner's code should more judiciously reuse small utxos (created by the key registration transaction) instead of looking for the first utxo with sufficient balance (https://github.com/blockstack/stacks-blockchain/blob/master/testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs#L860).

One possibility might be to use the amount the node plans to burn on the next round for the tx amount rather than 5500 so that utxo can be reused, or transfer the whole utxo amount minus the fee (no change output required means smaller transaction)) to avoid creating all these tiny utxos.

I would not suggest combining more than 1 input to meet the amount required, this would make the transaction bigger.

If my theory is close to correct, the fix should be fairly simple...

jcnelson commented 4 years ago

Thank you so much for taking a deep look at this @psq @friedger!

Fundamentally, the reason why a LeaderKeyRegisterOp Bitcoin transaction creates a UTXO with 5500 sats is because it needs to register a Bitcoin address with the Stacks node that will be paired with a corresponding LeaderBlockCommitOp. The LeaderBlockCommitOp "consumes" an associated LeaderKeyRegisterOp in that one of its inputs must have a scriptSig that matches the second scriptPubKey output of the LeaderKeyRegisterOp (i.e. the first non-OP_RETURN output). This check ensures that the principal who can use the VRF public key to produce a VRF proof and VRF seed as part of a block-commit can only have been the same principal who registered the VRF public key in the first place. But, implementing this check currently creates a "dust" UTXO output each time a VRF public key is registered, leading to this problem.

There's a couple ways I think we could fix this:

Related, I welcome any thoughts and opinions on #1615. It's a consensus-breaking change.

paradigma-cl commented 4 years ago

@psq @jcnelson Here in Github I am (Phillip) called @paradigma-cl . I am glad that our remote mining nodes can serve for testing! I will put a couple more in operation, to help to create more massivity of nodes mining.

psq commented 4 years ago

Make the Bitcoin UTXO scanner remember the UTXOs it creates. Then, when it goes to produce a new Bitcoin transaction, it will try to reuse a known UTXO instead of ask the Bitcoin node to re-scan each time

one can assume that a miner would use an address exclusively for mining, so yes, you probably wouldn't need to re-query the bitcoin node for available UTXOs as often, or just during startup, and instead make it a requirement. Furthermore, even if you can't keep reusing the same UTXO back to back to register a new key, 2 should be enough, and you could keep switching between the 2 (register UTXO1, commit with UTXO1/register using UTXO2, commit with UTXO2/register using UTXO1, commit with UTXO1/register using UTXO2...), which would keep the number of UTXOs needed to a minimum.

The JSON reply for listunspent in @friedger case was well over 1MB!

from #1615: since only the principal who has the VRF private key can produce a valid Stacks block

Intuitively, I had a feeling that this statement would apply, removing the need for registering a new key for each block, and glad to see it expressed in #1615 (I had not read it previously).

I will mull over #1615, as this would certainly help reduce the amount of fees for each block, and cut down on network usage. In fact, I think this is a must, as this would shave off about 40% of the bitcoin fee per block.

psq commented 4 years ago

I am (Phillip) called @paradigma-cl

good to know, @paradigma-cl, as I almost unknowingly spammed an unsuspecting @ phillip on github, and thank you for your help!

diwakergupta commented 4 years ago

@psq can you verify if this is still an issue after your fix for #1615 and close or update as appropriate?

psq commented 4 years ago

@diwakergupta this can't happen anymore because once a key is registered, there's always going to be a key available to send a commit.