Testsuite: open/close stdout and stderr manually
ClosedPublic

Authored by thomie on Sep 9 2015, 8:21 AM.

Details

Summary

Before, we were doing something like the following:

subprocess.call('command > test.run.stdout 2> test.run.stderr')

On Windows (msys2), it was somehow possible for this command to succeed,
without actually creating the output files (they show up a bit later).
This causes some tests to sporadically fail (e.g. T7037), because we
read those output files right after we write them.

To fix it, we now do:

stdout = open('test.run.stdout')
stderr = open('test.run.stderr')
subprocess.call('command', stdout=stdout, stderr=stderr)
stdout.close()
stderr.close()

This whole thing was a known issue, as evidenced by a comment in
read_no_crs:
"On Windows, if the program fails very early, it seems the
files stdout/stderr are redirected to may not get created"

I'm also wondering why we redirect stdout/stderr to file in the first
place, since we're going to read those files shortly after, and then
delete them when CLEANUP=1. But that's for another time.

Diff Detail

Repository
rGHC Glasgow Haskell Compiler
Lint
Automatic diff as part of commit; lint not applicable.
Unit
Automatic diff as part of commit; unit tests not applicable.
thomie updated this revision to Diff 4130.Sep 9 2015, 8:21 AM
thomie retitled this revision from to Testsuite: open/close stdout and stderr manually.
thomie updated this object.
thomie edited the test plan for this revision. (Show Details)
thomie added a reviewer: Phyx.Sep 9 2015, 11:10 AM
thomie added a subscriber: Phyx.

@Phyx: could you test if this fixes T7037 for you?

Phyx edited edge metadata.Sep 9 2015, 11:35 AM

Sweet, I'll give it a go right away :)

Phyx added a comment.Sep 9 2015, 4:06 PM

Unfortunately it still fails for me. And the time.sleep(1) still works. should we maybe explicitly flush the buffers?

$ make TESTS=T7037
python2 ../../driver/runtests.py  -e ghc_compiler_always_flags="'-fforce-recomp -dcore-lint -dcmm-lint -dno-debug-output -no-user-package-db -rtsopts  -fno-warn-tabs -fno-warn-missed-specialisations'" -e ghc_debugged=False -e ghc_with_native_codegen=1 -e ghc_with_vanilla=1 -e ghc_with_dynamic=0 -e ghc_with_profiling=0 -e ghc_with_threaded_rts=1 -e ghc_with_dynamic_rts=0 -e ghc_with_interpreter=1 -e ghc_unregisterised=0 -e ghc_dynamic_by_default=False -e ghc_dynamic=False -e ghc_with_smp=1 -e ghc_with_llvm=0 -e windows=True -e darwin=False -e in_tree_compiler=True -e clean_only=False --rootdir=. --configfile=../../config/ghc -e 'config.confdir="../../config"' -e 'config.platform="x86_64-unknown-mingw32"' -e 'config.os="mingw32"' -e 'config.arch="x86_64"' -e 'config.wordsize="64"' -e 'default_testopts.cleanup=""' -e 'config.timeout=int() or config.timeout' -e 'config.exeext=".exe"' -e 'config.top="E:/msys64/home/Tamar/ghc2/testsuite"' --config 'compiler="E:/msys64/home/Tamar/ghc2/inplace/bin/ghc-stage2.exe"' --config 'ghc_pkg="E:/msys64/home/Tamar/ghc2/inplace/bin/ghc-pkg.exe"' --config 'haddock="E:/msys64/home/Tamar/ghc2/inplace/bin/haddock.exe"' --config 'hp2ps="E:/msys64/home/Tamar/ghc2/inplace/bin/hp2ps.exe"' --config 'hpc="E:/msys64/home/Tamar/ghc2/inplace/bin/hpc.exe"' --config 'gs="gs"' --config 'timeout_prog="../../timeout/install-inplace/bin/timeout.exe"'  \
         \
         --only=T7037 \
         \
         \
         \
         \

Timeout is 300
Found 3 .T files...
Beginning test run at Wed Sep  9 23:00:33 2015 CEST
====> Scanning ./all.T
====> Scanning ./T5644/all.T
====> Scanning ./T9579/all.T
=====> T7037(normal) 1 of 1 [0, 0, 0]
cd . && $MAKE -s --no-print-directory T7037    </dev/null
Actual stdout output differs from expected:
--- ./T7037.stdout.normalised   2015-09-09 23:00:43.566050900 +0200
+++ ./T7037.run.stdout.normalised       2015-09-09 23:00:43.566050900 +0200
@@ -1 +0,0 @@
-"ok"
\ No newline at end of file
*** unexpected failure for T7037(normal)

