Testsuite exhibits large amount of framework failures

changed weight to 5

changed title from Testsuite exibits large amount of framework failures to Testsuite exhibits large amount of framework failures

mentioned in issue #12661 (closed)

Indeed I am also seeing this on the new Windows build bot.

Taking a look again, but my Python foo is weak..

I wonder if the testsuite driver is attempting to run the same test in multiple ways at concurrently, therefore attempting to copy the same file into place more than once. thomie, does this ring any bells?

Oh, right, we disable threading on Windows. Never mind then.

Well, my TeamCity runs patch the testrunner to run in parallel.

The weird thing is, it doesn't happen on my old msys installs, with python 3.4.3, I don't know if this started because of a change in python or the msys runtime.

Another odd thing is that I would expect the tests that trigger this to be pretty random. But according to my teamcity data of the past ~1 month, the tests that fail are pretty stable. +- 3-4 tests each run, but all in the same category. Mostly the TH tests.

I have my doubts about the threadsafety of the testsuite. In particular, the location of the function that's failing is right after a rmtree call that's supposed to ensure the path doesn't exist. Yet it does.

Also I see that only relative paths are used in all directory name. I can only assume that it's relative to the cwd as explicit shell commands are issued to change the shell's cwd. Why the python call for this is not used I don't understand.

I must be missing something since this is reliably working on Linux..

Alright, I think I see what is going on here.

But first some background. The testsuite driver runs each testcase in its own fresh directory to ensure a clean test environment. The code responsible for this can be found in testlib.do_test(). This looks something like the following,

def do_test(name, way, func, args, files):
    opts = getTestOpts()
    shutil.rmtree(opts.testdir, ignore_errors=True)
    os.makedirs(opts.testdir)

    # Copy test files into testdir and run test
    ...

Note how we invoke rmtree with ignore_errors=True, presumably to account for the fact that testdir may not exist (e.g. if we are running in a fresh working directory). However, this unfortunately hides any **real** errors that we may encounter while trying to delete testdir, in which case we'll attempt to create testdir when it already exists.

This appears to be precisely what happens some fraction of the time on Windows. Namely, if we rework do_test as follows,

def do_test(name, way, func, args, files):
    opts = getTestOpts()
    if os.path.exists(opts.testdir):
        print('cleaning %s' % opts.testdir)
        shutil.rmtree(opts.testdir, ignore_errors=False)
    os.makedirs(opts.testdir)

    # Copy test files into testdir and run test
    ...

We find the following,

=====> TH_nameSpace(ext-interp) 39 of 42 [0, 3, 12]
cleaning ./th/TH_nameSpace.run
*** framework failure for TH_nameSpace(ext-interp) [Error 5] Access is denied: './th/TH_nameSpace.run/TH_nameSpace.exe'

I suspect this is due to the fact that, on Windows, executable images of running programs are locked and therefore cannot be deleted. The strange thing here is that the process has presumably already terminated. It seems like the test process must still be in some sort of zombie state where it has terminated and we have its exit code, but its resources (e.g. executable image) have still not been released.

As one would expect, adding a time.sleep(0.1) before the rmtree hides the issue. It's not clear to me what the proper solution is here.

Attached file Logfile.CSV (download).

I/O trace

That (though filtering on the python process, will make a wider filter now, seems to indicate, that at least the stderr is still locked when it tries to delete the folder.)

oh and I seem to get a different error from you

=====> TH_repGuardOutput(ext-interp) 17 of 239 [0, 9, 8]
cleaning ./TH_repGuardOutput.run
cd "./TH_spliceE5_prof.run" && $MAKE -s --no-print-directory TH_spliceE5_prof
*** framework failure for TH_repGuardOutput(ext-interp) [Error 32] The process cannot access the file because it is being used by another process: './TH_repGuardOutput.run/TH_repGuardOutput.comp.stderr'

Attached file cgrun035.zip (download).

Zipped ProcMon log of a failure of cgrun035

Attached file ProcessName=cgrun035.exe.CSV (download).

Different subset of the same trace, this time filtered on processname=cgrun035

I spent quite a while today cleaning up the testsuite driver's Python 3 compatibility story and it seems that Python 3.5.2 is significantly less buggy than 2.7.11 with respect to this issue..

Here is a fairly minimal testcase which reproduces the issue. Phyx-, can you verify that this doesn't crash in your working environment? I used some random executable produced by the testsuite for test.exe.

#!/usr/bin/python

import sys
import subprocess
import os
import os.path
import time
import shutil

d = 'testdir'
f = d + '/test.exe'
log = d + '/log'
if os.path.exists(d):
    shutil.rmtree(d)

while True:
    os.makedirs(d)
    shutil.copy('test.exe', f)
    subprocess.check_call(f, stdout=open(log, 'w'))
    time.sleep(0.04)
    shutil.rmtree(d)
    print '.',
    sys.stdout.flush()

@bgamari, yes the script works fine for me as well.

that said, it also doesn't crash without the sleep in there. May be my test.exe is too simple? it's just "print 123" atm.

Usage of ignore_errors=True was sloppy program, sorry about that.

It would be better to revert back to the original (working and commented) code:

def clean_full_path(name):
        try:
            # Remove files...
            os.remove(name)
        except OSError as e1:
            try:
                # ... and empty directories
                os.rmdir(name)
            except OSError as e2:
                # We don't want to fail here, but we do want to know
                # what went wrong, so print out the exceptions.
                # ENOENT isn't a problem, though, as we clean files
                # that don't necessarily exist.
                if e1.errno != errno.ENOENT:
                    print(e1)
                if e2.errno != errno.ENOENT:
                    print(e2)

On the real bug: you could try to eliminate any possible problems with timeout:

-     r = subprocess.call([timeout_prog, timeout, cmd],
+     r = subprocess.call(['sh', '-c', cmd],

On Windows the testsuite uses a timeout program written in Haskell, on all other platforms timeout is written in Python. I'm not quite sure why two separate versions exist, but all the code is in testsuite/timeout.

Fwiw: I couldn't reproduce this issue myself, last time I tried.

I pushed some patches which I was testing with to D2598. They cover a few things including Python 3 compatibility, working around the cleanup issue described above, disabling usage of symlinks on Windows (since they require administrator privileges)n and marking a few tests as broken. Unfortunately the cleanup workaround only narrows the Window and does not close it entirely.

Phyx- has isolated the cleanup problem as being a regression in the msys2-runtime package. 2.5.1 apparently works but 2.5.2 seems to fail.

Alright, so I've been trying to work out how to downgrade our Windows builder to a non-broken version of msys2-runtime (namely 2.5.1). It seems that the current installer executable ships with a 2.6 runtime, which is not compatible with the 2.5 series. Consequently it is necessary to use a release from July 2016 instead (http://repo.msys2.org/distrib/x86_64/msys2-base-x86_64-20160719.tar.xz). From this release you can downgrade the runtime with pacman -U. Namely I'm using http://repo.msys2.org/msys/x86_64/msys2-runtime-2.5.1-1-x86_64.pkg.tar.xz.

So we're still at it. The current state of things is that,

msys python-3.4.3 works with msys2-runtime < 2.5.2
msys `python-3.4.3`` does not work with runtime 2.5.1 nor 2.5.2
- mingw python-2.7.11 does not work with either runtime
- mingw python-3.5.2 does not work with either runtime In all cases the failure mode is error 183 during test directory deletion.
In light of this it seems likely that there are two bugs:
- CPython has a Windows compatibility bug (hence none of the mingw builds work)
- msys2-runtime \>= 2.5.2 has a regression
While the msys2-runtime\ issue is likely easier to track down since its a regression over a rather small diff, it's unfortunately not the issue we really care about. We'd far prefer to have mingw python working; unfortunately this is a much harder issue to debug.

Phyx- contributed another invaluable data point:

mingw python-3.4.3 works with runtime 2.5.1

So it seems that there is very likely a Python regression between 3.4.3 and 3.5.2

Phyx- also tested mingw python-3.4.3 with runtime 2.5.2. It failed, although perhaps not as frequently as with runtime 2.5.1.

Phyx said that his nightly server has been reliably running msys python-3.4.3 and msys2-runtime 2.5.0 for quite some time.

Not my nightly, my main development machine.

Phyx- ran a run on his server to msys2-runtime 2.5.0 and mingw python-3.4.3 and found that it too failed.

Two runs with msys python-3.4.3 and msys-runtime-2.5.0 passed cleanly.

mentioned in commit 17d696f1

mentioned in commit 9cb44598

mentioned in commit 2864ad79

Trac metadata

Trac field	Value
Differential revisions	- → D2684

mentioned in commit 4d4f3533

Phyx has put in a herculean effort to try to fix up the testsuite driver in D2684. Unfortunately, while the result works on Harbormaster and RyanGlScott's machine, it still fails for me. However, it turns out that only mingw-w64 Python 2.7 is affected.

Given that maintaining Python 2 support is already becoming rather tiresome and that Python 3 seems to work just fine, I say let's just deprecate Python 2 support in the testsuite driver. I've proposed this as D2766.

mentioned in commit 605bb9b4

mentioned in commit 0ce59be3

closed

changed milestone to %8.2.1

This should at long last be fixed by the above two patches.

Trac metadata

Trac field	Value
Resolution	Unresolved → ResolvedFixed

added incorrect runtime result label

added Pnormal label

Trac field	Value
Version	8.0.1
Type	Bug
TypeOfFailure	OtherFailure
Priority	normal
Resolution	Unresolved
Component	Test Suite
Test case
Differential revisions
BlockedBy
Related
Blocking
CC
Operating system
Architecture

Testsuite exhibits large amount of framework failures

Child items 0

Activity