If the output lines of cargo test are interrupted by some log messages, which can occur during concurrent test execution, cargo-pretty-test cannot provide the right result.
Then, it outputs the following error, which should be expected to be passed.
Error from cargo-pretty-test:
the parsed amount of running tests [17] should equal to the number in stats.total [16]
split = [
(
1,
"running 17 tests",
17,
),
]
parsed_stdout = [
(
[
"test action::action_json::test::test_action_map_order ... ok",
"test action::test_action::test::test ... ok",
"test action::test_tla_typed_value::test::test_tla_typed_value ... ok",
"test data::path::_test::_test_non_exist_data_file - should panic ... ok",
"test dtm::action_input_json::test::test_read_trace_json ... ok",
"test dtm::test_dtm_player::test::test_dtm_player_check_all ... ok",
"test dtm::test_dtm_player::test::test_dtm_player_no_check ... ok",
"test trace::cover_walk_path::test::test_cover_walk_path ... ok",
"test trace::cover_walk_path::test::test_cover_walk_path_json_input ... ok",
"test trace::graph_find_path::test::test_contracted_scc ... ok",
"test trace::graph_find_path::test::test_find_path ... ok",
"test trace::graph_find_scc::test::test ... ok",
"test trace::subgraph_path::test::test_find_path_of ... ok",
"test trace::test_state_db_to_case::test::test_db_to_setup_init_trace ... ok",
"test trace::test_state_db_to_case::test::test_db_to_trace ... ok",
"test trace::test_trace_reader::test::test_trace_reader ... ok",
],
"",
Stats {
ok: true,
total: 16,
passed: 17,
failed: 0,
ignored: 0,
measured: 0,
filtered_out: 0,
finished_in: 3.650000095s,
},
"\nrunning 17 tests\n2024-06-28T10:58:01.371084Z INFO src/dtm/test_dtm_player.rs:53: test_dtm_player_no_check\n2024-06-28T10:58:01.371083Z INFO src/dtm/test_dtm_player.rs:46: test_dtm_player_check_all\ntest action::action_json::test::test_action_json ... 2024-06-28T10:58:01.371285Z INFO src/trace/test_state_db_to_case.rs:20: test_db_to_setup_init_trace\nok\ntest trace::cover_walk_path::test::test_cover_walk_path ... ok\ntest action::action_json::test::test_action_map_order ... ok\ntest trace::cover_walk_path::test::test_cover_walk_path_json_input ... ok\n2024-06-28T10:58:01.371420Z INFO src/trace/graph_find_path.rs:54: Time elapsed to find root vertex : 29.089µs\n2024-06-28T10:58:01.371477Z INFO src/trace/test_state_db_to_case.rs:13: test_db_to_trace\ntest data::path::_test::_test_non_exist_data_file - should panic ... ok\ntest trace::subgraph_path::test::test_find_path_of ... ok\n2024-06-28T10:58:01.371576Z INFO src/trace/graph_find_path.rs:276: Time elapsed to find 9 SCC: 95.328µs\n2024-06-28T10:58:01.371579Z INFO src/trace/gen_case.rs:43: use const mapping: {\"A_v1\": Number(100), \"A_v2\": Number(200), \"INVALID_NODE_ID\": Null, \"A_n3\": Number(3), \"A_n1\": Number(1), \"A_n2\": Number(2)}\n2024-06-28T10:58:01.371594Z INFO src/trace/gen_case.rs:43: use const mapping: {\"A_v1\": Number(100), \"A_n3\": Number(3), \"A_n1\": Number(1), \"INVALID_NODE_ID\": Null, \"A_v2\": Number(200), \"A_n2\": Number(2)}\ntest action::test_action::test::test ... ok\n2024-06-28T10:58:01.371647Z INFO src/dtm/test_dtm_player.rs:693: Generate test case, total action 31\n2024-06-28T10:58:01.371664Z INFO src/trace/graph_find_path.rs:314: Time elapsed to contract SCC 72.793µs\n2024-06-28T10:58:01.371737Z INFO src/trace/graph_find_path.rs:109: Time elapsed to find path : 53.605µs\ntest trace::graph_find_path::test::test_find_path ... ok\ntest trace::graph_find_scc::test::test ... ok\ntest dtm::action_input_json::test::test_read_trace_json ... ok\ntest action::test_tla_typed_value::test::test_tla_typed_value ... ok\n2024-06-28T10:58:01.396480Z INFO src/trace/action_from_state_db.rs:111: To write actions to DB\n2024-06-28T10:58:01.397475Z INFO src/trace/action_from_state_db.rs:111: To write actions to DB\ntest trace::test_trace_reader::test::test_trace_reader ... ok\ntest dtm::test_dtm_player::test::test_dtm_player_no_check ... ok\n2024-06-28T10:58:02.482752Z INFO src/dtm/test_dtm_player.rs:693: Generate test case, total action 31\n2024-06-28T10:58:02.506412Z INFO src/trace/graph_find_path.rs:276: Time elapsed to find 54482 SCC: 682.570869ms\n2024-06-28T10:58:02.979120Z INFO src/trace/graph_find_path.rs:314: Time elapsed to contract SCC 472.68078ms\n2024-06-28T10:58:03.006404Z INFO src/trace/graph_find_path.rs:565: Time elapsed to find 32749 non-trivial scc, 6.635µs,\ntest trace::graph_find_path::test::test_contracted_scc ... ok\n2024-06-28T10:58:03.147732Z INFO src/trace/action_from_state_db.rs:130: Time elapsed to write actions to DB, time costs: 1.751221544s\n2024-06-28T10:58:03.148668Z INFO src/trace/action_from_state_db.rs:130: Time elapsed to write actions to DB, time costs: 1.751176376s\n2024-06-28T10:58:03.151040Z INFO src/trace/gen_case.rs:49: Time elapsed to read from state DB /home/ybbh/workspace/sedeve-kit/src/data/state.db and write actions, time costs: 1.779421409s\n2024-06-28T10:58:03.151623Z INFO src/trace/gen_case.rs:49: Time elapsed to read from state DB /home/ybbh/workspace/sedeve-kit/src/data/state.db and write actions, time costs: 1.780031912s\n2024-06-28T10:58:03.162452Z INFO src/trace/gen_case.rs:93: To write path to DB\n2024-06-28T10:58:03.163276Z INFO src/trace/gen_case.rs:93: To write path to DB\n2024-06-28T10:58:03.164707Z INFO src/trace/graph_find_path.rs:54: Time elapsed to find root vertex : 2.083829ms\n2024-06-28T10:58:03.165492Z INFO src/trace/graph_find_path.rs:54: Time elapsed to find root vertex : 2.070202ms\n2024-06-28T10:58:03.170889Z INFO src/trace/graph_find_path.rs:276: Time elapsed to find 1831 SCC: 5.811629ms\n2024-06-28T10:58:03.171105Z INFO src/trace/graph_find_path.rs:314: Time elapsed to contract SCC 209.744µs\n2024-06-28T10:58:03.171658Z INFO src/trace/graph_find_path.rs:276: Time elapsed to find 1831 SCC: 5.796028ms\n2024-06-28T10:58:03.171875Z INFO src/trace/graph_find_path.rs:314: Time elapsed to contract SCC 210.515µs\n2024-06-28T10:58:03.218745Z INFO src/trace/graph_find_path.rs:109: Time elapsed to find path : 47.498926ms\n2024-06-28T10:58:03.219626Z INFO src/trace/graph_find_path.rs:109: Time elapsed to find path : 47.608945ms\n2024-06-28T10:58:03.256142Z INFO src/trace/gen_case.rs:129: Time elapsed to handle action graph, time costs: 89.149499ms\n2024-06-28T10:58:03.256234Z INFO src/trace/gen_case.rs:54: Time elapsed to generate path, time costs: 105.182508ms\n2024-06-28T10:58:03.256311Z INFO src/trace/trace_builder.rs:66: To write traces to DB\n2024-06-28T10:58:03.257986Z INFO src/trace/gen_case.rs:129: Time elapsed to handle action graph, time costs: 88.802789ms\n2024-06-28T10:58:03.258044Z INFO src/trace/gen_case.rs:54: Time elapsed to generate path, time costs: 106.412373ms\n2024-06-28T10:58:03.258122Z INFO src/trace/trace_builder.rs:66: To write traces to DB\n2024-06-28T10:58:03.412206Z INFO src/trace/trace_builder.rs:91: write 1830 traces\n2024-06-28T10:58:03.565550Z INFO src/trace/gen_case.rs:67: Time elapsed to gen final trace, time costs: 309.224473ms\n2024-06-28T10:58:03.683669Z INFO src/dtm/test_dtm_player.rs:217: Check history OK\ntest dtm::test_dtm_player::test::test_dtm_player_check_all ... ok\n2024-06-28T10:58:03.802350Z INFO src/trace/trace_builder.rs:91: write 701 traces\ntest trace::test_state_db_to_case::test::test_db_to_setup_init_trace ... ok\n2024-06-28T10:58:04.206334Z INFO src/trace/gen_case.rs:67: Time elapsed to gen final trace, time costs: 948.196845ms\ntest trace::test_state_db_to_case::test::test_db_to_trace ... ok\n\ntest result: ok. 17 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 3.65s\n\n",
),
]
Error from cargo test:
Finished `test` profile [unoptimized + debuginfo] target(s) in 0.06s
Running unittests src/lib.rs (target/debug/deps/sedeve_kit-bbc70c8b41e33ad5)
running 17 tests
2024-06-28T10:58:01.371084Z INFO src/dtm/test_dtm_player.rs:53: test_dtm_player_no_check
2024-06-28T10:58:01.371083Z INFO src/dtm/test_dtm_player.rs:46: test_dtm_player_check_all
test action::action_json::test::test_action_json ... 2024-06-28T10:58:01.371285Z INFO src/trace/test_state_db_to_case.rs:20: test_db_to_setup_init_trace
ok
test trace::cover_walk_path::test::test_cover_walk_path ... ok
test action::action_json::test::test_action_map_order ... ok
test trace::cover_walk_path::test::test_cover_walk_path_json_input ... ok
2024-06-28T10:58:01.371420Z INFO src/trace/graph_find_path.rs:54: Time elapsed to find root vertex : 29.089µs
2024-06-28T10:58:01.371477Z INFO src/trace/test_state_db_to_case.rs:13: test_db_to_trace
test data::path::_test::_test_non_exist_data_file - should panic ... ok
test trace::subgraph_path::test::test_find_path_of ... ok
2024-06-28T10:58:01.371576Z INFO src/trace/graph_find_path.rs:276: Time elapsed to find 9 SCC: 95.328µs
2024-06-28T10:58:01.371579Z INFO src/trace/gen_case.rs:43: use const mapping: {"A_v1": Number(100), "A_v2": Number(200), "INVALID_NODE_ID": Null, "A_n3": Number(3), "A_n1": Number(1), "A_n2": Number(2)}
2024-06-28T10:58:01.371594Z INFO src/trace/gen_case.rs:43: use const mapping: {"A_v1": Number(100), "A_n3": Number(3), "A_n1": Number(1), "INVALID_NODE_ID": Null, "A_v2": Number(200), "A_n2": Number(2)}
test action::test_action::test::test ... ok
2024-06-28T10:58:01.371647Z INFO src/dtm/test_dtm_player.rs:693: Generate test case, total action 31
2024-06-28T10:58:01.371664Z INFO src/trace/graph_find_path.rs:314: Time elapsed to contract SCC 72.793µs
2024-06-28T10:58:01.371737Z INFO src/trace/graph_find_path.rs:109: Time elapsed to find path : 53.605µs
test trace::graph_find_path::test::test_find_path ... ok
test trace::graph_find_scc::test::test ... ok
test dtm::action_input_json::test::test_read_trace_json ... ok
test action::test_tla_typed_value::test::test_tla_typed_value ... ok
2024-06-28T10:58:01.396480Z INFO src/trace/action_from_state_db.rs:111: To write actions to DB
2024-06-28T10:58:01.397475Z INFO src/trace/action_from_state_db.rs:111: To write actions to DB
test trace::test_trace_reader::test::test_trace_reader ... ok
test dtm::test_dtm_player::test::test_dtm_player_no_check ... ok
2024-06-28T10:58:02.482752Z INFO src/dtm/test_dtm_player.rs:693: Generate test case, total action 31
2024-06-28T10:58:02.506412Z INFO src/trace/graph_find_path.rs:276: Time elapsed to find 54482 SCC: 682.570869ms
2024-06-28T10:58:02.979120Z INFO src/trace/graph_find_path.rs:314: Time elapsed to contract SCC 472.68078ms
2024-06-28T10:58:03.006404Z INFO src/trace/graph_find_path.rs:565: Time elapsed to find 32749 non-trivial scc, 6.635µs,
test trace::graph_find_path::test::test_contracted_scc ... ok
2024-06-28T10:58:03.147732Z INFO src/trace/action_from_state_db.rs:130: Time elapsed to write actions to DB, time costs: 1.751221544s
2024-06-28T10:58:03.148668Z INFO src/trace/action_from_state_db.rs:130: Time elapsed to write actions to DB, time costs: 1.751176376s
2024-06-28T10:58:03.151040Z INFO src/trace/gen_case.rs:49: Time elapsed to read from state DB /home/ybbh/workspace/sedeve-kit/src/data/state.db and write actions, time costs: 1.779421409s
2024-06-28T10:58:03.151623Z INFO src/trace/gen_case.rs:49: Time elapsed to read from state DB /home/ybbh/workspace/sedeve-kit/src/data/state.db and write actions, time costs: 1.780031912s
2024-06-28T10:58:03.162452Z INFO src/trace/gen_case.rs:93: To write path to DB
2024-06-28T10:58:03.163276Z INFO src/trace/gen_case.rs:93: To write path to DB
2024-06-28T10:58:03.164707Z INFO src/trace/graph_find_path.rs:54: Time elapsed to find root vertex : 2.083829ms
2024-06-28T10:58:03.165492Z INFO src/trace/graph_find_path.rs:54: Time elapsed to find root vertex : 2.070202ms
2024-06-28T10:58:03.170889Z INFO src/trace/graph_find_path.rs:276: Time elapsed to find 1831 SCC: 5.811629ms
2024-06-28T10:58:03.171105Z INFO src/trace/graph_find_path.rs:314: Time elapsed to contract SCC 209.744µs
2024-06-28T10:58:03.171658Z INFO src/trace/graph_find_path.rs:276: Time elapsed to find 1831 SCC: 5.796028ms
2024-06-28T10:58:03.171875Z INFO src/trace/graph_find_path.rs:314: Time elapsed to contract SCC 210.515µs
2024-06-28T10:58:03.218745Z INFO src/trace/graph_find_path.rs:109: Time elapsed to find path : 47.498926ms
2024-06-28T10:58:03.219626Z INFO src/trace/graph_find_path.rs:109: Time elapsed to find path : 47.608945ms
2024-06-28T10:58:03.256142Z INFO src/trace/gen_case.rs:129: Time elapsed to handle action graph, time costs: 89.149499ms
2024-06-28T10:58:03.256234Z INFO src/trace/gen_case.rs:54: Time elapsed to generate path, time costs: 105.182508ms
2024-06-28T10:58:03.256311Z INFO src/trace/trace_builder.rs:66: To write traces to DB
2024-06-28T10:58:03.257986Z INFO src/trace/gen_case.rs:129: Time elapsed to handle action graph, time costs: 88.802789ms
2024-06-28T10:58:03.258044Z INFO src/trace/gen_case.rs:54: Time elapsed to generate path, time costs: 106.412373ms
2024-06-28T10:58:03.258122Z INFO src/trace/trace_builder.rs:66: To write traces to DB
2024-06-28T10:58:03.412206Z INFO src/trace/trace_builder.rs:91: write 1830 traces
2024-06-28T10:58:03.565550Z INFO src/trace/gen_case.rs:67: Time elapsed to gen final trace, time costs: 309.224473ms
2024-06-28T10:58:03.683669Z INFO src/dtm/test_dtm_player.rs:217: Check history OK
test dtm::test_dtm_player::test::test_dtm_player_check_all ... ok
2024-06-28T10:58:03.802350Z INFO src/trace/trace_builder.rs:91: write 701 traces
test trace::test_state_db_to_case::test::test_db_to_setup_init_trace ... ok
2024-06-28T10:58:04.206334Z INFO src/trace/gen_case.rs:67: Time elapsed to gen final trace, time costs: 948.196845ms
test trace::test_state_db_to_case::test::test_db_to_trace ... ok
test result: ok. 17 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 3.65s
If the output lines of cargo test are interrupted by some log messages, which can occur during concurrent test execution, cargo-pretty-test cannot provide the right result.
cargo and cargo-pretty-test version
Run cargo pretty-test
Then, it outputs the following error, which should be expected to be passed.