Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

tests::block_assembler::test_package_multi_best_scores failed with a probability about 10% #4252

Closed
eval-exec opened this issue Nov 30, 2023 · 2 comments · Fixed by #4277
Closed

tests::block_assembler::test_package_multi_best_scores failed with a probability about 10% #4252

eval-exec opened this issue Nov 30, 2023 · 2 comments · Fixed by #4277
Labels
t:bug Type: This doesn't seem right.

Comments

@eval-exec
Copy link
Collaborator

eval-exec commented Nov 30, 2023 •
edited
Loading

Bug Report

ckb-chain tests::block_assembler::test_package_multi_best_scores failed with a probability about 10%

Current Behavior

$ while true; do cargo test -p ckb-chain tests::block_assembler::test_package_multi_best_scores -- --nocapture; done     
Finished test [unoptimized + debuginfo] target(s) in 0.13s
     Running unittests src/lib.rs (target/debug/deps/ckb_chain-09dbec27bafb96f0)

running 1 test
thread 'tests::block_assembler::test_package_multi_best_scores' panicked at 'assertion failed: `(left == right)`
  left: `[Byte32(0xcd0d80078c5fb0aed3cc059f73562cb2f1e4a71823f8d720f83ff9f2c9214769), Byte32(0x001d9a4774b77d4d7d4572a52e7f88b267da4b483b1430ee3b1dbe8a555c0ff5), Byte32(0x790691b80c0e6dfca591bf62f72b4b74018ab296d8fc12c1f078397e8e1e2a2b), Byte32(0xf3ace5260c0e0c38b70235466c75645d70ab41d052035d3a636ead24c8c5c935), Byte32(0x42afa370eeb4ef6707a090317bb07740c97d4762c20bfdf114665e7422489524), Byte32(0xa181a0f4a636b91d7efa55ee49b9a42787847242d76c14343cf25eb116d052c2), Byte32(0xe9d809a20bef9c45bdc1258dadb55e7db72b88029b292633e6d748af00f3b6b3), Byte32(0x8006255ad512edfaee5b658424265bef712f49f82d8e4aae072c144232e167d2), Byte32(0xf2bdff1e814a130cf3a76a7e6147ed9c0fd6b367d4be44f1113149cc932b2b0e)]`,
 right: `[Byte32(0xcd0d80078c5fb0aed3cc059f73562cb2f1e4a71823f8d720f83ff9f2c9214769), Byte32(0x001d9a4774b77d4d7d4572a52e7f88b267da4b483b1430ee3b1dbe8a555c0ff5), Byte32(0x790691b80c0e6dfca591bf62f72b4b74018ab296d8fc12c1f078397e8e1e2a2b), Byte32(0xf3ace5260c0e0c38b70235466c75645d70ab41d052035d3a636ead24c8c5c935), Byte32(0x42afa370eeb4ef6707a090317bb07740c97d4762c20bfdf114665e7422489524), Byte32(0xa181a0f4a636b91d7efa55ee49b9a42787847242d76c14343cf25eb116d052c2), Byte32(0xe9d809a20bef9c45bdc1258dadb55e7db72b88029b292633e6d748af00f3b6b3), Byte32(0x8006255ad512edfaee5b658424265bef712f49f82d8e4aae072c144232e167d2), Byte32(0xd551fbc7a1b0f6ef4e1135ce320a562f66b171a1973ba4800e38810e5c618d9d), Byte32(0xf2bdff1e814a130cf3a76a7e6147ed9c0fd6b367d4be44f1113149cc932b2b0e)]`: best scored txs', chain/src/tests/block_assembler.rs:389:5
stack backtrace:
   0: rust_begin_unwind
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/std/src/panicking.rs:593:5
   1: core::panicking::panic_fmt
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/core/src/panicking.rs:67:14
   2: core::panicking::assert_failed_inner
   3: core::panicking::assert_failed
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/core/src/panicking.rs:228:5
   4: ckb_chain::tests::block_assembler::check_txs
             at ./src/tests/block_assembler.rs:389:5
   5: ckb_chain::tests::block_assembler::test_package_multi_best_scores
             at ./src/tests/block_assembler.rs:596:5
   6: ckb_chain::tests::block_assembler::test_package_multi_best_scores::{{closure}}
             at ./src/tests/block_assembler.rs:508:37
   7: core::ops::function::FnOnce::call_once
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/core/src/ops/function.rs:250:5
   8: core::ops::function::FnOnce::call_once
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/core/src/ops/function.rs:250:5
note: Some details are omitted, run with `RUST_BACKTRACE=full` for a verbose backtrace.
test tests::block_assembler::test_package_multi_best_scores ... FAILED

Environment

  • CKB version: latest develop branch: 3d674d558e5574f0c77a52798775c903561a933a
  • Chain: /
  • Operating system: NixOS 24.05 (Uakari) x86_64
  • Arch: Linux Mufasa 6.6.2 #1-NixOS SMP PREEMPT_DYNAMIC Mon Nov 20 10:59:39 UTC 2023 x86_64 GNU/Linux
  • Installation: /
@eval-exec eval-exec added the t:bug Type: This doesn't seem right. label Nov 30, 2023
@eval-exec eval-exec changed the title ckb-chain tests::block_assembler::test_package_multi_best_scores failed with a probability about 1% tests::block_assembler::test_package_multi_best_scores failed with a probability about 1% Nov 30, 2023
@eval-exec eval-exec changed the title tests::block_assembler::test_package_multi_best_scores failed with a probability about 1% tests::block_assembler::test_package_multi_best_scores failed with a probability about 10% Nov 30, 2023
@eval-exec
Copy link
Collaborator Author

