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 <jkukkonen@vmware.com>

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()

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()

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()

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()

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()

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()

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()

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()

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()

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()

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()

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()

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()

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()

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()

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()

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()

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()

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()

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()

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()

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()

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()

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()

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()

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()

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)