Patchbot and Python 3 doctest failures

[jhpalmieri]

With a Python 3 patchbot and a Ubuntu 18.04 computer running make ptestlong, there are doctest failures in three files:

sage -t --long src/sage/repl/attach.py  # 4 doctests failed
sage -t --long src/sage/libs/singular/function.pyx  # 1 doctest failed
sage -t --long src/sage/numerical/backends/generic_backend.pyx  # 2 doctests failed

This can be replicated by hand. cd to SAGE_ROOT for a Sage built with Python 3, run Python, and do

>>> import subprocess, os, sys
>>> tee = subprocess.Popen(["tee", 'LOGFILE.log'], stdin=subprocess.PIPE)
>>> os.dup2(tee.stdin.fileno(), sys.stdout.fileno())
>>> os.dup2(tee.stdin.fileno(), sys.stderr.fileno())
>>> os.system('./sage -tp src/sage/repl/attach.py src/sage/libs/singular/function.pyx src/sage/numerical/backends/generic_backend.pyx')

Note that in a fresh Python session, the following does not lead to errors:

>>> import os
>>> os.system('./sage -tp src/sage/repl/attach.py src/sage/libs/singular/function.pyx src/sage/numerical/backends/generic_backend.pyx')

Component: python3

Author: John Palmieri

Branch: 56e1642

Reviewer: Frédéric Chapoton, Eric Gourgoulhon

Issue created by migration from https://trac.sagemath.org/ticket/28622

[jhpalmieri]

comment:1

The failures:

sage -t --long src/sage/repl/attach.py
**********************************************************************
File "src/sage/repl/attach.py", line 36, in sage.repl.attach
Failed example:
    try:
        attach(src)
    except Exception:
        traceback.print_exc()
Expected:
    Traceback (most recent call last):
    ...
        exec(preparse_file(f.read()) + "\n", globals)
      File "<string>", line 3, in <module>
    ValueError: third
Got:
    <BLANKLINE>
**********************************************************************
File "src/sage/repl/attach.py", line 45, in sage.repl.attach
Failed example:
    detach(src)
Expected nothing
Got:
    Traceback (most recent call last):
      File "<doctest sage.repl.attach[10]>", line 2, in <module>
        attach(src)
      File "sage/misc/lazy_import.pyx", line 354, in sage.misc.lazy_import.LazyImport.__call__ (build/cythonized/sage/misc/lazy_import.c:3697)
        return self.get_object()(*args, **kwds)
      File "/Users/jpalmier/Desktop/Sage/sage_builds/TESTING/sage-9.0.beta1/local/lib/python3.7/site-packages/sage/repl/attach.py", line 356, in attach
        load(filename, globals(), attach=True)
      File "/Users/jpalmier/Desktop/Sage/sage_builds/TESTING/sage-9.0.beta1/local/lib/python3.7/site-packages/sage/repl/load.py", line 272, in load
        exec(preparse_file(f.read()) + "\n", globals)
      File "<string>", line 3, in <module>
    ValueError: third
**********************************************************************
File "src/sage/repl/attach.py", line 48, in sage.repl.attach
Failed example:
    try:
        attach(src)
    except Exception:
        traceback.print_exc()
Expected:
    Traceback (most recent call last):
    ...
        exec(code, globals)
      File ".../foobar.sage....py", line ..., in <module>
        raise ValueError("third")   # this should appear in the source snippet
    ValueError: third
Got:
    <BLANKLINE>
**********************************************************************
File "src/sage/repl/attach.py", line 58, in sage.repl.attach
Failed example:
    detach(src)
