warnings raised by test_peg_generator when setuptools_scm is installed

[kulikjak]

Bug report

Bug description:

Hi, since #131802, we see test_peg_generator failing with the following warning:

Warning -- logging._handlerList was modified by test_peg_generator
Warning --   Before: (140617884985088, [<weakref at 0x7fe4271c8720; to 'logging._StderrHandler' at 0x7fe427ceb620>, <weakref at 0x7fe421d4d350; to 'setuptools_scm._log.AlwaysStdErrHandler' at 0x7fe420b25fd0>], [<weakref at 0x7fe4271c8720; to 'logging._StderrHandler' at 0x7fe427ceb620>])
Warning --   After:  (140617884985088, [<weakref at 0x7fe4271c8720; to 'logging._StderrHandler' at 0x7fe427ceb620>, <weakref at 0x7fe421d4d350; to 'setuptools_scm._log.AlwaysStdErrHandler' at 0x7fe420b25fd0>], [<weakref at 0x7fe4271c8720; to 'logging._StderrHandler' at 0x7fe427ceb620>, <weakref at 0x7fe421d4d350; to 'setuptools_scm._log.AlwaysStdErrHandler' at 0x7fe420b25fd0>])

For some reason, during the execution, second reference to the same 'setuptools_scm._log.AlwaysStdErrHandler' appears in the _handlerList.

When I remove setuptools_scm, the issue is gone.

Interestingly (at least to me), when I revert changes done in #131802 in lib/test/support/__init__.py and os_helper.py (commenting out import logging is enough), the issue is gone as well, so it seems like some weird side effect of the import?

I tried to track the issue and got through setuptools all the way to ep.load() in finalize_options() which triggers the issue (see trace below).

I added some debug prints to _addHandlerRef function, and it's apparently called only once with this handler. Though I also see a single call for the logging._StderrHandler' and it's there twice as well, so I am probably overlooking something...

Here is the trace from when the handler ref is being added during the test execution:

.....
  File "/build/cpython-3.13/Lib/test/test_peg_generator/test_c_parser.py", line 131, in build_extension
    generate_parser_c_extension(grammar, Path('.'), library_dir=self.library_dir)
  File "/build/cpython-3.13/Tools/peg_generator/pegen/testutil.py", line 107, in generate_parser_c_extension
    compile_c_extension(
  File "/build/cpython-3.13/Tools/peg_generator/pegen/build.py", line 160, in compile_c_extension
    dist = Distribution({"name": extension_name, "ext_modules": [extension]})
  File "/usr/lib/python3.13/vendor-packages/setuptools/dist.py", line 323, in __init__
    _Distribution.__init__(self, dist_attrs)
  File "/usr/lib/python3.13/vendor-packages/setuptools/_distutils/dist.py", line 309, in __init__
    self.finalize_options()
  File "/usr/lib/python3.13/vendor-packages/setuptools/dist.py", line 787, in finalize_options
    for ep in sorted(loaded, key=by_order):
  File "/usr/lib/python3.13/vendor-packages/setuptools/dist.py", line 786, in <lambda>
    loaded = map(lambda e: e.load(), filtered)
  File "/build/cpython-3.13/Lib/importlib/metadata/__init__.py", line 179, in load
    module = import_module(match.group('module'))
  File "/build/cpython-3.13/Lib/importlib/__init__.py", line 88, in import_module
    return _bootstrap._gcd_import(name[level:], package, level)
  File "<frozen importlib._bootstrap>", line 1387, in _gcd_import
  File "<frozen importlib._bootstrap>", line 1360, in _find_and_load
  File "<frozen importlib._bootstrap>", line 1310, in _find_and_load_unlocked
  File "<frozen importlib._bootstrap>", line 488, in _call_with_frames_removed
  File "<frozen importlib._bootstrap>", line 1387, in _gcd_import
  File "<frozen importlib._bootstrap>", line 1360, in _find_and_load
  File "<frozen importlib._bootstrap>", line 1310, in _find_and_load_unlocked
  File "<frozen importlib._bootstrap>", line 488, in _call_with_frames_removed
  File "<frozen importlib._bootstrap>", line 1387, in _gcd_import
  File "<frozen importlib._bootstrap>", line 1360, in _find_and_load
  File "<frozen importlib._bootstrap>", line 1331, in _find_and_load_unlocked
  File "<frozen importlib._bootstrap>", line 935, in _load_unlocked
  File "<frozen importlib._bootstrap_external>", line 1026, in exec_module
  File "<frozen importlib._bootstrap>", line 488, in _call_with_frames_removed
  File "/usr/lib/python3.13/vendor-packages/setuptools_scm/__init__.py", line 8, in <module>
    from ._config import DEFAULT_LOCAL_SCHEME
  File "<frozen importlib._bootstrap>", line 1360, in _find_and_load
  File "<frozen importlib._bootstrap>", line 1331, in _find_and_load_unlocked
  File "<frozen importlib._bootstrap>", line 935, in _load_unlocked
  File "<frozen importlib._bootstrap_external>", line 1026, in exec_module
  File "<frozen importlib._bootstrap>", line 488, in _call_with_frames_removed
  File "/usr/lib/python3.13/vendor-packages/setuptools_scm/_config.py", line 15, in <module>
    from . import _log
  File "<frozen importlib._bootstrap>", line 1415, in _handle_fromlist
  File "<frozen importlib._bootstrap>", line 488, in _call_with_frames_removed
  File "<frozen importlib._bootstrap>", line 1360, in _find_and_load
  File "<frozen importlib._bootstrap>", line 1331, in _find_and_load_unlocked
  File "<frozen importlib._bootstrap>", line 935, in _load_unlocked
  File "<frozen importlib._bootstrap_external>", line 1026, in exec_module
  File "<frozen importlib._bootstrap>", line 488, in _call_with_frames_removed
  File "/usr/lib/python3.13/vendor-packages/setuptools_scm/_log.py", line 48, in <module>
    _default_handler = make_default_handler()
  File "/usr/lib/python3.13/vendor-packages/setuptools_scm/_log.py", line 43, in make_default_handler
    handler = AlwaysStdErrHandler()
  File "/usr/lib/python3.13/vendor-packages/setuptools_scm/_log.py", line 23, in __init__
    super().__init__(sys.stderr)
  File "/build/cpython-3.13/Lib/logging/__init__.py", line 1128, in __init__
    Handler.__init__(self)
  File "/build/cpython-3.13/Lib/logging/__init__.py", line 941, in __init__
    _addHandlerRef(self)

All this is with Python 3.13 (latest changes), setuptools 80.3.1, setuptools_scm 8.3.1, and on Oracle Solaris, but I don't think this is necessarily platform dependent.

I also reproduced this with older setuptools 73.0.1 and setuptools_scm 8.1.0.

CPython versions tested on:

3.13

Operating systems tested on:

Other

[kulikjak]

I just reproduced this with latest main, with just setuptools 80.3.1 and setuptools_scm 8.3.1 available in site-packages.

[ZeroIntensity]

The test is failing because the test suite doesn't like it when logging handlers are added by tests, which setuptools_scm is seemingly doing. Doing so causes a warning, which causes tests to fail since #131802, so I don't think this is actually a new issue. I don't think there's much we can do if setuptools_scm automatically adds some logging handlers.

[kulikjak]

I don't think that #131802 just uncovered something that was always the case.

As I mentioned above, when I remove logging imports from lib/test/support/__init__.py and os_helper.py (added in that change), the issue is gone. And when I turn warnings into errors in older 3.13.1 (with python_opts.extend(('-W', 'error'))), there is no environment change warning - only when I add import logging to lib/test/support/__init__.py, it appears.

That seems like there's more going on than just setuptools_scm adding a new logging handler.

Also, it doesn't really explain (at least to me) how does the same exact handler (it's the same weakref to the same handler) appear for the second time in the _handlerList.

