clean up NRWT logging/metering, be less verbose
[WebKit-https.git] / Tools / Scripts / webkitpy / layout_tests / controllers / worker.py
1 # Copyright (C) 2011 Google Inc. All rights reserved.
2 #
3 # Redistribution and use in source and binary forms, with or without
4 # modification, are permitted provided that the following conditions are
5 # met:
6 #
7 #     * Redistributions of source code must retain the above copyright
8 # notice, this list of conditions and the following disclaimer.
9 #     * Redistributions in binary form must reproduce the above
10 # copyright notice, this list of conditions and the following disclaimer
11 # in the documentation and/or other materials provided with the
12 # distribution.
13 #     * Neither the name of Google Inc. nor the names of its
14 # contributors may be used to endorse or promote products derived from
15 # this software without specific prior written permission.
16 #
17 # THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS
18 # "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT
19 # LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR
20 # A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT
21 # OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL,
22 # SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT
23 # LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE,
24 # DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY
25 # THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT
26 # (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE
27 # OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
28
29 """Handle messages from the Manager and executes actual tests."""
30
31 import logging
32 import sys
33 import threading
34 import time
35
36 from webkitpy.common.host import Host
37 from webkitpy.layout_tests.controllers import manager_worker_broker
38 from webkitpy.layout_tests.controllers import single_test_runner
39 from webkitpy.layout_tests.models import test_expectations
40 from webkitpy.layout_tests.models import test_results
41 from webkitpy.layout_tests.views import metered_stream
42
43
44 _log = logging.getLogger(__name__)
45
46
47 class WorkerArguments(object):
48     def __init__(self, worker_number, results_directory, options):
49         self.worker_number = worker_number
50         self.results_directory = results_directory
51         self.options = options
52
53
54 class Worker(manager_worker_broker.AbstractWorker):
55     def __init__(self, worker_connection, worker_arguments):
56         super(Worker, self).__init__(worker_connection, worker_arguments)
57         self._worker_number = worker_arguments.worker_number
58         self._name = 'worker/%d' % self._worker_number
59         self._results_directory = worker_arguments.results_directory
60         self._options = worker_arguments.options
61         self._port = None
62         self._batch_size = None
63         self._batch_count = None
64         self._filesystem = None
65         self._driver = None
66         self._tests_run_file = None
67         self._tests_run_filename = None
68         self._meter = None
69
70     def __del__(self):
71         self.cleanup()
72
73     def safe_init(self):
74         """This method should only be called when it is is safe for the mixin
75         to create state that can't be Pickled.
76
77         This routine exists so that the mixin can be created and then marshaled
78         across into a child process."""
79         self._filesystem = self._port.host.filesystem
80         self._batch_count = 0
81         self._batch_size = self._options.batch_size or 0
82         tests_run_filename = self._filesystem.join(self._results_directory, "tests_run%d.txt" % self._worker_number)
83         self._tests_run_file = self._filesystem.open_text_file_for_writing(tests_run_filename)
84
85     def _set_up_logging(self):
86         # The unix multiprocessing implementation clones the MeteredStream log handler
87         # into the child process, so we need to remove it before we can
88         # add a new one to get the correct pid logged.
89         root_logger = logging.getLogger()
90         handler_to_remove = None
91         for h in root_logger.handlers:
92             if h.name == metered_stream.LOG_HANDLER_NAME:
93                 handler_to_remove = h
94                 break
95         if handler_to_remove:
96             root_logger.removeHandler(handler_to_remove)
97
98         # FIXME: This won't work if the calling process is logging
99         # somewhere other than sys.stderr, but I'm not sure
100         # if this will be an issue in practice. Also, it would be
101         # nice if we trapped all of the messages for a given test
102         # and sent them back in finished_test() rather than logging
103         # them to stderr.
104         if not root_logger.handlers:
105             options = self._options
106             root_logger.setLevel(logging.DEBUG if options.verbose else logging.INFO)
107             self._meter = metered_stream.MeteredStream(sys.stderr, options.verbose, logger=root_logger)
108
109     def _set_up_host_and_port(self):
110         options = self._options
111         if options.platform and 'test' in options.platform:
112             # It is lame to import mocks into real code, but this allows us to use the test port in multi-process tests as well.
113             from webkitpy.common.host_mock import MockHost
114             host = MockHost()
115         else:
116             host = Host()
117         self._port = host.port_factory.get(options.platform, options)
118
119     def set_inline_arguments(self, port):
120         self._port = port
121
122     def run(self):
123         if not self._port:
124             # We are running in a child process and need to initialize things.
125             self._set_up_logging()
126             self._set_up_host_and_port()
127
128         self.safe_init()
129         try:
130             _log.debug("%s starting" % self._name)
131             super(Worker, self).run()
132         finally:
133             self.kill_driver()
134             self._worker_connection.post_message('done')
135             _log.debug("%s exiting" % self._name)
136             self.cleanup()
137
138     def handle_test_list(self, src, list_name, test_list):
139         start_time = time.time()
140         num_tests = 0
141         for test_input in test_list:
142             #FIXME: When the DRT support also this function, that would be useful
143             if self._port.driver_name() == "WebKitTestRunner" and self._port.get_option('skip_pixel_test_if_no_baseline') and self._port.get_option('pixel_tests'):
144                 test_input.should_run_pixel_test = (self._port.expected_image(test_input.test_name) != None)
145             self._run_test(test_input)
146             num_tests += 1
147             self._worker_connection.yield_to_broker()
148
149         elapsed_time = time.time() - start_time
150         self._worker_connection.post_message('finished_list', list_name, num_tests, elapsed_time)
151
152     def handle_stop(self, src):
153         self.stop_handling_messages()
154
155     def _run_test(self, test_input):
156         test_timeout_sec = self.timeout(test_input)
157         start = time.time()
158         self._worker_connection.post_message('started_test', test_input, test_timeout_sec)
159
160         result = self.run_test_with_timeout(test_input, test_timeout_sec)
161
162         elapsed_time = time.time() - start
163         self._worker_connection.post_message('finished_test', result, elapsed_time)
164
165         self.clean_up_after_test(test_input, result)
166
167     def cleanup(self):
168         _log.debug("%s cleaning up" % self._name)
169         self.kill_driver()
170         if self._tests_run_file:
171             self._tests_run_file.close()
172             self._tests_run_file = None
173         if self._meter:
174             self._meter.cleanup()
175             self._meter = None
176
177     def timeout(self, test_input):
178         """Compute the appropriate timeout value for a test."""
179         # The DumpRenderTree watchdog uses 2.5x the timeout; we want to be
180         # larger than that. We also add a little more padding if we're
181         # running tests in a separate thread.
182         #
183         # Note that we need to convert the test timeout from a
184         # string value in milliseconds to a float for Python.
185         driver_timeout_sec = 3.0 * float(test_input.timeout) / 1000.0
186         if not self._options.run_singly:
187             return driver_timeout_sec
188
189         thread_padding_sec = 1.0
190         thread_timeout_sec = driver_timeout_sec + thread_padding_sec
191         return thread_timeout_sec
192
193     def kill_driver(self):
194         if self._driver:
195             _log.debug("%s killing driver" % self._name)
196             self._driver.stop()
197             self._driver = None
198
199     def run_test_with_timeout(self, test_input, timeout):
200         if self._options.run_singly:
201             return self._run_test_in_another_thread(test_input, timeout)
202         return self._run_test_in_this_thread(test_input)
203
204     def clean_up_after_test(self, test_input, result):
205         self._batch_count += 1
206         test_name = test_input.test_name
207         self._tests_run_file.write(test_name + "\n")
208
209         if result.failures:
210             # Check and kill DumpRenderTree if we need to.
211             if any([f.driver_needs_restart() for f in result.failures]):
212                 self.kill_driver()
213                 # Reset the batch count since the shell just bounced.
214                 self._batch_count = 0
215
216             # Print the error message(s).
217             _log.debug("%s %s failed:" % (self._name, test_name))
218             for f in result.failures:
219                 _log.debug("%s  %s" % (self._name, f.message()))
220         elif result.type == test_expectations.SKIP:
221             _log.debug("%s %s skipped" % (self._name, test_name))
222         else:
223             _log.debug("%s %s passed" % (self._name, test_name))
224
225         if self._batch_size > 0 and self._batch_count >= self._batch_size:
226             self.kill_driver()
227             self._batch_count = 0
228
229     def _run_test_in_another_thread(self, test_input, thread_timeout_sec):
230         """Run a test in a separate thread, enforcing a hard time limit.
231
232         Since we can only detect the termination of a thread, not any internal
233         state or progress, we can only run per-test timeouts when running test
234         files singly.
235
236         Args:
237           test_input: Object containing the test filename and timeout
238           thread_timeout_sec: time to wait before killing the driver process.
239         Returns:
240           A TestResult
241         """
242         worker = self
243
244         driver = self._port.create_driver(self._worker_number)
245
246         class SingleTestThread(threading.Thread):
247             def __init__(self):
248                 threading.Thread.__init__(self)
249                 self.result = None
250
251             def run(self):
252                 self.result = worker.run_single_test(driver, test_input)
253
254         thread = SingleTestThread()
255         thread.start()
256         thread.join(thread_timeout_sec)
257         result = thread.result
258         if thread.isAlive():
259             # If join() returned with the thread still running, the
260             # DumpRenderTree is completely hung and there's nothing
261             # more we can do with it.  We have to kill all the
262             # DumpRenderTrees to free it up. If we're running more than
263             # one DumpRenderTree thread, we'll end up killing the other
264             # DumpRenderTrees too, introducing spurious crashes. We accept
265             # that tradeoff in order to avoid losing the rest of this
266             # thread's results.
267             _log.error('Test thread hung: killing all DumpRenderTrees')
268
269         driver.stop()
270
271         if not result:
272             result = test_results.TestResult(test_input.test_name, failures=[], test_run_time=0)
273         return result
274
275     def _run_test_in_this_thread(self, test_input):
276         """Run a single test file using a shared DumpRenderTree process.
277
278         Args:
279           test_input: Object containing the test filename, uri and timeout
280
281         Returns: a TestResult object.
282         """
283         if self._driver and self._driver.has_crashed():
284             self.kill_driver()
285         if not self._driver:
286             self._driver = self._port.create_driver(self._worker_number)
287         return self.run_single_test(self._driver, test_input)
288
289     def run_single_test(self, driver, test_input):
290         return single_test_runner.run_single_test(self._port, self._options,
291             test_input, driver, self._name)