This issue might be associated with #4220

If I revert the commit 0a64a9d9323b0c311625c3d59766bd74e4fd9312, the issue will not occur again.

@eval-exec
Copy link
Collaborator Author

I add trace level log to this unit test, got:

     Running unittests src/lib.rs (target/debug/deps/ckb_chain-e7f8d391d59742b7)

running 1 test
2023-12-01 06:03:01.004 +00:00 tests::block_assembler::test_package_multi_best_scores TRACE ckb_proposal_table  [proposal_finalize] table {0: {}}
2023-12-01 06:03:01.004 +00:00 tests::block_assembler::test_package_multi_best_scores TRACE ckb_proposal_table  [proposal_finalize] number 0 proposal_start 0----proposal_end 0
2023-12-01 06:03:01.004 +00:00 tests::block_assembler::test_package_multi_best_scores TRACE ckb_proposal_table  [proposal_finalize] number 0 new_ids {}----removed_ids {}
2023-12-01 06:03:01.004 +00:00 tests::block_assembler::test_package_multi_best_scores DEBUG ckb_reward_calculator  [RewardCalculator] target 0 Byte32(0x97a257cb8ef34d0c2355ee9907046619c7a703bdcbe5e07cc9eb80c35ab603ab)

             txs_fees Capacity(0), proposal_reward Capacity(0), primary Capacity(191780821918), secondary: Capacity(0), total_reward Capacity(191780821918)
2023-12-01 06:03:01.005 +00:00 tests::block_assembler::test_package_multi_best_scores INFO ckb_network::network  loading the peer store, which may take a few seconds to complete
2023-12-01 06:03:01.005 +00:00 tests::block_assembler::test_package_multi_best_scores DEBUG ckb_network::peer_store::peer_store_db  Failed to open AddrManager db, file: "/run/user/1000/.tmpYZU6oy/peer_store/addr_manager.db", error: Os { code: 2, kind: NotFound, message: "No such file or directory" }
2023-12-01 06:03:01.005 +00:00 tests::block_assembler::test_package_multi_best_scores DEBUG ckb_network::peer_store::peer_store_db  Failed to open BanList db, file: "/run/user/1000/.tmpYZU6oy/peer_store/ban_list.db", error: Os { code: 2, kind: NotFound, message: "No such file or directory" }
2023-12-01 06:03:01.005 +00:00 tests::block_assembler::test_package_multi_best_scores WARN ckb_network::network  Customized supported protocols: []
2023-12-01 06:03:01.006 +00:00 tests::block_assembler::test_package_multi_best_scores WARN ckb_tx_pool::pool  Recent reject database is disabled!
2023-12-01 06:03:01.006 +00:00 GlobalRt-19 DEBUG tentacle::service  init service level [ProtocolId(2)] proto handle
2023-12-01 06:03:01.006 +00:00 tests::block_assembler::test_package_multi_best_scores TRACE ckb_stop_handler::stop_register  register thread ChainService
2023-12-01 06:03:01.006 +00:00 tests::block_assembler::test_package_multi_best_scores TRACE ckb_stop_handler::stop_register  register thread done ChainService
2023-12-01 06:03:01.006 +00:00 *unnamed* DEBUG ckb_chain::chain  begin processing block: 1-Byte32(0xaef8dcca95edbdae5afe592ac45511c521c9f8ee468742abaeff706855ad3247)
2023-12-01 06:03:01.006 +00:00 *unnamed* DEBUG ckb_chain::chain  difficulty current = 0x2, cannon = 0x4
2023-12-01 06:03:01.006 +00:00 *unnamed* DEBUG ckb_chain::chain  new best block found: 1 => 0xaef8dcca95edbdae5afe592ac45511c521c9f8ee468742abaeff706855ad3247, difficulty diff = 0x2
2023-12-01 06:03:01.006 +00:00 *unnamed* TRACE ckb_chain::chain  light-client: new chain root MMR with size = 1
2023-12-01 06:03:01.007 +00:00 *unnamed* TRACE ckb_chain::chain  light-client: commit
2023-12-01 06:03:01.007 +00:00 *unnamed* INFO ckb_chain::chain  block: 1, hash: 0xaef8dcca95edbdae5afe592ac45511c521c9f8ee468742abaeff706855ad3247, epoch: 0(1/5), total_diff: 0x4, txs: 1
2023-12-01 06:03:01.007 +00:00 *unnamed* TRACE ckb_proposal_table  [proposal_finalize] table {0: {}, 1: {ProposalShortId(0x01010101010101010101)}}
2023-12-01 06:03:01.007 +00:00 *unnamed* TRACE ckb_proposal_table  [proposal_finalize] number 1 proposal_start 0----proposal_end 0
2023-12-01 06:03:01.007 +00:00 *unnamed* TRACE ckb_proposal_table  [proposal_finalize] number 1 new_ids {}----removed_ids {}
2023-12-01 06:03:01.007 +00:00 *unnamed* DEBUG ckb_chain::chain  Chain {
2023-12-01 06:03:01.007 +00:00 *unnamed* DEBUG ckb_chain::chain     1 => Byte32(0xaef8dcca95edbdae5afe592ac45511c521c9f8ee468742abaeff706855ad3247)
2023-12-01 06:03:01.007 +00:00 *unnamed* DEBUG ckb_chain::chain     0 => Byte32(0x97a257cb8ef34d0c2355ee9907046619c7a703bdcbe5e07cc9eb80c35ab603ab)
2023-12-01 06:03:01.007 +00:00 *unnamed* DEBUG ckb_chain::chain  }
2023-12-01 06:03:01.007 +00:00 *unnamed* DEBUG ckb_chain::chain  finish processing block
2023-12-01 06:03:01.007 +00:00 GlobalRt-16 TRACE ckb_notify  event new block BlockView { data: Block(0xc701000014000000e4000000e8000000b901000000000000000080200a000000000000000100000000000000000000010005000097a257cb8ef34d0c2355ee9907046619c7a703bdcbe5e07cc9eb80c35ab603ab0000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000009e43f8ff365b00000000c16ff286230000e8764817000000000961f4000000000b00000000000000000000000000000004000000d100000008000000c90000000c000000c5000000b90000001c00000020000000240000002800000058000000ad0000000000000000000000000000000100000001000000000000000000000000000000000000000000000000000000000000000000000000000000ffffffff55000000080000004d00000010000000180000004d0000009e1b07a72c00000035000000100000003000000031000000000000000000000000000000000000000000000000000000000000000000000000000000000c0000000800000000000000040000000100000001010101010101010101), hash: Byte32(0xaef8dcca95edbdae5afe592ac45511c521c9f8ee468742abaeff706855ad3247), uncle_hashes: Byte32Vec(0x00000000), tx_hashes: [Byte32(0x73b68706c30f986b16ba3ca283a7cefa7e8ef0f5da113aa89aaeeb0a3e4b1aee)], tx_witness_hashes: [Byte32(0x3d2e7fec3b56a60d3a03dd9f123229584b6993f240d074fd5c34983b9aa03a81)] }
2023-12-01 06:03:01.007 +00:00 GlobalRt-14 TRACE ckb_network::services::outbound_peer  feeler dial count=0, attempt_peers: []
2023-12-01 06:03:01.007 +00:00 GlobalRt-14 TRACE ckb_network::services::outbound_peer  identify dial count=0, attempt_peers: []
2023-12-01 06:03:01.007 +00:00 *unnamed* DEBUG ckb_chain::chain  begin processing block: 2-Byte32(0x9b114604a1e3ba7fb2e60a677d28a846189f77d605d3d21e62df06ab52fbf091)
2023-12-01 06:03:01.007 +00:00 *unnamed* DEBUG ckb_chain::chain  difficulty current = 0x4, cannon = 0x6
2023-12-01 06:03:01.007 +00:00 *unnamed* DEBUG ckb_chain::chain  new best block found: 2 => 0x9b114604a1e3ba7fb2e60a677d28a846189f77d605d3d21e62df06ab52fbf091, difficulty diff = 0x2
2023-12-01 06:03:01.007 +00:00 *unnamed* TRACE ckb_chain::chain  light-client: new chain root MMR with size = 3
2023-12-01 06:03:01.007 +00:00 GlobalRt-18 DEBUG ckb_reward_calculator  [RewardCalculator] target 0 Byte32(0x97a257cb8ef34d0c2355ee9907046619c7a703bdcbe5e07cc9eb80c35ab603ab)

             txs_fees Capacity(0), proposal_reward Capacity(0), primary Capacity(191780821918), secondary: Capacity(0), total_reward Capacity(191780821918)
