search

stacks-network / stacks-core

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

Miner commitment is spent when 'Failed to submit Bitcoin transaction' #2356

Closed MaksimalistT closed 3 years ago

MaksimalistT commented 3 years ago

Describe the bug

miner commitment per block is spent when errors like this occur:

ERRO [1610808785.386308] [testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs:953] [relayer] Bitcoin RPC failure: transaction submission failed - Network("Bitcoin RPC: status(500) != success, body is 'Object({"error": Object({"code": Number(-25), "message": String("bad-txns-inputs-missingorspent")}), "id": String("stacks"), "result": Null})'") WARN [1610808785.386393] [testnet/stacks-node/src/neon_node.rs:1638] [relayer] Failed to submit Bitcoin transaction

Steps To Reproduce conf: burn_fee_cap = 22000 satoshis_per_byte = 102

Expected behavior miner commitment per block is NOT spent

Environment (please complete the following information):

friedger commented 3 years ago

The relevant btc tx are: https://btc.com/2e0b6deca18dfb0ddbb389f3433db1bc33fcc18528007443f065bc2a1666c380 and https://btc.com/5395f15af9735a81d597fc801741f6641fca5628939b6b7bb37457a5e9856928

and another one: https://btc.com/f7b67cd177bf255f042d2b361c2c172805f4409230501cab2331e87394ed570c https://btc.com/443db74ea0dc783547b43a568fc1a54376b6c2191fae6041cf9468057b5df535

diwakergupta commented 3 years ago

@MaksimalistT @friedger can you also include debug logs from stacks-node when this happens?

@lgalabru @kantai would #2346 help with this?

psq commented 3 years ago

I've also encountered this issue, and will dig out some logs as well.

psq commented 3 years ago

After looking at the logs, I don't think anything gets spent when you get that error message, you see a transaction for that block because the miner has successfully sent other transactions. See attempt 7 below.

We should still fix this as the "best" commit was not successfully sent, but that's not always the last one where this happens.

INFO [1610788124.382293] [src/chainstate/stacks/miner.rs:829] [relayer] Miner: mined anchored block 4d9dfcad473604a459a769df998fc353139651ca1e3371c92d19378c258be369 with 2 txs, parent block 48e637fd1e02285d3d25773ee1b54c30d4fc1cf02acfa6aa34760871ff3f74b6, state root = 542e0d6dbc0f66e03af565e5b7840961175efa01065d2380b65dcba1c5153cab
INFO [1610788124.400016] [testnet/stacks-node/src/neon_node.rs:1574] [relayer] Succeeded assembling Stacks block #186: 4d9dfcad473604a459a769df998fc353139651ca1e3371c92d19378c258be369, with 2 txs, attempt 2
INFO [1610788124.463265] [testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs:804] [relayer] Miner node: submitting leader_block_commit op for 4d9dfcad473604a459a769df998fc353139651ca1e3371c92d19378c258be369 - 03fb3bc5bae4c088ca38a8c68bfe741f3b1cb62a067b69917908089a2082af31ae, waiting for its inclusion in the next Bitcoin block

INFO [1610788195.984455] [src/chainstate/stacks/miner.rs:829] [relayer] Miner: mined anchored block 2e6f66f66e8be48bbb9c272262907a894f0b27c24150a9e88d31bf826f0198c6 with 2 txs, parent block 48e637fd1e02285d3d25773ee1b54c30d4fc1cf02acfa6aa34760871ff3f74b6, state root = 181b75158dcd38bdc57637dae2196be9059c7eb4f9d34a2b4e3f1f91bf38fff5
INFO [1610788195.996548] [testnet/stacks-node/src/neon_node.rs:1574] [relayer] Succeeded assembling Stacks block #186: 2e6f66f66e8be48bbb9c272262907a894f0b27c24150a9e88d31bf826f0198c6, with 2 txs, attempt 3
INFO [1610788195.996914] [testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs:804] [relayer] Miner node: submitting leader_block_commit op for 2e6f66f66e8be48bbb9c272262907a894f0b27c24150a9e88d31bf826f0198c6 - 03fb3bc5bae4c088ca38a8c68bfe741f3b1cb62a067b69917908089a2082af31ae, waiting for its inclusion in the next Bitcoin block

