Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Multiple commits for btc block, missed target block #2969

Closed
MaksimalistT opened this issue Dec 12, 2021 · 10 comments
Closed

Multiple commits for btc block, missed target block #2969

MaksimalistT opened this issue Dec 12, 2021 · 10 comments
Labels
locked

Comments

@MaksimalistT
Copy link

Describe the bug
Multiple commits for series of btc blocks detected, missed target block
https://btc.com/btc/transaction/10d26d88f6d2fd18e1b593b74c99886b8da5519ac4b5fd36035043e44ee26345
https://btc.com/btc/transaction/02740d28e351394ce7dac1f7440c59e69d5544ebe3f05f65870f24d7033d3aaf
https://btc.com/btc/transaction/99e7e232c915b120d7d553c92a46f7366d8cd2747db893b53e5c3685d78bcff3
https://btc.com/btc/transaction/7daf7a50fb69abd7c0c3ff2558bc627c9579c246f42c721297680a52184ebd18
https://btc.com/btc/transaction/15643a45ac954a88c11e8d80e76752226fd5dae56ac3698290393a8b67a6f5ff
https://btc.com/btc/transaction/d5dafd4661c4fb3a5bdf8f15f13420193abf6e102b1c657464f7309cceee346b
https://btc.com/btc/transaction/97383a59e877a537d19fbb7b6f4bdc143f98dbf2ab0f0bc47ab4bb09f2cff4ad
https://btc.com/btc/transaction/a264a1508bf1f89bdc2f989d2eb686b968db2b2c7ea07ed023834b35f6a7787b
https://btc.com/btc/transaction/01d6169694017c48b1b6495f91c5b3f3fcd000419812e769f7f26536400dcd6d
https://btc.com/btc/transaction/1ae5682ff9346234c1cb1928999d6b684f393fd24cec826fec4f3b59043d96f9

logs attached, can't provide full debug log

Steps To Reproduce
no info

Expected behavior
one commit per block

Environment (please complete the following information):

  • OS: Amazon Linux
  • Rust version: rustc 1.49.0 (e1884a8e3 2020-12-29)
  • Stacks-node 2.05.0.0.0

Additional context
multiple_commits_main.log
@jcnelson
Copy link
Member

Yup, looks like a bug:

INFO [1639286229.697231] [testnet/stacks-node/src/neon_node.rs:1930] [relayer] Succeeded assembling Stacks block #41217: beb76f416f8a6747d9dda5a2c580f2c425fb5a5f3417159a50dec480e2e944f9, with 1 txs, attempt 1
INFO [1639286233.402615] [testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs:1007] [relayer] Miner node: submitting leader_block_commit (txid: 10d26d88f6d2fd18e1b593b74c99886b8da5519ac4b5fd36035043e44ee26345, rbf: false, total spent: 335264, size: 348, fee_rate: 18)
INFO [1639286335.879389] [testnet/stacks-node/src/neon_node.rs:1930] [relayer] Succeeded assembling Stacks block #41217: 7d526456f0c720ef4e1caa8001bc7c93939ae3c66b490ccec74cbcb894209ba5, with 363 txs, attempt 2
INFO [1639286338.299153] [testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs:1007] [relayer] Miner node: submitting leader_block_commit (txid: 02740d28e351394ce7dac1f7440c59e69d5544ebe3f05f65870f24d7033d3aaf, rbf: false, total spent: 335246, size: 347, fee_rate: 18)
INFO [1639286447.532090] [testnet/stacks-node/src/neon_node.rs:1930] [relayer] Succeeded assembling Stacks block #41217: 9c962cc667d1b02ce61d66335b818c12040515382f56aa48aabc208f6284a516, with 365 txs, attempt 3
INFO [1639286449.898905] [testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs:1007] [relayer] Miner node: submitting leader_block_commit (txid: 99e7e232c915b120d7d553c92a46f7366d8cd2747db893b53e5c3685d78bcff3, rbf: false, total spent: 335246, size: 347, fee_rate: 18)
INFO [1639286554.384621] [testnet/stacks-node/src/neon_node.rs:1930] [relayer] Succeeded assembling Stacks block #41217: 45e3e27bfc30fd17228ef7ddd4ee2fa10cfaff89d44d4ebb0d95d9de4bb3b3d2, with 366 txs, attempt 4
INFO [1639286556.758778] [testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs:1007] [relayer] Miner node: submitting leader_block_commit (txid: 70d79d37eef0837ea98b701c2d1bcb26a30d975414465b0cbb64a7db9c68ed64, rbf: false, total spent: 335246, size: 347, fee_rate: 18)
INFO [1639286662.721877] [testnet/stacks-node/src/neon_node.rs:1930] [relayer] Succeeded assembling Stacks block #41217: 9af44b5bca0707457528cf5ab8937a70204fb61214a40acdac30a25d4fc4b8d0, with 368 txs, attempt 5
INFO [1639286665.087602] [testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs:1007] [relayer] Miner node: submitting leader_block_commit (txid: d60eaafeceda981a242b9d8b69c3f206a9ea2d90973300410d49707147d28ba7, rbf: false, total spent: 335246, size: 347, fee_rate: 18)

