Fix various issues with testsuite code on Windows

Summary:
Previously we would make direct calls to `diff` using `os.system`.
On Windows `os.system` is implemented using the standard
idiom `CreateProcess .. WaitForSingleObject ..`.

This again runs afoul with the `_exec` behaviour on Windows. So we ran
into some trouble where sometimes `diff` would return before it's done.

On tests which run multiple ways, such as `8086` what happens is that
we think the diff is done and continue. The next way tries to set things
up again by removing any previous directory. This would then fail with
and error saying the directory can't be removed. Which is true, because
the previous diff code/child is still running.

We shouldn't make any external calls to anything using `os.system`.
Instead just use `runCmd` which uses `timeout`. This also ensures that if
we hit the cygwin bug where diff or any other utility hangs, we kill it and
continue and not hang the entire test and leave hanging processes.

Further more we also:
Ignore error lines from `removeFile` from tools in the testsuite. This is a rather large
hammer to work around the fact that `hsc2hs` often tries to remove it's own file too early.
When this is patched the workaround can be removed. See Trac #9775

We mark `prog003` as skip. Since this test randomly fails and passes. For stability it's disabled
but it is a genuine bug which we should find. It's something with interface files being
overwritten. See Trac #11317

when `rmtree` hits a readonly file, the `onerror` handler is raised afterwards but not
during the tree walk. It doesn't allow you to recover and continue as we thought.
Instead you have to explicitly start again. This is why sometimes even though we
call `cleanup` before `os.mkdirs`, it would sometimes fail with an error that the
folder already exists. So we now do a second walk.

A new verbosity level (4) will strip the silent flags from `MAKE` invocations so you can actually
see what's going on.

Test Plan: ./validate on build bots.

Reviewers: bgamari, austin

Reviewed By: bgamari

Subscribers: mpickering, thomie, #ghc_windows_task_force

Differential Revision: https://phabricator.haskell.org/D2894

GHC Trac Issues: #12661, #11317, #9775

3 files changed, 81 insertions, 39 deletions

diff --git a/testsuite/driver/testlib.py b/testsuite/driver/testlib.py
index 248f276c27..f6729acaa8 100644
--- a/testsuite/driver/testlib.py
+++ b/testsuite/driver/testlib.py
@@ -16,6 +16,7 @@ import time
 import datetime
 import copy
 import glob
+import sys
 from math import ceil, trunc
 import collections
 import subprocess
@@ -823,14 +824,14 @@ def do_test(name, way, func, args, files):
                     dst.write(makefile)
 
     if opts.pre_cmd:
-        exit_code = runCmd('cd "{0}" && {1}'.format(opts.testdir, opts.pre_cmd))
+        exit_code = runCmd('cd "{0}" && {1}'.format(opts.testdir, override_options(opts.pre_cmd)),
+                           stderr = subprocess.STDOUT,
+                           print_output = config.verbose >= 3)
+
         if exit_code != 0:
             framework_fail(name, way, 'pre_cmd failed: {0}'.format(exit_code))
 
-    try:
-        result = func(*[name,way] + args)
-    except Exception:
-        pass
+    result = func(*[name,way] + args)
 
     if opts.expect not in ['pass', 'fail', 'missing-lib']:
         framework_fail(name, way, 'bad expected ' + opts.expect)
@@ -866,6 +867,18 @@ def do_test(name, way, func, args, files):
     else:
         framework_fail(name, way, 'bad result ' + passFail)
 
+# Make is often invoked with -s, which means if it fails, we get
+# no feedback at all. This is annoying. So let's remove the option
+# if found and instead have the testsuite decide on what to do
+# with the output.
+def override_options(pre_cmd):
+    if config.verbose >= 4 and bool(re.match('\$make', pre_cmd, re.I)):
+        return pre_cmd.replace('-s'      , '') \
+                      .replace('--silent', '') \
+                      .replace('--quiet' , '')
+
+    return pre_cmd
+
 def framework_fail(name, way, reason):
     opts = getTestOpts()
     directory = re.sub('^\\.[/\\\\]', '', opts.testdir)
@@ -899,7 +912,7 @@ def failBecause(reason, tag=None):
 # run_command.
 
 def run_command( name, way, cmd ):
-    return simple_run( name, '', cmd, '' )
+    return simple_run( name, '', override_options(cmd), '' )
 
 # -----------------------------------------------------------------------------
 # GHCi tests
@@ -1230,7 +1243,7 @@ def simple_run(name, way, prog, extra_run_opts):
     # check the exit code
     if exit_code != opts.exit_code:
         if config.verbose >= 1 and _expect_pass(way):
