Experiment with timeout for `tests::nakamoto_integrations::check_block_info_rewards` about stacks-blockchain

[obycode]

I just discovered that in tests, the maturation time is just 2 blocks, so this test can be much faster!

[wileyj]

51 minutes for a failure (works locally in a few minutes). the result was a panic though:

INFO [1719453354.994953] [stackslib/src/net/db.rs:156] [run_loop] Will be authenticating p2p messages with the following, public key: 03263f727a59051003901f24c7e18126d550f1c9133e0ea899297e37e89e956adc, services: 0007, Stacker DBs: 
ERRO [1719453355.004823] [stackslib/src/net/poll.rs:94] [run_loop] Failed to bind to 127.0.0.1:36498: Os { code: 98, kind: AddrInUse, message: "Address already in use" }
test tests::nakamoto_integrations::check_block_info_rewards has been running for over 60 seconds
test tests::nakamoto_integrations::check_block_info_rewards ... FAILED
failures:
failures:
    tests::nakamoto_integrations::check_block_info_rewards
test result: FAILED. 0 passed; 1 failed; 0 ignored; 0 measured; 149 filtered out; finished in 600.85s

--- TRY 3 STDERR:        stacks-node::bin/stacks-node tests::nakamoto_integrations::check_block_info_rewards ---
bitcoind spawn: "bitcoind" "-regtest" "-nodebug" "-nodebuglogfile" "-rest" "-txindex=1" "-server=1" "-listenonion=0" "-rpcbind=127.0.0.1" "-port=8333" "-datadir=/tmp/stacks-node-tests/integrations-neon/8a92771fad6ed66d-1719453352/nakamoto-neon/burnchain" "-rpcport=8332" "-rpcuser=neon-tester" "-rpcpassword=neon-tester-pass"
bitcoind startup finished
thread 'run_loop' panicked at testnet/stacks-node/src/neon_node.rs:4231:14:
BUG: PeerNetwork could not bind or is already bound: BindError
stack backtrace:

incidentally, tests::epoch_21::test_pox_reorg_flap_reward_cycles doesn't pass locally for me (ran for 4 hours before i killed it) - will dig into that one a little more as well.

[wileyj]

@obycode after speaking to @jferrant about this specific test - i'm able to reproduce her failures on develop (17d917c).
additionally - it's possible i ran the check_block_info test when i commented that it worked locally.

i have the full ouput if needed, but it looks like an assertion error. i've reproduced this with both cargo test and nextest:

