Opened 4 years ago

Closed 19 months ago

#26912 closed defect (fixed)

Test failure in doctest framework

Reported by: Timo Kaufmann Owned by:
Priority: major Milestone: sage-9.3
Component: doctest framework Keywords:
Cc: jdmeyer Merged in:
Authors: Erik Bray Reviewers: Frédéric Chapoton
Report Upstream: N/A Work issues:
Branch: ca5257a (Commits, GitHub, GitLab) Commit: ca5257a5d0f32efc9f8f07e126020856270b1a18
Dependencies: Stopgaps:

Status badges

Description (last modified by Jeroen Demeyer)

As discussed on sage-packaging, one of the test cases in src/sage/doctest/test.py sometimes fails when the system is under load. This was reproduced by Jeroen Demeyer with sage 8.5.rc0. Here's the log:

File "/nix/store/s1x3samyxif0mdg4l9v6abjzccc88b08-sage-src-8.4/src/sage/doctest/test.py", line 220, in sage.doctest.test
Failed example:
    subprocess.call(["sage", "-tp", "1000000", "--timeout=120",  # long time
         "--warn-long", "0", "99seconds.rst", "interrupt_diehard.rst"], **kwds2)
Expected:
    Running doctests...
    Doctesting 2 files using 1000000 threads.
    Killing test 99seconds.rst
    Killing test interrupt_diehard.rst
    ----------------------------------------------------------------------
    Doctests interrupted: 0/2 files tested
    ----------------------------------------------------------------------
    ...
    128