The miner should be RBF'ing its in-flight block-commits, or if it can't for some reason, then it should not attempt to mine again.

@MaksimalistT
Copy link
Author

Hi, @jcnelson, @diwakergupta
we need to fix this as soon as possible, as miners are losing money whenever the bug occurs
thanks

@jcnelson
Copy link
Member

We're working on it, and PRs are welcome. Looking at these transactions, the node is trying to spend different UTXOs for each attempted block-commit. One remediation you can take is to consolidate your UTXOs into a single UTXO, which would prevent this from happening.

@jcnelson
Copy link
Member

Does this show up in your logs anywhere?

Attempt to submit another leader_block_commit, despite an ongoing (outdated) commit

Some background (cc @lgalabru who wrote this): the miner will make multiple attempts to mine a Stacks block during a Bitcoin block, and will do so even if it can't RBF. This is by design, per the following rules:

        // An ongoing operation is in the mempool and we received a new block. The desired behaviour is the following:
        // 1) If the ongoing and the incoming operation are **strictly** identical, we will be idempotent and discard the incoming.
        // 2) If the 2 operations are different, we will try to avoid wasting UTXOs, and attempt to RBF the outgoing transaction:
        //  i) If UTXOs are insufficient,
        //    a) If no other UTXOs, we'll have to wait on the ongoing operation to be mined before resuming operation.
        //    b) If we have some other UTXOs, drop the ongoing operation, and track the new one.
        //  ii) If UTXOs initially used are sufficient for paying for a fee bump, then RBF

You might be hitting case 2(i)(b), in which case, the miner will send multiple block-commits with different UTXOs. The presence of the above log line in your logfile will indicate this.

A question for @lgalabru is whether or not this case is one we should support, if it's going to cause problems like this in practice. Perhaps there should be a config option that disables case 2(i)(b) by default?

@MaksimalistT
Copy link
Author

Does this show up in your logs anywhere?

Attempt to submit another leader_block_commit, despite an ongoing (outdated) commit

no there isn't

Some background (cc @lgalabru who wrote this): the miner will make multiple attempts to mine a Stacks block during a Bitcoin block, and will do so even if it can't RBF. This is by design, per the following rules:

        // An ongoing operation is in the mempool and we received a new block. The desired behaviour is the following:
        // 1) If the ongoing and the incoming operation are **strictly** identical, we will be idempotent and discard the incoming.
        // 2) If the 2 operations are different, we will try to avoid wasting UTXOs, and attempt to RBF the outgoing transaction:
        //  i) If UTXOs are insufficient,
        //    a) If no other UTXOs, we'll have to wait on the ongoing operation to be mined before resuming operation.
        //    b) If we have some other UTXOs, drop the ongoing operation, and track the new one.
        //  ii) If UTXOs initially used are sufficient for paying for a fee bump, then RBF

You might be hitting case 2(i)(b), in which case, the miner will send multiple block-commits with different UTXOs. The presence of the above log line in your logfile will indicate this.

A question for @lgalabru is whether or not this case is one we should support, if it's going to cause problems like this in practice. Perhaps there should be a config option that disables case 2(i)(b) by default?

i am pretty sure that at the moment of the bug there was no other UTXO sufficient to make a tx

@MaksimalistT
Copy link
Author

MaksimalistT commented Dec 17, 2021 •
edited
Loading

Issue occurred again, there is only one UTXO in the wallet
here is the list of all txs