INFO [1719508110.744791] [testnet/stacks-node/src/tests/nakamoto_integrations.rs:6372] [tests::nakamoto_integrations::check_block_info_rewards] Chain info: RPCPeerInfoData { peer_version: 4207599114, pox_consensus: 3b04823cc3aaabae74b55983176476559f5346bc, burn_block_height: 334, stable_pox_consensus: 094b6c9b240b98b2e72af8594cbb20d35ac0cf4b, stable_burn_block_height: 333, server_version: "stacks-node 0.0.1 (:, debug build, linux [x86_64])", network_id: 2147483648, parent_network_id: 3669344250, stacks_tip_height: 136, stacks_tip: 973e2c424abd22483a21e71a149d32ca995c7ae4927ec5f64e28d27b89f4856b, stacks_tip_consensus_hash: 3b04823cc3aaabae74b55983176476559f5346bc, genesis_chainstate_hash: 74237aa39aa50a83de11a4f53e9d3bb7d43461d1de9873f402e5453ae60bc59b, unanchored_tip: None, unanchored_seq: None, exit_at_block_height: None, is_fully_synced: true, node_public_key: Some(0210493e917be07c23bbe48032646c73a21a93ca8e93f57e338c7ca9045dc46786), node_public_key_hash: Some(89fd1e67fdde7d7480d8c27f193a598cc6644db3), affirmations: Some(RPCAffirmationData { heaviest: nnnnnnnnnn, stacks_tip: nnnnnnnnnnp, sortition_tip: nnnnnnnnnnp, tentative_best: nnnnnnnnnnp }), last_pox_anchor: Some(RPCLastPoxAnchorData { anchor_block_hash: bf06a0975ace4d7d96a9ad3eb005f71256c369926ab8a2c612d74b69b6159c4b, anchor_block_txid: 83cecd5bbd0a455f8a24867a2c834528f345361be4bc53e8e0018f4beb0fbe74 }), stackerdbs: Some(["ST000000000000000000002AMW42H.signers-0-1", "ST000000000000000000002AMW42H.signers-1-0", "ST000000000000000000002AMW42H.signers-0-7", "ST000000000000000000002AMW42H.signers-0-0", "ST000000000000000000002AMW42H.signers-0-3", "ST000000000000000000002AMW42H.signers-1-12", "ST000000000000000000002AMW42H.signers-1-5", "ST000000000000000000002AMW42H.signers-1-6", "ST000000000000000000002AMW42H.signers-1-9", "ST000000000000000000002AMW42H.signers-0-9", "ST000000000000000000002AMW42H.signers-1-8", "ST000000000000000000002AMW42H.signers-1-11", "ST000000000000000000002AMW42H.signers-1-4", "ST000000000000000000002AMW42H.signers-0-2", "ST000000000000000000002AMW42H.signers-0-12", "ST000000000000000000002AMW42H.signers-0-5", "ST000000000000000000002AMW42H.signers-0-4", "ST000000000000000000002AMW42H.miners", "ST000000000000000000002AMW42H.signers-1-2", "ST000000000000000000002AMW42H.signers-1-10", "ST000000000000000000002AMW42H.signers-1-3", "ST000000000000000000002AMW42H.signers-0-6", "ST000000000000000000002AMW42H.signers-0-8", "ST000000000000000000002AMW42H.signers-1-7", "ST000000000000000000002AMW42H.signers-0-10", "ST000000000000000000002AMW42H.signers-0-11", "ST000000000000000000002AMW42H.signers-1-1"]) }
INFO [1719508110.776455] [stackslib/src/net/rpc.rs:555] [p2p-(127.0.0.1:27511,127.0.0.1:29928)] Handled StacksHTTPRequest, verb: POST, path: /v2/contracts/call-read/ST19F8J5YP9B2G5A650DJS3QMGFWTDA5NWBF1XV86/test-contract-0/get-info, processing_time_ms: 2, latency_ms: 0, conn_id: 260, peer_addr: 127.0.0.1:40934
INFO [1719508110.807690] [stackslib/src/net/rpc.rs:555] [p2p-(127.0.0.1:27511,127.0.0.1:29928)] Handled StacksHTTPRequest, verb: POST, path: /v2/contracts/call-read/ST19F8J5YP9B2G5A650DJS3QMGFWTDA5NWBF1XV86/test-contract-1/get-info, processing_time_ms: 1, latency_ms: 0, conn_id: 261, peer_addr: 127.0.0.1:40936
INFO [1719508110.839047] [stackslib/src/net/rpc.rs:555] [p2p-(127.0.0.1:27511,127.0.0.1:29928)] Handled StacksHTTPRequest, verb: POST, path: /v2/contracts/call-read/ST19F8J5YP9B2G5A650DJS3QMGFWTDA5NWBF1XV86/test-contract-3/get-tenure-info, processing_time_ms: 1, latency_ms: 0, conn_id: 262, peer_addr: 127.0.0.1:40944
INFO [1719508110.870944] [stackslib/src/net/rpc.rs:555] [p2p-(127.0.0.1:27511,127.0.0.1:29928)] Handled StacksHTTPRequest, verb: POST, path: /v2/contracts/call-read/ST19F8J5YP9B2G5A650DJS3QMGFWTDA5NWBF1XV86/test-contract-0/get-info, processing_time_ms: 1, latency_ms: 0, conn_id: 263, peer_addr: 127.0.0.1:40952
thread 'tests::nakamoto_integrations::check_block_info_rewards' panicked at testnet/stacks-node/src/tests/nakamoto_integrations.rs:6427:5:
assertion `left == right` failed
  left: UInt(2040800000)
 right: UInt(3061200000)
