logging: don't attempt to close handlers unless they have been opened by oliver-sanders · Pull Request #727 · ipython/traitlets

oliver-sanders · 2022-05-13T10:25:00Z

Accessing Application.log.handlers causes them to be opened if not done already.
Attempting to open log handlers whilst Python is shutting down causes traceback.
Closes Logging errors on Application teardown #722
Traceback introduced by Application: add logging_config trait #698 (apologies)

* Accessing `Application.log.handlers` causes them to be opened if not done already. * Attempting to open log handlers whilst Python is shutting down causes traceback. * Closes ipython#722

for more information, see https://pre-commit.ci

hroncok · 2022-05-13T17:58:49Z

This indeed fixes jupyter/notebook#6424

hroncok

I like the double-secured test very much!

hroncok · 2022-05-13T20:16:20Z

However, the second part of the test fails for me in Fedora:

=================================== FAILURES ===================================
________________________ test_logging_teardown_on_error ________________________

monkeypatch = <_pytest.monkeypatch.MonkeyPatch object at 0x7ff79ce25450>
capsys = <_pytest.capture.CaptureFixture object at 0x7ff79ce27820>

    def test_logging_teardown_on_error(monkeypatch, capsys):
        """Ensure we don't try to open logs in order to close them (See #722).
    
        If you try to configure logging handlers whilst Python is shutting down
        you'll get traceback.
        """
        # simulate a failure configuring logging handlers
        # (this can happen if you try to configure handlers whilst Python is
        # shutting down).
        def _configure(*args, **kwargs):
            raise Exception()
    
        monkeypatch.setattr(
            "logging.config.DictConfigurator.configure",
            _configure,
        )
    
        # create and destroy an app (without configuring logging)
        # (ensure that we don't get any traceback)
        app = Application()
        del app
        out, err = capsys.readouterr()
        assert "Traceback" not in err
    
        # ensure that we would get traceback otherwise
        # (to prevent this test from yielding false-negatives)
        app = Application()
        app._logging_configured = True  # make it look like logging was configured
        del app
        out, err = capsys.readouterr()
>       assert "Traceback" in err
E       AssertionError: assert 'Traceback' in ''

_configure = <function test_logging_teardown_on_error.<locals>._configure at 0x7ff79c08ce50>
capsys     = <_pytest.capture.CaptureFixture object at 0x7ff79ce27820>
err        = ''
monkeypatch = <_pytest.monkeypatch.MonkeyPatch object at 0x7ff79ce25450>
out        = ''

traitlets/config/tests/test_application.py:837: AssertionError

oliver-sanders · 2022-05-16T08:46:10Z

However, the second part of the test fails for me in Fedora:

Thanks for looking in, what version of Python were you using for your test?

hroncok · 2022-05-16T10:24:09Z

Sorry for not specifying. That'll be Python 3.10.4.

Also:

+ /usr/bin/python3 -m pip list
Package    Version
---------- -------
attrs      21.4.0
flit_core  3.7.1
iniconfig  1.1.1
packaging  21.3
pip        22.0.4
pluggy     1.0.0
py         1.11.0
pyparsing  2.4.7
pytest     7.1.2
setuptools 60.9.3
toml       0.10.2
tomli      2.0.1

hroncok · 2022-05-16T10:37:22Z

Note that I get the failure in traitlets 5.2.0 + this patch applied. If you think it's worth trying to use this branch entirely, I can do that, but there shouldn't be a difference.

I've also tested with Python 3.11.0b1 (the same package versions as with 3.10.4) and there is the same failure.

hroncok · 2022-05-16T10:46:28Z

The same failure happens with Python 3.9.12 and:

Package    Version
---------- -------
attrs      20.3.0
flit-core  3.7.1
iniconfig  1.1.1
packaging  20.9
pip        21.0.1
pluggy     0.13.1
py         1.11.0
pyparsing  2.4.7
pytest     6.2.2
setuptools 53.0.0
toml       0.10.2

=================================== FAILURES ===================================
________________________ test_logging_teardown_on_error ________________________

monkeypatch = <_pytest.monkeypatch.MonkeyPatch object at 0x7fcf2eb8ecd0>
capsys = <_pytest.capture.CaptureFixture object at 0x7fcf2eb82c40>

    def test_logging_teardown_on_error(monkeypatch, capsys):
        """Ensure we don't try to open logs in order to close them (See #722).
    
        If you try to configure logging handlers whilst Python is shutting down
        you'll get traceback.
        """
        # simulate a failure configuring logging handlers
        # (this can happen if you try to configure handlers whilst Python is
        # shutting down).
        def _configure(*args, **kwargs):
            raise Exception()
    
        monkeypatch.setattr(
            "logging.config.DictConfigurator.configure",
            _configure,
        )
    
        # create and destroy an app (without configuring logging)
        # (ensure that we don't get any traceback)
        app = Application()
        del app
        out, err = capsys.readouterr()
        assert "Traceback" not in err
    
        # ensure that we would get traceback otherwise
        # (to prevent this test from yielding false-negatives)
        app = Application()
        app._logging_configured = True  # make it look like logging was configured
        del app
        out, err = capsys.readouterr()
