[TEST] panicking `tests::epoch_205::bigger_microblock_streams_in_2_05`

[wileyj]

This is a test that is only run on release currently, so it's infrequent, but fails regularly in CI after roughly 10 minutes (locally, the timing is roughly the same).

this also seems related, but i'm not sure how - running this test locally has at least a 50% chance of disrupting the networking service on the host OS. i've re-run this 4x locally, and 2x networking service crashed (this is abnormal for this particular host - no apparent reason so far, but it's an interesting coincidence).

From the recent 3.1.0.0.7 release workflow (which is similar to the error locally):

2025-02-27T18:03:56.7225201Z INFO [1740679436.722002] [testnet/stacks-node/src/neon_node.rs:1507] [miner-block-http://127.0.0.1:13101] Best tip is #0 f2d4f97d372ee821cca41f2ce37eb2e0fcf3de84/a75e0b1f93cdc638851dacb00af5d80d43d302538ef29f65f613b1ab1ecf9ae5
2025-02-27T18:03:56.7232295Z INFO [1740679436.722537] [testnet/stacks-node/src/neon_node.rs:2694] [miner-block-http://127.0.0.1:13101] Relayer: Submit block-commit, burn_fee: 20000, block_hash: 8c5c1e5799445605912cb4a3beb381a92230af16b675cb186f3b32c1c634ef36, tx_count: 1, target_height: 7, parent_consensus_hash: f2d4f97d372ee821cca41f2ce37eb2e0fcf3de84, parent_block_hash: a75e0b1f93cdc638851dacb00af5d80d43d302538ef29f65f613b1ab1ecf9ae5, parent_microblock_hash: 0000000000000000000000000000000000000000000000000000000000000000, parent_microblock_seq: 0, tip_burn_block_hash: 194f44c2f523357875b31c96bb97c1887a7a1d99d60c4288e0b22c714727308a, tip_burn_block_height: 209, tip_burn_block_sortition_id: d663cc13ff760884f5905620aeacb036f88290d121dd67933d185159323eaa1d, cur_burn_block_hash: 194f44c2f523357875b31c96bb97c1887a7a1d99d60c4288e0b22c714727308a, cur_burn_block_height: 209, cur_burn_block_sortition_id: d663cc13ff760884f5905620aeacb036f88290d121dd67933d185159323eaa1d, attempt: 1
2025-02-27T18:03:56.7293992Z INFO [1740679436.729194] [testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs:1503] [miner-block-http://127.0.0.1:13101] Miner node: submitting leader_block_commit (txid: 384d10b68c8f48bb4406a07efc10c770563ac984fc3c1f0e46b69bd056311c34, rbf: false, total spent: 37500, size: 350, fee_rate: 50)
2025-02-27T18:03:56.7545660Z INFO [1740679436.754393] [testnet/stacks-node/src/neon_node.rs:916] [miner-microblock-http://127.0.0.1:13101] Will keep polling mempool for transactions to include in a microblock
2025-02-27T18:03:56.7679671Z INFO [1740679436.767797] [testnet/stacks-node/src/neon_node.rs:1313] [miner-block-http://127.0.0.1:13101] Picking best Stacks tip
2025-02-27T18:03:56.7704278Z INFO [1740679436.770229] [testnet/stacks-node/src/neon_node.rs:1478] [miner-block-http://127.0.0.1:13101] Tip #0 f2d4f97d372ee821cca41f2ce37eb2e0fcf3de84/a75e0b1f93cdc638851dacb00af5d80d43d302538ef29f65f613b1ab1ecf9ae5 at 209:6 has score 0 (0 (earlier sibs) + 0 (earlier sibs) + 0 (earlier sibs))
2025-02-27T18:03:56.7706737Z INFO [1740679436.770245] [testnet/stacks-node/src/neon_node.rs:1507] [miner-block-http://127.0.0.1:13101] Best tip is #0 f2d4f97d372ee821cca41f2ce37eb2e0fcf3de84/a75e0b1f93cdc638851dacb00af5d80d43d302538ef29f65f613b1ab1ecf9ae5
2025-02-27T18:03:56.7711885Z INFO [1740679436.771050] [testnet/stacks-node/src/neon_node.rs:1608] [miner-block-http://127.0.0.1:13101] Have only attempted one block; unconditionally trying again
2025-02-27T18:03:56.7742356Z WARN [1740679436.774084] [testnet/stacks-node/src/neon_node.rs:1769] [miner-block-http://127.0.0.1:13101] test version of make_microblock_secret_key
2025-02-27T18:03:56.7810297Z INFO [1740679436.780809] [stackslib/src/chainstate/stacks/miner.rs:2852] [miner-block-http://127.0.0.1:13101] Include tx, tx: e9506cb0a17ce260fd99b54a4f3baf3726f520b55f936a909ed5dad5116369f2, payload: Coinbase, origin: ST25WA53N4PWF8XZGQH2J5A4CGCWV4JADPM8MHTRV
2025-02-27T18:03:56.7813411Z INFO [1740679436.780840] [stackslib/src/chainstate/stacks/miner.rs:421] [miner-block-http://127.0.0.1:13101] Tx successfully processed., event_name: transaction_result, tx_id: e9506cb0a17ce260fd99b54a4f3baf3726f520b55f936a909ed5dad5116369f2, event_type: success
2025-02-27T18:03:56.7835270Z INFO [1740679436.783269] [stackslib/src/chainstate/stacks/miner.rs:1756] [miner-block-http://127.0.0.1:13101] Miner: mined anchored block 8c5c1e5799445605912cb4a3beb381a92230af16b675cb186f3b32c1c634ef36 height 7 with 1 txs, parent block a75e0b1f93cdc638851dacb00af5d80d43d302538ef29f65f613b1ab1ecf9ae5, parent microblock 0000000000000000000000000000000000000000000000000000000000000000 (0), state root = afd3cc78596c7fead4740a9d2cfd28c4ebcacd85c0a1ff26d8d262ecfc0409c3
2025-02-27T18:03:56.7840755Z INFO [1740679436.783637] [stackslib/src/chainstate/stacks/miner.rs:2704] [miner-block-http://127.0.0.1:13101] Miner: mined anchored block, stacks_block_hash: 8c5c1e5799445605912cb4a3beb381a92230af16b675cb186f3b32c1c634ef36, height: 7, tx_count: 1, parent_stacks_block_hash: a75e0b1f93cdc638851dacb00af5d80d43d302538ef29f65f613b1ab1ecf9ae5, parent_stacks_microblock: 0000000000000000000000000000000000000000000000000000000000000000, parent_stacks_microblock_seq: 0, block_size: 395, execution_consumed: {"runtime": 0, "write_len": 0, "write_cnt": 0, "read_len": 0, "read_cnt": 0}, %-full: 0, assembly_time_ms: 8, tx_fees_microstacks: 0
2025-02-27T18:03:56.7843704Z INFO [1740679436.783822] [testnet/stacks-node/src/neon_node.rs:2606] [miner-block-http://127.0.0.1:13101] Relayer: Succeeded assembling Stacks block #7: 8c5c1e5799445605912cb4a3beb381a92230af16b675cb186f3b32c1c634ef36, with 1 txs, attempt 2
2025-02-27T18:03:56.7846181Z INFO [1740679436.784504] [testnet/stacks-node/src/neon_node.rs:1313] [miner-block-http://127.0.0.1:13101] Picking best Stacks tip
2025-02-27T18:03:56.7878714Z INFO [1740679436.787622] [testnet/stacks-node/src/neon_node.rs:1478] [miner-block-http://127.0.0.1:13101] Tip #0 f2d4f97d372ee821cca41f2ce37eb2e0fcf3de84/a75e0b1f93cdc638851dacb00af5d80d43d302538ef29f65f613b1ab1ecf9ae5 at 209:6 has score 0 (0 (earlier sibs) + 0 (earlier sibs) + 0 (earlier sibs))
2025-02-27T18:03:56.7882159Z INFO [1740679436.787642] [testnet/stacks-node/src/neon_node.rs:1507] [miner-block-http://127.0.0.1:13101] Best tip is #0 f2d4f97d372ee821cca41f2ce37eb2e0fcf3de84/a75e0b1f93cdc638851dacb00af5d80d43d302538ef29f65f613b1ab1ecf9ae5
2025-02-27T18:03:56.7890398Z INFO [1740679436.788098] [testnet/stacks-node/src/neon_node.rs:2694] [miner-block-http://127.0.0.1:13101] Relayer: Submit block-commit, burn_fee: 20000, block_hash: 8c5c1e5799445605912cb4a3beb381a92230af16b675cb186f3b32c1c634ef36, tx_count: 1, target_height: 7, parent_consensus_hash: f2d4f97d372ee821cca41f2ce37eb2e0fcf3de84, parent_block_hash: a75e0b1f93cdc638851dacb00af5d80d43d302538ef29f65f613b1ab1ecf9ae5, parent_microblock_hash: 0000000000000000000000000000000000000000000000000000000000000000, parent_microblock_seq: 0, tip_burn_block_hash: 194f44c2f523357875b31c96bb97c1887a7a1d99d60c4288e0b22c714727308a, tip_burn_block_height: 209, tip_burn_block_sortition_id: d663cc13ff760884f5905620aeacb036f88290d121dd67933d185159323eaa1d, cur_burn_block_hash: 194f44c2f523357875b31c96bb97c1887a7a1d99d60c4288e0b22c714727308a, cur_burn_block_height: 209, cur_burn_block_sortition_id: d663cc13ff760884f5905620aeacb036f88290d121dd67933d185159323eaa1d, attempt: 2
2025-02-27T18:03:56.7897236Z INFO [1740679436.789551] [testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs:1617] [miner-block-http://127.0.0.1:13101] Abort attempt to re-submit identical LeaderBlockCommit
2025-02-27T18:03:56.7899247Z INFO [1740679436.789566] [testnet/stacks-node/src/neon_node.rs:2727] [miner-block-http://127.0.0.1:13101] Relayer: Block-commit already submitted
2025-02-27T18:03:56.8018945Z INFO [1740679436.801660] [testnet/stacks-node/src/tests/neon_integrations.rs:699] [tests::epoch_205::bigger_microblock_streams_in_2_05] Block bumped at 1740679436 (9)
2025-02-27T18:03:56.8037121Z INFO [1740679436.803264] [testnet/stacks-node/src/neon_node.rs:916] [miner-microblock-http://127.0.0.1:13101] Will keep polling mempool for transactions to include in a microblock
2025-02-27T18:03:56.8039796Z 7
2025-02-27T18:03:56.8065379Z Epoch size: ExecutionCost { write_length: 0, write_count: 0, read_length: 0, read_count: 0, runtime: 0 }
2025-02-27T18:03:56.8070930Z 1
2025-02-27T18:03:56.8071863Z Epoch size: ExecutionCost { write_length: 0, write_count: 0, read_length: 0, read_count: 0, runtime: 0 }
2025-02-27T18:03:56.8072619Z 2
2025-02-27T18:03:56.8075955Z Epoch size: ExecutionCost { write_length: 3361, write_count: 2, read_length: 1, read_count: 1, runtime: 2721051000 }
2025-02-27T18:03:56.8076761Z 3
2025-02-27T18:03:56.8080463Z Epoch size: ExecutionCost { write_length: 3361, write_count: 2, read_length: 1, read_count: 1, runtime: 2721051000 }
2025-02-27T18:03:56.8082491Z max_big_txs_per_microblock_20: 1, total_big_txs_per_microblock_20: 1
2025-02-27T18:03:56.8083379Z max_big_txs_per_microblock_205: 1, total_big_txs_per_microblock_205: 1
2025-02-27T18:03:56.8084559Z confirmed stream execution in 2.0: ExecutionCost { write_length: 3361, write_count: 2, read_length: 1, read_count: 1, runtime: 2721051000 }
2025-02-27T18:03:56.8086070Z confirmed stream execution in 2.05: ExecutionCost { write_length: 3361, write_count: 2, read_length: 1, read_count: 1, runtime: 2721051000 }
2025-02-27T18:03:56.8086925Z 
2025-02-27T18:03:56.8087721Z thread 'tests::epoch_205::bigger_microblock_streams_in_2_05' panicked at testnet/stacks-node/src/tests/epoch_205.rs:1237:5:
2025-02-27T18:03:56.8088848Z assertion failed: epoch_205_stream_cost.read_count > epoch_20_stream_cost.read_count
2025-02-27T18:03:56.8089732Z stack backtrace:
2025-02-27T18:03:56.8200612Z    0:     0x55b5611139ea - <std::sys::backtrace::BacktraceLock::print::DisplayBacktrace as core::fmt::Display>::fmt::he089f96442833f67
2025-02-27T18:03:56.8202132Z    1:     0x55b561143423 - core::fmt::write::h2f210ed4c94745cb
2025-02-27T18:03:56.8203154Z INFO [1740679436.820149] [testnet/stacks-node/src/neon_node.rs:1313] [miner-block-http://127.0.0.1:13101] Picking best Stacks tip
2025-02-27T18:03:56.8205194Z    2:     0x55b56110e3e3 - std::io::Write::write_fmt::h7de08171ab770fb2
2025-02-27T18:03:56.8206095Z    3:     0x55b561113832 - std::sys::backtrace::BacktraceLock::print::h810fbd31421329e6
2025-02-27T18:03:56.8210839Z    4:     0x55b561114df0 - std::panicking::default_hook::{{closure}}::hbaad47ed9dc6356d
2025-02-27T18:03:56.8211642Z    5:     0x55b561114bd0 - std::panicking::default_hook::h24e207139139d40a
2025-02-27T18:03:56.8212387Z    6:     0x55b561115552 - std::panicking::rust_panic_with_hook::ha9131beeb2ddc506
2025-02-27T18:03:56.8213229Z    7:     0x55b5611152c6 - std::panicking::begin_panic_handler::{{closure}}::h1bba0eaeb6da506f
2025-02-27T18:03:56.8214256Z    8:     0x55b561113ee9 - std::sys::backtrace::__rust_end_short_backtrace::h1d1ca3eade483f4c
2025-02-27T18:03:56.8214972Z    9:     0x55b561114f8d - rust_begin_unwind
2025-02-27T18:03:56.8215471Z   10:     0x55b55ec235e0 - __covrec_AC7D9811D30EFA5Au
2025-02-27T18:03:56.8215972Z   11:     0x55b55ec2366c - __covrec_DC1F9925B206F634u
2025-02-27T18:03:56.8216448Z   12:     0x55b55ee1619d - __covrec_7A305B950545E285u
2025-02-27T18:03:56.8217638Z   13:     0x55b55f1d0569 - <stacks_node[c187e20dc49a2bc0]::tests::epoch_205::bigger_microblock_streams_in_2_05::{closure#0} as core[3b140760090fa97d]::ops::function::FnOnce<()>>::call_once
2025-02-27T18:03:56.8218970Z   14:     0x55b55f6bb25b - test::__rust_begin_short_backtrace::h52b6da716ad42b7d
2025-02-27T18:03:56.8219905Z   15:     0x55b55f6ba193 - test::run_test::{{closure}}::h9f3bfaf910429adb
2025-02-27T18:03:56.8220757Z   16:     0x55b55f67dec5 - std::sys::backtrace::__rust_begin_short_backtrace::hb51d9a6c67ec382d
2025-02-27T18:03:56.8221685Z   17:     0x55b55f681906 - core::ops::function::FnOnce::call_once{{vtable.shim}}::hb3b44780e9c053e5
2025-02-27T18:03:56.8222600Z   18:     0x55b56111c0eb - std::sys::pal::unix::thread::Thread::new::thread_start::ha07e360225fa3528
2025-02-27T18:03:56.8223274Z   19:     0x7fe5c8c9caa4 - <unknown>
2025-02-27T18:03:56.8223688Z   20:     0x7fe5c8d29c3c - <unknown>
2025-02-27T18:03:56.8224084Z   21:                0x0 - <unknown>
2025-02-27T18:03:56.8232661Z test tests::epoch_205::bigger_microblock_streams_in_2_05 ... FAILED
2025-02-27T18:03:56.8233884Z 
2025-02-27T18:03:56.8234028Z failures:
2025-02-27T18:03:56.8234211Z 
2025-02-27T18:03:56.8237230Z failures:
2025-02-27T18:03:56.8261146Z     tests::epoch_205::bigger_microblock_streams_in_2_05
2025-02-27T18:03:56.8267159Z 
2025-02-27T18:03:56.8267630Z test result: FAILED. 0 passed; 1 failed; 0 ignored; 0 measured; 243 filtered out; finished in 509.85s
2025-02-27T18:03:56.8268232Z 
2025-02-27T18:03:56.8270056Z INFO [1740679436.823919] [testnet/stacks-node/src/neon_node.rs:1478] [miner-block-http://127.0.0.1:13101] Tip #0 f2d4f97d372ee821cca41f2ce37eb2e0fcf3de84/a75e0b1f93cdc638851dacb00af5d80d43d302538ef29f65f613b1ab1ecf9ae5 at 209:6 has score 0 (0 (earlier sibs) + 0 (earlier sibs) + 0 (earlier sibs))
2025-02-27T18:03:56.8273040Z INFO [1740679436.823957] [testnet/stacks-node/src/neon_node.rs:1507] [miner-block-http://127.0.0.1:13101] Best tip is #0 f2d4f97d372ee821cca41f2ce37eb2e0fcf3de84/a75e0b1f93cdc638851dacb00af5d80d43d302538ef29f65f613b1ab1ecf9ae5
2025-02-27T18:03:56.8275158Z INFO [1740679436.824836] [testnet/stacks-node/src/neon_node.rs:1608] [miner-block-http://127.0.0.1:13101] Have only attempted one block; unconditionally trying again
2025-02-27T18:03:56.8284053Z WARN [1740679436.828186] [testnet/stacks-node/src/neon_node.rs:1769] [miner-block-http://127.0.0.1:13101] test version of make_microblock_secret_key
2025-02-27T18:03:56.8286642Z ERRO [1740679436.828365] [stackslib/src/burnchains/bitcoin/network.rs:203] [ThreadId(8)] Failed to connect to peer 127.0.0.1:8333: connection to peer could not be (re-)established
2025-02-27T18:03:56.8342047Z INFO [1740679436.833969] [stackslib/src/chainstate/stacks/miner.rs:2852] [miner-block-http://127.0.0.1:13101] Include tx, tx: e9506cb0a17ce260fd99b54a4f3baf3726f520b55f936a909ed5dad5116369f2, payload: Coinbase, origin: ST25WA53N4PWF8XZGQH2J5A4CGCWV4JADPM8MHTRV
2025-02-27T18:03:56.8345211Z INFO [1740679436.833991] [stackslib/src/chainstate/stacks/miner.rs:421] [miner-block-http://127.0.0.1:13101] Tx successfully processed., event_name: transaction_result, tx_id: e9506cb0a17ce260fd99b54a4f3baf3726f520b55f936a909ed5dad5116369f2, event_type: success
2025-02-27T18:03:56.8362530Z INFO [1740679436.835900] [stackslib/src/chainstate/stacks/miner.rs:1756] [miner-block-http://127.0.0.1:13101] Miner: mined anchored block 8c5c1e5799445605912cb4a3beb381a92230af16b675cb186f3b32c1c634ef36 height 7 with 1 txs, parent block a75e0b1f93cdc638851dacb00af5d80d43d302538ef29f65f613b1ab1ecf9ae5, parent microblock 0000000000000000000000000000000000000000000000000000000000000000 (0), state root = afd3cc78596c7fead4740a9d2cfd28c4ebcacd85c0a1ff26d8d262ecfc0409c3
2025-02-27T18:03:56.8422552Z �[31;1m        FAIL�[0m [ 509.877s] �[35;1mstacks-node::bin/stacks-node�[0m �[36mtests::epoch_205�[0m�[36m::�[0m�[34;1mbigger_microblock_streams_in_2_05�[0m
2025-02-27T18:03:56.8423579Z �[31;1m  Cancelling�[0m due to �[31;1mtest failure�[0m
2025-02-27T18:03:56.8424160Z ────────────
2025-02-27T18:03:56.8424906Z �[31;1m     Summary�[0m [ 509.883s] �[1m1�[0m test run: �[1m0�[0m �[32;1mpassed�[0m, �[1m1�[0m �[31;1mfailed�[0m, �[1m6111�[0m �[33;1mskipped�[0m
2025-02-27T18:03:56.8426161Z �[31;1m        FAIL�[0m [ 509.877s] �[35;1mstacks-node::bin/stacks-node�[0m �[36mtests::epoch_205�[0m�[36m::�[0m�[34;1mbigger_microblock_streams_in_2_05�[0m
2025-02-27T18:03:56.9430286Z �[31;1merror�[0m: test run failed