stack backtrace:
INFO [1719508111.043630] [stackslib/src/chainstate/nakamoto/coordinator/mod.rs:224] [miner.f35cb3f67b7c0094201def777ec625e550e0fe0e11e8a76b17e32c1e93ddeb78] PoX reward set loaded from written block state, reward_set_block_id: 7afeea6b46b33a519cdffaebcfbb8b6474fe4f1a131dabd3d4e6ecc624dce028
   0:     0x560ab809ebb6 - std::backtrace_rs::backtrace::libunwind::trace::hbee8a7973eeb6c93
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/std/src/../../backtrace/src/backtrace/libunwind.rs:104:5
   1:     0x560ab809ebb6 - std::backtrace_rs::backtrace::trace_unsynchronized::hc8ac75eea3aa6899
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/std/src/../../backtrace/src/backtrace/mod.rs:66:5
   2:     0x560ab809ebb6 - std::sys_common::backtrace::_print_fmt::hc7f3e3b5298b1083
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/std/src/sys_common/backtrace.rs:68:5
   3:     0x560ab809ebb6 - <std::sys_common::backtrace::_print::DisplayBacktrace as core::fmt::Display>::fmt::hbb235daedd7c6190
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/std/src/sys_common/backtrace.rs:44:22
   4:     0x560ab80d0e40 - core::fmt::rt::Argument::fmt::h76c38a80d925a410
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/core/src/fmt/rt.rs:142:9
   5:     0x560ab80d0e40 - core::fmt::write::h3ed6aeaa977c8e45
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/core/src/fmt/mod.rs:1120:17
   6:     0x560ab809a58f - std::io::Write::write_fmt::h78b18af5775fedb5
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/std/src/io/mod.rs:1810:15
   7:     0x560ab809e994 - std::sys_common::backtrace::_print::h5d645a07e0fcfdbb
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/std/src/sys_common/backtrace.rs:47:5
   8:     0x560ab809e994 - std::sys_common::backtrace::print::h85035a511aafe7a8
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/std/src/sys_common/backtrace.rs:34:9
   9:     0x560ab80a0607 - std::panicking::default_hook::{{closure}}::hcce8cea212785a25
  10:     0x560ab80a0369 - std::panicking::default_hook::hf5fcb0f213fe709a
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/std/src/panicking.rs:292:9
  11:     0x560ab80a0a98 - std::panicking::rust_panic_with_hook::h095fccf1dc9379ee
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/std/src/panicking.rs:779:13
  12:     0x560ab80a0972 - std::panicking::begin_panic_handler::{{closure}}::h032ba12139b353db
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/std/src/panicking.rs:657:13
  13:     0x560ab809f0b6 - std::sys_common::backtrace::__rust_end_short_backtrace::h9259bc2ff8fd0f76
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/std/src/sys_common/backtrace.rs:171:18
  14:     0x560ab80a06d0 - rust_begin_unwind
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/std/src/panicking.rs:645:5
  15:     0x560ab666cc65 - core::panicking::panic_fmt::h784f20a50eaab275
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/core/src/panicking.rs:72:14
  16:     0x560ab666d13b - core::panicking::assert_failed_inner::hbf94b40c37b92af0
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/core/src/panicking.rs:342:17
  17:     0x560ab65ada7f - core::panicking::assert_failed::h8925d5d6585e9107
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/core/src/panicking.rs:297:5
  18:     0x560ab685e6e2 - stacks_node::tests::nakamoto_integrations::check_block_info_rewards::hd1642f2049de55a0
                               at /home/wileyj/stacks-core/testnet/stacks-node/src/tests/nakamoto_integrations.rs:6427:5
  19:     0x560ab69fb939 - stacks_node::tests::nakamoto_integrations::check_block_info_rewards::{{closure}}::h8518824d1393c95b
                               at /home/wileyj/stacks-core/testnet/stacks-node/src/tests/nakamoto_integrations.rs:6139:30
  20:     0x560ab69fb939 - core::ops::function::FnOnce::call_once::ha2f589ff24a2ff91
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/core/src/ops/function.rs:250:5
  21:     0x560ab6ccdd6f - core::ops::function::FnOnce::call_once::h8dc6907944022cf6
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/core/src/ops/function.rs:250:5
  22:     0x560ab6ccdd6f - test::__rust_begin_short_backtrace::haae1a87433f1efb3
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/test/src/lib.rs:627:18
  23:     0x560ab6cccaf1 - test::run_test_in_process::{{closure}}::h8c7decfa7c14e152
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/test/src/lib.rs:650:60
  24:     0x560ab6cccaf1 - <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once::h19e6ff056d9d21e9
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/core/src/panic/unwind_safe.rs:272:9
  25:     0x560ab6cccaf1 - std::panicking::try::do_call::h89c848fcaa37c035
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/std/src/panicking.rs:552:40
  26:     0x560ab6cccaf1 - std::panicking::try::h57ab3dc74e2839b8
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/std/src/panicking.rs:516:19
  27:     0x560ab6cccaf1 - std::panic::catch_unwind::hfb6a1b1abc120fb9
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/std/src/panic.rs:142:14
  28:     0x560ab6cccaf1 - test::run_test_in_process::h5ae2f9875edd562d
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/test/src/lib.rs:650:27
  29:     0x560ab6cccaf1 - test::run_test::{{closure}}::h35d7300d8928a067
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/test/src/lib.rs:573:43
  30:     0x560ab6c93e26 - test::run_test::{{closure}}::h7525ced405d23d1b
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/test/src/lib.rs:601:41
  31:     0x560ab6c93e26 - std::sys_common::backtrace::__rust_begin_short_backtrace::h4e7db78ce05afad8
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/std/src/sys_common/backtrace.rs:155:18
  32:     0x560ab6c98e87 - std::thread::Builder::spawn_unchecked_::{{closure}}::{{closure}}::hcfbcb64f1a1b3482
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/std/src/thread/mod.rs:529:17
  33:     0x560ab6c98e87 - <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once::h9d89c5c4108bd689
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/core/src/panic/unwind_safe.rs:272:9
  34:     0x560ab6c98e87 - std::panicking::try::do_call::h8a4869bc94ec50c9
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/std/src/panicking.rs:552:40
  35:     0x560ab6c98e87 - std::panicking::try::h9a576f20ff81ac30
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/std/src/panicking.rs:516:19
  36:     0x560ab6c98e87 - std::panic::catch_unwind::hbcb4e3f860ef9830
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/std/src/panic.rs:142:14
  37:     0x560ab6c98e87 - std::thread::Builder::spawn_unchecked_::{{closure}}::h93c79a6be1505948
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/std/src/thread/mod.rs:528:30
  38:     0x560ab6c98e87 - core::ops::function::FnOnce::call_once{{vtable.shim}}::h426d96740c81bdaf
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/core/src/ops/function.rs:250:5
  39:     0x560ab80a7cf5 - <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once::h12de4fc57affb195
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/alloc/src/boxed.rs:2015:9
  40:     0x560ab80a7cf5 - <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once::h3c619f45059d5cf1
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/alloc/src/boxed.rs:2015:9
  41:     0x560ab80a7cf5 - std::sys::unix::thread::Thread::new::thread_start::hbac657605e4b7389
                               at /rustc/07dca489ac2d933c78d3c5158e3f43beefeb02ce/library/std/src/sys/unix/thread.rs:108:17
  42:     0x7fbcb5758134 - start_thread
                               at ./nptl/pthread_create.c:442:8
  43:     0x7fbcb57d87dc - __GI___clone3
                               at ./misc/../sysdeps/unix/sysv/linux/x86_64/clone3.S:81
  44:                0x0 - <unknown>