Expected nothing
Got:
    Traceback (most recent call last):
      File "<doctest sage.repl.attach[13]>", line 2, in <module>
        attach(src)
      File "sage/misc/lazy_import.pyx", line 354, in sage.misc.lazy_import.LazyImport.__call__ (build/cythonized/sage/misc/lazy_import.c:3697)
        return self.get_object()(*args, **kwds)
      File "/Users/jpalmier/Desktop/Sage/sage_builds/TESTING/sage-9.0.beta1/local/lib/python3.7/site-packages/sage/repl/attach.py", line 356, in attach
        load(filename, globals(), attach=True)
      File "/Users/jpalmier/Desktop/Sage/sage_builds/TESTING/sage-9.0.beta1/local/lib/python3.7/site-packages/sage/repl/load.py", line 266, in load
        exec(code, globals)
      File "/Users/jpalmier/.sage/temp/jpalmieri138.local/85343/foobar.sageyh9c7b26.py", line 7, in <module>
        raise ValueError("third")   # this should appear in the source snippet
    ValueError: third
**********************************************************************
1 item had failures:
   4 of  16 in sage.repl.attach
    [129 tests, 4 failures, 2.43 s]

and

sage -t --long src/sage/libs/singular/function.pyx
**********************************************************************
File "src/sage/libs/singular/function.pyx", line 1314, in sage.libs.singular.function.SingularFunction.__call__
Failed example:
    G= Ideal(I.groebner_basis())
Expected nothing
Got:
    RuntimeError: Error raised calling singular function
    Exception ignored in: 'sage.libs.singular.function.LibraryCallHandler.handle_call'
    RuntimeError: Error raised calling singular function
**********************************************************************
1 item had failures:
   1 of  24 in sage.libs.singular.function.SingularFunction.__call__
    [302 tests, 1 failure, 1.63 s]

and

File "src/sage/numerical/backends/generic_backend.pyx", line 181, in sage.numerical.backends.generic_backend.GenericBackend._test_add_variables
Failed example:
    sig_on_count() # check sig_on/off pairings (virtual doctest)
Expected:
    0
Got:
    NotImplementedError
    Exception ignored in: 'sage.numerical.backends.generic_backend.GenericBackend.ncols'
    NotImplementedError: 
    0
**********************************************************************
File "src/sage/numerical/backends/generic_backend.pyx", line 646, in sage.numerical.backends.generic_backend.GenericBackend._test_add_linear_constraints
Failed example:
    sig_on_count() # check sig_on/off pairings (virtual doctest)
Expected:
    0
Got:
    NotImplementedError
    Exception ignored in: 'sage.numerical.backends.generic_backend.GenericBackend.nrows'
    NotImplementedError: 
    0
**********************************************************************
2 items had failures:
   1 of   4 in sage.numerical.backends.generic_backend.GenericBackend._test_add_linear_constraints
   1 of   4 in sage.numerical.backends.generic_backend.GenericBackend._test_add_variables
    [89 tests, 2 failures, 1.04 s]

[jhpalmieri]

comment:3

A quicker way to get the failures:

>>> from sage_patchbot.patchbot import Tee
>>> with Tee('/path/to/logfile', time=True, timeout=40):
...     os.system('/path/to/SAGE_ROOT/sage -tp 3 --long src/sage/repl/attach.py src/sage/numerical/backends/generic_backend.pyx src/sage/libs/singular/function.pyx')

[jhpalmieri]

comment:5

Could the problem be the inheritability (or not) of the file descriptors in Tee? In any case, in sage_patchbot.patchbot, if I comment out these lines, the doctests don't fail:

diff --git a/sage_patchbot/patchbot.py b/sage_patchbot/patchbot.py
index b411c7c..2994db1 100755
--- a/sage_patchbot/patchbot.py
+++ b/sage_patchbot/patchbot.py
@@ -142,8 +142,8 @@ class Tee(object):
         self._saved = os.dup(sys.stdout.fileno()), os.dup(sys.stderr.fileno())
         self.tee = subprocess.Popen(["tee", self.filepath],
                                     stdin=subprocess.PIPE)