2023-12-01 06:03:01.008 +00:00 *unnamed* TRACE ckb_chain::chain  light-client: commit
2023-12-01 06:03:01.008 +00:00 *unnamed* INFO ckb_chain::chain  block: 2, hash: 0x9b114604a1e3ba7fb2e60a677d28a846189f77d605d3d21e62df06ab52fbf091, epoch: 0(2/5), total_diff: 0x6, txs: 1
2023-12-01 06:03:01.008 +00:00 *unnamed* TRACE ckb_proposal_table  [proposal_finalize] table {0: {}, 1: {ProposalShortId(0x01010101010101010101)}, 2: {ProposalShortId(0x01010101010101010101)}}
2023-12-01 06:03:01.008 +00:00 *unnamed* TRACE ckb_proposal_table  [proposal_finalize] number 2 proposal_start 0----proposal_end 1
2023-12-01 06:03:01.008 +00:00 GlobalRt-18 TRACE ckb_tx_pool::block_assembler  [BlockAssembler] update_blank 2 uncles-0 proposals-0 txs-0
2023-12-01 06:03:01.008 +00:00 *unnamed* TRACE ckb_proposal_table  [proposal_finalize] number 2 new_ids {ProposalShortId(0x01010101010101010101)}----removed_ids {}
2023-12-01 06:03:01.008 +00:00 *unnamed* DEBUG ckb_chain::chain  Chain {
2023-12-01 06:03:01.008 +00:00 *unnamed* DEBUG ckb_chain::chain     2 => Byte32(0x9b114604a1e3ba7fb2e60a677d28a846189f77d605d3d21e62df06ab52fbf091)
2023-12-01 06:03:01.008 +00:00 *unnamed* DEBUG ckb_chain::chain     1 => Byte32(0xaef8dcca95edbdae5afe592ac45511c521c9f8ee468742abaeff706855ad3247)
2023-12-01 06:03:01.008 +00:00 *unnamed* DEBUG ckb_chain::chain     0 => Byte32(0x97a257cb8ef34d0c2355ee9907046619c7a703bdcbe5e07cc9eb80c35ab603ab)
2023-12-01 06:03:01.008 +00:00 *unnamed* DEBUG ckb_chain::chain  }
2023-12-01 06:03:01.008 +00:00 *unnamed* DEBUG ckb_chain::chain  finish processing block
2023-12-01 06:03:01.008 +00:00 GlobalRt-20 TRACE ckb_notify  event new block BlockView { data: Block(0xc701000014000000e4000000e8000000b90100000000000000008020140000000000000002000000000000000000000200050000aef8dcca95edbdae5afe592ac45511c521c9f8ee468742abaeff706855ad32470000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000009e43f8ff365b00000000c16ff286230000e8764817000000000961f4000000000b00000000000000000000000000000004000000d100000008000000c90000000c000000c5000000b90000001c00000020000000240000002800000058000000ad0000000000000000000000000000000100000002000000000000000000000000000000000000000000000000000000000000000000000000000000ffffffff55000000080000004d00000010000000180000004d0000009e1b07a72c00000035000000100000003000000031000000000000000000000000000000000000000000000000000000000000000000000000000000000c0000000800000000000000040000000100000001010101010101010101), hash: Byte32(0x9b114604a1e3ba7fb2e60a677d28a846189f77d605d3d21e62df06ab52fbf091), uncle_hashes: Byte32Vec(0x00000000), tx_hashes: [Byte32(0x01f23bad806f8f8f2dca4f8d43f20a2a032c84db3c2ab6ce39a4ee4cbae4d9d1)], tx_witness_hashes: [Byte32(0x68a8299dd44071d6666a0f720a09b0bcd1290a516c17108daf9f96b5414660c7)] }
2023-12-01 06:03:01.008 +00:00 *unnamed* DEBUG ckb_chain::chain  begin processing block: 3-Byte32(0xa0a3b31b955efce437fd16c5b8238688d0f73acaf0fcb6e20d8918522c2b76b8)
2023-12-01 06:03:01.008 +00:00 GlobalRt-18 TRACE ckb_tx_pool::block_assembler  [BlockAssembler] update_full 2 uncles-0 proposals-0 txs-0
2023-12-01 06:03:01.008 +00:00 *unnamed* DEBUG ckb_chain::chain  difficulty current = 0x6, cannon = 0x8
2023-12-01 06:03:01.008 +00:00 *unnamed* DEBUG ckb_chain::chain  new best block found: 3 => 0xa0a3b31b955efce437fd16c5b8238688d0f73acaf0fcb6e20d8918522c2b76b8, difficulty diff = 0x2
2023-12-01 06:03:01.008 +00:00 *unnamed* TRACE ckb_chain::chain  light-client: new chain root MMR with size = 4
2023-12-01 06:03:01.008 +00:00 *unnamed* TRACE ckb_chain::chain  light-client: commit
2023-12-01 06:03:01.009 +00:00 *unnamed* INFO ckb_chain::chain  block: 3, hash: 0xa0a3b31b955efce437fd16c5b8238688d0f73acaf0fcb6e20d8918522c2b76b8, epoch: 0(3/5), total_diff: 0x8, txs: 1
2023-12-01 06:03:01.009 +00:00 *unnamed* TRACE ckb_proposal_table  [proposal_finalize] table {0: {}, 1: {ProposalShortId(0x01010101010101010101)}, 2: {ProposalShortId(0x01010101010101010101)}, 3: {ProposalShortId(0x01010101010101010101)}}
2023-12-01 06:03:01.009 +00:00 *unnamed* TRACE ckb_proposal_table  [proposal_finalize] number 3 proposal_start 0----proposal_end 2
2023-12-01 06:03:01.009 +00:00 *unnamed* TRACE ckb_proposal_table  [proposal_finalize] number 3 new_ids {ProposalShortId(0x01010101010101010101)}----removed_ids {}
2023-12-01 06:03:01.009 +00:00 GlobalRt-18 DEBUG ckb_reward_calculator  [RewardCalculator] target 0 Byte32(0x97a257cb8ef34d0c2355ee9907046619c7a703bdcbe5e07cc9eb80c35ab603ab)

             txs_fees Capacity(0), proposal_reward Capacity(0), primary Capacity(191780821918), secondary: Capacity(0), total_reward Capacity(191780821918)