-            print('Wrong exit code (expected', opts.exit_code, ', actual', exit_code, ')')
+            print('Wrong exit code for ' + name + '(' + way + ')' + '(expected', opts.exit_code, ', actual', exit_code, ')')
             dump_stdout(name)
             dump_stderr(name)
         return failBecause('bad exit code')
@@ -1317,7 +1330,7 @@ def interpreter_run(name, way, extra_hc_opts, top_mod):
 
     # check the exit code
     if exit_code != getTestOpts().exit_code:
-        print('Wrong exit code (expected', getTestOpts().exit_code, ', actual', exit_code, ')')
+        print('Wrong exit code for ' + name + '(' + way + ') (expected', getTestOpts().exit_code, ', actual', exit_code, ')')
         dump_stdout(name)
         dump_stderr(name)
         return failBecause('bad exit code')
@@ -1375,9 +1388,11 @@ def stdout_ok(name, way):
                           expected_stdout_file, actual_stdout_file)
 
 def dump_stdout( name ):
-   print('Stdout:')
-   with open(in_testdir(name, 'run.stdout')) as f:
-       print(f.read())
+    with open(in_testdir(name, 'run.stdout')) as f:
+        str = f.read().strip()
+        if str:
+            print("Stdout (", name, "):")
+            print(str)
 
 def stderr_ok(name, way):
    actual_stderr_file = add_suffix(name, 'run.stderr')
@@ -1389,9 +1404,11 @@ def stderr_ok(name, way):
                           whitespace_normaliser=normalise_whitespace)
 
 def dump_stderr( name ):
-   print("Stderr:")
-   with open(in_testdir(name, 'run.stderr')) as f:
-       print(f.read())
+    with open(in_testdir(name, 'run.stderr')) as f:
+        str = f.read().strip()
+        if str:
+            print("Stderr (", name, "):")
+            print(str)
 
 def read_no_crs(file):
     str = ''
@@ -1522,14 +1539,16 @@ def compare_outputs(way, kind, normaliser, expected_file, actual_file,
 
         if config.verbose >= 1 and _expect_pass(way):
             # See Note [Output comparison].
-            r = os.system('diff -uw "{0}" "{1}"'.format(expected_normalised_path,
-                                                        actual_normalised_path))
+            r = runCmd('diff -uw "{0}" "{1}"'.format(expected_normalised_path,
+                                                        actual_normalised_path),
+                        print_output = 1)
 
             # If for some reason there were no non-whitespace differences,
             # then do a full diff
             if r == 0:
-                r = os.system('diff -u "{0}" "{1}"'.format(expected_normalised_path,
-                                                           actual_normalised_path))
+                r = runCmd('diff -u "{0}" "{1}"'.format(expected_normalised_path,
+                                                           actual_normalised_path),
+                           print_output = 1)
 
         if config.accept and (getTestOpts().expect == 'fail' or
                               way in getTestOpts().expect_fail_for):
@@ -1607,18 +1626,30 @@ def normalise_errmsg( str ):
     #    hacky solution is used in place of more sophisticated filename
     #    mangling
     str = re.sub('([^\\s])\\.exe', '\\1', str)
+
     # normalise slashes, minimise Windows/Unix filename differences
     str = re.sub('\\\\', '/', str)
+
     # The inplace ghc's are called ghc-stage[123] to avoid filename
     # collisions, so we need to normalise that to just "ghc"
     str = re.sub('ghc-stage[123]', 'ghc', str)
+
     # Error messages simetimes contain integer implementation package
     str = re.sub('integer-(gmp|simple)-[0-9.]+', 'integer-<IMPL>-<VERSION>', str)
+
     # Also filter out bullet characters.  This is because bullets are used to
     # separate error sections, and tests shouldn't be sensitive to how the
     # the division happens.
     bullet = '•'.encode('utf8') if isinstance(str, bytes) else '•'
     str = str.replace(bullet, '')
+
+    # Windows only, this is a bug in hsc2hs but it is preventing
+    # stable output for the testsuite. See Trac #9775. For now we filter out this
+    # warning message to get clean output.
+    if config.msys:
+        str = re.sub('Failed to remove file (.*); error= (.*)$', '', str)
+        str = re.sub('DeleteFile "(.+)": permission denied \(Access is denied\.\)(.*)$', '', str)
+
     return str
 
 # normalise a .prof file, so that we can reasonably compare it against
@@ -1723,7 +1754,7 @@ def if_verbose_dump( n, f ):
         except Exception:
             print('')
 
-def runCmd(cmd, stdin=None, stdout=None, stderr=None, timeout_multiplier=1.0):
+def runCmd(cmd, stdin=None, stdout=None, stderr=None, timeout_multiplier=1.0, print_output=0):
     timeout_prog = strip_quotes(config.timeout_prog)
     timeout = str(int(ceil(config.timeout * timeout_multiplier)))
 
@@ -1762,22 +1793,20 @@ def runCmd(cmd, stdin=None, stdout=None, stderr=None, timeout_multiplier=1.0):
                              stderr=hStdErr)
 
         stdout_buffer, stderr_buffer = r.communicate(stdin_buffer)