Got:
    Running doctests with ID 2018-12-17-16-27-41-26396051.
    Using --optional=dochtml,gmp,memlimit,nose,sage
    Doctesting 2 files using 1000000 threads.
    ------------------------------------------------------------------------
    Killing test 99seconds.rst
    Killing test interrupt_diehard.rst
    /nix/store/chdzkj17b8x0q42jnygpsjj9ccw2rasz-python-2.7.15-env/lib/python2.7/site-packages/cysignals/signals.so(+0x7bfb)[0x7ffff1a2bbfb]
    /nix/store/chdzkj17b8x0q42jnygpsjj9ccw2rasz-python-2.7.15-env/lib/python2.7/site-packages/cysignals/signals.so(+0x7cbf)[0x7ffff1a2bcbf]
    /nix/store/chdzkj17b8x0q42jnygpsjj9ccw2rasz-python-2.7.15-env/lib/python2.7/site-packages/cysignals/signals.so(+0xa7bb)[0x7ffff1a2e7bb]
    /nix/store/1mnsmslnx5anjfksac6417xfzzglrwhr-glibc-2.27/lib/libpthread.so.0(+0x11f10)[0x7ffff7592f10]
    /nix/store/vb3jdf8f9xq8aq77dq93csifdx3xkcwa-python-2.7.15/lib/libpython2.7.so.1.0(PyFrame_New+0xb5)[0x7ffff78294e5]
    /nix/store/vb3jdf8f9xq8aq77dq93csifdx3xkcwa-python-2.7.15/lib/libpython2.7.so.1.0(PyEval_EvalFrameEx+0x947a)[0x7ffff78b658a]
    /nix/store/vb3jdf8f9xq8aq77dq93csifdx3xkcwa-python-2.7.15/lib/libpython2.7.so.1.0(PyEval_EvalCodeEx+0x7b8)[0x7ffff78b6dd8]
    /nix/store/vb3jdf8f9xq8aq77dq93csifdx3xkcwa-python-2.7.15/lib/libpython2.7.so.1.0(PyEval_EvalFrameEx+0x6713)[0x7ffff78b3823]
    /nix/store/vb3jdf8f9xq8aq77dq93csifdx3xkcwa-python-2.7.15/lib/libpython2.7.so.1.0(PyEval_EvalCodeEx+0x7b8)[0x7ffff78b6dd8]
    /nix/store/vb3jdf8f9xq8aq77dq93csifdx3xkcwa-python-2.7.15/lib/libpython2.7.so.1.0(PyEval_EvalFrameEx+0x6713)[0x7ffff78b3823]
    /nix/store/vb3jdf8f9xq8aq77dq93csifdx3xkcwa-python-2.7.15/lib/libpython2.7.so.1.0(PyEval_EvalCodeEx+0x7b8)[0x7ffff78b6dd8]
    /nix/store/vb3jdf8f9xq8aq77dq93csifdx3xkcwa-python-2.7.15/lib/libpython2.7.so.1.0(PyEval_EvalFrameEx+0x6713)[0x7ffff78b3823]
    /nix/store/vb3jdf8f9xq8aq77dq93csifdx3xkcwa-python-2.7.15/lib/libpython2.7.so.1.0(PyEval_EvalCodeEx+0x7b8)[0x7ffff78b6dd8]
    /nix/store/vb3jdf8f9xq8aq77dq93csifdx3xkcwa-python-2.7.15/lib/libpython2.7.so.1.0(PyEval_EvalFrameEx+0x6713)[0x7ffff78b3823]
    /nix/store/vb3jdf8f9xq8aq77dq93csifdx3xkcwa-python-2.7.15/lib/libpython2.7.so.1.0(PyEval_EvalCodeEx+0x7b8)[0x7ffff78b6dd8]
    /nix/store/vb3jdf8f9xq8aq77dq93csifdx3xkcwa-python-2.7.15/lib/libpython2.7.so.1.0(PyEval_EvalFrameEx+0x6713)[0x7ffff78b3823]
    /nix/store/vb3jdf8f9xq8aq77dq93csifdx3xkcwa-python-2.7.15/lib/libpython2.7.so.1.0(PyEval_EvalCodeEx+0x7b8)[0x7ffff78b6dd8]
    /nix/store/vb3jdf8f9xq8aq77dq93csifdx3xkcwa-python-2.7.15/lib/libpython2.7.so.1.0(+0x8a109)[0x7ffff782a109]
    /nix/store/vb3jdf8f9xq8aq77dq93csifdx3xkcwa-python-2.7.15/lib/libpython2.7.so.1.0(PyObject_Call+0x43)[0x7ffff77f9043]
    /nix/store/vb3jdf8f9xq8aq77dq93csifdx3xkcwa-python-2.7.15/lib/libpython2.7.so.1.0(+0x6865c)[0x7ffff780865c]
    /nix/store/vb3jdf8f9xq8aq77dq93csifdx3xkcwa-python-2.7.15/lib/libpython2.7.so.1.0(PyObject_Call+0x43)[0x7ffff77f9043]
    /nix/store/vb3jdf8f9xq8aq77dq93csifdx3xkcwa-python-2.7.15/lib/libpython2.7.so.1.0(+0xcb3ba)[0x7ffff786b3ba]
    /nix/store/vb3jdf8f9xq8aq77dq93csifdx3xkcwa-python-2.7.15/lib/libpython2.7.so.1.0(PyObject_Call+0x43)[0x7ffff77f9043]
    /nix/store/vb3jdf8f9xq8aq77dq93csifdx3xkcwa-python-2.7.15/lib/libpython2.7.so.1.0(PyEval_EvalFrameEx+0x2d32)[0x7ffff78afe42]
    /nix/store/vb3jdf8f9xq8aq77dq93csifdx3xkcwa-python-2.7.15/lib/libpython2.7.so.1.0(PyEval_EvalCodeEx+0x7b8)[0x7ffff78b6dd8]
    /nix/store/vb3jdf8f9xq8aq77dq93csifdx3xkcwa-python-2.7.15/lib/libpython2.7.so.1.0(PyEval_EvalFrameEx+0x6713)[0x7ffff78b3823]
    /nix/store/vb3jdf8f9xq8aq77dq93csifdx3xkcwa-python-2.7.15/lib/libpython2.7.so.1.0(PyEval_EvalFrameEx+0x94cb)[0x7ffff78b65db]
    /nix/store/vb3jdf8f9xq8aq77dq93csifdx3xkcwa-python-2.7.15/lib/libpython2.7.so.1.0(PyEval_EvalCodeEx+0x7b8)[0x7ffff78b6dd8]
    /nix/store/vb3jdf8f9xq8aq77dq93csifdx3xkcwa-python-2.7.15/lib/libpython2.7.so.1.0(+0x8a109)[0x7ffff782a109]
    /nix/store/vb3jdf8f9xq8aq77dq93csifdx3xkcwa-python-2.7.15/lib/libpython2.7.so.1.0(PyObject_Call+0x43)[0x7ffff77f9043]
    /nix/store/vb3jdf8f9xq8aq77dq93csifdx3xkcwa-python-2.7.15/lib/libpython2.7.so.1.0(+0x6865c)[0x7ffff780865c]
    /nix/store/vb3jdf8f9xq8aq77dq93csifdx3xkcwa-python-2.7.15/lib/libpython2.7.so.1.0(PyObject_Call+0x43)[0x7ffff77f9043]
    /nix/store/vb3jdf8f9xq8aq77dq93csifdx3xkcwa-python-2.7.15/lib/libpython2.7.so.1.0(+0xcb6f2)[0x7ffff786b6f2]
    /nix/store/vb3jdf8f9xq8aq77dq93csifdx3xkcwa-python-2.7.15/lib/libpython2.7.so.1.0(+0xc7bba)[0x7ffff7867bba]
    /nix/store/vb3jdf8f9xq8aq77dq93csifdx3xkcwa-python-2.7.15/lib/libpython2.7.so.1.0(PyObject_Call+0x43)[0x7ffff77f9043]
    /nix/store/vb3jdf8f9xq8aq77dq93csifdx3xkcwa-python-2.7.15/lib/libpython2.7.so.1.0(PyEval_EvalFrameEx+0x2d32)[0x7ffff78afe42]
    /nix/store/vb3jdf8f9xq8aq77dq93csifdx3xkcwa-python-2.7.15/lib/libpython2.7.so.1.0(PyEval_EvalFrameEx+0x94cb)[0x7ffff78b65db]
    /nix/store/vb3jdf8f9xq8aq77dq93csifdx3xkcwa-python-2.7.15/lib/libpython2.7.so.1.0(PyEval_EvalCodeEx+0x7b8)[0x7ffff78b6dd8]
    /nix/store/vb3jdf8f9xq8aq77dq93csifdx3xkcwa-python-2.7.15/lib/libpython2.7.so.1.0(PyEval_EvalFrameEx+0x6713)[0x7ffff78b3823]
    /nix/store/vb3jdf8f9xq8aq77dq93csifdx3xkcwa-python-2.7.15/lib/libpython2.7.so.1.0(PyEval_EvalCodeEx+0x7b8)[0x7ffff78b6dd8]
    /nix/store/vb3jdf8f9xq8aq77dq93csifdx3xkcwa-python-2.7.15/lib/libpython2.7.so.1.0(PyEval_EvalFrameEx+0x6713)[0x7ffff78b3823]
    /nix/store/vb3jdf8f9xq8aq77dq93csifdx3xkcwa-python-2.7.15/lib/libpython2.7.so.1.0(PyEval_EvalCodeEx+0x7b8)[0x7ffff78b6dd8]
    /nix/store/vb3jdf8f9xq8aq77dq93csifdx3xkcwa-python-2.7.15/lib/libpython2.7.so.1.0(PyEval_EvalFrameEx+0x6713)[0x7ffff78b3823]
    /nix/store/vb3jdf8f9xq8aq77dq93csifdx3xkcwa-python-2.7.15/lib/libpython2.7.so.1.0(PyEval_EvalCodeEx+0x7b8)[0x7ffff78b6dd8]
    /nix/store/vb3jdf8f9xq8aq77dq93csifdx3xkcwa-python-2.7.15/lib/libpython2.7.so.1.0(PyEval_EvalFrameEx+0x6713)[0x7ffff78b3823]
    /nix/store/vb3jdf8f9xq8aq77dq93csifdx3xkcwa-python-2.7.15/lib/libpython2.7.so.1.0(PyEval_EvalCodeEx+0x7b8)[0x7ffff78b6dd8]
    /nix/store/vb3jdf8f9xq8aq77dq93csifdx3xkcwa-python-2.7.15/lib/libpython2.7.so.1.0(PyEval_EvalFrameEx+0x6713)[0x7ffff78b3823]
    /nix/store/vb3jdf8f9xq8aq77dq93csifdx3xkcwa-python-2.7.15/lib/libpython2.7.so.1.0(PyEval_EvalCodeEx+0x7b8)[0x7ffff78b6dd8]
    /nix/store/vb3jdf8f9xq8aq77dq93csifdx3xkcwa-python-2.7.15/lib/libpython2.7.so.1.0(PyEval_EvalCode+0x19)[0x7ffff78b6fe9]
    /nix/store/vb3jdf8f9xq8aq77dq93csifdx3xkcwa-python-2.7.15/lib/libpython2.7.so.1.0(PyRun_FileExFlags+0x8a)[0x7ffff78d9c8a]
    /nix/store/vb3jdf8f9xq8aq77dq93csifdx3xkcwa-python-2.7.15/lib/libpython2.7.so.1.0(PyRun_SimpleFileExFlags+0xe3)[0x7ffff78dbbc3]
    /nix/store/vb3jdf8f9xq8aq77dq93csifdx3xkcwa-python-2.7.15/lib/libpython2.7.so.1.0(Py_Main+0xb4a)[0x7ffff78f4ada]
    /nix/store/1mnsmslnx5anjfksac6417xfzzglrwhr-glibc-2.27/lib/libc.so.6(__libc_start_main+0xee)[0x7ffff6a52b8e]
    /nix/store/vb3jdf8f9xq8aq77dq93csifdx3xkcwa-python-2.7.15/bin/python(_start+0x2a)[0x4007fa]
    ------------------------------------------------------------------------
    ----------------------------------------------------------------------
    Doctests interrupted: 0/2 files tested
    ----------------------------------------------------------------------
    Total time for all tests: 0.1 seconds
        cpu time: 0.0 seconds
        cumulative wall time: 0.0 seconds
    Attaching gdb to process id 6834.
    Cannot find gdb installed
    GDB is not installed.
    Install gdb for enhanced tracebacks.
    ------------------------------------------------------------------------
    128