2023-12-01 06:03:01.009 +00:00 *unnamed* DEBUG ckb_chain::chain  Chain {
2023-12-01 06:03:01.009 +00:00 *unnamed* DEBUG ckb_chain::chain     3 => Byte32(0xa0a3b31b955efce437fd16c5b8238688d0f73acaf0fcb6e20d8918522c2b76b8)
2023-12-01 06:03:01.009 +00:00 *unnamed* DEBUG ckb_chain::chain     2 => Byte32(0x9b114604a1e3ba7fb2e60a677d28a846189f77d605d3d21e62df06ab52fbf091)
2023-12-01 06:03:01.009 +00:00 *unnamed* DEBUG ckb_chain::chain     1 => Byte32(0xaef8dcca95edbdae5afe592ac45511c521c9f8ee468742abaeff706855ad3247)
2023-12-01 06:03:01.009 +00:00 *unnamed* DEBUG ckb_chain::chain     0 => Byte32(0x97a257cb8ef34d0c2355ee9907046619c7a703bdcbe5e07cc9eb80c35ab603ab)
2023-12-01 06:03:01.009 +00:00 *unnamed* DEBUG ckb_chain::chain  }
2023-12-01 06:03:01.009 +00:00 *unnamed* DEBUG ckb_chain::chain  finish processing block
2023-12-01 06:03:01.009 +00:00 GlobalRt-20 TRACE ckb_notify  event new block BlockView { data: Block(0xc701000014000000e4000000e8000000b901000000000000000080201e00000000000000030000000000000000000003000500009b114604a1e3ba7fb2e60a677d28a846189f77d605d3d21e62df06ab52fbf0910000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000009e43f8ff365b00000000c16ff286230000e8764817000000000961f4000000000b00000000000000000000000000000004000000d100000008000000c90000000c000000c5000000b90000001c00000020000000240000002800000058000000ad0000000000000000000000000000000100000003000000000000000000000000000000000000000000000000000000000000000000000000000000ffffffff55000000080000004d00000010000000180000004d0000009e1b07a72c00000035000000100000003000000031000000000000000000000000000000000000000000000000000000000000000000000000000000000c0000000800000000000000040000000100000001010101010101010101), hash: Byte32(0xa0a3b31b955efce437fd16c5b8238688d0f73acaf0fcb6e20d8918522c2b76b8), uncle_hashes: Byte32Vec(0x00000000), tx_hashes: [Byte32(0x25e36d430341ec6c4c9e0623adde27a2bc9b14a16eee3ce737d7527aa0ec5a36)], tx_witness_hashes: [Byte32(0xaedc5dffcb3b5ad0a5703da453da18ec875da39fa835b5c3910fbd4a045c3a15)] }
2023-12-01 06:03:01.009 +00:00 GlobalRt-18 TRACE ckb_tx_pool::block_assembler  [BlockAssembler] update_blank 3 uncles-0 proposals-0 txs-0
2023-12-01 06:03:01.009 +00:00 *unnamed* DEBUG ckb_chain::chain  begin processing block: 4-Byte32(0xe0ecc5c3c534beb20314de82fb9e78b43213dacc79351b3fb774ce11a08fa0b9)
2023-12-01 06:03:01.009 +00:00 *unnamed* DEBUG ckb_chain::chain  difficulty current = 0x8, cannon = 0xa
2023-12-01 06:03:01.009 +00:00 *unnamed* DEBUG ckb_chain::chain  new best block found: 4 => 0xe0ecc5c3c534beb20314de82fb9e78b43213dacc79351b3fb774ce11a08fa0b9, difficulty diff = 0x2
2023-12-01 06:03:01.009 +00:00 *unnamed* TRACE ckb_chain::chain  light-client: new chain root MMR with size = 7
2023-12-01 06:03:01.009 +00:00 GlobalRt-18 TRACE ckb_tx_pool::block_assembler  [BlockAssembler] update_full 3 uncles-0 proposals-0 txs-0
2023-12-01 06:03:01.009 +00:00 *unnamed* TRACE ckb_chain::chain  light-client: commit
2023-12-01 06:03:01.009 +00:00 *unnamed* INFO ckb_chain::chain  block: 4, hash: 0xe0ecc5c3c534beb20314de82fb9e78b43213dacc79351b3fb774ce11a08fa0b9, epoch: 0(4/5), total_diff: 0xa, txs: 1
2023-12-01 06:03:01.009 +00:00 *unnamed* TRACE ckb_proposal_table  [proposal_finalize] table {0: {}, 1: {ProposalShortId(0x01010101010101010101)}, 2: {ProposalShortId(0x01010101010101010101)}, 3: {ProposalShortId(0x01010101010101010101)}, 4: {ProposalShortId(0x01010101010101010101)}}
2023-12-01 06:03:01.009 +00:00 *unnamed* TRACE ckb_proposal_table  [proposal_finalize] number 4 proposal_start 0----proposal_end 3
2023-12-01 06:03:01.009 +00:00 *unnamed* TRACE ckb_proposal_table  [proposal_finalize] number 4 new_ids {ProposalShortId(0x01010101010101010101)}----removed_ids {}
2023-12-01 06:03:01.009 +00:00 *unnamed* DEBUG ckb_chain::chain  Chain {
2023-12-01 06:03:01.009 +00:00 *unnamed* DEBUG ckb_chain::chain     4 => Byte32(0xe0ecc5c3c534beb20314de82fb9e78b43213dacc79351b3fb774ce11a08fa0b9)
2023-12-01 06:03:01.010 +00:00 *unnamed* DEBUG ckb_chain::chain     3 => Byte32(0xa0a3b31b955efce437fd16c5b8238688d0f73acaf0fcb6e20d8918522c2b76b8)
2023-12-01 06:03:01.010 +00:00 *unnamed* DEBUG ckb_chain::chain     2 => Byte32(0x9b114604a1e3ba7fb2e60a677d28a846189f77d605d3d21e62df06ab52fbf091)
2023-12-01 06:03:01.010 +00:00 *unnamed* DEBUG ckb_chain::chain     1 => Byte32(0xaef8dcca95edbdae5afe592ac45511c521c9f8ee468742abaeff706855ad3247)
2023-12-01 06:03:01.010 +00:00 *unnamed* DEBUG ckb_chain::chain     0 => Byte32(0x97a257cb8ef34d0c2355ee9907046619c7a703bdcbe5e07cc9eb80c35ab603ab)
2023-12-01 06:03:01.010 +00:00 *unnamed* DEBUG ckb_chain::chain  }
2023-12-01 06:03:01.010 +00:00 *unnamed* DEBUG ckb_chain::chain  finish processing block
2023-12-01 06:03:01.010 +00:00 GlobalRt-19 TRACE ckb_notify  event new block BlockView { data: Block(0xc701000014000000e4000000e8000000b90100000000000000008020280000000000000004000000000000000000000400050000a0a3b31b955efce437fd16c5b8238688d0f73acaf0fcb6e20d8918522c2b76b80000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000009e43f8ff365b00000000c16ff286230000e8764817000000000961f4000000000b00000000000000000000000000000004000000d100000008000000c90000000c000000c5000000b90000001c00000020000000240000002800000058000000ad0000000000000000000000000000000100000004000000000000000000000000000000000000000000000000000000000000000000000000000000ffffffff55000000080000004d00000010000000180000004d0000009e1b07a72c00000035000000100000003000000031000000000000000000000000000000000000000000000000000000000000000000000000000000000c0000000800000000000000040000000100000001010101010101010101), hash: Byte32(0xe0ecc5c3c534beb20314de82fb9e78b43213dacc79351b3fb774ce11a08fa0b9), uncle_hashes: Byte32Vec(0x00000000), tx_hashes: [Byte32(0x9b3afcac17d78d724f87fc1629e6d50448d735338cccfe6e8fd1e001732eace5)], tx_witness_hashes: [Byte32(0x305135adca93ccaae1f7f90cea72ca5fbae8351c83f0bf9aefb908d5026cc66e)] }
2023-12-01 06:03:01.010 +00:00 GlobalRt-18 DEBUG ckb_reward_calculator  [RewardCalculator] target 0 Byte32(0x97a257cb8ef34d0c2355ee9907046619c7a703bdcbe5e07cc9eb80c35ab603ab)

             txs_fees Capacity(0), proposal_reward Capacity(0), primary Capacity(191780821918), secondary: Capacity(0), total_reward Capacity(191780821918)
