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
Lint
Automatic diff as part of commit; lint not applicable.
Unit
Automatic diff as part of commit; unit tests not applicable.

Event Timeline

jasonbcox created this revision.May 12 2020, 01:06
Herald added a reviewer: Restricted Project. · View Herald TranscriptMay 12 2020, 01:06
jasonbcox requested review of this revision.May 12 2020, 01:06

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...

jasonbcox updated this revision to Diff 19952.May 12 2020, 18:11

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
jasonbcox updated this revision to Diff 20020.May 13 2020, 20:27

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.

jasonbcox edited the test plan for this revision. (Show Details)May 13 2020, 20:28
Fabien accepted this revision.May 13 2020, 20:34
This revision is now accepted and ready to land.May 13 2020, 20:34