classification
Title: test_warnings modifies warnings.filters when running with "-W default"
Type: behavior Stage: resolved
Components: Tests Versions: Python 3.6, Python 3.5
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: berker.peksag Nosy List: ashkop, berker.peksag, ezio.melotti, flox, martin.panter, python-dev, rbcollins, serhiy.storchaka, vstinner
Priority: low Keywords: patch

Created on 2013-07-06 13:36 by flox, last changed 2016-11-21 15:39 by python-dev. This issue is now closed.

Files
File name Uploaded Description Edit
issue18383_test_warnings_filters.diff flox, 2013-07-06 14:17 review
issue18383_remove_dups.patch ashkop, 2015-03-02 15:24 review
issue18383_remove_dups_and_test.patch ashkop, 2015-04-06 10:24 review
issue18383_assert_warns_and_dups.patch ashkop, 2015-04-09 13:34 review
issue18383_assert_warns_and_dups_v2.patch ashkop, 2015-04-14 06:13 review
issue18383_34.diff berker.peksag, 2015-07-31 01:02
issue18383_34_2.diff ashkop, 2015-08-14 06:47 review
issue18383_avoid_dups_3.diff martin.panter, 2016-05-22 04:46 review
issue18383_avoid_dups_4.diff martin.panter, 2016-05-26 00:18 review
Messages (34)
msg192441 - (view) Author: Florent Xicluna (flox) * (Python committer) Date: 2013-07-06 13:36
Running the test suite with -Wd, we got the warning:

[247/375] test_warnings
Warning -- warnings.filters was modified by test_warnings



This is how to reproduce:

./python -Wd

import warnings
from test import support

saved = warnings.filters.copy()

c_warnings = support.import_fresh_module('warnings', fresh=['_warnings'])

saved == warnings.filters
# --> False
msg192442 - (view) Author: Florent Xicluna (flox) * (Python committer) Date: 2013-07-06 13:56
Much simpler:

$ ./python -Wd

import warnings
import sys
saved = warnings.filters.copy()

del sys.modules['warnings']
import warnings

assert warnings.filters != saved
assert warnings.filters.pop(0) = warnings.filters[0]
assert warnings.filters == saved

Explanation: the "default" filter is duplicated on each reload of the warnings module.
msg192443 - (view) Author: Florent Xicluna (flox) * (Python committer) Date: 2013-07-06 14:17
This patch fixes the issue.
msg194567 - (view) Author: Ezio Melotti (ezio.melotti) * (Python committer) Date: 2013-08-06 16:58
LGTM
msg232451 - (view) Author: Serhiy Storchaka (serhiy.storchaka) * (Python committer) Date: 2014-12-10 22:55
The patch fixes symptoms. It would be better to fix the cause of the issue -- warnings.filters shouldn't duplicate after module reloading.
msg237050 - (view) Author: Alex Shkop (ashkop) * Date: 2015-03-02 15:24
The issue occurs only if C implementation of _warnings is available. It is caused by re-use of global filters variable from _warnings when warnings is being re-imported.
So warnings modifies _warnings.filters on first import. Then, when you import warnings again it uses already modified version of _warnings.filters and adds same filter for the second time.

I attach a simple patch that prevents duplicates in filters. I'm not sure if this is a best way to fix the problem, but it works. It certainly affects performance of filterwarnings(), but there shouldn't be a lot of filters anyway.

Making filters a set() will solve the problem also, but will require API changes. Although I didn't find anywhere in documentation that warnings.filters should be a list, someone might rely on its .append() method.
msg240055 - (view) Author: Berker Peksag (berker.peksag) * (Python committer) Date: 2015-04-04 09:42
issue18383_remove_dups.patch looks good to me. A test would be nice.
msg240147 - (view) Author: Alex Shkop (ashkop) * Date: 2015-04-06 10:24
When caller adds duplicate filter maybe we should promote his filter to the beginning of filters list? This feels more correct to me. So if user adds duplicate filter everything will work as if we added it.
msg240314 - (view) Author: Martin Panter (martin.panter) * (Python committer) Date: 2015-04-09 09:22
I tried issue18383_remove_dups_and_test.patch, but it doesn’t seem to fix the problem, and causes new test failures and warnings. Let me know if you want more info. Existing messages that I thought this was meant to fix:

[372/393/5] test_warnings
/media/disk/home/proj/python/cpython/Lib/test/test_warnings.py:100: UserWarning: FilterTests.test_ignore_after_default
  self.module.warn(message, UserWarning)
/media/disk/home/proj/python/cpython/Lib/test/test_warnings.py:100: UserWarning: FilterTests.test_ignore_after_default
  self.module.warn(message, UserWarning)
Warning -- warnings.filters was modified by test_warnings
[. . .]
1 test altered the execution environment:
    test_warnings

Three new failures:

[ 12/393/1] test___all__
test test___all__ failed -- Traceback (most recent call last):
  File "/media/disk/home/proj/python/cpython/Lib/test/test___all__.py", line 105, in test_all
    self.check_all(modname)
  File "/media/disk/home/proj/python/cpython/Lib/test/test___all__.py", line 28, in check_all
    raise FailedImport(modname)
  File "/media/disk/home/proj/python/cpython/Lib/contextlib.py", line 66, in __exit__
    next(self.gen)
  File "/media/disk/home/proj/python/cpython/Lib/test/support/__init__.py", line 1124, in _filterwarnings
    raise AssertionError("unhandled warning %s" % reraise[0])
AssertionError: unhandled warning {message : DeprecationWarning('stat_float_times() is deprecated',), category : 'DeprecationWarning', filename : '/media/disk/home/proj/python/cpython/Lib/test/test_os.py', lineno : 75, line : None}
[. . .]
[147/393/3] test_global
test test_global failed -- multiple errors occurred; run in verbose mode for details
[. . .]
[240/393/5] test_pkgutil
test test_pkgutil failed -- Traceback (most recent call last):
  File "/media/disk/home/proj/python/cpython/Lib/test/test_pkgutil.py", line 327, in test_importer_deprecated
    x = pkgutil.ImpImporter("")
  File "/media/disk/home/proj/python/cpython/Lib/contextlib.py", line 66, in __exit__
    next(self.gen)
  File "/media/disk/home/proj/python/cpython/Lib/test/support/__init__.py", line 1124, in _filterwarnings
    raise AssertionError("unhandled warning %s" % reraise[0])
AssertionError: unhandled warning {message : PendingDeprecationWarning("the imp module is deprecated in favour of importlib; see the module's documentation for alternative uses",), category : 'PendingDeprecationWarning', filename : '/media/disk/home/proj/python/cpython/Lib/importlib/_bootstrap.py', lineno : 321, line : None}
[. . .]
5 tests failed:
    test___all__ test_distutils test_gdb test_global test_pkgutil

(Ignore distutils and GDB; they normally fail for me.) New warnings, though I suspect they may be a side effect and not entirely the fault of the patch:

[ 18/393/1] test_unittest
[163/393/4] test_imp
[169/393/4] test_importlib
[205/393/4] test_modulefinder
[220/393/4] test_os
[241/393/5] test_platform
[329/393/5] test_threaded_import
[354/393/5] test_unicode
msg240324 - (view) Author: Alex Shkop (ashkop) * Date: 2015-04-09 13:34
So, there are actually two issues, both of them causing the original warning. 

First issue was pointed out by Florent Xicluna. warnings.filterwarnings() method can create duplicates in warnings.filters.

Second issue is that assertWarns() works incorrectly in test_warnings.py due to use of import_fresh_module(). This produced original warning even without -Wd flag.

I attached a patch that fixes both issues for review. It includes a fix of previous patch, so no new warnings are produced. But perhaps we should separate these issues and create two patches.
msg240523 - (view) Author: Martin Panter (martin.panter) * (Python committer) Date: 2015-04-12 02:38
issue18383_assert_warns_and_dups.patch fixes all my new test suite complaints, and removes the message about altering warnings.filters.
msg240846 - (view) Author: Alex Shkop (ashkop) * Date: 2015-04-14 06:13
Removed unnecessary assertWarns() contexts and fixed spelling errors.
msg242171 - (view) Author: Alex Shkop (ashkop) * Date: 2015-04-28 09:55
*ping*
msg242966 - (view) Author: Alex Shkop (ashkop) * Date: 2015-05-12 12:55
Please, review the patch.
msg245454 - (view) Author: Martin Panter (martin.panter) * (Python committer) Date: 2015-06-18 06:31
FWIW there is a new message currently being triggered by test___all__. The patch here also stops this message.