DEBG [1639705749.602731] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: 16363940a506354938dac71a6c05c5a19ca9f0a3800d1e685e3e76e1a98dd955, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639705749.602749] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: 2b8e986133dc3ff7c6dfc05cc137f84c0e5c69150d0aa59dc4f7b70964e8b2dd, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639705749.602759] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: ec29671a0649ee23e67f69f46b8bc98c8edf73b3b7c2fee1f63b65162ed3f975, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639705749.602775] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: 7de0918c44a95991e32f8004997ae83b11786bd1f1f1fbf5c575f337599d4c32, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639705749.602787] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: cec09e803b939dd3f9c7adc035c184e705e01868b2e24060fad50b2e55d435f9, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639705749.602797] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: a5ac21cf8f2c23e19c232500f00c0ef32bab2c801e2f34795f5e6c434b8fd4ab, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639705749.602807] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: a2d15fbdbd2ba947075dcf78b12273d9666c9e908a85c35a54a555396eb2410c, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639705749.602826] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: 9e93307916d885c43a8cd4b97b75b7c5e3c068836194e5f87f88b9eee35a5d59, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639705749.602837] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: 3a88cb01b4156bc9a1d148199b4a42d98211a412924fba3d1eea7db2fabd213e, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639705749.602847] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: b876b0466531cac393346b3790daa394c58b144f21562a3a36ce2998c3572c17, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639705749.602856] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: a0b53b3add746856324f44ac81daf8ba6990777dd4fad1340c97bd725aca2637, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639705950.728333] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: 190330af326b7de0e140ae8f01e1941baa4da426058edb6082022ad55d8c132b, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639705950.728344] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: c81b63e5a0cd6641faa016ab654ebeea96082043ead06409a9c33ea3820f9351, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639706309.412651] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: f8b9810dea9b6689729ec374a28374734268b285518a6d47df6cb34500a746eb, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639706309.412659] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: 8a1570ad9271c0ff50c33f3719b2d9743cd0ca9d3fcbf1002cdb36748319c4e4, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639706309.412670] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: 6996711aa2a8690aa25e464361fee7c69f45852856637aa8886f534564b0971d, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639707414.865246] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: 66dbdd850a0340b1270a2e54100c6fd31fd8d845c8cb3a9932b00580749f0bff, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639707414.865257] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: 02878399cca1d96f0770b6741f737e3407d620e36b74b8f65cf8579c9a7e0719, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639707414.865267] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: a83a11cbb8ccc1b1740ee79683cfa92960616b30a301b343cb312430a191970f, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639707414.865282] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: 45780999202126da9014ecb8340cc984d056095142a89aa3d158b296ce168bf6, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639707414.865292] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: e5791d6e946ab07064721dad20312782c5dcf11f44900f0c172b3f8ec3d6e9fc, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639707414.865302] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: 2f096f63332f17cb040072e5cb457e7ef80fa052d39f0e799b06765674fb1ded, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639707414.865312] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: f52f7d18f1a5f5c8b5a36af301d2e5eeb63cc19f39c091c3c8079a4202ee7202, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639707414.865322] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: 6ad7370211c856c49405ada568b75e89444afd34172d00bfe74ba56d398641c5, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639707414.865332] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: 858290598bfee95efce60eb02bd439fd305d66c856c8bb74714aed06b69d5284, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639707414.865343] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: 0e7a020a6b45a128c7c8d0e257176444660abd95d2a092b0a70b9f3766ce5ead, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639707547.738917] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: 005bd32943370fe91d8596d0d6f8f4ff9d0f813259b8b689c3ab98e278b7a478, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639709213.432120] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: de0b6725dec24e8e78cff2d682a974345d1077af57e4ae9906697f14587997f4, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639709213.432131] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: 5161b37e6829bbdb964feb3989afffff82e55db20c699d4e95fda40540a1df3c, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639709213.432141] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: beb70b31e2a878111df71465a515bea61edd3a3f33bd85ad42a113235236ef57, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639709213.432151] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: 579bc129f3cf0369b627253e8676ca888d2c8f104edef9d027b439267b1d3782, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639709213.432161] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: 78cf1ca9184176c85b8e096f0d46e516c48b57ccbd259f6640f4daffa0f68e7e, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639709213.432172] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: 4b06750e84a27290d757c9fd13d6512f9fdf85ea92f3675cdb1c77287ecbfb95, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639709213.432182] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: 860453f6bde08ab0bbd1197cb2d7228aa6f4a46d481d80e7cc5a11ceb6d6ac65, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639709213.432192] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: 2a4c9cb50a6f68dc81bd0ab1b93d03c383174983b4c584bac48636de7b436652, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639709213.432202] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: bc6cc8c2a59f6120edf128aef1fa2bc573ae07bcae34d00bf9e32ffc8ea56e92, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639709213.432220] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: 349f93dd2970ff843c03136795d4f5f8b319082aaa7e1aaba581c15bfe445b4b, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639709213.432230] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: b829246e278ed75d2e52c7bb495d2537103d335ee407cb64f66b6d06c73874ec, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639709213.432240] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: b32c1e540fe2721a860bffd7224e36771c554f8031786b1f7f02bb18bf59eac7, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639709213.432250] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: b574e69d9d01a3b29b7a133ef4610183ff8c8520d1592a52a073b386f15598cb, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639709213.432260] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: 2b6591667a730dff4e725625dca0e8888b4303be42d5d55dabfc98b84bd85dc0, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639710612.364207] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: 2672a9c970249c23786434ff20e0cf65a78b0c38a0ac676f40a8f79e9e7e845b, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639710612.364229] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: e385f1f3ab84336301474944a1ddd20aa7417a184be36b1bbec49e7a881220ac, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639710612.364240] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: 4864cc944c43a2dff05a4be505c0c88efeabc5d00f4307972450758440c9a8ef, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639710612.364250] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: 8fdbe52185c284d699540eea82fef5195fed332e963e0c6bf67fc156216b6ed0, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639710612.364261] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: 0e325f1e11efcd0501eb7f534871bf53945d75406f0c99f150d064a3ed9fc866, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639710612.364273] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: 0d69e60f197cacf364ee0dd57645fef847b831d6d61e7f67fa5229ca0a4a4758, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639710612.364287] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: 29b2383c3c7adb24c2b5f160cfced2913981ef6e898162f44146c994dab1d17e, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639711210.790343] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: 63e8379d308b8913fec122832edd35f2ea61ee8f2ace05baf7e70c64dcb24772, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 329000, 329000]
DEBG [1639711210.790361] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: f59d5ef962171170124b1ec73edc93a75617f0b98bb2f197f8fccca02139b746, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639711210.790374] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: 1a70d60d20048248b70cc916fffdb2b92d4648e785593b7a126f8e5bc5579705, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639711407.889822] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: d568ba5d0006eaee53d71bdcc32d6974272c331e8113c4a45250984ab8055885, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 329000, 329000]
DEBG [1639711407.889878] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: dc26d3509552d195abab357496864b10c84db36f9711f88b21e9bf385f75ee2e, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639711630.545403] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: 509417334a38d6e1e26466cc10ebc310a6c774d94467251222b257eef7b1c513, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 329000, 329000]
DEBG [1639711630.545464] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: 34d37b6efbda4fddf627097c526719887b67dcb9675ef8483a3cb8c8389cf3ce, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639711850.060012] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: 0a53b42ee4a454df28282c00f791c87cb24c370aa95555de2310356614767673, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 329000, 329000]
DEBG [1639711850.060042] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: a9b65dc00ef5a70a23594de8c8d414075b402e191a37607df937b1793bbfed1a, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639712110.202676] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: 0eba836902882ea9902502dae8ed4446329b47d138b693d321b3854249d4879c, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 329000, 329000]
DEBG [1639712110.202697] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: 7d17bf4d8b5bd49d98710866baaa76bd277451c52b5676dfc2a01586ce2176c2, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639712339.998336] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: 6974f2e85c93c057cb8bdeeb1e3ab7e918479224aca231342343d5f7a79b62a8, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 329000, 329000]
DEBG [1639712339.998349] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: b5a0ce39744ea76a5260fb39abc68e1e39b25c35642d7a50214700f6edd49944, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639712454.454965] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: 8664d95a51bc215925891339f0f647662ca3c11af4d6a7943ad89220c515d2b3, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 329000, 329000]
DEBG [1639713017.614739] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: 235d32319c01d9c6214dda16b944af8029b0962a18e9204bf0dd720fe73065ca, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639713017.614803] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: feff85589777fd1bd8163ac857bb5df2b96aa75a79305bccc007c7206314c337, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639713017.614853] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: cf9147183218fadd16e21f0ad27788b0e275c19fc6afd8a90a7897373bdebba2, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639714471.243597] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: 279f16eb0efade6258c881e4d05b3161216bea752fdb8e59b8eaf664fb9cf121, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 329000, 329000]
DEBG [1639714471.243610] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: fba0d3bd46ca8051c586abab7ad172853832642ee4bc5e48ed0f56079e40900f, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639714471.243620] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: 766fb63bc15b2d6f9387af187956f0652d725399fa043d8dc711e27bb5aeb0f6, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639714471.243629] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: cec134d1af8b0f318fdeec662a64c1ec9886661a8916176f5df7fff1de5d029e, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639714471.243640] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: 58c0994a315ed4338f8fa7eeaad819c667223cc93dbf6581e6d4e4df2d791bfc, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639714471.243657] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: 6bd244abcf41ea2a6b9195ae78b7fee941c642feffc3131a1e839fccc6019316, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639714471.243668] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: a868e6289e07324b88d027f087694e10b3a59d03e2f3b565481f86d046a4ab2a, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639714471.243686] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: 7c8f2e0c7aacc6613ce2de73c1bd27b136c86c1e718957585593d38ff97647b5, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639714471.243696] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: 1b4abfd4dd13b26487ed36f847d9291ba6697fd4894ec3c886149dc7c5412e80, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639714717.368088] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: 6e38f306466700b2ccbeb81075ada81687ab3d0d1a8122494200a2b061811e05, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 329000, 329000]
DEBG [1639714717.368102] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: 2d83da1ea517e59fe6c1b7c9a1a750ad4bee3195c6652af84a5aa51c59766380, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639714925.012535] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: 61d6f5af214819b503aff6e0085b89e0b1c1ca8f4ace70ca69243aa6b721fc99, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 329000, 329000]
DEBG [1639714925.012542] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: 3eed5ac73da691f321fcaff71578e4e740d8a677d9ce8c61ba3ce072a4866246, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639715879.809750] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: 46202417a89359c305dba7d9a0f5311166bb0188f99592986e7679ad92ec2424, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 329000, 329000]
DEBG [1639715879.809761] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: 58c4c898131e291cc48dd2101049b625d9505c74e98caa40530d61cba73edb8e, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 1, 329000]
DEBG [1639716911.254933] [src/chainstate/burn/distribution.rs:284] [chains-coordinator] Burn sample, txid: 1aa35d8b82a7915966c6c124c3f5e9a9f83b6b6f1aad98badd7454d93b03ce6e, most_recent_burn: 329000, median_burn: 1, all_burns: [1, 1, 1, 1, 329000, 329000]

