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.

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

cmake, doc: Document log output for failed tests #329

Merged
merged 1 commit into from
Aug 15, 2024

Conversation

hebasto
Copy link
Owner

@hebasto hebasto commented Aug 14, 2024

On the master branch, make check generates a foo_tests.log file for each foo_tests.cpp. These log files are only printed when a test fails. Since no one has raised concerns about the log file renaming in bitcoin#19385, these files appear to serve no other purpose.

CTest provides its own mechanisms for logging failed tests, making the creation of foo_tests.log files unnecessary.

This PR documents these CTest logging mechanisms.

An example of output with a mocked test error:

$ ctest --test-dir build -j 16 --output-on-failure
Internal ctest changing into directory: /home/hebasto/git/bitcoin/build
Test project /home/hebasto/git/bitcoin/build
        Start  10: amount_tests
        Start   6: tests
        Start   5: noverify_tests
        Start 120: coinselector_tests
        Start   7: exhaustive_tests
        Start  29: coins_tests
        Start 130: wallet_tests
        Start  75: random_tests
        Start 102: transaction_tests
        Start   1: util_test_runner
        Start 133: walletload_tests
        Start  31: coinstatsindex_tests
        Start  63: net_tests
        Start  35: crypto_tests
        Start  27: checkqueue_tests
        Start  56: miner_tests
  1/133 Test  #10: amount_tests .........................***Failed    0.02 sec
Running 4 test cases...
./src/test/amount_tests.cpp(19): error: in "amount_tests/MoneyRangeTest": check MoneyRange(MAX_MONEY) == false has failed [true != false]

*** 1 failure is detected in the test module "Bitcoin Core Test Suite"


        Start 113: validation_block_tests
  2/133 Test #113: validation_block_tests ...............   Passed    1.02 sec
< snip >
133/133 Test   #6: tests ................................   Passed  100.94 sec

99% tests passed, 1 tests failed out of 133

Total Test time (real) = 100.95 sec

The following tests FAILED:
	 10 - amount_tests (Failed)
Errors while running CTest

A question for reviewers: Do we really need the --log_level=test_suite option for these logs?

Describe log output for failed tests.
@hebasto hebasto added documentation Docs and manuals tests Tests, benchmarks, fuzzing, CI etc labels Aug 14, 2024
@hebasto
Copy link
Owner Author

hebasto commented Aug 14, 2024

cc @maflcko @vasild @fanquake

Copy link

@vasild vasild left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

ACK 784a87e

Do we really need the --log_level=test_suite option for these logs?

No, it is too verbose in an useless way. Correct me if I am wrong, but it is not used now by ctest --test-dir build, right?

@hebasto
Copy link
Owner Author

hebasto commented Aug 14, 2024

Do we really need the --log_level=test_suite option for these logs?

No, it is too verbose in an useless way. Correct me if I am wrong, but it is not used now by ctest --test-dir build, right?

Yes, it is not used now. My question implies a need to update this line:

COMMAND test_bitcoin --run_test=${test_suite_name} --catch_system_error=no

@hebasto hebasto merged commit 3c467d8 into cmake-staging Aug 15, 2024
40 checks passed
@maflcko
Copy link

maflcko commented Aug 23, 2024

Do we really need the --log_level=test_suite option for these logs?

No, it is too verbose in an useless way.

C++ does not print the backtrace on a segmentation fault (or other issue), like other languages like Rust (RUST_BACKTRACE=1) or Python (by default). Thus, the log is needed to print the checkpoint locations, so that at least some line numbers are available, instead of just the test suite name (the test suite could contain many test cases) and "segmentation fault" (without any more details).

So this is not useless.

In any case, changing this seems unrelated to the migration. The previous behavior should be matched here. If there was reason to change it, it could be done in a follow-up.

@vasild
Copy link

vasild commented Aug 23, 2024

the log is needed to print the checkpoint locations

Hmm, not for me:

--- i/src/test/net_tests.cpp
+++ w/src/test/net_tests.cpp
@@ -45,4 +45,5 @@ BOOST_AUTO_TEST_CASE(cnode_listen_port)
     uint16_t altPort = 12345;
     BOOST_CHECK(gArgs.SoftSetArg("-port", ToString(altPort)));
+    assert(0);
     port = GetListenPort();
     BOOST_CHECK(port == altPort);

Without --log_level=test_suite:

./test_bitcoin --run_test=net_tests/cnode_listen_port 
Running 1 test case...
Assertion failed: (0), function test_method, file /.../src/test/net_tests.cpp, line 47.
unknown location(0): fatal error: in "net_tests/cnode_listen_port": signal: SIGABRT (application abort requested)
/.../src/test/net_tests.cpp(46): last checkpoint

*** 1 failure is detected in the test module "Bitcoin Core Test Suite"

With --log_level=test_suite:

./test_bitcoin --run_test=net_tests/cnode_listen_port --log_level=test_suite
Running 1 test case...
Entering test module "Bitcoin Core Test Suite"
/.../src/test/addrman_tests.cpp(62): Test suite "addrman_tests" is skipped because disabled
/.../src/test/allocator_tests.cpp(16): Test suite "allocator_tests" is skipped because disabled
/.../src/test/amount_tests.cpp(12): Test suite "amount_tests" is skipped because disabled
/.../src/test/argsman_tests.cpp(25): Test suite "argsman_tests" is skipped because disabled
/.../src/test/arith_uint256_tests.cpp(19): Test suite "arith_uint256_tests" is skipped because disabled
/.../src/test/banman_tests.cpp(16): Test suite "banman_tests" is skipped because disabled
/.../src/test/base32_tests.cpp(12): Test suite "base32_tests" is skipped because disabled
/.../src/test/base58_tests.cpp(21): Test suite "base58_tests" is skipped because disabled
/.../src/test/base64_tests.cpp(12): Test suite "base64_tests" is skipped because disabled
/.../src/test/bech32_tests.cpp(13): Test suite "bech32_tests" is skipped because disabled
/.../src/test/bip32_tests.cpp(160): Test suite "bip32_tests" is skipped because disabled
/.../src/test/bip324_tests.cpp(161): Test suite "bip324_tests" is skipped because disabled
/.../src/test/blockchain_tests.cpp(54): Test suite "blockchain_tests" is skipped because disabled
/.../src/test/blockencodings_tests.cpp(19): Test suite "blockencodings_tests" is skipped because disabled
/.../src/test/blockfilter_index_tests.cpp(25): Test suite "blockfilter_index_tests" is skipped because disabled
/.../src/test/blockfilter_tests.cpp(19): Test suite "blockfilter_tests" is skipped because disabled
/.../src/test/blockmanager_tests.cpp(26): Test suite "blockmanager_tests" is skipped because disabled
/.../src/test/bloom_tests.cpp(25): Test suite "bloom_tests" is skipped because disabled
/.../src/test/bswap_tests.cpp(9): Test suite "bswap_tests" is skipped because disabled
/.../src/test/checkqueue_tests.cpp(37): Test suite "checkqueue_tests" is skipped because disabled
/.../src/test/cluster_linearize_tests.cpp(15): Test suite "cluster_linearize_tests" is skipped because disabled
/.../src/test/coins_tests.cpp(104): Test suite "coins_tests" is skipped because disabled
/.../src/test/coinscachepair_tests.cpp(11): Test suite "coinscachepair_tests" is skipped because disabled
/.../src/test/coinstatsindex_tests.cpp(16): Test suite "coinstatsindex_tests" is skipped because disabled
/.../src/test/common_url_tests.cpp(11): Test suite "common_url_tests" is skipped because disabled
/.../src/test/compilerbug_tests.cpp(7): Test suite "compilerbug_tests" is skipped because disabled
/.../src/test/compress_tests.cpp(26): Test suite "compress_tests" is skipped because disabled
/.../src/test/crypto_tests.cpp(28): Test suite "crypto_tests" is skipped because disabled
/.../src/test/cuckoocache_tests.cpp(32): Test suite "cuckoocache_tests" is skipped because disabled
/.../src/test/dbwrapper_tests.cpp(27): Test suite "dbwrapper_tests" is skipped because disabled
/.../src/test/denialofservice_tests.cpp(35): Test suite "denialofservice_tests" is skipped because disabled
/.../src/test/descriptor_tests.cpp(439): Test suite "descriptor_tests" is skipped because disabled
/.../src/test/disconnected_transactions.cpp(10): Test suite "disconnected_transactions" is skipped because disabled
/.../src/test/feefrac_tests.cpp(10): Test suite "feefrac_tests" is skipped because disabled
/.../src/test/flatfile_tests.cpp(13): Test suite "flatfile_tests" is skipped because disabled
/.../src/test/fs_tests.cpp(15): Test suite "fs_tests" is skipped because disabled
/.../src/test/getarg_tests.cpp(21): Test suite "getarg_tests" is skipped because disabled
/.../src/test/hash_tests.cpp(14): Test suite "hash_tests" is skipped because disabled
/.../src/test/headers_sync_chainwork_tests.cpp(58): Test suite "headers_sync_chainwork_tests" is skipped because disabled
/.../src/test/httpserver_tests.cpp(10): Test suite "httpserver_tests" is skipped because disabled
/.../src/test/i2p_tests.cpp(45): Test suite "i2p_tests" is skipped because disabled
/.../src/test/interfaces_tests.cpp(16): Test suite "interfaces_tests" is skipped because disabled
/.../src/test/key_io_tests.cpp(20): Test suite "key_io_tests" is skipped because disabled
/.../src/test/key_tests.cpp(37): Test suite "key_tests" is skipped because disabled
/.../src/test/logging_tests.cpp(23): Test suite "logging_tests" is skipped because disabled
/.../src/test/mempool_tests.cpp(16): Test suite "mempool_tests" is skipped because disabled
/.../src/test/merkle_tests.cpp(11): Test suite "merkle_tests" is skipped because disabled
/.../src/test/merkleblock_tests.cpp(14): Test suite "merkleblock_tests" is skipped because disabled
/.../src/test/miner_tests.cpp(60): Test suite "miner_tests" is skipped because disabled
/.../src/test/miniminer_tests.cpp(16): Test suite "miniminer_tests" is skipped because disabled
/.../src/test/miniscript_tests.cpp(494): Test suite "miniscript_tests" is skipped because disabled
/.../src/test/minisketch_tests.cpp(17): Test suite "minisketch_tests" is skipped because disabled
/.../src/test/multisig_tests.cpp(19): Test suite "multisig_tests" is skipped because disabled
/.../src/test/net_peer_connection_tests.cpp(37): Test suite "net_peer_connection_tests" is skipped because disabled
/.../src/test/net_peer_eviction_tests.cpp(18): Test suite "net_peer_eviction_tests" is skipped because disabled
/.../src/test/net_tests.cpp(37): Entering test suite "net_tests"
/.../src/test/net_tests.cpp(39): Entering test case "cnode_listen_port"
Assertion failed: (0), function test_method, file /.../src/test/net_tests.cpp, line 47.
unknown location(0): fatal error: in "net_tests/cnode_listen_port": signal: SIGABRT (application abort requested)
/.../src/test/net_tests.cpp(46): last checkpoint
/.../src/test/net_tests.cpp(39): Leaving test case "cnode_listen_port"; testing time: 134961us
/.../src/test/net_tests.cpp(52): Test case "net_tests/cnode_simple_test" is skipped because disabled
/.../src/test/net_tests.cpp(135): Test case "net_tests/cnetaddr_basic" is skipped because disabled
/.../src/test/net_tests.cpp(276): Test case "net_tests/cnetaddr_tostring_canonical_ipv6" is skipped because disabled
/.../src/test/net_tests.cpp(329): Test case "net_tests/cnetaddr_serialize_v1" is skipped because disabled
/.../src/test/net_tests.cpp(363): Test case "net_tests/cnetaddr_serialize_v2" is skipped because disabled
/.../src/test/net_tests.cpp(397): Test case "net_tests/cnetaddr_unserialize_v2" is skipped because disabled
/.../src/test/net_tests.cpp(605): Test case "net_tests/ipv4_peer_with_ipv6_addrMe_test" is skipped because disabled
/.../src/test/net_tests.cpp(656): Test case "net_tests/get_local_addr_for_peer_port" is skipped because disabled
/.../src/test/net_tests.cpp(720): Test case "net_tests/LimitedAndReachable_Network" is skipped because disabled
/.../src/test/net_tests.cpp(753): Test case "net_tests/LimitedAndReachable_NetworkCaseUnroutableAndInternal" is skipped because disabled
/.../src/test/net_tests.cpp(784): Test case "net_tests/LimitedAndReachable_CNetAddr" is skipped because disabled
/.../src/test/net_tests.cpp(798): Test case "net_tests/LocalAddress_BasicLifecycle" is skipped because disabled
/.../src/test/net_tests.cpp(812): Test case "net_tests/initial_advertise_from_version_message" is skipped because disabled
/.../src/test/net_tests.cpp(909): Test case "net_tests/advertise_local_address" is skipped because disabled
/.../src/test/net_tests.cpp(1345): Test case "net_tests/v2transport_test" is skipped because disabled
/.../src/test/net_tests.cpp(37): Leaving test suite "net_tests"; testing time: 135022us
/.../src/test/netbase_tests.cpp(22): Test suite "netbase_tests" is skipped because disabled
/.../src/test/node_warnings_tests.cpp(13): Test suite "node_warnings_tests" is skipped because disabled
/.../src/test/orphanage_tests.cpp(19): Test suite "orphanage_tests" is skipped because disabled
/.../src/test/peerman_tests.cpp(14): Test suite "peerman_tests" is skipped because disabled
/.../src/test/pmt_tests.cpp(28): Test suite "pmt_tests" is skipped because disabled
/.../src/test/policy_fee_tests.cpp(12): Test suite "policy_fee_tests" is skipped because disabled
/.../src/test/policyestimator_tests.cpp(18): Test suite "policyestimator_tests" is skipped because disabled
/.../src/test/pool_tests.cpp(18): Test suite "pool_tests" is skipped because disabled
/.../src/test/pow_tests.cpp(14): Test suite "pow_tests" is skipped because disabled
/.../src/test/prevector_tests.cpp(16): Test suite "prevector_tests" is skipped because disabled
/.../src/test/raii_event_tests.cpp(16): Test suite "raii_event_tests" is skipped because disabled
/.../src/test/random_tests.cpp(16): Test suite "random_tests" is skipped because disabled
/.../src/test/rbf_tests.cpp(17): Test suite "rbf_tests" is skipped because disabled
/.../src/test/rest_tests.cpp(12): Test suite "rest_tests" is skipped because disabled
/.../src/test/result_tests.cpp(19): Test suite "result_tests" is skipped because disabled
/.../src/test/reverselock_tests.cpp(12): Test suite "reverselock_tests" is skipped because disabled
/.../src/test/rpc_tests.cpp(85): Test suite "rpc_tests" is skipped because disabled
/.../src/test/sanity_tests.cpp(10): Test suite "sanity_tests" is skipped because disabled
/.../src/test/scheduler_tests.cpp(16): Test suite "scheduler_tests" is skipped because disabled
/.../src/test/script_p2sh_tests.cpp(57): Test suite "script_p2sh_tests" is skipped because disabled
/.../src/test/script_parse_tests.cpp(12): Test suite "script_parse_tests" is skipped because disabled
/.../src/test/script_segwit_tests.cpp(10): Test suite "script_segwit_tests" is skipped because disabled
/.../src/test/script_standard_tests.cpp(20): Test suite "script_standard_tests" is skipped because disabled
/.../src/test/script_tests.cpp(113): Test suite "script_tests" is skipped because disabled
/.../src/test/scriptnum_tests.cpp(13): Test suite "scriptnum_tests" is skipped because disabled
/.../src/test/serfloat_tests.cpp(17): Test suite "serfloat_tests" is skipped because disabled
/.../src/test/serialize_tests.cpp(16): Test suite "serialize_tests" is skipped because disabled
/.../src/test/settings_tests.cpp(52): Test suite "settings_tests" is skipped because disabled
/.../src/test/sighash_tests.cpp(117): Test suite "sighash_tests" is skipped because disabled
/.../src/test/sigopcount_tests.cpp(29): Test suite "sigopcount_tests" is skipped because disabled
/.../src/test/skiplist_tests.cpp(15): Test suite "skiplist_tests" is skipped because disabled
/.../src/test/sock_tests.cpp(18): Test suite "sock_tests" is skipped because disabled
/.../src/test/span_tests.cpp(47): Test suite "span_tests" is skipped because disabled
/.../src/test/streams_tests.cpp(15): Test suite "streams_tests" is skipped because disabled
/.../src/test/sync_tests.cpp(80): Test suite "sync_tests" is skipped because disabled
/.../src/test/system_tests.cpp(17): Test suite "system_tests" is skipped because disabled
/.../src/test/timeoffsets_tests.cpp(24): Test suite "timeoffsets_tests" is skipped because disabled
/.../src/test/torcontrol_tests.cpp(17): Test suite "torcontrol_tests" is skipped because disabled
/.../src/test/transaction_tests.cpp(191): Test suite "transaction_tests" is skipped because disabled
/.../src/test/translation_tests.cpp(10): Test suite "translation_tests" is skipped because disabled
/.../src/test/txindex_tests.cpp(15): Test suite "txindex_tests" is skipped because disabled
/.../src/test/txpackage_tests.cpp(23): Test suite "txpackage_tests" is skipped because disabled
/.../src/test/txreconciliation_tests.cpp(11): Test suite "txreconciliation_tests" is skipped because disabled
/.../src/test/txrequest_tests.cpp(18): Test suite "txrequest_tests" is skipped because disabled
/.../src/test/txvalidation_tests.cpp(20): Test suite "txvalidation_tests" is skipped because disabled
/.../src/test/txvalidationcache_tests.cpp(29): Test suite "txvalidationcache_tests" is skipped because disabled
/.../src/test/uint256_tests.cpp(20): Test suite "uint256_tests" is skipped because disabled
/.../src/test/util_tests.cpp(64): Test suite "util_tests" is skipped because disabled
/.../src/test/util_threadnames_tests.cpp(18): Test suite "util_threadnames_tests" is skipped because disabled
/.../src/test/validation_block_tests.cpp(34): Test suite "validation_block_tests" is skipped because disabled
/.../src/test/validation_chainstate_tests.cpp(22): Test suite "validation_chainstate_tests" is skipped because disabled
/.../src/test/validation_chainstatemanager_tests.cpp(32): Test suite "validation_chainstatemanager_tests" is skipped because disabled
/.../src/test/validation_flush_tests.cpp(13): Test suite "validation_flush_tests" is skipped because disabled
/.../src/test/validation_tests.cpp(22): Test suite "validation_tests" is skipped because disabled
/.../src/test/validationinterface_tests.cpp(16): Test suite "validationinterface_tests" is skipped because disabled
/.../src/test/versionbits_tests.cpp(187): Test suite "versionbits_tests" is skipped because disabled
/.../src/wallet/test/coinselector_tests.cpp(24): Test suite "coinselector_tests" is skipped because disabled
/.../src/wallet/test/feebumper_tests.cpp(18): Test suite "feebumper_tests" is skipped because disabled
/.../src/wallet/test/group_outputs_tests.cpp(15): Test suite "group_outputs_tests" is skipped because disabled
/.../src/wallet/test/init_tests.cpp(14): Test suite "init_tests" is skipped because disabled
/.../src/wallet/test/ismine_tests.cpp(20): Test suite "ismine_tests" is skipped because disabled
/.../src/wallet/test/psbt_wallet_tests.cpp(16): Test suite "psbt_wallet_tests" is skipped because disabled
/.../src/wallet/test/rpc_util_tests.cpp(11): Test suite "wallet_util_tests" is skipped because disabled
/.../src/wallet/test/scriptpubkeyman_tests.cpp(15): Test suite "scriptpubkeyman_tests" is skipped because disabled
/.../src/wallet/test/spend_tests.cpp(17): Test suite "spend_tests" is skipped because disabled
/.../src/wallet/test/wallet_crypto_tests.cpp(15): Test suite "wallet_crypto_tests" is skipped because disabled
/.../src/wallet/test/wallet_tests.cpp(47): Test suite "wallet_tests" is skipped because disabled
/.../src/wallet/test/wallet_transaction_tests.cpp(12): Test suite "wallet_transaction_tests" is skipped because disabled
/.../src/wallet/test/walletdb_tests.cpp(15): Test suite "walletdb_tests" is skipped because disabled
/.../src/wallet/test/walletload_tests.cpp(14): Test suite "walletload_tests" is skipped because disabled
Leaving test module "Bitcoin Core Test Suite"; testing time: 135541us

