Page MenuHomePhabricator

[tests] Give a useful error message when assert_debug_log is called with empty expected messages
ClosedPublic

Authored by jasonbcox on May 12 2020, 01:06.

Details

Summary

If given empty expected_msgs, assert_debug_log will return quickly without actually checking
much. This is dangerous if unexpected_msgs IS set, as the test will appear to pass when it hasn't.

The alternative is to reimplement this function so that it will wait for unexpected messages
when no expected messages are set, but running out the timeout does not seem like robust way to
do this. It's better to give assert_debug_log a "target" to hit and then check to make sure
we don't hit any explicit "non-targets" along the way.

Test Plan
ninja check-functional
sed -i 's/expected_msgs=\["added time data"\]/expected_msgs=[]/g' abc-version-message.py
test_runner.py abc-version-message    # should fail with the new message

Diff Detail

Repository
rABC Bitcoin ABC
Branch
empty-debug-log-expected
Lint
Lint Passed
Unit
No Test Coverage
Build Status
Buildable 10716
Build 19225: Default Diff Build & Tests
Build 19224: arc lint + arc unit

Event Timeline

Snippet of first build failure:

[01:13:48]i:		 [Bitcoin_ABC_unit_tests_with_next_upgrade_activated] util_tests.gettime
[01:13:48]i:		 [Bitcoin_ABC_unit_tests_with_next_upgrade_activated] util_tests.util_time_GetTime
[01:13:48]i:		 [Bitcoin_ABC_unit_tests_with_next_upgrade_activated] util_tests.test_IsDigit
[01:13:48]i:		 [Bitcoin_ABC_unit_tests_with_next_upgrade_activated] util_tests.test_ParseInt32
[01:13:48]i:		 [Bitcoin_ABC_unit_tests_with_next_upgrade_activated] util_tests.test_ParseInt64
[01:13:48]i:		 [Bitcoin_ABC_unit_tests_with_next_upgrade_activated] util_tests.test_ParseUInt32
[01:13:48]i:		 [Bitcoin_ABC_unit_tests_with_next_upgrade_activated] util_tests.test_ParseUInt64
[01:13:48]i:		 [Bitcoin_ABC_unit_tests_with_next_upgrade_activated] util_tests.test_ParseDouble
[01:13:48]i:		 [Bitcoin_ABC_unit_tests_with_next_upgrade_activated] util_tests.test_FormatParagraph
[01:13:48]i:		 [Bitcoin_ABC_unit_tests_with_next_upgrade_activated] util_tests.test_FormatSubVersion
[01:13:48]i:		 [Bitcoin_ABC_unit_tests_with_next_upgrade_activated] util_tests.test_ParseFixedPoint
[01:13:48]i:		 [Bitcoin_ABC_unit_tests_with_next_upgrade_activated] util_tests.test_LockDirectory
[01:13:48]i:		 [Bitcoin_ABC_unit_tests_with_next_upgrade_activated] util_tests.test_DirIsWritable
[01:13:48]i:		 [Bitcoin_ABC_unit_tests_with_next_upgrade_activated] util_tests.test_ConvertBits
[01:13:48]i:		 [Bitcoin_ABC_unit_tests_with_next_upgrade_activated] util_tests.test_ToLower
[01:13:48]i:		 [Bitcoin_ABC_unit_tests_with_next_upgrade_activated] util_tests.test_ToUpper
[01:13:48]i:		 [Bitcoin_ABC_unit_tests_with_next_upgrade_activated] util_tests.test_Capitalize
[01:13:48]i:		 [Bitcoin_ABC_unit_tests_with_next_upgrade_activated] util_threadnames_tests.util_threadnames_test_rename_threaded
[01:13:48]i:		 [Bitcoin_ABC_unit_tests_with_next_upgrade_activated] validation_block_tests.processnewblock_signals_ordering
[01:13:48]i:		 [Bitcoin_ABC_unit_tests_with_next_upgrade_activated] validation_tests.block_subsidy_test
[01:13:48]i:		 [Bitcoin_ABC_unit_tests_with_next_upgrade_activated] validation_tests.subsidy_limit_test
[01:13:48]i:		 [Bitcoin_ABC_unit_tests_with_next_upgrade_activated] validation_tests.validation_load_external_block_file
[01:13:48]i:		 [Bitcoin_ABC_unit_tests_with_next_upgrade_activated] versionbits_tests.versionbits_test
[01:13:48]i:		 [Bitcoin_ABC_unit_tests_with_next_upgrade_activated] versionbits_tests.versionbits_computeblockversion
[01:13:48]i:		 [Bitcoin_ABC_unit_tests_with_next_upgrade_activated] work_comparator_tests.work_comparator
[01:13:48]i:		 [Bitcoin_ABC_unit_tests_with_next_upgrade_activated] server_tests.server_IsDeprecatedRPCEnabled
[01:13:48]i:		 [Bitcoin_ABC_unit_tests_with_next_upgrade_activated] db_tests.getwalletenv_file
[01:13:48]i:		 [Bitcoin_ABC_unit_tests_with_next_upgrade_activated] db_tests.getwalletenv_directory
[01:13:48]i:		 [Bitcoin_ABC_unit_tests_with_next_upgrade_activated] db_tests.getwalletenv_g_dbenvs_multiple
[01:13:48]i:		 [Bitcoin_ABC_unit_tests_with_next_upgrade_activated] db_tests.getwalletenv_g_dbenvs_free_instance
[01:13:48]i:		 [Bitcoin_ABC_unit_tests_with_next_upgrade_activated] coinselector_tests.bnb_search_test
[01:13:48]i:		 [Bitcoin_ABC_unit_tests_with_next_upgrade_activated] coinselector_tests.knapsack_solver_test
[01:13:48]i:		 [Bitcoin_ABC_unit_tests_with_next_upgrade_activated] coinselector_tests.ApproximateBestSubset
[01:13:48]i:		 [Bitcoin_ABC_unit_tests_with_next_upgrade_activated] coinselector_tests.SelectCoins_test
[01:13:48]i:		 [Bitcoin_ABC_unit_tests_with_next_upgrade_activated] init_tests.walletinit_verify_walletdir_default
[01:13:48]i:		 [Bitcoin_ABC_unit_tests_with_next_upgrade_activated] init_tests.walletinit_verify_walletdir_custom
[01:13:48]i:		 [Bitcoin_ABC_unit_tests_with_next_upgrade_activated] init_tests.walletinit_verify_walletdir_does_not_exist
[01:13:48]i:		 [Bitcoin_ABC_unit_tests_with_next_upgrade_activated] init_tests.walletinit_verify_walletdir_is_not_directory
[01:13:48]i:		 [Bitcoin_ABC_unit_tests_with_next_upgrade_activated] init_tests.walletinit_verify_walletdir_is_not_relative
[01:13:48]i:		 [Bitcoin_ABC_unit_tests_with_next_upgrade_activated] init_tests.walletinit_verify_walletdir_no_trailing
[01:13:48]i:		 [Bitcoin_ABC_unit_tests_with_next_upgrade_activated] init_tests.walletinit_verify_walletdir_no_trailing2
[01:13:48]i:		 [Bitcoin_ABC_unit_tests_with_next_upgrade_activated] psbt_wallet_tests.psbt_updater_test
[01:13:48]i:		 [Bitcoin_ABC_unit_tests_with_next_upgrade_activated] psbt_wallet_tests.parse_hd_keypath
[01:13:48]i:		 [Bitcoin_ABC_unit_tests_with_next_upgrade_activated] wallet_tests.scan_for_wallet_transactions
[01:13:48]i:		 [Bitcoin_ABC_unit_tests_with_next_upgrade_activated] wallet_tests.importmulti_rescan
[01:13:48]i:		 [Bitcoin_ABC_unit_tests_with_next_upgrade_activated] wallet_tests.importwallet_rescan
[01:13:48]i:		 [Bitcoin_ABC_unit_tests_with_next_upgrade_activated] wallet_tests.coin_mark_dirty_immature_credit
[01:13:48]i:		 [Bitcoin_ABC_unit_tests_with_next_upgrade_activated] wallet_tests.ComputeTimeSmart
[01:13:48]i:		 [Bitcoin_ABC_unit_tests_with_next_upgrade_activated] wallet_tests.LoadReceiveRequests
[01:13:48]i:		 [Bitcoin_ABC_unit_tests_with_next_upgrade_activated] wallet_tests.ListCoins
[01:13:48]i:		 [Bitcoin_ABC_unit_tests_with_next_upgrade_activated] wallet_tests.wallet_disableprivkeys
[01:13:48]i:		 [Bitcoin_ABC_unit_tests_with_next_upgrade_activated] walletdb_tests.write_erase_name
[01:13:48]i:		 [Bitcoin_ABC_unit_tests_with_next_upgrade_activated] walletdb_tests.write_erase_purpose
[01:13:48]i:		 [Bitcoin_ABC_unit_tests_with_next_upgrade_activated] walletdb_tests.write_erase_destdata
[01:13:48]i:		 [Bitcoin_ABC_unit_tests_with_next_upgrade_activated] walletdb_tests.no_dest_fails
[01:13:48]i:		 [Bitcoin_ABC_unit_tests_with_next_upgrade_activated] wallet_crypto_tests.passphrase
[01:13:48]i:		 [Bitcoin_ABC_unit_tests_with_next_upgrade_activated] wallet_crypto_tests.encrypt
[01:13:48]i:		 [Bitcoin_ABC_unit_tests_with_next_upgrade_activated] wallet_crypto_tests.decrypt
[01:13:53]W:	 [Step 1/2] Process exited with code 1
[01:13:53]E:	 [Step 1/2] Process exited with code 1 (Step: Command Line)

