Opened 4 years ago

Last modified 2 years ago

#24755 new defect

py3: Some test results correctly contain DeprecationWarnings that nonetheless do not appear in Python 2

Reported by: embray Owned by:
Priority: minor Milestone: sage-pending
Component: python3 Keywords:
Cc: embray, jdemeyer Merged in:
Authors: Reviewers:
Report Upstream: N/A Work issues:
Branch: Commit:
Dependencies: Stopgaps:

Status badges

Description

I've seen a few examples of this now. One such example:

sage -t src/sage/functions/piecewise_old.py
**********************************************************************
File "src/sage/functions/piecewise_old.py", line 1819, in sage.functions.piecewise_old.PiecewisePolynomial.__mul__
Failed example:
    g*(11/2)
Expected:
    Piecewise defined function with 2 parts, [[(0, 5), 11/2*x - 11], [(5, 10), 11/2*x - 55/2]]
Got:
    doctest:warning
      File "/home/embray/src/sagemath/sage-python3/src/bin/sage-runtests", line 125, in <module>
        err = DC.run()
      File "/home/embray/src/sagemath/sage-python3/local/lib/python3.6/site-packages/sage/doctest/control.py", line 1183, in run
        self.run_doctests()
      File "/home/embray/src/sagemath/sage-python3/local/lib/python3.6/site-packages/sage/doctest/control.py", line 911, in run_doctests
        self.dispatcher.dispatch()
      File "/home/embray/src/sagemath/sage-python3/local/lib/python3.6/site-packages/sage/doctest/forker.py", line 1860, in dispatch
        self.parallel_dispatch()
      File "/home/embray/src/sagemath/sage-python3/local/lib/python3.6/site-packages/sage/doctest/forker.py", line 1757, in parallel_dispatch
        w.start()  # This might take some time
      File "/home/embray/src/sagemath/sage-python3/local/lib/python3.6/site-packages/sage/doctest/forker.py", line 2034, in start
        super(DocTestWorker, self).start()
      File "/home/embray/src/sagemath/sage-python3/local/lib/python3.6/multiprocessing/process.py", line 105, in start
        self._popen = self._Popen(self)
      File "/home/embray/src/sagemath/sage-python3/local/lib/python3.6/multiprocessing/context.py", line 223, in _Popen
        return _default_context.get_context().Process._Popen(process_obj)
      File "/home/embray/src/sagemath/sage-python3/local/lib/python3.6/multiprocessing/context.py", line 277, in _Popen
        return Popen(process_obj)
      File "/home/embray/src/sagemath/sage-python3/local/lib/python3.6/multiprocessing/popen_fork.py", line 20, in __init__
        self._launch(process_obj)
      File "/home/embray/src/sagemath/sage-python3/local/lib/python3.6/multiprocessing/popen_fork.py", line 74, in _launch
        code = process_obj._bootstrap()
      File "/home/embray/src/sagemath/sage-python3/local/lib/python3.6/multiprocessing/process.py", line 249, in _bootstrap
        self.run()
      File "/home/embray/src/sagemath/sage-python3/local/lib/python3.6/site-packages/sage/doctest/forker.py", line 2001, in run
        task(self.options, self.outtmpfile, msgpipe, self.result_queue)
      File "/home/embray/src/sagemath/sage-python3/local/lib/python3.6/site-packages/sage/doctest/forker.py", line 2338, in __call__
        doctests, extras = self._run(runner, options, results)
      File "/home/embray/src/sagemath/sage-python3/local/lib/python3.6/site-packages/sage/doctest/forker.py", line 2389, in _run
        result = runner.run(test)
      File "/home/embray/src/sagemath/sage-python3/local/lib/python3.6/site-packages/sage/doctest/forker.py", line 746, in run
        return self._run(test, compileflags, out)
      File "/home/embray/src/sagemath/sage-python3/local/lib/python3.6/site-packages/sage/doctest/forker.py", line 562, in _run
        self.compile_and_execute(example, compiler, test.globs)
      File "/home/embray/src/sagemath/sage-python3/local/lib/python3.6/site-packages/sage/doctest/forker.py", line 972, in compile_and_execute
        exec(compiled, globs)
      File "<doctest sage.functions.piecewise_old.PiecewisePolynomial.__mul__[11]>", line 1, in <module>
        g*(Integer(11)/Integer(2))
      File "/home/embray/src/sagemath/sage-python3/local/lib/python3.6/site-packages/sage/functions/piecewise_old.py", line 1827, in __mul__
        return Piecewise([[(a,b), other*f] for (a,b),f in self.list()])
      File "/home/embray/src/sagemath/sage-python3/local/lib/python3.6/site-packages/sage/functions/piecewise_old.py", line 125, in Piecewise
        deprecation(14801, 'use lower-case piecewise instead')
      File "/home/embray/src/sagemath/sage-python3/local/lib/python3.6/site-packages/sage/misc/superseded.py", line 101, in deprecation
        warning(trac_number, message, DeprecationWarning, stacklevel)
      File "/home/embray/src/sagemath/sage-python3/local/lib/python3.6/site-packages/sage/misc/superseded.py", line 142, in warning
        warn(message, warning_class, stacklevel)
      File "/home/embray/src/sagemath/sage-python3/local/lib/python3.6/warnings.py", line 99, in _showwarnmsg
        msg.file, msg.line)
    :
    DeprecationWarning: use lower-case piecewise instead
    See http://trac.sagemath.org/14801 for details.
    Piecewise defined function with 2 parts, [[(0, 5), 11/2*x - 11], [(5, 10), 11/2*x - 55/2]]

The DeprecationWarning here definitely makes sense (the code is calling Piecewise(...) which issues a warning. On Python 3 the DeprecationWarning is displayed, in this case, but not on Python 2. It seems maybe an issue more with Python 2 and the seen warnings cache not being reset consistently between tests, but I haven't looked too deeply yet.

Change History (21)

comment:1 Changed 4 years ago by embray

  • Milestone changed from sage-8.2 to sage-8.3

comment:2 in reply to: ↑ description ; follow-up: Changed 4 years ago by jdemeyer

Replying to embray:

the seen warnings cache not being reset consistently between tests

The "seen warnings cache" is not meant to be reset between tests (IMHO). It's quite useful when you deprecate something that has a lot of tests: instead of adding DeprecationWarning in the test output everywhere, you only need to do it once.

Of course, it doesn't answer the question why this is different in Python 3.

comment:3 Changed 4 years ago by jdemeyer

There is a specific strangeness about Piecewise: the deprecation warning is shown every time, even in interactive usage:

sage: f1(x) = 1
sage: f2(x) = 1 - x
sage: f = Piecewise([[(0,1),f1],[(1,2),f2]])
/usr/local/src/sage-config/src/bin/sage-ipython:1: DeprecationWarning: use lower-case piecewise instead
See http://trac.sagemath.org/14801 for details.
  #!/usr/bin/env sage-python23
sage: f = Piecewise([[(0,1),f1],[(1,2),f2]])
/usr/local/src/sage-config/src/bin/sage-ipython:1: DeprecationWarning: use lower-case piecewise instead
See http://trac.sagemath.org/14801 for details.
  #!/usr/bin/env sage-python23

comment:4 Changed 4 years ago by jdemeyer

Piecewise is a lazy import, but that's not the cause:

sage: f1(x) = 1
sage: f2(x) = 1 - x
sage: Piecewise = Piecewise._get_object()
sage: f = Piecewise([[(0,1),f1],[(1,2),f2]])
/usr/local/src/sage-config/src/bin/sage-ipython:1: DeprecationWarning: use lower-case piecewise instead
See http://trac.sagemath.org/14801 for details.
  #!/usr/bin/env sage-python23
sage: f = Piecewise([[(0,1),f1],[(1,2),f2]])
/usr/local/src/sage-config/src/bin/sage-ipython:1: DeprecationWarning: use lower-case piecewise instead
See http://trac.sagemath.org/14801 for details.
  #!/usr/bin/env sage-python23

comment:5 in reply to: ↑ 2 Changed 4 years ago by embray

Replying to jdemeyer:

Replying to embray:

the seen warnings cache not being reset consistently between tests

The "seen warnings cache" is not meant to be reset between tests (IMHO). It's quite useful when you deprecate something that has a lot of tests: instead of adding DeprecationWarning in the test output everywhere, you only need to do it once.

Of course, it doesn't answer the question why this is different in Python 3.

This also works very inconsistently depending on the order in which the tests are run. For example, sometimes if I run the tests for a specific module I get failures because either some warning wasn't displayed that was expected, or more often a warning that wasn't expected (but is still correct) is displayed.

Maybe it would be better to have a way to ignore certain warnings in the doctests unless they're explicitly asked for (i.e. to test the warning itself).

comment:6 Changed 4 years ago by jdemeyer

I'd still like to know why this specific warning behaves differently from other very similar warnings.

comment:7 Changed 4 years ago by embray

I've figured out at least in part what's going on with warnings on Python 3, and it's pretty annoying. I believe it to be a bug in Python and I'm not alone there: https://bugs.python.org/issue29672

It is a regression introduced by a previous fix to a different but related issue: https://bugs.python.org/issue4180

The original issue, which was also a reasonable problem, was that if you display some warning, say

>>> def foo():
...     warnings.warn("foo")
>>> foo()
UserWarning: foo

Normally, that warning will be displayed once and only once. But if you change the default warnings filter to 'always', the reasonable expectation (arguably) is that it should start displaying that warning again:

>>> warnings.simplefilter('always')
>>> foo()
UserWarning: foo

On Python 2 this does not happen--a warning once displayed is never displayed again, even if the warnings filter is changed.

The solution to this problem, unfortunately, was something of a baseball bat. It adds a monotonically increasing global "_filter_version" that is incremented any time the warnings filters are modified at all, and this version is applied to all warnings. It also adds a 'version' to each __warningregistry__. If, when a warning is to be displayed, the 'version' in relevant __warningregistry__ is behind the global _filter_version, it ignores whether or not that warning has already been displayed, and just treats it more or less as a new warning. This happens even if the warning filters were updated in such a way that in no way affects the warning in question, so it's really quite a blunt instrument.

What's worse, is also updates this "_filter_version" every time a catch_warnings() context manager is entered or exited, even if the warning filters were not modified at all in the context body. This screws up how warnings are handled in the IPython prompt even in plain IPython (or Sage's prompt):

In [1]: import warnings

In [2]: def foo():
   ...:     warnings.warn('foo')
   ...:

In [3]: foo()
/home/embray/src/sagemath/sage-python3/local/bin/ipython:2: UserWarning: foo
  # EASY-INSTALL-ENTRY-SCRIPT: 'ipython==5.5.0','console_scripts','ipython'

In [4]: foo()
/home/embray/src/sagemath/sage-python3/local/bin/ipython:2: UserWarning: foo
  # EASY-INSTALL-ENTRY-SCRIPT: 'ipython==5.5.0','console_scripts','ipython'

This is because there's some catch_warnings() going on every time it displays a prompt. From IPython.core.inputsplitter:InputSplitter.push:

310         self._update_indent(lines)
311         try:
312             with warnings.catch_warnings():
313                 warnings.simplefilter('error', SyntaxWarning)
314                 self.code = self._compile(source, symbol="exec")
315         # Invalid syntax can produce any of a number of different errors from
316         # inside the compiler, so we have to catch them all.  Syntax errors
317         # immediately produce a 'ready' block, so the invalid Python can be
318         # sent to the kernel for evaluation with possible ipython
319         # special-syntax conversion.
320         except (SyntaxError, OverflowError, ValueError, TypeError,
321                 MemoryError, SyntaxWarning):
322             self._is_complete = True
323             self._is_invalid = True
324         else:
325             # Compilation didn't produce any exceptions (though it may not have
326             # given a complete code object)
327             self._is_complete = self.code is not None

This has the effect that for every line you input to the IPython prompt (and this includes multi-line input) the warnings filter is effectively reset, making it useless to try to prevent warnings from being displayed multiple times.

This also explained why we get erratic behavior w.r.t. warnings in the Sage doctests. Although there aren't many cases directly in the doctests where we directly manipulate the warnings filter, there are at least a few (and probably more cases where we do so indirectly). So every time that happens it resets whether a warning has been displayed =_=

I'm not really sure yet what a workaround to this would look like...

comment:8 Changed 4 years ago by embray

Another related issue I came up with in trying to find a workaround to this, is that even if sort of brute force work around the _filter_version hack, you still get incorrectly duplicated warnings when you use a deprecated function in a list comprehension expression (or possibly other generated expressions).