test tests::nakamoto_integrations::check_block_info_rewards ... FAILED

failures:

failures:
    tests::nakamoto_integrations::check_block_info_rewards

test result: FAILED. 0 passed; 1 failed; 0 ignored; 0 measured; 149 filtered out; finished in 1186.71s

        FAIL [1186.721s] stacks-node::bin/stacks-node tests::nakamoto_integrations::check_block_info_rewards
------------
     Summary [1186.728s] 1 test run: 0 passed, 1 failed, 5326 skipped
        FAIL [1186.721s] stacks-node::bin/stacks-node tests::nakamoto_integrations::check_block_info_rewards
error: test run failed

[wileyj]

to reproduce:

nextest

standalone

BITCOIND_TEST=1 RUST_BACKTRACE=full cargo nextest run \
    --no-capture \
    --verbose \
    --tests \
    --workspace \
    --run-ignored all \
    --bin stacks-node \
    --package stacks-node \
    --retries 0  \
    --no-fail-fast \
    -E 'test(=tests::nakamoto_integrations::check_block_info_rewards)'
    

nextext archive (this is similar to how CI will execute the test)

cargo nextest archive \
   --build-jobs 8 \
   --workspace \
   --tests \
   --release \
   --archive-file ~/test_archive.tar.zst

RUST_BACKTRACE=1 BITCOIND_TEST=1 cargo nextest run \
   --no-capture \
   --retries 0  \
   --archive-file ~/test_archive.tar.zst \
   --run-ignored all \
   --no-fail-fast \
   --status-level fail \
   -E 'test(=tests::nakamoto_integrations::check_block_info_rewards)'

