Reliability improvements: UTXO chaining breaks after miner commitments miss intended burnchain block

[friedger]

Describe the bug
Burn values for 1K1rSXoxAaJPQdWpm6XgZ6xwzkikxmWonW are 1 even though the miner is burning regularly.

666656 most_recent_burn: 205000, median_burn: 102500, all_burns: [1, 1, 1, 205000, 205000, 205000]
666655 most_recent_burn: 205000, median_burn: 1, all_burns: [1, 1, 1, 1, 205000, 205000]
666655 BlockCommitNoParent
666652 most_recent_burn: 205000, median_burn: 102500, all_burns: [1, 1, 1, 205000, 205000, 205000]
666651 most_recent_burn: 205000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 205000]
666650 most_recent_burn: 205000, median_burn: 1, all_burns: [1, 1, 1, 1, 205000, 205000]
666649 BlockCommitNoParent
666649 most_recent_burn: 205000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 205000]
666646 most_recent_burn: 205000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 205000]
666644 leader key register 

Another example:
Take an example where there were two adjacent stacks blocks that were mined by exactly the same participants. Blocks 449 and 450. 449 was mined on burn block 666652 and 450 off 666655
53 and 54 were skipped for whatever reason

The sortition playing field for block 449 looks like this

222k miner is the winner here
the rest of the field looks pretty healthy contribution wise at this point
we then skip blocks #666653 #666654
and this is the field for the next block

same participation as the prev block, but apart from the leader of the previous block everyone else has had their commit history truncated back to 1

Stacks dump:

Expected behavior

666652 most_recent_burn: 205000, median_burn: **205000**, all_burns: [1, 1, **205000**, 205000, 205000, 205000]
666651 most_recent_burn: 205000, median_burn: **102500**, all_burns: [1, 1, 1, **205000**, **205000**, 205000]
666650 most_recent_burn: 205000, median_burn: 1, all_burns: [1, 1, 1, 1, 205000, 205000]
666649 BlockCommitNoParent
666649 most_recent_burn: 205000, median_burn: 1, all_burns: [1, 1, **20500**, 1, 1, 205000]
666646 most_recent_burn: 205000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 205000]
666644 leader key register 

** Additional context**

stacks:~/programs/stacks-2.0.1$ grep b5c38f0bd79fb3763390cad6a1656947b67b503df5955812c050108673e87849 miner.log 
DEBG [1611006617.876020] [src/chainstate/burn/distribution.rs:288] [chains-coordinator] Burn sample, txid: b5c38f0bd79fb3763390cad6a1656947b67b503df5955812c050108673e87849, most_recent_burn: 205000, median_burn: 102500, all_burns: [1, 1, 1, 205000, 205000, 205000]
INFO [1611006617.935554] [src/chainstate/burn/db/sortdb.rs:3358] [chains-coordinator] ACCEPTED(666656) leader block commit b5c38f0bd79fb3763390cad6a1656947b67b503df5955812c050108673e87849 at 666656,591

stacks:~/programs/stacks-2.0.1$ grep 02d54f340f875f4b0a37294ca591c8cb9f280be7fdc3ae269bceb5358a173be4  miner.log 
DEBG [1611004572.708293] [src/chainstate/burn/distribution.rs:288] [chains-coordinator] Burn sample, txid: 02d54f340f875f4b0a37294ca591c8cb9f280be7fdc3ae269bceb5358a173be4, most_recent_burn: 205000, median_burn: 1, all_burns: [1, 1, 1, 1, 205000, 205000]
INFO [1611004572.755955] [src/chainstate/burn/db/sortdb.rs:3358] [chains-coordinator] ACCEPTED(666655) leader block commit 02d54f340f875f4b0a37294ca591c8cb9f280be7fdc3ae269bceb5358a173be4 at 666655,412

stacks:~/programs/stacks-2.0.1$ grep 860e71e0fce0dd8f313fe710c5b0babbb691418b83c01e87a703653e4573f30c  miner.log 
WARN [1611004572.674936] [src/chainstate/burn/db/processing.rs:66] [chains-coordinator] REJECTED(666655) leader block commit 860e71e0fce0dd8f313fe710c5b0babbb691418b83c01e87a703653e4573f30c at 666655,666: BlockCommitNoParent

