Generate more output with --verbose option

[ssbarnea]

Update 7/15/2020: See #381 (comment) for a roadmap

I was trying to debug twine usage (and especially twine upload) and making it more verbose but apparently there is no documentation about any verbose mode.

Even if I found some references in the source code to a --verbose option, apparently this is not recognised by twine.

Please advise how to enable a more verbose mode on twine so we would know what went wrong when we got an error like #289 (comment)

[brainwane]

@ssbarnea We have a little documentation about the fact that there is a --verbose option now; does that help?

[bhrutledge]

My read of this issue is that --verbose doesn't do much. It seems that it's only used once, in check_status_code:

twine/twine/utils.py

Lines 167 to 169 in 95ecde2

	if verbose:
	print('Content received from server:\n{}'.format(
	response.text))

Maybe the resolution is using it in more places? @ssbarnea what does "more verbose" mean to you?

[bhrutledge]

Brainstorming w/ @brainwane on opportunities to increase verbosity:

• Network interactions (e.g., what is requests doing)?
• Size of uploaded packages
• Package signing behavior
• List of packages that will be uploaded

In the case of #289, I'm not sure verbosity would have helped as much as a friendlier error message (as proposed in #499).

[VikramJayanthi17]

Some ways I think we could increase verbosity that I am working on is logging the following:

• Each request/response to/from PyPI (URL and HTTP method being used, headers and possibly w/ more verbosity, the payload)
• Where configuration (the .pypirc) file is being loaded from, and what is being loaded from it
• Size of uploaded packages
• Explicitly marking errors from PyPI with “Got this error message from PyPI:”
• List of packages that will be uploaded

To address this issue it seems that we would need to create a framework for logging verbose output and displaying it to the user. To allow reuse-ability and separation of complexity I believe adding a generic TwineCommand class with the following functionality would be beneficial:

• TwineCommand.__init__(self.args) - Creates the settings, initializes the arguments parser, adds arguments. This allows for any member of the command class to access the settings instance(via self.settings).
• TwineCommand.output(self, message, verbose=False) - Outputs a message to the user, if verbose is true then it only outputs the message if self.settings.verbose is true as well.
• TwineCommand.main(self) - Would raise a NotImplemented error as it must be implemented by its child classes.

The child classes would be specific commands such as ‘upload’. Eg:

• UploadCommand(TwineCommand)
  Must implement a main function:
• UploadCommand.main(self)
  Can implement any helper functions it needs:
• UploadCommand._skip_upload(...)

This would allow for the instance to access the settings(via self.settings) and prevents us from having to pass settings through multiple function calls. Utility functions could also be moved to this generic class, such as check_status_code. They would also be able to access the settings and check for relevant settings such as self.settings.verbose for check_status_code.

The TwineCommand.output function will be used to output, including verbose output, and will be called wherever we want to output anything to the user.

Overall I believe this restructuring would allow us to create a framework for handling verbosity as well as allow us to use this pattern for other settings if we ever need to, while separating complexity.

[bhrutledge]

Thanks for thinking this through, @VikramJayanthi17. I'd like to solicit feedback from the other @pypa/twine-maintainers before proceeding, so I've added the question label to this.

I like your list of things to add, though it might be worth prioritizing them and implementing them separately. You can see an example of how I did this with a checklist and separate PR's for in #231 (comment).

I'm wary of the restructuring you're proposing, which seems like it would require a lot of effort on your part and the maintainers to review it. I'm wondering if we can start with a lighter-weight approach, that leans on the configuration options provided by the standard logging module. I would have to dig into that to provide more specific suggestions.

[di]

I'm wary of the restructuring you're proposing, which seems like it would require a lot of effort on your part and the maintainers to review it.

I should mention that @VikramJayanthi17 and I have already spent some time chatting about this. As is, we'd need to pass the setting that determines verbosity through multiple function calls, which would change a number of function signatures, hence this proposal to refactor into a TwineCommand class instead.

That said, I agree it seems like a lot of changes. I'd argue that we should think about doing this anyways, to make individual commands more uniform and give them a more clear API (which would help with adding new commands (#324), and with providing a supported API (#194).

I'm wondering if we can start with a lighter-weight approach, that leans on the configuration options provided by the standard logging module. I would have to dig into that to provide more specific suggestions.

I think a light-weight approach could use a handler on the stdlib logging module and set the log level based on the supplied verbosity. Since it supports five different levels, do we want to have multiple levels of verbosity? Or map some (DEBUG/INFO) to "verbose on" and leave the rest (WARN/ERROR/CRITICAL) to when verbosity is not enabled? How would this work with #649? It seems like ideally we'd be able to specify the color once for each log level.

[sigmavirus24]

I should mention that @VikramJayanthi17 and I have already spent some time chatting about this. As is, we'd need to pass the setting that determines verbosity through multiple function calls, which would change a number of function signatures, hence this proposal to refactor into a TwineCommand class instead.

Which is why we need an API. This will break the zest.releaser folks

I think a light-weight approach could use a handler on the stdlib logging module and set the log level based on the supplied verbosity. Since it supports five different levels, do we want to have multiple levels of verbosity? Or map some (DEBUG/INFO) to "verbose on" and leave the rest (WARN/ERROR/CRITICAL) to when verbosity is not enabled? How would this work with #649? It seems like ideally we'd be able to specify the color once for each log level.

