Skip to content

Conversation

maflcko
Copy link
Member

@maflcko maflcko commented Sep 27, 2019

Often, it is hard to debug unit test failures without the debug log. Especially when the failure happens remotely (e.g. on a ci system).

Fix that by printing the log on failure.

@fanquake fanquake added the Tests label Sep 27, 2019
@maflcko maflcko force-pushed the 1909-testPrintLogOnFail branch 5 times, most recently from fa758c2 to fa8e20a Compare September 27, 2019 17:56
@maflcko
Copy link
Member Author

maflcko commented Sep 27, 2019

Can be tested by injecting a failure in any test case and then running make check

@jamesob
Copy link
Contributor

jamesob commented Sep 27, 2019

Concept ACK.

Ran make -j7 check with following patch and got confusing output - looks like a lot of duplicated lines. Maybe unavoidable?

diff --git a/src/test/net_tests.cpp b/src/test/net_tests.cpp
index fed65afdbf..d0948dcbca 100644
--- a/src/test/net_tests.cpp
+++ b/src/test/net_tests.cpp
@@ -88,6 +88,7 @@ BOOST_AUTO_TEST_CASE(cnode_listen_port)
     BOOST_CHECK(gArgs.SoftSetArg("-port", std::to_string(altPort)));
     port = GetListenPort();
     BOOST_CHECK(port == altPort);
+    BOOST_CHECK(false);
 }
 
 BOOST_AUTO_TEST_CASE(caddrdb_read)