INFO [1610788266.989116] [src/chainstate/stacks/miner.rs:829] [relayer] Miner: mined anchored block bb733c44b0a9d1fb78e30a537d9707958b9f2d079a31548184ac4536903650ca with 1 txs, parent block 48e637fd1e02285d3d25773ee1b54c30d4fc1cf02acfa6aa34760871ff3f74b6, state root = 181b75158dcd38bdc57637dae2196be9059c7eb4f9d34a2b4e3f1f91bf38fff5
INFO [1610788267.000101] [testnet/stacks-node/src/neon_node.rs:1574] [relayer] Succeeded assembling Stacks block #186: bb733c44b0a9d1fb78e30a537d9707958b9f2d079a31548184ac4536903650ca, with 1 txs, attempt 4
INFO [1610788267.000467] [testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs:804] [relayer] Miner node: submitting leader_block_commit op for bb733c44b0a9d1fb78e30a537d9707958b9f2d079a31548184ac4536903650ca - 03fb3bc5bae4c088ca38a8c68bfe741f3b1cb62a067b69917908089a2082af31ae, waiting for its inclusion in the next Bitcoin block

INFO [1610788405.056671] [src/chainstate/stacks/miner.rs:829] [relayer] Miner: mined anchored block 5e7d46c7087fa86cfac693fc2974bae1bf3d232671ada763e649f4aec62d73f2 with 1 txs, parent block 48e637fd1e02285d3d25773ee1b54c30d4fc1cf02acfa6aa34760871ff3f74b6, state root = 5e31cbb1afc088f883b1fc532fcd3feab450ac0770095d26580aab48e2697312
INFO [1610788405.070524] [testnet/stacks-node/src/neon_node.rs:1574] [relayer] Succeeded assembling Stacks block #186: 5e7d46c7087fa86cfac693fc2974bae1bf3d232671ada763e649f4aec62d73f2, with 1 txs, attempt 5
INFO [1610788405.070898] [testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs:804] [relayer] Miner node: submitting leader_block_commit op for 5e7d46c7087fa86cfac693fc2974bae1bf3d232671ada763e649f4aec62d73f2 - 03fb3bc5bae4c088ca38a8c68bfe741f3b1cb62a067b69917908089a2082af31ae, waiting for its inclusion in the next Bitcoin block

INFO [1610788475.911214] [src/chainstate/stacks/miner.rs:829] [relayer] Miner: mined anchored block c6ab47ed878366c6c54fbed458ddf9fa323ccd51ecfc09d5e36948c32d2b0f21 with 1 txs, parent block 48e637fd1e02285d3d25773ee1b54c30d4fc1cf02acfa6aa34760871ff3f74b6, state root = d96d07776686112861f55e9549b90def88c3d08c9baaa59701e290346f92cd9a
INFO [1610788475.924230] [testnet/stacks-node/src/neon_node.rs:1574] [relayer] Succeeded assembling Stacks block #186: c6ab47ed878366c6c54fbed458ddf9fa323ccd51ecfc09d5e36948c32d2b0f21, with 1 txs, attempt 6
INFO [1610788475.924661] [testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs:804] [relayer] Miner node: submitting leader_block_commit op for c6ab47ed878366c6c54fbed458ddf9fa323ccd51ecfc09d5e36948c32d2b0f21 - 03fb3bc5bae4c088ca38a8c68bfe741f3b1cb62a067b69917908089a2082af31ae, waiting for its inclusion in the next Bitcoin block