-        os.dup2(self.tee.stdin.fileno(), sys.stdout.fileno())
-        os.dup2(self.tee.stdin.fileno(), sys.stderr.fileno())
+        # os.dup2(self.tee.stdin.fileno(), sys.stdout.fileno())
+        # os.dup2(self.tee.stdin.fileno(), sys.stderr.fileno())
         if self.time:
             print(now_str())
             self.start_time = time.time()

Of course also the log file doesn't get written.

[jhpalmieri]

comment:8

Could there be some connection to the use of Python's traceback module? I'm trying to find common threads among the three files with failures, and I'm not getting very far, but if I make this change, then tests pass in repl/attach.py:

diff --git a/src/sage/repl/attach.py b/src/sage/repl/attach.py
index c350ec33af..e1c98e32ad 100644
--- a/src/sage/repl/attach.py
+++ b/src/sage/repl/attach.py
@@ -36,7 +36,7 @@ character-by-character::
     sage: try:
     ....:     attach(src)
     ....: except Exception:
-    ....:     traceback.print_exc()
+    ....:     raise
     Traceback (most recent call last):
     ...
         exec(preparse_file(f.read()) + "\n", globals)
@@ -48,7 +48,7 @@ character-by-character::
     sage: try:
     ....:     attach(src)
     ....: except Exception:
-    ....:     traceback.print_exc()
+    ....:     raise
     Traceback (most recent call last):
     ...
         exec(code, globals)

[jhpalmieri]

comment:9

The following change to repl/attach.py is almost good enough:

diff --git a/src/sage/repl/attach.py b/src/sage/repl/attach.py
index c350ec33af..bdfaad4f7f 100644
--- a/src/sage/repl/attach.py
+++ b/src/sage/repl/attach.py
@@ -20,12 +20,8 @@ Check that no file clutter is produced::
     ['foobar.sage']
     sage: detach(src)
 
-In debug mode backtraces contain code snippets. We need to manually
-print the traceback because the python doctest module has special
-support for exceptions and does not match them
-character-by-character::
+Check printing of code snippets in debug mode::
 
-    sage: import traceback
     sage: with open(src, 'w') as f:
     ....:     _ = f.write('# first line\n')
     ....:     _ = f.write('# second line\n')
@@ -33,10 +29,7 @@ character-by-character::
     ....:     _ = f.write('# fourth line\n')
 
     sage: load_attach_mode(attach_debug=False)
-    sage: try:
-    ....:     attach(src)
-    ....: except Exception:
-    ....:     traceback.print_exc()
+    sage: attach(src)
     Traceback (most recent call last):
     ...
         exec(preparse_file(f.read()) + "\n", globals)
@@ -45,10 +38,7 @@ character-by-character::
     sage: detach(src)
 
     sage: load_attach_mode(attach_debug=True)
-    sage: try:
-    ....:     attach(src)
-    ....: except Exception:
-    ....:     traceback.print_exc()
+    sage: attach(src)
     Traceback (most recent call last):
     ...
         exec(code, globals)

The problem is that it would allow some doctests to pass that should fail. From the file:

    sage: with open(src, 'w') as f:
    ....:     _ = f.write('# first line\n')
    ....:     _ = f.write('# second line\n')
    ....:     _ = f.write('raise ValueError("third")   # this should appear in the source snippet\n')
    ....:     _ = f.write('# fourth line\n')

Then this passes, as it should:

    sage: load_attach_mode(attach_debug=True)
    sage: attach(src)
    Traceback (most recent call last):
    ...
        exec(code, globals)
      File ".../foobar.sage....py", line ..., in <module>
        raise ValueError("third")   # this should appear in the source snippet
    ValueError: third

But this also passes: note that the second to last line is different:

    sage: load_attach_mode(attach_debug=True)
    sage: attach(src)
    Traceback (most recent call last):
    ...
        exec(code, globals)
      File ".../foobar.sage....py", line ..., in <module>
        raise ValueError("third")   # this is gibberish
    ValueError: third