Making check in src
make[1]: Entering directory '/home/james/src/bitcoin/src'
make[2]: Entering directory '/home/james/src/bitcoin/src'
make[3]: Entering directory '/home/james/src/bitcoin'
make[3]: Leaving directory '/home/james/src/bitcoin'
make  check-TESTS check-local
make[3]: Entering directory '/home/james/src/bitcoin/src'
Running tests: arith_uint256_tests from test/arith_uint256_tests.cpp
Running tests: addrman_tests from test/addrman_tests.cpp
Running tests: amount_tests from test/amount_tests.cpp
Running tests: allocator_tests from test/allocator_tests.cpp
Running tests: base32_tests from test/base32_tests.cpp
Running tests: base58_tests from test/base58_tests.cpp
Running tests: base64_tests from test/base64_tests.cpp
Running tests: bech32_tests from test/bech32_tests.cpp
Running tests: bip32_tests from test/bip32_tests.cpp
Running tests: blockchain_tests from test/blockchain_tests.cpp
Running tests: blockencodings_tests from test/blockencodings_tests.cpp
Running tests: blockfilter_tests from test/blockfilter_tests.cpp
Running tests: blockfilter_index_tests from test/blockfilter_index_tests.cpp
Running tests: bloom_tests from test/bloom_tests.cpp
Running tests: bswap_tests from test/bswap_tests.cpp
Running tests: checkqueue_tests from test/checkqueue_tests.cpp
Running tests: coins_tests from test/coins_tests.cpp
Running tests: compilerbug_tests from test/compilerbug_tests.cpp
Running tests: compress_tests from test/compress_tests.cpp
Running tests: crypto_tests from test/crypto_tests.cpp
Running tests: cuckoocache_tests from test/cuckoocache_tests.cpp
Running tests: denialofservice_tests from test/denialofservice_tests.cpp
make[4]: Entering directory '/home/james/src/bitcoin/src'
make[5]: Entering directory '/home/james/src/bitcoin'
make[5]: Leaving directory '/home/james/src/bitcoin'
Running tests: descriptor_tests from test/descriptor_tests.cpp
Running tests: flatfile_tests from test/flatfile_tests.cpp
Running tests: fs_tests from test/fs_tests.cpp
Running tests: getarg_tests from test/getarg_tests.cpp
Running tests: hash_tests from test/hash_tests.cpp
Running tests: key_io_tests from test/key_io_tests.cpp
Running tests: key_tests from test/key_tests.cpp
Running tests: limitedmap_tests from test/limitedmap_tests.cpp
Running tests: dbwrapper_tests from test/dbwrapper_tests.cpp
Running tests: validation_tests from test/validation_tests.cpp
Running tests: mempool_tests from test/mempool_tests.cpp
Running tests: merkle_tests from test/merkle_tests.cpp
Running tests: merkleblock_tests from test/merkleblock_tests.cpp
Running tests: miner_tests from test/miner_tests.cpp
PASS: qt/test/test_bitcoin-qt
============================================================================
Testsuite summary for Bitcoin Core 0.18.99
============================================================================
# TOTAL: 1
# PASS:  1
# SKIP:  0
# XFAIL: 0
# FAIL:  0
# XPASS: 0
# ERROR: 0
============================================================================
make[4]: Leaving directory '/home/james/src/bitcoin/src'
Running tests: multisig_tests from test/multisig_tests.cpp
Running tests: net_tests from test/net_tests.cpp
Running 9 test cases...
Entering test module "Bitcoin Core Test Suite"
test/net_tests.cpp(79): Entering test suite "net_tests"
test/net_tests.cpp(81): Entering test case "cnode_listen_port"
2019-09-27T18:03:51Z Bitcoin Core version v0.18.99.0-fa8e20aaca-dirty (debug build)
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements
test/net_tests.cpp(91): error: in "net_tests/cnode_listen_port": check false has failed
test/net_tests.cpp(81): Leaving test case "cnode_listen_port"; testing time: 36113us
test/net_tests.cpp(94): Entering test case "caddrdb_read"
2019-09-27T18:03:51Z Bitcoin Core version v0.18.99.0-fa8e20aaca-dirty (debug build)
2019-09-27T18:03:51Z Bitcoin Core version v0.18.99.0-fa8e20aaca-dirty (debug build)
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements
test/net_tests.cpp(94): Leaving test case "caddrdb_read"; testing time: 12342us
test/net_tests.cpp(139): Entering test case "caddrdb_read_corrupted"
2019-09-27T18:03:51Z Bitcoin Core version v0.18.99.0-fa8e20aaca-dirty (debug build)
2019-09-27T18:03:51Z Bitcoin Core version v0.18.99.0-fa8e20aaca-dirty (debug build)
2019-09-27T18:03:51Z Bitcoin Core version v0.18.99.0-fa8e20aaca-dirty (debug build)
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements
2019-09-27T18:03:51Z ERROR: DeserializeDB: Deserialize or I/O error - CDataStream::read(): end of data: iostream error
2019-09-27T18:03:51Z ERROR: DeserializeDB: Deserialize or I/O error - CDataStream::read(): end of data: iostream error
2019-09-27T18:03:51Z ERROR: DeserializeDB: Deserialize or I/O error - CDataStream::read(): end of data: iostream error
test/net_tests.cpp(139): Leaving test case "caddrdb_read_corrupted"; testing time: 7922us
test/net_tests.cpp(170): Entering test case "cnode_simple_test"
2019-09-27T18:03:51Z Bitcoin Core version v0.18.99.0-fa8e20aaca-dirty (debug build)
2019-09-27T18:03:51Z Bitcoin Core version v0.18.99.0-fa8e20aaca-dirty (debug build)
2019-09-27T18:03:51Z Bitcoin Core version v0.18.99.0-fa8e20aaca-dirty (debug build)
2019-09-27T18:03:51Z Bitcoin Core version v0.18.99.0-fa8e20aaca-dirty (debug build)
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements
test/net_tests.cpp(170): Leaving test case "cnode_simple_test"; testing time: 7579us
test/net_tests.cpp(195): Entering test case "ipv4_peer_with_ipv6_addrMe_test"
2019-09-27T18:03:51Z Bitcoin Core version v0.18.99.0-fa8e20aaca-dirty (debug build)
2019-09-27T18:03:51Z Bitcoin Core version v0.18.99.0-fa8e20aaca-dirty (debug build)
2019-09-27T18:03:51Z Bitcoin Core version v0.18.99.0-fa8e20aaca-dirty (debug build)
2019-09-27T18:03:51Z Bitcoin Core version v0.18.99.0-fa8e20aaca-dirty (debug build)
2019-09-27T18:03:51Z Bitcoin Core version v0.18.99.0-fa8e20aaca-dirty (debug build)
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements
test/net_tests.cpp(195): Leaving test case "ipv4_peer_with_ipv6_addrMe_test"; testing time: 6446us
test/net_tests.cpp(233): Entering test case "LimitedAndReachable_Network"
2019-09-27T18:03:51Z Bitcoin Core version v0.18.99.0-fa8e20aaca-dirty (debug build)
2019-09-27T18:03:51Z Bitcoin Core version v0.18.99.0-fa8e20aaca-dirty (debug build)
2019-09-27T18:03:51Z Bitcoin Core version v0.18.99.0-fa8e20aaca-dirty (debug build)
2019-09-27T18:03:51Z Bitcoin Core version v0.18.99.0-fa8e20aaca-dirty (debug build)
2019-09-27T18:03:51Z Bitcoin Core version v0.18.99.0-fa8e20aaca-dirty (debug build)
2019-09-27T18:03:51Z Bitcoin Core version v0.18.99.0-fa8e20aaca-dirty (debug build)
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements
test/net_tests.cpp(233): Leaving test case "LimitedAndReachable_Network"; testing time: 5801us
test/net_tests.cpp(256): Entering test case "LimitedAndReachable_NetworkCaseUnroutableAndInternal"
2019-09-27T18:03:51Z Bitcoin Core version v0.18.99.0-fa8e20aaca-dirty (debug build)
2019-09-27T18:03:51Z Bitcoin Core version v0.18.99.0-fa8e20aaca-dirty (debug build)
2019-09-27T18:03:51Z Bitcoin Core version v0.18.99.0-fa8e20aaca-dirty (debug build)
2019-09-27T18:03:51Z Bitcoin Core version v0.18.99.0-fa8e20aaca-dirty (debug build)
2019-09-27T18:03:51Z Bitcoin Core version v0.18.99.0-fa8e20aaca-dirty (debug build)
2019-09-27T18:03:51Z Bitcoin Core version v0.18.99.0-fa8e20aaca-dirty (debug build)
2019-09-27T18:03:51Z Bitcoin Core version v0.18.99.0-fa8e20aaca-dirty (debug build)
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements
test/net_tests.cpp(256): Leaving test case "LimitedAndReachable_NetworkCaseUnroutableAndInternal"; testing time: 5789us
test/net_tests.cpp(279): Entering test case "LimitedAndReachable_CNetAddr"
2019-09-27T18:03:51Z Bitcoin Core version v0.18.99.0-fa8e20aaca-dirty (debug build)
2019-09-27T18:03:51Z Bitcoin Core version v0.18.99.0-fa8e20aaca-dirty (debug build)
2019-09-27T18:03:51Z Bitcoin Core version v0.18.99.0-fa8e20aaca-dirty (debug build)
2019-09-27T18:03:51Z Bitcoin Core version v0.18.99.0-fa8e20aaca-dirty (debug build)
2019-09-27T18:03:51Z Bitcoin Core version v0.18.99.0-fa8e20aaca-dirty (debug build)
2019-09-27T18:03:51Z Bitcoin Core version v0.18.99.0-fa8e20aaca-dirty (debug build)
2019-09-27T18:03:51Z Bitcoin Core version v0.18.99.0-fa8e20aaca-dirty (debug build)
2019-09-27T18:03:51Z Bitcoin Core version v0.18.99.0-fa8e20aaca-dirty (debug build)
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements
test/net_tests.cpp(279): Leaving test case "LimitedAndReachable_CNetAddr"; testing time: 5767us
test/net_tests.cpp(293): Entering test case "LocalAddress_BasicLifecycle"
2019-09-27T18:03:51Z Bitcoin Core version v0.18.99.0-fa8e20aaca-dirty (debug build)
2019-09-27T18:03:51Z Bitcoin Core version v0.18.99.0-fa8e20aaca-dirty (debug build)
2019-09-27T18:03:51Z Bitcoin Core version v0.18.99.0-fa8e20aaca-dirty (debug build)
2019-09-27T18:03:51Z Bitcoin Core version v0.18.99.0-fa8e20aaca-dirty (debug build)
2019-09-27T18:03:51Z Bitcoin Core version v0.18.99.0-fa8e20aaca-dirty (debug build)
2019-09-27T18:03:51Z Bitcoin Core version v0.18.99.0-fa8e20aaca-dirty (debug build)
2019-09-27T18:03:51Z Bitcoin Core version v0.18.99.0-fa8e20aaca-dirty (debug build)
2019-09-27T18:03:51Z Bitcoin Core version v0.18.99.0-fa8e20aaca-dirty (debug build)
2019-09-27T18:03:51Z Bitcoin Core version v0.18.99.0-fa8e20aaca-dirty (debug build)
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements
2019-09-27T18:03:51Z Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements
2019-09-27T18:03:51Z AddLocal(2.1.1.1:1000,1000)
2019-09-27T18:03:51Z AddLocal(2.1.1.1:1000,1000)
2019-09-27T18:03:51Z AddLocal(2.1.1.1:1000,1000)
2019-09-27T18:03:51Z AddLocal(2.1.1.1:1000,1000)
2019-09-27T18:03:51Z AddLocal(2.1.1.1:1000,1000)
2019-09-27T18:03:51Z AddLocal(2.1.1.1:1000,1000)
2019-09-27T18:03:51Z AddLocal(2.1.1.1:1000,1000)
2019-09-27T18:03:51Z AddLocal(2.1.1.1:1000,1000)
2019-09-27T18:03:51Z AddLocal(2.1.1.1:1000,1000)
2019-09-27T18:03:51Z RemoveLocal(2.1.1.1:1000)
2019-09-27T18:03:51Z RemoveLocal(2.1.1.1:1000)
2019-09-27T18:03:51Z RemoveLocal(2.1.1.1:1000)
2019-09-27T18:03:51Z RemoveLocal(2.1.1.1:1000)
2019-09-27T18:03:51Z RemoveLocal(2.1.1.1:1000)
2019-09-27T18:03:51Z RemoveLocal(2.1.1.1:1000)
2019-09-27T18:03:51Z RemoveLocal(2.1.1.1:1000)
2019-09-27T18:03:51Z RemoveLocal(2.1.1.1:1000)
2019-09-27T18:03:51Z RemoveLocal(2.1.1.1:1000)
test/net_tests.cpp(293): Leaving test case "LocalAddress_BasicLifecycle"; testing time: 5885us
test/net_tests.cpp(79): Leaving test suite "net_tests"; testing time: 93768us
Leaving test module "Bitcoin Core Test Suite"; testing time: 93846us

