[webkitpy] Improve some error handling and logging

This CL contains some code health improvements as a by product of fixing
issue 822041. Though the root cause of that issue was eventually fixed
from upstream (https://github.com/w3c/web-platform-tests/pull/10323),
these improvements are still good to have.

* WPTManifest raises an exception when `wpt manifest` fails instead of
  directy exiting the process. Subprocess invocation is simplified.
* lint-test-expectations now has a --verbose flag to print debug logs,
  including error messages from subprocesses (i.e. `wpt manifest`).
* Use the canonical configure_logging in lint-test-expectations and
  LoggingTestCase in its unit test. Also make the unit test stricter as
  PRESUBMIT.py relies on the output.

Bug: 822041
Change-Id: I4724904c61b3c5b6ed3239584ed03089f2b203ce
Reviewed-on: https://chromium-review.googlesource.com/998341Reviewed-by: Quinten Yearsley <qyearsley@chromium.org>
Commit-Queue: Robert Ma <robertma@chromium.org>
Cr-Commit-Position: refs/heads/master@{#548632}

third_party/WebKit/Tools/Scripts/webkitpy/common/system/executive_mock.py

@@ -179,7 +179,7 @@ class MockExecutive(object):
                 env_string = ', env=%s' % env
             _log.info('MOCK popen: %s%s%s', args, cwd_string, env_string)
         if not self._proc:
-            self._proc = MockProcess(self._output)
+            self._proc = MockProcess(stdout=self._output, stderr=self._stderr, returncode=self._exit_code)
         return self._proc
 
     def call(self, args, **_):

third_party/WebKit/Tools/Scripts/webkitpy/layout_tests/lint_test_expectations.py

@@ -31,8 +31,9 @@ import logging
 import optparse
 import traceback
 
-from webkitpy.common.host import Host
 from webkitpy.common import exit_codes
+from webkitpy.common.host import Host
+from webkitpy.common.system.log_utils import configure_logging
 from webkitpy.layout_tests.models import test_expectations
 from webkitpy.layout_tests.port.factory import platform_options
 from webkitpy.w3c.wpt_manifest import WPTManifest
@@ -126,43 +127,29 @@ def check_smoke_tests(host, options):
     return failures
 
 
-def set_up_logging(logging_stream):
-    logger = logging.getLogger()
-    logger.setLevel(logging.INFO)
-    handler = logging.StreamHandler(logging_stream)
-    logger.addHandler(handler)
-    return (logger, handler)
-
-
-def tear_down_logging(logger, handler):
-    logger.removeHandler(handler)
+def run_checks(host, options):
+    failures = []
+    failures.extend(lint(host, options))
+    failures.extend(check_virtual_test_suites(host, options))
+    failures.extend(check_smoke_tests(host, options))
 
+    if options.json:
+        with open(options.json, 'w') as f:
+            json.dump(failures, f)
 
-def run_checks(host, options, logging_stream):
-    logger, handler = set_up_logging(logging_stream)
-    try:
-        failures = []
-        failures.extend(lint(host, options))
-        failures.extend(check_virtual_test_suites(host, options))
-        failures.extend(check_smoke_tests(host, options))
-
-        if options.json:
-            with open(options.json, 'w') as f:
-                json.dump(failures, f)
-
-        if failures:
-            _log.error('Lint failed.')
-            return 1
-        else:
-            _log.info('Lint succeeded.')
-            return 0
-    finally:
-        logger.removeHandler(handler)
+    if failures:
+        _log.error('Lint failed.')
+        return 1
+    else:
+        _log.info('Lint succeeded.')
+        return 0
 
 
 def main(argv, stderr, host=None):
     parser = optparse.OptionParser(option_list=platform_options(use_globs=True))
     parser.add_option('--json', help='Path to JSON output file')
+    parser.add_option('--verbose', action='store_true', default=False,
+                      help='log extra details that may be helpful when debugging')
     options, _ = parser.parse_args(argv)
 
     if not host:
@@ -175,13 +162,20 @@ def main(argv, stderr, host=None):
         else:
             host = Host()
 
-    # Need to generate MANIFEST.json since some expectations correspond to WPT
-    # tests that aren't files and only exist in the manifest.
-    _log.info('Generating MANIFEST.json for web-platform-tests ...')
-    WPTManifest.ensure_manifest(host)
+    if options.verbose:
+        configure_logging(logging_level=logging.DEBUG, stream=stderr)
+        # Print full stdout/stderr when a command fails.
+        host.executive.error_output_limit = None
+    else:
+        # PRESUBMIT.py relies on our output, so don't include timestamps.
+        configure_logging(logging_level=logging.INFO, stream=stderr, include_time=False)
 
     try:
-        exit_status = run_checks(host, options, stderr)
+        # Need to generate MANIFEST.json since some expectations correspond to WPT
+        # tests that aren't files and only exist in the manifest.
+        _log.debug('Generating MANIFEST.json for web-platform-tests ...')
+        WPTManifest.ensure_manifest(host)
+        exit_status = run_checks(host, options)
     except KeyboardInterrupt:
         exit_status = exit_codes.INTERRUPTED_EXIT_STATUS
     except Exception as error:  # pylint: disable=broad-except

third_party/WebKit/Tools/Scripts/webkitpy/layout_tests/lint_test_expectations_unittest.py

@@ -32,6 +32,7 @@ import unittest
 
 from webkitpy.common import exit_codes
 from webkitpy.common.host_mock import MockHost
+from webkitpy.common.system.log_testing import LoggingTestCase
 from webkitpy.layout_tests import lint_test_expectations
 
 
@@ -89,7 +90,7 @@ class FakeFactory(object):
         return sorted(self.ports.keys())
 
 
-class LintTest(unittest.TestCase):
+class LintTest(LoggingTestCase):
 
     def test_all_configurations(self):
         host = MockHost()
@@ -98,29 +99,19 @@ class LintTest(unittest.TestCase):
                                                FakePort(host, 'b', 'path-to-b'),
                                                FakePort(host, 'b-win', 'path-to-b')))
 