cargo test

BITCOIND_TEST=1 RUST_BACKTRACE=full cargo test \
    --package stacks-node \
    --bin stacks-node \
    -- \
    tests::nakamoto_integrations::check_block_info_rewards \
    --exact \
    --nocapture \
    --ignored

[wileyj]

possible this value is incorrect? https://github.com/stacks-network/stacks-core/blob/develop/testnet/stacks-node/src/tests/nakamoto_integrations.rs#L6435

[wileyj]

updating that line does pass the test, so i'm not sure if that value is incorrect or the test is off:

ERRO [1719528151.891720] [stackslib/src/burnchains/bitcoin/indexer.rs:687] [run_loop] Failed to fetch Bitcoin headers from 319 - 335: TimedOut
ERRO [1719528151.893670] [stackslib/src/burnchains/burnchain.rs:1150] [run_loop] Failed to check for reorgs from /tmp/stacks-node-tests/integrations-neon/1ee831db9876601c-1719526965/nakamoto-neon/headers.sqlite: TrySyncAgain
ERRO [1719528151.893716] [testnet/stacks-node/src/burnchains/bitcoin_regtest_controller.rs:557] [run_loop] Unable to sync with burnchain: Try synchronizing again
WARN [1719528151.893722] [testnet/stacks-node/src/run_loop/nakamoto.rs:587] [run_loop] Runloop: Burnchain controller stopped: ChainsCoordinator closed
INFO [1719528151.893786] [testnet/stacks-node/src/run_loop/nakamoto.rs:529] [run_loop] Terminating p2p process
INFO [1719528151.893788] [testnet/stacks-node/src/run_loop/nakamoto.rs:530] [run_loop] Terminating relayer
INFO [1719528151.893791] [testnet/stacks-node/src/run_loop/nakamoto.rs:531] [run_loop] Terminating chains-coordinator
INFO [1719528151.901394] [testnet/stacks-node/src/nakamoto_node/peer.rs:140] [p2p-(127.0.0.1:13787,127.0.0.1:8936)] P2P thread exit!
INFO [1719528151.917809] [testnet/stacks-node/src/run_loop/nakamoto.rs:537] [run_loop] Exiting stacks-node
test tests::nakamoto_integrations::check_block_info_rewards ... ok

test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 149 filtered out; finished in 1186.01s

        PASS [1186.019s] stacks-node::bin/stacks-node tests::nakamoto_integrations::check_block_info_rewards
------------
     Summary [1186.028s] 1 test run: 1 passed (1 slow), 5326 skipped
     
 $ git diff
diff --git a/testnet/stacks-node/src/tests/nakamoto_integrations.rs b/testnet/stacks-node/src/tests/nakamoto_integrations.rs
index 8570b0aef..b69711be6 100644
--- a/testnet/stacks-node/src/tests/nakamoto_integrations.rs
+++ b/testnet/stacks-node/src/tests/nakamoto_integrations.rs
@@ -6432,7 +6432,8 @@ fn check_block_info_rewards() {
             .expect_optional()
             .unwrap()
             .unwrap(),
-        Value::UInt(3061200000)
+        Value::UInt(2040800000)
+        //Value::UInt(3061200000)
     );
 
     let result1 = call_read_only(

[obycode]

ah, yes, it's definitely possible that the value is off. I don't think it will definitely be consistent though, so I think we can just check that there is a (some uX).

[wileyj]

I think i have enough to get some timing here - i'll run some CI tests against the PR'ed branch since that does indeed pass (and won't affect timing at all)

[wileyj]

@obycode with the generic assert, it takes ~20 minutes. i don't expect that to change much with a specific value: