From 4bcf761f3519f418da8ffeee24d0afb18c1d493c Mon Sep 17 00:00:00 2001 From: Jussi Kukkonen Date: Tue, 15 Sep 2020 10:52:02 +0300 Subject: [PATCH 1/6] Download: Do not log unnecessary errors A mismatched length will lead to DownloadLengthMismatchError that will be handled by user. There is no need to log Errors or Criticals on the way. Signed-off-by: Jussi Kukkonen --- tuf/download.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/tuf/download.py b/tuf/download.py index 7065fe1c03..f75e7cdf17 100755 --- a/tuf/download.py +++ b/tuf/download.py @@ -278,7 +278,7 @@ def _download_file(url, required_length, STRICT_REQUIRED_LENGTH=True): except Exception: # Close 'temp_file'. Any written data is lost. temp_file.close() - logger.exception('Could not download URL: ' + repr(url)) + logger.debug('Could not download URL: ' + repr(url)) raise else: @@ -450,7 +450,7 @@ def _check_downloaded_length(total_downloaded, required_length, # What we downloaded is not equal to the required length, but did we ask # for strict checking of required length? if STRICT_REQUIRED_LENGTH: - logger.error('Downloaded ' + str(total_downloaded) + ' bytes, but' + logger.info('Downloaded ' + str(total_downloaded) + ' bytes, but' ' expected ' + str(required_length) + ' bytes. There is a difference' ' of ' + str(difference_in_bytes) + ' bytes.') From 69a45946e61478df2fadea158671924e3633803a Mon Sep 17 00:00:00 2001 From: Jussi Kukkonen Date: Tue, 15 Sep 2020 11:07:40 +0300 Subject: [PATCH 2/6] Updater: Don't log errors that will be raised Don't use log level ERROR when we are only raising an exception for user to handle (the issue is not a bug in TUF: TUF is working as expected in all of these cases). Don't log at all if all the info is included in the raised exception. Also definitely don't log at error level when we don't know if this will even be raised (e.g. a 404 is expected at least once on every Updater.refresh()). Signed-off-by: Jussi Kukkonen --- tuf/client/updater.py | 27 +++++++++++---------------- 1 file changed, 11 insertions(+), 16 deletions(-) diff --git a/tuf/client/updater.py b/tuf/client/updater.py index 564e285efd..a595a62953 100755 --- a/tuf/client/updater.py +++ b/tuf/client/updater.py @@ -960,8 +960,8 @@ def _import_delegations(self, parent_role): pass except (securesystemslib.exceptions.FormatError, securesystemslib.exceptions.Error): - logger.exception('Invalid key for keyid: ' + repr(keyid) + '.') - logger.error('Aborting role delegation for parent role ' + parent_role + '.') + logger.warning('Invalid key: ' + repr(keyid) + '. Aborting role ' + + 'delegation for parent role \'' + parent_role + '\'.') raise else: @@ -981,7 +981,7 @@ def _import_delegations(self, parent_role): logger.warning('Role already exists: ' + rolename) except Exception: - logger.exception('Failed to add delegated role: ' + repr(rolename) + '.') + logger.warning('Failed to add delegated role: ' + repr(rolename) + '.') raise @@ -1142,12 +1142,10 @@ def neither_403_nor_404(mirror_error): # Otherwise, reraise the error, because it is not a simple HTTP # error. if neither_403_nor_404(mirror_error): - logger.exception('Misc error for root version '+str(next_version)) + logger.info('Misc error for root version ' + str(next_version)) raise else: - # Calling this function should give us a detailed stack trace - # including an HTTP error code, if any. - logger.exception('HTTP error for root version '+str(next_version)) + logger.debug('HTTP error for root version ' + str(next_version)) # If we are here, then we ran into only 403 / 404 errors, which are # good reasons to suspect that the next root metadata file does not # exist. @@ -1635,7 +1633,7 @@ def _get_metadata_file(self, metadata_role, remote_filename, except Exception as exception: # Remember the error from this mirror, and "reset" the target file. - logger.exception('Update failed from ' + file_mirror + '.') + logger.debug('Update failed from ' + file_mirror + '.') file_mirror_errors[file_mirror] = exception file_object = None @@ -1646,7 +1644,7 @@ def _get_metadata_file(self, metadata_role, remote_filename, return file_object else: - logger.error('Failed to update ' + repr(remote_filename) + ' from all' + logger.debug('Failed to update ' + repr(remote_filename) + ' from all' ' mirrors: ' + repr(file_mirror_errors)) raise tuf.exceptions.NoWorkingMirrorError(file_mirror_errors) @@ -1725,7 +1723,7 @@ def _get_file(self, filepath, verify_file_function, file_type, file_length, except Exception as exception: # Remember the error from this mirror, and "reset" the target file. - logger.exception('Update failed from ' + file_mirror + '.') + logger.debug('Update failed from ' + file_mirror + '.') file_mirror_errors[file_mirror] = exception file_object = None @@ -1736,7 +1734,7 @@ def _get_file(self, filepath, verify_file_function, file_type, file_length, return file_object else: - logger.error('Failed to update ' + repr(filepath) + ' from' + logger.debug('Failed to update ' + repr(filepath) + ' from' ' all mirrors: ' + repr(file_mirror_errors)) raise tuf.exceptions.NoWorkingMirrorError(file_mirror_errors) @@ -1988,7 +1986,7 @@ def _update_metadata_if_changed(self, metadata_role, # need to, but we need to check the trust implications of the current # implementation. self._delete_metadata(metadata_role) - logger.error('Metadata for ' + repr(metadata_role) + ' cannot' + logger.warning('Metadata for ' + repr(metadata_role) + ' cannot' ' be updated.') raise @@ -2404,8 +2402,6 @@ def _ensure_not_expired(self, metadata_object, metadata_rolename): if expires_timestamp < current_time: message = 'Metadata '+repr(metadata_rolename)+' expired on ' + \ expires_datetime.ctime() + ' (UTC).' - logger.error(message) - raise tuf.exceptions.ExpiredMetadataError(message) @@ -2755,7 +2751,6 @@ def get_one_valid_targetinfo(self, target_filepath): # Raise an exception if the target information could not be retrieved. if target is None: - logger.error(repr(target_filepath) + ' not found.') raise tuf.exceptions.UnknownTargetError(repr(target_filepath) + ' not' ' found.') @@ -3111,7 +3106,7 @@ def remove_obsolete_targets(self, destination_directory): ' removed.') else: - logger.error(str(e)) + logger.warning('Failed to remove obsolete target: ' + str(e) ) else: logger.debug('Skipping: ' + repr(target) + '. It is still' From aad3bd49eb54877eb640f9cfe43a4676a68f0645 Mon Sep 17 00:00:00 2001 From: Jussi Kukkonen Date: Tue, 15 Sep 2020 14:06:08 +0300 Subject: [PATCH 3/6] tests: remove test_init and test_exceptions All of these tests create an exception and log it. They do not actually test anything. The alternative would be to change the log level to something that is not error to prevent verbose error output on successful test runs -- but that still wouldn't make them actual tests. Signed-off-by: Jussi Kukkonen --- tests/test_exceptions.py | 59 ------------------------------- tests/test_init.py | 75 ---------------------------------------- 2 files changed, 134 deletions(-) delete mode 100755 tests/test_exceptions.py delete mode 100755 tests/test_init.py diff --git a/tests/test_exceptions.py b/tests/test_exceptions.py deleted file mode 100755 index d3e54afb25..0000000000 --- a/tests/test_exceptions.py +++ /dev/null @@ -1,59 +0,0 @@ -#!/usr/bin/env python - -# Copyright 2014 - 2017, New York University and the TUF contributors -# SPDX-License-Identifier: MIT OR Apache-2.0 - -""" - - test_exceptions.py - - - Vladimir Diaz - - - July 13, 2017. - - - See LICENSE-MIT OR LICENSE for licensing information. - - - Test cases for exceptions.py (mainly the exceptions defined there). -""" - -# Help with Python 3 compatibility, where the print statement is a function, an -# implicit relative import is invalid, and the '/' operator performs true -# division. Example: print 'hello world' raises a 'SyntaxError' exception. -from __future__ import print_function -from __future__ import absolute_import -from __future__ import division -from __future__ import unicode_literals - -import unittest -import logging - -import tuf.exceptions - -logger = logging.getLogger(__name__) - -class TestExceptions(unittest.TestCase): - def setUp(self): - pass - - - def tearDown(self): - pass - - - def test_bad_signature_error(self): - bad_signature_error = tuf.exceptions.BadSignatureError('bad sig') - logger.error(bad_signature_error) - - - def test_bad_hash_error(self): - bad_hash_error = tuf.exceptions.BadHashError('1234', '5678') - logger.error(bad_hash_error) - - -# Run the unit tests. -if __name__ == '__main__': - unittest.main() diff --git a/tests/test_init.py b/tests/test_init.py deleted file mode 100755 index 03dfc65bdb..0000000000 --- a/tests/test_init.py +++ /dev/null @@ -1,75 +0,0 @@ -#!/usr/bin/env python - -# Copyright 2015 - 2017, New York University and the TUF contributors -# SPDX-License-Identifier: MIT OR Apache-2.0 - -""" - - test_init.py - - - Vladimir Diaz - - - March 30, 2015. - - - See LICENSE-MIT OR LICENSE for licensing information. - - - Test cases for __init__.py (mainly the exceptions defined there). -""" - -# Help with Python 3 compatibility, where the print statement is a function, an -# implicit relative import is invalid, and the '/' operator performs true -# division. Example: print 'hello world' raises a 'SyntaxError' exception. -from __future__ import print_function -from __future__ import absolute_import -from __future__ import division -from __future__ import unicode_literals - -import unittest -import logging - -import tuf -import tuf.exceptions -import tuf.log - -import securesystemslib - -logger = logging.getLogger(__name__) - -class TestInit(unittest.TestCase): - def setUp(self): - pass - - - def tearDown(self): - pass - - - def test_bad_signature_error(self): - bad_signature_error = securesystemslib.exceptions.BadSignatureError('bad_role') - logger.error(bad_signature_error) - - - def test_slow_retrieval_error(self): - slow_signature_error = tuf.exceptions.SlowRetrievalError('bad_role') - logger.error(slow_signature_error) - - - def test_bad_hash_error(self): - bad_hash_error = securesystemslib.exceptions.BadHashError('01234', '56789') - logger.error(bad_hash_error) - - - def test_invalid_metadata_json_error(self): - format_error = securesystemslib.exceptions.FormatError('Improperly formatted JSON') - invalid_metadata_json_error = tuf.exceptions.InvalidMetadataJSONError(format_error) - logger.error(invalid_metadata_json_error) - - - -# Run the unit tests. -if __name__ == '__main__': - unittest.main() From 03b15fb4be88fa2273134d23025c26d3bb2d8f8a Mon Sep 17 00:00:00 2001 From: Jussi Kukkonen Date: Tue, 15 Sep 2020 18:05:51 +0300 Subject: [PATCH 4/6] tests: Configure logging for all test files all test_*.py files now accept zero or more '-v' to increase tuf logging level. The default is now ERROR. default: ERROR "-v": ERROR, but unittest prints test names "-vv": WARNING "-vvv": INFO "-vvvv": DEBUG Example to run a single test with DEBUG level: python3 test_updater.py -vvvv TestUpdater.test_4_refresh Also make test_log.py restore the log level it modifies during test. Fixes #1093 Signed-off-by: Jussi Kukkonen --- tests/test_api.py | 3 +++ tests/test_arbitrary_package_attack.py | 2 ++ tests/test_developer_tool.py | 4 ++++ tests/test_download.py | 1 + tests/test_endless_data_attack.py | 2 ++ tests/test_extraneous_dependencies_attack.py | 2 ++ tests/test_formats.py | 4 ++++ tests/test_indefinite_freeze_attack.py | 2 ++ tests/test_key_revocation_integration.py | 2 ++ tests/test_keydb.py | 4 ++++ tests/test_log.py | 9 ++++++++ tests/test_mirrors.py | 4 ++++ tests/test_mix_and_match_attack.py | 2 ++ .../test_multiple_repositories_integration.py | 2 ++ tests/test_proxy_use.py | 1 + tests/test_replay_attack.py | 2 ++ tests/test_repository_lib.py | 4 ++++ tests/test_repository_tool.py | 7 ++++-- tests/test_roledb.py | 4 ++++ tests/test_root_versioning_integration.py | 4 ++++ tests/test_sig.py | 4 ++++ tests/test_slow_retrieval_attack.py | 4 ++++ tests/test_tutorial.py | 3 +++ tests/test_unittest_toolbox.py | 4 ++++ tests/test_updater.py | 2 ++ .../test_updater_root_rotation_integration.py | 2 ++ tests/utils.py | 23 +++++++++++++++++++ 27 files changed, 105 insertions(+), 2 deletions(-) diff --git a/tests/test_api.py b/tests/test_api.py index b2329bf780..00733132e9 100644 --- a/tests/test_api.py +++ b/tests/test_api.py @@ -17,6 +17,8 @@ from datetime import datetime, timedelta from dateutil.relativedelta import relativedelta +import utils + # TODO: Remove case handling when fully dropping support for versions >= 3.6 IS_PY_VERSION_SUPPORTED = sys.version_info >= (3, 6) @@ -258,4 +260,5 @@ def test_metadata_timestamp(self): # Run unit test. if __name__ == '__main__': + utils.configure_test_logging(sys.argv) unittest.main() diff --git a/tests/test_arbitrary_package_attack.py b/tests/test_arbitrary_package_attack.py index 6ce0ed691d..640b5596b1 100755 --- a/tests/test_arbitrary_package_attack.py +++ b/tests/test_arbitrary_package_attack.py @@ -44,6 +44,7 @@ import subprocess import logging import unittest +import sys import tuf import tuf.formats @@ -302,4 +303,5 @@ def test_with_tuf_and_metadata_tampering(self): if __name__ == '__main__': + utils.configure_test_logging(sys.argv) unittest.main() diff --git a/tests/test_developer_tool.py b/tests/test_developer_tool.py index 27ceeb76e5..6867104b60 100755 --- a/tests/test_developer_tool.py +++ b/tests/test_developer_tool.py @@ -26,6 +26,7 @@ import logging import tempfile import shutil +import sys import tuf import tuf.log @@ -40,6 +41,8 @@ from tuf.developer_tool import METADATA_DIRECTORY_NAME from tuf.developer_tool import TARGETS_DIRECTORY_NAME +import utils + logger = logging.getLogger(__name__) developer_tool.disable_console_log_messages() @@ -423,4 +426,5 @@ def test_write(self): if __name__ == '__main__': + utils.configure_test_logging(sys.argv) unittest.main() diff --git a/tests/test_download.py b/tests/test_download.py index 2f97048ac6..e9f1429e1c 100755 --- a/tests/test_download.py +++ b/tests/test_download.py @@ -391,4 +391,5 @@ def popen_python(command_arg_list): # Run unit test. if __name__ == '__main__': + utils.configure_test_logging(sys.argv) unittest.main() diff --git a/tests/test_endless_data_attack.py b/tests/test_endless_data_attack.py index 14452a6b85..b1977ec5b0 100755 --- a/tests/test_endless_data_attack.py +++ b/tests/test_endless_data_attack.py @@ -47,6 +47,7 @@ import subprocess import logging import unittest +import sys import tuf import tuf.formats @@ -290,4 +291,5 @@ def test_with_tuf(self): if __name__ == '__main__': + utils.configure_test_logging(sys.argv) unittest.main() diff --git a/tests/test_extraneous_dependencies_attack.py b/tests/test_extraneous_dependencies_attack.py index 421b4983a6..c67a6a25a4 100755 --- a/tests/test_extraneous_dependencies_attack.py +++ b/tests/test_extraneous_dependencies_attack.py @@ -50,6 +50,7 @@ import subprocess import logging import unittest +import sys import tuf.formats import tuf.log @@ -234,4 +235,5 @@ def test_with_tuf(self): if __name__ == '__main__': + utils.configure_test_logging(sys.argv) unittest.main() diff --git a/tests/test_formats.py b/tests/test_formats.py index 7b3116e7f4..9faa017633 100755 --- a/tests/test_formats.py +++ b/tests/test_formats.py @@ -30,10 +30,13 @@ import unittest import datetime +import sys import tuf import tuf.formats +import utils + import securesystemslib import six @@ -968,4 +971,5 @@ def test_encode_canonical(self): # Run unit test. if __name__ == '__main__': + utils.configure_test_logging(sys.argv) unittest.main() diff --git a/tests/test_indefinite_freeze_attack.py b/tests/test_indefinite_freeze_attack.py index 80ef4f7f02..c94b288a02 100755 --- a/tests/test_indefinite_freeze_attack.py +++ b/tests/test_indefinite_freeze_attack.py @@ -53,6 +53,7 @@ import subprocess import logging import unittest +import sys import tuf.formats import tuf.log @@ -504,4 +505,5 @@ def test_with_tuf(self): if __name__ == '__main__': + utils.configure_test_logging(sys.argv) unittest.main() diff --git a/tests/test_key_revocation_integration.py b/tests/test_key_revocation_integration.py index 1e72443aa0..8e7aade040 100755 --- a/tests/test_key_revocation_integration.py +++ b/tests/test_key_revocation_integration.py @@ -44,6 +44,7 @@ import random import subprocess import unittest +import sys import tuf import tuf.log @@ -514,4 +515,5 @@ def _load_role_keys(keystore_directory): if __name__ == '__main__': + utils.configure_test_logging(sys.argv) unittest.main() diff --git a/tests/test_keydb.py b/tests/test_keydb.py index d9ef148d25..4d481bd776 100755 --- a/tests/test_keydb.py +++ b/tests/test_keydb.py @@ -30,6 +30,7 @@ import unittest import logging +import sys import tuf import tuf.formats @@ -38,6 +39,8 @@ import tuf.keydb import tuf.log +import utils + logger = logging.getLogger(__name__) @@ -408,4 +411,5 @@ def test_create_keydb_from_root_metadata(self): # Run unit test. if __name__ == '__main__': + utils.configure_test_logging(sys.argv) unittest.main() diff --git a/tests/test_log.py b/tests/test_log.py index ad4aa37127..ea545ea12c 100755 --- a/tests/test_log.py +++ b/tests/test_log.py @@ -24,6 +24,7 @@ import unittest import os import shutil +import sys import tuf import tuf.log @@ -32,6 +33,8 @@ import securesystemslib import securesystemslib.util +import utils + from six.moves import reload_module # We explicitly create a logger which is a child of the tuf hierarchy, @@ -46,10 +49,15 @@ class TestLog(unittest.TestCase): + def setUp(self): + # store the current log level so it can be restored after the test + self._initial_level = logging.getLogger('tuf').level def tearDown(self): tuf.log.remove_console_handler() tuf.log.disable_file_logging() + logging.getLogger('tuf').level = self._initial_level + @@ -198,4 +206,5 @@ def test_disable_file_logging(self): # Run unit test. if __name__ == '__main__': + utils.configure_test_logging(sys.argv) unittest.main() diff --git a/tests/test_mirrors.py b/tests/test_mirrors.py index aa5efc7fb3..0c703ff37d 100755 --- a/tests/test_mirrors.py +++ b/tests/test_mirrors.py @@ -29,10 +29,13 @@ from __future__ import unicode_literals import unittest +import sys import tuf.mirrors as mirrors import tuf.unittest_toolbox as unittest_toolbox +import utils + import securesystemslib import securesystemslib.util import six @@ -111,4 +114,5 @@ def test_get_list_of_mirrors(self): # Run the unittests if __name__ == '__main__': + utils.configure_test_logging(sys.argv) unittest.main() diff --git a/tests/test_mix_and_match_attack.py b/tests/test_mix_and_match_attack.py index f077cb6ed1..131af35a54 100755 --- a/tests/test_mix_and_match_attack.py +++ b/tests/test_mix_and_match_attack.py @@ -45,6 +45,7 @@ import subprocess import logging import unittest +import sys import tuf.exceptions import tuf.log @@ -255,4 +256,5 @@ def test_with_tuf(self): if __name__ == '__main__': + utils.configure_test_logging(sys.argv) unittest.main() diff --git a/tests/test_multiple_repositories_integration.py b/tests/test_multiple_repositories_integration.py index d3c0c9717c..6db53682a0 100755 --- a/tests/test_multiple_repositories_integration.py +++ b/tests/test_multiple_repositories_integration.py @@ -37,6 +37,7 @@ import shutil import unittest import json +import sys import tuf import tuf.log @@ -301,4 +302,5 @@ def test_repository_tool(self): if __name__ == '__main__': + utils.configure_test_logging(sys.argv) unittest.main() diff --git a/tests/test_proxy_use.py b/tests/test_proxy_use.py index 744880b78a..27e0988217 100644 --- a/tests/test_proxy_use.py +++ b/tests/test_proxy_use.py @@ -380,4 +380,5 @@ def popen_python(command_arg_list): # Run unit test. if __name__ == '__main__': + utils.configure_test_logging(sys.argv) unittest.main() diff --git a/tests/test_replay_attack.py b/tests/test_replay_attack.py index 1fdd8915d8..e8c862425b 100755 --- a/tests/test_replay_attack.py +++ b/tests/test_replay_attack.py @@ -46,6 +46,7 @@ import subprocess import logging import unittest +import sys import tuf.formats import tuf.log @@ -338,4 +339,5 @@ def test_with_tuf(self): if __name__ == '__main__': + utils.configure_test_logging(sys.argv) unittest.main() diff --git a/tests/test_repository_lib.py b/tests/test_repository_lib.py index 4c449f4c97..0fa9a6aeee 100755 --- a/tests/test_repository_lib.py +++ b/tests/test_repository_lib.py @@ -37,6 +37,7 @@ import shutil import unittest import copy +import sys import tuf import tuf.formats @@ -49,6 +50,8 @@ import tuf.repository_lib as repo_lib import tuf.repository_tool as repo_tool +import utils + import securesystemslib import securesystemslib.exceptions import securesystemslib.rsa_keys @@ -1057,4 +1060,5 @@ def test__remove_invalid_and_duplicate_signatures(self): # Run the test cases. if __name__ == '__main__': + utils.configure_test_logging(sys.argv) unittest.main() diff --git a/tests/test_repository_tool.py b/tests/test_repository_tool.py index bdea70d500..09095411b8 100755 --- a/tests/test_repository_tool.py +++ b/tests/test_repository_tool.py @@ -35,17 +35,19 @@ import logging import tempfile import shutil +import sys import tuf import tuf.log import tuf.formats import tuf.roledb import tuf.keydb - import tuf.repository_tool as repo_tool -import securesystemslib.exceptions + +import utils import securesystemslib +import securesystemslib.exceptions import securesystemslib.storage logger = logging.getLogger(__name__) @@ -2194,4 +2196,5 @@ def test_append_signature(self): # Run the test cases. if __name__ == '__main__': + utils.configure_test_logging(sys.argv) unittest.main() diff --git a/tests/test_roledb.py b/tests/test_roledb.py index f036c763fd..4bc4efb0c8 100755 --- a/tests/test_roledb.py +++ b/tests/test_roledb.py @@ -30,6 +30,7 @@ import unittest import logging +import sys import tuf import tuf.formats @@ -37,6 +38,8 @@ import tuf.exceptions import tuf.log +import utils + import securesystemslib import securesystemslib.keys @@ -788,4 +791,5 @@ def tearDownModule(): # Run the unit tests. if __name__ == '__main__': + utils.configure_test_logging(sys.argv) unittest.main() diff --git a/tests/test_root_versioning_integration.py b/tests/test_root_versioning_integration.py index a73c2ade73..ee6f143c34 100755 --- a/tests/test_root_versioning_integration.py +++ b/tests/test_root_versioning_integration.py @@ -30,6 +30,7 @@ import tempfile import shutil import unittest +import sys import tuf import tuf.log @@ -39,6 +40,8 @@ import tuf.keydb import tuf.repository_tool as repo_tool +import utils + import securesystemslib import securesystemslib.storage @@ -227,4 +230,5 @@ def test_root_role_versioning(self): if __name__ == '__main__': + utils.configure_test_logging(sys.argv) unittest.main() diff --git a/tests/test_sig.py b/tests/test_sig.py index 1876c44a45..100c1368fa 100755 --- a/tests/test_sig.py +++ b/tests/test_sig.py @@ -32,6 +32,7 @@ import unittest import logging import copy +import sys import tuf import tuf.log @@ -41,6 +42,8 @@ import tuf.sig import tuf.exceptions +import utils + import securesystemslib import securesystemslib.keys @@ -547,4 +550,5 @@ def test_signable_has_invalid_format(self): # Run unit test. if __name__ == '__main__': + utils.configure_test_logging(sys.argv) unittest.main() diff --git a/tests/test_slow_retrieval_attack.py b/tests/test_slow_retrieval_attack.py index 50e9b89e97..5273e16843 100755 --- a/tests/test_slow_retrieval_attack.py +++ b/tests/test_slow_retrieval_attack.py @@ -52,6 +52,7 @@ import subprocess import logging import unittest +import sys import tuf.log import tuf.client.updater as updater @@ -60,6 +61,8 @@ import tuf.roledb import tuf.keydb +import utils + import six logger = logging.getLogger(__name__) @@ -322,4 +325,5 @@ def test_with_tuf_mode_2(self): if __name__ == '__main__': + utils.configure_test_logging(sys.argv) unittest.main() diff --git a/tests/test_tutorial.py b/tests/test_tutorial.py index e3102c66cc..83ee56404a 100644 --- a/tests/test_tutorial.py +++ b/tests/test_tutorial.py @@ -44,6 +44,8 @@ from tuf.repository_tool import * # part of TUTORIAL.md +import utils + import securesystemslib.exceptions from securesystemslib.formats import encode_canonical # part of TUTORIAL.md @@ -416,4 +418,5 @@ def test_tutorial(self): # Run unit test. if __name__ == '__main__': + utils.configure_test_logging(sys.argv) unittest.main() diff --git a/tests/test_unittest_toolbox.py b/tests/test_unittest_toolbox.py index 10b68202b9..308c0a4c80 100755 --- a/tests/test_unittest_toolbox.py +++ b/tests/test_unittest_toolbox.py @@ -31,9 +31,12 @@ import unittest import logging import shutil +import sys import tuf.unittest_toolbox as unittest_toolbox +import utils + logger = logging.getLogger(__name__) @@ -55,4 +58,5 @@ def test_tear_down_already_deleted_dir(self): # Run the unit tests. if __name__ == '__main__': + utils.configure_test_logging(sys.argv) unittest.main() diff --git a/tests/test_updater.py b/tests/test_updater.py index 3ea0206adf..5f2f3c3ee4 100644 --- a/tests/test_updater.py +++ b/tests/test_updater.py @@ -58,6 +58,7 @@ import random import subprocess import errno +import sys import unittest import tuf @@ -2178,4 +2179,5 @@ def _load_role_keys(keystore_directory): if __name__ == '__main__': + utils.configure_test_logging(sys.argv) unittest.main() diff --git a/tests/test_updater_root_rotation_integration.py b/tests/test_updater_root_rotation_integration.py index 71cdc39e0a..84ce59ac63 100755 --- a/tests/test_updater_root_rotation_integration.py +++ b/tests/test_updater_root_rotation_integration.py @@ -49,6 +49,7 @@ import subprocess import unittest import filecmp +import sys import tuf import tuf.log @@ -643,4 +644,5 @@ def _load_role_keys(keystore_directory): if __name__ == '__main__': + utils.configure_test_logging(sys.argv) unittest.main() diff --git a/tests/utils.py b/tests/utils.py index 02b0820c3e..a59cc30a03 100644 --- a/tests/utils.py +++ b/tests/utils.py @@ -20,11 +20,14 @@ Provide common utilities for TUF tests """ +import argparse import errno import logging import socket import time +import tuf.log + logger = logging.getLogger(__name__) try: @@ -74,3 +77,23 @@ def wait_for_server(host, port, timeout=10): raise TimeoutError +def configure_test_logging(argv): + # parse arguments but only handle '-v': argv may contain + # other things meant for unittest argument parser + parser = argparse.ArgumentParser(add_help=False) + parser.add_argument('-v', '--verbose', action='count', default=0) + args, _ = parser.parse_known_args(argv) + + if args.verbose <= 1: + # 0 and 1 both mean ERROR: this way '-v' makes unittest print test + # names without increasing log level + loglevel = logging.ERROR + elif args.verbose == 2: + loglevel = logging.WARNING + elif args.verbose == 3: + loglevel = logging.INFO + else: + loglevel = logging.DEBUG + + logging.basicConfig() + tuf.log.set_log_level(loglevel) From 1e0a2a31036aafb05ec5239783b155fab7f1d3eb Mon Sep 17 00:00:00 2001 From: Jussi Kukkonen Date: Tue, 15 Sep 2020 22:30:20 +0300 Subject: [PATCH 5/6] docs: Mention how to run individual tests Fixes #1076. Signed-off-by: Jussi Kukkonen --- docs/CONTRIBUTORS.rst | 8 ++++++++ 1 file changed, 8 insertions(+) diff --git a/docs/CONTRIBUTORS.rst b/docs/CONTRIBUTORS.rst index 3be2b607b6..cc2704f269 100644 --- a/docs/CONTRIBUTORS.rst +++ b/docs/CONTRIBUTORS.rst @@ -116,6 +116,14 @@ dependencies must already be installed (see above). $ cd tests $ python aggregate_tests.py +Individual tests can also be executed. Optional '-v' flags can be added to +increase log level up to DEBUG ('-vvvv'). +:: + + $ python test_updater.py # run a specific test file + $ python test_updater.py TestUpdater.test_4_refresh # run a specific test + $ python test_updater.py -vvvv TestUpdater.test_4_refresh # run test with DEBUG log level + To run the tests and measure their code coverage, the aggregation script can be invoked with the ``coverage`` tool (requires installation of ``coverage``, e.g. From 1e7ca5fb427610482e42defb93ee55a8194a17ef Mon Sep 17 00:00:00 2001 From: Jussi Kukkonen Date: Wed, 16 Sep 2020 14:38:10 +0300 Subject: [PATCH 6/6] tests: Set root logger level too We want the tests own log output visible as well, and they are not under the "tuf" logger. Set root level to the same value as "tuf". Signed-off-by: Jussi Kukkonen --- tests/utils.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tests/utils.py b/tests/utils.py index a59cc30a03..d0ad75d5b8 100644 --- a/tests/utils.py +++ b/tests/utils.py @@ -95,5 +95,5 @@ def configure_test_logging(argv): else: loglevel = logging.DEBUG - logging.basicConfig() + logging.basicConfig(level=loglevel) tuf.log.set_log_level(loglevel)