testrunner: Fix disrupted lines in the error log

Windows inserts extra newlines into the error log when certain
errors occur like
    "Exit code 0xc0000409\n***Exception:"
and that newline caused the parser match to fail.

Note that this is the normal stdout. CMake does not use stderr.
It makes no sense to fix the pipe structure of the script.
Instead, the only fix needed was recognition of line breaks
in the error log. You can see this also in the failure listing

    The following tests FAILED:
       1 - pysidetest_constructor_properties_test (Exit code 0xc0000409
    )

The following improvements were done:
- add an extra pass that checks for broken lines in the error log
- add ad extra plausibility check or consecutive test numbers
- improve the output, program structure and add some documentation

When there should still an unforeseen bug occurs, it will be recognized
by the plausi-check and the test repetitions are immediately cancelled.

We could also fix the output not to contain the line breaks, but
that breaks the principle of keeping the original output and needs
discussion by the developers.

Fixes: PYSIDE-1229
Change-Id: Ib71f3361e78eb59f3469da172c74c719e9f08706
Reviewed-by: Friedemann Kleint <Friedemann.Kleint@qt.io>

7 files changed, 146 insertions, 58 deletions

diff --git a/testing/__init__.py b/testing/__init__.py
index 1098f47e7..03c590604 100644
--- a/testing/__init__.py
+++ b/testing/__init__.py
@@ -39,6 +39,13 @@
 
 from __future__ import print_function
 
+"""
+testing/__init__.py
+
+- install an alternative, flushing print
+- define command.main as entry point
+"""
+
 import sys
 from . import command
 
diff --git a/testing/blacklist.py b/testing/blacklist.py
index c0a5e233d..f82f2b5e7 100644
--- a/testing/blacklist.py
+++ b/testing/blacklist.py
@@ -39,6 +39,14 @@
 
 from __future__ import print_function
 
+"""
+testing/blacklist.py
+
+Take a blacklist file and build classifiers for all tests.
+
+find_matching_line() adds info using classifiers.
+"""
+
 from .helper import decorate, StringIO
 from .buildlog import builds
 
@@ -56,7 +64,7 @@ class BlackList(object):
 
         def filtered_line(line):
             if '#' in line:
-                line = line[0:line.index('#')]
+                line = line[0 : line.index('#')]
             return line.split()
 
         # now put every bracketed line in a test
