Diff
Modified: trunk/Tools/ChangeLog (120618 => 120619)
--- trunk/Tools/ChangeLog 2012-06-18 19:53:38 UTC (rev 120618)
+++ trunk/Tools/ChangeLog 2012-06-18 19:59:53 UTC (rev 120619)
@@ -1,3 +1,42 @@
+2012-06-18 Dirk Pranke <[email protected]>
+
+ new-run-webkit-tests output gets confused when logging
+ https://bugs.webkit.org/show_bug.cgi?id=63793
+
+ Reviewed by Adam Barth.
+
+ Ship all of the log messages generated in the worker back
+ to the manager; this allows the messages to be properly
+ serialized to stderr and for the meter to flush its output correctly.
+
+ Note however that this will likely result in messages to be
+ logged out of order between workers; I'm not sure that there's
+ an easy way to fix this short of buffering a potentially
+ unbounded amount of data. It might be better to just log through
+ stderr unless we're in 'metering' mode, but it's also worth
+ noting that we already get messages out of order through stderr
+ on Windows.
+
+ * Scripts/webkitpy/layout_tests/controllers/manager.py:
+ (Manager.handle_done):
+ (Manager.handle_finished_test):
+ (Manager._log_messages):
+ * Scripts/webkitpy/layout_tests/controllers/worker.py:
+ (Worker.__init__):
+ (Worker._set_up_logging):
+ (Worker.run):
+ (Worker._run_test):
+ (Worker.cleanup):
+ (Worker.run_single_test):
+ (_WorkerLogHandler):
+ (_WorkerLogHandler.__init__):
+ (_WorkerLogHandler.emit):
+ * Scripts/webkitpy/layout_tests/views/metered_stream.py:
+ (MeteredStream.write):
+ (MeteredStream.writeln):
+ * Scripts/webkitpy/layout_tests/views/printing.py:
+ (Printer.writeln):
+
2012-06-18 Zan Dobersek <[email protected]>
[garden-o-matic] Builder names without underscores cause incorrect BuildSelector behavior
Modified: trunk/Tools/Scripts/webkitpy/layout_tests/controllers/manager.py (120618 => 120619)
--- trunk/Tools/Scripts/webkitpy/layout_tests/controllers/manager.py 2012-06-18 19:53:38 UTC (rev 120618)
+++ trunk/Tools/Scripts/webkitpy/layout_tests/controllers/manager.py 2012-06-18 19:59:53 UTC (rev 120619)
@@ -1463,9 +1463,10 @@
worker_state.current_test_name = test_info.test_name
worker_state.next_timeout = time.time() + hang_timeout
- def handle_done(self, source):
+ def handle_done(self, source, log_messages=None):
worker_state = self._worker_states[source]
worker_state.done = True
+ self._log_messages(log_messages)
def handle_exception(self, source, exception_type, exception_value, stack):
if exception_type in (KeyboardInterrupt, TestRunInterruptedException):
@@ -1492,16 +1493,21 @@
if not self._remaining_locked_shards:
self.stop_servers_with_lock()
- def handle_finished_test(self, source, result, elapsed_time):
+ def handle_finished_test(self, source, result, elapsed_time, log_messages=None):
worker_state = self._worker_states[source]
worker_state.next_timeout = None
worker_state.current_test_name = None
worker_state.stats['total_time'] += elapsed_time
worker_state.stats['num_tests'] += 1
+ self._log_messages(log_messages)
self._all_results.append(result)
self._update_summary_with_result(self._current_result_summary, result)
+ def _log_messages(self, messages):
+ for message in messages:
+ self._printer.writeln(*message)
+
def _log_worker_stack(self, stack):
webkitpydir = self._port.path_from_webkit_base('Tools', 'Scripts', 'webkitpy') + self._filesystem.sep
for filename, line_number, function_name, text in stack:
Modified: trunk/Tools/Scripts/webkitpy/layout_tests/controllers/worker.py (120618 => 120619)
--- trunk/Tools/Scripts/webkitpy/layout_tests/controllers/worker.py 2012-06-18 19:53:38 UTC (rev 120618)
+++ trunk/Tools/Scripts/webkitpy/layout_tests/controllers/worker.py 2012-06-18 19:59:53 UTC (rev 120619)
@@ -29,6 +29,7 @@
"""Handle messages from the Manager and executes actual tests."""
import logging
+import os
import sys
import threading
import time
@@ -65,7 +66,9 @@
self._driver = None
self._tests_run_file = None
self._tests_run_filename = None
- self._meter = None
+ self._log_messages = []
+ self._logger = None
+ self._log_handler = None
def __del__(self):
self.cleanup()
@@ -83,29 +86,19 @@
self._tests_run_file = self._filesystem.open_text_file_for_writing(tests_run_filename)
def _set_up_logging(self):
+ self._logger = logging.getLogger()
+
# The unix multiprocessing implementation clones the MeteredStream log handler
- # into the child process, so we need to remove it before we can
- # add a new one to get the correct pid logged.
- root_logger = logging.getLogger()
- handler_to_remove = None
- for h in root_logger.handlers:
+ # into the child process, so we need to remove it to avoid duplicate logging.
+ for h in self._logger.handlers:
# log handlers don't have names until python 2.7.
if getattr(h, 'name', '') == metered_stream.LOG_HANDLER_NAME:
- handler_to_remove = h
+ self._logger.removeHandler(h)
break
- if handler_to_remove:
- root_logger.removeHandler(handler_to_remove)
- # FIXME: This won't work if the calling process is logging
- # somewhere other than sys.stderr, but I'm not sure
- # if this will be an issue in practice. Also, it would be
- # nice if we trapped all of the messages for a given test
- # and sent them back in finished_test() rather than logging
- # them to stderr.
- if not root_logger.handlers:
- options = self._options
- root_logger.setLevel(logging.DEBUG if options.verbose else logging.INFO)
- self._meter = metered_stream.MeteredStream(sys.stderr, options.verbose, logger=root_logger)
+ self._logger.setLevel(logging.DEBUG if self._options.verbose else logging.INFO)
+ self._log_handler = _WorkerLogHandler(self)
+ self._logger.addHandler(self._log_handler)
def _set_up_host_and_port(self):
options = self._options
@@ -132,9 +125,9 @@
super(Worker, self).run()
finally:
self.kill_driver()
- self._worker_connection.post_message('done')
_log.debug("%s exiting" % self._name)
self.cleanup()
+ self._worker_connection.post_message('done', self._log_messages)
def handle_test_list(self, src, list_name, test_list):
start_time = time.time()
@@ -171,7 +164,9 @@
result = self.run_test_with_timeout(test_input, test_timeout_sec)
elapsed_time = time.time() - start
- self._worker_connection.post_message('finished_test', result, elapsed_time)
+ log_messages = self._log_messages
+ self._log_messages = []
+ self._worker_connection.post_message('finished_test', result, elapsed_time, log_messages)
self.clean_up_after_test(test_input, result)
@@ -181,9 +176,10 @@
if self._tests_run_file:
self._tests_run_file.close()
self._tests_run_file = None
- if self._meter:
- self._meter.cleanup()
- self._meter = None
+ if self._log_handler and self._logger:
+ self._logger.removeHandler(self._log_handler)
+ self._log_handler = None
+ self._logger = None
def timeout(self, test_input):
"""Compute the appropriate timeout value for a test."""
@@ -300,3 +296,13 @@
def run_single_test(self, driver, test_input):
return single_test_runner.run_single_test(self._port, self._options,
test_input, driver, self._name)
+
+
+class _WorkerLogHandler(logging.Handler):
+ def __init__(self, worker):
+ logging.Handler.__init__(self)
+ self._worker = worker
+ self._pid = os.getpid()
+
+ def emit(self, record):
+ self._worker._log_messages.append(tuple([record.getMessage(), record.created, self._pid]))
Modified: trunk/Tools/Scripts/webkitpy/layout_tests/views/metered_stream.py (120618 => 120619)
--- trunk/Tools/Scripts/webkitpy/layout_tests/views/metered_stream.py 2012-06-18 19:53:38 UTC (rev 120618)
+++ trunk/Tools/Scripts/webkitpy/layout_tests/views/metered_stream.py 2012-06-18 19:59:53 UTC (rev 120619)
@@ -91,14 +91,15 @@
if self._erasing:
self._last_partial_line = txt[txt.rfind('\n') + 1:]
- def write(self, txt, now=None):
+ def write(self, txt, now=None, pid=None):
now = now or self._time_fn()
+ pid = pid or self._pid
self._last_write_time = now
if self._last_partial_line:
self._erase_last_partial_line()
if self._verbose:
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), self._pid, self._ensure_newline(txt))
+ 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
else:
@@ -106,8 +107,8 @@
self._stream.write(msg)
- def writeln(self, txt, now=None):
- self.write(self._ensure_newline(txt), now)
+ def writeln(self, txt, now=None, pid=None):
+ self.write(self._ensure_newline(txt), now, pid)
def _erase_last_partial_line(self):
num_chars = len(self._last_partial_line)
Modified: trunk/Tools/Scripts/webkitpy/layout_tests/views/printing.py (120618 => 120619)
--- trunk/Tools/Scripts/webkitpy/layout_tests/views/printing.py 2012-06-18 19:53:38 UTC (rev 120618)
+++ trunk/Tools/Scripts/webkitpy/layout_tests/views/printing.py 2012-06-18 19:59:53 UTC (rev 120619)
@@ -407,6 +407,9 @@
return
self._write(msg)
+ def writeln(self, *args, **kwargs):
+ self._meter.writeln(*args, **kwargs)
+
def _write(self, msg):
self._meter.writeln(msg)