2023-12-01 06:03:01.010 +00:00 GlobalRt-18 TRACE ckb_tx_pool::block_assembler  [BlockAssembler] update_blank 4 uncles-0 proposals-0 txs-0
2023-12-01 06:03:01.010 +00:00 GlobalRt-19 TRACE ckb_tx_pool::component::pool_map  pool_map.add_Proposed Byte32(0xcd0d80078c5fb0aed3cc059f73562cb2f1e4a71823f8d720f83ff9f2c9214769)
2023-12-01 06:03:01.010 +00:00 GlobalRt-19 TRACE ckb_tx_pool::component::pool_map  pool_map.add_Proposed Byte32(0x001d9a4774b77d4d7d4572a52e7f88b267da4b483b1430ee3b1dbe8a555c0ff5)
2023-12-01 06:03:01.010 +00:00 GlobalRt-19 TRACE ckb_tx_pool::component::pool_map  pool_map.add_Proposed Byte32(0x790691b80c0e6dfca591bf62f72b4b74018ab296d8fc12c1f078397e8e1e2a2b)
2023-12-01 06:03:01.010 +00:00 GlobalRt-19 TRACE ckb_tx_pool::component::pool_map  pool_map.add_Proposed Byte32(0xf3ace5260c0e0c38b70235466c75645d70ab41d052035d3a636ead24c8c5c935)
2023-12-01 06:03:01.010 +00:00 GlobalRt-19 TRACE ckb_tx_pool::component::pool_map  pool_map.add_Proposed Byte32(0x42afa370eeb4ef6707a090317bb07740c97d4762c20bfdf114665e7422489524)
2023-12-01 06:03:01.010 +00:00 GlobalRt-19 TRACE ckb_tx_pool::component::pool_map  pool_map.add_Proposed Byte32(0xa181a0f4a636b91d7efa55ee49b9a42787847242d76c14343cf25eb116d052c2)
2023-12-01 06:03:01.010 +00:00 GlobalRt-19 TRACE ckb_tx_pool::component::pool_map  pool_map.add_Proposed Byte32(0xe9d809a20bef9c45bdc1258dadb55e7db72b88029b292633e6d748af00f3b6b3)
2023-12-01 06:03:01.010 +00:00 GlobalRt-19 TRACE ckb_tx_pool::component::pool_map  pool_map.add_Proposed Byte32(0x8006255ad512edfaee5b658424265bef712f49f82d8e4aae072c144232e167d2)
2023-12-01 06:03:01.010 +00:00 GlobalRt-19 TRACE ckb_tx_pool::component::pool_map  pool_map.add_Proposed Byte32(0xf2bdff1e814a130cf3a76a7e6147ed9c0fd6b367d4be44f1113149cc932b2b0e)
2023-12-01 06:03:01.010 +00:00 GlobalRt-19 TRACE ckb_tx_pool::component::pool_map  pool_map.add_Proposed Byte32(0xd551fbc7a1b0f6ef4e1135ce320a562f66b171a1973ba4800e38810e5c618d9d)
2023-12-01 06:03:01.011 +00:00 GlobalRt-19 INFO ckb_tx_pool::pool  [get_block_template] candidate txs count: 3, size: 250/250, cycles:0/3500000000
2023-12-01 06:03:01.011 +00:00 GlobalRt-15 INFO ckb_tx_pool::pool  [get_block_template] candidate txs count: 10, size: 2400/596558, cycles:0/3500000000
2023-12-01 06:03:01.011 +00:00 GlobalRt-19 INFO ckb_tx_pool::pool  [get_block_template] candidate txs count: 4, size: 400/400, cycles:0/3500000000
2023-12-01 06:03:01.011 +00:00 GlobalRt-15 ERROR ckb_tx_pool::block_assembler  resolve transactions when build block template, tip_number: 3, tip_hash: Byte32(0xa0a3b31b955efce437fd16c5b8238688d0f73acaf0fcb6e20d8918522c2b76b8), tx_hash: Byte32(0xd551fbc7a1b0f6ef4e1135ce320a562f66b171a1973ba4800e38810e5c618d9d), error: Unknown(OutPoint(0x9b3afcac17d78d724f87fc1629e6d50448d735338cccfe6e8fd1e001732eace500000000))
2023-12-01 06:03:01.011 +00:00 GlobalRt-19 INFO ckb_tx_pool::pool  [get_block_template] candidate txs count: 5, size: 500/500, cycles:0/3500000000
2023-12-01 06:03:01.011 +00:00 GlobalRt-19 DEBUG ckb_tx_pool::component::pool_map  remove entry Byte32(0xd551fbc7a1b0f6ef4e1135ce320a562f66b171a1973ba4800e38810e5c618d9d) from status: Proposed
2023-12-01 06:03:01.011 +00:00 GlobalRt-19 ERROR ckb_tx_pool::pool  total_tx_size 0 overflow by sub 250
2023-12-01 06:03:01.011 +00:00 GlobalRt-19 TRACE ckb_tx_pool::block_assembler  [BlockAssembler] update_full 4 uncles-0 proposals-0 txs-9
2023-12-01 06:03:01.012 +00:00 GlobalRt-18 INFO ckb_tx_pool::pool  [get_block_template] candidate txs count: 5, size: 850/900, cycles:0/3500000000
2023-12-01 06:03:01.012 +00:00 GlobalRt-19 DEBUG ckb_reward_calculator  [RewardCalculator] target 0 Byte32(0x97a257cb8ef34d0c2355ee9907046619c7a703bdcbe5e07cc9eb80c35ab603ab)

             txs_fees Capacity(0), proposal_reward Capacity(0), primary Capacity(191780821918), secondary: Capacity(0), total_reward Capacity(191780821918)
