thread 'consensus::multishard_validator_fee_claim' panicked at dan_layer/consensus_tests/src/support/harness.rs:498:13:
Validator TestAddress(4) did not commit transaction 24697641c1f9c29165ed7440437e42fd80b047bd98d07028755b6c4b58dcb52d
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

running 1 test
2025-02-28T11:26:28.377237355Z [consensus_tests::support::validator::builder] INFO Spawning validator with address TestAddress(3) and public key a45af5c5eeb3db9687fe9edae95387f91ff5a90c442159204c3f97514dddad7c
2025-02-28T11:26:28.382642132Z [tari::dan::consensus::sm::worker] INFO ⚙️ TRANSITION: Idle --- Registered for epoch Epoch(1) ---> CheckSync
2025-02-28T11:26:28.382665015Z [tari::dan::consensus::sm::worker] INFO ⚙️ TRANSITION: CheckSync --- Ready ---> Running
2025-02-28T11:26:28.382789086Z [worker] DEBUG Creating zero block
2025-02-28T11:26:28.383112558Z [worker] INFO ✨Creating genesis block [NodeHeight(0), justify: NodeHeight(0) (\U0001f7e2), Epoch(1), ShardGroup(33-64), 0 cmd(s), 1bb94722b3645335f89da94ba4f4f64b648b45adfcf9e1a2b5b38e6912336fc9->0000000000000000000000000000000000000000000000000000000000000000]
2025-02-28T11:26:28.383428165Z [worker] INFO \U0001f680 Pacemaker starting for epoch Epoch(1), height: NodeHeight(0), high_qc: (block_id: 0000000000000000000000000000000000000000000000000000000000000000, height: NodeHeight(0), qc_id: 47579c79c1a65a18713bc1b00c12fdbe57fedf203db85065df1d54fa7708cfed)
2025-02-28T11:26:28.383452781Z [current_view] INFO \U0001f9ff PACEMAKER: View updated from Epoch(0)/NodeHeight(0) to Epoch(1)/NodeHeight(0)
2025-02-28T11:26:28.383507102Z [on_catch_up_sync] INFO ⏰ Catch up required from block (block_id: 0000000000000000000000000000000000000000000000000000000000000000, height: NodeHeight(0), qc_id: 47579c79c1a65a18713bc1b00c12fdbe57fedf203db85065df1d54fa7708cfed) from TestAddress(4) (current view: Epoch(1)/NodeHeight(0))
2025-02-28T11:26:28.383521048Z [current_view] INFO \U0001f9ff PACEMAKER: reset View updated to Epoch(1)/NodeHeight(0)
2025-02-28T11:26:28.383525306Z [worker] DEBUG \U0001f525 TestAddress(3) Current height #0
2025-02-28T11:26:28.383537949Z [pacemaker] INFO \U0001f680 Starting pacemaker at leaf height Epoch(1)/NodeHeight(0) and high QC: NodeHeight(0)
2025-02-28T11:26:28.383544922Z [pacemaker] INFO Reset! Current height: Epoch(1)/NodeHeight(0), Delta: 20.00s
2025-02-28T11:26:28.383555863Z [pacemaker] INFO \U0001f9ff Pacemaker Reset! Current height: Epoch(1)/NodeHeight(0), Delta: 20.00s
2025-02-28T11:26:28.383575680Z [worker] DEBUG \U0001f525 [on_beat] TestAddress(3) Not leader for height (NodeHeight(1))
2025-02-28T11:26:28.383582683Z [worker] DEBUG \U0001f525 TestAddress(3) Current height #0
2025-02-28T11:26:28.383663223Z [consensus_tests::support::validator::builder] INFO Spawning validator with address TestAddress(2) and public key 9e504f9b10c40230ec4e1570dcf295d5da01aa0daeced57316b160c80bc57e0c
2025-02-28T11:26:28.387855584Z [consensus_tests::support::validator::builder] INFO Spawning validator with address TestAddress(4) and public key 30eb54ee0d290e0fd9f8a6c6cbc84e3a516645fe1be77429987375498aee8641
2025-02-28T11:26:28.391050069Z [tari::dan::consensus::sm::worker] INFO ⚙️ TRANSITION: Idle --- Registered for epoch Epoch(1) ---> CheckSync
2025-02-28T11:26:28.391062762Z [tari::dan::consensus::sm::worker] INFO ⚙️ TRANSITION: CheckSync --- Ready ---> Running
2025-02-28T11:26:28.391124367Z [worker] DEBUG Creating zero block
2025-02-28T11:26:28.391348394Z [worker] INFO ✨Creating genesis block [NodeHeight(0), justify: NodeHeight(0) (\U0001f7e2), Epoch(1), ShardGroup(1-32), 0 cmd(s), 264c11cb7f2d4ccada84c61268de9c9aeda101e23bd6ec80cf0dd1099be170dc->0000000000000000000000000000000000000000000000000000000000000000]
2025-02-28T11:26:28.391687084Z [worker] INFO \U0001f680 Pacemaker starting for epoch Epoch(1), height: NodeHeight(0), high_qc: (block_id: 0000000000000000000000000000000000000000000000000000000000000000, height: NodeHeight(0), qc_id: 43c75e0881370dcdad6795f27e262b2182fc4edb7510f8904b8b0b37652f7cdb)
2025-02-28T11:26:28.391706200Z [current_view] INFO \U0001f9ff PACEMAKER: View updated from Epoch(0)/NodeHeight(0) to Epoch(1)/NodeHeight(0)
2025-02-28T11:26:28.391727870Z [on_catch_up_sync] INFO ⏰ Catch up required from block (block_id: 0000000000000000000000000000000000000000000000000000000000000000, height: NodeHeight(0), qc_id: 43c75e0881370dcdad6795f27e262b2182fc4edb7510f8904b8b0b37652f7cdb) from TestAddress(1) (current view: Epoch(1)/NodeHeight(0))
2025-02-28T11:26:28.391740995Z [current_view] INFO \U0001f9ff PACEMAKER: reset View updated to Epoch(1)/NodeHeight(0)
2025-02-28T11:26:28.391745343Z [worker] DEBUG \U0001f525 TestAddress(2) Current height #0
2025-02-28T11:26:28.391754189Z [pacemaker] INFO \U0001f680 Starting pacemaker at leaf height Epoch(1)/NodeHeight(0) and high QC: NodeHeight(0)
2025-02-28T11:26:28.391761362Z [pacemaker] INFO Reset! Current height: Epoch(1)/NodeHeight(0), Delta: 20.00s
2025-02-28T11:26:28.391766021Z [pacemaker] INFO \U0001f9ff Pacemaker Reset! Current height: Epoch(1)/NodeHeight(0), Delta: 20.00s
2025-02-28T11:26:28.391785868Z [worker] INFO \U0001f525 [on_beat] TestAddress(2) Local node is leader for height (NodeHeight(1)), num local members: 2, ShardGroup(1-32)
2025-02-28T11:26:28.391951246Z [tari::dan::storage::transaction_pool] DEBUG has_ready_or_pending_transaction_updates: No pending state updates
2025-02-28T11:26:28.392023049Z [tari::dan::storage::transaction_pool] DEBUG has_ready_or_pending_transaction_updates: No transactions marked as ready
2025-02-28T11:26:28.392075397Z [tari::dan::storage::transaction_pool] DEBUG has_ready_or_pending_transaction_updates: No transactions that need to be finalized
2025-02-28T11:26:28.392087068Z [worker] INFO [on_beat] No transactions to propose. Waiting for a timeout.
2025-02-28T11:26:28.392089353Z [worker] DEBUG \U0001f525 TestAddress(2) Current height #0
2025-02-28T11:26:28.393229004Z [tari::dan::consensus::sm::worker] INFO ⚙️ TRANSITION: Idle --- Registered for epoch Epoch(1) ---> CheckSync
2025-02-28T11:26:28.393242389Z [tari::dan::consensus::sm::worker] INFO ⚙️ TRANSITION: CheckSync --- Ready ---> Running
2025-02-28T11:26:28.393309373Z [worker] DEBUG Creating zero block
2025-02-28T11:26:28.393572964Z [worker] INFO ✨Creating genesis block [NodeHeight(0), justify: NodeHeight(0) (\U0001f7e2), Epoch(1), ShardGroup(33-64), 0 cmd(s), 1bb94722b3645335f89da94ba4f4f64b648b45adfcf9e1a2b5b38e6912336fc9->0000000000000000000000000000000000000000000000000000000000000000]
2025-02-28T11:26:28.393872371Z [worker] INFO \U0001f680 Pacemaker starting for epoch Epoch(1), height: NodeHeight(0), high_qc: (block_id: 0000000000000000000000000000000000000000000000000000000000000000, height: NodeHeight(0), qc_id: 47579c79c1a65a18713bc1b00c12fdbe57fedf203db85065df1d54fa7708cfed)
2025-02-28T11:26:28.393891186Z [current_view] INFO \U0001f9ff PACEMAKER: View updated from Epoch(0)/NodeHeight(0) to Epoch(1)/NodeHeight(0)
2025-02-28T11:26:28.393936330Z [on_catch_up_sync] INFO ⏰ Catch up required from block (block_id: 0000000000000000000000000000000000000000000000000000000000000000, height: NodeHeight(0), qc_id: 47579c79c1a65a18713bc1b00c12fdbe57fedf203db85065df1d54fa7708cfed) from TestAddress(3) (current view: Epoch(1)/NodeHeight(0))
2025-02-28T11:26:28.393949705Z [current_view] INFO \U0001f9ff PACEMAKER: reset View updated to Epoch(1)/NodeHeight(0)
2025-02-28T11:26:28.393953372Z [worker] DEBUG \U0001f525 TestAddress(4) Current height #0
2025-02-28T11:26:28.393963200Z [pacemaker] INFO \U0001f680 Starting pacemaker at leaf height Epoch(1)/NodeHeight(0) and high QC: NodeHeight(0)
2025-02-28T11:26:28.393970323Z [pacemaker] INFO Reset! Current height: Epoch(1)/NodeHeight(0), Delta: 20.00s
2025-02-28T11:26:28.393974741Z [pacemaker] INFO \U0001f9ff Pacemaker Reset! Current height: Epoch(1)/NodeHeight(0), Delta: 20.00s
2025-02-28T11:26:28.394011209Z [worker] INFO \U0001f525 [on_beat] TestAddress(4) Local node is leader for height (NodeHeight(1)), num local members: 2, ShardGroup(33-64)
2025-02-28T11:26:28.394158403Z [tari::dan::storage::transaction_pool] DEBUG has_ready_or_pending_transaction_updates: No pending state updates
2025-02-28T11:26:28.394200902Z [tari::dan::storage::transaction_pool] DEBUG has_ready_or_pending_transaction_updates: No transactions marked as ready
2025-02-28T11:26:28.394249012Z [tari::dan::storage::transaction_pool] DEBUG has_ready_or_pending_transaction_updates: No transactions that need to be finalized
2025-02-28T11:26:28.394259662Z [worker] INFO [on_beat] No transactions to propose. Waiting for a timeout.
2025-02-28T11:26:28.394261886Z [worker] DEBUG \U0001f525 TestAddress(4) Current height #0
2025-02-28T11:26:28.394335142Z [consensus_tests::support::validator::builder] INFO Spawning validator with address TestAddress(1) and public key cec1426a33965eb2a7d82b281964ad39f06d6fba7d8e57f8da4fcfefd946d855
2025-02-28T11:26:28.398520951Z [tari::dan::consensus::sm::worker] INFO ⚙️ TRANSITION: Idle --- Registered for epoch Epoch(1) ---> CheckSync
2025-02-28T11:26:28.398535027Z [tari::dan::consensus::sm::worker] INFO ⚙️ TRANSITION: CheckSync --- Ready ---> Running
2025-02-28T11:26:28.398593496Z [worker] DEBUG Creating zero block
2025-02-28T11:26:28.398844223Z [worker] INFO ✨Creating genesis block [NodeHeight(0), justify: NodeHeight(0) (\U0001f7e2), Epoch(1), ShardGroup(1-32), 0 cmd(s), 264c11cb7f2d4ccada84c61268de9c9aeda101e23bd6ec80cf0dd1099be170dc->0000000000000000000000000000000000000000000000000000000000000000]
2025-02-28T11:26:28.399207178Z [worker] INFO \U0001f680 Pacemaker starting for epoch Epoch(1), height: NodeHeight(0), high_qc: (block_id: 0000000000000000000000000000000000000000000000000000000000000000, height: NodeHeight(0), qc_id: 43c75e0881370dcdad6795f27e262b2182fc4edb7510f8904b8b0b37652f7cdb)
2025-02-28T11:26:28.399226524Z [current_view] INFO \U0001f9ff PACEMAKER: View updated from Epoch(0)/NodeHeight(0) to Epoch(1)/NodeHeight(0)
2025-02-28T11:26:28.399246732Z [on_catch_up_sync] INFO ⏰ Catch up required from block (block_id: 0000000000000000000000000000000000000000000000000000000000000000, height: NodeHeight(0), qc_id: 43c75e0881370dcdad6795f27e262b2182fc4edb7510f8904b8b0b37652f7cdb) from TestAddress(2) (current view: Epoch(1)/NodeHeight(0))
2025-02-28T11:26:28.399259887Z [current_view] INFO \U0001f9ff PACEMAKER: reset View updated to Epoch(1)/NodeHeight(0)
2025-02-28T11:26:28.399263924Z [worker] DEBUG \U0001f525 TestAddress(1) Current height #0
2025-02-28T11:26:28.399271638Z [pacemaker] INFO \U0001f680 Starting pacemaker at leaf height Epoch(1)/NodeHeight(0) and high QC: NodeHeight(0)
2025-02-28T11:26:28.399278581Z [pacemaker] INFO Reset! Current height: Epoch(1)/NodeHeight(0), Delta: 20.00s
2025-02-28T11:26:28.399283380Z [pacemaker] INFO \U0001f9ff Pacemaker Reset! Current height: Epoch(1)/NodeHeight(0), Delta: 20.00s
2025-02-28T11:26:28.399302285Z [worker] DEBUG \U0001f525 [on_beat] TestAddress(1) Not leader for height (NodeHeight(1))
2025-02-28T11:26:28.399309038Z [worker] DEBUG \U0001f525 TestAddress(1) Current height #0
2025-02-28T11:26:28.400981691Z [consensus_tests::support::harness] INFO \U0001f31f Starting Epoch(1)
2025-02-28T11:26:28.401011496Z [consensus_tests::support::epoch_manager] ERROR Current epoch Epoch(1) -> Epoch(1)
2025-02-28T11:26:28.401019080Z [consensus_tests::support::epoch_manager] ERROR Current epoch Epoch(1) -> Epoch(1)
2025-02-28T11:26:28.401021214Z [consensus_tests::support::epoch_manager] ERROR Current epoch Epoch(1) -> Epoch(1)
2025-02-28T11:26:28.401023077Z [consensus_tests::support::epoch_manager] ERROR Current epoch Epoch(1) -> Epoch(1)
2025-02-28T11:26:28.401026714Z [consensus_tests::support::harness] INFO Validator TestAddress(4): consensus is running
2025-02-28T11:26:28.401029179Z [consensus_tests::support::harness] INFO Validator TestAddress(3): consensus is running
2025-02-28T11:26:28.401031203Z [consensus_tests::support::harness] INFO Validator TestAddress(2): consensus is running
2025-02-28T11:26:28.401033347Z [consensus_tests::support::harness] INFO Validator TestAddress(1): consensus is running
2025-02-28T11:26:28.401042744Z [consensus_tests::support::harness] INFO [TestAddress(2)] Ignoring event: EpochChanged { epoch: Epoch(1), registered_shard_group: Some(ShardGroup { start: Shard(1), end_inclusive: Shard(32) }) }
2025-02-28T11:26:28.401054809Z [worker] INFO \U0001f31f This validator is registered for epoch Epoch(1).
2025-02-28T11:26:28.401256435Z [worker] DEBUG \U0001f525 TestAddress(3) Current height #0
2025-02-28T11:26:28.401260973Z [worker] INFO \U0001f31f This validator is registered for epoch Epoch(1).
2025-02-28T11:26:28.401263067Z [worker] DEBUG \U0001f525 TestAddress(3) Current height #0
2025-02-28T11:26:28.401265371Z [worker] INFO \U0001f31f This validator is registered for epoch Epoch(1).
2025-02-28T11:26:28.401267034Z [worker] DEBUG \U0001f525 TestAddress(3) Current height #0
2025-02-28T11:26:28.401269138Z [worker] INFO \U0001f31f This validator is registered for epoch Epoch(1).
2025-02-28T11:26:28.401270771Z [worker] DEBUG \U0001f525 TestAddress(3) Current height #0
2025-02-28T11:26:28.401065316Z [worker] INFO \U0001f31f This validator is registered for epoch Epoch(1).
2025-02-28T11:26:28.401108126Z [consensus_tests::support::network] INFO \U0001f680 Network started
2025-02-28T11:26:28.401322284Z [consensus_tests::support::network] DEBUG ✉️ Message SyncRequest((block_id: 0000000000000000000000000000000000000000000000000000000000000000, height: NodeHeight(0), qc_id: 43c75e0881370dcdad6795f27e262b2182fc4edb7510f8904b8b0b37652f7cdb)) sent from TestAddress(1) to TestAddress(2)
2025-02-28T11:26:28.401344967Z [consensus_tests::support::network] DEBUG ✉️ Message SyncRequest((block_id: 0000000000000000000000000000000000000000000000000000000000000000, height: NodeHeight(0), qc_id: 47579c79c1a65a18713bc1b00c12fdbe57fedf203db85065df1d54fa7708cfed)) sent from TestAddress(3) to TestAddress(4)
2025-02-28T11:26:28.401360746Z [consensus_tests::support::network] DEBUG ✉️ Message SyncRequest((block_id: 0000000000000000000000000000000000000000000000000000000000000000, height: NodeHeight(0), qc_id: 47579c79c1a65a18713bc1b00c12fdbe57fedf203db85065df1d54fa7708cfed)) sent from TestAddress(4) to TestAddress(3)
2025-02-28T11:26:28.401375934Z [consensus_tests::support::network] DEBUG ✉️ Message SyncRequest((block_id: 0000000000000000000000000000000000000000000000000000000000000000, height: NodeHeight(0), qc_id: 43c75e0881370dcdad6795f27e262b2182fc4edb7510f8904b8b0b37652f7cdb)) sent from TestAddress(2) to TestAddress(1)
2025-02-28T11:26:28.401425837Z [on_message_validate] DEBUG ⏲️ on_message_validate took 501.00ns
2025-02-28T11:26:28.401473275Z [worker] DEBUG \U0001f525 TestAddress(3) Current height #0
2025-02-28T11:26:28.401536252Z [on_sync_request] INFO This node is at height 0 so cannot return any sync blocks. Ignoring request
2025-02-28T11:26:28.401548045Z [on_sync_request] INFO \U0001f310 Sending 0 block(s) (NodeHeight(0) to NodeHeight(0)) to TestAddress(4)
2025-02-28T11:26:28.401592768Z [consensus_tests::support::network] INFO \U0001f41e New transaction 4c058bae703f8e94c1166ba71899b098c5d837b4ed10a9c7482e8e41b99f6add for vn TestAddress(3)
2025-02-28T11:26:28.401605111Z [consensus_tests::support::network] INFO \U0001f41e New transaction 4c058bae703f8e94c1166ba71899b098c5d837b4ed10a9c7482e8e41b99f6add for vn TestAddress(2)
2025-02-28T11:26:28.401610882Z [consensus_tests::support::network] INFO \U0001f41e New transaction 4c058bae703f8e94c1166ba71899b098c5d837b4ed10a9c7482e8e41b99f6add for vn TestAddress(4)
2025-02-28T11:26:28.401621080Z [consensus_tests::support::network] INFO \U0001f41e New transaction 4c058bae703f8e94c1166ba71899b098c5d837b4ed10a9c7482e8e41b99f6add for vn TestAddress(1)
2025-02-28T11:26:28.401628484Z [consensus_tests::support::network] INFO \U0001f41e New transaction ac8c2467fca072e12796d6999ef54beba351f189573c9a854fd4e6babd9ac1a2 for vn TestAddress(3)
2025-02-28T11:26:28.401638393Z [consensus_tests::support::network] INFO \U0001f41e New transaction ac8c2467fca072e12796d6999ef54beba351f189573c9a854fd4e6babd9ac1a2 for vn TestAddress(2)
2025-02-28T11:26:28.401646608Z [consensus_tests::support::network] INFO \U0001f41e New transaction ac8c2467fca072e12796d6999ef54beba351f189573c9a854fd4e6babd9ac1a2 for vn TestAddress(4)
2025-02-28T11:26:28.401656015Z [consensus_tests::support::network] INFO \U0001f41e New transaction ac8c2467fca072e12796d6999ef54beba351f189573c9a854fd4e6babd9ac1a2 for vn TestAddress(1)
2025-02-28T11:26:28.401800845Z [on_receive_new_transaction] INFO \U0001f525 Adding transaction 4c058bae703f8e94c1166ba71899b098c5d837b4ed10a9c7482e8e41b99f6add (2 input(s)) to pool. Is ready: true
2025-02-28T11:26:28.401887686Z [worker] INFO \U0001f525 new transaction ready for consensus: 4c058bae703f8e94c1166ba71899b098c5d837b4ed10a9c7482e8e41b99f6add (0 pending)
2025-02-28T11:26:28.401956054Z [on_message_validate] DEBUG ⏲️ update_local_parked_blocks took 55.79µs for 1 iterations (avg: 0ms)
2025-02-28T11:26:28.401968767Z [worker] INFO ⏲️ on_new_transaction took 304.58µs
2025-02-28T11:26:28.401971412Z [worker] DEBUG \U0001f525 TestAddress(3) Current height #0
2025-02-28T11:26:28.402005235Z [worker] DEBUG \U0001f525 [on_beat] TestAddress(3) Not leader for height (NodeHeight(1))
2025-02-28T11:26:28.402013531Z [worker] DEBUG \U0001f525 TestAddress(3) Current height #0
2025-02-28T11:26:28.402062652Z [on_receive_new_transaction] INFO \U0001f525 Adding transaction ac8c2467fca072e12796d6999ef54beba351f189573c9a854fd4e6babd9ac1a2 (2 input(s)) to pool. Is ready: true
2025-02-28T11:26:28.402107646Z [worker] INFO \U0001f525 new transaction ready for consensus: ac8c2467fca072e12796d6999ef54beba351f189573c9a854fd4e6babd9ac1a2 (0 pending)
2025-02-28T11:26:28.402137682Z [on_message_validate] DEBUG ⏲️ update_local_parked_blocks took 16.93µs for 1 iterations (avg: 0ms)
2025-02-28T11:26:28.402142170Z [worker] INFO ⏲️ on_new_transaction took 123.96µs
2025-02-28T11:26:28.402144515Z [worker] DEBUG \U0001f525 TestAddress(3) Current height #0
2025-02-28T11:26:28.402157298Z [worker] DEBUG \U0001f525 [on_beat] TestAddress(3) Not leader for height (NodeHeight(1))
2025-02-28T11:26:28.402198595Z [worker] DEBUG \U0001f525 TestAddress(3) Current height #0
2025-02-28T11:26:28.401227438Z [worker] INFO \U0001f31f This validator is registered for epoch Epoch(1).
2025-02-28T11:26:28.402224794Z [worker] DEBUG \U0001f525 TestAddress(1) Current height #0
2025-02-28T11:26:28.402227599Z [worker] INFO \U0001f31f This validator is registered for epoch Epoch(1).
2025-02-28T11:26:28.401279097Z [worker] INFO \U0001f31f This validator is registered for epoch Epoch(1).
2025-02-28T11:26:28.402236729Z [worker] DEBUG \U0001f525 TestAddress(2) Current height #0
2025-02-28T11:26:28.402229392Z [worker] DEBUG \U0001f525 TestAddress(1) Current height #0
2025-02-28T11:26:28.402251123Z [worker] INFO \U0001f31f This validator is registered for epoch Epoch(1).
2025-02-28T11:26:28.402252866Z [worker] DEBUG \U0001f525 TestAddress(1) Current height #0
2025-02-28T11:26:28.402409460Z [on_receive_new_transaction] INFO \U0001f525 Adding transaction 4c058bae703f8e94c1166ba71899b098c5d837b4ed10a9c7482e8e41b99f6add (2 input(s)) to pool. Is ready: true
2025-02-28T11:26:28.402481471Z [on_receive_new_transaction] INFO \U0001f525 Adding transaction 4c058bae703f8e94c1166ba71899b098c5d837b4ed10a9c7482e8e41b99f6add (2 input(s)) to pool. Is ready: true
2025-02-28T11:26:28.402527156Z [worker] DEBUG \U0001f525 TestAddress(4) Current height #0
2025-02-28T11:26:28.402611854Z [on_message_validate] DEBUG ⏲️ on_message_validate took 401.00ns
2025-02-28T11:26:28.402597587Z [worker] INFO \U0001f525 new transaction ready for consensus: 4c058bae703f8e94c1166ba71899b098c5d837b4ed10a9c7482e8e41b99f6add (0 pending)
2025-02-28T11:26:28.402543289Z [worker] INFO \U0001f525 new transaction ready for consensus: 4c058bae703f8e94c1166ba71899b098c5d837b4ed10a9c7482e8e41b99f6add (0 pending)
2025-02-28T11:26:28.402745152Z [on_message_validate] DEBUG ⏲️ update_local_parked_blocks took 90.88µs for 1 iterations (avg: 0ms)
2025-02-28T11:26:28.402768345Z [worker] INFO ⏲️ on_new_transaction took 511.19µs
2025-02-28T11:26:28.402781179Z [worker] DEBUG \U0001f525 TestAddress(1) Current height #0
2025-02-28T11:26:28.402841161Z [on_receive_new_transaction] INFO \U0001f525 Adding transaction ac8c2467fca072e12796d6999ef54beba351f189573c9a854fd4e6babd9ac1a2 (2 input(s)) to pool. Is ready: true
2025-02-28T11:26:28.402898027Z [worker] INFO \U0001f525 new transaction ready for consensus: ac8c2467fca072e12796d6999ef54beba351f189573c9a854fd4e6babd9ac1a2 (0 pending)
2025-02-28T11:26:28.402929545Z [on_message_validate] DEBUG ⏲️ update_local_parked_blocks took 12.85µs for 1 iterations (avg: 0ms)
2025-02-28T11:26:28.402944894Z [worker] INFO ⏲️ on_new_transaction took 149.30µs
2025-02-28T11:26:28.402957287Z [worker] DEBUG \U0001f525 TestAddress(1) Current height #0
2025-02-28T11:26:28.402970041Z [worker] INFO \U0001f31f This validator is registered for epoch Epoch(1).
2025-02-28T11:26:28.402981682Z [worker] DEBUG \U0001f525 TestAddress(1) Current height #0
2025-02-28T11:26:28.403027287Z [worker] DEBUG \U0001f525 [on_beat] TestAddress(1) Not leader for height (NodeHeight(1))
2025-02-28T11:26:28.403041183Z [worker] DEBUG \U0001f525 TestAddress(1) Current height #0
2025-02-28T11:26:28.403059026Z [on_message_validate] DEBUG ⏲️ on_message_validate took 280.00ns
2025-02-28T11:26:28.403108699Z [worker] DEBUG \U0001f525 TestAddress(1) Current height #0
2025-02-28T11:26:28.403165815Z [on_sync_request] INFO This node is at height 0 so cannot return any sync blocks. Ignoring request
2025-02-28T11:26:28.403184940Z [on_sync_request] INFO \U0001f310 Sending 0 block(s) (NodeHeight(0) to NodeHeight(0)) to TestAddress(2)
2025-02-28T11:26:28.403289806Z [worker] DEBUG \U0001f525 TestAddress(4) Current height #0
2025-02-28T11:26:28.403432261Z [on_receive_new_transaction] INFO \U0001f525 Adding transaction 4c058bae703f8e94c1166ba71899b098c5d837b4ed10a9c7482e8e41b99f6add (2 input(s)) to pool. Is ready: true
2025-02-28T11:26:28.403549158Z [worker] INFO \U0001f525 new transaction ready for consensus: 4c058bae703f8e94c1166ba71899b098c5d837b4ed10a9c7482e8e41b99f6add (0 pending)
2025-02-28T11:26:28.402754142Z [on_message_validate] DEBUG ⏲️ update_local_parked_blocks took 82.88µs for 1 iterations (avg: 0ms)
2025-02-28T11:26:28.403612299Z [worker] INFO ⏲️ on_new_transaction took 1.37ms
2025-02-28T11:26:28.403615234Z [worker] DEBUG \U0001f525 TestAddress(2) Current height #0
2025-02-28T11:26:28.403621583Z [on_message_validate] DEBUG ⏲️ update_local_parked_blocks took 50.44µs for 1 iterations (avg: 0ms)
2025-02-28T11:26:28.403627134Z [worker] INFO ⏲️ on_new_transaction took 319.06µs
2025-02-28T11:26:28.403629618Z [worker] DEBUG \U0001f525 TestAddress(4) Current height #0
2025-02-28T11:26:28.403634740Z [worker] INFO \U0001f525 [on_beat] TestAddress(2) Local node is leader for height (NodeHeight(1)), num local members: 2, ShardGroup(1-32)
2025-02-28T11:26:28.403644766Z [worker] INFO \U0001f525 [on_beat] TestAddress(4) Local node is leader for height (NodeHeight(1)), num local members: 2, ShardGroup(33-64)
2025-02-28T11:26:28.403736039Z [tari::dan::storage::transaction_pool] DEBUG has_ready_or_pending_transaction_updates: No pending state updates
2025-02-28T11:26:28.403736257Z [tari::dan::storage::transaction_pool] DEBUG has_ready_or_pending_transaction_updates: No pending state updates
2025-02-28T11:26:28.403754313Z [tari::dan::storage::transaction_pool] DEBUG has_ready_or_pending_transaction_updates: 1 transactions marked as ready
2025-02-28T11:26:28.403755001Z [tari::dan::storage::transaction_pool] DEBUG has_ready_or_pending_transaction_updates: 1 transactions marked as ready
2025-02-28T11:26:28.404053467Z [on_sync_request] INFO This node is at height 0 so cannot return any sync blocks. Ignoring request
2025-02-28T11:26:28.404067994Z [on_sync_request] INFO \U0001f310 Sending 0 block(s) (NodeHeight(0) to NodeHeight(0)) to TestAddress(3)
2025-02-28T11:26:28.404193557Z [on_local_propose] INFO \U0001f33f PROPOSE local block with parent LeafBlock(NodeHeight(0) 264c11cb7f2d4ccada84c61268de9c9aeda101e23bd6ec80cf0dd1099be170dc Epoch(1)). HighQC: Qc(block: NodeHeight(0) 0000000000000000000000000000000000000000000000000000000000000000, qc_id: 43c75e0881370dcdad6795f27e262b2182fc4edb7510f8904b8b0b37652f7cdb, epoch: Epoch(1), 0 signatures)
2025-02-28T11:26:28.404205372Z [on_local_propose] INFO \U0001f33f PROPOSE local block with parent LeafBlock(NodeHeight(0) 1bb94722b3645335f89da94ba4f4f64b648b45adfcf9e1a2b5b38e6912336fc9 Epoch(1)). HighQC: Qc(block: NodeHeight(0) 0000000000000000000000000000000000000000000000000000000000000000, qc_id: 47579c79c1a65a18713bc1b00c12fdbe57fedf203db85065df1d54fa7708cfed, epoch: Epoch(1), 0 signatures)
2025-02-28T11:26:28.404809416Z [tari::dan::storage::state_store_sqlite::reader] DEBUG \U0001f6e2️ transaction_pool_get_many_ready: block_id=264c11cb7f2d4ccada84c61268de9c9aeda101e23bd6ec80cf0dd1099be170dc, in progress ready_txs=0, max=500
2025-02-28T11:26:28.406018516Z [tari::dan::storage::state_store_sqlite::reader] DEBUG transaction_pool_get_many_ready: locked.block_id=264c11cb7f2d4ccada84c61268de9c9aeda101e23bd6ec80cf0dd1099be170dc, leaf.block_id=264c11cb7f2d4ccada84c61268de9c9aeda101e23bd6ec80cf0dd1099be170dc, len(ready_txs)=0, updates=0
2025-02-28T11:26:28.406153758Z [tari::dan::storage::state_store_sqlite::reader] DEBUG get_block_ids_between: start: 264c11cb7f2d4ccada84c61268de9c9aeda101e23bd6ec80cf0dd1099be170dc, end: 264c11cb7f2d4ccada84c61268de9c9aeda101e23bd6ec80cf0dd1099be170dc
2025-02-28T11:26:28.406208009Z [tari::dan::storage::state_store_sqlite::reader] DEBUG get_transaction_atom_state_updates_between_blocks: from_block_id=264c11cb7f2d4ccada84c61268de9c9aeda101e23bd6ec80cf0dd1099be170dc, to_block_id=264c11cb7f2d4ccada84c61268de9c9aeda101e23bd6ec80cf0dd1099be170dc, len(applicable_block_ids)=1
2025-02-28T11:26:28.406377224Z [tari::dan::storage::state_store_sqlite::reader] DEBUG \U0001f6e2️ transaction_pool_get_many_ready: block_id=264c11cb7f2d4ccada84c61268de9c9aeda101e23bd6ec80cf0dd1099be170dc, new ready_txs=1, total ready_txs=1, max=500, updates=0
2025-02-28T11:26:28.406420224Z [on_local_propose] DEBUG ⏲️ fetch_next_proposal_batch took 2.18ms
2025-02-28T11:26:28.406423730Z [on_local_propose] DEBUG \U0001f33f PROPOSE: 1 transaction(s), 0 foreign proposal(s), 0 UTXOs, 0 evict, 0 command(s)
2025-02-28T11:26:28.406563571Z [on_local_propose] INFO \U0001f468‍\U0001f527 PROPOSE: PREPARE transaction 4c058bae703f8e94c1166ba71899b098c5d837b4ed10a9c7482e8e41b99f6add
2025-02-28T11:26:28.406689786Z [tari::dan::hotstuff::substate_store::pending_store] DEBUG assert_is_up: id: component_000000000000000000000000000000005478645a28bd884be1929703d22403ff:0, pending: {}, head: {}
2025-02-28T11:26:28.406703611Z [tari::dan::hotstuff::substate_store::pending_store] DEBUG assert_is_up id: component_000000000000000000000000000000005478645a28bd884be1929703d22403ff:0 not found in pending
2025-02-28T11:26:28.406819647Z [tari::dan::hotstuff::substate_store::pending_store] DEBUG assert_is_up: id: component_000000000000000000000000000000005478645a28bd884be1929703d22403ff:0 not found in block diff
2025-02-28T11:26:28.406900487Z [block_transaction_executor] INFO Resolved LOCAL substate: component_000000000000000000000000000000005478645a28bd884be1929703d22403ff:0
2025-02-28T11:26:28.406920845Z [tari::dan::storage::state_store_sqlite::reader] DEBUG get_block_ids_between: start: 264c11cb7f2d4ccada84c61268de9c9aeda101e23bd6ec80cf0dd1099be170dc, end: 264c11cb7f2d4ccada84c61268de9c9aeda101e23bd6ec80cf0dd1099be170dc
2025-02-28T11:26:28.407097314Z [tari::dan::hotstuff::substate_store::pending_store] INFO \U0001f512️ Requested substate lock: component_000000000000000000000000000000005478645a28bd884be1929703d22403ff:0 lock ver: 0 (Write)
2025-02-28T11:26:28.407148239Z [tari::dan::hotstuff::substate_store::pending_store] DEBUG assert_is_up: id: component_000000000000000000000000000000005478645a28bd884be1929703d22403ff:0, pending: {}, head: {}
2025-02-28T11:26:28.407158167Z [tari::dan::hotstuff::substate_store::pending_store] DEBUG assert_is_up id: component_000000000000000000000000000000005478645a28bd884be1929703d22403ff:0 not found in pending
2025-02-28T11:26:28.407256450Z [tari::dan::hotstuff::substate_store::pending_store] DEBUG assert_is_up: id: component_000000000000000000000000000000005478645a28bd884be1929703d22403ff:0 not found in block diff
2025-02-28T11:26:28.407291245Z [tari::dan::hotstuff::substate_store::pending_store] DEBUG \U0001f512️ Adding new lock: component_000000000000000000000000000000005478645a28bd884be1929703d22403ff SubstateLock(version: 0, lock_flag: Write, is_local_only: false, transaction_id: 4c058bae703f8e94c1166ba71899b098c5d837b4ed10a9c7482e8e41b99f6add)
2025-02-28T11:26:28.407306754Z [block_transaction_executor] INFO \U0001f468‍\U0001f527 PREPARE: Multishard transaction 4c058bae703f8e94c1166ba71899b098c5d837b4ed10a9c7482e8e41b99f6add requires additional input pledges. Partial evidence: {ShardGroup(1-32): inputs[component_000000000000000000000000000000005478645a28bd884be1929703d22403ff: v0 Write],outputs[] Prepare[NONE] Accept[NONE], ShardGroup(33-64): inputs[component_83ffffffffffffffffffffffffffffff97d983c894ac97e9d5721e6b5bd0aafb: None],outputs[] Prepare[NONE] Accept[NONE]}
2025-02-28T11:26:28.407325028Z [block_transaction_executor] INFO ⏲️ prepare took 754.91µs
2025-02-28T11:26:28.407330347Z [on_local_propose] INFO \U0001f30d Transaction involves foreign shard groups, proposing Prepare(4c058bae703f8e94c1166ba71899b098c5d837b4ed10a9c7482e8e41b99f6add, Commit)
2025-02-28T11:26:28.407343702Z [on_local_propose] INFO ⏲️ Generating commands took 780.76µs for 1 iterations (avg: 0ms)
2025-02-28T11:26:28.407347239Z [on_local_propose] DEBUG command(s) for next block: [{Prepare(4c058bae703f8e94c1166ba71899b098c5d837b4ed10a9c7482e8e41b99f6add, Commit)}]
2025-02-28T11:26:28.407364521Z [tari::dan::storage::state_store_sqlite::reader] DEBUG get_block_ids_between: start: 264c11cb7f2d4ccada84c61268de9c9aeda101e23bd6ec80cf0dd1099be170dc, end: 264c11cb7f2d4ccada84c61268de9c9aeda101e23bd6ec80cf0dd1099be170dc
2025-02-28T11:26:28.407482721Z [on_local_propose] INFO ⏲️ Propose calculate state root took 125.20µs
2025-02-28T11:26:28.408104227Z [tari::dan::storage::state_store_sqlite::reader] DEBUG \U0001f6e2️ transaction_pool_get_many_ready: block_id=1bb94722b3645335f89da94ba4f4f64b648b45adfcf9e1a2b5b38e6912336fc9, in progress ready_txs=0, max=500
2025-02-28T11:26:28.408127330Z [tari::dan::storage::state_store_sqlite::reader] DEBUG transaction_pool_get_many_ready: locked.block_id=1bb94722b3645335f89da94ba4f4f64b648b45adfcf9e1a2b5b38e6912336fc9, leaf.block_id=1bb94722b3645335f89da94ba4f4f64b648b45adfcf9e1a2b5b38e6912336fc9, len(ready_txs)=0, updates=0
2025-02-28T11:26:28.408149790Z [on_local_propose] INFO \U0001f33f [9e504f9b10c40230ec4e1570dcf295d5da01aa0daeced57316b160c80bc57e0c] PROPOSING new local block [NodeHeight(1), justify: NodeHeight(0) (\U0001f7e1), Epoch(1), ShardGroup(1-32), 1 cmd(s), 96083f8ae744037f54d933d246fc113562d0e1dde7dc29e366b9e77e1ac7eeae->264c11cb7f2d4ccada84c61268de9c9aeda101e23bd6ec80cf0dd1099be170dc] to 2 validators. justify: 0000000000000000000000000000000000000000000000000000000000000000 (NodeHeight(0)), parent: 264c11cb7f2d4ccada84c61268de9c9aeda101e23bd6ec80cf0dd1099be170dc
2025-02-28T11:26:28.408196186Z [on_local_propose] INFO \U0001f33f Broadcasting local proposal to 2/2 local committee members LeafBlock(NodeHeight(1) 96083f8ae744037f54d933d246fc113562d0e1dde7dc29e366b9e77e1ac7eeae Epoch(1))
2025-02-28T11:26:28.408214029Z [on_local_propose] INFO ⏲️ OnPropose took 4.44ms
2025-02-28T11:26:28.408227384Z [worker] DEBUG \U0001f525 TestAddress(2) Current height #0
2025-02-28T11:26:28.408246703Z [tari::dan::storage::state_store_sqlite::reader] DEBUG get_block_ids_between: start: 1bb94722b3645335f89da94ba4f4f64b648b…1ff5a90c442159204c3f97514dddad7c to next leader TestAddress(4)
2025-02-28T11:26:28.687020662Z [on_receive_local_proposal] DEBUG ⏲️ SendVoteToLeader took 182.93µs
2025-02-28T11:26:28.687032945Z [on_receive_local_proposal] DEBUG ⏲️ OnReceiveLocalProposalHandler took 6.74ms
2025-02-28T11:26:28.687036692Z [worker] DEBUG \U0001f525 TestAddress(3) Current height #16
2025-02-28T11:26:28.687043064Z [inbound_messages] INFO \U0001f5d1️ Discard message Proposal(Epoch=Epoch(1),Height=NodeHeight(16),QC=NodeHeight(15)) is for previous view Epoch(1)/NodeHeight(16). Current view Epoch(1)/NodeHeight(17)
2025-02-28T11:26:28.687057951Z [consensus_tests::support::network] DEBUG ✉️ Message Vote(NodeHeight(16), Epoch(1), 1e363d9528f7fb1713e913fa2cff1056288ea8caae6149374ffeced48343b0f9, Accept) sent from TestAddress(3) to TestAddress(4)
2025-02-28T11:26:28.687081245Z [pacemaker] INFO \U0001f9ff Pacemaker Reset! Current height: Epoch(1)/NodeHeight(16), Delta: 2.00s
2025-02-28T11:26:28.687171412Z [on_local_propose] INFO \U0001f33f PROPOSE local block with parent LeafBlock(NodeHeight(15) fba7cfd16f9919c41653d61c313979f92c5b8aeaaa46da539533a9a629a40a15 Epoch(1)). HighQC: Qc(block: NodeHeight(15) fba7cfd16f9919c41653d61c313979f92c5b8aeaaa46da539533a9a629a40a15, qc_id: 2cfa31f98b8305fbabe8c90c99510e50a182e021302e3b7104ce79d187779b0c, epoch: Epoch(1), 2 signatures)
2025-02-28T11:26:28.687488593Z [tari::dan::storage::state_store_sqlite::reader] DEBUG \U0001f6e2️ transaction_pool_get_many_ready: block_id=fba7cfd16f9919c41653d61c313979f92c5b8aeaaa46da539533a9a629a40a15, in progress ready_txs=0, max=500
2025-02-28T11:26:28.687511525Z [tari::dan::storage::state_store_sqlite::reader] DEBUG transaction_pool_get_many_ready: locked.block_id=cdf328634f8c83cfcf20aa349c06285bfff669092f58ca2c1b53984acd1bfd84, leaf.block_id=fba7cfd16f9919c41653d61c313979f92c5b8aeaaa46da539533a9a629a40a15, len(ready_txs)=0, updates=0
2025-02-28T11:26:28.687529479Z [tari::dan::storage::state_store_sqlite::reader] DEBUG \U0001f6e2️ transaction_pool_get_many_ready: block_id=fba7cfd16f9919c41653d61c313979f92c5b8aeaaa46da539533a9a629a40a15, new ready_txs=0, total ready_txs=0, max=500, updates=0
2025-02-28T11:26:28.687539938Z [on_local_propose] DEBUG ⏲️ fetch_next_proposal_batch took 347.40µs
2025-02-28T11:26:28.687542803Z [on_local_propose] DEBUG \U0001f33f PROPOSE: 0 transaction(s), 0 foreign proposal(s), 0 UTXOs, 0 evict, 0 command(s)
2025-02-28T11:26:28.687546561Z [on_local_propose] INFO ⏲️ Generating commands took 370.00ns for 0 iterations (avg: NaNms)
2025-02-28T11:26:28.687549666Z [on_local_propose] DEBUG command(s) for next block: [{}]
2025-02-28T11:26:28.687561709Z [tari::dan::storage::state_store_sqlite::reader] DEBUG get_block_ids_between: start: e0ac3be2c767975ac01cb35be88443d290cddadd226f7b41d86b9a8c18cce26c, end: fba7cfd16f9919c41653d61c313979f92c5b8aeaaa46da539533a9a629a40a15
2025-02-28T11:26:28.687758435Z [tari::dan::consensus::sharded_state_tree] DEBUG PENDING INSERT: node v1: leaf: None
2025-02-28T11:26:28.687771459Z [tari::dan::consensus::sharded_state_tree] DEBUG PENDING INSERT: node v1:0 leaf: 93f01dafa26091e27ea67da331b85417e33e7c2a9714ea23842d6dd05aa6e8ae
2025-02-28T11:26:28.687775977Z [tari::dan::consensus::sharded_state_tree] DEBUG PENDING INSERT: node v1:c leaf: 8fe1c0d685f00200609af6b04b5f334ee07b15750b54f7f9a0ac017ed433f3e9
2025-02-28T11:26:28.687780336Z [tari::dan::consensus::sharded_state_tree] DEBUG PENDING INSERT: node v1:b leaf: 2bc158300fe347edbf7b6eff2542216ab7ad054628d464e2c96ddb4ebf9ce236
2025-02-28T11:26:28.687784353Z [tari::dan::consensus::sharded_state_tree] DEBUG PENDING INSERT: node v1:e leaf: 083602b8c3170f99d2f6766c3f4352262068edbc6f4a1155ed47860a4354ed01
2025-02-28T11:26:28.687795353Z [tari::dan::consensus::sharded_state_tree] DEBUG PENDING INSERT: node v1:f leaf: 64ef259f8be25701a498c02c269647de4dd2a1fc5dbbb1b92da6365f25230803
2025-02-28T11:26:28.687824468Z [tari::dan::consensus::sharded_state_tree] DEBUG PENDING INSERT: node v1: leaf: b27edf0c2bae39c0da37d97ef38cf20dc2ab98106a37e303ab6f99d59fa071fa
2025-02-28T11:26:28.687856738Z [on_local_propose] INFO ⏲️ Propose calculate state root took 304.51µs
2025-02-28T11:26:28.688022907Z [on_local_propose] INFO \U0001f33f [cec1426a33965eb2a7d82b281964ad39f06d6fba7d8e57f8da4fcfefd946d855] PROPOSING new local block [NodeHeight(16), justify: NodeHeight(15) (\U0001f7e2), Epoch(1), ShardGroup(1-32), 0 cmd(s), 03345cbe10d03d2f8ecf215b6c763c5cbf2dde6c33648d74060e8360e63d0cc0->fba7cfd16f9919c41653d61c313979f92c5b8aeaaa46da539533a9a629a40a15] to 2 validators. justify: fba7cfd16f9919c41653d61c313979f92c5b8aeaaa46da539533a9a629a40a15 (NodeHeight(15)), parent: fba7cfd16f9919c41653d61c313979f92c5b8aeaaa46da539533a9a629a40a15
2025-02-28T11:26:28.688048014Z [on_local_propose] INFO \U0001f33f Broadcasting local proposal to 2/2 local committee members LeafBlock(NodeHeight(16) 03345cbe10d03d2f8ecf215b6c763c5cbf2dde6c33648d74060e8360e63d0cc0 Epoch(1))
2025-02-28T11:26:28.688054696Z [on_local_propose] INFO ⏲️ OnPropose took 1.39ms
2025-02-28T11:26:28.688057952Z [worker] DEBUG \U0001f525 TestAddress(1) Current height #15
2025-02-28T11:26:28.688065226Z [on_message_validate] INFO \U0001f4dc new unvalidated PROPOSAL message [NodeHeight(16), justify: NodeHeight(15) (\U0001f7e2), Epoch(1), ShardGroup(1-32), 0 cmd(s), 03345cbe10d03d2f8ecf215b6c763c5cbf2dde6c33648d74060e8360e63d0cc0->fba7cfd16f9919c41653d61c313979f92c5b8aeaaa46da539533a9a629a40a15] from cec1426a33965eb2a7d82b281964ad39f06d6fba7d8e57f8da4fcfefd946d855 (current height = NodeHeight(15))
2025-02-28T11:26:28.688080724Z [block_validations] DEBUG Validating signature block_id=03345cbe10d03d2f8ecf215b6c763c5cbf2dde6c33648d74060e8360e63d0cc0, P=cec1426a33965eb2a7d82b281964ad39f06d6fba7d8e57f8da4fcfefd946d855, R=8c07095c80df4b1a80313187398c195cfab9d370a75eba5e48cf283ed7a0f82a
2025-02-28T11:26:28.688337903Z [on_message_validate] DEBUG ✅ Block [NodeHeight(16), justify: NodeHeight(15) (\U0001f7e2), Epoch(1), ShardGroup(1-32), 0 cmd(s), 03345cbe10d03d2f8ecf215b6c763c5cbf2dde6c33648d74060e8360e63d0cc0->fba7cfd16f9919c41653d61c313979f92c5b8aeaaa46da539533a9a629a40a15] is empty (no missing transactions)
2025-02-28T11:26:28.688352541Z [on_message_validate] DEBUG ⏲️ on_message_validate took 287.55µs
2025-02-28T11:26:28.688358121Z [on_receive_local_proposal] DEBUG \U0001f525 LOCAL PROPOSAL: block [NodeHeight(16), justify: NodeHeight(15) (\U0001f7e2), Epoch(1), ShardGroup(1-32), 0 cmd(s), 03345cbe10d03d2f8ecf215b6c763c5cbf2dde6c33648d74060e8360e63d0cc0->fba7cfd16f9919c41653d61c313979f92c5b8aeaaa46da539533a9a629a40a15] from cec1426a33965eb2a7d82b281964ad39f06d6fba7d8e57f8da4fcfefd946d855
2025-02-28T11:26:28.688637992Z [on_receive_local_proposal] INFO ✅ Block ValidBlock([NodeHeight(16), justify: NodeHeight(15) (\U0001f7e2), Epoch(1), ShardGroup(1-32), 0 cmd(s), 03345cbe10d03d2f8ecf215b6c763c5cbf2dde6c33648d74060e8360e63d0cc0->fba7cfd16f9919c41653d61c313979f92c5b8aeaaa46da539533a9a629a40a15]) is valid and persisted.
2025-02-28T11:26:28.688665503Z [on_receive_local_proposal] DEBUG RECV-LOCAL-PROPOSAL - [Epoch(1)] Starting processing block: ValidBlock([NodeHeight(16), justify: NodeHeight(15) (\U0001f7e2), Epoch(1), ShardGroup(1-32), 0 cmd(s), 03345cbe10d03d2f8ecf215b6c763c5cbf2dde6c33648d74060e8360e63d0cc0->fba7cfd16f9919c41653d61c313979f92c5b8aeaaa46da539533a9a629a40a15])
2025-02-28T11:26:28.688691461Z [pacemaker] DEBUG \U0001f9ff Pacemaker suspend
2025-02-28T11:26:28.688699406Z [on_ready_to_vote_on_local_block] DEBUG \U0001f525 LOCAL PROPOSAL READY: ValidBlock([NodeHeight(16), justify: NodeHeight(15) (\U0001f7e2), Epoch(1), ShardGroup(1-32), 0 cmd(s), 03345cbe10d03d2f8ecf215b6c763c5cbf2dde6c33648d74060e8360e63d0cc0->fba7cfd16f9919c41653d61c313979f92c5b8aeaaa46da539533a9a629a40a15])
2025-02-28T11:26:28.688701570Z [consensus_tests::support::network] DEBUG ✉️ Broadcast Proposal(Epoch=Epoch(1),Height=NodeHeight(16),QC=NodeHeight(15)) from TestAddress(1) to TestAddress(1), TestAddress(2)
2025-02-28T11:26:28.688788982Z [on_message_validate] INFO \U0001f4dc new unvalidated PROPOSAL message [NodeHeight(16), justify: NodeHeight(15) (\U0001f7e2), Epoch(1), ShardGroup(1-32), 0 cmd(s), 03345cbe10d03d2f8ecf215b6c763c5cbf2dde6c33648d74060e8360e63d0cc0->fba7cfd16f9919c41653d61c313979f92c5b8aeaaa46da539533a9a629a40a15] from cec1426a33965eb2a7d82b281964ad39f06d6fba7d8e57f8da4fcfefd946d855 (current height = NodeHeight(15))
2025-02-28T11:26:28.688801165Z [block_validations] DEBUG Validating signature block_id=03345cbe10d03d2f8ecf215b6c763c5cbf2dde6c33648d74060e8360e63d0cc0, P=cec1426a33965eb2a7d82b281964ad39f06d6fba7d8e57f8da4fcfefd946d855, R=8c07095c80df4b1a80313187398c195cfab9d370a75eba5e48cf283ed7a0f82a
2025-02-28T11:26:28.688822866Z [on_ready_to_vote_on_local_block] INFO ✅ New leaf block [NodeHeight(15), justify: NodeHeight(14) (\U0001f7e2), Epoch(1), ShardGroup(1-32), 0 cmd(s), fba7cfd16f9919c41653d61c313979f92c5b8aeaaa46da539533a9a629a40a15->949026ebc27246a7f1d9015ebbb5884f3b0812a9b48bc4d9029d3a5542993374] is justified. Updating evidence for transactions
2025-02-28T11:26:28.688830831Z [on_ready_to_vote_on_local_block] INFO ⏲️ Process newly justified block took 16.15µs for 0 iterations (avg: NaNms)
2025-02-28T11:26:28.688875634Z [tari::dan::storage::state_store_sqlite::reader] DEBUG get_block_ids_between: start: e0ac3be2c767975ac01cb35be88443d290cddadd226f7b41d86b9a8c18cce26c, end: fba7cfd16f9919c41653d61c313979f92c5b8aeaaa46da539533a9a629a40a15
2025-02-28T11:26:28.689056320Z [on_message_validate] DEBUG ✅ Block [NodeHeight(16), justify: NodeHeight(15) (\U0001f7e2), Epoch(1), ShardGroup(1-32), 0 cmd(s), 03345cbe10d03d2f8ecf215b6c763c5cbf2dde6c33648d74060e8360e63d0cc0->fba7cfd16f9919c41653d61c313979f92c5b8aeaaa46da539533a9a629a40a15] is empty (no missing transactions)
2025-02-28T11:26:28.689069084Z [on_message_validate] DEBUG ⏲️ on_message_validate took 280.73µs
2025-02-28T11:26:28.689073242Z [tari::dan::consensus::sharded_state_tree] DEBUG PENDING INSERT: node v1: leaf: None
2025-02-28T11:26:28.689074624Z [on_receive_local_proposal] DEBUG \U0001f525 LOCAL PROPOSAL: block [NodeHeight(16), justify: NodeHeight(15) (\U0001f7e2), Epoch(1), ShardGroup(1-32), 0 cmd(s), 03345cbe10d03d2f8ecf215b6c763c5cbf2dde6c33648d74060e8360e63d0cc0->fba7cfd16f9919c41653d61c313979f92c5b8aeaaa46da539533a9a629a40a15] from cec1426a33965eb2a7d82b281964ad39f06d6fba7d8e57f8da4fcfefd946d855
2025-02-28T11:26:28.689076377Z [tari::dan::consensus::sharded_state_tree] DEBUG PENDING INSERT: node v1:0 leaf: 93f01dafa26091e27ea67da331b85417e33e7c2a9714ea23842d6dd05aa6e8ae
2025-02-28T11:26:28.689102907Z [tari::dan::consensus::sharded_state_tree] DEBUG PENDING INSERT: node v1:c leaf: 8fe1c0d685f00200609af6b04b5f334ee07b15750b54f7f9a0ac017ed433f3e9
2025-02-28T11:26:28.689107135Z [tari::dan::consensus::sharded_state_tree] DEBUG PENDING INSERT: node v1:b leaf: 2bc158300fe347edbf7b6eff2542216ab7ad054628d464e2c96ddb4ebf9ce236
2025-02-28T11:26:28.689111333Z [tari::dan::consensus::sharded_state_tree] DEBUG PENDING INSERT: node v1:e leaf: 083602b8c3170f99d2f6766c3f4352262068edbc6f4a1155ed47860a4354ed01
2025-02-28T11:26:28.689115550Z [tari::dan::consensus::sharded_state_tree] DEBUG PENDING INSERT: node v1:f leaf: 64ef259f8be25701a498c02c269647de4dd2a1fc5dbbb1b92da6365f25230803
2025-02-28T11:26:28.689144224Z [tari::dan::consensus::sharded_state_tree] DEBUG PENDING INSERT: node v1: leaf: b27edf0c2bae39c0da37d97ef38cf20dc2ab98106a37e303ab6f99d59fa071fa
2025-02-28T11:26:28.689179299Z [tari::dan::storage::quorum_certificate] INFO \U0001f525 HIGH_QC (Qc(block: NodeHeight(15) fba7cfd16f9919c41653d61c313979f92c5b8aeaaa46da539533a9a629a40a15, qc_id: 2cfa31f98b8305fbabe8c90c99510e50a182e021302e3b7104ce79d187779b0c, epoch: Epoch(1), 2 signatures), previous high QC: fba7cfd16f9919c41653d61c313979f92c5b8aeaaa46da539533a9a629a40a15 NodeHeight(15))
2025-02-28T11:26:28.689353523Z [on_receive_local_proposal] INFO ✅ Block ValidBlock([NodeHeight(16), justify: NodeHeight(15) (\U0001f7e2), Epoch(1), ShardGroup(1-32), 0 cmd(s), 03345cbe10d03d2f8ecf215b6c763c5cbf2dde6c33648d74060e8360e63d0cc0->fba7cfd16f9919c41653d61c313979f92c5b8aeaaa46da539533a9a629a40a15]) is valid and persisted.
2025-02-28T11:26:28.689373040Z [on_receive_local_proposal] DEBUG RECV-LOCAL-PROPOSAL - [Epoch(1)] Starting processing block: ValidBlock([NodeHeight(16), justify: NodeHeight(15) (\U0001f7e2), Epoch(1), ShardGroup(1-32), 0 cmd(s), 03345cbe10d03d2f8ecf215b6c763c5cbf2dde6c33648d74060e8360e63d0cc0->fba7cfd16f9919c41653d61c313979f92c5b8aeaaa46da539533a9a629a40a15])
2025-02-28T11:26:28.689390562Z [pacemaker] DEBUG \U0001f9ff Pacemaker suspend
2025-02-28T11:26:28.684422928Z [tari::dan::storage] DEBUG Deleted 0 lock conflicts
2025-02-28T11:26:28.689451926Z [tari::dan::storage::state_store_sqlite::reader] DEBUG get_block_ids_between: start: 36bb1eadc32da940f124058847f9f1c940656c7652d0b137bd327a2874bb4d9a, end: 36bb1eadc32da940f124058847f9f1c940656c7652d0b137bd327a2874bb4d9a
2025-02-28T11:26:28.689471924Z [on_ready_to_vote_on_local_block] INFO \U0001f512️ LOCKED BLOCK: [NodeHeight(14), justify: NodeHeight(13) (\U0001f7e2), Epoch(1), ShardGroup(1-32), 0 cmd(s), 949026ebc27246a7f1d9015ebbb5884f3b0812a9b48bc4d9029d3a5542993374->cdf328634f8c83cfcf20aa349c06285bfff669092f58ca2c1b53984acd1bfd84]
2025-02-28T11:26:28.689492051Z [tari::dan::storage] DEBUG transaction_pool_confirm_all_transitions: new_locked_block=LockedBlock(NodeHeight(14), 949026ebc27246a7f1d9015ebbb5884f3b0812a9b48bc4d9029d3a5542993374), 0 updates
2025-02-28T11:26:28.689528459Z [on_ready_to_vote_on_local_block] DEBUG \U0001f525 LOCAL PROPOSAL READY: ValidBlock([NodeHeight(16), justify: NodeHeight(15) (\U0001f7e2), Epoch(1), ShardGroup(1-32), 0 cmd(s), 03345cbe10d03d2f8ecf215b6c763c5cbf2dde6c33648d74060e8360e63d0cc0->fba7cfd16f9919c41653d61c313979f92c5b8aeaaa46da539533a9a629a40a15])
2025-02-28T11:26:28.689639846Z [on_ready_to_vote_on_local_block] INFO ✅ New leaf block [NodeHeight(15), justify: NodeHeight(14) (\U0001f7e2), Epoch(1), ShardGroup(1-32), 0 cmd(s), fba7cfd16f9919c41653d61c313979f92c5b8aeaaa46da539533a9a629a40a15->949026ebc27246a7f1d9015ebbb5884f3b0812a9b48bc4d9029d3a5542993374] is justified. Updating evidence for transactions
2025-02-28T11:26:28.689649243Z [on_ready_to_vote_on_local_block] INFO ⏲️ Process newly justified block took 16.58µs for 0 iterations (avg: NaNms)
2025-02-28T11:26:28.689693696Z [tari::dan::storage::state_store_sqlite::reader] DEBUG get_block_ids_between: start: e0ac3be2c767975ac01cb35be88443d290cddadd226f7b41d86b9a8c18cce26c, end: fba7cfd16f9919c41653d61c313979f92c5b8aeaaa46da539533a9a629a40a15
2025-02-28T11:26:28.689849296Z [on_ready_to_vote_on_local_block] DEBUG ✅ 1 transactions finalized
2025-02-28T11:26:28.689856529Z [on_ready_to_vote_on_local_block] INFO \U0001fa99 Validator fee (475, Total Fees Paid = 1000) for block [NodeHeight(13), justify: NodeHeight(12) (\U0001f7e2), Epoch(1), ShardGroup(33-64), 1 cmd(s), 36bb1eadc32da940f124058847f9f1c940656c7652d0b137bd327a2874bb4d9a->9d5655a2971386d1d71461b39c17924451f7009334f07a9a50994649c737f028]
2025-02-28T11:26:28.689870495Z [tari::dan::storage::consensus_models::block] DEBUG ✅ Block NodeHeight(16) 03345cbe10d03d2f8ecf215b6c763c5cbf2dde6c33648d74060e8360e63d0cc0 forms a 3-chain b'' = fba7cfd16f9919c41653d61c313979f92c5b8aeaaa46da539533a9a629a40a15, b' = 949026ebc27246a7f1d9015ebbb5884f3b0812a9b48bc4d9029d3a5542993374, b = cdf328634f8c83cfcf20aa349c06285bfff669092f58ca2c1b53984acd1bfd84
2025-02-28T11:26:28.689975771Z [on_ready_to_vote_on_local_block] DEBUG ✅ COMMIT block [NodeHeight(13), justify: NodeHeight(12) (\U0001f7e2), Epoch(1), ShardGroup(33-64), 1 cmd(s), 36bb1eadc32da940f124058847f9f1c940656c7652d0b137bd327a2874bb4d9a->9d5655a2971386d1d71461b39c17924451f7009334f07a9a50994649c737f028], last executed height = NodeHeight(12)
2025-02-28T11:26:28.690026455Z [on_ready_to_vote_on_local_block] INFO ✅ Saving changeset for Local block [NodeHeight(16), justify: NodeHeight(15) (\U0001f7e2), Epoch(1), ShardGroup(33-64), 0 cmd(s), 1e363d9528f7fb1713e913fa2cff1056288ea8caae6149374ffeced48343b0f9->83303778576c83bc8c1baa63cbee420309947a18fc7a1beed05156363e8d8072] decision Some(Accept), change set: ProposedBlockChangeSet(LeafBlock(NodeHeight(16) 1e363d9528f7fb1713e913fa2cff1056288ea8caae6149374ffeced48343b0f9 Epoch(1)),  Decision: Accept,)
2025-02-28T11:26:28.690038728Z [tari::dan::consensus::block_change_set] DEBUG ⏲️ ProposedBlockChangeSet::save took 952.00ns
2025-02-28T11:26:28.690042014Z [on_ready_to_vote_on_local_block] INFO ⏲️ Decide on local block took 7.72ms for 0 iterations (avg: infms)
2025-02-28T11:26:28.690149424Z [tari::dan::storage::state_store_sqlite::reader] DEBUG get_block_ids_between: start: 36bb1eadc32da940f124058847f9f1c940656c7652d0b137bd327a2874bb4d9a, end: 1e363d9528f7fb1713e913fa2cff1056288ea8caae6149374ffeced48343b0f9
2025-02-28T11:26:28.690219735Z [on_ready_to_vote_on_local_block] INFO \U0001f333 Committing block [NodeHeight(13), justify: NodeHeight(12) (\U0001f7e2), Epoch(1), ShardGroup(1-32), 2 cmd(s), cdf328634f8c83cfcf20aa349c06285bfff669092f58ca2c1b53984acd1bfd84->e0ac3be2c767975ac01cb35be88443d290cddadd226f7b41d86b9a8c18cce26c] with 8 substate change(s)
2025-02-28T11:26:28.690252606Z [common] DEBUG Validator TestAddress(4) selected as next leader at height NodeHeight(16)
2025-02-28T11:26:28.690259850Z [current_view] INFO \U0001f9ff PACEMAKER: View updated from Epoch(1)/NodeHeight(15) to Epoch(1)/NodeHeight(16)
2025-02-28T11:26:28.690336622Z [tari_consensus::hotstuff::substate_store::sharded_state_tree] DEBUG (shard=Shard(1)) Inserting node: v1:
2025-02-28T11:26:28.690355638Z [on_receive_local_proposal] INFO \U0001f525 VOTE Accept for block [NodeHeight(16), justify: NodeHeight(15) (\U0001f7e2), Epoch(1), ShardGroup(33-64), 0 cmd(s), 1e363d9528f7fb1713e913fa2cff1056288ea8caae6149374ffeced48343b0f9->83303778576c83bc8c1baa63cbee420309947a18fc7a1beed05156363e8d8072] proposed by a45af5c5eeb3db9687fe9edae95387f91ff5a90c442159204c3f97514dddad7c to next leader TestAddress(4)
2025-02-28T11:26:28.690373722Z [tari_consensus::hotstuff::substate_store::sharded_state_tree] DEBUG (shard=Shard(1)) Inserting node: v1:0
2025-02-28T11:26:28.690385904Z [tari_consensus::hotstuff::substate_store::sharded_state_tree] DEBUG (shard=Shard(1)) Inserting node: v1:c
2025-02-28T11:26:28.690393539Z [pacemaker] INFO \U0001f9ff Pacemaker Reset! Current height: Epoch(1)/NodeHeight(16), Delta: 2.00s
2025-02-28T11:26:28.690396434Z [tari_consensus::hotstuff::substate_store::sharded_state_tree] DEBUG (shard=Shard(1)) Inserting node: v1:b
2025-02-28T11:26:28.690406022Z [tari_consensus::hotstuff::substate_store::sharded_state_tree] DEBUG (shard=Shard(1)) Inserting node: v1:e
2025-02-28T11:26:28.690415319Z [tari_consensus::hotstuff::substate_store::sharded_state_tree] DEBUG (shard=Shard(1)) Inserting node: v1:f
2025-02-28T11:26:28.690457818Z [tari_consensus::hotstuff::substate_store::sharded_state_tree] DEBUG (shard=Shard(20)) Inserting node: v1:
2025-02-28T11:26:28.690461254Z [on_receive_local_proposal] DEBUG ⏲️ SendVoteToLeader took 196.76µs
2025-02-28T11:26:28.690467526Z [on_receive_local_proposal] DEBUG ⏲️ OnReceiveLocalProposalHandler took 9.56ms
2025-02-28T11:26:28.690471533Z [worker] DEBUG \U0001f525 TestAddress(4) Current height #16
2025-02-28T11:26:28.690478827Z [on_message_validate] DEBUG ⏲️ on_message_validate took 301.00ns
2025-02-28T11:26:28.690483937Z [on_receive_vote] DEBUG \U0001f4ec Validating vote message from TestAddress(3): VoteMessage: Epoch(1), block_id: 1e363d9528f7fb1713e913fa2cff1056288ea8caae6149374ffeced48343b0f9, NodeHeight(16), decision: Accept, voter: a45af5c5eeb3db9687fe9edae95387f91ff5a90c442159204c3f97514dddad7c
2025-02-28T11:26:28.690564186Z [on_receive_vote] INFO \U0001f525 Received vote for block Epoch(1) NodeHeight(16) 1e363d9528f7fb1713e913fa2cff1056288ea8caae6149374ffeced48343b0f9 from TestAddress(3) (1 of 2)
2025-02-28T11:26:28.690574535Z [on_receive_vote] DEBUG ⏲️ check_and_collect_vote took 90.72µs
2025-02-28T11:26:28.690577301Z [on_receive_vote] INFO ⏲️ OnReceiveVote took 93.71µs
2025-02-28T11:26:28.690580246Z [worker] DEBUG \U0001f525 TestAddress(4) Current height #16
2025-02-28T11:26:28.690589112Z [consensus_tests::support::network] DEBUG ✉️ Message Vote(NodeHeight(16), Epoch(1), 1e363d9528f7fb1713e913fa2cff1056288ea8caae6149374ffeced48343b0f9, Accept) sent from TestAddress(4) to TestAddress(4)
2025-02-28T11:26:28.690630089Z [on_message_validate] DEBUG ⏲️ on_message_validate took 240.00ns
2025-02-28T11:26:28.690635198Z [on_receive_vote] DEBUG \U0001f4ec Validating vote message from TestAddress(4): VoteMessage: Epoch(1), block_id: 1e363d9528f7fb1713e913fa2cff1056288ea8caae6149374ffeced48343b0f9, NodeHeight(16), decision: Accept, voter: 30eb54ee0d290e0fd9f8a6c6cbc84e3a516645fe1be77429987375498aee8641
2025-02-28T11:26:28.690706270Z [on_receive_vote] INFO \U0001f525 Received vote for block Epoch(1) NodeHeight(16) 1e363d9528f7fb1713e913fa2cff1056288ea8caae6149374ffeced48343b0f9 from TestAddress(4) (2 of 2)
2025-02-28T11:26:28.690882679Z [tari::dan::storage::quorum_certificate] INFO \U0001f525 NEW HIGH_QC (Qc(block: NodeHeight(16) 1e363d9528f7fb1713e913fa2cff1056288ea8caae6149374ffeced48343b0f9, qc_id: 4f39deaf349b716e38b7408ac0cf934066db436d8aaac8fcce95346178f8c713, epoch: Epoch(1), 2 signatures), previous high QC: 1e363d9528f7fb1713e913fa2cff1056288ea8caae6149374ffeced48343b0f9 NodeHeight(16))
2025-02-28T11:26:28.690963389Z [on_receive_vote] INFO \U0001f525 New HIGH Qc(block: NodeHeight(16) 1e363d9528f7fb1713e913fa2cff1056288ea8caae6149374ffeced48343b0f9, qc_id: 4f39deaf349b716e38b7408ac0cf934066db436d8aaac8fcce95346178f8c713, epoch: Epoch(1), 2 signatures)
2025-02-28T11:26:28.690971534Z [on_receive_vote] DEBUG ⏲️ check_and_collect_vote took 336.27µs
2025-02-28T11:26:28.690976243Z [on_receive_vote] INFO ⏲️ OnReceiveVote took 341.17µs
2025-02-28T11:26:28.690979559Z [worker] DEBUG \U0001f525 TestAddress(4) Current height #16
2025-02-28T11:26:28.691020074Z [worker] INFO \U0001f525 [on_beat] TestAddress(4) Local node is leader for height (NodeHeight(17)), num local members: 2, ShardGroup(33-64)
2025-02-28T11:26:28.691175333Z [tari::dan::storage::transaction_pool] DEBUG has_ready_or_pending_transaction_updates: No pending state updates
2025-02-28T11:26:28.691187987Z [tari::dan::storage::transaction_pool] DEBUG has_ready_or_pending_transaction_updates: No transactions marked as ready
2025-02-28T11:26:28.691207182Z [tari::dan::storage::transaction_pool] DEBUG has_ready_or_pending_transaction_updates: No transactions that need to be finalized
2025-02-28T11:26:28.691213234Z [worker] INFO [on_beat] No transactions to propose. Waiting for a timeout.
2025-02-28T11:26:28.691215729Z [worker] DEBUG \U0001f525 TestAddress(4) Current height #16
2025-02-28T11:26:28.691223543Z [pacemaker] INFO \U0001f9ff Pacemaker Leader timeout Reset! Current height: Epoch(1)/NodeHeight(16), Delta: 2.00s
2025-02-28T11:26:28.691266263Z [tari::dan::storage] DEBUG Deleted 5 foreign substate pledges
2025-02-28T11:26:28.691292221Z [tari::dan::storage] DEBUG Deleted 0 lock conflicts
2025-02-28T11:26:28.691324441Z [tari::dan::storage::state_store_sqlite::reader] DEBUG get_block_ids_between: start: cdf328634f8c83cfcf20aa349c06285bfff669092f58ca2c1b53984acd1bfd84, end: cdf328634f8c83cfcf20aa349c06285bfff669092f58ca2c1b53984acd1bfd84
2025-02-28T11:26:28.691335702Z [tari::dan::consensus::sharded_state_tree] DEBUG PENDING INSERT: node v1:c leaf: 8fe1c0d685f00200609af6b04b5f334ee07b15750b54f7f9a0ac017ed433f3e9
2025-02-28T11:26:28.691341122Z [tari::dan::consensus::sharded_state_tree] DEBUG PENDING INSERT: node v1: leaf: None
2025-02-28T11:26:28.691343316Z [tari::dan::consensus::sharded_state_tree] DEBUG PENDING INSERT: node v1:b leaf: 2bc158300fe347edbf7b6eff2542216ab7ad054628d464e2c96ddb4ebf9ce236
2025-02-28T11:26:28.691347283Z [tari::dan::consensus::sharded_state_tree] DEBUG PENDING INSERT: node v1:e leaf: 083602b8c3170f99d2f6766c3f4352262068edbc6f4a1155ed47860a4354ed01
2025-02-28T11:26:28.691351391Z [tari::dan::consensus::sharded_state_tree] DEBUG PENDING INSERT: node v1:f leaf: 64ef259f8be25701a498c02c269647de4dd2a1fc5dbbb1b92da6365f25230803
2025-02-28T11:26:28.691355619Z [tari::dan::consensus::sharded_state_tree] DEBUG PENDING INSERT: node v1:0 leaf: 93f01dafa26091e27ea67da331b85417e33e7c2a9714ea23842d6dd05aa6e8ae
2025-02-28T11:26:28.691387819Z [tari::dan::consensus::sharded_state_tree] DEBUG PENDING INSERT: node v1: leaf: b27edf0c2bae39c0da37d97ef38cf20dc2ab98106a37e303ab6f99d59fa071fa
2025-02-28T11:26:28.691426130Z [tari::dan::storage::quorum_certificate] INFO \U0001f525 NEW HIGH_QC (Qc(block: NodeHeight(15) fba7cfd16f9919c41653d61c313979f92c5b8aeaaa46da539533a9a629a40a15, qc_id: 2cfa31f98b8305fbabe8c90c99510e50a182e021302e3b7104ce79d187779b0c, epoch: Epoch(1), 2 signatures), previous high QC: fba7cfd16f9919c41653d61c313979f92c5b8aeaaa46da539533a9a629a40a15 NodeHeight(15))
2025-02-28T11:26:28.691579926Z [tari::dan::storage::state_store_sqlite::reader] DEBUG get_block_ids_between: start: cdf328634f8c83cfcf20aa349c06285bfff669092f58ca2c1b53984acd1bfd84, end: cdf328634f8c83cfcf20aa349c06285bfff669092f58ca2c1b53984acd1bfd84
2025-02-28T11:26:28.691808251Z [on_ready_to_vote_on_local_block] INFO \U0001f512️ LOCKED BLOCK: [NodeHeight(14), justify: NodeHeight(13) (\U0001f7e2), Epoch(1), ShardGroup(1-32), 0 cmd(s), 949026ebc27246a7f1d9015ebbb5884f3b0812a9b48bc4d9029d3a5542993374->cdf328634f8c83cfcf20aa349c06285bfff669092f58ca2c1b53984acd1bfd84]
2025-02-28T11:26:28.691830863Z [tari::dan::storage] DEBUG transaction_pool_confirm_all_transitions: new_locked_block=LockedBlock(NodeHeight(14), 949026ebc27246a7f1d9015ebbb5884f3b0812a9b48bc4d9029d3a5542993374), 0 updates
2025-02-28T11:26:28.691930218Z [on_ready_to_vote_on_local_block] DEBUG ✅ 2 transactions finalized
2025-02-28T11:26:28.691934186Z [on_ready_to_vote_on_local_block] INFO \U0001fa99 Validator fee (950, Total Fees Paid = 2000) for block [NodeHeight(13), justify: NodeHeight(12) (\U0001f7e2), Epoch(1), ShardGroup(1-32), 2 cmd(s), cdf328634f8c83cfcf20aa349c06285bfff669092f58ca2c1b53984acd1bfd84->e0ac3be2c767975ac01cb35be88443d290cddadd226f7b41d86b9a8c18cce26c]
2025-02-28T11:26:28.692061472Z [on_ready_to_vote_on_local_block] DEBUG ✅ COMMIT block [NodeHeight(13), justify: NodeHeight(12) (\U0001f7e2), Epoch(1), ShardGroup(1-32), 2 cmd(s), cdf328634f8c83cfcf20aa349c06285bfff669092f58ca2c1b53984acd1bfd84->e0ac3be2c767975ac01cb35be88443d290cddadd226f7b41d86b9a8c18cce26c], last executed height = NodeHeight(12)
2025-02-28T11:26:28.692090707Z [on_ready_to_vote_on_local_block] INFO ✅ Saving changeset for Local block [NodeHeight(16), justify: NodeHeight(15) (\U0001f7e2), Epoch(1), ShardGroup(1-32), 0 cmd(s), 03345cbe10d03d2f8ecf215b6c763c5cbf2dde6c33648d74060e8360e63d0cc0->fba7cfd16f9919c41653d61c313979f92c5b8aeaaa46da539533a9a629a40a15] decision Some(Accept), change set: ProposedBlockChangeSet(LeafBlock(NodeHeight(16) 03345cbe10d03d2f8ecf215b6c763c5cbf2dde6c33648d74060e8360e63d0cc0 Epoch(1)),  Decision: Accept,)
2025-02-28T11:26:28.692103851Z [tari::dan::consensus::block_change_set] DEBUG ⏲️ ProposedBlockChangeSet::save took 922.00ns
2025-02-28T11:26:28.692106667Z [on_ready_to_vote_on_local_block] INFO ⏲️ Decide on local block took 3.41ms for 0 iterations (avg: infms)
2025-02-28T11:26:28.692181045Z [tari::dan::storage::consensus_models::block] DEBUG ✅ Block NodeHeight(16) 03345cbe10d03d2f8ecf215b6c763c5cbf2dde6c33648d74060e8360e63d0cc0 forms a 3-chain b'' = fba7cfd16f9919c41653d61c313979f92c5b8aeaaa46da539533a9a629a40a15, b' = 949026ebc27246a7f1d9015ebbb5884f3b0812a9b48bc4d9029d3a5542993374, b = cdf328634f8c83cfcf20aa349c06285bfff669092f58ca2c1b53984acd1bfd84
2025-02-28T11:26:28.692508514Z [on_ready_to_vote_on_local_block] INFO \U0001f333 Committing block [NodeHeight(13), justify: NodeHeight(12) (\U0001f7e2), Epoch(1), ShardGroup(1-32), 2 cmd(s), cdf328634f8c83cfcf20aa349c06285bfff669092f58ca2c1b53984acd1bfd84->e0ac3be2c767975ac01cb35be88443d290cddadd226f7b41d86b9a8c18cce26c] with 8 substate change(s)
2025-02-28T11:26:28.692625281Z [tari_consensus::hotstuff::substate_store::sharded_state_tree] DEBUG (shard=Shard(1)) Inserting node: v1:c
2025-02-28T11:26:28.692658093Z [tari_consensus::hotstuff::substate_store::sharded_state_tree] DEBUG (shard=Shard(1)) Inserting node: v1:
2025-02-28T11:26:28.692671678Z [tari_consensus::hotstuff::substate_store::sharded_state_tree] DEBUG (shard=Shard(1)) Inserting node: v1:b
2025-02-28T11:26:28.692680755Z [tari_consensus::hotstuff::substate_store::sharded_state_tree] DEBUG (shard=Shard(1)) Inserting node: v1:e
2025-02-28T11:26:28.692689020Z [tari_consensus::hotstuff::substate_store::sharded_state_tree] DEBUG (shard=Shard(1)) Inserting node: v1:f
2025-02-28T11:26:28.692697356Z [tari_consensus::hotstuff::substate_store::sharded_state_tree] DEBUG (shard=Shard(1)) Inserting node: v1:0
2025-02-28T11:26:28.692731529Z [tari_consensus::hotstuff::substate_store::sharded_state_tree] DEBUG (shard=Shard(20)) Inserting node: v1:
2025-02-28T11:26:28.693413188Z [tari::dan::storage] DEBUG Deleted 5 foreign substate pledges
2025-02-28T11:26:28.693435459Z [tari::dan::storage] DEBUG Deleted 0 lock conflicts
2025-02-28T11:26:28.693466126Z [tari::dan::storage::state_store_sqlite::reader] DEBUG get_block_ids_between: start: cdf328634f8c83cfcf20aa349c06285bfff669092f58ca2c1b53984acd1bfd84, end: cdf328634f8c83cfcf20aa349c06285bfff669092f58ca2c1b53984acd1bfd84
2025-02-28T11:26:28.693747600Z [tari::dan::storage::state_store_sqlite::reader] DEBUG get_block_ids_between: start: cdf328634f8c83cfcf20aa349c06285bfff669092f58ca2c1b53984acd1bfd84, end: cdf328634f8c83cfcf20aa349c06285bfff669092f58ca2c1b53984acd1bfd84
2025-02-28T11:26:28.694099425Z [on_ready_to_vote_on_local_block] DEBUG ✅ 2 transactions finalized
2025-02-28T11:26:28.694104234Z [on_ready_to_vote_on_local_block] INFO \U0001fa99 Validator fee (950, Total Fees Paid = 2000) for block [NodeHeight(13), justify: NodeHeight(12) (\U0001f7e2), Epoch(1), ShardGroup(1-32), 2 cmd(s), cdf328634f8c83cfcf20aa349c06285bfff669092f58ca2c1b53984acd1bfd84->e0ac3be2c767975ac01cb35be88443d290cddadd226f7b41d86b9a8c18cce26c]
2025-02-28T11:26:28.694203058Z [on_ready_to_vote_on_local_block] DEBUG ✅ COMMIT block [NodeHeight(13), justify: NodeHeight(12) (\U0001f7e2), Epoch(1), ShardGroup(1-32), 2 cmd(s), cdf328634f8c83cfcf20aa349c06285bfff669092f58ca2c1b53984acd1bfd84->e0ac3be2c767975ac01cb35be88443d290cddadd226f7b41d86b9a8c18cce26c], last executed height = NodeHeight(12)
2025-02-28T11:26:28.694231370Z [on_ready_to_vote_on_local_block] INFO ✅ Saving changeset for Local block [NodeHeight(16), justify: NodeHeight(15) (\U0001f7e2), Epoch(1), ShardGroup(1-32), 0 cmd(s), 03345cbe10d03d2f8ecf215b6c763c5cbf2dde6c33648d74060e8360e63d0cc0->fba7cfd16f9919c41653d61c313979f92c5b8aeaaa46da539533a9a629a40a15] decision Some(Accept), change set: ProposedBlockChangeSet(LeafBlock(NodeHeight(16) 03345cbe10d03d2f8ecf215b6c763c5cbf2dde6c33648d74060e8360e63d0cc0 Epoch(1)),  Decision: Accept,)
2025-02-28T11:26:28.694242742Z [tari::dan::consensus::block_change_set] DEBUG ⏲️ ProposedBlockChangeSet::save took 821.00ns
2025-02-28T11:26:28.694245677Z [on_ready_to_vote_on_local_block] INFO ⏲️ Decide on local block took 4.72ms for 0 iterations (avg: infms)
2025-02-28T11:26:28.695489491Z [on_receive_local_proposal] DEBUG ⏲️ OnReceiveLocalProposalHandler took 6.41ms
2025-02-28T11:26:28.695524256Z [on_receive_local_proposal] DEBUG ⏲️ OnReceiveLocalProposalHandler took 7.17ms
test consensus::multishard_validator_fee_claim ... FAILED

failures:

failures:
    consensus::multishard_validator_fee_claim

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

thread 'consensus::multishard_validator_fee_claim' panicked at dan_layer/consensus_tests/src/support/harness.rs:498:13:
Validator TestAddress(4) did not commit transaction 24697641c1f9c29165ed7440437e42fd80b047bd98d07028755b6c4b58dcb52d
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace