Attachment 340142 Details for Bug 185090 – Patch for landing

[patch] Patch for landing

bug-185090-20180510180834.patch (text/plain), 16.09 KB, created by Jonathan Bedard on 2018-05-10 16:08:35 PDT

(hide)

Description:

Filename:

MIME Type:

Creator: Jonathan Bedard

Created: 2018-05-10 16:08:35 PDT

Size: 16.09 KB

patch

obsolete

>Index: Tools/ChangeLog
>===================================================================
>--- Tools/ChangeLog	(revision 231660)
>+++ Tools/ChangeLog	(working copy)
>@@ -1,3 +1,40 @@
>+2018-05-10  Jonathan Bedard  <jbedard@apple.com>
>+
>+        REGRESSION (r230998): Cannot stream API test output
>+        https://bugs.webkit.org/show_bug.cgi?id=185090
>+
>+        Reviewed by Ryosuke Niwa.
>+
>+        Change run-api-tests so that the stdout and stderr of a test will be printed
>+        before it's result. If -v is passed, the output of single test runs will be
>+        streamed. 
>+
>+        * Scripts/webkitpy/api_tests/run_api_tests.py:
>+        (run): Use print_timestamps flag.
>+        (parse_args): Add timestamps option to print timestamps in the log.
>+        * Scripts/webkitpy/api_tests/runner.py:
>+        (Runner): Add running status.
>+        (Runner.__init__): Add number of workers and a flag to detect if a newline
>+        is needed at the beginning of a log line.
>+        (Runner.run): Turn off most logging coming from server process since it is
>+        not constructive for API tests.
>+        (Runner.handle): Add new log message to stream stdout and stderr instead of
>+        caching values until the test run finished.
>+        (_Worker._run_single_test): Log stdout and stderr in real time.
>+        (_Worker._run_shard_with_binary): Log stderr and stdout buffer before ending
>+        the test.
>+        (_Worker.post): Provide a post with explicitly enumerated argument names.
>+        * Scripts/webkitpy/layout_tests/views/metered_stream.py:
>+        (MeteredStream.__init__): Differentiate verbose logging and logging with timestamps.
>+        (MeteredStream.write): Allow for verbose logging without timestamps.
>+        * Scripts/webkitpy/layout_tests/views/metered_stream_unittest.py:
>+        (RegularTest): Add print_timestamps flag.
>+        (RegularTest.setUp):
>+        (RegularTest.test_logging_not_included):
>+        (VerboseTest.test_log_args):
>+        (VerboseWithOutTimestamp):
>+        (VerboseWithOutTimestamp.test_basic): Add test for verbose logging without timestamps.
>+
> 2018-05-10  Fujii Hironori  <Hironori.Fujii@sony.com>
> 
>         [Win][MiniBrowser] Add a separate WndProc for the layered window
>Index: Tools/Scripts/webkitpy/api_tests/run_api_tests.py
>===================================================================
>--- Tools/Scripts/webkitpy/api_tests/run_api_tests.py	(revision 231660)
>+++ Tools/Scripts/webkitpy/api_tests/run_api_tests.py	(working copy)
>@@ -70,7 +70,7 @@ def run(port, options, args, logging_str
>     logger.setLevel(logging.DEBUG if options.verbose else logging.ERROR if options.quiet else logging.INFO)
> 
>     try:
>-        stream = MeteredStream(logging_stream, options.verbose, logger=logger, number_of_columns=port.host.platform.terminal_width())
>+        stream = MeteredStream(logging_stream, options.verbose, logger=logger, number_of_columns=port.host.platform.terminal_width(), print_timestamps=options.timestamps)
>         manager = Manager(port, options, stream)
> 
>         result = manager.run(args)
>@@ -90,6 +90,8 @@ def parse_args(args):
>                              help='Run quietly (errors, warnings, and progress only)'),
>         optparse.make_option('-v', '--verbose', action='store_true', default=False,
>                              help='Enable verbose printing'),
>+        optparse.make_option('--timestamps', action='store_true', default=False,
>+                             help='Print timestamps for each logged line'),
>     ]))
> 
>     option_group_definitions.append(('WebKit Options', [
>Index: Tools/Scripts/webkitpy/api_tests/runner.py
>===================================================================
>--- Tools/Scripts/webkitpy/api_tests/runner.py	(revision 231660)
>+++ Tools/Scripts/webkitpy/api_tests/runner.py	(working copy)
>@@ -21,10 +21,11 @@
> # SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
> 
> import os
>+import logging
> import time
> 
> from webkitpy.common import message_pool
>-from webkitpy.port.server_process import ServerProcess
>+from webkitpy.port.server_process import ServerProcess, _log as server_process_logger
> from webkitpy.xcode.simulated_device import SimulatedDeviceManager
> 
> 
>@@ -34,6 +35,7 @@ class Runner(object):
>     STATUS_CRASHED = 2
>     STATUS_TIMEOUT = 3
>     STATUS_DISABLED = 4
>+    STATUS_RUNNING = 5
> 
>     NAME_FOR_STATUS = [
>         'Passed',
>@@ -47,6 +49,8 @@ class Runner(object):
>         self.port = port
>         self.printer = printer
>         self.tests_run = 0
>+        self._num_workers = 1
>+        self._has_logged_for_test = True  # Suppress an empty line between "Running tests" and the first test's output.
>         self.results = {}
> 
>     @staticmethod
>@@ -78,24 +82,48 @@ class Runner(object):
>         self.printer.write_update('Sharding tests ...')
>         shards = Runner._shard_tests(tests)
> 
>-        with message_pool.get(self, lambda caller: _Worker(caller, self.port, shards), min(num_workers, len(shards))) as pool:
>-            pool.run(('test', shard) for shard, _ in shards.iteritems())
>+        original_level = server_process_logger.level
>+        server_process_logger.setLevel(logging.CRITICAL)
>+
>+        try:
>+            self._num_workers = min(num_workers, len(shards))
>+            with message_pool.get(self, lambda caller: _Worker(caller, self.port, shards), self._num_workers) as pool:
>+                pool.run(('test', shard) for shard, _ in shards.iteritems())
>+        finally:
>+            server_process_logger.setLevel(original_level)
>+
> 
>     def handle(self, message_name, source, test_name=None, status=0, output=''):
>         if message_name == 'did_spawn_worker':
>             return
>+
>+        source = '' if self._num_workers == 1 else source + ' '
>+        will_stream_logs = self._num_workers == 1 and self.port.get_option('verbose')
>         if message_name == 'ended_test':
>-            update = '{} {} {}'.format(source, test_name, Runner.NAME_FOR_STATUS[status])
>+            update = '{}{} {}'.format(source, test_name, Runner.NAME_FOR_STATUS[status])
> 
>             # Don't print test output if --quiet.
>             if status != Runner.STATUS_PASSED or (output and not self.port.get_option('quiet')):
>+                if not will_stream_logs:
>+                    for line in output.splitlines():
>+                        if not self._has_logged_for_test:
>+                            self._has_logged_for_test = True
>+                            self.printer.writeln(source)
>+                        self.printer.writeln('{}    {}'.format(source, line))
>                 self.printer.writeln(update)
>-                for line in output.splitlines():
>-                    self.printer.writeln('    {}'.format(line))
>             else:
>                 self.printer.write_update(update)
>             self.tests_run += 1
>             self.results[test_name] = (status, output)
>+            self._has_logged_for_test = False
>+
>+        if message_name == 'log' and will_stream_logs:
>+            for line in output.splitlines():
>+                if not self._has_logged_for_test:
>+                    self._has_logged_for_test = True
>+                    self.printer.writeln(source)
>+                self.printer.writeln('{}    {}'.format(source, line))
>+
> 
>     def result_map_by_status(self, status=None):
>         map = {}
>@@ -130,31 +158,51 @@ class _Worker(object):
>             Runner.command_for_port(self._port, [self._port._build_path(binary_name), '--gtest_filter={}'.format(test)]),
>             env=self._port.environment_for_api_tests())
> 
>+        status = Runner.STATUS_RUNNING
>+        if test.split('.')[1].startswith('DISABLED_'):
>+            status = Runner.STATUS_DISABLED
>+
>         try:
>             deadline = time.time() + self._timeout
>-            server_process.start()
>+            if status != Runner.STATUS_DISABLED:
>+                server_process.start()
> 
>-            if not test.split('.')[1].startswith('DISABLED_'):
>-                stdout_line = server_process.read_stdout_line(deadline)
>-            else:
>-                stdout_line = None
>+            stdout_buffer = ''
>+            stderr_buffer = ''
>+            while status == Runner.STATUS_RUNNING:
>+                stdout_line, stderr_line = server_process.read_either_stdout_or_stderr_line(deadline)
>+                if not stderr_line and not stdout_line:
>+                    break
> 
>-            if not stdout_line and server_process.timed_out:
>+                if stderr_line:
>+                    stderr_buffer += stderr_line
>+                    self.post('log', output=stderr_line[:-1])
>+                if stdout_line:
>+                    if '**PASS**' in stdout_line:
>+                        status = Runner.STATUS_PASSED
>+                    elif '**FAIL**' in stdout_line:
>+                        status = Runner.STATUS_FAILED
>+                    else:
>+                        stdout_buffer += stdout_line
>+                        self.post('log', output=stdout_line[:-1])
>+
>+            if status == Runner.STATUS_DISABLED:
>+                pass
>+            elif server_process.timed_out:
>                 status = Runner.STATUS_TIMEOUT
>-            elif not stdout_line and server_process.has_crashed():
>+            elif server_process.has_crashed():
>                 status = Runner.STATUS_CRASHED
>-            elif not stdout_line:
>-                status = Runner.STATUS_DISABLED
>-            elif '**PASS**' in stdout_line:
>-                status = Runner.STATUS_PASSED
>-            else:
>+            elif status == Runner.STATUS_RUNNING:
>                 status = Runner.STATUS_FAILED
> 
>         finally:
>-            output_buffer = server_process.pop_all_buffered_stdout() + server_process.pop_all_buffered_stderr()
>+            remaining_stderr = server_process.pop_all_buffered_stderr()
>+            remaining_stdout = server_process.pop_all_buffered_stdout()
>+            self.post('log', output=remaining_stderr + remaining_stdout)
>+            output_buffer = stderr_buffer + stdout_buffer + remaining_stderr + remaining_stdout
>             server_process.stop()
> 
>-        self._caller.post('ended_test', '{}.{}'.format(binary_name, test), status, self._filter_noisy_output(output_buffer))
>+        self.post('ended_test', '{}.{}'.format(binary_name, test), status, self._filter_noisy_output(output_buffer))
> 
>     def _run_shard_with_binary(self, binary_name, tests):
>         remaining_tests = list(tests)
>@@ -196,7 +244,7 @@ class _Worker(object):
>                         continue
>                     if last_test is not None:
>                         remaining_tests.remove(last_test)
>-                        self._caller.post('ended_test', '{}.{}'.format(binary_name, last_test), last_status, stdout_buffer)
>+                        self.post('ended_test', '{}.{}'.format(binary_name, last_test), last_status, stdout_buffer)
>                         deadline = time.time() + self._timeout
>                         stdout_buffer = ''
> 
>@@ -211,7 +259,8 @@ class _Worker(object):
>                     remaining_tests.remove(last_test)
>                     stdout_buffer += server_process.pop_all_buffered_stdout()
>                     stderr_buffer = server_process.pop_all_buffered_stderr() if last_status == Runner.STATUS_CRASHED else ''
>-                    self._caller.post('ended_test', '{}.{}'.format(binary_name, last_test), last_status, self._filter_noisy_output(stdout_buffer + stderr_buffer))
>+                    self.post('log', output=stdout_buffer + stderr_buffer)
>+                    self.post('ended_test', '{}.{}'.format(binary_name, last_test), last_status, self._filter_noisy_output(stdout_buffer + stderr_buffer))
> 
>                 if server_process.timed_out:
>                     break
>@@ -226,9 +275,12 @@ class _Worker(object):
>         for test in remaining_tests:
>             self._run_single_test(binary_name, test)
> 
>+    def post(self, message_name, test_name=None, status=0, output=''):
>+        self._caller.post(message_name, test_name, status, output)
>+
>     def handle(self, message_name, source, shard_name):
>         assert message_name == 'test'
>-        self._caller.post('started_shard', shard_name)
>+        self.post('started_shard', shard_name)
> 
>         binary_map = {}
>         for test in self._shard_map[shard_name]:
>Index: Tools/Scripts/webkitpy/layout_tests/views/metered_stream.py
>===================================================================
>--- Tools/Scripts/webkitpy/layout_tests/views/metered_stream.py	(revision 231660)
>+++ Tools/Scripts/webkitpy/layout_tests/views/metered_stream.py	(working copy)
>@@ -51,9 +51,10 @@ class MeteredStream(object):
>     def _ensure_newline(txt):
>         return txt if txt.endswith('\n') else txt + '\n'
> 
>-    def __init__(self, stream=None, verbose=False, logger=None, time_fn=None, pid=None, number_of_columns=None):
>+    def __init__(self, stream=None, verbose=False, logger=None, time_fn=None, pid=None, number_of_columns=None, print_timestamps=None):
>         self._stream = stream or sys.stderr
>         self._verbose = verbose
>+        self._print_timestamps = verbose if print_timestamps is None else print_timestamps
>         self._time_fn = time_fn or time.time
>         self._pid = pid or os.getpid()
>         self._isatty = self._stream.isatty()
>@@ -97,13 +98,16 @@ class MeteredStream(object):
>         self._last_write_time = now
>         if self._last_partial_line:
>             self._erase_last_partial_line()
>-        if self._verbose:
>+
>+        timestamp_string = ''
>+        if self._print_timestamps:
>             now_tuple = time.localtime(now)
>-            msg = '%02d:%02d:%02d.%03d %d %s' % (now_tuple.tm_hour, now_tuple.tm_min, now_tuple.tm_sec, int((now * 1000) % 1000), pid, self._ensure_newline(txt))
>-        elif self._isatty:
>-            msg = txt
>+            timestamp_string = '%02d:%02d:%02d.%03d %d ' % (now_tuple.tm_hour, now_tuple.tm_min, now_tuple.tm_sec, int((now * 1000) % 1000), pid)
>+
>+        if self._isatty and not self._verbose:
>+            msg = '{}{}'.format(timestamp_string, txt)
>         else:
>-            msg = self._ensure_newline(txt)
>+            msg = '{}{}'.format(timestamp_string, self._ensure_newline(txt))
> 
>         self._stream.write(msg)
> 
>Index: Tools/Scripts/webkitpy/layout_tests/views/metered_stream_unittest.py
>===================================================================
>--- Tools/Scripts/webkitpy/layout_tests/views/metered_stream_unittest.py	(revision 231660)
>+++ Tools/Scripts/webkitpy/layout_tests/views/metered_stream_unittest.py	(working copy)
>@@ -37,6 +37,7 @@ from webkitpy.layout_tests.views.metered
> class RegularTest(unittest.TestCase):
>     verbose = False
>     isatty = False
>+    print_timestamps = None
> 
>     def setUp(self):
>         self.stream = StringIO.StringIO()
>@@ -51,7 +52,7 @@ class RegularTest(unittest.TestCase):
>         # add a dummy time counter for a default behavior.
>         self.times = range(10)
> 
>-        self.meter = MeteredStream(self.stream, self.verbose, self.logger, self.time_fn, 8675)
>+        self.meter = MeteredStream(self.stream, self.verbose, self.logger, self.time_fn, 8675, print_timestamps=self.print_timestamps)
> 
>     def tearDown(self):
>         if self.meter:
>@@ -71,7 +72,7 @@ class RegularTest(unittest.TestCase):
>         root_logger.addHandler(handler)
>         root_logger.setLevel(logging.DEBUG)
>         try:
>-            self.meter = MeteredStream(self.stream, self.verbose, None, self.time_fn, 8675)
>+            self.meter = MeteredStream(self.stream, self.verbose, None, self.time_fn, 8675, print_timestamps=self.print_timestamps)
>             self.meter.write_throttled_update('foo')
>             self.meter.write_update('bar')
>             self.meter.write('baz')
>@@ -152,3 +153,17 @@ class VerboseTest(RegularTest):
>         self.logger.info('foo %s %d', 'bar', 2)
>         self.assertEqual(len(self.buflist), 1)
>         self.assertTrue(self.buflist[0].endswith('foo bar 2\n'))
>+
>+
>+class VerboseWithOutTimestamp(RegularTest):
>+    isatty = True
>+    verbose = True
>+    print_timestamps = False
>+
>+    def test_basic(self):
>+        buflist = self._basic([0, 1, 2.1, 13, 14.1234])
>+        self.assertTrue(re.match('foo\n', buflist[0]))
>+        self.assertTrue(re.match('bar\n', buflist[1]))
>+        self.assertTrue(re.match('baz 2\n', buflist[2]))
>+        self.assertTrue(re.match('done\n', buflist[3]))
>+        self.assertEqual(len(buflist), 4)

Actions: View | Formatted Diff | Diff

Attachments on bug 185090: 339025 | 339123 | 340142