[ZeroIntensity]

And when I turn warnings into errors in older 3.13.1 (with python_opts.extend(('-W', 'error'))),

To be clear--I don't think there's a bug, on our end or on setuptools_scm. The tests just don't like it when state changes between tests. You can see something similar if you change an environment variable in a test. It's not a bug to set an environment variable, but it fails under our test suite.

It's not immediately obvious why removing import logging "fixes" it, but I don't think it matters much. If you can find an easy fix, then go for it! But otherwise, I don't think tracking this down is worthwhile.

[kulikjak]

Well, the main issue I am trying to solve is that the test suite is failing. I can live with the warning, but we'd really like to have the test suite pass, and there doesn't seem to be a simple way to ignore this warning-turned-to-error.

BTW, I just reproduced this on Fedora with 3.13.3 as well, so it's not a platform diff.

I will ask in setuptools_scm issues; maybe somebody will have some more insight there.

[zware]

In general, running the tests with third-party packages installed is not a supported (or supportable) configuration. There's no limit to what such packages can change.

[ZeroIntensity]

I can live with the warning, but we'd really like to have the test suite pass

The whole point is that warnings won't freely pass in tests anymore, hopefully catching bugs.

What's the use case here, anyway? I can't think of many reasons why you'd need to run the CPython test suite with packages installed.

[kulikjak]

In general, running the tests with third-party packages installed is not a supported (or support_able_) configuration. There's no limit to what such packages can change.

That makes sense. But it would still be nice if it worked with at least a subset of packages known to be installed on machine used to build python stuff ;).

The whole point is that warnings won't freely pass in tests anymore, hopefully catching bugs.

I understand that, but as you mentioned above, this is likely not a bug. And there doesn't seem to be a way to suppress the warning for test_peg_generator specifically (I don't want to run whole test suite with warning disabled as they are otherwise useful).

What's the use case here, anyway? I can't think of many reasons why you'd need to run the CPython test suite with packages installed.

That's the way we are building all packages for Oracle Solaris (and I wouldn't be surprised if we were alone in this). The build machine contains everything that is necessary to build the whole Userland, and since setuptools_scm is necessary to build many other things, Python tests find it.

I tried running tests isolated from the machine with TESTPYTHONOPTS=-S and that fixed this issue, but that unfortunately skips test_site, which seems like a nice test to run, so not ideal.

Maybe the simplest thing is to skip the pegen tests... Or would you have another suggestion on how to handle this? Being able to ignore the warning for this specific test would be nice, though I don't think there is a nice place to put a warning filter into.

[RonnyPfannschmidt]

Im happy to adjust how setuptools_scm creates its handlers

[ZeroIntensity]

AFAICS, the problem is that it initializes handlers in a pth file, which the test suite notices. An easy fix would be to put that behavior behind an environment variable (e.g., SETUPTOOLS_SCM_NO_PTH).