Capture and log messages emitted by C modules when importing them

[jacobtylerwalls]

Steps

• For new features or bug fixes, add a ChangeLog entry describing what your PR does.
• Write a good description on what the PR does.

Description

Pipe stdout to stderr Capture and log messages emitted while importing C modules. This prevents contaminating programmatic output, e.g. pylint's JSON reporter.

An alternative would be to silence stdout altogether, but there may be users who appreciate the notice that code is being executed. This way no information is lost, while still allowing clean programmatic output.

Type of Changes

	Type
✓	🐛 Bug fix

Related Issue

Closes pylint-dev/pylint#3518

/cc @piotr-machura, what do you think of this approach?

[coveralls]

Pull Request Test Coverage Report for Build 2374232989

• 13 of 13 (100.0%) changed or added relevant lines in 1 file are covered.
• No unchanged relevant lines lost coverage.
• Overall coverage increased (+0.01%) to 91.916%

---

Totals
Change from base Build 2371242414:	0.01%
Covered Lines:	9233
Relevant Lines:	10045

---

💛 - Coveralls

[Pierre-Sassoulas]

I'm wondering if the solution would be to add debug logging to astroid. It seems to me that this output is not error so technically should not be printed to stderr (although it's convenient to do so because we would not have to setup logging). I don't think we have logging in astroid yet, but we don't have to do the configuration, probably just clarifying in the documentation that you need to activate logging with debug level if you want to see the stdout from loading c module.

[jacobtylerwalls]

It seems to me that this output is not error so technically should not be printed to stderr (although it's convenient to do so because we would not have to setup logging).

Thanks, I thought about this for a bit. I think the fact that astroid imports C modules (that are allowlisted, or even just that have a brain, see #562), is worth warning the user, and that's an okay use for stderr. "Welcome to pygame!" is not an error in pygame, but IMO when it happens in astroid it's worth a warning because it could be unexpected.

I found a couple interesting things at the Python logging docs for library developers:

If the using application does not use logging, and library code makes logging calls, then (as described in the previous section) events of severity WARNING and greater will be printed to sys.stderr. This is regarded as the best default behaviour.

So I think even if we go the logging route we'll end up generating messages in stderr, is that right?

[jacobtylerwalls]

Ah, maybe we could wrap it in a UserWarning or something that can be filtered idiomatically.

[Pierre-Sassoulas]

So I think even if we go the logging route we'll end up generating messages in stderr,

I would use the "info" log level for what comes from stdout, debug is a little low. If the output comes from stderr originally we should use the error level though. Reading your documentation it seems we should add a NullHandler so nothing is printed unless lib users add a configuration.

If for some reason you don’t want these messages printed in the absence of any logging configuration, you can attach a do-nothing handler to the top-level logger for your library. This avoids the message being printed, since a handler will always be found for the library’s events: it just doesn’t produce any output. If the library user configures logging for application use, presumably that configuration will add some handlers, and if levels are suitably configured then logging calls made in library code will send output to those handlers, as normal.

A do-nothing handler is included in the logging package: NullHandler (since Python 3.1). An instance of this handler could be added to the top-level logger of the logging namespace used by the library (if you want to prevent your library’s logged events being output to sys.stderr in the absence of logging configuration).

import logging
logger = logging.getLogger(astroid).addHandler(logging.NullHandler())

# (logger = logging.getLogger(__file__))
...
if stderr:
    logger.error(...)
else:
    logger.info(...)

[Pierre-Sassoulas]

LGTM, that's a nice addition to 2.12 !

[jacobtylerwalls]

@Pierre-Sassoulas did you want to remove this in another MR? I reverted this change here.

[Pierre-Sassoulas]

It happened to prevent installing with pip locally I guess it's not that important. (Duplicated entry)