This came up in sage.structure.element.generic_power:

        sage: from sage.structure.element import generic_power
        sage: generic_power(int(12),int(0))
        doctest:...: DeprecationWarning: import 'generic_power' from sage.arith.power instead
        See http://trac.sagemath.org/24256 for details.
        1
        sage: generic_power(int(0),int(100))
        0
        sage: generic_power(Integer(10),Integer(0))
        1
        sage: generic_power(Integer(0),Integer(23))
        0
        sage: sum([generic_power(2,i) for i in range(17)]) #test all 4-bit combinations
        131071

one workaround I tried actually fixed it up to the line with the list comprehension. In this case the frame the warning comes from is at line 1 of the exec'd code in the expression (I think), so it's effectively treated as a new warning coming from a new location.

Perhaps at least for Sage's deprecation warnings we can brute force keep our own warnings registry so that each deprecation is truly only reported once no matter what.

comment:9 Changed 4 years ago by embray

  • Milestone changed from sage-8.3 to sage-8.4

comment:10 Changed 4 years ago by embray

  • Milestone changed from sage-8.4 to sage-8.5

comment:11 Changed 3 years ago by embray

  • Milestone changed from sage-8.5 to sage-8.7

Retargeting some of my tickets (somewhat optimistically for now).

comment:12 Changed 3 years ago by embray

  • Milestone changed from sage-8.7 to sage-pending

Removing most of the rest of my open tickets out of the 8.7 milestone, which should be closed.

comment:13 follow-up: Changed 3 years ago by chapoton

  • Cc embray jdemeyer added

apparently, the fix has been merged (NO, SORRY, NOT MERGED YET)

https://github.com/python/cpython/pull/8232

Maybe we should upgrade cpython ?

Last edited 3 years ago by chapoton (previous) (diff)

comment:14 Changed 3 years ago by embray

Yeah, I know it's had a proposed fix for a while; it's just sitting around waiting for review, as is often the case as there are not enough cpython core developers to review most bug fix PRs, especially for relatively non-critical stuff.

Perhaps I could try to make some noise about this one because it would be good to have fixed. In the meantime I'd be hesitant to rely on a patch to work around this.

I think my earlier suggestion

Perhaps at least for Sage's deprecation warnings we can brute force keep our own warnings registry so that each deprecation is truly only reported once no matter what.

is going to end up being simplest until this is fixed upstream. It sucks, but it's better than nothing and probably not too hard. I could try to tackle it though it will take me a little time to reorient myself to the warnings module code, since it's been nearly a year since I last looked into it.

comment:15 in reply to: ↑ 13 Changed 3 years ago by embray

Replying to chapoton:

Maybe we should upgrade cpython ?

Also we just did that in #25680 ! =) You helped review the ticket. Python 3.7.3 is the most recent release as of now.

comment:16 Changed 3 years ago by nbruin

The file piecewise_old.py has been removed by #26865, so this ticket should probably either be updated with another example in its description or be closed as "invalid/wontfix/worksforme".

comment:17 follow-up: Changed 2 years ago by dimpase

the catch_warnings() context manager is not meant to work in multithreaded environment: https://docs.python.org/3/library/warnings.html

this looks like it's basically doomed to be broken for our doctests - see e.g. #28329 where this resurfaced.

comment:18 in reply to: ↑ 17 Changed 2 years ago by embray

Replying to dimpase:

the catch_warnings() context manager is not meant to work in multithreaded environment: https://docs.python.org/3/library/warnings.html

this looks like it's basically doomed to be broken for our doctests - see e.g. #28329 where this resurfaced.

I don't think threads have anything to do with this. In that ticket the problem is just exactly what I described above: Because catch_warnings was used it reset some other __warningsregistry__ and warnings that should have not been displayed again do get displayed. Threads don't enter into it.

comment:19 Changed 2 years ago by dimpase

This does not explain how the interference from #28329 (i.e. https://git.sagemath.org/sage.git/commit/?id=6192e54fe6894b5c444e1a2cb7d0adeec1d94348) can make a difference here. Because it should have been totally safe in a single-threaded environment!

comment:20 Changed 2 years ago by embray

No, it explains it exactly. The original change used warnings.catch_warnings(), and if that code happened to be called from anywhere in that module it would reset the warnings registry for that module and cause warnings that were previously shown to be shown again instead of hidden.

Again, threads have nothing to do with it. It is a single-threaded environment.

comment:21 Changed 2 years ago by dimpase

catch_warnings() has been called in context, in with block. Are you saying this changes global state? Then the Python docs on it are wrong.

Note: See TracTickets for help on using tickets.