you can find full debug log here https://watcher-data.s3.amazonaws.com/multiple_commits_329.log.gz

@MaksimalistT
Copy link
Author

Hi, @jcnelson, @lgalabru, @diwakergupta
issue occurred again
miner stopped assembling blocks
from https://btc.com/btc/transaction/74816326a745d98d4c816dfdff566451ad7ef80af0dc6f9fba98012cdc50ed13
to https://btc.com/btc/transaction/370814e9e13e742b690644128d3f935cfc0956aea1b21270844760c1c5988369
than it started to make multiple commits for one block
some examples:
block 718716
https://btc.com/btc/transaction/a6d48056581d8dd2d512d02b0ede81760e7f96376347662c8f7773d6302a5415
https://btc.com/btc/transaction/b2a39a2854cb59382390d4a73f95bfe881429323829c477143bed16a5da43877
https://btc.com/btc/transaction/c5151824ebef2e6fbcc78d371eeaf189a477e81dcaf4d3fa8ad6ac6594f47c14
block 718717
https://btc.com/btc/transaction/63495240a70e40a58a9ebf1a70082a4fb6019e99c488fdcda6b6885f700a4f15
https://btc.com/btc/transaction/e7db288f0d78531c0ffc455d43c2028360b8f00381f63a6df66bc828e44586ae

