Add timeouts to test_runner.py

Adds a (5 minute) timeout to subprocess calls in test_runner.py, to
ensure the test runner eventually terminates even if a subprocess hangs.

Notably, this does not add a timeout to RunCommandExtractHashedFiles()
in common.py; this will be addressed in a future change.

Also changes the test log to a bytes object, instead of a str object,
allowing the command output to deviate from valid UTF-8. The
TimeoutExpired exception does not decode captured output, and ResultDB
does not require the test log to be valid UTF-8.

Bug: pdfium:1964
Change-Id: I8df8d6df9eee7f475cef8cadb6246c782cbf2bb3
Reviewed-on: https://pdfium-review.googlesource.com/c/pdfium/+/102890
Commit-Queue: K. Moon <kmoon@chromium.org>
Reviewed-by: Nigi <nigi@chromium.org>

testing/tools/test_runner.py

diff --git a/testing/tools/test_runner.py b/testing/tools/test_runner.py
index 8ccd395..8835981 100644
--- a/testing/tools/test_runner.py
+++ b/testing/tools/test_runner.py
@@ -5,6 +5,7 @@
 
 import argparse
 from dataclasses import dataclass, field
+from datetime import timedelta
 import multiprocessing
 import os
 import re
@@ -31,6 +32,11 @@
 # List of test types that should run text tests instead of pixel tests.
 TEXT_TESTS = ['javascript']
 
+# Timeout (in seconds) for individual test commands.
+# TODO(crbug.com/pdfium/1967): array_buffer.in is slow under MSan, so need a
+# very generous 5 minute timeout for now.
+TEST_TIMEOUT = timedelta(minutes=5).total_seconds()
+
 
 class TestRunner:
 
@@ -86,7 +92,8 @@
       if test_result.reason:
         print(f'Failure reason: {test_result.reason}')
       if test_result.log:
-        print(f'Test output:\n{test_result.log}')
+        decoded_log = bytes.decode(test_result.log, errors='backslashreplace')
+        print(f'Test output:\n{decoded_log}')
       for artifact in test_result.image_artifacts:
         if artifact.skia_gold_status == result_types.FAIL:
           print(f'Failed Skia Gold: {artifact.image_path}')
@@ -446,7 +453,8 @@
     return finder.ExecutablePath('pdfium_test')
 
   def InitializeFeatures(self, pdfium_test_path):
-    output = subprocess.check_output([pdfium_test_path, '--show-config'])
+    output = subprocess.check_output([pdfium_test_path, '--show-config'],
+                                     timeout=TEST_TIMEOUT)
     self.features = output.decode('utf-8').strip().split(',')
 
 
@@ -553,20 +561,29 @@
       stdout = subprocess.PIPE
       stderr = subprocess.STDOUT
 
-    completed_process = subprocess.run(
-        command, stdout=stdout, stderr=stderr, check=False, encoding='utf-8')
-    if completed_process.returncode != 0:
-      if stdout == subprocess.PIPE:
-        test_log = completed_process.stdout
-      else:
-        test_log = completed_process.stderr
-      return self.test_case.NewResult(
-          result_types.FAIL,
-          log=test_log,
-          reason='Command {} exited with code {}'.format(
-              completed_process.args, completed_process.returncode))
+    test_result = self.test_case.NewResult(result_types.PASS)
+    try:
+      run_result = subprocess.run(
+          command,
+          stdout=stdout,
+          stderr=stderr,
+          timeout=TEST_TIMEOUT,
+          check=False)
+      if run_result.returncode != 0:
+        test_result.status = result_types.FAIL
+        test_result.reason = 'Command {} exited with code {}'.format(
+            run_result.args, run_result.returncode)
+    except subprocess.TimeoutExpired as timeout_expired:
+      run_result = timeout_expired
+      test_result.status = result_types.TIMEOUT
+      test_result.reason = 'Command {} timed out'.format(run_result.cmd)
 
-    return self.test_case.NewResult(result_types.PASS)
+    if not test_result.IsPass():
+      if stdout == subprocess.PIPE:
+        test_result.log = run_result.stdout
+      else:
+        test_result.log = run_result.stderr
+    return test_result
 
   def GenerateAndTest(self, test_function):
     """Generate test input and run pdfium_test."""
@@ -643,7 +660,7 @@
     ])
 
   def _VerifyEmptyText(self, txt_path):
-    with open(txt_path, "r") as txt_file:
+    with open(txt_path, "rb") as txt_file:
       txt_data = txt_file.read()
 
     if txt_data:
@@ -715,7 +732,7 @@
 
         for artifact in test_result.image_artifacts:
           artifact.image_diff = diff_map.get(artifact.image_path)
-        test_result.log = ''.join(diff_log)
+        test_result.log = ''.join(diff_log).encode()
 
     elif _per_process_state.enforce_expected_images:
       if not self.IsImageDiffSuppressed():