$ hg update 4335d898be59
$ ./python -bWall -m test test___all__
[1/1] test___all__
Warning -- warnings.filters was modified by test___all__
1 test altered the execution environment:
    test___all__
msg247719 - (view) Author: Berker Peksag (berker.peksag) * (Python committer) Date: 2015-07-31 01:02
Here is an updated patch (against 3.4 branch). I've just made some small cosmetic changes and split the test into two parts (filterwarnings and simplefilter). Patch looks reasonable to me, but it would be nice to get a second opinion.
msg247737 - (view) Author: Alex Shkop (ashkop) * Date: 2015-07-31 06:13
Looking at this patch again, I'm wondering if it is correct to remove duplicate filter if append=True. Perhaps in this case it is more correct to leave the filter in place and do not append new one?
msg248479 - (view) Author: Robert Collins (rbcollins) * (Python committer) Date: 2015-08-12 22:01
@ashkop so append=True could be clearer as 'atend=True' - both forms of call are expected to add the filter, but one adds to the front, one to the end.

Looking at warn_explicit, its takes the first matching filter, and then acts on its action.

So the following:
simplefilter("ignore")
simplefilter("error", append=True)
simplefilter("ignore", append=True)

will ignore all warnings today.

With this patch it will error on all warnings.

So at *best* I think this is a breaking API change.

Old:
>>> from warnings import simplefilter, warn
>>> simplefilter("ignore")
>>> simplefilter("error", append=True)
>>> simplefilter("ignore", append=True)
>>> warn("boo")
>>> 

With this patch:
>>> from warnings import simplefilter, warn
>>> simplefilter("ignore")
>>> simplefilter("error", append=True)
>>> simplefilter("ignore", append=True)
>>> warn("boo")
Traceback (most recent call last):
  File "<stdin>", line 1, in <module>
UserWarning: boo
>>> 

Now, perhaps its desirable to make this change. I haven't decided yet about the tastefulness of the new API, but if we do we're going to need docstring updates, and API doc changes to match it.

Since the goal here is to fix module reloads, I think the right way to do that is to only change the module initialisation code.

e.g. add an optional 'no_duplicate' parameter to simplefilter and use that from the module initialisation. Thats backwards compatible and opt-in. If we don't think it should be public, make it a _ prefixed parameter. I think it would be fine to be public though.
msg248499 - (view) Author: Alex Shkop (ashkop) * Date: 2015-08-13 06:11
@rbcollins that is exactly what was trying to say in previous comment. We can make a change to current patch that won't affect behavior. In old API in this sequence of filters last filter was never used:

simplefilter("ignore")
simplefilter("error", append=True)
simplefilter("ignore", append=True)  # never used

So I suggest that new patch should work like this:


simplefilter("error")
simplefilter("ignore", append=True)  # appends new filter to the end

simplefilter("ignore")
simplefilter("error", append=True)
simplefilter("ignore", append=True)  # does nothing since same filter is present.

This way filtering will work in the same way it worked before patch and we won't have duplicates.

I'll update the patch as soon as I will get to my computer.
msg248559 - (view) Author: Alex Shkop (ashkop) * Date: 2015-08-14 06:47
This is updated patch that doesn't alter warn_explicit behavior.

So the following:
simplefilter("ignore")
simplefilter("error", append=True)
simplefilter("ignore", append=True)

will ignore all warnings with this patch and no duplicates are inserted to warnings.filters. Also added a test for that case.
msg249179 - (view) Author: Martin Panter (martin.panter) * (Python committer) Date: 2015-08-26 04:25
Florent’s manual reproducer is fixed by issue18383_34_2.diff, as is test___all__. And I think the new logic for changing the priority of the filter entries might be sound now. But it does seem like we are adding unnecessary complexity to the implementation just to avoid a quirk of the test suite. Maybe it would be better to save and restore the original filters in the test suite, with a comment explaining why. Or perhaps set a _warnings._options_processed flag to prevent the double initialization?