-    except Exception as e:
-        traceback.print_exc()
-        framework_fail(name, way, str(e))
     finally:
-        try:
-            if stdout:
-                with io.open(stdout, 'ab') as f:
-                    f.write(stdout_buffer)
-            if stderr:
-                if stderr is not subprocess.STDOUT:
-                    with io.open(stderr, 'ab') as f:
-                        f.write(stderr_buffer)
-
-        except Exception as e:
-            traceback.print_exc()
-            framework_fail(name, way, str(e))
+        if config.verbose >= 1 and print_output >= 1:
+            if stdout_buffer:
+                sys.stdout.buffer.write(stdout_buffer)
+            if stderr_buffer:
+                sys.stderr.buffer.write(stderr_buffer)
+
+        if stdout:
+            with io.open(stdout, 'ab') as f:
+                f.write(stdout_buffer)
+        if stderr:
+            if stderr is not subprocess.STDOUT:
+                with io.open(stderr, 'ab') as f:
+                    f.write(stderr_buffer)
 
     if r.returncode == 98:
         # The python timeout program uses 98 to signal that ^C was pressed
@@ -1865,16 +1894,25 @@ def find_expected_file(name, suff):
 if config.msys:
     import stat
     def cleanup():
+        testdir = getTestOpts().testdir
+
         def on_error(function, path, excinfo):
             # At least one test (T11489) removes the write bit from a file it
             # produces. Windows refuses to delete read-only files with a
             # permission error. Try setting the write bit and try again.
             if excinfo[1].errno == 13:
                 os.chmod(path, stat.S_IWRITE)
-                os.unlink(path)
+                function(path)
 
-        testdir = getTestOpts().testdir
         shutil.rmtree(testdir, ignore_errors=False, onerror=on_error)
+
+        if os.path.exists(testdir):
+            # And now we try to cleanup the folder again, since the above
+            # Would have removed the problematic file(s), but not the folder.
+            # The onerror doesn't seem to be raised during the tree walk, only
+            # afterwards to report the failures.
+            # See https://bugs.python.org/issue8523 and https://bugs.python.org/issue19643
+            shutil.rmtree(testdir, ignore_errors=False)
 else:
     def cleanup():
         testdir = getTestOpts().testdir
diff --git a/testsuite/tests/ghci/prog003/prog003.T b/testsuite/tests/ghci/prog003/prog003.T
index 19551fd927..92aadbac93 100644
--- a/testsuite/tests/ghci/prog003/prog003.T
+++ b/testsuite/tests/ghci/prog003/prog003.T
@@ -1,7 +1,11 @@
+# This test is very flaky on Windows.
+# It is a genuine bug that should be looked at, but
+# for the sake of stability of the build bot we disable it for now.
+# See Trac 11317.
 test('prog003',
      [extra_clean(['D.hs', 'D.hi', 'C.hi', 'C.o', 'B.hi', 'B.o',
                    'A', 'A.hi', 'A.o', 'a.out']),
-      when(opsys('mingw32'), expect_broken(11317)),
+      when(opsys('mingw32'), skip),
       cmd_prefix('ghciWayFlags=' + config.ghci_way_flags)],
      ghci_script,
      ['prog003.script'])
diff --git a/testsuite/timeout/timeout.hs b/testsuite/timeout/timeout.hs
index d466495fe2..f72efe30ae 100644
--- a/testsuite/timeout/timeout.hs
+++ b/testsuite/timeout/timeout.hs
@@ -112,8 +112,8 @@ run secs cmd =
        -- We're explicitly turning off handle inheritance to prevent misc handles
        -- from being inherited by the child. Notable we don't want the I/O Completion
        -- Ports and Job handles to be inherited. So we mark them as non-inheritable.
-       setHandleInformation job cHANDLE_FLAG_INHERIT 0
-       setHandleInformation job cHANDLE_FLAG_INHERIT 0
+       setHandleInformation job    cHANDLE_FLAG_INHERIT 0
+       setHandleInformation ioPort cHANDLE_FLAG_INHERIT 0
 
        -- Now create the process suspended so we can add it to the job and then resume.
        -- This is so we don't miss any events on the receiving end of the I/O port.