2023-12-01 06:03:01.012 +00:00 GlobalRt-19 TRACE ckb_tx_pool::block_assembler  [BlockAssembler] update_blank 5 uncles-0 proposals-0 txs-0
2023-12-01 06:03:01.012 +00:00 GlobalRt-18 INFO ckb_tx_pool::pool  [get_block_template] candidate txs count: 9, size: 2150/597000, cycles:0/3500000000
2023-12-01 06:03:01.013 +00:00 GlobalRt-18 INFO ckb_tx_pool::pool  [get_block_template] candidate txs count: 9, size: 2150/596558, cycles:0/3500000000
2023-12-01 06:03:01.013 +00:00 GlobalRt-18 TRACE ckb_tx_pool::block_assembler  [BlockAssembler] update_full 5 uncles-0 proposals-0 txs-9
2023-12-01 06:03:01.807 +00:00 GlobalRt-19 INFO ckb_tx_pool::pool  [get_block_template] candidate txs count: 9, size: 2150/596558, cycles:0/3500000000
2023-12-01 06:03:01.807 +00:00 GlobalRt-19 TRACE ckb_tx_pool::block_assembler  [BlockAssembler] update_transactions-5 epoch-1 uncles-0 proposals-0 txs-9
2023-12-01 06:03:02.007 +00:00 GlobalRt-16 TRACE ckb_network::services::outbound_peer  feeler dial count=0, attempt_peers: []
2023-12-01 06:03:02.007 +00:00 GlobalRt-16 TRACE ckb_network::services::outbound_peer  identify dial count=0, attempt_peers: []
2023-12-01 06:03:02.007 +00:00 GlobalRt-18 TRACE tentacle::service::future_task  future task(1) finished
2023-12-01 06:03:02.102 +00:00 tests::block_assembler::test_package_multi_best_scores ERROR panic  thread 'tests::block_assembler::test_package_multi_best_scores' panicked at 'assertion failed: `(left == right)`
  left: `[Byte32(0xcd0d80078c5fb0aed3cc059f73562cb2f1e4a71823f8d720f83ff9f2c9214769), Byte32(0x001d9a4774b77d4d7d4572a52e7f88b267da4b483b1430ee3b1dbe8a555c0ff5), Byte32(0x790691b80c0e6dfca591bf62f72b4b74018ab296d8fc12c1f078397e8e1e2a2b), Byte32(0xf3ace5260c0e0c38b70235466c75645d70ab41d052035d3a636ead24c8c5c935), Byte32(0x42afa370eeb4ef6707a090317bb07740c97d4762c20bfdf114665e7422489524), Byte32(0xa181a0f4a636b91d7efa55ee49b9a42787847242d76c14343cf25eb116d052c2), Byte32(0xe9d809a20bef9c45bdc1258dadb55e7db72b88029b292633e6d748af00f3b6b3), Byte32(0x8006255ad512edfaee5b658424265bef712f49f82d8e4aae072c144232e167d2), Byte32(0xf2bdff1e814a130cf3a76a7e6147ed9c0fd6b367d4be44f1113149cc932b2b0e)]`,
 right: `[Byte32(0xcd0d80078c5fb0aed3cc059f73562cb2f1e4a71823f8d720f83ff9f2c9214769), Byte32(0x001d9a4774b77d4d7d4572a52e7f88b267da4b483b1430ee3b1dbe8a555c0ff5), Byte32(0x790691b80c0e6dfca591bf62f72b4b74018ab296d8fc12c1f078397e8e1e2a2b), Byte32(0xf3ace5260c0e0c38b70235466c75645d70ab41d052035d3a636ead24c8c5c935), Byte32(0x42afa370eeb4ef6707a090317bb07740c97d4762c20bfdf114665e7422489524), Byte32(0xa181a0f4a636b91d7efa55ee49b9a42787847242d76c14343cf25eb116d052c2), Byte32(0xe9d809a20bef9c45bdc1258dadb55e7db72b88029b292633e6d748af00f3b6b3), Byte32(0x8006255ad512edfaee5b658424265bef712f49f82d8e4aae072c144232e167d2), Byte32(0xd551fbc7a1b0f6ef4e1135ce320a562f66b171a1973ba4800e38810e5c618d9d), Byte32(0xf2bdff1e814a130cf3a76a7e6147ed9c0fd6b367d4be44f1113149cc932b2b0e)]`: best scored txs': chain/src/tests/block_assembler.rs:389   0: ckb_logger_service::setup_panic_logger::{{closure}}
             at /home/exec/Projects/github.com/nervosnetwork/ckb/util/logger-service/src/lib.rs:508:25
   1: <alloc::boxed::Box<F,A> as core::ops::function::Fn<Args>>::call
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/alloc/src/boxed.rs:1999:9
      std::panicking::rust_panic_with_hook
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/std/src/panicking.rs:709:13
   2: std::panicking::begin_panic_handler::{{closure}}
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/std/src/panicking.rs:597:13
   3: std::sys_common::backtrace::__rust_end_short_backtrace
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/std/src/sys_common/backtrace.rs:151:18
   4: rust_begin_unwind
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/std/src/panicking.rs:593:5
   5: core::panicking::panic_fmt
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/core/src/panicking.rs:67:14
   6: core::panicking::assert_failed_inner
   7: core::panicking::assert_failed
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/core/src/panicking.rs:228:5
   8: ckb_chain::tests::block_assembler::check_txs
             at src/tests/block_assembler.rs:389:5
   9: ckb_chain::tests::block_assembler::test_package_multi_best_scores
             at src/tests/block_assembler.rs:598:5
  10: ckb_chain::tests::block_assembler::test_package_multi_best_scores::{{closure}}
             at src/tests/block_assembler.rs:508:37
  11: core::ops::function::FnOnce::call_once
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/core/src/ops/function.rs:250:5
  12: core::ops::function::FnOnce::call_once
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/core/src/ops/function.rs:250:5
      test::__rust_begin_short_backtrace
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/test/src/lib.rs:655:18
  13: test::run_test::{{closure}}
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/test/src/lib.rs:646:30
      core::ops::function::FnOnce::call_once{{vtable.shim}}
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/core/src/ops/function.rs:250:5
  14: <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/alloc/src/boxed.rs:1985:9
      <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/core/src/panic/unwind_safe.rs:271:9
      std::panicking::try::do_call
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/std/src/panicking.rs:500:40
      std::panicking::try
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/std/src/panicking.rs:464:19
      std::panic::catch_unwind
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/std/src/panic.rs:142:14
      test::run_test_in_process
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/test/src/lib.rs:678:27
      test::run_test::run_test_inner::{{closure}}
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/test/src/lib.rs:572:39
  15: test::run_test::run_test_inner::{{closure}}
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/test/src/lib.rs:599:37
      std::sys_common::backtrace::__rust_begin_short_backtrace
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/std/src/sys_common/backtrace.rs:135:18
  16: std::thread::Builder::spawn_unchecked_::{{closure}}::{{closure}}
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/std/src/thread/mod.rs:529:17
      <core::panic::unwind_safe::AssertUnwindSafe<F> as core::ops::function::FnOnce<()>>::call_once
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/core/src/panic/unwind_safe.rs:271:9
      std::panicking::try::do_call
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/std/src/panicking.rs:500:40
      std::panicking::try
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/std/src/panicking.rs:464:19
      std::panic::catch_unwind
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/std/src/panic.rs:142:14
      std::thread::Builder::spawn_unchecked_::{{closure}}
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/std/src/thread/mod.rs:528:30
      core::ops::function::FnOnce::call_once{{vtable.shim}}
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/core/src/ops/function.rs:250:5
  17: <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/alloc/src/boxed.rs:1985:9
      <alloc::boxed::Box<F,A> as core::ops::function::FnOnce<Args>>::call_once
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/alloc/src/boxed.rs:1985:9
      std::sys::unix::thread::Thread::new::thread_start
             at /rustc/eb26296b556cef10fb713a38f3d16b9886080f26/library/std/src/sys/unix/thread.rs:108:17
  18: start_thread
  19: __GI___clone3

test tests::block_assembler::test_package_multi_best_scores ... FAILED

failures:

failures:
    tests::block_assembler::test_package_multi_best_scores

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

error: test failed, to rerun pass `-p ckb-chain --lib`
    Finished test [unoptimized + debuginfo] target(s) in 0.23s

@eval-exec eval-exec mentioned this issue Dec 25, 2023
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
t:bug Type: This doesn't seem right.
Projects
None yet
Milestone
No milestone
1 participant
@eval-exec