stacks:~/programs/stacks-2.0.1$ grep f953425f8a9649ccc64046e2c19ca85ae092d7e6f1abfc59d669b580ee9823f6  miner.log 
DEBG [1611003354.095299] [src/chainstate/burn/distribution.rs:288] [chains-coordinator] Burn sample, txid: f953425f8a9649ccc64046e2c19ca85ae092d7e6f1abfc59d669b580ee9823f6, most_recent_burn: 205000, median_burn: 102500, all_burns: [1, 1, 1, 205000, 205000, 205000]
INFO [1611003354.144981] [src/chainstate/burn/db/sortdb.rs:3358] [chains-coordinator] ACCEPTED(666652) leader block commit f953425f8a9649ccc64046e2c19ca85ae092d7e6f1abfc59d669b580ee9823f6 at 666652,445

stacks:~/programs/stacks-2.0.1$ grep a533b5670e99b28b9193f834a2f04074e410fd747c81897db11a6fc1337cfe6c miner.log  
DEBG [1611002220.456359] [src/chainstate/burn/distribution.rs:288] [chains-coordinator] Burn sample, txid: a533b5670e99b28b9193f834a2f04074e410fd747c81897db11a6fc1337cfe6c, most_recent_burn: 205000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 205000]
INFO [1611002220.494951] [src/chainstate/burn/db/sortdb.rs:3358] [chains-coordinator] ACCEPTED(666651) leader block commit a533b5670e99b28b9193f834a2f04074e410fd747c81897db11a6fc1337cfe6c at 666651,102

stacks:~/programs/stacks-2.0.1$ grep 0d4b9435eb896127a8c2ee5a36117a236a4f3406c86889a0034b5078f5eeedad  miner.log 
DEBG [1611002067.812064] [src/chainstate/burn/distribution.rs:288] [chains-coordinator] Burn sample, txid: 0d4b9435eb896127a8c2ee5a36117a236a4f3406c86889a0034b5078f5eeedad, most_recent_burn: 205000, median_burn: 1, all_burns: [1, 1, 1, 1, 205000, 205000]
INFO [1611002067.860139] [src/chainstate/burn/db/sortdb.rs:3358] [chains-coordinator] ACCEPTED(666650) leader block commit 0d4b9435eb896127a8c2ee5a36117a236a4f3406c86889a0034b5078f5eeedad at 666650,812

stacks:~/programs/stacks-2.0.1$ grep 76edabd3c7454910db6864168f8f857a84468151e51b6f61ecbc23984e0d8ee1  miner.log 
WARN [1610999671.503027] [src/chainstate/burn/db/processing.rs:66] [chains-coordinator] REJECTED(666649) leader block commit 76edabd3c7454910db6864168f8f857a84468151e51b6f61ecbc23984e0d8ee1 at 666649,1408: BlockCommitNoParent

stacks:~/programs/stacks-2.0.1$ grep c2bebf1334edf72e7c6d5835edd9714b591a635b2e2ebd0e15c5a7356cd909f2 miner.log 
DEBG [1610999671.527261] [src/chainstate/burn/distribution.rs:288] [chains-coordinator] Burn sample, txid: c2bebf1334edf72e7c6d5835edd9714b591a635b2e2ebd0e15c5a7356cd909f2, most_recent_burn: 205000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 205000]
INFO [1610999671.574769] [src/chainstate/burn/db/sortdb.rs:3358] [chains-coordinator] ACCEPTED(666649) leader block commit c2bebf1334edf72e7c6d5835edd9714b591a635b2e2ebd0e15c5a7356cd909f2 at 666649,860

stacks:~/programs/stacks-2.0.1$ grep 4090349295a7ee4b5a935020a79cea58c663c73b22458e4e9eeba9ab2b2b62df miner.log 
DEBG [1610997454.742286] [src/chainstate/burn/distribution.rs:288] [chains-coordinator] Burn sample, txid: 4090349295a7ee4b5a935020a79cea58c663c73b22458e4e9eeba9ab2b2b62df, most_recent_burn: 205000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 205000]
INFO [1610997454.782022] [src/chainstate/burn/db/sortdb.rs:3358] [chains-coordinator] ACCEPTED(666646) leader block commit 4090349295a7ee4b5a935020a79cea58c663c73b22458e4e9eeba9ab2b2b62df at 666646,704

stacks:~/programs/stacks-2.0.1$ grep 07c9d99d21ba6c4c3978b7365e2b120945983cd5837423296b71e4c208ae7dea miner.log 
INFO [1610996098.559753] [src/chainstate/burn/db/sortdb.rs:3351] [chains-coordinator] ACCEPTED(666644) leader key register 07c9d99d21ba6c4c3978b7365e2b120945983cd5837423296b71e4c208ae7dea at 666644,276