*** 1 failure is detected in the test module "Bitcoin Core Test Suite"

@maflcko
Copy link

maflcko commented Aug 23, 2024

the log is needed to print the checkpoint locations

Hmm, not for me:

You will have to use the other options as well. For example --catch_system_error=no. If you use other options, a different result is expected.

@maflcko
Copy link

maflcko commented Aug 23, 2024

To clarify, the catch_system_error comes from #329 (comment)

@vasild
Copy link

vasild commented Aug 23, 2024

Again, the only difference between:

test_bitcoin --run_test=net_tests/cnode_listen_port --catch_system_error=no

and

test_bitcoin --run_test=net_tests/cnode_listen_port --catch_system_error=no --log_level=test_suite

is an extra clutter in the second case. The checkpoint is not printed in either case (when --catch_system_error=no is used).

Can you show the exact commands and their output that demonstrate that adding --log_level=test_suite prints the checkpoint whereas without --log_level=test_suite the checkpoint is not printed?

@maflcko
Copy link

maflcko commented Aug 23, 2024

Again, you'll have to use the exact same options as the ctest command in #329 (comment) and compare it to the automake command. Using something else will give another result.

For example, you are specifying the test case, so there is only one test running. However, ctest specifies a test suite. Also, DEBUG_LOG_OUT is missing as well.