*** 1 failure is detected in the test module "Bitcoin Core Test Suite"
Makefile:13822: recipe for target 'test/net_tests.cpp.test' failed
make[3]: *** [test/net_tests.cpp.test] Error 1
make[3]: *** Waiting for unfinished jobs....
make[3]: Leaving directory '/home/james/src/bitcoin/src'
Makefile:13560: recipe for target 'check-am' failed
make[2]: *** [check-am] Error 2
make[2]: Leaving directory '/home/james/src/bitcoin/src'
Makefile:13248: recipe for target 'check-recursive' failed
make[1]: *** [check-recursive] Error 1
make[1]: Leaving directory '/home/james/src/bitcoin/src'
Makefile:775: recipe for target 'check-recursive' failed
make: *** [check-recursive] Error 1

@maflcko
Copy link
Member Author

maflcko commented Sep 27, 2019

Whoops. Fixing ...

@maflcko maflcko force-pushed the 1909-testPrintLogOnFail branch 2 times, most recently from faaa2d3 to fa006d8 Compare September 27, 2019 19:05
@maflcko
Copy link
Member Author

maflcko commented Sep 27, 2019

Fixed

src/logging.h Outdated
@@ -77,6 +77,9 @@ namespace BCLog {

std::string LogTimestampStr(const std::string& str);

/** Slots that connect to the print signal */
std::list<std::function<void(const std::string&)>> m_print_callbacks /* GUARDED_BY(m_cs) */ {};
Copy link
Contributor

Choose a reason for hiding this comment

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

Why comment the lock annotation?

Copy link
Member Author

Choose a reason for hiding this comment

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

It can't compile otherwise. If you include sync.h, the tests won't run after compilation.

src/logging.h Outdated
}

