logging in updater tests is weirdly broken

[jku]

Something weird goes on in the updater tests logging. In the middle of the test (seemingly around the time the last root.json download fails during Updater.refresh()) logger level seems to somehow change to debug. It's not just that though: even if I change the level of some earlier logger calls (like changing logger.debug() to logger.error()) so that they become visible, they don't look the same as similar logging later on. The earlier output from e.g. logger.error() isn't prefixed with logger level and component.

Current behavior:

jku@luna:~/src/tuf/tests$ python3 test_updater_root_rotation_integration.py TestUpdater.test_root_rotation
Adding a verification key that has already been used.
Adding a verification key that has already been used.
127.0.0.1 - - [17/Jul/2020 17:44:27] code 404, message File not found
Could not download URL: 'http://localhost:30379/tmp2kxfm_pt/TestUpdater_nsqxv0n9/repository/metadata/4.root.json'
Traceback (most recent call last):
  File "/home/jku/src/tuf/tuf/download.py", line 264, in _download_file
    response.raise_for_status()
  File "/usr/lib/python3/dist-packages/requests/models.py", line 941, in raise_for_status
    raise HTTPError(http_error_msg, response=self)
requests.exceptions.HTTPError: 404 Client Error: File not found for url: http://localhost:30379/tmp2kxfm_pt/TestUpdater_nsqxv0n9/repository/metadata/4.root.json
Update failed from http://localhost:30379/tmp2kxfm_pt/TestUpdater_nsqxv0n9/repository/metadata/4.root.json.
Traceback (most recent call last):
  File "/home/jku/src/tuf/tuf/client/updater.py", line 1502, in _get_metadata_file
    file_object = tuf.download.unsafe_download(file_mirror,
  File "/home/jku/src/tuf/tuf/download.py", line 150, in unsafe_download
    return _download_file(url, required_length, STRICT_REQUIRED_LENGTH=False)
  File "/home/jku/src/tuf/tuf/download.py", line 264, in _download_file
    response.raise_for_status()
  File "/usr/lib/python3/dist-packages/requests/models.py", line 941, in raise_for_status
    raise HTTPError(http_error_msg, response=self)
requests.exceptions.HTTPError: 404 Client Error: File not found for url: http://localhost:30379/tmp2kxfm_pt/TestUpdater_nsqxv0n9/repository/metadata/4.root.json
Failed to update '4.root.json' from all mirrors: {'http://localhost:30379/tmp2kxfm_pt/TestUpdater_nsqxv0n9/repository/metadata/4.root.json': HTTPError('404 Client Error: File not found for url: http://localhost:30379/tmp2kxfm_pt/TestUpdater_nsqxv0n9/repository/metadata/4.root.json')}
ERROR:root:HTTP error for root version 4
Traceback (most recent call last):
  File "/home/jku/src/tuf/tuf/client/updater.py", line 1145, in _update_root_metadata
    self._update_metadata('root', DEFAULT_ROOT_UPPERLENGTH,
  File "/home/jku/src/tuf/tuf/client/updater.py", line 1781, in _update_metadata
    self._get_metadata_file(metadata_role, remote_filename,
  File "/home/jku/src/tuf/tuf/client/updater.py", line 1598, in _get_metadata_file
    raise tuf.exceptions.NoWorkingMirrorError(file_mirror_errors)
tuf.exceptions.NoWorkingMirrorError: No working mirror was found:
  'localhost:30379': HTTPError('404 Client Error: File not found for url: http://localhost:30379/tmp2kxfm_pt/TestUpdater_nsqxv0n9/repository/metadata/4.root.json')
INFO:tuf.download:Downloading: 'http://localhost:30379/tmp2kxfm_pt/TestUpdater_nsqxv0n9/repository/metadata/timestamp.json'
DEBUG:tuf.download:url: http://localhost:30379/tmp2kxfm_pt/TestUpdater_nsqxv0n9/repository/metadata/timestamp.json
DEBUG:tuf.download:session index: http+localhost
DEBUG:tuf.download:Reusing session for http+localhost
DEBUG:tuf.download:The average download speed has not dipped below the minimum average download speed set in tuf.settings.py.
DEBUG:tuf.download:The average download speed has not dipped below the minimum average download speed set in tuf.settings.py.
DEBUG:tuf.download:Downloaded 704/16384 bytes.
DEBUG:tuf.download:Good average download speed: 3255805.689459533 bytes per second
INFO:tuf.download:Downloaded 704 bytes out of an upper limit of 16384 bytes.
DEBUG:tuf.client.updater:Updated '/home/jku/src/tuf/tests/tmp2kxfm_pt/TestUpdater_nsqxv0n9/client/test_repository1/metadata/current/timestamp.json'.
DEBUG:tuf.client.updater:'snapshot' referenced in 'timestamp'.  'snapshot' may be updated.
DEBUG:tuf.client.updater:New version for 'snapshot.json': 2.  Old version: 1
DEBUG:tuf.client.updater:Metadata 'snapshot.json' has changed.
INFO:tuf.download:Downloading: 'http://localhost:30379/tmp2kxfm_pt/TestUpdater_nsqxv0n9/repository/metadata/snapshot.json'
DEBUG:tuf.download:url: http://localhost:30379/tmp2kxfm_pt/TestUpdater_nsqxv0n9/repository/metadata/snapshot.json
DEBUG:tuf.download:session index: http+localhost
DEBUG:tuf.download:Reusing session for http+localhost
DEBUG:tuf.download:The average download speed has not dipped below the minimum average download speed set in tuf.settings.py.
DEBUG:tuf.download:The average download speed has not dipped below the minimum average download speed set in tuf.settings.py.
DEBUG:tuf.download:Downloaded 515/2000000 bytes.
DEBUG:tuf.download:Good average download speed: 2003757.797441751 bytes per second
INFO:tuf.download:Downloaded 515 bytes out of an upper limit of 2000000 bytes.
DEBUG:tuf.client.updater:Updated '/home/jku/src/tuf/tests/tmp2kxfm_pt/TestUpdater_nsqxv0n9/client/test_repository1/metadata/current/snapshot.json'.
DEBUG:tuf.client.updater:'targets' referenced in 'snapshot'.  'targets' may be updated.
DEBUG:tuf.client.updater:New version for 'targets.json': 1.  Old version: 1
INFO:tuf.client.updater:'targets.json' up-to-date.
.
----------------------------------------------------------------------
Ran 1 test in 1.426s

OK

[jku]

After shutting the laptop down I realized we are probably not initializing logging when running the test "by hand", and then something does it during the test. We should do something like logging.basicConfig() somewhere waves hands vaguely

[sechkova]

After spending a surprisingly long time on this log, I think I have found, if not a solution, at least an explanation.

1. Executing the tests by aggregate_tests.py buffers the output on a successful run. Likewise if we execute a test "by hand" with buffer=True (-b on the command line), the logging output remains hidden until an error occurs. But this only hides the problem without resolving it.

2. The first part of the log (which 'isn't prefixed with logger level and component'):
   This should not be seen at all since test_updater_root_rotation_integration.py, same as many other test, calls repo_tool.disable_console_log_messages() which seems to be useless. What actually happens is that after removing the console handler, there are no handlers left at all which most likely leads to a "handler of a last resort" situation.

3. The second part of the log (and this is the funny part 😁 ):
   Here the log mysteriously changes its formatting without an obvious reason. However in Updater._update_root_metadata(), there is an (unintentional?) call to logging.exception instead of logger.exception which is doing exactly what we observe:

    """
    Log a message with severity 'ERROR' on the root logger, with exception
    information. If the logger has no handlers, basicConfig() is called to add
    a console handler with a pre-defined format.
    """

https://github.com/theupdateframework/tuf/blob/b265fb944656d8e42f5dcb0cc89aae65639c8b2a/tuf/client/updater.py#L1154

[sechkova]

I opened #1092 to start a discussion of the above in a way.

[jku]

Closing. update_tests.py output is still four screens of various ResourceWarnings but the output is not obviously broken anymore: Thanks!