Diff
Modified: trunk/Tools/ChangeLog (231678 => 231679)
--- trunk/Tools/ChangeLog 2018-05-11 00:23:19 UTC (rev 231678)
+++ trunk/Tools/ChangeLog 2018-05-11 00:42:03 UTC (rev 231679)
@@ -1,3 +1,40 @@
+2018-05-10 Jonathan Bedard <[email protected]>
+
+ 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 Ryosuke Niwa <[email protected]>
build-webkit can erroneously warn about Xcode being too old
Modified: trunk/Tools/Scripts/webkitpy/api_tests/run_api_tests.py (231678 => 231679)
--- trunk/Tools/Scripts/webkitpy/api_tests/run_api_tests.py 2018-05-11 00:23:19 UTC (rev 231678)
+++ trunk/Tools/Scripts/webkitpy/api_tests/run_api_tests.py 2018-05-11 00:42:03 UTC (rev 231679)
@@ -70,7 +70,7 @@
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 @@
help='Run quietly (errors, warnings, and progress only)'),
optparse.make_option('-v', '--verbose', action='', default=False,
help='Enable verbose printing'),
+ optparse.make_option('--timestamps', action='', default=False,
+ help='Print timestamps for each logged line'),
]))
option_group_definitions.append(('WebKit Options', [
Modified: trunk/Tools/Scripts/webkitpy/api_tests/runner.py (231678 => 231679)
--- trunk/Tools/Scripts/webkitpy/api_tests/runner.py 2018-05-11 00:23:19 UTC (rev 231678)
+++ trunk/Tools/Scripts/webkitpy/api_tests/runner.py 2018-05-11 00:42:03 UTC (rev 231679)
@@ -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 @@
STATUS_CRASHED = 2
STATUS_TIMEOUT = 3
STATUS_DISABLED = 4
+ STATUS_RUNNING = 5
NAME_FOR_STATUS = [
'Passed',
@@ -47,6 +49,8 @@
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,25 +82,49 @@
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 = {}
for test_name, result in self.results.iteritems():
@@ -130,31 +158,51 @@
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 @@
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 @@
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 @@
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]:
Modified: trunk/Tools/Scripts/webkitpy/layout_tests/views/metered_stream.py (231678 => 231679)
--- trunk/Tools/Scripts/webkitpy/layout_tests/views/metered_stream.py 2018-05-11 00:23:19 UTC (rev 231678)
+++ trunk/Tools/Scripts/webkitpy/layout_tests/views/metered_stream.py 2018-05-11 00:42:03 UTC (rev 231679)
@@ -51,9 +51,10 @@
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 @@
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)
Modified: trunk/Tools/Scripts/webkitpy/layout_tests/views/metered_stream_unittest.py (231678 => 231679)
--- trunk/Tools/Scripts/webkitpy/layout_tests/views/metered_stream_unittest.py 2018-05-11 00:23:19 UTC (rev 231678)
+++ trunk/Tools/Scripts/webkitpy/layout_tests/views/metered_stream_unittest.py 2018-05-11 00:42:03 UTC (rev 231679)
@@ -37,6 +37,7 @@
class RegularTest(unittest.TestCase):
verbose = False
isatty = False
+ print_timestamps = None
def setUp(self):
self.stream = StringIO.StringIO()
@@ -51,7 +52,7 @@
# 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 @@
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 @@
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)
