def _process_test(domain_prefix, test, args, test_stats, result_stats, test_count, tests_count, boot_executor): logger = logutil.getLogger(domain_prefix, __name__, test.name) prefix = "******" suffix = "******" test_stats.add(test, "total") test_runtime = test_boot_time = test_script_time = test_post_time = None old_result = None backup_directory = os.path.join(args.backup_directory, test.name) # Would the number of tests to be [re]run be better? test_prefix = "%s (test %d of %d)" % (test.name, test_count, tests_count) publish.json_status(logger, args, "processing %s" % test_prefix) with logger.time("processing test %s", test_prefix): # Ignoring the test completely? # # So that there's no possible confusion over the test being # run; remove any pre-existing output. ignored, details = ignore.test(logger, args, test) if ignored: # The isdir() test followed by a simple move, while # racy, should be good enough. if os.path.isdir(test.output_directory): logger.info("moving '%s' to '%s'", test.output_directory, backup_directory) os.makedirs(os.path.dirname(backup_directory), exist_ok=True) os.rename(test.output_directory, backup_directory) result_stats.add_ignored(test, ignored) test_stats.add(test, "ignored") logger.info("%s %s ignored (%s) %s", prefix, test_prefix, details, suffix) return # Skip the test, leaving old results? # # For instance, during a test re-run, skip any tests that are # passing. # # The check below compares the test and expected output, # ignoring any previous test result. This way the results are # consistent with kvmresults.py which always reflects the # current sources. # # - modifying the expected output so that it no longer matches # the last result is a fail # # - modifying the expected output so that it matches the last # result is a pass old_result = post.mortem(test, args, domain_prefix=domain_prefix, quick=False) if skip.result(logger, args, old_result): logger.info("%s %s skipped (previously %s) %s", prefix, test_prefix, old_result, suffix) test_stats.add(test, "skipped") result_stats.add_skipped(old_result) publish.everything(logger, args, old_result) return # Running the test ... # # From now on the test will be run so need to perform post # mortem. try: if old_result: test_stats.add(test, "tests", "retry") logger.info("%s %s started (previously %s) ....", prefix, test_prefix, old_result) else: test_stats.add(test, "tests", "try") logger.info("%s %s started ....", prefix, test_prefix) test_stats.add(test, "tests") # Create just the OUTPUT/ directory. # # If the directory already exists, copy the contents # BACKUP/. Do it file-by-file so that, at no point, the # OUTPUT/ directory is missing (having an OUTPUT/ # directory implies the test was started). # # Don't try to create the path. If the parent directory # is missing, this and the entire script will crash. # Someone did something nasty like deleted the parent # directory. # # By backing up each test just before it is started, # leaves a trail of what tests were attempted during a # test run. # # XXX: # # During boot, swan-transmogrify runs "chcon -R # testing/pluto". Of course this means that each time a # test is added and/or a test is run (adding files under # <test>/OUTPUT), the boot process (and consequently the # time taken to run a test) keeps increasing. # # By moving the directory contents to BACKUP/, which is # not under testing/pluto/ this problem is avoided. try: os.mkdir(test.output_directory) except FileExistsError: logger.info("moving contents of '%s' to '%s'", test.output_directory, backup_directory) # Even if OUTPUT/ is empty, move it. os.makedirs(backup_directory, exist_ok=True) for name in os.listdir(test.output_directory): src = os.path.join(test.output_directory, name) dst = os.path.join(backup_directory, name) logger.debug("moving '%s' to '%s'", src, dst) os.replace(src, dst) # Now that the OUTPUT directory is empty, start a debug # log writing to that directory; include timing for this # test run. with logger.debug_time("testing %s", test_prefix, logfile=os.path.join( test.output_directory, "debug.log"), loglevel=logutil.INFO) as test_runtime: # boot the domains with logger.time("booting domains") as test_boot_time: try: test_domains = _boot_test_domains( logger, test, domain_prefix, boot_executor) except pexpect.TIMEOUT: # Bail. Being unable to boot the domains is a # disaster. The test is UNRESOLVED. logger.exception("TIMEOUT while booting domains") return except pexpect.EOF: # Bail. Being unable to attach to the domains # is a disaster. The test is UNRESOLVED. logger.exception("EOF while booting domains") return except: logger.exception("EXCEPTION while booting domains") raise # Run the scripts directly with logger.time("running scripts %s", test.host_scripts) as test_script_time: with tcpdump.Dump( logger, domain_prefix, test.output_directory, [ test_domain.domain for test_domain in test_domains.values() ], enable=args.tcpdump): try: # re-direct the test-result log file for test_domain in test_domains.values(): output = os.path.join( test.output_directory, test_domain.domain.host_name + ".console.verbose.txt") test_domain.console.redirect_output( open(output, "w")) # If a script times out, don't try to run # post-mortem.sh. host_timed_out = None for script in test.host_scripts: test_domain = test_domains[script.host_name] try: test_domain.read_file_run(script.path) except pexpect.TIMEOUT as e: # A timeout while running a test # script is a sign that a command # hung. message = "%s while running script %s" % ( post.Issues.TIMEOUT, script) logger.warning("*** %s ***" % message) test_domain.console.append_output( "%s %s %s", post.LHS, message, post.RHS) host_timed_out = script.host_name break except pexpect.EOF as e: # An EOF while a script is running # is a sign that libvirt crashed. message = "%s while running script %s" % ( post.Issues.EOF, script) logger.exception("*** %s ***" % message) test_domain.console.append_output( "%s %s %s", post.LHS, message, post.RHS) host_timed_out = script.host_name break except BaseException as e: # if there is an exception, write # it to the console message = "%s %s while running script %s" % ( post.Issues.EXCEPTION, str(e), script) logger.exception("*** %s ***" % message) test_domain.console.append_output( "\n%s %s %s\n", post.LHS, message, post.RHS) raise if args.run_post_mortem is False: logger.warning( "+++ skipping script post-mortem.sh -- disabled +++" ) elif host_timed_out: logger.warning( "+++ skipping script post-mortem.sh -- %s timed out +++" % (host_timed_out)) else: # None or True script = "../bin/post-mortem.sh" for host_name in test.host_names: test_domain = test_domains[host_name] test_domain.console.append_output( "%s post-mortem %s", post.LHS, post.LHS) logger.info("running %s on %s", script, host_name) try: status = test_domain.console.run( script) if status: logger.error( "%s failed on %s with status %s", script, host_name, status) else: test_domain.console.append_output( "%s post-mortem %s", post.RHS, post.RHS) except pexpect.TIMEOUT as e: # A post-mortem ending with a # TIMEOUT gets treated as a # FAIL. message = "%s while running script %s" % ( post.Issues.TIMEOUT, script) logger.warning("*** %s ***" % message) test_domain.console.append_output( "%s %s %s", post.LHS, message, post.RHS) continue # always teardown except pexpect.EOF as e: # A post-mortem ending with an # EOF gets treated as # unresloved. message = "%s while running script %s" % ( post.Issues.EOF, script) logger.exception("*** %s ***" % message) test_domain.console.append_output( "%s %s %s", post.LHS, message, post.RHS) continue # always teardown except BaseException as e: # if there is an exception, write # it to the console message = "%s %s while running script %s" % ( post.Issues.EXCEPTION, str(e), script) logger.exception(message) test_domain.console.append_output( "\n%s %s %s\n", post.LHS, message, post.RHS) raise for test_domain in test_domains.values(): test_domain.console.append_output(post.DONE) finally: # Close the redirected test-result log files logger.info( "closing all the test domain log files") for test_domain in test_domains.values(): test_domain.console.close_output() # Always disconnect from the test domains. logger.info("closing all the test domains") for test_domain in test_domains.values(): test_domain.close() finally: with logger.time("post-mortem %s", test_prefix): # The test finished; it is assumed that post.mortem # can deal with a crashed test. result = post.mortem(test, args, domain_prefix=domain_prefix) logger.info("%s %s %s%s%s %s", prefix, test_prefix, result, result.issues and " ", result.issues, suffix) result.save() # If the test was run (a fresh run would delete RESULT) # and finished (resolved in POSIX terminology), emit # enough JSON to fool scripts like pluto-testlist-scan.sh. # # A test that timed-out or crashed, isn't considered # resolved so the file isn't created. # # XXX: this should go away. result_file = os.path.join(test.output_directory, "RESULT") if not os.path.isfile(result_file) \ and result.resolution.isresolved(): RESULT = { jsonutil.result.testname: test.name, jsonutil.result.expect: test.status, jsonutil.result.result: result, jsonutil.result.issues: result.issues, jsonutil.result.hosts: test.host_names, jsonutil.result.time: jsonutil.ftime(test_runtime.start), jsonutil.result.runtime: round(test_runtime.seconds(), 1), jsonutil.result.boot_time: round(test_boot_time.seconds(), 1), jsonutil.result.script_time: round(test_script_time.seconds(), 1), } j = jsonutil.dumps(RESULT) logger.debug("filling '%s' with json: %s", result_file, j) with open(result_file, "w") as f: f.write(j) f.write("\n") # Do this after RESULT is created so it too is published. publish.everything(logger, args, result) publish.json_status(logger, args, "finished %s" % test_prefix) test_stats.add(test, "tests", str(result)) result_stats.add_result(result, old_result) # test_stats.log_summary(logger.info, header="updated test stats:", prefix=" ") result_stats.log_summary(logger.info, header="updated test results:", prefix=" ")
def _process_test(domain_prefix, test, args, test_stats, result_stats, test_count, tests_count, boot_executor): logger = logutil.getLogger(domain_prefix, __name__, test.name) prefix = "******" suffix = "******" test_stats.add(test, "total") test_runtime = test_boot_time = test_script_time = test_post_time = None old_result = None backup_directory = os.path.join(args.backup_directory, test.name) # Would the number of tests to be [re]run be better? test_prefix = "%s (test %d of %d)" % (test.name, test_count, tests_count) publish.json_status(logger, args, "processing %s" % test_prefix) with logger.time("processing test %s", test_prefix): # always perform post mortem on the test directory. try: ignored, details = ignore.test(logger, args, test) if ignored: # If there is any pre-existing output move it to # backup. Otherwise it looks like the test was run # when it wasn't (and besides, the output is no longer # applicable). # # The isdir() test followed by a simple move, while # racy, should be good enough. if os.path.isdir(test.output_directory): logger.info("moving '%s' to '%s'", test.output_directory, backup_directory) os.makedirs(os.path.dirname(backup_directory), exist_ok=True) os.rename(test.output_directory, backup_directory) result_stats.add_ignored(test, ignored) test_stats.add(test, "ignored") logger.info("%s %s ignored (%s) %s", prefix, test_prefix, details, suffix) return # Be lazy when gathering the results, don't run the # sanitizer or diff. Let post.mortem figure out if the # test finished. old_result = post.mortem(test, args, domain_prefix=domain_prefix, quick=True) if skip.result(logger, args, old_result): logger.info("%s %s skipped (previously %s) %s", prefix, test_prefix, old_result, suffix) test_stats.add(test, "skipped") result_stats.add_skipped(old_result) return if old_result: test_stats.add(test, "tests", "retry") logger.info("%s %s started (previously %s) ....", prefix, test_prefix, old_result) else: test_stats.add(test, "tests", "try") logger.info("%s %s started ....", prefix, test_prefix) test_stats.add(test, "tests") # Create just the OUTPUT/ directory; if it already exists, # move any contents to BACKUP/. Do it file-by-file so # that, at no point, the OUTPUT/ directory is missing # (having an OUTPUT/ directory implies the test was # started). # # Don't create the path. If the parent directory is # missing, this will fail. # # By backing up each test just before it is started, a # trail of what tests were attempted during each run is # created. # # XXX: # # During boot, swan-transmogrify runs "chcon -R # testing/pluto". Of course this means that each time a # test is added and/or a test is run (adding files under # <test>/OUTPUT), the boot process (and consequently the # time taken to run a test) keeps increasing. # # By moving the directory contents to BACKUP/, which is # not under testing/pluto/ this problem is avoided. try: os.mkdir(test.output_directory) except FileNotFoundError: # Bail, something is messed up (for instance the parent directory doesn't exist). return except FileExistsError: logger.info("moving contents of '%s' to '%s'", test.output_directory, backup_directory) # Even if OUTPUT/ is empty, move it. os.makedirs(backup_directory, exist_ok=True) for name in os.listdir(test.output_directory): src = os.path.join(test.output_directory, name) dst = os.path.join(backup_directory, name) logger.debug("moving '%s' to '%s'", src, dst) os.replace(src, dst) # Now that the OUTPUT directory is empty, start a debug # log writing to that directory; include timing for this # test run. with logger.debug_time("testing %s", test_prefix, logfile=os.path.join( test.output_directory, "debug.log"), loglevel=logutil.INFO) as test_runtime: # boot the domains with logger.time("booting domains") as test_boot_time: try: test_domains = _boot_test_domains( logger, test, domain_prefix, boot_executor) except pexpect.TIMEOUT: logger.exception("timeout while booting domains") # Bail. Being unable to boot the domains is a # disaster. The test is UNRESOLVED. return # Run the scripts directly with logger.time( "running scripts %s", " ".join(("%s:%s" % (host, script)) for host, script in test.host_script_tuples)) as test_script_time: with tcpdump.Dump( logger, domain_prefix, test.output_directory, [ test_domain.domain for test_domain in test_domains.values() ], enable=args.tcpdump): try: # re-direct the test-result log file for test_domain in test_domains.values(): output = os.path.join( test.output_directory, test_domain.domain.host_name + ".console.verbose.txt") test_domain.console.output(open(output, "w")) for host, script in test.host_script_tuples: if args.stop_at == script: logger.error( "stopping test run at (before executing) script %s", script) break test_domain = test_domains[host] try: test_domain.read_file_run(script) except BaseException as e: # if there is an exception, write # it to the console test_domain.console.child.logfile.write( "\n*** exception running script %s ***\n%s" % (script, str(e))) raise for test_domain in test_domains.values(): test_domain.console.child.logfile.write( post.DONE) except pexpect.TIMEOUT as e: # A test ending with a timeout gets # treated as unresolved. Timeouts # shouldn't occur so human intervention # is required. logger.error( "**** timeout out while running test script %s ****", script) finally: # Close the redirected test-result log files logger.info( "closing all the test domain log files") for test_domain in test_domains.values(): outfile = test_domain.console.output() outfile.close() # Always disconnect from the test domains. logger.info("closing all the test domains") for test_domain in test_domains.values(): test_domain.close() finally: with logger.time("post-mortem %s", test_prefix): # The test finished; it is assumed that post.mortem # can deal with a crashed test. result = post.mortem(test, args, domain_prefix=domain_prefix, update=True) logger.info("%s %s %s%s%s %s", prefix, test_prefix, result, result.issues and " ", result.issues, suffix) # If the test was run (a fresh run would delete RESULT) # and finished (resolved in POSIX terminology), emit # enough JSON to fool scripts like pluto-testlist-scan.sh. # # A test that timed-out or crashed, isn't considered # resolved so the file isn't created. # # XXX: this should go away. if not os.path.isfile(test.result_file()) \ and result.resolution.isresolved(): RESULT = { jsonutil.result.testname: test.name, jsonutil.result.expect: test.status, jsonutil.result.result: result, jsonutil.result.issues: result.issues, jsonutil.result.hosts: test.host_names, jsonutil.result.time: jsonutil.ftime(test_runtime.start), jsonutil.result.runtime: round(test_runtime.seconds(), 1), jsonutil.result.boot_time: round(test_boot_time.seconds(), 1), jsonutil.result.script_time: round(test_script_time.seconds(), 1), jsonutil.result.total_time: round(test_runtime.seconds(), 1), } j = jsonutil.dumps(RESULT) logger.debug("filling '%s' with json: %s", test.result_file(), j) with open(test.result_file(), "w") as f: f.write(j) f.write("\n") # Do this after RESULT is created so it too is published. publish.everything(logger, args, result) publish.json_status(logger, args, "finished %s" % test_prefix) test_stats.add(test, "tests", str(result)) result_stats.add_result(result, old_result) # test_stats.log_summary(logger.info, header="updated test stats:", prefix=" ") result_stats.log_summary(logger.info, header="updated test results:", prefix=" ")
def _process_test(domain_prefix, test, args, test_stats, result_stats, test_count, tests_count, boot_executor): logger = logutil.getLogger(domain_prefix, __name__, test.name) prefix = "******" suffix = "******" test_stats.add(test, "total") test_runtime = test_boot_time = test_script_time = test_post_time = None old_result = None backup_directory = os.path.join(args.backup_directory, test.name) # Would the number of tests to be [re]run be better? test_prefix = "%s (test %d of %d)" % (test.name, test_count, tests_count) publish.json_status(logger, args, "processing %s" % test_prefix) with logger.time("processing test %s", test_prefix): # Ignoring the test completely? # # So that there's no possible confusion over the test being # run; remove any pre-existing output. ignored, details = ignore.test(logger, args, test) if ignored: # The isdir() test followed by a simple move, while # racy, should be good enough. if os.path.isdir(test.output_directory): logger.info("moving '%s' to '%s'", test.output_directory, backup_directory) os.makedirs(os.path.dirname(backup_directory), exist_ok=True) os.rename(test.output_directory, backup_directory) result_stats.add_ignored(test, ignored) test_stats.add(test, "ignored") logger.info("%s %s ignored (%s) %s", prefix, test_prefix, details, suffix) return # Skip the test, leaving old results? # # For instance, during a test re-run, skip any tests that are # passing. # # The check below compares the test and expected output, # ignoring any previous test result. This way the results are # consistent with kvmresults.py which always reflects the # current sources. # # - modifying the expected output so that it no longer matches # the last result is a fail # # - modifying the expected output so that it matches the last # result is a pass old_result = post.mortem(test, args, domain_prefix=domain_prefix, quick=False) if skip.result(logger, args, old_result): logger.info("%s %s skipped (previously %s) %s", prefix, test_prefix, old_result, suffix) test_stats.add(test, "skipped") result_stats.add_skipped(old_result) publish.everything(logger, args, old_result) return # Running the test ... # # From now on the test will be run so need to perform post # mortem. try: if old_result: test_stats.add(test, "tests", "retry") logger.info("%s %s started (previously %s) ....", prefix, test_prefix, old_result) else: test_stats.add(test, "tests", "try") logger.info("%s %s started ....", prefix, test_prefix) test_stats.add(test, "tests") # Create just the OUTPUT/ directory. # # If the directory already exists, copy the contents # BACKUP/. Do it file-by-file so that, at no point, the # OUTPUT/ directory is missing (having an OUTPUT/ # directory implies the test was started). # # Don't try to create the path. If the parent directory # is missing, this and the entire script will crash. # Someone did something nasty like deleted the parent # directory. # # By backing up each test just before it is started, # leaves a trail of what tests were attempted during a # test run. # # XXX: # # During boot, swan-transmogrify runs "chcon -R # testing/pluto". Of course this means that each time a # test is added and/or a test is run (adding files under # <test>/OUTPUT), the boot process (and consequently the # time taken to run a test) keeps increasing. # # By moving the directory contents to BACKUP/, which is # not under testing/pluto/ this problem is avoided. try: os.mkdir(test.output_directory) except FileExistsError: logger.info("moving contents of '%s' to '%s'", test.output_directory, backup_directory) # Even if OUTPUT/ is empty, move it. os.makedirs(backup_directory, exist_ok=True) for name in os.listdir(test.output_directory): src = os.path.join(test.output_directory, name) dst = os.path.join(backup_directory, name) logger.debug("moving '%s' to '%s'", src, dst) os.replace(src, dst) # Now that the OUTPUT directory is empty, start a debug # log writing to that directory; include timing for this # test run. with logger.debug_time("testing %s", test_prefix, logfile=os.path.join(test.output_directory, "debug.log"), loglevel=logutil.INFO) as test_runtime: # boot the domains with logger.time("booting domains") as test_boot_time: try: test_domains = _boot_test_domains(logger, test, domain_prefix, boot_executor) except pexpect.TIMEOUT: # Bail. Being unable to boot the domains is a # disaster. The test is UNRESOLVED. logger.exception("timeout while booting domains") return except pexpect.EOF: # Bail. Being unable to attach to the domains # is a disaster. The test is UNRESOLVED. logger.exception("eof (disconnect) while booting domains") return # Run the scripts directly with logger.time("running scripts %s", " ".join(("%s:%s" % (host, script)) for host, script in test.host_script_tuples)) as test_script_time: with tcpdump.Dump(logger, domain_prefix, test.output_directory, [test_domain.domain for test_domain in test_domains.values()], enable=args.tcpdump): try: # re-direct the test-result log file for test_domain in test_domains.values(): output = os.path.join(test.output_directory, test_domain.domain.host_name + ".console.verbose.txt") test_domain.console.output(open(output, "w")) for host, script in test.host_script_tuples: if args.stop_at == script: logger.error("stopping test run at (before executing) script %s", script) break test_domain = test_domains[host] try: test_domain.read_file_run(script) except pexpect.TIMEOUT as e: # A test ending with a timeout # gets treated as a FAIL. A # timeout while running a test # script is a sign that a command # hung. post_timeout = "%s %s:%s" % (post.TIMEOUT, host, script) logger.warning("*** %s ***" % post_timeout) test_domain.console.child.logfile.write("%s %s %s" % (post.LHS, post_timeout, post.RHS)) break except BaseException as e: # if there is an exception, write # it to the console test_domain.console.child.logfile.write("\n%s %s %s:%s %rhs\n%s" % (post.LHS, post.EXCEPTION, host, script, post.RHS, str(e))) raise for test_domain in test_domains.values(): test_domain.console.child.logfile.write(post.DONE) finally: # Close the redirected test-result log files logger.info("closing all the test domain log files") for test_domain in test_domains.values(): outfile = test_domain.console.output() outfile.close() # Always disconnect from the test domains. logger.info("closing all the test domains") for test_domain in test_domains.values(): test_domain.close() finally: with logger.time("post-mortem %s", test_prefix): # The test finished; it is assumed that post.mortem # can deal with a crashed test. result = post.mortem(test, args, domain_prefix=domain_prefix) logger.info("%s %s %s%s%s %s", prefix, test_prefix, result, result.issues and " ", result.issues, suffix) result.save() # If the test was run (a fresh run would delete RESULT) # and finished (resolved in POSIX terminology), emit # enough JSON to fool scripts like pluto-testlist-scan.sh. # # A test that timed-out or crashed, isn't considered # resolved so the file isn't created. # # XXX: this should go away. result_file = os.path.join(test.output_directory, "RESULT") if not os.path.isfile(result_file) \ and result.resolution.isresolved(): RESULT = { jsonutil.result.testname: test.name, jsonutil.result.expect: test.status, jsonutil.result.result: result, jsonutil.result.issues: result.issues, jsonutil.result.hosts: test.host_names, jsonutil.result.time: jsonutil.ftime(test_runtime.start), jsonutil.result.runtime: round(test_runtime.seconds(), 1), jsonutil.result.boot_time: round(test_boot_time.seconds(), 1), jsonutil.result.script_time: round(test_script_time.seconds(), 1), } j = jsonutil.dumps(RESULT) logger.debug("filling '%s' with json: %s", result_file, j) with open(result_file, "w") as f: f.write(j) f.write("\n") # Do this after RESULT is created so it too is published. publish.everything(logger, args, result) publish.json_status(logger, args, "finished %s" % test_prefix) test_stats.add(test, "tests", str(result)) result_stats.add_result(result, old_result) # test_stats.log_summary(logger.info, header="updated test stats:", prefix=" ") result_stats.log_summary(logger.info, header="updated test results:", prefix=" ")