Opened 11 years ago

Closed 10 years ago

#9446 closed defect (fixed)

misc/trace.py doctest failure

Reported by: jhpalmieri Owned by: mvngu
Priority: major Milestone: sage-4.7.1
Component: doctest coverage Keywords:
Cc: drkirkby, justin, mhansen Merged in: sage-4.7.1.alpha2
Authors: Mitesh Patel Reviewers: Mariah Lenox
Report Upstream: N/A Work issues:
Branch: Commit:
Dependencies: Stopgaps:

Status badges

Description (last modified by mpatel)

With Sage 4.5.alpha4 on t2.math.washington.edu (solaris):

sage -t  -long devel/sage/sage/misc/trace.py
**********************************************************************
File "/home/palmieri/t2/sage-4.5.alpha4/devel/sage-main/sage/misc/trace.py", line 54:
    sage: _ = s.expect('100')
Exception raised:
    Traceback (most recent call last):
      File "/home/palmieri/t2/sage-4.5.alpha4/local/bin/ncadoctest.py", line 1231, in run_one_test
        self.run_one_example(test, example, filename, compileflags)
      File "/home/palmieri/t2/sage-4.5.alpha4/local/bin/sagedoctest.py", line 38, in run_one_examp\
le
        OrigDocTestRunner.run_one_example(self, test, example, filename, compileflags)
      File "/home/palmieri/t2/sage-4.5.alpha4/local/bin/ncadoctest.py", line 1172, in run_one_exam\
ple
        compileflags, 1) in test.globs
      File "<doctest __main__.example_1[6]>", line 1, in <module>
        _ = s.expect('100')###line 54:
    sage: _ = s.expect('100')
      File "/home/palmieri/t2/sage-4.5.alpha4/local/lib/python/site-packages/pexpect.py", line 912\
, in expect
        return self.expect_list(compiled_pattern_list, timeout, searchwindowsize)
      File "/home/palmieri/t2/sage-4.5.alpha4/local/lib/python/site-packages/pexpect.py", line 989\
, in expect_list
        raise TIMEOUT (str(e) + '\n' + str(self))
    TIMEOUT: Timeout exceeded in read_nonblocking().
    <pexpect.spawn instance at 0x2c005d0>
    version: 2.0 ($Revision: 1.151 $)
    command: /home/palmieri/t2/sage-4.5.alpha4/sage
    args: ['/home/palmieri/t2/sage-4.5.alpha4/sage']
    patterns:
        100
    buffer (last 100 chars):
    before (last 100 chars):                       *^M
    **********************************************************************^M
    c^M

    after: <class 'pexpect.TIMEOUT'>
    match: None
    match_index: None
    exitstatus: None
    flag_eof: 0
    pid: 22383
    child_fd: 4
    timeout: 30
    delimiter: <class 'pexpect.EOF'>
    logfile: None
    maxread: 2000
    searchwindowsize: None
    delaybeforesend: 0.1
**********************************************************************
File "/home/palmieri/t2/sage-4.5.alpha4/devel/sage-main/sage/misc/trace.py", line 61:
    sage: print s.before[s.before.find('-'):]
Expected:
    ---...
    ipdb> c
    2 * 5
Got:
    ----------------------------------------------------------------------^M
    | Sage Version 4.5.alpha4, Release Date: 2010-07-06                  |^M
    | Type notebook() for the GUI, and license() for information.        |^M
    ----------------------------------------------------------------------^M
    **********************************************************************^M
    *                                                                    *^M
    * Warning: this is a prerelease version, and it may be unstable.     *^M
    *                                                                    *^M
    **********************************************************************^M
    c^M
    <BLANKLINE>
**********************************************************************

Is this due to something timing out?

Attachments (1)

trac_9446-trace_doctest_timeout.patch (774 bytes) - added by mpatel 11 years ago.
Increase pexpect timeout for test

Download all attachments as: .zip

Change History (16)

comment:1 Changed 11 years ago by drkirkby

This does not look like a timeout to me - at least not like one I've seen. Have you set something like the following?

SAGE_TIMEOUT_LONG=10000
SAGE_TIMEOUT=1000
export SAGE_TIMEOUT_LONG
export SAGE_TIMEOUT

I'm just making a build on t2 myself. I'll see if I get this issue.

comment:2 Changed 11 years ago by drkirkby

This is odd:

kirkby@t2:[/tmp/kirkby/sage-4.5.alpha4] $ ./sage -t  -long devel/sage/sage/misc/trace.py
sage -t -long "devel/sage/sage/misc/trace.py"               
	 [29.7 s]
 
----------------------------------------------------------------------
All tests passed!
Total time for all tests: 29.7 seconds
kirkby@t2:[/tmp/kirkby/sage-4.5.alpha4] $ 

Can you retry the test John.

I'm personally quite suspicious about using /home anywhere on *.math.washington.edu, since I'm aware the NFS directories are shared from a server (disk.math) which has the default configuration of the pools modified to increase performance, in a manner which risks data corruption on NFS shares.

Dave

comment:3 follow-up: Changed 11 years ago by jhpalmieri

  • Priority changed from blocker to minor

The first three times I ran the test, I had a failure. Now I've run it without a failure, too, so I'm changing the "blocker" status.

Since it's not even reproducible, should this ticket be closed?

comment:4 in reply to: ↑ 3 Changed 11 years ago by drkirkby

Replying to jhpalmieri:

The first three times I ran the test, I had a failure. Now I've run it without a failure, too, so I'm changing the "blocker" status.

Since it's not even reproducible, should this ticket be closed?

I think not yet. There are a lot of doctest failures which seem to not be reproducible. I think something is screwed up with the doctesting framework myself.

comment:5 follow-up: Changed 11 years ago by mpatel

  • Cc justin added
  • Component changed from misc to doctest
  • Description modified (diff)
  • Owner changed from jason to mvngu

Justin Walker has seen this problem with 4.6.alpha2 on two OS X 10.6.4 systems (Dual Quad Xeon, Core i7):

sage -t  -long devel/sage/sage/misc/trace.py
**********************************************************************
File "/Users/Sage/sage-4.6.alpha0/devel/sage-main/sage/misc/trace.py", line 61:
    sage: print s.before[s.before.find('-'):]
Expected:
    ---...
    ipdb> c
    2 * 5
Got:
    -bit mode
    Creating SAGE_LOCAL/lib/sage-64.txt since it does not exist
    Detected SAGE64 flag
    Building Sage on OS X in 64-bit mode
    ----------------------------------------------------------------------
    | Sage Version 4.6.alpha2, Release Date: 2010-09-29                  |
    | Type notebook() for the GUI, and license() for information.        |
    ----------------------------------------------------------------------
    **********************************************************************
    *                                                                    *
    * Warning: this is a prerelease version, and it may be unstable.     *
    *                                                                    *
    **********************************************************************
    trace('print factor(10)'); print 3+97
    s
    c
    sage: trace('print factor(10)'); print 3+97
    > <string>(1)<module>()
    
    ipdb> s
    --Call--
    > /Users/Sage/sage-4.6.alpha0/local/lib/python2.6/site-packages/sage/rings/arith.py(2153)factor()
       2152 
    -> 2153 def factor(n, proof=None, int_=False, algorithm='pari', verbose=0, **kwds):
       2154     """
    
    ipdb> c
    2 * 5
    <BLANKLINE>

comment:6 Changed 11 years ago by mpatel

  • Summary changed from misc/trace.py doctest failure on t2 (solaris) to misc/trace.py doctest failure

comment:7 Changed 11 years ago by drkirkby

I'm changing the priority of this to the default "major" since it was only changed to minor when it was thought to be almost a non-issue.

Dave

comment:8 Changed 11 years ago by drkirkby

  • Priority changed from minor to major

comment:9 Changed 11 years ago by mpatel

Maybe the problem is that pexpect's default timeout (30 seconds) is exceeded under load. For example

sage: import pexpect
sage: s = pexpect.spawn('sage')
sage: _ = s.sendline("trace('print factor(10)'); import time; time.sleep(31); print 3+97")
sage: _ = s.sendline("s"); _ = s.sendline("c");
sage: _ = s.expect('100')
---------------------------------------------------------------------------
TIMEOUT                                   Traceback (most recent call last)
[...]
TIMEOUT: Timeout exceeded in read_nonblocking().
<pexpect.spawn instance at 0x6d9d88>
version: 2.0 ($Revision: 1.151 $)
command: /home/mpatel/apps/sage/sage
args: ['/home/mpatel/apps/sage/sage']
patterns:
    100
buffer (last 100 chars):
before (last 100 chars): , proof=None, int_=False, algorithm='pari', verbose=0, **kwds):
   2154     """

ipdb> c
2 * 5

after: <class 'pexpect.TIMEOUT'>
match: None
match_index: None
exitstatus: None
flag_eof: 0
pid: 29286
child_fd: 3
timeout: 30
delimiter: <class 'pexpect.EOF'>
logfile: None
maxread: 2000
searchwindowsize: None
delaybeforesend: 0.1
sage: 

comment:10 Changed 11 years ago by mpatel

With

def example(verbose=False, **kwargs):
    error = False
    try:
        import pexpect
        s = pexpect.spawn('sage')
        _ = s.sendline("trace('print factor(10)'); print 3+97")
        _ = s.sendline("s"); _ = s.sendline("c");
        _ = s.expect('100', timeout=kwargs['timeout'])
        t = s.before[s.before.find('-'):]
        if not t.strip().endswith('ipdb> c\r\n2 * 5'):
            raise Exception('"Got" does not match "Expected"')

    except Exception as exc:
        error = True
        if verbose:
            print exc
    return error

def runner(n=1000, verbose=False, **kwargs):
    fail = 0
    for i in xrange(n):
        fail += example(verbose, **kwargs)
    return fail

runner(100, timeout=1)

I get 13 failures on sage.math, at least some of which I may have induced with a simultaneous sage -tp. This 4.6.alpha3 installation is under /scratch.

Changed 11 years ago by mpatel

Increase pexpect timeout for test

comment:11 Changed 11 years ago by mpatel

  • Authors set to Mitesh Patel
  • Status changed from new to needs_review

I've attached a patch that increases the timeout to 90 seconds.

comment:12 Changed 11 years ago by mpatel

  • Cc mhansen added

comment:13 in reply to: ↑ 5 Changed 11 years ago by mpatel

Replying to mpatel:

Justin Walker has seen this problem with 4.6.alpha2 on two OS X 10.6.4 systems (Dual Quad Xeon, Core i7):

See #10138 for this problem, which is specific to 64-bit builds.

comment:14 Changed 10 years ago by mariah

  • Reviewers set to Mariah Lenox
  • Status changed from needs_review to positive_review

I did 'make NUM_THREADS=10 ptestlong' on a 4.7.rc4 build on skynet/eno and had one test failure, which passed with I ran it individually. (So I suspect a timeout problem.) I then applied the patch and did 'make NUM_THREADS=10 ptestlong' again, and this time all the tests passed.

Positive review.

comment:15 Changed 10 years ago by jdemeyer

  • Merged in set to sage-4.7.1.alpha2
  • Resolution set to fixed
  • Status changed from positive_review to closed
Note: See TracTickets for help on using tickets.