You can also add your own levels like Flake8 does. We need to be judicious with what we log, so (for now) we wouldn't want to say "We loaded ~/.pypirc" (since that's the only one). We'd want to have logs for ourselves but we'd want that to be something like -vvv

[di]

OK, so I'm hearing:

• we would prefer to move forward with the lightweight approach
• we should have more multiple levels, possibly up to -vvv
• we should probably use our own levels
• we should save TwineCommand refactoring for Present supported API #194

so (for now) we wouldn't want to say "We loaded ~/.pypirc" (since that's the only one).

My thinking here is that this would be useful for determining whether twine is successfully loading user configuration or not, e.g. maybe the user has typo'd the filename and come to us saying "twine is ignoring my .pypirc", we can say "run that command with -vvv" and see that twine failed to find ~/.pypirc.

[bhrutledge]

@di your list sounds reasonable to me.

After thinking about how I would approach this, could @VikramJayanthi17 start with a PR that adds one thing to the current -v option? It could even follow the current pattern of if verbose: print(...). I think that might make it faster/easier for them to go through the whole contribution process. That could be followed by refactoring when adding more to -v, -vv, etc.

I'd suggest "List of packages that will be uploaded" (and maybe "Size of uploaded packages"), since I think that's a source of confusion when using twine upload dist/*.

[di]

@bhrutledge Sounds like a good plan.

[VikramJayanthi17]

I will start working on a PR that adds the list of packages that will be uploaded following the current pattern. Thanks for the help!

[bhrutledge]

Some thoughts on future work.

Re: "Explicitly marking errors from PyPI”, I'd rather see that addressed in #587.

Re: "Where configuration (the .pypirc) file is being loaded from", I think just showing the absolute path in -v would be useful. I also like the idea of showing the resulting configuration. That could just be a list of attributes and values from Settings, but maybe it could also list where they were loaded from.

For example, how does the repository URL get set? In ascending order of precedence, I believe that's currently:

• TWINE_REPOSITORY w/ config in .pypirc
• --repository w/ config in .pypirc
• TWINE_REPOSITORY_URL
• --repository-url

[deveshks]

Given that there is a plan to approach this with multiple PRs, are we planning to do them in parallel?

If yes, I would love to work on some of them if possible.

[bhrutledge]

Thanks for offering, @deveshks. Other folks might feel differently, but I'm inclined to let @VikramJayanthi17 roll with this for now, esp. with the idea that there could be a refactoring, and that parallel efforts could be a source of confusion for everyone involved.

[VikramJayanthi17]

Roadmap for --verbose option changes

Outputting the following information when the verbose option is selected (depending on verbosity level):

• Distributions being uploaded Prints the packages that will be uploaded when using the --verbose option #652
• Size of uploaded distributions Prints the packages that will be uploaded when using the --verbose option #652
• Show that we're uploading the associated .asc file
• Where upload configuration is being loaded from Logged config location #675
• How the credentials (username, password, certificates) are set (.pypirc, keyring, CLI) and what they are (w/ placeholders for sensitive values) Credential Logging #685
• Request/response to/from PyPI (URL and HTTP method being used, headers and possibly w/ more verbosity, the payload)

Additionally, an open question is:

• What should be displayed at the each verbosity level?
  • @bhrutledge thinks adding multiple levels might not be worth the effort; see Logging package names, file sizes, and signatures #669 (comment)

[VikramJayanthi17]

As mentioned above I'm using stdlib to log the items in the checklist. Using custom levels was suggested by @sigmavirus24. While I believe we can use the existing levels for the functionality we want for this issue, custom levels may be useful for future functionality. The custom levels I would use would be below DEBUG(10 numerically).

If we used the existing levels which ones would be used? (I am assuming we want 3 levels of verbosity) What are the potential drawbacks of using existing levels? Any advice regarding this is appreciated. Thanks for the help.

[di]

With regards to custom levels, https://docs.python.org/3/howto/logging.html#custom-levels says:

...if you are convinced that you need custom levels, great care should be exercised when doing this, and it is possibly a very bad idea to define custom levels if you are developing a library.

Looking at flake8, it seems like it's not entirely using custom levels, but reusing logging.INFO and logging.DEBUG:

https://github.com/PyCQA/flake8/blob/181bb46098dddf7e2d45319ea654b4b4d58c2840/src/flake8/__init__.py#L27-L39

plus a custom level for _EXTRA_VERBOSE (-vvv).

[di]

I think what flake8 is doing here looks good to me, should we move ahead with this @bhrutledge @sigmavirus24?

[ssbarnea]

If I remember well the name of extra debug level are DEBUG2, DEBUG3. At least this is what I seen on other places.

[sigmavirus24]

If I remember well the name of extra debug level are DEBUG2, DEBUG3. At least this is what I seen on other places.

They can be that, or you can give them clearer names.

[bhrutledge]

@VikramJayanthi17 After digging around the code a bit, I tweaked the checklist in #381 (comment). I think "Where upload configuration is being loaded from" is a good next addition to --verbose after #670 is merged.

[bhrutledge]

With the merge of #685, and looking over the checklist in #381 (comment), I think there's been enough improvement to --verbose to close this. If folks want additions/changes, please open specific issues.

Thanks to everyone who participated in the discussion, and to @VikramJayanthi17 for all of his work to implement it.

[bhrutledge]

This has been released: https://pypi.org/project/twine/3.3.0/