Silence errors to be raised #1145

jku · 2020-09-15T09:07:56Z

Fixes #1108, fixes #1093

This does not fix every logging inconsistency but it does fix issues that become visible in normal usage when running the updater at log level ERROR.

I decided to not try issue #1120 in the same PR (as it might require more discussion), but did fix #1093 (Option to show log output when running individual tests) because that is needed to easily verify these fixes. Now you can run e.g.

python3 test_updater.py -vvvv TestUpdater.test_4_refresh

to run a specific test with DEBUG level output. The default level is ERROR.

Description of the changes being introduced by the pull request:

Avoid logging inside the library when all info is included in the exception that will be raised
When logging, avoid using log levels ERROR, CRITICAL (and the exception logger) when tuf is not actually in error or critical state itself.
remove test_init.py and test_exceptions.py: they do not seem to be tests
Configure logging for all individual test files

I still have these complaints/questions (but personally can live with the PR as is):

test_log.py is strange: I'm not 100% sure how it works or should work, but I dislike it printing errors and warnings on normal operation
repository_tool and repository_lib modify log handlers and their log levels. The fact that just importing repository_tool affects logging is fishy... but I did not want to modify this here as I'm not sure if there are any visible issues
Unittest already uses "-v": this is fine except that the effects I added are now a little hard to discover -- I did not want to implement "--help" since that would hide the help output from unittest itself...

Please verify and check that the pull request fulfills the following
requirements:

The code follows the Code Style Guidelines
Tests have been added for the bug fix or new feature
Docs have been added for the bug fix or new feature

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

tuf/client/updater.py

MVrachev · 2020-09-15T15:17:11Z

Looks good to me.

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

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

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 theupdateframework#1093 Signed-off-by: Jussi Kukkonen <jkukkonen@vmware.com>

Fixes theupdateframework#1076. Signed-off-by: Jussi Kukkonen <jkukkonen@vmware.com>

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

jku · 2020-09-17T11:29:41Z

Something that may not be obvious: Running some tests like test_updater.py (at default ERROR level) is currently still very chatty because we get a lot of warnings. Warnings are not integrated into the logging system by default, but we should be able to make them into e.g. WARNING level log entries quite easily: then the default output would be quite nice.

However, ideally we should fix the warnings instead of hiding them so I've not done the integration here (EDIT: this was annoying enough that I finished my ResourceWarning cleanup: #1147).

MVrachev · 2020-09-17T12:28:34Z

tests/utils.py

+  parser.add_argument('-v', '--verbose', action='count', default=0)
+  args, _ = parser.parse_known_args(argv)
+
+  if args.verbose <= 1:


In your commit message, you have mentioned that the number of v means the following:

default: ERROR "-v": ERROR, but unittest prints test names "-vv": WARNING "-vvv": INFO "-vvvv": DEBUG

I think this should be documented somewhere.
Can we have like --help argument and functionality?

I wish we could... but I don't see a way to do that without breaking unittest --help. The lack of discoverability is annoying but I just don't know how to make it better (without essentially hiding unittest functionality, which I also don't want to do)

MVrachev · 2020-09-17T12:41:12Z

Looks good to me besides my comment.

I am glad you have removed tests/test_exceptions.py and tests/test_init.py.
I don't quite understand the need for those tests...

joshuagl · 2020-09-21T15:27:03Z

remove test_init.py and test_exceptions.py: they do not seem to be tests

I half-expected this to change the coverage, but it's still at 97% 🤷‍♂️

repository_tool and repository_lib modify log handlers and their log levels. The fact that just importing repository_tool affects logging is fishy... but I did not want to modify this here as I'm not sure if there are any visible issues

I think this one is worth an issue, would you mind creating one?

jku · 2020-09-22T07:33:22Z

#1148 is about import repository_tool side effects

joshuagl

Great set of cleanups for logging, thanks @jku. I have a question in-line about how you're choosing logging levels, I think I figured it out in most cases apart from that one.

joshuagl · 2020-09-22T10:48:37Z

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


Can you elaborate on why you chose debug level here?

I don't have a strong opinion here, but I think the reason I went with debug() was to avoid info() for things that

do happen in normal usage

are then raised as exceptions and handled in calling code: in this case Updater will usually log 'Update failed from ...' also at debug level

just so I'm not misleading: 'Update failed from ...' log level was also chosen by me in this PR.

The point that I tried to make was that the 'lower level code' (download) probably should not log at INFO if the 'higher level code' (Updater) logs the same thing at DEBUG. A case could be made for the Updater logs for failed updates to be INFO though...

And that logging in updater is only a DEBUG because an exception is raised if all mirrors fail. This makes sense, thanks for providing that extra context.

I agree, a case could be made for info. But I'm not making that case here.

Download: Do not log unnecessary errors

4bcf761

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

joshuagl mentioned this pull request Sep 15, 2020

Add logging config and guidelines #1132

Closed

MVrachev reviewed Sep 15, 2020

View reviewed changes

tuf/client/updater.py Outdated Show resolved Hide resolved

MVrachev reviewed Sep 15, 2020

View reviewed changes

tuf/client/updater.py Outdated Show resolved Hide resolved

Jussi Kukkonen added 2 commits September 15, 2020 19:49

jku force-pushed the silence-errors-to-be-raised branch 2 times, most recently from 99a597e to 0dd7ef8 Compare September 15, 2020 17:16

jku force-pushed the silence-errors-to-be-raised branch from 0dd7ef8 to 03b15fb Compare September 15, 2020 18:40

docs: Mention how to run individual tests

1e0a2a3

Fixes theupdateframework#1076. Signed-off-by: Jussi Kukkonen <jkukkonen@vmware.com>

jku marked this pull request as ready for review September 15, 2020 19:43

tests: Set root logger level too

1e7ca5f

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

MVrachev mentioned this pull request Sep 17, 2020

Log subproceses stdout and stderr in temp files #1104

Merged

3 tasks

MVrachev reviewed Sep 17, 2020

View reviewed changes

MVrachev mentioned this pull request Sep 18, 2020

logging in test runner / CI : higher log level but only print failing tests #1120

Open

joshuagl approved these changes Sep 22, 2020

View reviewed changes

joshuagl merged commit 505f354 into theupdateframework:develop Sep 22, 2020

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Silence errors to be raised #1145

Silence errors to be raised #1145

jku commented Sep 15, 2020 •

edited

Loading

MVrachev commented Sep 15, 2020

jku commented Sep 17, 2020 •

edited

Loading

MVrachev Sep 17, 2020

jku Sep 17, 2020

MVrachev commented Sep 17, 2020 •

edited

Loading

joshuagl commented Sep 21, 2020 •

edited

Loading

jku commented Sep 22, 2020

joshuagl left a comment

joshuagl Sep 22, 2020

jku Sep 22, 2020

jku Sep 22, 2020 •

edited

Loading

joshuagl Sep 22, 2020

Silence errors to be raised #1145

Silence errors to be raised #1145

Conversation

jku commented Sep 15, 2020 • edited Loading

MVrachev commented Sep 15, 2020

jku commented Sep 17, 2020 • edited Loading

MVrachev Sep 17, 2020

Choose a reason for hiding this comment

jku Sep 17, 2020

Choose a reason for hiding this comment

MVrachev commented Sep 17, 2020 • edited Loading

joshuagl commented Sep 21, 2020 • edited Loading

jku commented Sep 22, 2020

joshuagl left a comment

Choose a reason for hiding this comment

joshuagl Sep 22, 2020

Choose a reason for hiding this comment

jku Sep 22, 2020

Choose a reason for hiding this comment

jku Sep 22, 2020 • edited Loading

Choose a reason for hiding this comment

joshuagl Sep 22, 2020

Choose a reason for hiding this comment

jku commented Sep 15, 2020 •

edited

Loading

jku commented Sep 17, 2020 •

edited

Loading

MVrachev commented Sep 17, 2020 •

edited

Loading

joshuagl commented Sep 21, 2020 •

edited

Loading

jku Sep 22, 2020 •

edited

Loading