def run(
self,
testcases,
time_limit,
repeat=1,
min_results=1,
exit_early=True,
expect_hang=False,
idle_delay=0,
idle_threshold=0,
on_iteration_cb=None,
):
"""Run testcase replay.
Args:
testcases (list): One or more TestCases to run.
time_limit (int): Maximum time in seconds a test should take to complete.
repeat (int): Maximum number of times to run the TestCase.
min_results (int): Minimum number of results needed before run can
be considered successful.
expect_hang (bool): Running testcases is expected to result in a hang.
exit_early (bool): If True the minimum required number of iterations
are performed to either meet `min_results` or
determine that it is not possible to do so.
If False `repeat` number of iterations are
performed.
idle_delay (int): Number of seconds to wait before polling for idle.
idle_threshold (int): CPU usage threshold to mark the process as idle.
on_iteration_cb (callable): called every time a single iteration is run
Returns:
list: ReplayResults that were found running testcases.
"""
assert idle_delay >= 0
assert idle_threshold >= 0
assert min_results > 0
assert repeat > 0
assert repeat >= min_results
assert testcases
assert time_limit > 0
assert self._harness is not None or len(testcases) == 1
assert not expect_hang or self._signature is not None
self.status = Status.start(db_file=self.STATUS_DB)
server_map = ServerMap()
if self._harness is None:
server_map.set_redirect("grz_start", "grz_current_test", required=False)
else:
server_map.set_dynamic_response(
"grz_harness", lambda _: self._harness, mime_type="text/html"
)
server_map.set_redirect("grz_start", "grz_harness", required=False)
# track unprocessed results
reports = dict()
try:
sig_hash = Report.calc_hash(self._signature) if self._signature else None
test_count = len(testcases)
relaunch = min(self._relaunch, repeat)
runner = Runner(
self.server,
self.target,
idle_threshold=idle_threshold,
idle_delay=idle_delay,
relaunch=relaunch * test_count,
)
# perform iterations
for _ in range(repeat):
self.status.iteration += 1
if on_iteration_cb is not None:
on_iteration_cb()
if self.target.closed:
if self._harness is None:
location = runner.location("/grz_start", self.server.port)
else:
location = runner.location(
"/grz_start",
self.server.port,
close_after=relaunch * test_count,
time_limit=time_limit,
)
runner.launch(location)
# run tests
durations = list()
served = list()
for test_idx in range(test_count):
if test_count > 1:
LOG.info(
"Running test, part %d/%d (%d/%d)...",
test_idx + 1,
test_count,
self.status.iteration,
repeat,
)
else:
LOG.info(
"Running test (%d/%d)...", self.status.iteration, repeat
)
# update redirects
if self._harness is not None:
next_idx = (test_idx + 1) % test_count
server_map.set_redirect(
"grz_next_test",
testcases[next_idx].landing_page,
required=True,
)
server_map.set_redirect(
"grz_current_test",
testcases[test_idx].landing_page,
required=False,
)
# run testcase
run_result = runner.run(
self.ignore,
server_map,
testcases[test_idx],
wait_for_callback=self._harness is None,
)
durations.append(run_result.duration)
served.append(run_result.served)
if run_result.status != Result.NONE or not run_result.attempted:
break
if not run_result.attempted:
LOG.warning("Test case was not served")
if runner.initial:
if run_result.status == Result.FOUND:
# TODO: what is to best action to take in this case?
LOG.warning("Delayed startup failure detected")
else:
LOG.warning("Timeout too short? System too busy?")
# process run results
if run_result.status == Result.FOUND:
# processing the result may take a few minutes (rr)
# update console to show progress
LOG.info("Processing result...")
# TODO: use self.target.create_report here
log_path = mkdtemp(prefix="logs_", dir=grz_tmp("logs"))
self.target.save_logs(log_path)
report = Report(
log_path, self.target.binary, is_hang=run_result.timeout
)
# check signatures
if run_result.timeout:
short_sig = "Potential hang detected"
elif report.crash_signature is not None:
short_sig = report.crash_info.createShortSignature()
else:
# FM crash signature creation failed
short_sig = "Signature creation failed"
# set active signature
if (
not runner.startup_failure
and not self._any_crash
and not run_result.timeout
and self._signature is None
):
assert not expect_hang
LOG.debug("no signature given, using %r", short_sig)
self._signature = report.crash_signature
# bucket result
if not runner.startup_failure and (
self._any_crash
or self.check_match(self._signature, report, expect_hang)
):
if sig_hash is not None:
LOG.debug("using provided signature (hash) to bucket")
bucket_hash = sig_hash
else:
bucket_hash = report.crash_hash
self.status.results.count(bucket_hash, short_sig)
LOG.info(
"Result: %s (%s:%s)",
short_sig,
report.major[:8],
report.minor[:8],
)
if bucket_hash not in reports:
reports[bucket_hash] = ReplayResult(
report, served, durations, True
)
LOG.debug("now tracking %s", bucket_hash)
report = None # don't remove report
else:
reports[bucket_hash].count += 1
LOG.debug("already tracking %s", bucket_hash)
else:
LOG.info(
"Result: Different signature: %s (%s:%s)",
short_sig,
report.major[:8],
report.minor[:8],
)
self.status.ignored += 1
if report.crash_hash not in reports:
reports[report.crash_hash] = ReplayResult(
report, served, durations, False
)
LOG.debug("now tracking %s", report.crash_hash)
report = None # don't remove report
else:
reports[report.crash_hash].count += 1
LOG.debug("already tracking %s", report.crash_hash)
# purge untracked report
if report is not None:
report.cleanup()
report = None
elif run_result.status == Result.IGNORED:
self.status.ignored += 1
LOG.info("Result: Ignored (%d)", self.status.ignored)
if exit_early and self.status.iteration < repeat:
# check if failed to meet minimum number of results
if (
repeat - self.status.iteration + self.status.results.total
< min_results
):
# failed to reproduce issue
LOG.debug("skipping remaining attempts")
LOG.debug(
"results (%d) < minimum (%d), after %d attempts",
self.status.results.total,
min_results,
self.status.iteration,
)
# NOTE: this can be tricky if the harness is used because it can
# skip the shutdown performed in the harness and runner, if this
# is an issue for now use relaunch=1
break
# check if complete (minimum number of results found)
if self.status.results.total >= min_results:
assert self.status.results.total == min_results
assert (
sum(x.count for x in reports.values() if x.expected)
>= min_results
)
LOG.debug(
"results == expected (%d), after %d attempts",
min_results,
self.status.iteration,
)
break
# TODO: should we warn about large browser logs?
# process results
if self._any_crash:
assert (
all(x.expected for x in reports.values()) or runner.startup_failure
)
# add all results if min_results was reached
if sum(x.count for x in reports.values() if x.expected) >= min_results:
results = list(reports.values())
else:
# add only unexpected results since min_results was not reached
results = list()
for report in reports.values():
if report.expected:
report.report.cleanup()
else:
results.append(report)
LOG.debug(
"%d (any_crash) less than minimum %d",
self.status.results.total,
min_results,
)
else:
# there should be at most one expected bucket
assert sum(x.expected for x in reports.values()) <= 1
# filter out unreliable expected results
results = list()
for crash_hash, report in reports.items():
if report.expected and report.count < min_results:
LOG.debug(
"%r less than minimum (%d/%d)",
crash_hash,
report.count,
min_results,
)
report.report.cleanup()
continue
results.append(report)
# this should only be displayed when both conditions are met:
# 1) runner does not close target (no delay was given before shutdown)
# 2) result has not been successfully reproduced
if (
self._relaunch > 1
and not self.target.closed
and not any(x.expected for x in results)
):
LOG.info("Perhaps try with --relaunch=1")
# active reports have been moved to results
# clear reports to avoid cleanup of active reports
reports.clear()
return results
finally:
# we don't want to clean up but we are not checking results
self.target.close(force_close=True)
# remove unprocessed reports
for report in reports.values():
report.report.cleanup()
def run(self,
testcases,
repeat=1,
min_results=1,
exit_early=True,
idle_delay=0,
idle_threshold=0):
"""Run testcase replay.
Args:
testcases (list): One or more TestCases to run.
repeat (int): Maximum number of times to run the TestCase.
min_results (int): Minimum number of results needed before run can
be considered successful.
exit_early (bool): If True the minimum required number of iterations
are performed to either meet `min_results` or
determine that it is not possible to do so.
If False `repeat` number of iterations are
performed.
idle_delay (int): Number of seconds to wait before polling for idle.
idle_threshold (int): CPU usage threshold to mark the process as idle.
Returns:
list: ReplayResults that were found running testcases.
"""
assert idle_delay >= 0
assert idle_threshold >= 0
assert min_results > 0
assert repeat > 0
assert repeat >= min_results
assert testcases
assert len(testcases) == 1 or self._harness is not None
if self.status is not None:
LOG.debug("clearing previous status data")
self.status.cleanup()
self.status = Status.start()
server_map = ServerMap()
if self._harness is not None:
server_map.set_dynamic_response("grz_harness",
lambda: self._harness,
mime_type="text/html")
# track unprocessed results
reports = dict()
# track unpacked testcases
unpacked = list()
try:
sig_hash = Report.calc_hash(
self._signature) if self._signature else None
test_count = len(testcases)
LOG.debug("unpacking testcases (%d)...", test_count)
for test in testcases:
dst_path = mkdtemp(prefix="tc_", dir=grz_tmp("serve"))
unpacked.append(dst_path)
test.dump(dst_path)
relaunch = min(self._relaunch, repeat)
runner = Runner(self.server,
self.target,
idle_threshold=idle_threshold,
idle_delay=idle_delay,
relaunch=relaunch * test_count)
# perform iterations
for _ in range(repeat):
self.status.iteration += 1
if self.target.closed:
if self._harness is None:
location = runner.location("/grz_current_test",
self.server.port)
else:
location = runner.location("/grz_harness",
self.server.port,
close_after=relaunch *
test_count,
timeout=self.server.timeout)
startup_error = False
# The environment from the initial testcase is used because
# a sequence of testcases is expected to be run without
# relaunching the Target to match the functionality of
# Grizzly. If this is not the case each TestCase should
# be run individually.
runner.launch(location, env_mod=testcases[0].env_vars)
# run tests
durations = list()
served = list()
for test_idx in range(test_count):
if test_count > 1:
LOG.info("Running test, part %d/%d (%d/%d)...",
test_idx + 1, test_count,
self.status.iteration, repeat)
else:
LOG.info("Running test (%d/%d)...",
self.status.iteration, repeat)
# update redirects
if self._harness is not None:
next_idx = (test_idx + 1) % test_count
server_map.set_redirect(
"grz_next_test",
testcases[next_idx].landing_page,
required=True)
server_map.set_redirect("grz_current_test",
testcases[test_idx].landing_page,
required=False)
# run testcase
run_result = runner.run(
self.ignore,
server_map,
testcases[test_idx],
test_path=unpacked[test_idx],
wait_for_callback=self._harness is None)
durations.append(run_result.duration)
served.append(run_result.served)
if run_result.status is not None or not run_result.attempted:
break
if not run_result.attempted:
LOG.warning("Test case was not served")
if run_result.initial:
startup_error = True
if run_result.status == RunResult.FAILED:
# TODO: what is to best action to take in this case?
LOG.warning("Delayed startup failure detected")
else:
LOG.warning("Timeout too short? System too busy?")
# process run results
if run_result.status == RunResult.FAILED:
# TODO: use self.target.create_report here
log_path = mkdtemp(prefix="logs_", dir=grz_tmp("logs"))
self.target.save_logs(log_path)
report = Report(log_path, self.target.binary)
# check signatures
short_sig = report.crash_info.createShortSignature()
if (not startup_error and not self._any_crash
and self._signature is None
and short_sig != "No crash detected"):
LOG.debug("no signature given, using %r", short_sig)
self._signature = report.crash_signature
if short_sig == "No crash detected":
# TODO: verify report.major == "NO_STACK" otherwise FM failed to parse the logs
# TODO: change this to support hangs/timeouts, etc
LOG.info("Result: No crash detected")
elif (not startup_error
and (self._any_crash
or self._signature.matches(report.crash_info))):
self.status.count_result(short_sig)
LOG.info("Result: %s (%s:%s)", short_sig,
report.major[:8], report.minor[:8])
if sig_hash:
LOG.debug(
"using provided signature (hash) to bucket")
bucket_hash = sig_hash
else:
bucket_hash = report.crash_hash
if bucket_hash not in reports:
reports[bucket_hash] = ReplayResult(
report, served, durations, True)
LOG.debug("now tracking %s", bucket_hash)
report = None # don't remove report
else:
reports[bucket_hash].count += 1
LOG.debug("already tracking %s", bucket_hash)
else:
LOG.info("Result: Different signature: %s (%s:%s)",
short_sig, report.major[:8], report.minor[:8])
self.status.ignored += 1
if report.crash_hash not in reports:
reports[report.crash_hash] = ReplayResult(
report, served, durations, False)
LOG.debug("now tracking %s", report.crash_hash)
report = None # don't remove report
else:
reports[report.crash_hash].count += 1
LOG.debug("already tracking %s", report.crash_hash)
# purge untracked report
if report is not None:
report.cleanup()
report = None
elif run_result.status == RunResult.IGNORED:
self.status.ignored += 1
LOG.info("Result: Ignored (%d)", self.status.ignored)
if exit_early:
# failed to meet minimum number of results
if repeat - self.status.iteration + self.status.results < min_results:
if self.status.iteration < repeat:
LOG.debug("skipping remaining attempts")
# failed to reproduce issue
LOG.debug(
"results (%d) < minimum (%d), after %d attempts",
self.status.results, min_results,
self.status.iteration)
# NOTE: this can be tricky if the harness is used because it can
# skip the shutdown performed in the harness and runner, if this
# is an issue for now use relaunch=1
break
# check if complete (minimum number of results found)
if self.status.results >= min_results:
assert self.status.results == min_results
assert sum(x.count for x in reports.values()
if x.expected) >= min_results
LOG.debug(
"results == expected (%d), after %d attempts",
min_results, self.status.iteration)
break
# warn about large browser logs
#self.status.log_size = self.target.log_size()
#if self.status.log_size > self.TARGET_LOG_SIZE_WARN:
# LOG.warning("Large browser logs: %dMBs", (self.status.log_size / 0x100000))
# process results
results = list()
if self._any_crash:
assert all(x.expected for x in reports.values())
if sum(x.count for x in reports.values()) >= min_results:
results = list(reports.values())
else:
LOG.debug("%d (any_crash) less than minimum %d",
self.status.results, min_results)
for report in reports.values():
report.report.cleanup()
else:
assert sum(x.expected for x in reports.values()) <= 1
# filter out unreliable expected results
for crash_hash, report in reports.items():
if report.expected and report.count < min_results:
LOG.debug("%r less than minimum (%d/%d)", crash_hash,
report.count, min_results)
report.report.cleanup()
continue
results.append(report)
# this should only be displayed when both conditions are met:
# 1) runner does not close target (no delay was given before shutdown)
# 2) result has not been successfully reproduced
if self._relaunch > 1 and not self.target.closed and not any(
x.expected for x in results):
LOG.info("Perhaps try with --relaunch=1")
# active reports have been moved to results
# clear reports to avoid cleanup of active reports
reports.clear()
return results
finally:
# remove unpacked testcase data
for tc_path in unpacked:
rmtree(tc_path)
self.target.close()
# remove unprocessed reports
for report in reports.values():
report.report.cleanup()
def run(self, repeat=1, min_results=1):
"""Run testcase replay.
Args:
repeat (int): Maximum number of times to run the test case.
min_results (int): Minimum number of results needed before run can
be considered successful.
Returns:
bool: True if results were reproduced otherwise False.
"""
assert repeat > 0
assert min_results > 0
assert min_results <= repeat
self.status = Status.start()
server_map = ServerMap()
if self._harness is not None:
def _dyn_close(): # pragma: no cover
if self.target.monitor.is_healthy():
# delay to help catch window close/shutdown related crashes
sleep(0.1)
self.target.close()
return b"<h1>Close Browser</h1>"
server_map.set_dynamic_response("grz_close_browser",
_dyn_close,
mime_type="text/html")
server_map.set_dynamic_response("grz_harness",
lambda: self._harness,
mime_type="text/html")
server_map.set_redirect("grz_next_test",
self.testcase.landing_page,
required=True)
server_map.set_redirect("grz_current_test",
self.testcase.landing_page,
required=False)
success = False
for _ in range(repeat):
self.status.iteration += 1
if self.target.closed:
LOG.info("Launching target...")
if self._harness is None:
location = self._runner.location("/grz_current_test",
self.server.port)
else:
location = self._runner.location(
"/grz_harness",
self.server.port,
close_after=self.target.rl_reset,
forced_close=self.target.forced_close)
try:
self._runner.launch(location,
env_mod=self.testcase.env_vars)
except TargetLaunchError:
LOG.error(
"Target launch error. Check browser logs for details.")
log_path = mkdtemp(prefix="grzreplay_logs_")
self.target.save_logs(log_path)
self._reports_other["STARTUP"] = Report.from_path(log_path)
raise
self.target.step()
LOG.info("Performing replay (%d/%d)...", self.status.iteration,
repeat)
# run test case
self._runner.run(self.ignore,
server_map,
self.testcase,
wait_for_callback=self._harness is None)
# process results
if self._runner.result == self._runner.FAILED:
log_path = mkdtemp(prefix="grzreplay_logs_")
self.target.save_logs(log_path)
report = Report.from_path(log_path)
# check signatures
crash_info = report.crash_info(self.target.binary)
short_sig = crash_info.createShortSignature()
if not self._any_crash and self._signature is None and short_sig != "No crash detected":
# signature has not been specified use the first one created
self._signature = report.crash_signature(crash_info)
if short_sig == "No crash detected":
# TODO: verify report.major == "NO_STACK" otherwise FM failed to parse the logs
# TODO: change this to support hangs/timeouts, etc
LOG.info("Result: No crash detected")
crash_hash = None
elif self._any_crash or self._signature.matches(crash_info):
self.status.results += 1
LOG.info("Result: %s (%s:%s)", short_sig, report.major[:8],
report.minor[:8])
crash_hash = report.crash_hash(crash_info)
if crash_hash not in self._reports_expected:
LOG.debug("now tracking %s", crash_hash)
self._reports_expected[crash_hash] = report
report = None # don't remove report
assert self._any_crash or len(self._reports_expected) == 1
else:
LOG.info("Result: Different signature: %s (%s:%s)",
short_sig, report.major[:8], report.minor[:8])
self.status.ignored += 1
crash_hash = report.crash_hash(crash_info)
if crash_hash not in self._reports_other:
LOG.debug("now tracking %s", crash_hash)
self._reports_other[crash_hash] = report
report = None # don't remove report
# purge untracked report
if report is not None:
if crash_hash is not None:
LOG.debug("already tracking %s", crash_hash)
report.cleanup()
report = None
elif self._runner.result == self._runner.IGNORED:
self.status.ignored += 1
LOG.info("Result: Ignored (%d)", self.status.ignored)
elif self._runner.result == self._runner.ERROR:
LOG.error(
"ERROR: Replay malfunction, test case was not served")
break
# check status and exit early if possible
if repeat - self.status.iteration + self.status.results < min_results:
if self.status.iteration < repeat:
LOG.debug("skipping remaining attempts")
# failed to reproduce issue
LOG.debug("results (%d) < expected (%s) after %d attempts",
self.status.results, min_results,
self.status.iteration)
break
if self.status.results >= min_results:
assert self.status.results == min_results
success = True
LOG.debug("results == expected (%s) after %d attempts",
min_results, self.status.iteration)
break
# warn about large browser logs
#self.status.log_size = self.target.log_size()
#if self.status.log_size > self.TARGET_LOG_SIZE_WARN:
# LOG.warning("Large browser logs: %dMBs", (self.status.log_size / 0x100000))
# trigger relaunch by closing the browser if needed
self.target.check_relaunch()
if success:
LOG.info("Result successfully reproduced")
else:
LOG.info("Failed to reproduce results")
self.target.close()
return success