Unexpected results from:
TEST="T7037"

OVERALL SUMMARY for test run started at Wed Sep  9 23:00:33 2015 CEST
 0:00:11 spent to go through
       1 total tests, which gave rise to
       1 test cases, of which
       0 were skipped

       0 had missing libraries
       0 expected passes
       0 expected failures

       0 caused framework failures
       0 unexpected passes
       1 unexpected failures
       0 unexpected stat failures

Unexpected failures:
   .  T7037 [bad stdout] (normal)


Tamar@Kino MINGW64 ~/ghc2/testsuite/tests/rts
$ cat ./T7037.run.stdout
"ok"

Tamar@Kino MINGW64 ~/ghc2/testsuite/tests/rts
$ cat ./T7037.run.stdout.normalised

Tamar@Kino MINGW64 ~/ghc2/testsuite/tests/rts
$
Phyx added a comment.Sep 9 2015, 4:39 PM

Particularly, what I meant was, should we force a call to os.fsync ? Or any of the other methods to get unbuffered stdout in Python?

This seems to be working for me, changing rawSystem to call

if stdout is not None:
    os.fsync(stdout)
    stdout.close()
if stderr is not None and stderr is not subprocess.STDOUT:
    os.fsync(stderr)
    stderr.close()

Is now consistently making the test pass.

thomie added a comment.Sep 9 2015, 5:09 PM

Great. The documentation says:

If you’re starting with a Python file object f, first do f.flush(), and then do os.fsync(f.fileno()), to ensure that all internal buffers associated with f are written to disk.

https://docs.python.org/2/library/os.html#os.fsync

thomie planned changes to this revision.Sep 9 2015, 5:12 PM

Actually, I will also try the other approach I mentioned. Don't redirect stdout/stderr to file at all, or only when there is a test failure.

thomie added a comment.EditedSep 10 2015, 7:44 AM

@Phyx:
To be sure: on your system, the following program doesn't print anything?

import os
f = open('/tmp/test.txt', 'w')
f.write('foo')
f.close()
f = open('/tmp/test.txt')
print f.read()

Note that f.close() calls f.flush(), but not os.fsync. I would like to understand why syncing to disk is necessary.

Phyx added a comment.Sep 10 2015, 1:10 PM

@thomie I'm don't know much about python, so am I doing something wrong here?

Tamar@Kino MINGW64 ~/Temp
$ cat test.py
import os
f = open('/tmp/test.txt', 'w')
f.write('foo')
f.close()
f = open('/tmp/test.txt')
print f.read()

Tamar@Kino MINGW64 ~/Temp
$ ./test.py
./test.py: line 1: import: command not found
./test.py: line 2: syntax error near unexpected token `('
./test.py: line 2: `f = open('/tmp/test.txt', 'w')'

Tamar@Kino MINGW64 ~/Temp
$ python test.py
Traceback (most recent call last):
  File "test.py", line 2, in <module>
    f = open('/tmp/test.txt', 'w')
IOError: [Errno 2] No such file or directory: '/tmp/test.txt'
Phyx added a comment.Sep 10 2015, 1:13 PM

I just realized that the python on my path isn't the msys python.

And that the Windows build instructions contain an install line for python2.

So using that instead:

Tamar@Kino MINGW64 ~/Temp
$ python2 test.py
foo
Phyx added a comment.Oct 18 2015, 2:08 AM

Hey @thomie,

Just wondering if you're still planning to do this one?

I'm still getting sporadic test failures.

Phyx added a comment.Oct 18 2015, 3:02 AM

Or rather, T7037 still always fails for me, but the stdout file contains the right output..

This revision was automatically updated to reflect the committed changes.

I pushed the above patch, although T7037 still fails occasionally.

This seems to be working for me, changing rawSystem to call

if stdout is not None:
    os.fsync(stdout)
    stdout.close()
if stderr is not None and stderr is not subprocess.STDOUT:
    os.fsync(stderr)
    stderr.close()

Is now consistently making the test pass.

I tried, but that didn't fix it for me. A time.sleep(0.1) works, but I'd rather not do that.