/** Delete a connection */
void DeleteCallback(std::list<std::function<void(const std::string&)>>::iterator it)
Copy link
Contributor

Choose a reason for hiding this comment

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

Unused?

Copy link
Member Author

Choose a reason for hiding this comment

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

Used in #16540

@maflcko maflcko force-pushed the 1909-testPrintLogOnFail branch 2 times, most recently from 64fac9a to fa39655 Compare September 27, 2019 22:20
@practicalswift
Copy link
Contributor

Concept ACK

@promag
Copy link
Contributor

promag commented Sep 28, 2019

Concept ACK.

@mzumsande
Copy link
Contributor

Concept ACK.
There is a data race warning in the Travis TSan build for txindex_tests, which I could reproduce.

@DrahtBot
Copy link
Contributor

DrahtBot commented Oct 3, 2019

The following sections might be updated with supplementary metadata relevant to reviewers and maintainers.

Conflicts

No conflicts as of last run.

@maflcko maflcko force-pushed the 1909-testPrintLogOnFail branch 2 times, most recently from fa116ab to faa5a01 Compare October 7, 2019 19:40
@maflcko
Copy link
Member Author

maflcko commented Oct 7, 2019

Ah, forgot to push one more tsan suppression. Fixed.

Though, longer term I'd like to do #8670 (comment)