Each failure log is accessible here:
Bitcoin ABC functional tests: abc-block-sigchecks-activation.py
Bitcoin ABC functional tests: abc-invalid-chains.py
Bitcoin ABC functional tests: abc-mempool-accept-txn.py
Bitcoin ABC functional tests: abc-mempool-coherence-on-activations.py
Bitcoin ABC functional tests: abc-minimaldata.py
Bitcoin ABC functional tests: abc-op-reversebytes-activation.py
Bitcoin ABC functional tests: abc-p2p-fullblocktest-sigops.py
Bitcoin ABC functional tests: abc-phonon-mempoolpolicy.py
Bitcoin ABC functional tests: abc-replay-protection.py
Bitcoin ABC functional tests: abc-schnorr.py
Bitcoin ABC functional tests: abc-schnorrmultisig.py
Bitcoin ABC functional tests: abc-segwit-recovery.py
Bitcoin ABC functional tests: abc-sigchecks-inputstandardness-activation.py
Bitcoin ABC functional tests: abc-sigops-deactivation.py
Bitcoin ABC functional tests: abc-sigops-mempool-mining.py
Bitcoin ABC functional tests: abc-transaction-ordering.py
Bitcoin ABC functional tests: feature_block_sigops.py
Bitcoin ABC functional tests: feature_csv_activation.py
Bitcoin ABC functional tests: mining_basic.py
Bitcoin ABC functional tests: p2p_invalid_block.py
Bitcoin ABC functional tests: p2p_invalid_tx.py

Fabien requested changes to this revision.May 12 2020, 12:11
Fabien added a subscriber: Fabien.

This is causing a large number of tests to fail

This revision now requires changes to proceed.May 12 2020, 12:11

This is causing a large number of tests to fail

I didn't look hard enough for all of the assert_debug_log usages...

Fixed two assert_debug_log usages that "depend" on the old behavior, but don't need to.

Fabien requested changes to this revision.May 13 2020, 08:24

I don't think the logic is correct here. This function intended to check for expected and/or unexpected messages in the log, and after this change it cannot check for unexpected messages only without using a hacky expected message that hopefully won't appear in the log.
The previous behavior was wrong in this regard, but the new one is also wrong.

This revision now requires changes to proceed.May 13 2020, 08:24

Discussed offline with Fabiento clarify why I believe this API is the correct one. I've distilled our conversation
into a comment for future reference.

This revision is now accepted and ready to land.May 13 2020, 20:34