[wptrunner] Support crash logs when using run_wpt_tests.py

This augments the Chromium log formatter to handle process_output
messages, allowing it to capture logs for a test from ChromeDriver. The
logs are accumulated for each test, then inserted into the output JSON
as an artifact if the test has a CRASH status. The post-run script in
wpt_common.py then converts the crash log lines to a file on disk.

Also, the handling of the CRASH status in the Chromium log formatter is
fixed; it was incorrectly mapping CRASH to FAIL.

Finally, --enable-chrome-logs is passed as a webdriver-arg in
run_wpt_tests.py, so that full browser logs are available.

Bug: 1057197
Change-Id: I7b533398f8b008ea493c1d183f429b1b13d4a1f8
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2327613
Commit-Queue: Stephen McGruer <smcgruer@chromium.org>
Reviewed-by: Robert Ma <robertma@chromium.org>
Cr-Commit-Position: refs/heads/master@{#796412}

testing/scripts/run_wpt_tests.py

@@ -43,6 +43,7 @@ class WPTTestAdapter(wpt_common.BaseWptScriptAdapter):
             "--binary-arg=--enable-experimental-web-platform-features",
             "--binary-arg=--enable-blink-features=MojoJS,MojoJSTest",
             "--webdriver-binary=../../out/Release/chromedriver",
+            "--webdriver-arg=--enable-chrome-logs",
             "--headless",
             "--no-capture-stdio",
             "--no-manifest-download",

testing/scripts/wpt_common.py

@@ -106,6 +106,7 @@ class BaseWptScriptAdapter(common.BaseIsolatedScriptArgsAdapter):
             log_artifact = root_node["artifacts"].pop("log", None)
             if log_artifact:
                 artifact_subpath = self._write_log_artifact(
+                    test_failures.FILENAME_SUFFIX_ACTUAL,
                     results_dir, path_so_far, log_artifact)
                 root_node["artifacts"]["actual_text"] = [artifact_subpath]
 
@@ -117,6 +118,13 @@ class BaseWptScriptAdapter(common.BaseIsolatedScriptArgsAdapter):
                 for screenshot_key, path in screenshot_paths_dict.items():
                     root_node["artifacts"][screenshot_key] = [path]
 
+            crashlog_artifact = root_node["artifacts"].pop("wpt_crash_log",
+                                                           None)
+            if crashlog_artifact:
+                artifact_subpath = self._write_log_artifact(
+                    test_failures.FILENAME_SUFFIX_CRASH_LOG,
+                    results_dir, path_so_far, crashlog_artifact)
+
             return
 
         # We're not at a leaf node, continue traversing the trie.
@@ -128,13 +136,15 @@ class BaseWptScriptAdapter(common.BaseIsolatedScriptArgsAdapter):
             self._process_test_leaves(results_dir, delim, root_node[key],
                                       new_path)
 
-    def _write_log_artifact(self, results_dir, test_name, log_artifact):
+    def _write_log_artifact(self, suffix, results_dir, test_name, log_artifact):
         """Writes a log artifact to disk.
 
-        The log artifact contains all the output of a test. It gets written to
-        the -actual.txt file for the test.
+        A log artifact contains some form of output for a test. It is written to
+        a txt file with a suffix generated from the log type.
 
         Args:
+            suffix: str suffix of the artifact to write, e.g.
+                test_failures.FILENAME_SUFFIX_ACTUAL
             results_dir: str path to the directory that results live in
             test_name: str name of the test that this artifact is for
             log_artifact: list of strings, the log entries for this test from
@@ -146,9 +156,7 @@ class BaseWptScriptAdapter(common.BaseIsolatedScriptArgsAdapter):
         """
         log_artifact_sub_path = (
             os.path.join("layout-test-results",
-                         self.port.output_filename(
-                             test_name, test_failures.FILENAME_SUFFIX_ACTUAL,
-                             ".txt"))
+                         self.port.output_filename(test_name, suffix, ".txt"))
         )
         log_artifact_full_path = os.path.join(results_dir,
                                               log_artifact_sub_path)

third_party/blink/web_tests/external/wpt/tools/wptrunner/wptrunner/formatters/chromium.py

@@ -38,6 +38,9 @@ class ChromiumFormatter(base.BaseFormatter):
         # List of tests that have failing subtests.
         self.tests_with_subtest_fails = set()
 
+        # Browser log for the current test under execution.
+        self.test_log = []
+
     def _append_test_message(self, test, subtest, status, expected, message):
         """
         Appends the message data for a test.
@@ -90,6 +93,9 @@ class ChromiumFormatter(base.BaseFormatter):
             self._append_artifact(cur_dict, "wpt_subtest_failure", "true")
         if wpt_actual != actual:
             self._append_artifact(cur_dict, "wpt_actual_status", wpt_actual)
+        if wpt_actual == 'CRASH':
+            for line in self.test_log:
+                self._append_artifact(cur_dict, "wpt_crash_log", line)
         for message in messages:
             self._append_artifact(cur_dict, "log", message)
 
@@ -129,13 +135,9 @@ class ChromiumFormatter(base.BaseFormatter):
             return "SKIP"
         if status == "EXTERNAL-TIMEOUT":
             return "TIMEOUT"
-        if status in ("ERROR", "CRASH", "PRECONDITION_FAILED"):
-            # CRASH in WPT means a browser crash, which Chromium treats as a
-            # test failure.
+        if status in ("ERROR", "PRECONDITION_FAILED"):
             return "FAIL"
         if status == "INTERNAL-ERROR":
-            # CRASH in Chromium refers to an error in the test runner not the
-            # browser.
             return "CRASH"
         # Any other status just gets returned as-is.
         return status
@@ -218,6 +220,9 @@ class ChromiumFormatter(base.BaseFormatter):
         # Update the count of how many tests ran with each status.
         self.num_failures_by_status[actual_status] += 1
 
+        # New test, new browser logs.
+        self.test_log = []
+
     def suite_end(self, data):
         # Create the final result dictionary
         final_result = {
@@ -230,3 +235,7 @@ class ChromiumFormatter(base.BaseFormatter):
             "tests": self.tests
         }
         return json.dumps(final_result)
+
+    def process_output(self, data):
+        if 'command' in data and 'chromedriver' in data['command']:
+            self.test_log.append(data['data'])

third_party/blink/web_tests/external/wpt/tools/wptrunner/wptrunner/formatters/tests/test_chromium.py

@@ -570,3 +570,56 @@ def test_reftest_screenshots(capfd):
         "foo.html: DATA1",
         "foo-ref.html: DATA2",
     ]
+
+
+def test_process_output_crashing_test(capfd):
+    """Test that chromedriver logs are preserved for crashing tests"""
+
+    # Set up the handler.
+    output = StringIO()
+    logger = structuredlog.StructuredLogger("test_a")
+    logger.add_handler(handlers.StreamHandler(output, ChromiumFormatter()))
+
+    logger.suite_start(["t1", "t2", "t3"], run_info={}, time=123)
+
+    logger.test_start("t1")
+    logger.process_output(100, "This message should be recorded", "/some/path/to/chromedriver --some-flag")
+    logger.process_output(101, "This message should not be recorded", "/some/other/process --another-flag")
+    logger.process_output(100, "This message should also be recorded", "/some/path/to/chromedriver --some-flag")
+    logger.test_end("t1", status="CRASH", expected="CRASH")
+
+    logger.test_start("t2")
+    logger.process_output(100, "Another message for the second test", "/some/path/to/chromedriver --some-flag")
+    logger.test_end("t2", status="CRASH", expected="PASS")
+
+    logger.test_start("t3")
+    logger.process_output(100, "This test fails", "/some/path/to/chromedriver --some-flag")
+    logger.process_output(100, "But the output should not be captured", "/some/path/to/chromedriver --some-flag")
+    logger.process_output(100, "Because it does not crash", "/some/path/to/chromedriver --some-flag")
+    logger.test_end("t3", status="FAIL", 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"]
+    assert test_obj["artifacts"]["wpt_crash_log"] == [
+        "This message should be recorded",
+        "This message should also be recorded"
+    ]
+
+    test_obj = output_json["tests"]["t2"]
+    assert test_obj["artifacts"]["wpt_crash_log"] == [
+        "Another message for the second test"
+    ]
+
+    test_obj = output_json["tests"]["t3"]
+    assert "wpt_crash_log" not in test_obj["artifacts"]