@adamjonas
Copy link
Member

utACK faa5a01. Tried a few different scenarios and noted that logging is provided for multiple failed test cases in a file before exiting.

For example:

test/arith_uint256_tests.cpp:345: Entering test case "divide"
2019-10-22T19:44:29Z Bitcoin Core version v0.18.99.0-faa5a01d5-dirty (release build)
2019-10-22T19:44:29Z Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements
2019-10-22T19:44:29Z Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements
test/arith_uint256_tests.cpp:353: error: in "arith_uint256_tests/divide": check MaxL / R1L == 3 has failed
test/arith_uint256_tests.cpp:345: Leaving test case "divide"; testing time: 2732us
...
test/arith_uint256_tests.cpp:404: Entering test case "bignum_SetCompact"
2019-10-22T19:44:29Z Bitcoin Core version v0.18.99.0-faa5a01d5-dirty (release build)
2019-10-22T19:44:29Z Using 16 MiB out of 32/2 requested for signature cache, able to store 524288 elements
2019-10-22T19:44:29Z Using 16 MiB out of 32/2 requested for script execution cache, able to store 524288 elements
test/arith_uint256_tests.cpp:430: error: in "arith_uint256_tests/bignum_SetCompact": check fNegative == true has failed [false != true]
test/arith_uint256_tests.cpp:404: Leaving test case "bignum_SetCompact"; testing time: 2225us

