Logging in Updater is reporting errors despite things proceeding as expected

[joshuagl]

Description of issue or feature request:

When following the steps in the QUICKSTART.md the call to client.py results in three tracebacks, with associated error messages, being printed to the terminal. These occur when trying to check for a new version of the root metadata (as is the standard client workflow), triggered by the call to updater.refresh() in client.py.
These error messages are printed despite the file fetch being successful and client.py exiting cleanly.

When the Updater looks for a newer version of root.json a new file is not found and tracebacks for three different, otherwise handled or spurious, exceptions are printed in:

• download.py's _download_file()
• updater.pys _get_metadata_file()
• updater.pys _update_root_metadata()

Note: the tracebacks are printed even when logging is disabled by passing --verbose 0 to client.py

Current behavior:

Successful file fetch with client.py causes 3 tracebacks and error messages to be printed:

Could not download URL: 'http://localhost:8001/metadata/2.root.json'
Traceback (most recent call last):
  File "/Users/jlock/.venv/tuf/lib/python3.7/site-packages/tuf/download.py", line 264, in _download_file
    response.raise_for_status()
  File "/Users/jlock/.venv/tuf/lib/python3.7/site-packages/requests/models.py", line 940, in raise_for_status
    raise HTTPError(http_error_msg, response=self)
requests.exceptions.HTTPError: 404 Client Error: File not found for url: http://localhost:8001/metadata/2.root.json
Update failed from http://localhost:8001/metadata/2.root.json.
Traceback (most recent call last):
  File "/Users/jlock/.venv/tuf/lib/python3.7/site-packages/tuf/client/updater.py", line 1507, in _get_metadata_file
    upperbound_filelength)
  File "/Users/jlock/.venv/tuf/lib/python3.7/site-packages/tuf/download.py", line 150, in unsafe_download
    return _download_file(url, required_length, STRICT_REQUIRED_LENGTH=False)
  File "/Users/jlock/.venv/tuf/lib/python3.7/site-packages/tuf/download.py", line 264, in _download_file
    response.raise_for_status()
  File "/Users/jlock/.venv/tuf/lib/python3.7/site-packages/requests/models.py", line 940, in raise_for_status
    raise HTTPError(http_error_msg, response=self)
requests.exceptions.HTTPError: 404 Client Error: File not found for url: http://localhost:8001/metadata/2.root.json
Failed to update '2.root.json' from all mirrors: {'http://localhost:8001/metadata/2.root.json': HTTPError('404 Client Error: File not found for url: http://localhost:8001/metadata/2.root.json')}
ERROR:root:HTTP error for root version 2
Traceback (most recent call last):
  File "/Users/jlock/.venv/tuf/lib/python3.7/site-packages/tuf/client/updater.py", line 1150, in _update_root_metadata
    version=next_version)
  File "/Users/jlock/.venv/tuf/lib/python3.7/site-packages/tuf/client/updater.py", line 1786, in _update_metadata
    upperbound_filelength, version)
  File "/Users/jlock/.venv/tuf/lib/python3.7/site-packages/tuf/client/updater.py", line 1602, in _get_metadata_file
    raise tuf.exceptions.NoWorkingMirrorError(file_mirror_errors)
tuf.exceptions.NoWorkingMirrorError: No working mirror was found:
  'localhost:8001': HTTPError('404 Client Error: File not found for url: http://localhost:8001/metadata/2.root.json')
INFO:tuf.download:Downloading: 'http://localhost:8001/metadata/timestamp.json'
INFO:tuf.download:Downloaded 557 bytes out of an upper limit of 16384 bytes.
INFO:tuf.client.updater:'snapshot.json' up-to-date.
INFO:tuf.client.updater:'targets.json' up-to-date.
INFO:tuf.client.updater:'targets.json' up-to-date.
INFO:tuf.client.updater:'targets.json' up-to-date.

Expected behavior:

Standard client workflows (such as checking for newer root metadata) don't cause Tracebacks and Errors to be printed.
Successful operations don't result in Tracebacks and Errors being printed.

[lukpueh]

Many thanks for submitting this issue, @joshuagl. Let me cross-reference this with two related issues: #967 (exception hierarchy/messages) and #881 (roadmap for cli tools).

[jku]

Note: the tracebacks are printed even when logging is disabled by passing --verbose 0 to client.py

--verbose 0 does not actually disable logging (it sets verbosity to default so actually means --verbose 2). The least logging happens with --verbose 5 🤷 which only prints the ERROR and related traceback.

Looks like _download_file() and _get_metadata_file() failure messages and tracebacks should be handled at DEBUG level, not ERROR. The _update_root_metadata() should be a (better written) INFO at most and the related traceback DEBUG at most.

[lukpueh]

Thanks for digging into this issue, @jku!

[sechkova]

This behaviour may have improved to the extent of not logging anything after merging #1092. At least this is what I've observed after a quick test:

~/workspace/tutorial/tufclient$ client.py --repo http://localhost:8001 testfile
~/workspace/tutorial/tufclient$ tree
.
├── tufrepo
│   └── metadata
│       ├── current
│       │   ├── 1.root.json
│       │   ├── root.json
│       │   ├── snapshot.json
│       │   ├── targets.json
│       │   └── timestamp.json
│       └── previous
│           ├── 1.root.json
│           ├── root.json
│           ├── snapshot.json
│           ├── targets.json
│           └── timestamp.json
└── tuftargets
    └── testfile

5 directories, 11 files
~/workspace/tutorial/tufclient$ client.py --repo http://localhost:8001 testfileJDFHDf
Error: 'testfileJDFHDf' not found.

While on the server side:

~/workspace/tutorial/tufrepo$ python3 -m http.server 8001
Serving HTTP on 0.0.0.0 port 8001 (http://0.0.0.0:8001/) ...
127.0.0.1 - - [30/Jul/2020 18:07:43] code 404, message File not found
127.0.0.1 - - [30/Jul/2020 18:07:43] "GET /metadata/2.root.json HTTP/1.1" 404 -
127.0.0.1 - - [30/Jul/2020 18:07:43] "GET /metadata/timestamp.json HTTP/1.1" 200 -
127.0.0.1 - - [30/Jul/2020 18:07:43] "GET /metadata/snapshot.json HTTP/1.1" 200 -
127.0.0.1 - - [30/Jul/2020 18:07:43] "GET /metadata/targets.json HTTP/1.1" 200 -
127.0.0.1 - - [30/Jul/2020 18:07:43] "GET /targets/testfile HTTP/1.1" 200 -
127.0.0.1 - - [30/Jul/2020 18:08:00] code 404, message File not found
127.0.0.1 - - [30/Jul/2020 18:08:00] "GET /metadata/2.root.json HTTP/1.1" 404 -
127.0.0.1 - - [30/Jul/2020 18:08:00] "GET /metadata/timestamp.json HTTP/1.1" 200 -

Yet probably a more thorough testing is needed to confirm that everything is ok ...

[trishankatdatadog]

💯 Thanks for fixing this long outstanding annoying issue, all

[joshuagl]

Resolved in #1092! Thanks @sechkova 🎉 🥇