@@ -99,7 +107,6 @@ class BlackList(object):
         if line found and test passed, it is a BPASS.
         If line found and test failed, it is a BFAIL.
         """
-        passed = test.passed
         classifiers = set(builds.classifiers)
 
         if "" in self.tests:
diff --git a/testing/buildlog.py b/testing/buildlog.py
index a0438de0b..0cea8c934 100644
--- a/testing/buildlog.py
+++ b/testing/buildlog.py
@@ -39,6 +39,14 @@
 
 from __future__ import print_function
 
+"""
+testing/buildlog.py
+
+A BuildLog holds the tests of a build.
+
+BuildLog.classifiers finds the set of classifier strings.
+"""
+
 import os
 import sys
 from collections import namedtuple
diff --git a/testing/command.py b/testing/command.py
index dd71eab56..886ab3e74 100644
--- a/testing/command.py
+++ b/testing/command.py
@@ -46,7 +46,7 @@ testrunner
 Provide an interface to the pyside tests.
 -----------------------------------------
 
-This program can only be run if PySide was build with tests enabled.
+This program can only be run if PySide was built with tests enabled.
 All tests are run in a single pass, and if not blacklisted, an error
 is raised at the end of the run.
 
@@ -123,20 +123,26 @@ def test_project(project, args, blacklist, runs):
             else:
                 rerun = None
             runner.run("RUN {}:".format(idx + 1), rerun, 10 * 60)
-        result = TestParser(runner.logfile)
+        results = TestParser(runner.logfile)
         r = 5 * [0]
         rerun_list = []
         print()
-        for test, res in result.iter_blacklist(blacklist):
-            print("RES {}:".format(index), end=" ")
-            print("%-6s" % res, decorate(test) + "()")
+        fatal = False
+        for item in results.iter_blacklist(blacklist):
+            res = item.rich_result
+            sharp = "#" + str(item.sharp)
+            mod_name = decorate(item.mod_name)
+            print("RES {index}: Test {sharp:>4}: {res:<6} {mod_name}()".format(**locals()))
             r[0] += 1 if res == "PASS" else 0
             r[1] += 1 if res == "FAIL!" else 0
             r[2] += 1 if res == "SKIPPED" else 0 # not yet supported
             r[3] += 1 if res == "BFAIL" else 0
             r[4] += 1 if res == "BPASS" else 0
             if res not in ("PASS", "BPASS"):
-                rerun_list.append(test)
+                rerun_list.append(item.mod_name)
+            # PYSIDE-1229: When a fatal error happens, bail out immediately!
+            if item.fatal:
+                fatal = item
         print()
         print("Totals:", sum(r), "tests.",
               "{} passed, {} failed, {} skipped, {} blacklisted, {} bpassed."
@@ -145,8 +151,11 @@ def test_project(project, args, blacklist, runs):
         print("********* Finished testing of %s *********" % project)
         print()
         ret.append(r)
-
-    return ret
+        if fatal:
+            print("FATAL ERROR:", fatal)
+            print("Repetitions cancelled!")
+            break
+    return ret, fatal
 
 def main():
     # create the top-level command parser
@@ -249,8 +258,11 @@ def main():
     runs = COIN_TESTING
     fail_crit = COIN_THRESHOLD
     # now loop over the projects and accumulate
+    fatal = False
     for project in args.projects:
-        res = test_project(project, args, bl, runs)
+        res, fatal = test_project(project, args, bl, runs)
+        if fatal:
+            runs = 1
         for idx, r in enumerate(res):
             q = list(map(lambda x, y: x+y, r, q))
 
@@ -265,11 +277,11 @@ def main():
         for idx in range(runs):
             index = idx + 1
             runner = TestRunner(builds.selected, project, index)
-            result = TestParser(runner.logfile)
-            for test, res in result.iter_blacklist(bl):
-                key = project + ":" + test
+            results = TestParser(runner.logfile)
+            for item in results.iter_blacklist(bl):
+                key = project + ":" + item.mod_name
                 tot_res.setdefault(key, [])
-                tot_res[key].append(res)
+                tot_res[key].append(item.rich_result)
     tot_flaky = 0
     print("*" * 79)
     print("**")
@@ -282,17 +294,20 @@ def main():
         fail__c = res.count("FAIL!")
         bfail_c = res.count("BFAIL")
         fail2_c = fail__c + bfail_c
+        fatal_c = res.count("FATAL")
         if pass__c == len(res):
             continue
-        elif bpass_c == runs and runs > 1:
+        elif bpass_c >= runs and runs > 1:
             msg = "Remove blacklisting; test passes"
-        elif fail__c == runs:
+        elif fail__c >= runs:
             msg = "Newly detected Real test failure!"
-        elif bfail_c == runs:
+        elif bfail_c >= runs:
             msg = "Keep blacklisting ;-("
         elif fail2_c > 0 and fail2_c < len(res):
             msg = "Flaky test"
             tot_flaky += 1
+        elif fatal_c:
+            msg = "FATAL format error, repetitions aborted!"
         else:
             continue
         empty = False
@@ -326,6 +341,8 @@ def main():
     used_time = stop_time - start_time
     # Now create an error if the criterion is met:
     try:
+        if fatal:
+            raise ValueError("FATAL format error:", fatal)
         err_crit = "'FAIL! >= {}'".format(fail_crit)
         for res in tot_res.values():
             if res.count("FAIL!") >= fail_crit:
diff --git a/testing/helper.py b/testing/helper.py
index 0d7b31a72..88da48c6e 100644
--- a/testing/helper.py
+++ b/testing/helper.py
@@ -39,6 +39,12 @@
 
 from __future__ import print_function
 
+"""
+testing/helper.py
+
+Some tools that do not fit elsewhere.
+"""
+
 import os
 import sys
 from collections import namedtuple
diff --git a/testing/parser.py b/testing/parser.py
index 035aab091..1d5c34680 100644
--- a/testing/parser.py
+++ b/testing/parser.py
@@ -44,6 +44,15 @@ import re
 from collections import namedtuple
 from .helper import StringIO
 
+"""
+testing/parser.py
+
+Parse test output lines from ctest and build TestResult objects.
+
+TestParser.iter_blacklist adds info from the blacklist while iterating
+over the test results.
+"""
+
 _EXAMPLE = """
 Example output:
 
@@ -62,39 +71,42 @@ Note the field "mod_name". I had split this before, but it is necessary
 to use the combination as the key, because the test names are not unique.
 """
 
-# validation of our pattern:
+_TEST_PAT_PRE = r"""
+    ^                          # start
+    \s*                        # any whitespace ==: WS
+    ([0-9]+)/([0-9]+)          #                         ip1 "/" n
+    \s+                        # some WS
+    Test                       #                         "Test"
+    \s+                        # some WS
+    \#                         # sharp symbol            "#"
+    ([0-9]+)                   #                         sharp
+    :                          # colon symbol            ':'
+    """
+_TEST_PAT = _TEST_PAT_PRE + r"""
+    \s+                        # some WS
+    ([\w-]+)                   #                         mod_name
+    .*?                        # whatever (non greedy)
+    (                          #
+      (Passed)                 # either "Passed", None
+      |                        #
+      \*\*\*(\w+.*?)           # or     None, "Something"
+    )                          #                         code
+    \s+                        # some WS
+    ([0-9]+\.[0-9]+)           #                         tim
+    \s+                        # some WS
+    sec                        #                         "sec"
+    \s*                        # any WS
+    $                          # end
+    """
 
-_TEST_PAT = r"""
-              ^                          # start
-              \s*                        # any whitespace ==: WS
-              ([0-9]+)/([0-9]+)          #                         ip1 "/" n
-              \s+                        # some WS
-              Test                       #                         "Test"
-              \s+                        # some WS
-              \#                         # sharp symbol            "#"
-              ([0-9]+)                   #                         sharp
-              :                          # colon symbol            ':'
-              \s+                        # some WS
-              ([\w-]+)                   #                         mod_name
-              .*?                        # whatever (non greedy)
-              (                          #
-                (Passed)                 # either "Passed", None
-                |                        #
-                \*\*\*(\w+.*?)           # or     None, "Something"
-              )                          #                         code
-              \s+                        # some WS
-              ([0-9]+\.[0-9]+)           #                         tim
-              \s+                        # some WS
-              sec                        #                         "sec"
-              \s*                        # any WS
-              $                          # end
-              """
+# validation of our pattern:
 assert re.match(_TEST_PAT, _EXAMPLE.splitlines()[5], re.VERBOSE)
 assert len(re.match(_TEST_PAT, _EXAMPLE.splitlines()[5], re.VERBOSE).groups()) == 8
 assert len(re.match(_TEST_PAT, _EXAMPLE.splitlines()[7], re.VERBOSE).groups()) == 8
 
-TestResult = namedtuple("TestResult", ["idx", "mod_name", "passed",
-                                       "code", "time"])
+TestResult = namedtuple("TestResult", "idx n sharp mod_name passed "
+                                      "code time fatal rich_result".split())
+
 def _parse_tests(test_log):
     """
     Create a TestResult object for every entry.
@@ -107,6 +119,15 @@ def _parse_tests(test_log):
             lines = f.readlines()
     else:
         lines = []
+
+    # PYSIDE-1229: Fix disrupted lines like "Exit code 0xc0000409\n***Exception:"
+    pat = _TEST_PAT_PRE
+    for idx, line in enumerate(lines[:-1]):
+        match = re.match(pat, line, re.VERBOSE)
+        if match and line.split()[-1] != "sec":
+            # don't change the number of lines
+            lines[idx : idx + 2] = [line.rstrip() + lines[idx + 1], ""]
+
     pat = _TEST_PAT
     for line in lines:
         match = re.match(pat, line, re.VERBOSE)
@@ -114,29 +135,41 @@ def _parse_tests(test_log):
             idx, n, sharp, mod_name, much_stuff, code1, code2, tim = tup = match.groups()
             # either code1 or code2 is None
             code = code1 or code2
-            idx, n, code, tim = int(idx), int(n), code.lower(), float(tim)
-            res = TestResult(idx, mod_name, code == "passed", code, tim)
-            result.append(res)
+            idx, n, sharp, code, tim = int(idx), int(n), int(sharp), code.lower(), float(tim)
+            item = TestResult(idx, n, sharp, mod_name, code == "passed", code, tim, False, None)
+            result.append(item)
+
+    # PYSIDE-1229: Be sure that the numbering of the tests is consecutive
+    for idx, item in enumerate(result):
+        # testing fatal error:
+        # Use "if idx + 1 != item.idx or idx == 42:"
+        if idx + 1 != item.idx:
+            # The numbering is disrupted. Provoke an error in this line!
+            passed = False
+            code += ", but lines are disrupted!"
+            result[idx] = item._replace(passed=False,
+                                        code=item.code + ", but lines are disrupted!",
+                                        fatal=True)
+            break
     return result
 
 
 class TestParser(object):
     def __init__(self, test_log):
-        self._result = _parse_tests(test_log)
+        self._results = _parse_tests(test_log)
 
     @property
-    def result(self):
-        return self._result
+    def results(self):
+        return self._results
 
     def __len__(self):
-        return len(self._result)
+        return len(self._results)
 
     def iter_blacklist(self, blacklist):
         bl = blacklist
-        for line in self._result:
-            mod_name = line.mod_name
-            passed = line.passed
-            match = bl.find_matching_line(line)
+        for item in self.results:
+            passed = item.passed
+            match = bl.find_matching_line(item)
             if not passed:
                 if match:
                     res = "BFAIL"
@@ -147,4 +180,7 @@ class TestParser(object):
                     res = "BPASS"
                 else:
                     res = "PASS"
-            yield mod_name, res
+            if item.fatal:
+                # PYSIDE-1229: Stop the testing completely when a fatal error exists
+                res = "FATAL"
+            yield item._replace(rich_result=res)
diff --git a/testrunner.py b/testrunner.py
index a16a07ab2..6ce0b1be1 100644
--- a/testrunner.py
+++ b/testrunner.py
@@ -39,6 +39,13 @@
 
 from __future__ import print_function, absolute_import
 
+"""
+testrunner.py
+
+Run ctest on the last build.
+See the notes in testing/command.py .
+"""
+
 import sys
 import testing
 import testing.blacklist # just to be sure it's us...