@maflcko
Copy link
Member Author

maflcko commented Oct 24, 2019

Rebased for minor merge conflict

@fjahr
Copy link
Contributor

fjahr commented Oct 28, 2019

Concept ACK

If there are multiple test cases in a single test file and one of them fails currently the logs of all the test cases are printed, also the succeeding ones. Could that be improved? It could be especially annoying if there are a lot of logs for every test case and the developer would have to search for the failing one (I discovered this on merkle_tests.cpp where logs were short, not sure which unit test has the most logs).

@maflcko
Copy link
Member Author

maflcko commented Oct 30, 2019

@fjahr I don't think I can solve that without having a way to detect (inside the TestingSetup, e.g. the destructor) whether a test case failed

Also, I think having too much logs is better than having no logs to debug at all.

@maflcko maflcko force-pushed the 1909-testPrintLogOnFail branch from fa031ab to fa9ab18 Compare November 5, 2019 19:39
@laanwj
Copy link
Member

laanwj commented Nov 6, 2019

Concept ACK.

Also, I think having too much logs is better than having no logs to debug at all.

Usually true, though having too much (unrelated) logging can also distract. And CI web interfaces make the experience of browsing large files quite horrible. Also, too much logging can slow down the tests.

But I don't think that's the case with this change.

@maflcko maflcko force-pushed the 1909-testPrintLogOnFail branch 2 times, most recently from fa55a17 to fab72a3 Compare November 7, 2019 15:31
@maflcko
Copy link
Member Author

maflcko commented Nov 7, 2019

Usually true, though having too much (unrelated) logging can also distract. And CI web interfaces make the experience of browsing large files quite horrible. Also, too much logging can slow down the tests.
But I don't think that's the case with this change.

Agree on the distraction part, but if you set the log level to "debug" or "test_suite" I think a verbose log should be expected.

Note that this is not printed to the ci log unless the test fails.

Also note that the tests already log to the debug.log, so logging to the test log shouldn't slow them down.

See the comparison:

$ /usr/bin/time ./src/test/test_bitcoin-fab72a301a86373d7d7a8d05a300391687048ec8
Running 381 test cases...

*** No errors detected
42.97user 9.04system 0:41.84elapsed 124%CPU (0avgtext+0avgdata 250648maxresident)k

$ /usr/bin/time ./src/test/test_bitcoin-master
Running 381 test cases...

*** No errors detected
44.08user 8.72system 0:42.28elapsed 124%CPU (0avgtext+0avgdata 250176maxresident)k

So it might or might not be slower, but I don't think there is any significant difference

@maflcko maflcko force-pushed the 1909-testPrintLogOnFail branch from fab72a3 to fad5fe2 Compare November 7, 2019 17:30
Copy link
Contributor

@promag promag left a comment

Choose a reason for hiding this comment

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

ACK fad5fe2.

@maflcko
Copy link
Member Author

maflcko commented Dec 20, 2019

Anything left to do here?

@practicalswift
Copy link
Contributor

ACK fad5fe2 -- diff looks correct

@maflcko maflcko force-pushed the 1909-testPrintLogOnFail branch from fad5fe2 to fa37e0a Compare January 2, 2020 23:19
@maflcko
Copy link
Member Author

maflcko commented Jan 2, 2020

Rebased to fix trivial merge conflict

@jamesob
Copy link
Contributor

jamesob commented Jan 3, 2020

Would-be ACK fa37e0a but it looks like I've hit a deadlock.

Modified the coins test for failure:

diff --git a/src/test/coins_tests.cpp b/src/test/coins_tests.cpp
index 436c1bffa0..2c20efc12b 100644
--- a/src/test/coins_tests.cpp
+++ b/src/test/coins_tests.cpp
@@ -213,6 +213,7 @@ BOOST_AUTO_TEST_CASE(coins_cache_simulation_test)
                 unsigned int flushIndex = InsecureRandRange(stack.size() - 1);
                 BOOST_CHECK(stack[flushIndex]->Flush());
             }