-        logging_stream = StringIO.StringIO()
         options = optparse.Values({'platform': None})
-        logger, handler = lint_test_expectations.set_up_logging(logging_stream)
-        try:
-            res = lint_test_expectations.lint(host, options)
-        finally:
-            lint_test_expectations.tear_down_logging(logger, handler)
+        res = lint_test_expectations.lint(host, options)
         self.assertEqual(res, [])
         self.assertEqual(host.ports_parsed, ['a', 'b', 'b-win'])
 
     def test_lint_test_files(self):
-        logging_stream = StringIO.StringIO()
         options = optparse.Values({'platform': 'test-mac-mac10.10'})
         host = MockHost()
 
         host.port_factory.all_port_names = lambda platform=None: [platform]
 
-        logger, handler = lint_test_expectations.set_up_logging(logging_stream)
-        try:
-            res = lint_test_expectations.lint(host, options)
-            self.assertEqual(res, [])
-        finally:
-            lint_test_expectations.tear_down_logging(logger, handler)
+        res = lint_test_expectations.lint(host, options)
+        self.assertEqual(res, [])
 
     def test_lint_test_files_errors(self):
         options = optparse.Values({'platform': 'test', 'debug_rwt_logging': False})
@@ -132,16 +123,12 @@ class LintTest(unittest.TestCase):
         host.port_factory.get = lambda platform, options=None: port
         host.port_factory.all_port_names = lambda platform=None: [port.name()]
 
-        logging_stream = StringIO.StringIO()
-        logger, handler = lint_test_expectations.set_up_logging(logging_stream)
-        try:
-            res = lint_test_expectations.lint(host, options)
-        finally:
-            lint_test_expectations.tear_down_logging(logger, handler)
+        res = lint_test_expectations.lint(host, options)
 
         self.assertTrue(res)
-        self.assertIn('foo:1', logging_stream.getvalue())
-        self.assertIn('bar:1', logging_stream.getvalue())
+        all_logs = ''.join(self.logMessages())
+        self.assertIn('foo:1', all_logs)
+        self.assertIn('bar:1', all_logs)
 
     def test_extra_files_errors(self):
         options = optparse.Values({'platform': 'test', 'debug_rwt_logging': False})
@@ -154,15 +141,11 @@ class LintTest(unittest.TestCase):
         host.port_factory.all_port_names = lambda platform=None: [port.name()]
         host.filesystem.write_text_file('/test.checkout/LayoutTests/LeakExpectations', '-- syntax error')
 
-        logging_stream = StringIO.StringIO()
-        logger, handler = lint_test_expectations.set_up_logging(logging_stream)
-        try:
-            res = lint_test_expectations.lint(host, options)
-        finally:
-            lint_test_expectations.tear_down_logging(logger, handler)
+        res = lint_test_expectations.lint(host, options)
 
         self.assertTrue(res)
-        self.assertIn('LeakExpectations:1', logging_stream.getvalue())
+        all_logs = ''.join(self.logMessages())
+        self.assertIn('LeakExpectations:1', all_logs)
 
     def test_lint_flag_specific_expectation_errors(self):
         options = optparse.Values({'platform': 'test', 'debug_rwt_logging': False})
@@ -174,16 +157,12 @@ class LintTest(unittest.TestCase):
         host.port_factory.get = lambda platform, options=None: port
         host.port_factory.all_port_names = lambda platform=None: [port.name()]
 
-        logging_stream = StringIO.StringIO()
-        logger, handler = lint_test_expectations.set_up_logging(logging_stream)
-        try:
-            res = lint_test_expectations.lint(host, options)
-        finally:
-            lint_test_expectations.tear_down_logging(logger, handler)
+        res = lint_test_expectations.lint(host, options)
 
         self.assertTrue(res)
-        self.assertIn('flag-specific:1 Path does not exist. does/not/exist', logging_stream.getvalue())
-        self.assertNotIn('noproblem', logging_stream.getvalue())
+        all_logs = ''.join(self.logMessages())
+        self.assertIn('flag-specific:1 Path does not exist. does/not/exist', all_logs)
+        self.assertNotIn('noproblem', all_logs)
 
 
 class CheckVirtualSuiteTest(unittest.TestCase):