I guess this is what is meant by "We need to manually print the traceback because ..."

[fchapoton]

comment:10

Nice to see that you are making progress. Sorry that I cannot help.

[egourgoulhon]

comment:12

FWIW, I systematically get these doctest failures outside the patchbot framework, namely on a Ubuntu 18.04 computer when doing make ptestlong, cf. https://groups.google.com/d/msg/sage-release/yFwTkcr5AVY/ifqU7-3ZAAAJ

[fchapoton]

comment:13

Couldn't some of them be yet another cases of "flush missing", as the previous py3 problems that were fixed ? In the repl_attach case, the correct answer seems to appear in the next doctest.

[jhpalmieri]

comment:14

Interesting question. If I add some sys.stdout.flush() commands, then I can get the repl/attach.py doctests to pass when run as in the ticket description (using tee and output redirection), but then doctests fail when run the usual way. I'll keep experimenting.

[jhpalmieri]

Branch: u/jhpalmieri/flushing

[jhpalmieri]

Commit: 6ade770

[jhpalmieri]

comment:16

Okay, here is an attempt at a fix. It fixes the particular problem in the ticket description, at least for me on OS X. Eric, does it help with your situation?

Should I mark it as "needs review", or should some explanatory comments be added? Or is it even the correct approach?

---

New commits:

6ade770

trac 28622: flush or redirect some output

[fchapoton]

comment:17

This looks good enough for me, even if this is maybe more fixing symptoms than illness.

I will launch my atlas patchbot on the branch.

[fchapoton]

comment:18

This seems to work with python2 and to fix the python3 issues also on Ubuntu patchbot. I am extremely tempted to give a positive review.

[egourgoulhon]

comment:19

Replying to @jhpalmieri:

Okay, here is an attempt at a fix. It fixes the particular problem in the ticket description, at least for me on OS X. Eric, does it help with your situation?

I am just running make ptestlong and shall report soon...

[egourgoulhon]

comment:20

Replying to @egourgoulhon:

Replying to @jhpalmieri:

Okay, here is an attempt at a fix. It fixes the particular problem in the ticket description, at least for me on OS X. Eric, does it help with your situation?

I am just running make ptestlong and shall report soon...

Here is the report from my Ubuntu 18.04 computer:

----------------------------------------------------------------------
sage -t --long --warn-long 53.0 src/sage/rings/polynomial/polynomial_rational_flint.pyx  # 1 doctest failed
----------------------------------------------------------------------
Total time for all tests: 1357.6 seconds

In other words, all the doctests discussed here are passed! The only failure is that discussed in #28334.

So +1 for the positive review.

[fchapoton]

comment:21

ok, so let us first turn to "needs review"

[fchapoton]

comment:22

John, do you agree that this could be set to positive ?

[jhpalmieri]

comment:23

It’s okay with me.

[fchapoton]

Author: John Palmieri

[fchapoton]

comment:24

Good. I am setting to positive.

[fchapoton]

Reviewer: Frédéric Chapoton, ​Eric Gourgoulhon

[dcoudert]

comment:25

Shouldn't we add reference to this ticket to the added lines of code to avoid inadvertent removal ?

[sagetrac-git]

Branch pushed to git repo; I updated commit sha1 and set ticket back to needs_review. New commits:

56e1642

trac 28622: add ticket reference when we use stdout.flush()

[sagetrac-git]

Changed commit from 6ade770 to 56e1642

[jhpalmieri]

comment:27

Replying to @dcoudert:

Shouldn't we add reference to this ticket to the added lines of code to avoid inadvertent removal ?

Done. I'm setting back to positive review, also.

[vbraun]

Changed branch from u/jhpalmieri/flushing to 56e1642

[mkoeppe]

Changed reviewer from Frédéric Chapoton, ​Eric Gourgoulhon to Frédéric Chapoton, Eric Gourgoulhon

[mkoeppe]

Changed commit from 56e1642 to none