Experiment with timeout for tests::nakamoto_integrations::check_block_info_rewards

[obycode]

tests::nakamoto_integrations::check_block_info_rewards is added in #4846 to the "slow" tests, but it likely will take longer than the 30 minute timeout set for those tests when running in CI. We need to experiment with how long it takes, and then create a new job for this longer timeout.

[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:

[obycode]

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

[blockstack-devops]

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.