Repository navigation
Logging in Updater is reporting errors despite things proceeding as expected #983
Description
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.
Activity
lukpueh commentedon Feb 19, 2020
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).
[-]Following the QUICKSTART.md, when fetching the target file with client.py, produces lengthy output with Tracebacks and several mentions of Errors when the operation succeeds[/-][+]Logging in Updater is reporting errors despite things proceeding as expected[/+]jku commentedon Jun 17, 2020
--verbose 0does 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 commentedon Jun 17, 2020
Thanks for digging into this issue, @jku!
sechkova commentedon Jul 30, 2020
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:
While on the server side:
Yet probably a more thorough testing is needed to confirm that everything is ok ...
trishankatdatadog commentedon Jul 30, 2020
💯 Thanks for fixing this long outstanding annoying issue, all
joshuagl commentedon Jul 30, 2020
Resolved in #1092! Thanks @sechkova 🎉 🥇