autotest: augment bisect-helper.py to help with flapping tests

- option to allow for a string which must be present in the outout
 - option for strings which must not be present in the output
 - repeat option so test must pass many times
 - elaborate diagnostic output
 - option to run under Valgrind (to provoke races)

The output from each test run is poked into a directory in /tmp

The number of runs a test took to fail is poked into a different file in /tmp, helping to tune the --autotest-test-passes parameter

Tools/autotest/bisect-helper.py

@@ -1,7 +1,6 @@
 #!/usr/bin/env python
 
-'''
-A helper script for bisecting common problems when working with ArduPilot
+'''A helper script for bisecting common problems when working with ArduPilot
 
 Bisect between a commit which builds and one which doesn't,
 finding the first commit which broke the build with a
@@ -43,6 +42,13 @@ git bisect good $GOOD &&
   git bisect run Tools2/autotest/bisect-helper.py --build \
     --waf-configure-arg="--board OmniBusF4Pro" \
      --build-failure-string="$BFS"
+
+# Use a flapping test to work out which commit broke things.  The
+# "autotest-branch" is the branch containing the flapping test (which
+# may be master)
+rm /tmp/bisect-debug/*; git commit -m "stuff" -a ; cp Tools/autotest/bisect-helper.py /tmp; git bisect reset; git bisect start; git bisect bad d24e569b20; git bisect good 3f6fd49507f286ad8f6ccc9e29b110d5e9fc9207^
+time git bisect run /tmp/bisect-helper.py --autotest --autotest-vehicle=Copter --autotest-test=Replay --autotest-branch=wip/bisection-using-flapping-test --autotest-test-passes=40 --autotest-failure-require-string="Mismatch in field XKF1.Pitch" --autotest-failure-ignore-string="HALSITL::SITL_State::_check_rc_input"
+
 '''
 
 import optparse
@@ -51,23 +57,50 @@ import subprocess
 import shlex
 import sys
 import time
+import traceback
 
+def get_exception_stacktrace(e):
+    if sys.version_info[0] >= 3:
+        ret = "%s\n" % e
+        ret += ''.join(traceback.format_exception(etype=type(e),
+                                                  value=e,
+                                                  tb=e.__traceback__))
+        return ret
+    return traceback.format_exc(e)
 
 class Bisect(object):
     def __init__(self, opts):
         self.opts = opts
 
+    def exit_skip_code(self):
+        return 125
+
+    def exit_pass_code(self):
+        return 0
+
+    def exit_fail_code(self):
+        return 1
+
+    def exit_abort_code(self):
+        return 129
+
     def exit_skip(self):
         self.progress("SKIP")
-        sys.exit(125)
+        sys.exit(self.exit_skip_code())
 
     def exit_pass(self):
         self.progress("PASS")
-        sys.exit(0)
+        sys.exit(self.exit_pass_code())
 
     def exit_fail(self):
         self.progress("FAIL")
-        sys.exit(1)
+        sys.exit(self.exit_fail_code())
+
+    def exit_abort(self):
+        '''call when this harness has failed (e.g. to reset to required
+        state)'''
+        self.progress("ABORT")
+        sys.exit(self.exit_abort_code())
 
     def progress(self, string):
         '''pretty-print progress'''
@@ -93,6 +126,8 @@ class Bisect(object):
                     # select not available on Windows... probably...
                 time.sleep(0.1)
                 continue
+            if type(x) == bytes:
+                x = x.decode('utf-8')
             self.program_output += x
             x = x.rstrip()
             print("%s: %s" % (prefix, x))
@@ -151,8 +186,25 @@ class BisectCITest(Bisect):
         return os.path.join("Tools", "autotest", "autotest.py")
 
 
+    def git_reset(self):
+        try:
+            self.run_program("Reset autotest directory", ["git", "reset", "--hard"])
+        except subprocess.CalledProcessError as e:
+            self.exit_abort()
+
+    def get_current_hash(self):
+        self.run_program("Get current hash", ["git", "rev-parse", "HEAD"])
+        x = self.program_output
+        return x.strip()
+
     def run(self):
 
+        current_hash = self.get_current_hash()
+
+        self.debug_dir = os.path.join("/tmp", "bisect-debug")
+        if not os.path.exists(self.debug_dir):
+            os.mkdir(self.debug_dir)
+
         if self.opts.autotest_branch is None:
             raise ValueError("expected autotest branch")
 
@@ -160,37 +212,70 @@ class BisectCITest(Bisect):
             self.run_program("Update submodules",
                              ["git", "submodule", "update", "--init", "--recursive"])
         except subprocess.CalledProcessError as e:
-            self.exit_fail()
+            self.exit_abort()
 
         try:
             self.run_program("Check autotest directory out from master",
                              ["git", "checkout", self.opts.autotest_branch, "Tools/autotest"])
         except subprocess.CalledProcessError as e:
-            self.exit_fail()
+            self.exit_abort()
 
 
+        self.progress("Build")
         cmd = [self.autotest_script()]
+        if self.opts.autotest_valgrind:
+            cmd.append("--debug")
         cmd.append("build.%s" % self.opts.autotest_vehicle)
-        cmd.append("test.%s.%s" % (self.opts.autotest_vehicle, self.opts.autotest_test))
-
-        print("cmd: %s" % str(cmd))
-
-        failed = False
+        print("build cmd: %s" % str(cmd))
 
         try:
-            self.run_program("Run autotest", cmd)
+            self.run_program("Run autotest (build)", cmd)
         except subprocess.CalledProcessError as e:
-            failed = True
+            self.git_reset()
+            self.exit_skip()
 
-        try:
-            self.run_program("Reset autotest directory", ["git", "reset", "--hard"])
-        except subprocess.CalledProcessError as e:
-            self.exit_fail()
+        cmd = [self.autotest_script()]
+        if self.opts.autotest_valgrind:
+            cmd.append("--valgrind")
+        cmd.append("test.%s.%s" % (self.opts.autotest_vehicle, self.opts.autotest_test))
 
-        if failed:
-            self.exit_fail()
+        code = self.exit_pass_code()
+        for i in range(0, self.opts.autotest_test_passes):
+            ignore = False
+            try:
+                self.run_program(
+                    "Run autotest (%u/%u)" % (i+1, self.opts.autotest_test_passes),
+                    cmd)
+            except subprocess.CalledProcessError as e:
+                for ignore_string in self.opts.autotest_failure_ignore_string:
+                    if ignore_string in self.program_output:
+                        self.progress("Found ignore string (%s) in program output" % ignore_string)
+                        ignore = True
+                if not ignore and self.opts.autotest_failure_require_string is not None:
+                    if self.opts.autotest_failure_require_string not in self.program_output:
+                        # it failed, but not for the reason we're looking
+                        # for...
+                        self.progress("Did not find test failure string (%s); skipping" % self.opts.autotest_failure_require_string)
+                        code = self.exit_skip_code()
+                        break
+                if not ignore:
+                    code = self.exit_fail_code()
+
+            with open(os.path.join(self.debug_dir, "run-%s-%u.txt" % (current_hash, i+1)), "w") as f:
+                f.write(self.program_output)
+
+            if code == self.exit_fail_code():
+                with open("/tmp/fail-counts", "a") as f:
+                    print("Failed on run %u" % (i+1,), file=f)
+            if ignore:
+                self.progress("Ignoring this run")
+                continue
+            if code != self.exit_pass_code():
+                break
 
-        self.exit_pass()
+        self.git_reset()
+
+        sys.exit(code)
 
 
 if __name__ == '__main__':
@@ -221,10 +306,31 @@ if __name__ == '__main__':
                               type="string",
                               default="NavDelayAbsTime",
                               help="Test to run to find failure")
+    group_autotest.add_option("", "--autotest-valgrind",
+                              dest="autotest_valgrind",
+                              action='store_true',
+                              default=False,
+                              help="Run autotest under valgrind")
+    group_autotest.add_option("", "--autotest-test-passes",
+                              dest="autotest_test_passes",
+                              type=int,
+                              default=1,
+                              help="Number of times to run test before declaring it is good")
     group_autotest.add_option("", "--autotest-branch",
                               dest="autotest_branch",
                               type="string",
                               help="Branch on which the test exists.  The autotest directory will be reset to this branch")
+    group_autotest.add_option("--autotest-failure-require-string",
+                             type='string',
+                             default=None,
+                             help="If supplied, must be present in"
+                             "test output to count as a failure")
+    group_autotest.add_option("--autotest-failure-ignore-string",
+                              type='string',
+                              default=[],
+                              action="append",
+                              help="If supplied and present in"
+                              "test output run will be ignored")
 
     group_build = optparse.OptionGroup(parser, "Build options")
     group_build.add_option("", "--waf-configure-arg",
@@ -257,4 +363,5 @@ try:
     bisecter.run()
 except Exception as e:
     print("Caught exception in bisect-helper: %s" % str(e))
+    print(get_exception_stacktrace(e))
     sys.exit(129)  # should abort the bisect process