FTR Alex already hinted at this, but I only now realize issue18383_assert_warns_and_dups_v2.patch contains extra fixes for assertWarns() that are only applicable to 3.5+. They are basically a followup of Issue 16382 and Issue 23027, rather than the original issue here, although the symptom is almost the same.
msg249581 - (view) Author: Martin Panter (martin.panter) * (Python committer) Date: 2015-09-02 22:55
Revision c1396d28c440 looks like it may help. Possibly with the 3.5+ assertWarns() half of the problem; I’ll have to have a closer look later.
msg249583 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2015-09-02 23:34
> Revision c1396d28c440 looks like it may help. Possibly with the 3.5+ assertWarns() half of the problem; I’ll have to have a closer look later.

Oh, I wasn't aware of this issue. Good to know that I contributed to it :-)
msg249599 - (view) Author: Martin Panter (martin.panter) * (Python committer) Date: 2015-09-03 03:22
Okay so I take back my first proposal of restoring the filters in the test suite, which would bring us back to <https://bugs.python.org/issue18383#msg232451>.

Also, my second proposal of setting a flag doesn’t look so easy either. The “_warnings” C module caches the filters list in a static variable between module reloads, so it is not so easy to keep a flag recording whether the “warnings” Python module needs to initialize it. I started on a patch, but discovered I would have to make uncomfortable changes to the C module.

So unless anyone has any better ideas, I think Alex’s patch is as good and practical enough. And yes Victor’s change does fix the other half of the problem.
msg266047 - (view) Author: Martin Panter (martin.panter) * (Python committer) Date: 2016-05-22 04:41
I am inclined to go with Alex’s patch. I am uploading a new version of it, issue18383_avoid_dups_3.diff, which resolves conflicts with recent changes.
msg266049 - (view) Author: Martin Panter (martin.panter) * (Python committer) Date: 2016-05-22 04:46
Forgot to refresh my patch
msg266076 - (view) Author: Berker Peksag (berker.peksag) * (Python committer) Date: 2016-05-22 13:10
LGTM
msg266087 - (view) Author: Serhiy Storchaka (serhiy.storchaka) * (Python committer) Date: 2016-05-22 16:17
$ ./python -We::UserWarning -m test.regrtest test_warnings
Run tests sequentially
0:00:00 [1/1] test_warnings
/home/serhiy/py/cpython/Lib/test/test_warnings/__init__.py:108: UserWarning: FilterTests.test_ignore_after_default
  self.module.warn(message, UserWarning)
/home/serhiy/py/cpython/Lib/test/test_warnings/__init__.py:108: UserWarning: FilterTests.test_ignore_after_default
  self.module.warn(message, UserWarning)
test test_warnings failed -- multiple errors occurred; run in verbose mode for details
test_warnings failed
1 test failed:
    test_warnings
Total duration: 0:00:02
msg266399 - (view) Author: Martin Panter (martin.panter) * (Python committer) Date: 2016-05-26 00:18
New patch with common _add_filters() function, and added resetwarnings() calls to avoid the conflict with pre-defined filters.
msg266410 - (view) Author: Serhiy Storchaka (serhiy.storchaka) * (Python committer) Date: 2016-05-26 04:25
LGTM, except that initial_len is now always 0.
msg266423 - (view) Author: Roundup Robot (python-dev) (Python triager) Date: 2016-05-26 10:32
New changeset f57f4e33ba5e by Martin Panter in branch '3.5':
Issue #18383: Avoid adding duplicate filters when warnings is reloaded
https://hg.python.org/cpython/rev/f57f4e33ba5e

New changeset 90bb91be6f3b by Martin Panter in branch 'default':
Issue #18383: Merge warnings fix from 3.5
https://hg.python.org/cpython/rev/90bb91be6f3b
msg266427 - (view) Author: Martin Panter (martin.panter) * (Python committer) Date: 2016-05-26 12:07
I eliminated initial_len from my final version.
msg266433 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2016-05-26 13:14
Note: My issue #26742 has been marked as a duplicate of this one.