@@ -194,18 +173,13 @@ class CheckVirtualSuiteTest(unittest.TestCase):
         orig_get = host.port_factory.get
         host.port_factory.get = lambda options: orig_get('test', options=options)
 
-        logging_stream = StringIO.StringIO()
-        logger, handler = lint_test_expectations.set_up_logging(logging_stream)
-        try:
-            res = lint_test_expectations.check_virtual_test_suites(host, options)
-            self.assertTrue(res)
+        res = lint_test_expectations.check_virtual_test_suites(host, options)
+        self.assertTrue(res)
 
-            options = optparse.Values({'platform': 'test', 'debug_rwt_logging': False})
-            host.filesystem.exists = lambda path: True
-            res = lint_test_expectations.check_virtual_test_suites(host, options)
-            self.assertFalse(res)
-        finally:
-            lint_test_expectations.tear_down_logging(logger, handler)
+        options = optparse.Values({'platform': 'test', 'debug_rwt_logging': False})
+        host.filesystem.exists = lambda path: True
+        res = lint_test_expectations.check_virtual_test_suites(host, options)
+        self.assertFalse(res)
 
 
 class MainTest(unittest.TestCase):
@@ -223,13 +197,13 @@ class MainTest(unittest.TestCase):
     def test_success(self):
         lint_test_expectations.lint = lambda host, options: []
         res = lint_test_expectations.main(['--platform', 'test'], self.stderr)
-        self.assertTrue('Lint succeeded' in self.stderr.getvalue())
+        self.assertEqual('Lint succeeded.', self.stderr.getvalue().strip())
         self.assertEqual(res, 0)
 
     def test_failure(self):
         lint_test_expectations.lint = lambda host, options: ['test failure']
         res = lint_test_expectations.main(['--platform', 'test'], self.stderr)
-        self.assertTrue('Lint failed' in self.stderr.getvalue())
+        self.assertEqual('Lint failed.', self.stderr.getvalue().strip())
         self.assertEqual(res, 1)
 
     def test_interrupt(self):

third_party/WebKit/Tools/Scripts/webkitpy/w3c/wpt_manifest.py

@@ -117,25 +117,17 @@ class WPTManifest(object):
         wpt_path = manifest_path = finder.path_from_layout_tests('external', 'wpt')
         WPTManifest.generate_manifest(host, wpt_path)
 
-        # Adding this log line to diagnose https://crbug.com/714503
         _log.debug('Manifest generation completed.')
 
     @staticmethod
     def generate_manifest(host, dest_path):
         """Generates MANIFEST.json on the specified directory."""
-        executive = host.executive
         finder = PathFinder(host.filesystem)
         wpt_exec_path = finder.path_from_tools_scripts('webkitpy', 'thirdparty', 'wpt', 'wpt', 'wpt')
-
         cmd = ['python', wpt_exec_path, 'manifest', '--work', '--tests-root', dest_path]
-        _log.debug('Running command: %s', ' '.join(cmd))
-        proc = executive.popen(cmd, stdout=executive.PIPE, stderr=executive.PIPE, stdin=executive.PIPE)
-        out, err = proc.communicate('')
-        if proc.returncode:
-            _log.info('# ret> %d', proc.returncode)
-            if out:
-                _log.info(out)
-            if err:
-                _log.info(err)
-            host.exit(proc.returncode)
-        return proc.returncode, out
+
+        # ScriptError will be raised if the command fails.
+        host.executive.run_command(
+            cmd,
+            return_stderr=True  # This will also include stderr in the exception message.
+        )

third_party/WebKit/Tools/Scripts/webkitpy/w3c/wpt_manifest_unittest.py

@@ -5,6 +5,8 @@
 import unittest
 
 from webkitpy.common.host_mock import MockHost
+from webkitpy.common.system.executive import ScriptError
+from webkitpy.common.system.executive_mock import MockExecutive
 from webkitpy.w3c.wpt_manifest import WPTManifest
 
 
@@ -37,7 +39,7 @@ class WPTManifestUnitTest(unittest.TestCase):
         host = MockHost()
         manifest_path = '/mock-checkout/third_party/WebKit/LayoutTests/external/wpt/MANIFEST.json'
 
-        host.filesystem.write_binary_file(manifest_path, '{}')
+        host.filesystem.write_text_file(manifest_path, '{}')
         self.assertTrue(host.filesystem.exists(manifest_path))
 
         WPTManifest.ensure_manifest(host)
@@ -57,3 +59,10 @@ class WPTManifestUnitTest(unittest.TestCase):
                 ]
             ]
         )
+
+    def test_ensure_manifest_raises_exception(self):
+        host = MockHost()
+        host.executive = MockExecutive(should_throw=True)
+
+        with self.assertRaises(ScriptError):
+            WPTManifest.ensure_manifest(host)