it continued all the way by block 718,784 before i stopped it
please find debug logs for a period between blocks 718682-718783
https://watcher-data.s3.amazonaws.com/debug_14_1.log.gz

UTXOs on the balance where consolidated before the issue

p.s. this issue made a devastating affect on miner balance, please find time to fix it, thanks

jcnelson added a commit that referenced this issue Jan 16, 2022
@jcnelson
fix: don't attempt to process tenures if the last-processed sortition…
507c16f 
… is different than the one used to queue the original tenure. Possibly fixes #2969 as well.
@jcnelson
Copy link
Member

Hey, I may have a fix for this. I'm testing it out right now with the mock miner. The issue appears to be that the node doesn't quite realize that the Bitcoin chain has moved on from the request to attempt to build a block. The feat/faster-bootup branch will drop any requests if they are out-of-sync with the Bitcoin chain tip. I'm testing this now on some Foundation nodes.

@jcnelson jcnelson mentioned this issue Jan 20, 2022
Merged
@jcnelson
Copy link
Member

jcnelson commented Feb 7, 2022

I've confirmed that this behavior has at least stopped on the Foundation miner with #2989 applied. The root cause was due to the node attempting to process stale sortition requests. Going to go ahead and close this issue; please re-open if it happens again. The fix is available in the current release candidate (2.05.0.1.0-rc4), and will be available in the next release.

@jcnelson jcnelson closed this as completed Feb 7, 2022
@blockstack-devops
Copy link
Contributor

This issue has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.

@stacks-network stacks-network locked as resolved and limited conversation to collaborators Nov 12, 2024
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
locked
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@jcnelson @blockstack-devops @MaksimalistT