Fix debug logging for build with a build script

[vit-zikmund]

Pull Request Check List

Resolves: #8756

• Added tests for changed code.
  Haven't seen any existing tests for log output 🤔 should I hack it nevertheless?
• Updated documentation for changed code.
  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 the virtualenv.cli_run call. With the default setup_logging=True it pretty much resets the root logger level to WARNING (or to its desired verbosity in args, but that's not being used). I'm setting the setup_logging=False, which then adopts the root logger as is. That fixes the original problem, now every Poetry's info and debug logs pass through again, but also all info and debug logs from virtualenv 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.

• One way is by setting the custom handler on the particular named log handlers and setting back setup_logging=True for virtualenv. 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 the virtualenv.report.LOGGER (root logger) to some logger we control. Won't work, they directly use logging.info etc. for logging 😞 that always goes back to the root logger.

[vit-zikmund]

I've eventually realized improving the third-party decoration logic in IOFormatter could make this look acceptable. The last commit bears a take on that.

[radoering]

Thank you for going down this rabbit hole and providing such a detailed explanation.

I've eventually realized improving the third-party decoration logic in IOFormatter could make this look acceptable. The last commit bears a take on that.

Trying poetry build with the example from the linked issue, I get [filelock:filelock] and [virtualenv] on Linux but [lib:filelock] and [lib] on Windows. So probably something we should improve (and write a unit test for).

Without having taken a closer look, I'd suppose to have one test for the third party logging logic in io_formatter and one test for the virtualenv.cli_run() thing.

Haven't seen any existing tests for log output

There are tests where we check the output via io.fetch_output() and io.fetch_error(). (Not sure if that's what you meant.)

[vit-zikmund]

Good points and pointers @radoering , thanks for giving it a whirl under Windows. I'll see what I can do, despite Win not being readily available around my premises.

[vit-zikmund]

Thank you @radoering for finishing up this PR, it's an honor. I'm sorry I wasn't able to be of a better further assistance.

[github-actions]

This pull request has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.