catch_warnings context manager causes all warnings to be printed every time, even after exiting

[gerritholl]

BPO	29672
Nosy	@pitrou, @gerritholl, @embray, @serhiy-storchaka, @segevfiner
PRs	[WIP] bpo-29672: Save and restore module warning registries in catch_warnings #8232

^{Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.}

Show more details

GitHub fields:

assignee = None
closed_at = None
created_at = <Date 2017-02-27.22:29:56.490>
labels = ['type-bug', 'library']
title = '`catch_warnings` context manager causes all warnings to be printed every time, even after exiting'
updated_at = <Date 2021-04-02.21:55:37.433>
user = 'https://github.com/gerritholl'

bugs.python.org fields:

activity = <Date 2021-04-02.21:55:37.433>
actor = 'taldcroft'
assignee = 'none'
closed = False
closed_date = None
closer = None
components = ['Library (Lib)']
creation = <Date 2017-02-27.22:29:56.490>
creator = 'Gerrit.Holl'
dependencies = []
files = []
hgrepos = []
issue_num = 29672
keywords = ['patch']
message_count = 10.0
messages = ['288677', '288678', '288680', '288709', '298588', '298822', '320662', '321380', '321393', '390103']
nosy_count = 6.0
nosy_names = ['pitrou', 'Gerrit.Holl', 'erik.bray', 'serhiy.storchaka', 'Segev Finer', 'taldcroft']
pr_nums = ['8232']
priority = 'normal'
resolution = None
stage = 'patch review'
status = 'open'
superseder = None
type = 'behavior'
url = 'https://bugs.python.org/issue29672'
versions = []

[gerritholl]

Entering the catch_warnings context manager is causing warnings to be printed over and over again, rather than just once as it should. Without such a context manager, the behaviour is as expected:

    $ cat ./mwe.py 
    #!/usr/bin/env python3.5
    
    import warnings
    
    for i in range(3):
        try:
            print(i, __warningregistry__)
        except NameError:
            print(i, "first warning")
        warnings.warn("I don't like this.", UserWarning)
        print(i, __warningregistry__)
    #    with warnings.catch_warnings():
    #        pass
        print(i, __warningregistry__)
        warnings.warn("I don't like this.", UserWarning)
    $ ./mwe.py 
    0 first warning
    ./mwe.py:10: UserWarning: I don't like this.
      warnings.warn("I don't like this.", UserWarning)
    0 {'version': 0, ("I don't like this.", <class 'UserWarning'>, 10): True}
    0 {'version': 0, ("I don't like this.", <class 'UserWarning'>, 10): True}
    ./mwe.py:15: UserWarning: I don't like this.
      warnings.warn("I don't like this.", UserWarning)
    1 {'version': 0, ("I don't like this.", <class 'UserWarning'>, 15): True, ("I don't like this.", <class 'UserWarning'>, 10): True}
    1 {'version': 0, ("I don't like this.", <class 'UserWarning'>, 15): True, ("I don't like this.", <class 'UserWarning'>, 10): True}
    1 {'version': 0, ("I don't like this.", <class 'UserWarning'>, 15): True, ("I don't like this.", <class 'UserWarning'>, 10): True}
    2 {'version': 0, ("I don't like this.", <class 'UserWarning'>, 15): True, ("I don't like this.", <class 'UserWarning'>, 10): True}
    2 {'version': 0, ("I don't like this.", <class 'UserWarning'>, 15): True, ("I don't like this.", <class 'UserWarning'>, 10): True}
    2 {'version': 0, ("I don't like this.", <class 'UserWarning'>, 15): True, ("I don't like this.", <class 'UserWarning'>, 10): True}

Uncommenting the context manager causes the warning to be printed every time:

    $ ./mwe.py 
    0 first warning
    ./mwe.py:10: UserWarning: I don't like this.
      warnings.warn("I don't like this.", UserWarning)
    0 {'version': 0, ("I don't like this.", <class 'UserWarning'>, 10): True}
    0 {'version': 0, ("I don't like this.", <class 'UserWarning'>, 10): True}
    ./mwe.py:15: UserWarning: I don't like this.
      warnings.warn("I don't like this.", UserWarning)
    1 {'version': 2, ("I don't like this.", <class 'UserWarning'>, 15): True}
    ./mwe.py:10: UserWarning: I don't like this.
      warnings.warn("I don't like this.", UserWarning)
    1 {'version': 2, ("I don't like this.", <class 'UserWarning'>, 15): True, ("I don't like this.", <class 'UserWarning'>, 10): True}
    1 {'version': 2, ("I don't like this.", <class 'UserWarning'>, 15): True, ("I don't like this.", <class 'UserWarning'>, 10): True}
    ./mwe.py:15: UserWarning: I don't like this.
      warnings.warn("I don't like this.", UserWarning)
    2 {'version': 4, ("I don't like this.", <class 'UserWarning'>, 15): True}
    ./mwe.py:10: UserWarning: I don't like this.
      warnings.warn("I don't like this.", UserWarning)
    2 {'version': 4, ("I don't like this.", <class 'UserWarning'>, 15): True, ("I don't like this.", <class 'UserWarning'>, 10): True}
    2 {'version': 4, ("I don't like this.", <class 'UserWarning'>, 15): True, ("I don't like this.", <class 'UserWarning'>, 10): True}
    ./mwe.py:15: UserWarning: I don't like this.
      warnings.warn("I don't like this.", UserWarning)

I think this is undesirable. There is code deep inside a module that I'm using that is using the context manager, and as a consequence, I get warnings printed every time that should be printed only once.

See also on Stack Overflow: http://stackoverflow.com/q/42496579/974555

[gerritholl]

I suppose this is a consequence of the change in:

http://bugs.python.org/issue4180

and although I can see why the warnings filter would be reset when entering the context manager, I don't think it is desirable to have side effects for modules that are entirely unrelated.

[gerritholl]

To clarify, this behaviour crosses module boundaries. So even if some piece of code many layers deep buried in a module uses this context manager, it has global consequences.

[gerritholl]

To resolve this, the catch_warnings context manager upon exiting should not only reset filters, but also _filters_version, and perhaps an associated dictionary? Not sure if I'm understanding the code in warnings.c correctly, and whether, for this change, it would suffice to change warnings.py or whether warnings.c would need to be updated as well.

[gerritholl]

I get bitten by this frequently, and find myself patching many libraries just to avoid them from calling .catch_warnings.

Does anyone know whether to fix this it would suffice to edit warnings.py, or would I need to dig into _warnings.c as well?

[segevfiner]

I think you will need to save and restore _filters_version and _onceregistry. Since _filters_version is a static variable in _warnings.c you will probably also have to modify it somehow to make it accessible to warnings.py.

[embray]

I just encountered this as well. The way catch_warnings is implemented is a bit "dumb" in how it treats _filter_version (it calls _filters_mutated even if the active filters are not actually changed when entering catch_warnings).

More significantly, _filter_version is not fine-grained enough. If some warning was already displayed, calling catch_warnings() should not later cause that same warning to be displayed again unless the filters were modified in such a way, during catch_warnings(), that that warning should be displayed (e.g. changed to 'always').

I'm not really sure what to do about that though. Maybe the "filter version" should be per-warning? Currently the value assigned to each warning in __warningregistry__ is not used (it is just set to True), so maybe that could actually be used for this.

[segevfiner]

Hmm, I originally missed the per module __warningregistry__... Need to read the code more closely...

What should the behavior be? We can add a flag that will make all warning actions be "always" when catch_warnings is in effect. But that doesn't feel right with the way catch_warnings currently behaves or what is expected of it.

Another idea would be to add a callback that is called whenever we set a module registry, allowing catch_warnings to backup the original registry of each module and restore them all on exit (Also the _onceregistry and _filters_version).