Change History (13)

comment:1 Changed 4 years ago by Timo Kaufmann

@Jeroen

Unfortunately, I don't manage to reproduce it reliably enough to be able to fix it.

Thats unfortunate. Do you think it may have something to do with the "ridiculous number of threads"?

comment:2 Changed 4 years ago by Jeroen Demeyer

Component: packages: standarddoctest framework
Description: modified (diff)
Keywords: cysignals removed
Summary: cysignals related test failure in test.pyTest failure in doctest framework

As I mentioned before, I don't think that this is related to cysignals in any way.

comment:3 Changed 4 years ago by Jeroen Demeyer

Description: modified (diff)

comment:4 Changed 4 years ago by Timo Kaufmann

Oh, I misunderstood. I thought you only meant that the update to 1.8.0 wasn't responsible.

comment:5 Changed 4 years ago by Erik Bray

Milestone: sage-8.6sage-8.7

Retarging tickets optimistically to the next milestone. If you are responsible for this ticket (either its reporter or owner) and don't believe you are likely to complete this ticket before the next release (8.7) please retarget this ticket's milestone to sage-pending or sage-wishlist.

comment:6 Changed 4 years ago by Erik Bray

Milestone: sage-8.7sage-8.8

Ticket retargeted after milestone closed (if you don't believe this ticket is appropriate for the Sage 8.8 release please retarget manually)

comment:7 Changed 3 years ago by Erik Bray

Milestone: sage-8.8

As the Sage-8.8 release milestone is pending, we should delete the sage-8.8 milestone for tickets that are not actively being worked on or that still require significant work to move forward. If you feel that this ticket should be included in the next Sage release at the soonest please set its milestone to the next release milestone (sage-8.9).

comment:8 Changed 19 months ago by Erik Bray

I'm seeing something like this quite frequently since trying to test the fix to #30945:

$ SAGE_TIMEOUT=3 sage -t --warn-long 0 --random-seed=0 src/sage/doctest/tests/99seconds.rst 
Running doctests with ID 2021-03-08-14-48-11-b862a4f7.
Git branch: u/embray/gappy-without-wrappers
Using --optional=build,debian,dochtml,memlimit,pip,rubiks,sage,sage_spkg
Doctesting 1 file.
sage -t --warn-long 0.0 --random-seed=0 src/sage/doctest/tests/99seconds.rst
    Timed out (and interrupt failed)
**********************************************************************
Tests run before process (pid=7821) timed out:
sage: import time ## line 3 ##
sage: time.sleep(99) ## line 4 ##
------------------------------------------------------------------------
/home/embray/src/sagemath/sage/local/lib/python3.6/site-packages/cysignals/signals.cpython-36m-x86_64-linux-gnu.so(+0x6a6b)[0x7f4ccad87a6b]
/home/embray/src/sagemath/sage/local/lib/python3.6/site-packages/cysignals/signals.cpython-36m-x86_64-linux-gnu.so(+0x6c48)[0x7f4ccad87c48]
/home/embray/src/sagemath/sage/local/lib/python3.6/site-packages/cysignals/signals.cpython-36m-x86_64-linux-gnu.so(+0x90fa)[0x7f4ccad8a0fa]
<long stacktrace>
------------------------------------------------------------------------
Attaching gdb to process id 7821.

**********************************************************************
----------------------------------------------------------------------
sage -t --warn-long 0.0 --random-seed=0 src/sage/doctest/tests/99seconds.rst  # Timed out (and interrupt failed)
----------------------------------------------------------------------
Total time for all tests: 63.0 seconds
    cpu time: 0.0 seconds
    cumulative wall time: 0.0 seconds

comment:9 Changed 19 months ago by Erik Bray

I think I might know the reason in my case. The doctest runner gives test processes timeout * 0.05 to die after they are sent a SIGQUIT due to timeout. After this "die timeout" they are killed with SIGKILL. This is the case in which the doctest reporter reports "Timed out (and interrupt failed)" as opposed to just "Timed out" (the message is a bit deceptive since the "interrupt" in question is a SIGQUIT).

The sigdie() in cysignals, in response to the SIGQUT is calling print_enhanced_backtrace() which fires up the cysignals-CSI machinery and starts up gdb. Normally this is happening within the "die timeout" limit, but since I was working on #30945 I have some plugins loaded for gdb which are making it take longer to start up, resulting in the process not dying fast enough.

I'm going to try running this test with CYSIGNALS_CRASH_NDEBUG=1 and see if that makes a difference.

comment:10 Changed 19 months ago by Erik Bray

I'll note that in the original ticket report it shows that gdb is not installed at all in that case. But it's still conceivable that, especially on a system under load, just trying to start the cysignals-CSI script creates enough overhead that the process doesn't quit quickly enough.

comment:11 Changed 19 months ago by Erik Bray

Authors: Erik Bray
Branch: u/embray/ticket-26912
Commit: ca5257a5d0f32efc9f8f07e126020856270b1a18
Milestone: sage-9.3
Status: newneeds_review

This should fix it in most cases. It's not a silver bullet, but it should greatly reduce the likelihood of this (already rare) test failure.


New commits:

ca5257aTrac #26912: Improve the likelihood of these tests passing.

comment:12 Changed 19 months ago by Frédéric Chapoton

Reviewers: Frédéric Chapoton
Status: needs_reviewpositive_review

ok, let's do that

comment:13 Changed 19 months ago by Volker Braun

Branch: u/embray/ticket-26912ca5257a5d0f32efc9f8f07e126020856270b1a18
Resolution: fixed
Status: positive_reviewclosed
Note: See TracTickets for help on using tickets.