stacks:~/programs/stacks-2.0.1$ grep fd47afb9c8e8b165d3649760272efb84e0425b66413863e61d85625ccfa37fb2 miner.log 
DEBG [1610995142.087068] [src/chainstate/burn/distribution.rs:288] [chains-coordinator] Burn sample, txid: fd47afb9c8e8b165d3649760272efb84e0425b66413863e61d85625ccfa37fb2, most_recent_burn: 77776, median_burn: 77776, all_burns: [77776, 77776, 77776, 77776, 77776, 77776]
INFO [1610995142.128939] [src/chainstate/burn/db/sortdb.rs:3358] [chains-coordinator] ACCEPTED(666641) leader block commit fd47afb9c8e8b165d3649760272efb84e0425b66413863e61d85625ccfa37fb2 at 666641,228

stacks:~/programs/stacks-2.0.1$ grep 30e41d660c0bd615382a81111d3f5e4b1fa33550185effc620d9b726a50dc534  miner.log 
DEBG [1610993167.229839] [src/chainstate/burn/distribution.rs:288] [chains-coordinator] Burn sample, txid: 30e41d660c0bd615382a81111d3f5e4b1fa33550185effc620d9b726a50dc534, most_recent_burn: 77776, median_burn: 77776, all_burns: [77776, 77776, 77776, 77776, 77776, 77776]
INFO [1610993167.300835] [src/chainstate/burn/db/sortdb.rs:3358] [chains-coordinator] ACCEPTED(666640) leader block commit 30e41d660c0bd615382a81111d3f5e4b1fa33550185effc620d9b726a50dc534 at 666640,20

[friedger]

The smoothing function is only taking the commits from the canonical fork, not from the bitcoin chain. So, different burn values are expected on different branches/forks.

[kantai]

There's two things at work here, the second of which is, I believe, a bug --

First, miner commitment windows are evaluated by Bitcoin block (not Stacks block), so when miners skip mining in a block, the consequence is that the commitments won't get counted for that block. In the example block 666655:

The node only detects two transactions from that Bitcoin block having any history of burns in that window, blocks in the range (666655-666650]:

1. a637ac4026d107fd8787163ca25781a92921eef64e8a71720cd383202cf97abb -- 3 prior burns
   • ab68292dbf7282cb4f5646ab34d3d5e4eeb0e2087d9ebae219c9d4a69d887127: in block 666652
   • 183f8af604f4399a03d56feb736c816478241d391e0dbb5e1f4fd49aa726dac1: in block 666651
   • b932d1cb1ca1ef0f344327d49baa44523280c1edf4ea0b3f763aeaacf2fbd0f8: in block 666650
   • So for the window, this txid correctly has 4 commits of 200,000 sats, and 2 "empty" commits
2. 02d54f340f875f4b0a37294ca591c8cb9f280be7fdc3ae269bceb5358a173be4 -- 1 prior burn
   • a533b5670e99b28b9193f834a2f04074e410fd747c81897db11a6fc1337cfe6c: in block 666651
   • So for the window, this txid correctly has 2 non-empty commits, and 4 "empty" commits

The second issue at work in that block, which I believe is a bug, is that in order to evaluate a mining window, the stacks-node needs to be able to associate each commit with that miner's previous commits. To do this it uses UTXO chaining. However, the stacks-node only tracks UTXOs for valid Bitcoin operations. That means if the previous commit was an invalid commitment, it wouldn't normally be tracked. However, #2177 attempted to address this by allowing missed commits to still be tracked and therefore the "chain" of UTXOs not to be dropped.

Unfortunately, it seems like there is a bug in this handling of MissedBlockCommits (https://github.com/blockstack/stacks-blockchain/blob/master/src/chainstate/burn/operations/leader_block_commit.rs#L687) uses the absolute intended burn height, whereas it should use the relative burn height (i.e., burn_height - FIRST_BURN_HEIGHT). The consequence of this issue is that UTXO chains are not preserved when a commitment is broadcasted in the "wrong" bitcoin block.

[friedger]

As a consequence bitcoin miners can delay a commit tx and thereby reset the stacks miners probability to win.

[lgalabru]

#2383 should be limiting the impact of that bug

[MaksimalistT]

Hi, @jcnelson, @kantai
is there any settings in configuration options for stacks-node (2.0.11.2.0) that will potentially reduce number of invalid block commits? i can see some miners is getting invalid block commits much rearer than others, which is definitely not a random thing.

[jcnelson]

Try polling your bitcoin node more frequently. It's poll_time_secs under [burnchain].

[MaksimalistT]

Try polling your bitcoin node more frequently. It's poll_time_secs under [burnchain].

it is set to poll_time_secs = 1, is this value provide the most frequent polling?
is there anything else? can it be improved with bitcoin node config?

[jcnelson]

This is fixed in next