Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Improve Logging Configuration: don't modify root logger #182

Merged

Conversation

theOehrly
Copy link
Contributor

Currently, pytest-mpl uses logging.basicConfiguration to configure logging. But this modifies the configuration of the root logger which leads to unexpected and unwanted behaviour when testing code that itself uses logging.

To demonstrate the problem, I will use test_succeeds_faulty_mirror() with an additional logging call added:

@pytest.mark.mpl_image_compare(baseline_dir='http://www.python.org,' + baseline_dir_remote,
                               filename='test_succeeds_remote.png',
                               tolerance=DEFAULT_TOLERANCE)
def test_succeeds_faulty_mirror():
    logging.info("Example INFO message from tested module")
    fig = plt.figure()
    ax = fig.add_subplot(1, 1, 1)
    ax.plot([1, 2, 3])
    return fig

This test already causes a logging message from pytest-mpl itself, because an invalid URL is used. Now addtionally, it simulates that the tested code/module makes use of logging as well.

In pytest the --log-cli-level option can be used to configure the logging level that is output on the cli. By default, no messages are output.

If we now run the above example...

... without pytest-mpl (pytest) there is no logging output as expected.

example.py .                                                                        [100%]

=================================== 1 passed in 0.48s ====================================

... with pytest-mpl (pytest --mpl), suddenly there is logging output from pytest-mpl and from the tested code (should not happen).

example.py INFO:root:Example INFO message from tested module
INFO:pytest-mpl:Downloading http://www.python.orgtest_succeeds_remote.png failed: URLError(gaierror
(11001, 'getaddrinfo failed'))
.                                                                        [100%]

=================================== 1 passed in 1.15s ====================================

... with pytest-mpl and logging configured through pytest (pytest --mpl --log-cli-level=INFO), the logging messages from pytest-mpl are now output twice. (This happens because messages are propagated to the root logger as well and those are then handled by pytest.)

INFO     root:example.py:20 Example INFO message from tested module
INFO:pytest-mpl:Downloading http://www.python.orgtest_succeeds_remote.png failed: URLError(gaierror
(11001, 'getaddrinfo failed'))
INFO     pytest-mpl:plugin.py:375 Downloading http://www.python.orgtest_succeeds_remote.png failed:
 URLError(gaierror(11001, 'getaddrinfo failed'))
PASSED                                                                                      [100%]

======================================= 1 passed in 0.90s ========================================

The main problem here is that it is impossible to turn of logging to the cli when pytest-mpl is used. As shown, this is usually configured in pytest with the --log-cli-level option and similar options. But pytest-mpl's modification of the root logger completely bypasses this. This can make test output fairly unreadable if the tested module itself makes extensive use of logging.

This PR implements the usage of a completely separate logger for pytest-mpl. Its logging configuration is fully independent of pytest and independent of the tested code. Additionally, the same logging format as used for pytest's cli ouput is used.

I did consider tying into pytest's logging functionality directly to make pytest-mpl interact perfectly and use all features, including coloured output and similar. But this would need to rely heavily on non-public API parts of pytest and might therefore be prone to breaking when there are changes in pytest. The minor improvements would not be worth the risk and maintenance effort in my opinion.

@Cadair
Copy link
Contributor

Cadair commented Oct 24, 2022

Thanks a lot for the PR, I think it looks good, though I need to check if the docs build also fails on the main branch.

@theOehrly
Copy link
Contributor Author

I was waiting on feedback for the doc build failure. I looked at it but couldn't really make sense of it.

Copy link
Member

@ConorMacBride ConorMacBride left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This looks great, thanks! Just tried it out and it now means we can run pytest with -vv and not see hundreds of lines of Matplotlib and PIL debugging messages!

The docs build is failing as the latest version of Matplotlib no longer matches a filename within the repository. Not an issue with this PR, so I shall merge.

@ConorMacBride ConorMacBride merged commit 8ce4878 into matplotlib:main Oct 25, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

Successfully merging this pull request may close these issues.

None yet

3 participants