[embray]

Yes, I think catch_warnings should back up and restore the relevant __warningregistry__. At which point it's not even clear to me what value there is in the _filter_version...

[taldcroft]

I encountered this issue today and want to +1 getting some attention on this.

The disconnected nature of this issue makes it especially difficult to understand -- any package in the stack can change this hidden global variable _filters_version in the warnings module that then impacts the local behavior of warnings in the user script.

The only way I was able to finally understand that an update to an obscure dependency was breaking our regression testing was by reading the warnings source code and then monkey patching it to print diagnostic information.

Even a documentation update would be useful. This could explain not only catch_warnings(), but in general the unexpected feature that if any package anywhere in the stack sets a warning filter, then that globally resets whether a warning has been seen before (via the call to _filters_mutated()).

[kurtamohler]

I've encountered this issue as well. PyTorch's unit tests generate duplicated warnings because of it. Not sure if this helps at all, but here's a more minimal reproduction script:

Click to see script

import warnings
for _ in range(3):
    with warnings.catch_warnings():
        pass
    warnings.warn('warning')

Output:

/home/endoplasm/tmp/tmp.py:5: UserWarning: warning
  warnings.warn('warning')
/home/endoplasm/tmp/tmp.py:5: UserWarning: warning
  warnings.warn('warning')
/home/endoplasm/tmp/tmp.py:5: UserWarning: warning
  warnings.warn('warning')

And here's an idea of how to make a workaround for it. I haven't tried using it in practice yet though

Click to see script

import warnings

class my_catch_warnings(warnings.catch_warnings):

    def __enter__(self):
        global __warningregistry__
        try:
            self._saved_registry = __warningregistry__.copy()
        except NameError:
            self._saved_registry = None

        super().__enter__()

    def __exit__(self, *args, **kwargs):
        super().__exit__(*args, **kwargs)

        if self._saved_registry is not None:
            global __warningregistry__
            dummy_message = 'dummy warning to find out warning registry version number'
            warnings.filterwarnings('ignore', message=dummy_message)
            warnings.warn(dummy_message)
            self._saved_registry['version'] = __warningregistry__['version']
            __warningregistry__ = self._saved_registry

for i in range(3):
    with my_catch_warnings():
        warnings.warn('inside catch_warnings')

    warnings.warn('this should only emit once')
    warnings.warn(RuntimeWarning('and this should only emit once too'))

Output:

/home/endoplasm/develop/python_stuff/catch_warnings_workaround.py:27: UserWarning: inside catch_warnings
  warnings.warn('inside catch_warnings')
/home/endoplasm/develop/python_stuff/catch_warnings_workaround.py:29: UserWarning: this should only emit once
  warnings.warn('this should only emit once')
/home/endoplasm/develop/python_stuff/catch_warnings_workaround.py:30: RuntimeWarning: and this should only emit once too
  warnings.warn(RuntimeWarning('and this should only emit once too'))
/home/endoplasm/develop/python_stuff/catch_warnings_workaround.py:27: UserWarning: inside catch_warnings
  warnings.warn('inside catch_warnings')
/home/endoplasm/develop/python_stuff/catch_warnings_workaround.py:27: UserWarning: inside catch_warnings
  warnings.warn('inside catch_warnings')

[eliegoudout]

I'm also interested in this issue. I think a good start would be to update the doc, because current behaviour is not as expected.

[stev-0]

I think this is biting me for Pandas - where I get millions of notifications and the logging goes to a DB, so it massively slows down: https://stackoverflow.com/questions/75029437/pandas-get-single-warning-message-per-line.

[karlicoss]

This is particularly annoying considering catch_warnings is used in some builtin modules, e.g.

cpython/Lib/os.py

Line 636 in ea77520

with warnings.catch_warnings():

So for every time you call stuff from subprocess like Popen or check_output, it results in duplicate warnings

Leaving it here cause took me a while to debug this, so hopefully it helps other people too!