>       assert "Traceback" in err
E       AssertionError: assert 'Traceback' in ''

_configure = <function test_logging_teardown_on_error.<locals>._configure at 0x7fcf2eb993a0>
capsys     = <_pytest.capture.CaptureFixture object at 0x7fcf2eb82c40>
err        = ''
monkeypatch = <_pytest.monkeypatch.MonkeyPatch object at 0x7fcf2eb8ecd0>
out        = ''

traitlets/config/tests/test_application.py:837: AssertionError

oliver-sanders · 2022-05-16T10:47:23Z

It seems to be a change in Python 3.10, that traceback doesn't show up any more. Not sure why, can't see anything obvious in the changes. Easy workaround...

hroncok · 2022-05-16T10:49:09Z

Note that if I remove the monkeypatch of logging.config.DictConfigurator.configure, I get the very same thing. Is it possible that it is never actually called?

oliver-sanders · 2022-05-16T10:50:05Z

It's definitely called, but only when logging needs to be configured. This doesn't happen until the first time the log attribute is accessed.

oliver-sanders · 2022-05-16T10:52:43Z

(With 83ac6f9 it should pass 3.7-3.10)

hroncok

This passes now on Fedora with Pythons 3.9.12, 3.10.4, 3.11.0b1. Thank you.

blink1073

Thanks! I'm working on fixing builds in #728, will kick this after merging and then cut a release.

blink1073 · 2022-05-16T12:57:02Z

https://github.com/ipython/traitlets/releases/tag/5.2.1

hroncok · 2022-05-16T13:34:12Z

Thanks! What's up with the 5.2.1.post0 release? It appears identical to 5.2.1 (sans the version information).

blink1073 · 2022-05-16T13:37:09Z

I had a stray extra set of quotes in the version spec.

hroncok · 2022-05-16T13:38:44Z

Oh, I see. Thanks.

oliver-sanders and others added 2 commits May 13, 2022 11:23

logging: don't attmpt to close handlers unless they have been opened

e1b7f7d

* Accessing `Application.log.handlers` causes them to be opened if not done already. * Attempting to open log handlers whilst Python is shutting down causes traceback. * Closes ipython#722

[pre-commit.ci] auto fixes from pre-commit.com hooks

4f58814

for more information, see https://pre-commit.ci

oliver-sanders mentioned this pull request May 13, 2022

Logging errors on Application teardown #722

Closed

hroncok approved these changes May 13, 2022

View reviewed changes

logging: fix test for Python 3.10+

83ac6f9

hroncok approved these changes May 16, 2022

View reviewed changes

blink1073 approved these changes May 16, 2022

View reviewed changes

blink1073 closed this May 16, 2022

blink1073 reopened this May 16, 2022

blink1073 merged commit 18b2f47 into ipython:main May 16, 2022

oliver-sanders deleted the 722 branch May 16, 2022 12:39

consideRatio mentioned this pull request May 24, 2022

ValueError: Unable to configure formatter 'console' seen also with 5.2.2.post1 #731

Closed

blink1073 mentioned this pull request Jan 5, 2023

traitlets 5.2 breaks --help-all check in application CLI jupyter-server/jupyter_server#843

Closed

lexming added a commit to lexming/easybuild-easyconfigs that referenced this pull request Mar 28, 2023

fix ipython/traitlets#727 in IPython v8.5.0 by upgrading to v5.2.1.post0

3a3162b

Uh oh!

Conversation

oliver-sanders commented May 13, 2022

Uh oh!

hroncok commented May 13, 2022

Uh oh!

hroncok left a comment

Choose a reason for hiding this comment

Uh oh!

hroncok commented May 13, 2022

Uh oh!

oliver-sanders commented May 16, 2022

Uh oh!

hroncok commented May 16, 2022

Uh oh!

hroncok commented May 16, 2022 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

hroncok commented May 16, 2022

Uh oh!

oliver-sanders commented May 16, 2022

Uh oh!

hroncok commented May 16, 2022

Uh oh!

oliver-sanders commented May 16, 2022

Uh oh!

oliver-sanders commented May 16, 2022

Uh oh!

hroncok left a comment

Choose a reason for hiding this comment

Uh oh!

blink1073 left a comment

Choose a reason for hiding this comment

Uh oh!

blink1073 commented May 16, 2022

Uh oh!

hroncok commented May 16, 2022

Uh oh!

blink1073 commented May 16, 2022

Uh oh!

hroncok commented May 16, 2022

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

3 participants

hroncok commented May 16, 2022 •

edited

Loading