Thus, the commands to compare would be:

./test_bitcoin --run_test=net_tests --catch_system_error=no

and

./test_bitcoin --run_test=net_tests --catch_system_error=no --log_level=test_suite -- DEBUG_LOG_OUT

@vasild
Copy link

vasild commented Aug 23, 2024

The last checkpoint is not printed for neither of the above commands 👀

@maflcko
Copy link

maflcko commented Aug 23, 2024

Ah right, the log level for that would be all. However, removing the log level completely is still wrong, because all debug logs would be interleaved without an easy way to spot sections when a unit test starts or ends.

@maflcko
Copy link

maflcko commented Aug 23, 2024

Can you show the exact commands and their output that demonstrate that adding --log_level=test_suite prints the checkpoint whereas without --log_level=test_suite the checkpoint is not printed?

Sure, see below, where I test this with a segfault. Omitting the log level doesn't give any hint where the issue happened. However, with the log level, one can at least see the unit test.

./test_bitcoin --run_test=net_tests --catch_system_error=no
Running 16 test cases...
Segmentation fault (core dumped)
./test_bitcoin --run_test=net_tests --catch_system_error=no --log_level=test_suite
Running 16 test cases...

<snip>

../../src/test/net_tests.cpp(51): Entering test case "cnode_simple_test"
Segmentation fault (core dumped)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
documentation Docs and manuals tests Tests, benchmarks, fuzzing, CI etc
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants