Logging package names, file sizes, and signatures #669

VikramJayanthi17 · 2020-06-24T21:32:07Z

As mentioned in #381 I used the stdlib logging library to log packages being uploaded, file sizes, and signatures. These are already logged using the current --verbose pattern. This PR potentially serves as the start of the transition from the current --verbose pattern and output to a one based on logging using stdlib and has multiple verbosity levels.

The logger is setup in utils.py and utilized throughout the upload command. The --verbose field in Settings is now an integer(not a boolean) from 0(default) to 3. The log level is determined by verbose's value and the higher the verbosity, the lower(more encompassing) the log level is. I used 1 custom log level(for -vvv) and 2 existing levels.

The additional information we want to output, as outlined in #381(comment) will be added in subsequent PRs after resolving any concerns/issue/concerns/problems in this PR.

bhrutledge

This is a great start, thank you! Seeing the implementation raises a few questions which hadn't occurred to me. With that in mind, I'd wait for @sigmavirus24 to give a review before proceeding.

bhrutledge · 2020-06-27T10:01:16Z

twine/settings.py

-        verbose: bool = False,
+        verbose: int = 0,


This looks like an API change to a public class, which we've avoided in the time that I've been contributing to Twine. Now, it might be fine, thanks to duck typing, but it makes me wonder:

Do we actually need multiple verbosity levels and the complexity that brings? IE, can we leave it as a boolean in this PR, and iterate towards multiple if/when necessary?

If we do want multiple levels right away, does this imply the next version is Twine 4.0?

If we add verbosity and deprecate verbose then we could keep verboes around and use verbosity if it's an int and not None.

We could schedule verbose for removal in 4.0

Okay, that's helpful roadmap, but it still makes me wonder if supporting -vv and -vvv at this point provides enough value to Twine's users to warrant the maintenance overhead.

In my opinion, it doesn't, and I'd like to stick with one -v that remains a bool, unless @sigmavirus24 and @di feel strongly otherwise.

bhrutledge · 2020-06-27T10:01:38Z

twine/settings.py

-        :param bool verbose:
+        :param int verbosity:


This doesn't match the keyword argument.

bhrutledge · 2020-06-27T10:09:06Z

twine/commands/upload.py

@@ -65,9 +67,9 @@ def _make_package(

    if upload_settings.verbose:


I think one of the benefits of using logging is that we don't need to check the setting each time; we can just log at the appropriate level, and let the logging configuration handle the filtering.

Suggested change

if upload_settings.verbose:

Exactly right, @bhrutledge. Good catch

bhrutledge · 2020-06-27T10:13:46Z

twine/utils.py

            if verbose:
-                print("Content received from server:\n{}".format(response.text))
+                logger.info("Content received from server:\n{}".format(response.text))
            else:
-                print("NOTE: Try --verbose to see response content.")
+                logger.warning("NOTE: Try --verbose to see response content.")


Same note as above re: not checking verbose and letting logging do the work.

logger.info("Content received from server:\n{}".format(response.text)) logger.warning("NOTE: Try --verbose to see response content.")

However, this makes the verbose argument to the function unnecessary, and I'm not sure how to deal with that.

If we do this then the "NOTE: Try --verbose to see response content" will be printed even if the user is using the --verbose option as a warning level log will be logged even if the log level is set to info. I think leaving verbose as a parameter for the function makes sense here as it would allow for selectively printing the "NOTE: Try --verbose to see response content" message without having to print conditionally on log level(which may be confusing to read) but that would also work.

bhrutledge · 2020-06-27T10:25:11Z

twine/utils.py

+_MAX_VERBOSITY = 5
+
+_VERBOSITY_TO_LOG_LEVEL = {
+    0: logging.WARNING,
+    1: logging.INFO,
+    2: logging.DEBUG,
+    3: _MAX_VERBOSITY,
+}


Looking at the flake8 implementation, it seems like this is missing a logging.addLevelName call, as well as an explanation of why _MAX_VERBOSITY is 5.

However, again I wonder if we really need _MAX_VERBOSITY (or anything beyond logging.INFO for now).

bhrutledge · 2020-06-27T10:29:18Z

twine/utils.py

+        args_verbosity = 3
+
+    log_level = _VERBOSITY_TO_LOG_LEVEL[args_verbosity]
+    logger = logging.getLogger("LOGGER")


I'm pretty sure the logger name should reflect the root package name:

Suggested change

logger = logging.getLogger("LOGGER")

logger = logging.getLogger("twine")

bhrutledge · 2020-06-27T10:31:57Z

twine/utils.py

+    handler.setLevel(log_level)
+    logger.addHandler(handler)
+    # Setting a level of verbosity for the logger
+    logger.setLevel(log_level)


I think we only need one setLevel call, and the method name is sufficiently descriptive to not need a comment:

Suggested change

handler.setLevel(log_level)

logger.addHandler(handler)

# Setting a level of verbosity for the logger

logger.setLevel(log_level)

logger.addHandler(handler)

logger.setLevel(log_level)

I'm guessing this is cribbed liberally from Flake8 and I do think that I needed to call to setLevel but that may have been a 2/3 compatibility issue. We should test which combination of set levels is actually appropriate rather than guessing

bhrutledge · 2020-06-27T10:34:20Z

twine/settings.py

-            action="store_true",
-            help="Show verbose output.",
+            action="count",
+            help="Show verbose output. -v to -vvv in increasing verbosity.",


Suggested change

help="Show verbose output. -v to -vvv in increasing verbosity.",

help="Show more output. Can be used up to 3 times.",

bhrutledge · 2020-06-27T10:40:25Z

twine/settings.py

+        # Setting up logging before the config is loaded
+        utils.setup_logging(verbose)


I'm not sure utils is the right place for setup_logging. If --verbose were a global option (similar to --no-color), I might suggest moving it __init__.py ala flake8, or a dedicated twine.logging module.

However, since --verbose only applies to commands that use Settings (i.e. upload and register, but not check), I'd tempted to move the logging configuration to this class, so that this becomes:

Suggested change

# Setting up logging before the config is loaded

utils.setup_logging(verbose)

self._setup_logging()

I really don't know that it matters if setup_logging is in utils. I could see users of the the porcelain API wanting to also turn off logging regardless of what's passed into the config and using this to try to do so (and thus wanting to use twine.utils)

However, given our suggestion to define a twine.utils.logger module attribute, I think that might be confusing with the current implementation, which also defines logger as a local variable in setup_logging. It looks like flake8 manages this by setting up logging in the package's __init__.py. @sigmavirus24 what do you think about following that pattern?

# twine/__init__.py import logging logger = logging.getLogger(__name__) def setup_logging(verbose): # ... logger.setLevel(log_level) # twine/settings.py import twine class Settings: def __init__(self, ...): # ... self.verbose = verbose twine.setup_logging(verbose)

@bhrutledge I think your example will result in a circular dependency. I think doing

root_logger = logging.getLogger("twine")

is acceptable for altering the logger. I don't think we need to rely too heavily on setup_logging if we move that into twine. I'm also worried that setup_logging being at the top-level module will be confusing for folks looking at the API who aren't familiar with logging.

Out of curiosity, I tried out the twine/__init__.py approach (plus some of the other suggested changes) in df46b35, and it doesn't seem to result in a circular dependency.

Given that it's package-level configuration, __init__.py feels reasonable, but I see how it might not be obvious. That said, I've recently become wary of the utils.py pattern of unrelated behaviors. Maybe cli.py would be a more natural location? Or, how about a function in settings.py?

import logging def _setup_logging(verbose): # ... root_logger = logging.getLogger("twine") class Settings: def __init__(self, ...): # ... self.verbose = verbose _setup_logging(verbose)

Here, I made it private, to avoid prematurely adding another public API.

bhrutledge · 2020-06-27T10:50:37Z

twine/commands/upload.py

@@ -56,6 +57,7 @@ def _make_package(
 ) -> package_file.PackageFile:
    """Create and sign a package, based off of filename, signatures and settings."""
    package = package_file.PackageFile.from_filename(filename, upload_settings.comment)
+    logger = logging.getLogger("LOGGER")


I think by changing the setup_logging to use twine instead of LOGGER, you could follow the typical convention of using the module name (i.e. twine.commands.upload) as the logger name.

Suggested change

logger = logging.getLogger("LOGGER")

logger = logging.getLogger(__name__)

Also, I think this should be at the top of the module, after the imports, so that any function can use logger without needing to call getLogger.

Correct @bhrutledge

To correctly setup the logger(in _setup_logging), we need the name of the logger to be consistent(so that we have the right handlers and log_level in place). __name__ wouldn't work as logger name as __name__ would be "twine.settings" in _setup_logging and twine.commands.upload in upload.py so the two files would refer to different loggers. Using "twine" presents no issue. Additionally we need to setup the loggerinsettings.py` because we plan on logging the config file path & config so we cannot wait until the command is called to setup the logger.

sigmavirus24 · 2020-06-27T14:33:32Z

twine/commands/upload.py

@@ -56,6 +57,7 @@ def _make_package(
 ) -> package_file.PackageFile:
    """Create and sign a package, based off of filename, signatures and settings."""
    package = package_file.PackageFile.from_filename(filename, upload_settings.comment)
+    logger = logging.getLogger("LOGGER")


Correct @bhrutledge

sigmavirus24 · 2020-06-27T14:35:04Z

twine/settings.py

+        # Setting up logging before the config is loaded
+        utils.setup_logging(verbose)


I really don't know that it matters if setup_logging is in utils. I could see users of the the porcelain API wanting to also turn off logging regardless of what's passed into the config and using this to try to do so (and thus wanting to use twine.utils)

sigmavirus24 · 2020-06-27T14:35:30Z

twine/utils.py

    """Generate a helpful message based on the response from the repository.

    Raise a custom exception for recognized errors. Otherwise, print the
    response content (based on the verbose option) before re-raising the
    HTTPError.
    """
+    logger = logging.getLogger("LOGGER")


Again there should be one global logger = logging.getLogger(__name__)

To clarify, "global" here means at the top of the module, after the imports, same as https://github.com/pypa/twine/pull/669/files#r446512223.

sigmavirus24 · 2020-06-27T14:35:46Z

twine/utils.py

+        args_verbosity = 3
+
+    log_level = _VERBOSITY_TO_LOG_LEVEL[args_verbosity]
+    logger = logging.getLogger("LOGGER")


sigmavirus24 · 2020-06-27T14:36:44Z

twine/utils.py

+    handler.setLevel(log_level)
+    logger.addHandler(handler)
+    # Setting a level of verbosity for the logger
+    logger.setLevel(log_level)


I'm guessing this is cribbed liberally from Flake8 and I do think that I needed to call to setLevel but that may have been a 2/3 compatibility issue. We should test which combination of set levels is actually appropriate rather than guessing

bhrutledge · 2020-06-27T18:16:49Z

twine/utils.py

    """Generate a helpful message based on the response from the repository.

    Raise a custom exception for recognized errors. Otherwise, print the
    response content (based on the verbose option) before re-raising the
    HTTPError.
    """
+    logger = logging.getLogger("LOGGER")


To clarify, "global" here means at the top of the module, after the imports, same as https://github.com/pypa/twine/pull/669/files#r446512223.

bhrutledge · 2020-06-27T18:31:03Z

twine/settings.py

+        # Setting up logging before the config is loaded
+        utils.setup_logging(verbose)


However, given our suggestion to define a twine.utils.logger module attribute, I think that might be confusing with the current implementation, which also defines logger as a local variable in setup_logging. It looks like flake8 manages this by setting up logging in the package's __init__.py. @sigmavirus24 what do you think about following that pattern?

# twine/__init__.py import logging logger = logging.getLogger(__name__) def setup_logging(verbose): # ... logger.setLevel(log_level) # twine/settings.py import twine class Settings: def __init__(self, ...): # ... self.verbose = verbose twine.setup_logging(verbose)

bhrutledge · 2020-06-27T18:34:17Z

twine/settings.py

-        verbose: bool = False,
+        verbose: int = 0,


Okay, that's helpful roadmap, but it still makes me wonder if supporting -vv and -vvv at this point provides enough value to Twine's users to warrant the maintenance overhead.

In my opinion, it doesn't, and I'd like to stick with one -v that remains a bool, unless @sigmavirus24 and @di feel strongly otherwise.

VikramJayanthi17 · 2020-07-01T23:35:31Z

Thanks for the feedback @bhrutledge & @sigmavirus24. I will go ahead and make these changes.

Okay, that's helpful roadmap, but it still makes me wonder if supporting -vv and -vvv at this point provides enough value to Twine's users to warrant the maintenance overhead.

Some of the additional information we planned to log(as mentioned in #381) were only going to be outputted at higher verbosity levels(-vv or -vvv). If we don't have multiple verbosity levels would we log all that information for the -v verbosity level or not at all?

bhrutledge · 2020-07-01T23:50:57Z

Some of the additional information we planned to log(as mentioned in #381) were only going to be outputted at higher verbosity levels(-vv or -vvv). If we did't have multiple verbosity levels would we log all that information for the -v verbosity level or not at all?

We could do either of those things, or we could decide to add support for -vv when the additional logging is implemented. But, in the spirit YAGNI and smaller PR's, I would stick with one -v for now, and keep this PR scoped to just the changes necessary to convert the existing verbose output from print to logger.info.

With that in mind, and given all of the other feedback, I might consider closing this and starting with a fresh branch. But if you prefer to work off this one, that's fine, too.

My apologies for not suggesting this sooner. Thanks for sticking with it.

sigmavirus24 · 2020-07-02T14:36:37Z

@bhrutledge YAGNI here isn't helpful. Users already want the ability to increase verbosity, so we do need it. We have an existence proof for users that will use this. I agree smaller PRs are nice, and we can break this work up into smaller PRs if necessary but you haven't defined what "smaller" is. At the moment this is +105,-41 which is plenty reviewable. I'd argue that based on scientific research we could grow this PR an extra few hundred lines without it out-growing "small". This feels like you're moving the goal posts on @VikramJayanthi17 though and that doesn't seem fair to me.

bhrutledge · 2020-07-02T17:33:50Z

@sigmavirus24 Some quick thoughts to keep things moving along; I'm opting for direct language here, which I realize can read as defensive/antagonistic, which is not my intent.

This feels like you're moving the goal posts on @VikramJayanthi17 though and that doesn't seem fair to me.

I feel bad about that, and have attempted to convey that in my comments. However, I think it's okay to reconsider the desired outcome when the implementation reveals unexpected complexities, which I believe this PR has done. FWIW, I attempted to discuss this in #669 (comment) and #669 (comment), but didn't get the response that I hoped. Maybe we can have a discussion elsewhere about how to resolve these sorts of things.

Users already want the ability to increase verbosity, so we do need it

The ask, as I understand it from #381, is to make --verbose more useful, which I think is well under way. It was only in #381 (comment) that you proposed additional verbosity levels.

We have an existence proof for users that will use this.

Do you mean verbose output in general? I agree. However, if you mean multiple levels of verbosity, I don't see the proof of that.

we can break this work up into smaller PRs if necessary but you haven't defined what "smaller" is

That was my intention in #669 (comment):

I would stick with one -v for now, and keep this PR scoped to just the changes necessary to convert the existing verbose output from print to logger.info.

How could I have been more clear?

At the moment this is +105,-41 which is plenty reviewable.

I'm more interested in the scope of the changes than the number of lines changed. Again, my concern is that by adding the extra support for -vv and -vvv at this point, we're prematurely adding work for @VikramJayanthi17 and the reviewers.

VikramJayanthi17 · 2020-07-06T21:42:42Z

I closed this PR and opened a new one(with a new branch) here : #670

di marked this pull request as draft June 24, 2020 22:24

VikramJayanthi17 force-pushed the logging-package-name-signatures branch 2 times, most recently from 7ded9e4 to f3c3806 Compare June 25, 2020 19:47

VikramJayanthi17 marked this pull request as ready for review June 25, 2020 19:48

logging package names, signatures, and file sizes with stdlib logging

1ac3fe3

VikramJayanthi17 force-pushed the logging-package-name-signatures branch from 7ac8f47 to 1ac3fe3 Compare June 25, 2020 22:11

di requested review from bhrutledge and sigmavirus24 June 26, 2020 19:34

bhrutledge requested changes Jun 27, 2020

View reviewed changes

sigmavirus24 reviewed Jun 27, 2020

View reviewed changes

bhrutledge requested changes Jun 27, 2020

View reviewed changes

VikramJayanthi17 closed this Jul 6, 2020

VikramJayanthi17 mentioned this pull request Jul 6, 2020

Setup basic logging functionality(existing output) with 1 level of verbosity #670

Merged

VikramJayanthi17 mentioned this pull request Jul 15, 2020

Generate more output with --verbose option #381

Closed

bhrutledge mentioned this pull request Jan 22, 2022

Log all upload responses with --verbose #859

Merged

		@@ -65,9 +67,9 @@ def _make_package(

		if upload_settings.verbose:

	logger = logging.getLogger("LOGGER")
	logger = logging.getLogger("twine")

	help="Show verbose output. -v to -vvv in increasing verbosity.",
	help="Show more output. Can be used up to 3 times.",

		# Setting up logging before the config is loaded
		utils.setup_logging(verbose)

	# Setting up logging before the config is loaded
	utils.setup_logging(verbose)
	self._setup_logging()

	logger = logging.getLogger("LOGGER")
	logger = logging.getLogger(__name__)

Logging package names, file sizes, and signatures #669

Logging package names, file sizes, and signatures #669

Conversation

VikramJayanthi17 commented Jun 24, 2020 • edited

bhrutledge left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

bhrutledge Jun 27, 2020 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

bhrutledge Jun 27, 2020 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

bhrutledge Jun 27, 2020 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

VikramJayanthi17 commented Jul 1, 2020 • edited

bhrutledge commented Jul 1, 2020

sigmavirus24 commented Jul 2, 2020

bhrutledge commented Jul 2, 2020 • edited

VikramJayanthi17 commented Jul 6, 2020

VikramJayanthi17 commented Jun 24, 2020 •

edited

bhrutledge Jun 27, 2020 •

edited

bhrutledge Jun 27, 2020 •

edited

bhrutledge Jun 27, 2020 •

edited

VikramJayanthi17 commented Jul 1, 2020 •

edited

bhrutledge commented Jul 2, 2020 •

edited