INFO [1610788546.262044] [testnet/stacks-node/src/neon_node.rs:1574] [relayer] Succeeded assembling Stacks block #186: 9bfbe219ae8f330c69442792fe76cf39b24605fc4bd0118eebebb9adf4ac34df, with 2 txs, attempt 7
INFO [1610788546.262467] [testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs:804] [relayer] Miner node: submitting leader_block_commit op for 9bfbe219ae8f330c69442792fe76cf39b24605fc4bd0118eebebb9adf4ac34df - 03fb3bc5bae4c088ca38a8c68bfe741f3b1cb62a067b69917908089a2082af31ae, waiting for its inclusion in the next Bitcoin block
ERRO [1610788546.298030] [testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs:953] [relayer] Bitcoin RPC failure: transaction submission failed - Network("Bitcoin RPC: status(500) != success, body is \'Object({\"error\": Object({\"code\": Number(-25), \"message\": String(\"bad-txns-inputs-missingorspent\")}), \"id\": String(\"stacks\"), \"result\": Null})\'")
WARN [1610788546.298063] [testnet/stacks-node/src/neon_node.rs:1638] [relayer] Failed to submit Bitcoin transaction
gzelda commented 3 years ago 
INFO [1610946272.320900] [testnet/stacks-node/src/neon_node.rs:1592] [relayer] Succeeded assembling Stacks block #381: fc4a22ecffb644a29d7e2dbfc3e26d31f1708e2e486208c9cf625407a60aebd2, with 4 txs, attempt 11
INFO [1610946272.323043] [testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs:827] [relayer] Miner node: submitting leader_block_commit op for fc4a22ecffb644a29d7e2dbfc3e26d31f1708e2e486208c9cf625407a60aebd2 - 02964a6d7758a04ce64a4d32c307ad1a1041f2186c2a0feaacdfe675ddf2496546, waiting for its inclusion in the next Bitcoin block
ERRO [1610946272.324593] [testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs:976] [relayer] Bitcoin RPC failure: transaction submission failed - Network("Bitcoin RPC: status(500) != success, body is \'Object({\"error\": Object({\"code\": Number(-26), \"message\": String(\"insufficient fee, rejecting replacement 04873728f81d199b95ec2a52b9d36378054d1cb7ed107ae6608659f25aa7579a, not enough additional fees to relay; 0.0000035 < 0.00000351\")}), \"id\": String(\"stacks\"), \"result\": Null})\'")

Met code: -26 when attempt commit 11 times

gzelda commented 3 years ago

Here is the log after syncing the block.