I confirm that "./python -Wd -m test -j0 test_warnings" doesn't complain "1 test altered the execution environment: test_warnings" anymore. Thanks for the fix.
msg281366 - (view) Author: Roundup Robot (python-dev) (Python triager) Date: 2016-11-21 15:39
New changeset 5e8ef1493843 by Victor Stinner in branch '3.6':
Implement rich comparison for _sre.SRE_Pattern
https://hg.python.org/cpython/rev/5e8ef1493843
History
Date User Action Args
2016-11-21 15:39:26python-devsetmessages: + msg281366
2016-05-26 13:14:36vstinnersetmessages: + msg266433
2016-05-26 12:07:45martin.pantersetstatus: open -> closed
resolution: fixed
messages: + msg266427

stage: commit review -> resolved
2016-05-26 10:32:40python-devsetnosy: + python-dev
messages: + msg266423
2016-05-26 04:25:39serhiy.storchakasetmessages: + msg266410
2016-05-26 00:19:01martin.pantersetfiles: + issue18383_avoid_dups_4.diff

messages: + msg266399
2016-05-22 16:17:00serhiy.storchakasetmessages: + msg266087
2016-05-22 13:10:23berker.peksagsetmessages: + msg266076
stage: patch review -> commit review
2016-05-22 04:46:28martin.pantersetfiles: + issue18383_avoid_dups_3.diff

messages: + msg266049
2016-05-22 04:45:20martin.pantersetfiles: - issue18383_avoid_dups_3.diff
2016-05-22 04:42:01martin.panterlinkissue26742 superseder
2016-05-22 04:41:16martin.pantersetfiles: + issue18383_avoid_dups_3.diff

messages: + msg266047
versions: - Python 3.4
2016-04-13 02:32:56martin.panterlinkissue14784 superseder
2015-09-03 03:22:36martin.pantersetmessages: + msg249599
2015-09-02 23:34:10vstinnersetnosy: + vstinner
messages: + msg249583
2015-09-02 22:55:53martin.pantersetmessages: + msg249581
2015-08-26 04:25:55martin.pantersetmessages: + msg249179
2015-08-14 06:47:26ashkopsetfiles: + issue18383_34_2.diff

messages: + msg248559
2015-08-13 06:11:49ashkopsetmessages: + msg248499
2015-08-12 22:01:50rbcollinssetnosy: + rbcollins

messages: + msg248479
stage: commit review -> patch review
2015-07-31 06:13:10ashkopsetmessages: + msg247737
2015-07-31 01:02:22berker.peksagsetfiles: + issue18383_34.diff

messages: + msg247719
2015-06-18 06:31:50martin.pantersetmessages: + msg245454
versions: + Python 3.6
2015-05-12 12:55:46ashkopsetmessages: + msg242966
2015-04-28 09:55:00ashkopsetmessages: + msg242171
2015-04-14 06:13:48ashkopsetfiles: + issue18383_assert_warns_and_dups_v2.patch

messages: + msg240846
2015-04-12 02:38:47martin.pantersetmessages: + msg240523
2015-04-09 13:34:35ashkopsetfiles: + issue18383_assert_warns_and_dups.patch

messages: + msg240324
2015-04-09 09:22:24martin.pantersetmessages: + msg240314
2015-04-08 14:42:29berker.peksagunlinkissue23027 dependencies
2015-04-06 10:24:39ashkopsetfiles: + issue18383_remove_dups_and_test.patch

messages: + msg240147
2015-04-04 22:26:33martin.pantersetnosy: + martin.panter
2015-04-04 10:11:53serhiy.storchakalinkissue23027 dependencies
2015-04-04 10:09:15serhiy.storchakasetassignee: berker.peksag
stage: patch review -> commit review
2015-04-04 09:42:48berker.peksagsetnosy: + berker.peksag
messages: + msg240055
2015-03-02 15:24:04ashkopsetfiles: + issue18383_remove_dups.patch
nosy: + ashkop
messages: + msg237050

2014-12-10 22:55:00serhiy.storchakasetnosy: + serhiy.storchaka

messages: + msg232451
versions: + Python 3.5, - Python 3.3
2013-08-06 16:58:35ezio.melottisetmessages: + msg194567
2013-07-12 22:26:23terry.reedysetnosy: + ezio.melotti
2013-07-06 14:17:51floxsetfiles: + issue18383_test_warnings_filters.diff
keywords: + patch
messages: + msg192443

stage: needs patch -> patch review
2013-07-06 13:56:53floxsetmessages: + msg192442
2013-07-06 13:36:14floxcreate