I/O operation on closed file when sage -t --optional=sage,external --logfile is_provided.log

[slabbe]

From ​8.3.beta1 post on sage-release:

sage -t src/sage/misc/latex.py --optional=sage,external --logfile a.log
Running doctests with ID 2018-05-17-08-30-16-d8cc67d9.
Git branch: develop
Using --optional=external,sage
External software to be detected: cplex,gurobi,internet,latex,macaulay2,magma,maple,mathematica,matlab,octave,scilab
Doctesting 1 file.
sage -t --warn-long 80.1 src/sage/misc/latex.py
    [315 tests, 1.52 s]
----------------------------------------------------------------------
All tests passed!
----------------------------------------------------------------------
Total time for all tests: 1.8 seconds
    cpu time: 0.5 seconds
    cumulative wall time: 1.5 seconds
External software detected for doctesting: latex
Traceback (most recent call last):
  File "/home/slabbe/GitBox/sage/src/bin/sage-runtests", line 127, in <module>
    err = DC.run()
  File "/home/slabbe/GitBox/sage/local/lib/python2.7/site-packages/sage/doctest/control.py", line 1176, in run
    + ','.join(available_software.seen()))
  File "/home/slabbe/GitBox/sage/local/lib/python2.7/site-packages/sage/doctest/control.py", line 583, in log
    self.logger.write(s + end)
  File "/home/slabbe/GitBox/sage/local/lib/python2.7/site-packages/sage/doctest/control.py", line 250, in write
    f.write(x)
ValueError: I/O operation on closed file

This confirms that the last line (External software detected for doctesting: latex) is not written to the log file because of I/O errors:

$ tail a.log
External software to be detected: cplex,gurobi,internet,latex,macaulay2,magma,maple,mathematica,matlab,octave,scilab
Doctesting 1 file.
sage -t --warn-long 80.1 src/sage/misc/latex.py
    [315 tests, 1.52 s]
----------------------------------------------------------------------
All tests passed!
----------------------------------------------------------------------
Total time for all tests: 1.8 seconds
    cpu time: 0.5 seconds
    cumulative wall time: 1.5 seconds

The error is not there if external software are not tested:

sage -t src/sage/misc/latex.py --optional=sage --logfile a.log
Running doctests with ID 2018-05-17-08-30-28-7b637155.
Git branch: develop
Using --optional=sage
Doctesting 1 file.
sage -t --warn-long 80.1 src/sage/misc/latex.py
    [310 tests, 1.14 s]
----------------------------------------------------------------------
All tests passed!
----------------------------------------------------------------------
Total time for all tests: 1.2 seconds
    cpu time: 0.5 seconds
    cumulative wall time: 1.1 seconds

The error is not there if no log file is provided:

sage -t src/sage/misc/latex.py --optional=sage,external
Running doctests with ID 2018-05-17-08-30-40-21f560b3.
Git branch: develop
Using --optional=external,sage
External software to be detected: cplex,gurobi,internet,latex,macaulay2,magma,maple,mathematica,matlab,octave,scilab
Doctesting 1 file.
sage -t --warn-long 80.1 src/sage/misc/latex.py
    [315 tests, 1.45 s]
----------------------------------------------------------------------
All tests passed!
----------------------------------------------------------------------
Total time for all tests: 1.7 seconds
    cpu time: 0.5 seconds
    cumulative wall time: 1.4 seconds
External software detected for doctesting: latex

[git]

Branch pushed to git repo; I updated commit sha1. New commits:

​221a7db

Trac 25378: Don't close logfile before last message

[slabbe]

I found a way to raise the issue from sage:

sage: from sage.doctest.control import DocTestDefaults, DocTestController
sage: DD = DocTestDefaults(optional=set(['sage', 'external']), logfile=tmp_filename())
sage: filename = os.path.join(SAGE_SRC, "sage", "misc", "latex.py")
sage: DC = DocTestController(DD, [filename])
sage: DC.run()

Thus, I added a commit with a doctest + a commit fixing the two pyflakes issues (see patchbot report).

---

New commits:

​4f2d544	25378: adding a doctest
​4eb2799	25378: fixing issues seen by pyflakes

[slabbe]

I give positive review to commit ​221a7db. I let someone else review my two commits.

[slabbe]

Of course, "someone else" may include you Vincent Klein as this is often done, see #19494 :)

[vklein]

I m ok for the last two commits.

[vbraun]

File "src/sage/doctest/control.py", line 1145, in sage.doctest.control.DocTestController.run
Failed example:
    DC.run()
Expected:
    Running doctests with ID ...
    Using --optional=external,sage
    External software to be detected: ...
    Doctesting 1 file.
    sage -t .../sage/misc/latex.py
        [... tests, ... s]
    ----------------------------------------------------------------------
    All tests passed!
    ----------------------------------------------------------------------
    Total time for all tests: ... seconds
        cpu time: ... seconds
        cumulative wall time: ... seconds
    External software detected for doctesting: ...
    0
Got:
    Running doctests with ID 2018-07-30-14-14-47-59620918.
    Git branch: test
    Using --optional=external,sage
    External software to be detected: cplex,ffmpeg,graphviz,gurobi,imagemagick,internet,latex,macaulay2,magma,maple,mathematica,matlab,octave,pandoc,scilab
    Doctesting 1 file.
    sage -t /mnt/disk/home/release/Sage/src/sage/misc/latex.py
    **********************************************************************
    File "/mnt/disk/home/release/Sage/src/sage/misc/latex.py", line 1548, in sage.misc.latex.Latex.add_package_to_preamble_if_available
    Failed example:
        latex.extra_preamble()       # optional - latex
    Expected:
        '\\usepackage{xypic}\n'
    Got:
        ''
    **********************************************************************
    1 item had failures:
       1 of   5 in sage.misc.latex.Latex.add_package_to_preamble_if_available
        [316 tests, 1 failure, 1.29 s]
    ----------------------------------------------------------------------
    sage -t /mnt/disk/home/release/Sage/src/sage/misc/latex.py  # 1 doctest failed
    ----------------------------------------------------------------------
    Total time for all tests: 1.6 seconds
        cpu time: 0.4 seconds
        cumulative wall time: 1.3 seconds
    External software detected for doctesting: imagemagick,latex
    1
**********************************************************************

[vdelecroix]

update milestone 8.3 -> 8.4

[slabbe]

In the doctest, I was testing that sage -t --optional=sage,external --logfile a.log works on a file inside the sage library containing at least one external doctest namely sage/misc/latex.py. Of course, this test way too much thing including all of the doctests inside of that file which may create other unrelated failures like the one obtained by Volker.

I found a much simpler way to test that the error is fixed. Indeed, running the command on a empty file raises the failure:

$ touch a.py
$ sage -t a.py --optional=sage,external --logfile a.log
too many failed tests, not using stored timings
Running doctests with ID 2018-08-22-14-45-05-4d9b505f.
Git branch: develop
Using --optional=external,sage
External software to be detected: cplex,ffmpeg,graphviz,gurobi,imagemagick,internet,latex,macaulay2,magma,maple,mathematica,matlab,octave,pandoc,scilab
Doctesting 1 file.
sage -t a.py
    [0 tests, 0.00 s]
----------------------------------------------------------------------
All tests passed!
----------------------------------------------------------------------
Total time for all tests: 0.2 seconds
    cpu time: 0.0 seconds
    cumulative wall time: 0.0 seconds
External software detected for doctesting: 
Traceback (most recent call last):
  File "/home/slabbe/GitBox/sage/src/bin/sage-runtests", line 139, in <module>
    err = DC.run()
  File "/home/slabbe/GitBox/sage/local/lib/python2.7/site-packages/sage/doctest/control.py", line 1185, in run
    + ','.join(available_software.seen()))
  File "/home/slabbe/GitBox/sage/local/lib/python2.7/site-packages/sage/doctest/control.py", line 592, in log
    self.logger.write(s + end)
  File "/home/slabbe/GitBox/sage/local/lib/python2.7/site-packages/sage/doctest/control.py", line 255, in write
    f.write(x)
ValueError: I/O operation on closed file

Therefore, I will update the doctest with this instead.

[git]

Branch pushed to git repo; I updated commit sha1. New commits:

​4f8a7ac	Merge branch 'public/25378' into 8.4.beta1
​7c7e278	25378: better doctest

[vklein]

Fine for me

[vbraun]

The test is fragile:

File "src/sage/doctest/control.py", line 1161, in sage.doctest.control.DocTestController.run
Failed example:
    DC.run()
Expected:
    Running doctests with ID ...
    Using --optional=external,sage
    External software to be detected: ...
    Doctesting 1 file.
    sage -t ....py
        [0 tests, 0.00 s]
    ----------------------------------------------------------------------
    All tests passed!
    ----------------------------------------------------------------------
    Total time for all tests: 0.0 seconds
        cpu time: 0.0 seconds
        cumulative wall time: 0.0 seconds
    External software detected for doctesting:
    0
Got:
    Running doctests with ID 2018-08-25-08-26-30-30c10539.
    Git branch: develop
    Using --optional=external,sage
    External software to be detected: cplex,ffmpeg,graphviz,gurobi,imagemagick,internet,latex,macaulay2,magma,maple,mathematica,matlab,octave,pandoc,scilab
    Doctesting 1 file.
    sage -t /var/lib/buildbot/slave/sage_git/dot_sage/temp/kucalc/29651/tmp_eWoSer.py
        [0 tests, 0.00 s]
    ----------------------------------------------------------------------
    All tests passed!
    ----------------------------------------------------------------------
    Total time for all tests: 0.0 seconds
        cpu time: 0.0 seconds
        cumulative wall time: 0.0 seconds
    External software detected for doctesting: latex
    0
**********************************************************************
1 item had failures:
   1 of  13 in sage.doctest.control.DocTestController.run
    [206 tests, 1 failure, 4.48 s]
**********************************************************************

---

New commits:

​221a7db	Trac 25378: Don't close logfile before last message
​4f2d544	25378: adding a doctest
​4eb2799	25378: fixing issues seen by pyflakes
​4f8a7ac	Merge branch 'public/25378' into 8.4.beta1
​7c7e278	25378: better doctest

[chapoton]

use the trac role :trac:`25378` instead of #25378 in

+ We check that #25378 is fixed (testing external packages while

[git]

Branch pushed to git repo; I updated commit sha1. New commits:

​1040475

25378: more robust doctest

[vbraun]

On OSX I get lots of failures of the form

**********************************************************************
File "src/sage/interfaces/expect.py", line 763, in sage.interfaces.expect.Expect._eval_line_using_file
Failed example:
    singular._eval_line_using_file('def a=3;')
Exception raised:
    Traceback (most recent call last):
      File "/Users/buildslave-sage/slave/sage_git/build/local/lib/python2.7/site-packages/sage/doctest/forker.py", line 650, in _run
        self.compile_and_execute(example, compiler, test.globs)
      File "/Users/buildslave-sage/slave/sage_git/build/local/lib/python2.7/site-packages/sage/doctest/forker.py", line 1061, in compile_and_execute
        exec(compiled, globs)
      File "<doctest sage.interfaces.expect.Expect._eval_line_using_file[3]>", line 1, in <module>
        singular._eval_line_using_file('def a=3;')
      File "/Users/buildslave-sage/slave/sage_git/build/local/lib/python2.7/site-packages/sage/interfaces/expect.py", line 813, in _eval_line_using_file
        self._synchronize()
      File "/Users/buildslave-sage/slave/sage_git/build/local/lib/python2.7/site-packages/sage/interfaces/expect.py", line 1284, in _synchronize
        self._sendstr(cmd)
      File "/Users/buildslave-sage/slave/sage_git/build/local/lib/python2.7/site-packages/sage/interfaces/expect.py", line 1226, in _sendstr
        self.quit()
      File "/Users/buildslave-sage/slave/sage_git/build/local/lib/python2.7/site-packages/sage/interfaces/expect.py", line 597, in quit
        self._expect.close()
      File "/Users/buildslave-sage/slave/sage_git/build/local/lib/python2.7/site-packages/pexpect/pty_spawn.py", line 327, in close
        self.ptyproc.close(force=force)
      File "sage/interfaces/sagespawn.pyx", line 202, in sage.interfaces.sagespawn.SagePtyProcess.close (build/cythonized/sage/interfaces/sagespawn.c:3059)
        self.fileobj.close()
    IOError: [Errno 5] Input/output error
**********************************************************************
File "src/sage/interfaces/expect.py", line 766, in sage.interfaces.expect.Expect._eval_line_using_file
Failed example:
    singular('a')
Exception raised:
    Traceback (most recent call last):
      File "/Users/buildslave-sage/slave/sage_git/build/local/lib/python2.7/site-packages/sage/doctest/forker.py", line 650, in _run
        self.compile_and_execute(example, compiler, test.globs)
      File "/Users/buildslave-sage/slave/sage_git/build/local/lib/python2.7/site-packages/sage/doctest/forker.py", line 1061, in compile_and_execute
        exec(compiled, globs)
      File "<doctest sage.interfaces.expect.Expect._eval_line_using_file[4]>", line 1, in <module>
        singular('a')
      File "/Users/buildslave-sage/slave/sage_git/build/local/lib/python2.7/site-packages/sage/interfaces/singular.py", line 798, in __call__
        return SingularElement(self, type, x, False)
      File "/Users/buildslave-sage/slave/sage_git/build/local/lib/python2.7/site-packages/sage/interfaces/singular.py", line 1279, in __init__
        self._name = parent._create(value, type)
      File "/Users/buildslave-sage/slave/sage_git/build/local/lib/python2.7/site-packages/sage/interfaces/singular.py", line 759, in _create
        self.set(type, name, value)
      File "/Users/buildslave-sage/slave/sage_git/build/local/lib/python2.7/site-packages/sage/interfaces/singular.py", line 702, in set
        self.eval(cmd)
      File "/Users/buildslave-sage/slave/sage_git/build/local/lib/python2.7/site-packages/sage/interfaces/singular.py", line 655, in eval
        s = Expect.eval(self, x, **kwds)
      File "/Users/buildslave-sage/slave/sage_git/build/local/lib/python2.7/site-packages/sage/interfaces/expect.py", line 1354, in eval
        for L in code.split('\n') if L != ''])
      File "/Users/buildslave-sage/slave/sage_git/build/local/lib/python2.7/site-packages/sage/interfaces/expect.py", line 942, in _eval_line
        self._synchronize()
      File "/Users/buildslave-sage/slave/sage_git/build/local/lib/python2.7/site-packages/sage/interfaces/expect.py", line 1284, in _synchronize
        self._sendstr(cmd)
      File "/Users/buildslave-sage/slave/sage_git/build/local/lib/python2.7/site-packages/sage/interfaces/expect.py", line 1226, in _sendstr
        self.quit()
      File "/Users/buildslave-sage/slave/sage_git/build/local/lib/python2.7/site-packages/sage/interfaces/expect.py", line 597, in quit
        self._expect.close()
      File "/Users/buildslave-sage/slave/sage_git/build/local/lib/python2.7/site-packages/pexpect/pty_spawn.py", line 327, in close
        self.ptyproc.close(force=force)
      File "sage/interfaces/sagespawn.pyx", line 199, in sage.interfaces.sagespawn.SagePtyProcess.close (build/cythonized/sage/interfaces/sagespawn.c:2940)
        self.write(str_to_bytes(self.quit_string))
      File "/Users/buildslave-sage/slave/sage_git/build/local/lib/python2.7/site-packages/ptyprocess/ptyprocess.py", line 562, in write
        return self._writeb(s, flush=flush)
      File "/Users/buildslave-sage/slave/sage_git/build/local/lib/python2.7/site-packages/ptyprocess/ptyprocess.py", line 552, in _writeb
        n = self.fileobj.write(b)
    ValueError: write to closed file
**********************************************************************
File "src/sage/interfaces/expect.py", line 768, in sage.interfaces.expect.Expect._eval_line_using_file
Failed example:
    singular.eval('quit;')
Exception raised:
    Traceback (most recent call last):
      File "/Users/buildslave-sage/slave/sage_git/build/local/lib/python2.7/site-packages/sage/doctest/forker.py", line 650, in _run
        self.compile_and_execute(example, compiler, test.globs)
      File "/Users/buildslave-sage/slave/sage_git/build/local/lib/python2.7/site-packages/sage/doctest/forker.py", line 1061, in compile_and_execute
        exec(compiled, globs)
      File "<doctest sage.interfaces.expect.Expect._eval_line_using_file[5]>", line 1, in <module>
        singular.eval('quit;')
      File "/Users/buildslave-sage/slave/sage_git/build/local/lib/python2.7/site-packages/sage/interfaces/singular.py", line 655, in eval
        s = Expect.eval(self, x, **kwds)
      File "/Users/buildslave-sage/slave/sage_git/build/local/lib/python2.7/site-packages/sage/interfaces/expect.py", line 1354, in eval
        for L in code.split('\n') if L != ''])
      File "/Users/buildslave-sage/slave/sage_git/build/local/lib/python2.7/site-packages/sage/interfaces/expect.py", line 942, in _eval_line
        self._synchronize()
      File "/Users/buildslave-sage/slave/sage_git/build/local/lib/python2.7/site-packages/sage/interfaces/expect.py", line 1284, in _synchronize
        self._sendstr(cmd)
      File "/Users/buildslave-sage/slave/sage_git/build/local/lib/python2.7/site-packages/sage/interfaces/expect.py", line 1226, in _sendstr
        self.quit()
      File "/Users/buildslave-sage/slave/sage_git/build/local/lib/python2.7/site-packages/sage/interfaces/expect.py", line 597, in quit
        self._expect.close()
      File "/Users/buildslave-sage/slave/sage_git/build/local/lib/python2.7/site-packages/pexpect/pty_spawn.py", line 327, in close
        self.ptyproc.close(force=force)
      File "sage/interfaces/sagespawn.pyx", line 199, in sage.interfaces.sagespawn.SagePtyProcess.close (build/cythonized/sage/interfaces/sagespawn.c:2940)
        self.write(str_to_bytes(self.quit_string))
      File "/Users/buildslave-sage/slave/sage_git/build/local/lib/python2.7/site-packages/ptyprocess/ptyprocess.py", line 562, in write
        return self._writeb(s, flush=flush)
      File "/Users/buildslave-sage/slave/sage_git/build/local/lib/python2.7/site-packages/ptyprocess/ptyprocess.py", line 552, in _writeb
        n = self.fileobj.write(b)
    ValueError: write to closed file
**********************************************************************

[vbraun]

Might have been due to other ticket, trying again

[vbraun]

**********************************************************************
File "src/sage/doctest/control.py", line 1161, in sage.doctest.control.DocTestController.run
Failed example:
    DC.run()
Expected:
    Running doctests with ID ...
    Using --optional=external,sage
    External software to be detected: ...
    Doctesting 1 file.
    sage -t ....py
        [0 tests, 0.00 s]
    ----------------------------------------------------------------------
    All tests passed!
    ----------------------------------------------------------------------
    Total time for all tests: 0.0 seconds
        cpu time: 0.0 seconds
        cumulative wall time: 0.0 seconds
    External software detected for doctesting:...
    0
Got:
    Running doctests with ID 2018-09-01-03-28-58-9687e9f6.
    Git branch: develop
    Using --optional=external,sage
    External software to be detected: cplex,ffmpeg,graphviz,gurobi,imagemagick,internet,latex,macaulay2,magma,maple,mathematica,matlab,octave,pandoc,scilab
    Doctesting 1 file.
    sage -t /home/buildbot/slave/sage_git/dot_sage/temp/sagebd07_64s02/8118/tmp_5ksam4.py
        [0 tests, 0.00 s]
    ----------------------------------------------------------------------
    All tests passed!
    ----------------------------------------------------------------------
    Total time for all tests: 0.1 seconds
        cpu time: 0.0 seconds
        cumulative wall time: 0.0 seconds
    External software detected for doctesting: 
    0
**********************************************************************
1 item had failures:
   1 of  13 in sage.doctest.control.DocTestController.run
    [206 tests, 1 failure, 4.49 s]
----------------------------------------------------------------------
sage -t --long src/sage/doctest/control.py  # 1 doctest failed
----------------------------------------------------------------------

[slabbe]

New commits:

​221a7db	Trac 25378: Don't close logfile before last message
​4f2d544	25378: adding a doctest
​4eb2799	25378: fixing issues seen by pyflakes
​4f8a7ac	Merge branch 'public/25378' into 8.4.beta1
​7c7e278	25378: better doctest
​1040475	25378: more robust doctest
​76f0177	25378: doctesting an empty file can take time

[vklein]

Can't the line Git branch: develop cause a doctest error too ?

[vklein]

No it can't as end of line ellipsis marker allow to skip lines as regular ellipsis marker.

[slabbe]

Exactly, this is what I thought. Thanks for the review. Hopefully everything is okay now. Last 6 patchbots reports are green (or contain unrelated failures with pbori.pyx and magma.py).

Sébastien