def test_expected_subtest_failure(capfd): # Tests that an expected subtest failure does not cause the test to fail # Set up the handler. output = StringIO() logger = structuredlog.StructuredLogger("test_a") formatter = ChromiumFormatter() logger.add_handler(handlers.StreamHandler(output, formatter)) # Run a test with some expected subtest failures. logger.suite_start(["t1"], run_info={}, time=123) logger.test_start("t1") logger.test_status("t1", status="FAIL", expected="FAIL", subtest="t1_a", message="t1_a_message") logger.test_status("t1", status="PASS", subtest="t1_b", message="t1_b_message") logger.test_status("t1", status="TIMEOUT", expected="TIMEOUT", subtest="t1_c", message="t1_c_message") # The subtest failures are all expected so this test should not be added to # the set of tests with subtest failures. assert "t1" not in formatter.tests_with_subtest_fails # The test status is reported as a pass here because the harness was able to # run the test to completion. logger.test_end("t1", status="PASS", expected="PASS") logger.suite_end() # check nothing got output to stdout/stderr # (note that mozlog outputs exceptions during handling to stderr!) captured = capfd.readouterr() assert captured.out == "" assert captured.err == "" # check the actual output of the formatter output.seek(0) output_json = json.load(output) test_obj = output_json["tests"]["t1"] t1_log = test_obj["artifacts"]["log"] assert t1_log == "[FAIL] t1_a: t1_a_message\n" \ "[PASS] t1_b: t1_b_message\n" \ "[TIMEOUT] t1_c: t1_c_message\n" # The status of the test in the output is a pass because the subtest # failures were all expected. assert test_obj["actual"] == "PASS"
def create_log(self, *args, **kwargs): logger = structuredlog.StructuredLogger("expected_test") data = StringIO.StringIO() handler = handlers.StreamHandler(data, formatters.JSONFormatter()) logger.add_handler(handler) log_entries = ([("suite_start", { "tests": [], "run_info": kwargs.get("run_info", {}) })] + list(args) + [("suite_end", {})]) for item in log_entries: action, kwargs = item getattr(logger, action)(**kwargs) logger.remove_handler(handler) data.seek(0) return data
def test_reftest_screenshots(capfd): # reftest_screenshots, if present, should be plumbed into artifacts. # Set up the handler. output = StringIO() logger = structuredlog.StructuredLogger("test_a") logger.add_handler(handlers.StreamHandler(output, ChromiumFormatter())) # Run a reftest with reftest_screenshots. logger.suite_start(["t1"], run_info={}, time=123) logger.test_start("t1") logger.test_end("t1", status="FAIL", expected="PASS", extra={ "reftest_screenshots": [ { "url": "foo.html", "hash": "HASH1", "screenshot": "DATA1" }, "!=", { "url": "foo-ref.html", "hash": "HASH2", "screenshot": "DATA2" }, ] }) logger.suite_end() # check nothing got output to stdout/stderr # (note that mozlog outputs exceptions during handling to stderr!) captured = capfd.readouterr() assert captured.out == "" assert captured.err == "" # check the actual output of the formatter output.seek(0) output_json = json.load(output) test_obj = output_json["tests"]["t1"] assert test_obj["artifacts"]["screenshots"] == [ "foo.html: DATA1", "foo-ref.html: DATA2", ]
def test_unexpected_subtest_pass(capfd): # A subtest that unexpectedly passes is considered a failure condition. # Set up the handler. output = StringIO() logger = structuredlog.StructuredLogger("test_a") formatter = ChromiumFormatter() logger.add_handler(handlers.StreamHandler(output, formatter)) # Run a test with a subtest that is expected to fail but passes. logger.suite_start(["t1"], run_info={}, time=123) logger.test_start("t1") logger.test_status("t1", status="PASS", expected="FAIL", subtest="t1_a", message="t1_a_message") # Since the subtest behaviour is unexpected, it's considered a failure, so # the test should be added to the set of tests with subtest failures. assert "t1" in formatter.tests_with_subtest_fails # The test status is reported as a pass here because the harness was able to # run the test to completion. logger.test_end("t1", status="PASS", expected="PASS") logger.suite_end() # check nothing got output to stdout/stderr # (note that mozlog outputs exceptions during handling to stderr!) captured = capfd.readouterr() assert captured.out == "" assert captured.err == "" # check the actual output of the formatter output.seek(0) output_json = json.load(output) test_obj = output_json["tests"]["t1"] t1_artifacts = test_obj["artifacts"] assert t1_artifacts["log"] == "[PASS expected FAIL] t1_a: t1_a_message\n" assert t1_artifacts["wpt_subtest_failure"] == "true" # Since the subtest status is unexpected, we fail the test. But we report # wpt_actual_status as an artifact assert t1_artifacts["wpt_actual_status"] == "PASS" assert test_obj["actual"] == "FAIL" assert test_obj["expected"] == "PASS" # Also ensure that the formatter cleaned up its internal state assert "t1" not in formatter.tests_with_subtest_fails
def test_subtest_messages(capfd): # Tests accumulation of test output # Set up the handler. output = StringIO() logger = structuredlog.StructuredLogger("test_a") logger.add_handler(handlers.StreamHandler(output, ChromiumFormatter())) # Run two tests with subtest messages. The subtest name should be included # in the output. We should also tolerate missing messages. logger.suite_start(["t1", "t2"], run_info={}, time=123) logger.test_start("t1") logger.test_status("t1", status="FAIL", subtest="t1_a", message="t1_a_message") logger.test_status("t1", status="PASS", subtest="t1_b", message="t1_b_message") logger.test_end("t1", status="PASS", expected="PASS") logger.test_start("t2") # Currently, subtests with empty messages will be ignored logger.test_status("t2", status="PASS", subtest="t2_a") # A test-level message will also be appended logger.test_end("t2", status="TIMEOUT", expected="PASS", message="t2_message") logger.suite_end() # check nothing got output to stdout/stderr # (note that mozlog outputs exceptions during handling to stderr!) captured = capfd.readouterr() assert captured.out == "" assert captured.err == "" # check the actual output of the formatter output.seek(0) output_json = json.load(output) t1_log = output_json["tests"]["t1"]["artifacts"]["log"] assert t1_log == "subtest_failure\n" \ "[FAIL expected PASS] t1_a: t1_a_message\n" \ "[PASS] t1_b: t1_b_message\n" t2_log = output_json["tests"]["t2"]["artifacts"]["log"] assert t2_log == "[TIMEOUT expected PASS] t2_message\n"
def test_update_pickle(): logger = structuredlog.StructuredLogger("expected_test") args = { "test_paths": { "/": { "tests_path": os.path.abspath( os.path.join(here, os.pardir, os.pardir, os.pardir, os.pardir)) }, }, "abort": False, "continue": False, "sync": False, } args2 = args.copy() args2["abort"] = True wptupdate = WPTUpdate(logger, **args2) wptupdate = WPTUpdate(logger, runner_cls=UpdateRunner, **args) wptupdate.run()
def test_chromium_test_name_trie(capfd): # Ensure test names are broken into directories and stored in a trie with # test results at the leaves. # Set up the handler. output = StringIO() logger = structuredlog.StructuredLogger("test_a") logger.add_handler( handlers.StreamHandler(output, chromium.ChromiumFormatter())) # output a bunch of stuff logger.suite_start(["/foo/bar/test-id-1", "/foo/test-id-2"], run_info={}, time=123) logger.test_start("/foo/bar/test-id-1") logger.test_end("/foo/bar/test-id-1", status="TIMEOUT", expected="FAIL") logger.test_start("/foo/test-id-2") logger.test_end("/foo/test-id-2", status="ERROR", expected="TIMEOUT") logger.suite_end() # check nothing got output to stdout/stderr # (note that mozlog outputs exceptions during handling to stderr!) captured = capfd.readouterr() assert captured.out == "" assert captured.err == "" # check the actual output of the formatter output.seek(0) output_obj = json.load(output) # Ensure that the test names are broken up by directory name and that the # results are stored at the leaves. test_obj = output_obj["tests"]["foo"]["bar"]["test-id-1"] assert test_obj["actual"] == "TIMEOUT" assert test_obj["expected"] == "FAIL" test_obj = output_obj["tests"]["foo"]["test-id-2"] # The ERROR status is mapped to FAIL for Chromium assert test_obj["actual"] == "FAIL" assert test_obj["expected"] == "TIMEOUT"
def __init__(self, suite_name, size, test_source_cls, test_source_kwargs, browser_cls, browser_kwargs, executor_cls, executor_kwargs, rerun=1, pause_after_test=False, pause_on_unexpected=False, restart_on_unexpected=True, debug_info=None, capture_stdio=True, restart_on_new_group=True, recording=None): self.suite_name = suite_name self.size = size self.test_source_cls = test_source_cls self.test_source_kwargs = test_source_kwargs self.browser_cls = browser_cls self.browser_kwargs = browser_kwargs self.executor_cls = executor_cls self.executor_kwargs = executor_kwargs self.pause_after_test = pause_after_test self.pause_on_unexpected = pause_on_unexpected self.restart_on_unexpected = restart_on_unexpected self.debug_info = debug_info self.rerun = rerun self.capture_stdio = capture_stdio self.restart_on_new_group = restart_on_new_group self.recording = recording assert recording is not None self.pool = set() # Event that is polled by threads so that they can gracefully exit in the face # of sigint self.stop_flag = threading.Event() self.logger = structuredlog.StructuredLogger(suite_name)
def test_wptreport_run_info_optional(capfd): """per the mozlog docs, run_info is optional; check we work without it""" # setup the logger output = StringIO() logger = structuredlog.StructuredLogger("test_a") logger.add_handler(handlers.StreamHandler(output, WptreportFormatter())) # output a bunch of stuff logger.suite_start(["test-id-1"]) # no run_info arg! logger.test_start("test-id-1") logger.test_end("test-id-1", "PASS") logger.suite_end() # check nothing got output to stdout/stderr # (note that mozlog outputs exceptions during handling to stderr!) captured = capfd.readouterr() assert captured.out == "" assert captured.err == "" # check the actual output of the formatter output.seek(0) output_obj = json.load(output) assert "run_info" not in output_obj or output_obj["run_info"] == {}
def test_flaky_test_unexpected(capfd): # Check that a flaky test with multiple possible statuses is seen as # unexpected if its actual status is NOT one of the possible ones. # set up the handler. output = StringIO() logger = structuredlog.StructuredLogger("test_a") logger.add_handler(handlers.StreamHandler(output, ChromiumFormatter())) # Run a test that is known to be flaky logger.suite_start(["t1"], run_info={}, time=123) logger.test_start("t1") logger.test_end("t1", status="ERROR", expected="OK", known_intermittent=["TIMEOUT"]) logger.suite_end() # check nothing got output to stdout/stderr # (note that mozlog outputs exceptions during handling to stderr!) captured = capfd.readouterr() assert captured.out == "" assert captured.err == "" # check the actual output of the formatter output.seek(0) output_json = json.load(output) test_obj = output_json["tests"]["t1"] # The test's statuses are all mapped, changing ERROR->FAIL and OK->PASS assert test_obj["actual"] == "FAIL" # All the possible statuses are merged and sorted together into expected. assert test_obj["expected"] == "PASS TIMEOUT" # ...this is a regression and unexpected because the actual status is not # one of the expected ones assert test_obj["is_regression"] is True assert test_obj["is_unexpected"] is True
def test_filter_component(self): component_logger = structuredlog.StructuredLogger( self.logger.name, "test_component") component_logger.component_filter = handlers.LogLevelFilter( lambda x: x, "info") self.logger.debug("Test") self.assertFalse(self.handler.empty) self.assert_log_equals({ "action": "log", "level": "DEBUG", "message": "Test" }) self.assertTrue(self.handler.empty) component_logger.info("Test 1") self.assertFalse(self.handler.empty) self.assert_log_equals({ "action": "log", "level": "INFO", "message": "Test 1", "component": "test_component" }) component_logger.debug("Test 2") self.assertTrue(self.handler.empty) component_logger.component_filter = None component_logger.debug("Test 3") self.assertFalse(self.handler.empty) self.assert_log_equals({ "action": "log", "level": "DEBUG", "message": "Test 3", "component": "test_component" })
def test_wptreport_lone_surrogate_ucs2(capfd): # Since UCS4 is a superset of UCS2 we can meaningfully test the UCS2 code on a # UCS4 build, but not the reverse. However UCS2 is harder to handle and UCS4 is # the commonest (and sensible) configuration, so that's OK. output = StringIO() logger = structuredlog.StructuredLogger("test_a") logger.add_handler(handlers.StreamHandler(output, WptreportFormatter())) with mock.patch.object(wptreport, 'surrogate_replacement', wptreport.SurrogateReplacementUcs2()): # output a bunch of stuff logger.suite_start(["test-id-1"]) # no run_info arg! logger.test_start("test-id-1") logger.test_status("test-id-1", subtest=u"Name with surrogate\uD800", status="FAIL", message=u"\U0001F601 \uDE0A\uD83D \uD83D\uDE0A") logger.test_end("test-id-1", status="PASS", message=u"\uDE0A\uD83D \uD83D\uDE0A \U0001F601") logger.suite_end() # check nothing got output to stdout/stderr # (note that mozlog outputs exceptions during handling to stderr!) captured = capfd.readouterr() assert captured.out == "" assert captured.err == "" # check the actual output of the formatter output.seek(0) output_obj = json.load(output) test = output_obj["results"][0] assert test["message"] == u"U+de0aU+d83d \U0001f60a \U0001F601" subtest = test["subtests"][0] assert subtest["name"] == u"Name with surrogateU+d800" assert subtest["message"] == u"\U0001F601 U+de0aU+d83d \U0001f60a"
def setUp(self): self.logger = structuredlog.StructuredLogger("test") self.handler = TestHandler() self.logger.add_handler(self.handler)
def setUp(self): self.logger = structuredlog.StructuredLogger("testBuffer") self.handler = handlers.BufferHandler(TestHandler(), message_limit=4) self.logger.add_handler(self.handler)
from collections import defaultdict, namedtuple from mozlog import structuredlog from six import ensure_str, ensure_text, iteritems, iterkeys, itervalues, text_type from six.moves import intern, range from . import manifestupdate from . import testloader from . import wptmanifest from . import wpttest from .expected import expected_path from .vcs import git manifest = None # Module that will be imported relative to test_root manifestitem = None logger = structuredlog.StructuredLogger("web-platform-tests") try: import ujson as json except ImportError: import json class RunInfo(object): """A wrapper around RunInfo dicts so that they can be hashed by identity""" def __init__(self, dict_value): self.data = dict_value self.canonical_repr = tuple( tuple(item) for item in sorted(dict_value.items())) def __getitem__(self, key):
def run(self): """Main loop for the TestRunnerManager. TestRunnerManagers generally receive commands from their TestRunner updating them on the status of a test. They may also have a stop flag set by the main thread indicating that the manager should shut down the next time the event loop spins.""" self.logger = structuredlog.StructuredLogger(self.suite_name) with self.browser_cls(self.logger, **self.browser_kwargs) as browser: self.browser = BrowserManager(self.logger, browser, self.command_queue, no_timeout=self.debug_info is not None) dispatch = { RunnerManagerState.before_init: self.start_init, RunnerManagerState.initializing: self.init, RunnerManagerState.running: self.run_test, RunnerManagerState.restarting: self.restart_runner } self.state = RunnerManagerState.before_init() end_states = (RunnerManagerState.stop, RunnerManagerState.error) try: while not isinstance(self.state, end_states): f = dispatch.get(self.state.__class__) while f: self.logger.debug("Dispatch %s" % f.__name__) if self.should_stop(): return new_state = f() if new_state is None: break self.state = new_state self.logger.debug("new state: %s" % self.state.__class__.__name__) if isinstance(self.state, end_states): return f = dispatch.get(self.state.__class__) new_state = None while new_state is None: new_state = self.wait_event() if self.should_stop(): return self.state = new_state self.logger.debug("new state: %s" % self.state.__class__.__name__) except Exception as e: self.logger.error(traceback.format_exc(e)) raise finally: self.logger.debug( "TestRunnerManager main loop terminating, starting cleanup" ) clean = isinstance(self.state, RunnerManagerState.stop) self.stop_runner(force=not clean) self.teardown() self.logger.debug("TestRunnerManager main loop terminated")
def test_subtest_failure(capfd): # Tests that a test fails if a subtest fails # Set up the handler. output = StringIO() logger = structuredlog.StructuredLogger("test_a") formatter = ChromiumFormatter() logger.add_handler(handlers.StreamHandler(output, formatter)) # Run a test with some subtest failures. logger.suite_start(["t1"], run_info={}, time=123) logger.test_start("t1") logger.test_status("t1", status="FAIL", subtest="t1_a", message="t1_a_message") logger.test_status("t1", status="PASS", subtest="t1_b", message="t1_b_message") logger.test_status("t1", status="TIMEOUT", subtest="t1_c", message="t1_c_message") # Make sure the test name was added to the set of tests with subtest fails assert "t1" in formatter.tests_with_subtest_fails # The test status is reported as a pass here because the harness was able to # run the test to completion. logger.test_end("t1", status="PASS", expected="PASS", message="top_message") logger.suite_end() # check nothing got output to stdout/stderr # (note that mozlog outputs exceptions during handling to stderr!) captured = capfd.readouterr() assert captured.out == "" assert captured.err == "" # check the actual output of the formatter output.seek(0) output_json = json.load(output) test_obj = output_json["tests"]["t1"] t1_artifacts = test_obj["artifacts"] assert t1_artifacts["wpt_actual_metadata"] == [ "[t1]\n expected: PASS\n", " [t1_a]\n expected: FAIL\n", " [t1_b]\n expected: PASS\n", " [t1_c]\n expected: TIMEOUT\n", ] assert t1_artifacts["wpt_log"] == [ "Harness: top_message\n", "t1_a: t1_a_message\n", "t1_b: t1_b_message\n", "t1_c: t1_c_message\n", ] assert t1_artifacts["wpt_subtest_failure"] == ["true"] # The status of the test in the output is a failure because subtests failed, # despite the harness reporting that the test passed. But the harness status # is logged as an artifact. assert t1_artifacts["wpt_actual_status"] == ["PASS"] assert test_obj["actual"] == "FAIL" assert test_obj["expected"] == "PASS" # Also ensure that the formatter cleaned up its internal state assert "t1" not in formatter.tests_with_subtest_fails
def run(self): """Main loop for the TestManager. TestManagers generally receive commands from their TestRunner updating them on the status of a test. They may also have a stop flag set by the main thread indicating that the manager should shut down the next time the event loop spins.""" self.logger = structuredlog.StructuredLogger(self.suite_name) with self.browser_cls( self.logger, **self.browser_kwargs) as browser, self.test_source_cls( self.test_queue) as test_source: self.browser = browser self.test_source = test_source try: if self.init() is Stop: return while True: commands = { "init_succeeded": self.init_succeeded, "init_failed": self.init_failed, "test_start": self.test_start, "test_ended": self.test_ended, "after_test_ended": self.after_test_ended, "restart_runner": self.restart_runner, "runner_teardown": self.runner_teardown, "log": self.log, "error": self.error } try: command, data = self.command_queue.get(True, 1) except IOError: if not self.should_stop(): self.logger.error("Got IOError from poll") self.restart_count += 1 if self.restart_runner() is Stop: break except Empty: command = None if self.should_stop(): self.logger.debug("A flag was set; stopping") break if command is not None: self.restart_count = 0 if commands[command](*data) is Stop: break else: if (self.debug_info and self.debug_info.interactive and self.browser_started and not browser.is_alive()): self.logger.debug("Debugger exited") break if not self.test_runner_proc.is_alive(): if not self.command_queue.empty(): # We got a new message so process that continue # If we got to here the runner presumably shut down # unexpectedly self.logger.info("Test runner process shut down") if self.test is not None: # This could happen if the test runner crashed for some other # reason # Need to consider the unlikely case where one test causes the # runner process to repeatedly die self.logger.critical( "Last test did not complete") break self.logger.warning( "More tests found, but runner process died, restarting" ) self.restart_count += 1 if self.restart_runner() is Stop: break finally: self.logger.debug( "TestRunnerManager main loop terminating, starting cleanup" ) self.stop_runner() self.teardown() self.logger.debug("TestRunnerManager main loop terminated")