Fix debug logging for build
with a build script
#8760
Merged
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
Pull Request Check List
Resolves: #8756
Haven't seen any existing tests for log output 🤔 should I hack it nevertheless?
This shouldn't need any change.
This change aims to fix the muted debug level logs for builds with a custom build script.
Trying to understand in depth what the optional build script can do, I ran into a very scarce output despite using
-vvv
. Roaming the building/packaging code, I found out there's definitely some debug logging that might come in handy but is not getting out.First I found a piece of logging (a7a42905 by @abn) that lacked a newline. I tried to fix that in line with what I understood the original code tries to do (I still have a feeling I didn't hit the exact spot, but it sure works better now). It also seemed like a lost opportunity not to log the pip call there, so I added it for debug. It looks quite good as is, but we it might want to prefix those lines with something to make it clear it's a 3rd party log. Either way, this doesn't really tackle the original problem...
I found that despite the
poetry-core
builders' loggers have their log level set properly, they have no handlers of their own, so rely on the parent's (root logger's) custom handler set a couple lines above. This works nice, until something touches the root logger, which is exactly what happens by default in thevirtualenv.cli_run
call. With the defaultsetup_logging=True
it pretty much resets the root logger level toWARNING
(or to its desired verbosity inargs
, but that's not being used). I'm setting thesetup_logging=False
, which then adopts the root logger as is. That fixes the original problem, now every Poetry'sinfo
anddebug
logs pass through again, but also allinfo
anddebug
logs fromvirtualenv
hitch a ride, which is not the prettiest thing under the sun. But it's the debug logs we're after, right, so this might be a good thing!Either way, this surely requires at least your aesthetic opinion, as I'm not aware of any logging guideline you stand by. Thank you for helping me out.
PS: I think there's a way how to avoid the
virutalenv
's verbose logs.setup_logging=True
forvirtualenv
. But that tramples the root logger, which definitely sucks and seems hardly as a conceptual thing to do.Another way might be to monkey-patch theWon't work, they directly usevirtualenv.report.LOGGER
(root logger) to some logger we control.logging.info
etc. for logging 😞 that always goes back to the root logger.