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             # log handlers don't have names until python 2.7.
93             if getattr(h, 'name', '') == metered_stream.LOG_HANDLER_NAME:
94                 handler_to_remove = h
95                 break
96         if handler_to_remove:
97             root_logger.removeHandler(handler_to_remove)
98
99         # FIXME: This won't work if the calling process is logging
100         # somewhere other than sys.stderr, but I'm not sure
101         # if this will be an issue in practice. Also, it would be
102         # nice if we trapped all of the messages for a given test
103         # and sent them back in finished_test() rather than logging
104         # them to stderr.
105         if not root_logger.handlers:
106             options = self._options
107             root_logger.setLevel(logging.DEBUG if options.verbose else logging.INFO)
108             self._meter = metered_stream.MeteredStream(sys.stderr, options.verbose, logger=root_logger)
109
110     def _set_up_host_and_port(self):
111         options = self._options
112         if options.platform and 'test' in options.platform:
113             # It is lame to import mocks into real code, but this allows us to use the test port in multi-process tests as well.
114             from webkitpy.common.host_mock import MockHost
115             host = MockHost()
116         else:
117             host = Host()
118         self._port = host.port_factory.get(options.platform, options)
119
120     def set_inline_arguments(self, port):
121         self._port = port
122
123     def run(self):
124         if not self._port:
125             # We are running in a child process and need to initialize things.
126             self._set_up_logging()
127             self._set_up_host_and_port()
128
129         self.safe_init()
130         try:
131             _log.debug("%s starting" % self._name)
132             super(Worker, self).run()
133         finally:
134             self.kill_driver()
135             self._worker_connection.post_message('done')
136             _log.debug("%s exiting" % self._name)
137             self.cleanup()
138
139     def handle_test_list(self, src, list_name, test_list):
140         start_time = time.time()
141         num_tests = 0
142         for test_input in test_list:
143             #FIXME: When the DRT support also this function, that would be useful
144             if self._port.driver_name() == "WebKitTestRunner" and self._port.get_option('skip_pixel_test_if_no_baseline') and self._port.get_option('pixel_tests'):
145                 test_input.should_run_pixel_test = (self._port.expected_image(test_input.test_name) != None)
146             self._run_test(test_input)
147             num_tests += 1
148             self._worker_connection.yield_to_broker()
149
150         elapsed_time = time.time() - start_time
151         self._worker_connection.post_message('finished_list', list_name, num_tests, elapsed_time)
152
153     def handle_stop(self, src):
154         self.stop_handling_messages()
155
156     def _run_test(self, test_input):
157         test_timeout_sec = self.timeout(test_input)
158         start = time.time()
159         self._worker_connection.post_message('started_test', test_input, test_timeout_sec)
160
161         result = self.run_test_with_timeout(test_input, test_timeout_sec)
162
163         elapsed_time = time.time() - start
164         self._worker_connection.post_message('finished_test', result, elapsed_time)
165
166         self.clean_up_after_test(test_input, result)
167
168     def cleanup(self):
169         _log.debug("%s cleaning up" % self._name)
170         self.kill_driver()
171         if self._tests_run_file:
172             self._tests_run_file.close()
173             self._tests_run_file = None
174         if self._meter:
175             self._meter.cleanup()
176             self._meter = None
177
178     def timeout(self, test_input):
179         """Compute the appropriate timeout value for a test."""
180         # The DumpRenderTree watchdog uses 2.5x the timeout; we want to be
181         # larger than that. We also add a little more padding if we're
182         # running tests in a separate thread.
183         #
184         # Note that we need to convert the test timeout from a
185         # string value in milliseconds to a float for Python.
186         driver_timeout_sec = 3.0 * float(test_input.timeout) / 1000.0
187         if not self._options.run_singly:
188             return driver_timeout_sec
189
190         thread_padding_sec = 1.0
191         thread_timeout_sec = driver_timeout_sec + thread_padding_sec
192         return thread_timeout_sec
193
194     def kill_driver(self):
195         if self._driver:
196             _log.debug("%s killing driver" % self._name)
197             self._driver.stop()
198             self._driver = None
199
200     def run_test_with_timeout(self, test_input, timeout):
201         if self._options.run_singly:
202             return self._run_test_in_another_thread(test_input, timeout)
203         return self._run_test_in_this_thread(test_input)
204
205     def clean_up_after_test(self, test_input, result):
206         self._batch_count += 1
207         test_name = test_input.test_name
208         self._tests_run_file.write(test_name + "\n")
209
210         if result.failures:
211             # Check and kill DumpRenderTree if we need to.
212             if any([f.driver_needs_restart() for f in result.failures]):
213                 self.kill_driver()
214                 # Reset the batch count since the shell just bounced.
215                 self._batch_count = 0
216
217             # Print the error message(s).
218             _log.debug("%s %s failed:" % (self._name, test_name))
219             for f in result.failures:
220                 _log.debug("%s  %s" % (self._name, f.message()))
221         elif result.type == test_expectations.SKIP:
222             _log.debug("%s %s skipped" % (self._name, test_name))
223         else:
224             _log.debug("%s %s passed" % (self._name, test_name))
225
226         if self._batch_size > 0 and self._batch_count >= self._batch_size:
227             self.kill_driver()
228             self._batch_count = 0
229
230     def _run_test_in_another_thread(self, test_input, thread_timeout_sec):
231         """Run a test in a separate thread, enforcing a hard time limit.
232
233         Since we can only detect the termination of a thread, not any internal
234         state or progress, we can only run per-test timeouts when running test
235         files singly.
236
237         Args:
238           test_input: Object containing the test filename and timeout
239           thread_timeout_sec: time to wait before killing the driver process.
240         Returns:
241           A TestResult
242         """
243         worker = self
244
245         driver = self._port.create_driver(self._worker_number)
246
247         class SingleTestThread(threading.Thread):
248             def __init__(self):
249                 threading.Thread.__init__(self)
250                 self.result = None
251
252             def run(self):
253                 self.result = worker.run_single_test(driver, test_input)
254
255         thread = SingleTestThread()
256         thread.start()
257         thread.join(thread_timeout_sec)
258         result = thread.result
259         if thread.isAlive():
260             # If join() returned with the thread still running, the
261             # DumpRenderTree is completely hung and there's nothing
262             # more we can do with it.  We have to kill all the
263             # DumpRenderTrees to free it up. If we're running more than
264             # one DumpRenderTree thread, we'll end up killing the other
265             # DumpRenderTrees too, introducing spurious crashes. We accept
266             # that tradeoff in order to avoid losing the rest of this
267             # thread's results.
268             _log.error('Test thread hung: killing all DumpRenderTrees')
269
270         driver.stop()
271
272         if not result:
273             result = test_results.TestResult(test_input.test_name, failures=[], test_run_time=0)
274         return result
275
276     def _run_test_in_this_thread(self, test_input):
277         """Run a single test file using a shared DumpRenderTree process.
278
279         Args:
280           test_input: Object containing the test filename, uri and timeout
281
282         Returns: a TestResult object.
283         """
284         if self._driver and self._driver.has_crashed():
285             self.kill_driver()
286         if not self._driver:
287             self._driver = self._port.create_driver(self._worker_number)
288         return self.run_single_test(self._driver, test_input)
289
290     def run_single_test(self, driver, test_input):
291         return single_test_runner.run_single_test(self._port, self._options,
292             test_input, driver, self._name)