LogCapture breaks ipdb

[bromatofiel]

Hello,

Thank you for LogCapture, I'm using it by default during all my tests to hide spam and displays errors only if a test fails. Very helpful!

But with release 8.3.0, I can't use ipdb anymore due to LogCapture.close() raising AssertionError('LogCapture instance closed while still installed').

Here is a minimalist way to reproduce:

from testfixtures import LogCapture

def test():
    with LogCapture() as capture:
        import ipdb
        ipdb.set_trace()
    print("success")


test()

And here is the trace:

Error in sys.excepthook:
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/site-packages/IPython/core/debugger.py", line 179, in BdbQuit_excepthook
    raise ValueError(
ValueError: `BdbQuit_excepthook` is deprecated since version 5.1. It is still around only because it is still imported by ipdb.

Original exception was:
Traceback (most recent call last):
  File "/usr/local/lib/python3.12/site-packages/traitlets/traitlets.py", line 632, in get
    value = obj._trait_values[self.name]
            ~~~~~~~~~~~~~~~~~^^^^^^^^^^^
KeyError: 'log'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/app/test.py", line 10, in <module>
    test()
  File "/app/test.py", line 6, in test
    ipdb.set_trace()
  File "/usr/local/lib/python3.12/site-packages/ipdb/__main__.py", line 77, in set_trace
    p = _init_pdb(context).set_trace(frame)
        ^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/ipdb/__main__.py", line 54, in _init_pdb
    debugger_cls = _get_debugger_cls()
                   ^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/ipdb/__main__.py", line 34, in _get_debugger_cls
    ipapp.initialize(["--no-term-title"])
  File "/usr/local/lib/python3.12/site-packages/traitlets/config/application.py", line 118, in inner
    return method(app, *args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/IPython/terminal/ipapp.py", line 269, in initialize
    super(TerminalIPythonApp, self).initialize(argv)
  File "/usr/local/lib/python3.12/site-packages/traitlets/config/application.py", line 118, in inner
    return method(app, *args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/IPython/core/application.py", line 480, in initialize
    self.parse_command_line(argv)
  File "/usr/local/lib/python3.12/site-packages/traitlets/config/application.py", line 118, in inner
    return method(app, *args, **kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/traitlets/config/application.py", line 879, in parse_command_line
    loader = self._create_loader(argv, aliases, flags, classes=classes)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/traitlets/config/application.py", line 790, in _create_loader
    argv, aliases, flags, classes=classes, log=self.log, subcommands=self.subcommands
                                               ^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/traitlets/traitlets.py", line 687, in __get__
    return t.cast(G, self.get(obj, cls))  # the G should encode the Optional
                     ^^^^^^^^^^^^^^^^^^
  File "/usr/local/lib/python3.12/site-packages/traitlets/traitlets.py", line 653, in get
    obj._notify_observers(
  File "/usr/local/lib/python3.12/site-packages/traitlets/traitlets.py", line 1568, in _notify_observers
    c(event)
  File "/usr/local/lib/python3.12/site-packages/traitlets/config/application.py", line 287, in _observe_logging_default
    self._configure_logging()
  File "/usr/local/lib/python3.12/site-packages/traitlets/config/application.py", line 292, in _configure_logging
    dictConfig(config)
  File "/usr/local/lib/python3.12/logging/config.py", line 914, in dictConfig
    dictConfigClass(config).configure()
  File "/usr/local/lib/python3.12/logging/config.py", line 554, in configure
    _clearExistingHandlers()
  File "/usr/local/lib/python3.12/logging/config.py", line 293, in _clearExistingHandlers
    logging.shutdown(logging._handlerList[:])
  File "/usr/local/lib/python3.12/logging/__init__.py", line 2272, in shutdown
    h.close()
  File "/usr/local/lib/python3.12/site-packages/testfixtures/logcapture.py", line 304, in close
    raise AssertionError(
AssertionError: LogCapture instance closed while still installed, loggers captured:
(None,)

There was no problem before. If this is not the right way to use it, please feel free to tell!

Best regards.

[asqui]

I saw this recently too, while debugging a test that was using LogCapture and setting a breakpoint in PyCharm within the scope of the LogCapture.

I didn't have a chance to dig into what was going on and just commented-out the LogCapture temporarily, but this stack trace looks the same as what I saw.

[cjw296]

@bromatofiel - ipdb (well, traitlets, by the look of it) doing a logging.shutdown by way of configuring its own logging at the point set_trace is called is a pretty challenging choice.

@asqui - what's the traceback for the situation you encountered? What's PyCharm using under the hood?

[cjw296]

@asqui - can you remember the reason for this commit? I have a feeling it was related to a gotcha in the codebase you're working on, but it's not recorded in an issue or commit message here :-/

[bromatofiel]

@cjw296 I don't know why ipdb does that 😅 (it seems that traitlets is also in ipython project). When looking at the project history, this behavior was coded the 11/04/2022 in response to this issue : ipython/traitlets#688

It doesn't explain why they reconfigure the loggers during runtime, but it seems it has something to do with changing the existing logger levels.

[asqui]

My traceback is materially the same: pydev -> IPython -> traitlets > logging.dictConfig -> LogCapture.close

I suspect the motivation for the change in 2686329 (to fail loudly if the LogCapture is closed while installed) was a result of confusion over code-under-test which ended up resetting logging configuration, quietly orphaning the LogCapture handler, and leaving us wondering why logging wasn't being captured.

For that scenario "fail loudly" seems desirable, but for the "IPython in the debugger" scenario, not so much 😢

[cjw296]

It feels like the pragmatic thing to do here is to change this exception to be a warning. That way, you'll hopefully see the warning when debugging, and so know that the debugger has trashed your log capturing, but will be able to continue.

If suitably paranoid, CI runs could be configured to turn this warning into an exception.

Do you both agree with this course of action?

[asqui]

Seems reasonable.

I’m slightly worried that the exception might go unseen, but I don’t have any better suggestions.

[cjw296]

If you have a warning filter turn this warning into an exception, it'll blow up in exactly the same way it does with the current code, I think?