DEBG [1610948793.522611] [testnet/stacks-node/src/run_loop/neon.rs:372] [main] Synchronized burnchain up to block height 666564 (chain tip height is 666564)
DEBG [1610948793.522632] [testnet/stacks-node/src/run_loop/neon.rs:380] [main] Synchronized full burnchain up to height 666564. Proceeding to mine blocks
DEBG [1610948793.522620] [testnet/stacks-node/src/neon_node.rs:769] [relayer] Relayer: Process tenure cad65aec07a7189477100bd05865c5266a1fd7fa/222cfbec07b66422b71b1bd00b51ea87728308adb760ba56a1bac0cdbd3f1d7b in 0000000000000000000da1aabb43f3b8abd601a683b9087892bdfc5d1757b939
WARN [1610948793.522745] [testnet/stacks-node/src/neon_node.rs:1181] [main] Skipped tenure because no active VRF key. Trying to register one.
DEBG [1610948793.522765] [testnet/stacks-node/src/run_loop/neon.rs:317] [main] Wait until we reach steady-state before processing more burnchain blocks...
DEBG [1610948793.522782] [testnet/stacks-node/src/syncctl.rs:389] [main] PoX watchdog in first reward cycle -- sync immediately
DEBG [1610948793.523105] [testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs:1356] [relayer] BitcoinRPC builder: Some("daemontech2"):Some("daemontech2")@http://127.0.0.1:8332/
DEBG [1610948793.524258] [testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs:910] [relayer] Payments value: 1397000, total_consumed: 1446580, total_spent: 49580, tx_fee: 44080, attempt: 1
DEBG [1610948793.524390] [testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs:955] [relayer] Send transaction: "0100000001a939d54fa4607bf013dd6cf30db26ddde5eaa3aa7f5de20c1caaccbe515584bc030000006a4730440220237204607471132c22e93e7a348239cb336e3be3abfb1b287dd881bf8e42c451022045fbf2b9ade3748fed3210ac67d1858329d3de96d4c41f5b3f4229ea1a616250012102964a6d7758a04ce64a4d32c307ad1a1041f2186c2a0feaacdfe675ddf2496546fdffffff030000000000000000396a3758325ecad65aec07a7189477100bd05865c5266a1fd7fa3c34c3ef139e3fe4414cc1a86c1b19d06090c28d73d06d51d00d94c555ac31eb7c150000000000001976a91429b4f12c0c5acd2f389edfe83a5705673a34f72188ac08511500000000001976a91429b4f12c0c5acd2f389edfe83a5705673a34f72188ac00000000"
INFO [1610948793.524410] [testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs:590] [relayer] Miner node: submitting leader_key_register op - 02964a6d7758a04ce64a4d32c307ad1a1041f2186c2a0feaacdfe675ddf2496546, waiting for its inclusion in the next Bitcoin block
DEBG [1610948793.524461] [testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs:1356] [relayer] BitcoinRPC builder: Some("daemontech2"):Some("daemontech2")@http://127.0.0.1:8332/
ERRO [1610948793.525844] [testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs:976] [relayer] Bitcoin RPC failure: transaction submission failed - Network("Bitcoin RPC: status(500) != success, body is \'Object({\"error\": Object({\"code\": Number(-25), \"message\": String(\"bad-txns-inputs-missingorspent\")}), \"id\": String(\"stacks\"), \"result\": Null})\'")
psq commented 3 years ago 
INFO [1610946272.320900] [testnet/stacks-node/src/neon_node.rs:1592] [relayer] Succeeded assembling Stacks block #381: fc4a22ecffb644a29d7e2dbfc3e26d31f1708e2e486208c9cf625407a60aebd2, with 4 txs, attempt 11
INFO [1610946272.323043] [testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs:827] [relayer] Miner node: submitting leader_block_commit op for fc4a22ecffb644a29d7e2dbfc3e26d31f1708e2e486208c9cf625407a60aebd2 - 02964a6d7758a04ce64a4d32c307ad1a1041f2186c2a0feaacdfe675ddf2496546, waiting for its inclusion in the next Bitcoin block
ERRO [1610946272.324593] [testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs:976] [relayer] Bitcoin RPC failure: transaction submission failed - Network("Bitcoin RPC: status(500) != success, body is \'Object({\"error\": Object({\"code\": Number(-26), \"message\": String(\"insufficient fee, rejecting replacement 04873728f81d199b95ec2a52b9d36378054d1cb7ed107ae6608659f25aa7579a, not enough additional fees to relay; 0.0000035 < 0.00000351\")}), \"id\": String(\"stacks\"), \"result\": Null})\'")

Met code: -26 when attempt commit 11 times

this is not the same error, see https://github.com/blockstack/stacks-blockchain/issues/2347

jcnelson commented 3 years ago

We believe that the cause of this issue is that there's a race condition between the miner's attempt to replace-by-fee, and the bitcoin chain advancing by one block before the miner sees the new chain tip. I think the code should just try mining again once the view of the bitcoin chain gets refreshed (and take this error as a hint to refresh the bitcoin chain tip).

leslieonline27 commented 3 years ago

We believe that the cause of this issue is that there's a race condition between the miner's attempt to replace-by-fee, and the bitcoin chain advancing by one block before the miner sees the new chain tip. I think the code should just try mining again once the view of the bitcoin chain gets refreshed (and take this error as a hint to refresh the bitcoin chain tip).

I've managed to observe this in real-time - bitcoin chain advanced while my node was re-assembling the block and attempting a replace-by-fee when this error appeared. To confirm, there was no double spend although I may not have won as a result of the node not being able to submit its best commit and so the commit was essentially wasted

lgalabru commented 3 years ago

Should be addressed with https://github.com/blockstack/stacks-blockchain/pull/2383

lgalabru commented 3 years ago

Addressed with https://github.com/blockstack/stacks-blockchain/releases/tag/2.0.3