+            assert(false);
         }
         if (InsecureRandRange(100) == 0) {
             // Every 100 iterations, change the cache stack.

and ran with make -j 4 check.

Noticed the test seemed to be hanging, so straced:

$ ps aux | grep test
...
james    20079  0.0  0.0  19992  3180 pts/15   S+   11:38   0:00 /bin/bash -c test/test_bitcoin -l test_suite -t "`cat test/coins_tests.cpp | grep -E "(BOOST_FIXTURE_TEST_SUITE\\(|BOOST_AUTO_TEST_SUITE\\()" | cut -d '(' -f 2 | cut -d ',' -f 1 | cut -d ')' -f 1`" > test/coins_tests.cpp.log 2>&1 || (cat test/coins_tests.cpp.log && false)
...

$ sudo strace -p 20079

strace: Process 20079 attached
wait4(-1,

@maflcko
Copy link
Member Author

maflcko commented Jan 3, 2020

@jamesob I think you can't use assert in the boost test framework, see #16700. I'd guess this issue also happens on master

@jamesob
Copy link
Contributor

jamesob commented Jan 4, 2020

ACK fa37e0a (jamesob/ackr/16975.1.MarcoFalke.test_show_debug_log_on_u)

Confirmed that assert(false); behavior deadlocks on master too.

Show signature data

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA512

ACK fa37e0a68bea65979f9f8f2e5258fe608acf2bdf ([`jamesob/ackr/16975.1.MarcoFalke.test_show_debug_log_on_u`](https://github.com/jamesob/bitcoin/tree/ackr/16975.1.MarcoFalke.test_show_debug_log_on_u))

Confirmed that `assert(false);` behavior deadlocks on master too.
-----BEGIN PGP SIGNATURE-----

iQIzBAEBCgAdFiEEpm2+LMqPsWj2rAwWyrywS1A+5mgFAl4QsLcACgkQyrywS1A+
5mhfUQ//f7fDaV29XKZ6Ww7Cb1NWzLedvSbkpYmE/6EgGhT2/HHQyCLWg6z+xbmI
273lVXdjIUKShuoSk97SjfAJAkyAk9bcehrVTvbSSixh5uVrdSKe6OENIoIoOWRO
wUWDIu7uR3zBcrdHkVIF+RxbTybtKhzZ6pPPpB6lMUZD/YFzrCZjG7NrwNWMxJ5i
ikDQfL5Jx80lc6BkvfEjtYVWJIazDvEty7UWqzlex3wtKS5QfA0a02KZ2H+v0D9V
9bfnl7WDDXqmVJdgkD0x9jsc2twcsPbw8CmQLV+/josYpgD9r9LM0uGE9l9rz2W2
2Ik6zQ2aSJZiOjJa1pmR9472LuS48folnyVYvvoVkhBiokgK2N5mLxFNAvIm8snf
Bx2p9xj4ts88loBwbKu1k00x/9wRgUk+Thd1va/32FJ1DcWN+JPbkxJwJp85D2Hc
3zD5CgxZYYIhddXu7qvwIi3xPMXeQZrYImtASeOOsHklVvkjhkAt136Gt1ZGjnzB
CeR9Kb1/mcfIooGuUIeO0PDNWQsWjG4JU+0UBVSOB/bSqx4ioKLLz3NvjT0NwIde
yONvxlJRGUjbaUZ5elEMGI0RRX/Ncw9b/jQglZWuqj6iJN+3bja+BnZoCwbwoh5/
dwajH3AZOTos5QR+kjY58WstyjNT98jx9Hm83BcqYXkqBgOnUEk=
=jrpf
-----END PGP SIGNATURE-----

laanwj added a commit that referenced this pull request Jan 8, 2020
fa37e0a test: Show debug log on unit test failure (MarcoFalke)

Pull request description:

  Often, it is hard to debug unit test failures without the debug log. Especially when the failure happens remotely (e.g. on a ci system).

  Fix that by printing the log on failure.

ACKs for top commit:
  jamesob:
    ACK fa37e0a ([`jamesob/ackr/16975.1.MarcoFalke.test_show_debug_log_on_u`](https://github.com/jamesob/bitcoin/tree/ackr/16975.1.MarcoFalke.test_show_debug_log_on_u))

Tree-SHA512: 2ca4150c4ae3d4ad47e03b5e5e70da2baffec928ddef1fdf53a3ebc061f14aee249205387cb1b12ef6d4eb55711ef0080c0b41d9d18000b5da124ca80299793b
@laanwj laanwj merged commit fa37e0a into bitcoin:master Jan 8, 2020
sidhujag pushed a commit to syscoin/syscoin that referenced this pull request Jan 8, 2020
fa37e0a test: Show debug log on unit test failure (MarcoFalke)

Pull request description:

  Often, it is hard to debug unit test failures without the debug log. Especially when the failure happens remotely (e.g. on a ci system).

  Fix that by printing the log on failure.

ACKs for top commit:
  jamesob:
    ACK fa37e0a ([`jamesob/ackr/16975.1.MarcoFalke.test_show_debug_log_on_u`](https://github.com/jamesob/bitcoin/tree/ackr/16975.1.MarcoFalke.test_show_debug_log_on_u))

Tree-SHA512: 2ca4150c4ae3d4ad47e03b5e5e70da2baffec928ddef1fdf53a3ebc061f14aee249205387cb1b12ef6d4eb55711ef0080c0b41d9d18000b5da124ca80299793b
@maflcko maflcko deleted the 1909-testPrintLogOnFail branch March 30, 2020 16:31
maflcko pushed a commit to maflcko/bitcoin-core that referenced this pull request Apr 1, 2020
7777703 doc: Explain new test logging (MarcoFalke)

Pull request description:

  Explain logging added in bitcoin#18472 and bitcoin#16975

ACKs for top commit:
  jonatack:
    ACK 7777703

Tree-SHA512: 3a0aa7bab32a6753d8894d29cf82604b044b23e512102dd275b717eefda3c2212dbf43ea7e9155267350dd9f3bc5badba2eb660152db3efeab30a04f52126c95
sidhujag pushed a commit to syscoin-core/syscoin that referenced this pull request Nov 10, 2020
fa37e0a test: Show debug log on unit test failure (MarcoFalke)

Pull request description:

  Often, it is hard to debug unit test failures without the debug log. Especially when the failure happens remotely (e.g. on a ci system).

  Fix that by printing the log on failure.

ACKs for top commit:
  jamesob:
    ACK fa37e0a ([`jamesob/ackr/16975.1.MarcoFalke.test_show_debug_log_on_u`](https://github.com/jamesob/bitcoin/tree/ackr/16975.1.MarcoFalke.test_show_debug_log_on_u))

Tree-SHA512: 2ca4150c4ae3d4ad47e03b5e5e70da2baffec928ddef1fdf53a3ebc061f14aee249205387cb1b12ef6d4eb55711ef0080c0b41d9d18000b5da124ca80299793b
Fabcien pushed a commit to Bitcoin-ABC/bitcoin-abc that referenced this pull request Aug 31, 2021
Summary: This is a backport of [[bitcoin/bitcoin#16975 | core#16975]]

Test Plan: `ninja check`

Reviewers: #bitcoin_abc, majcosta

Reviewed By: #bitcoin_abc, majcosta

Subscribers: majcosta

Differential Revision: https://reviews.bitcoinabc.org/D9971
@bitcoin bitcoin locked as resolved and limited conversation to collaborators Feb 15, 2022
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
Projects
None yet
Development

Successfully merging this pull request may close these issues.

10 participants