2010-11-17 Hayato Ito <hayato@chromium.org>
[WebKit-https.git] / WebKitTools / Scripts / webkitpy / layout_tests / layout_package / dump_render_tree_thread.py
1 #!/usr/bin/env python
2 # Copyright (C) 2010 Google Inc. All rights reserved.
3 # Copyright (C) 2010 Gabor Rapcsanyi (rgabor@inf.u-szeged.hu), University of Szeged
4 #
5 # Redistribution and use in source and binary forms, with or without
6 # modification, are permitted provided that the following conditions are
7 # met:
8 #
9 #     * Redistributions of source code must retain the above copyright
10 # notice, this list of conditions and the following disclaimer.
11 #     * Redistributions in binary form must reproduce the above
12 # copyright notice, this list of conditions and the following disclaimer
13 # in the documentation and/or other materials provided with the
14 # distribution.
15 #     * Neither the name of Google Inc. nor the names of its
16 # contributors may be used to endorse or promote products derived from
17 # this software without specific prior written permission.
18 #
19 # THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS
20 # "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT
21 # LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR
22 # A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT
23 # OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL,
24 # SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT
25 # LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE,
26 # DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY
27 # THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT
28 # (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE
29 # OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
30
31 """A Thread object for running DumpRenderTree and processing URLs from a
32 shared queue.
33
34 Each thread runs a separate instance of the DumpRenderTree binary and validates
35 the output.  When there are no more URLs to process in the shared queue, the
36 thread exits.
37 """
38
39 from __future__ import with_statement
40
41 import codecs
42 import copy
43 import logging
44 import os
45 import Queue
46 import signal
47 import sys
48 import thread
49 import threading
50 import time
51 import traceback
52
53 import test_failures
54 import test_output
55 import test_results
56
57 _log = logging.getLogger("webkitpy.layout_tests.layout_package."
58                          "dump_render_tree_thread")
59
60
61 def find_thread_stack(id):
62     """Returns a stack object that can be used to dump a stack trace for
63     the given thread id (or None if the id is not found)."""
64     for thread_id, stack in sys._current_frames().items():
65         if thread_id == id:
66             return stack
67     return None
68
69
70 def log_stack(stack):
71     """Log a stack trace to log.error()."""
72     for filename, lineno, name, line in traceback.extract_stack(stack):
73         _log.error('File: "%s", line %d, in %s' % (filename, lineno, name))
74         if line:
75             _log.error('  %s' % line.strip())
76
77
78 def _expected_test_output(port, filename):
79     """Returns an expected TestOutput object."""
80     return test_output.TestOutput(port.expected_text(filename),
81                                   port.expected_image(filename),
82                                   port.expected_checksum(filename))
83
84 def _process_output(port, options, test_input, test_types, test_args,
85                     test_output):
86     """Receives the output from a DumpRenderTree process, subjects it to a
87     number of tests, and returns a list of failure types the test produced.
88
89     Args:
90       port: port-specific hooks
91       options: command line options argument from optparse
92       proc: an active DumpRenderTree process
93       test_input: Object containing the test filename, uri and timeout
94       test_types: list of test types to subject the output to
95       test_args: arguments to be passed to each test
96       test_output: a TestOutput object containing the output of the test
97
98     Returns: a TestResult object
99     """
100     failures = []
101
102     if test_output.crash:
103         failures.append(test_failures.FailureCrash())
104     if test_output.timeout:
105         failures.append(test_failures.FailureTimeout())
106
107     if test_output.crash:
108         _log.debug("Stacktrace for %s:\n%s" % (test_input.filename,
109                                                test_output.error))
110         # Strip off "file://" since RelativeTestFilename expects
111         # filesystem paths.
112         filename = os.path.join(options.results_directory,
113                                 port.relative_test_filename(
114                                 test_input.filename))
115         filename = os.path.splitext(filename)[0] + "-stack.txt"
116         port.maybe_make_directory(os.path.split(filename)[0])
117         with codecs.open(filename, "wb", "utf-8") as file:
118             file.write(test_output.error)
119     elif test_output.error:
120         _log.debug("Previous test output stderr lines:\n%s" % test_output.error)
121
122     expected_test_output = _expected_test_output(port, test_input.filename)
123
124     # Check the output and save the results.
125     start_time = time.time()
126     time_for_diffs = {}
127     for test_type in test_types:
128         start_diff_time = time.time()
129         new_failures = test_type.compare_output(port, test_input.filename,
130                                                 test_args, test_output,
131                                                 expected_test_output)
132         # Don't add any more failures if we already have a crash, so we don't
133         # double-report those tests. We do double-report for timeouts since
134         # we still want to see the text and image output.
135         if not test_output.crash:
136             failures.extend(new_failures)
137         time_for_diffs[test_type.__class__.__name__] = (
138             time.time() - start_diff_time)
139
140     total_time_for_all_diffs = time.time() - start_diff_time
141     return test_results.TestResult(test_input.filename, failures, test_output.test_time,
142                                    total_time_for_all_diffs, time_for_diffs)
143
144
145 def _pad_timeout(timeout):
146     """Returns a safe multiple of the per-test timeout value to use
147     to detect hung test threads.
148
149     """
150     # When we're running one test per DumpRenderTree process, we can
151     # enforce a hard timeout.  The DumpRenderTree watchdog uses 2.5x
152     # the timeout; we want to be larger than that.
153     return timeout * 3
154
155
156 def _milliseconds_to_seconds(msecs):
157     return float(msecs) / 1000.0
158
159
160 def _should_fetch_expected_checksum(options):
161     return options.pixel_tests and not (options.new_baseline or options.reset_results)
162
163
164 def _run_single_test(port, options, test_input, test_types, test_args, driver):
165     # FIXME: Pull this into TestShellThread._run().
166
167     # The image hash is used to avoid doing an image dump if the
168     # checksums match, so it should be set to a blank value if we
169     # are generating a new baseline.  (Otherwise, an image from a
170     # previous run will be copied into the baseline."""
171     if _should_fetch_expected_checksum(options):
172         image_hash_to_driver = port.expected_checksum(test_input.filename)
173     else:
174         image_hash_to_driver = None
175     test_input.uri = port.filename_to_uri(test_input.filename).strip()
176     test_output = driver.run_test(test_input.uri, test_input.timeout, image_hash_to_driver)
177     return _process_output(port, options, test_input, test_types, test_args,
178                            test_output)
179
180
181 class SingleTestThread(threading.Thread):
182     """Thread wrapper for running a single test file."""
183
184     def __init__(self, port, options, test_input, test_types, test_args):
185         """
186         Args:
187           port: object implementing port-specific hooks
188           options: command line argument object from optparse
189           test_input: Object containing the test filename, uri and timeout
190           test_types: A list of TestType objects to run the test output
191               against.
192           test_args: A TestArguments object to pass to each TestType.
193         """
194
195         threading.Thread.__init__(self)
196         self._port = port
197         self._options = options
198         self._test_input = test_input
199         self._test_types = test_types
200         self._test_args = test_args
201         self._driver = None
202
203     def run(self):
204         self._covered_run()
205
206     def _covered_run(self):
207         # FIXME: this is a separate routine to work around a bug
208         # in coverage: see http://bitbucket.org/ned/coveragepy/issue/85.
209         self._driver = self._port.create_driver(self._test_args.png_path,
210                                                 self._options)
211         self._driver.start()
212         self._test_result = _run_single_test(self._port, self._options,
213                                              self._test_input, self._test_types,
214                                              self._test_args, self._driver)
215         self._driver.stop()
216
217     def get_test_result(self):
218         return self._test_result
219
220
221 class WatchableThread(threading.Thread):
222     """This class abstracts an interface used by
223     run_webkit_tests.TestRunner._wait_for_threads_to_finish for thread
224     management."""
225     def __init__(self):
226         threading.Thread.__init__(self)
227         self._canceled = False
228         self._exception_info = None
229         self._next_timeout = None
230         self._thread_id = None
231
232     def cancel(self):
233         """Set a flag telling this thread to quit."""
234         self._canceled = True
235
236     def clear_next_timeout(self):
237         """Mark a flag telling this thread to stop setting timeouts."""
238         self._timeout = 0
239
240     def exception_info(self):
241         """If run() terminated on an uncaught exception, return it here
242         ((type, value, traceback) tuple).
243         Returns None if run() terminated normally. Meant to be called after
244         joining this thread."""
245         return self._exception_info
246
247     def id(self):
248         """Return a thread identifier."""
249         return self._thread_id
250
251     def next_timeout(self):
252         """Return the time the test is supposed to finish by."""
253         return self._next_timeout
254
255
256 class TestShellThread(WatchableThread):
257     def __init__(self, port, options, filename_list_queue, result_queue,
258                  test_types, test_args):
259         """Initialize all the local state for this DumpRenderTree thread.
260
261         Args:
262           port: interface to port-specific hooks
263           options: command line options argument from optparse
264           filename_list_queue: A thread safe Queue class that contains lists
265               of tuples of (filename, uri) pairs.
266           result_queue: A thread safe Queue class that will contain
267               serialized TestResult objects.
268           test_types: A list of TestType objects to run the test output
269               against.
270           test_args: A TestArguments object to pass to each TestType.
271         """
272         WatchableThread.__init__(self)
273         self._port = port
274         self._options = options
275         self._filename_list_queue = filename_list_queue
276         self._result_queue = result_queue
277         self._filename_list = []
278         self._test_types = test_types
279         self._test_args = test_args
280         self._driver = None
281         self._test_group_timing_stats = {}
282         self._test_results = []
283         self._num_tests = 0
284         self._start_time = 0
285         self._stop_time = 0
286         self._have_http_lock = False
287         self._http_lock_wait_begin = 0
288         self._http_lock_wait_end = 0
289
290         # Current group of tests we're running.
291         self._current_group = None
292         # Number of tests in self._current_group.
293         self._num_tests_in_current_group = None
294         # Time at which we started running tests from self._current_group.
295         self._current_group_start_time = None
296
297     def get_test_group_timing_stats(self):
298         """Returns a dictionary mapping test group to a tuple of
299         (number of tests in that group, time to run the tests)"""
300         return self._test_group_timing_stats
301
302     def get_test_results(self):
303         """Return the list of all tests run on this thread.
304
305         This is used to calculate per-thread statistics.
306
307         """
308         return self._test_results
309
310     def get_total_time(self):
311         return max(self._stop_time - self._start_time -
312                    self._http_lock_wait_time(), 0.0)
313
314     def get_num_tests(self):
315         return self._num_tests
316
317     def run(self):
318         """Delegate main work to a helper method and watch for uncaught
319         exceptions."""
320         self._covered_run()
321
322     def _covered_run(self):
323         # FIXME: this is a separate routine to work around a bug
324         # in coverage: see http://bitbucket.org/ned/coveragepy/issue/85.
325         self._thread_id = thread.get_ident()
326         self._start_time = time.time()
327         self._num_tests = 0
328         try:
329             _log.debug('%s starting' % (self.getName()))
330             self._run(test_runner=None, result_summary=None)
331             _log.debug('%s done (%d tests)' % (self.getName(),
332                        self.get_num_tests()))
333         except KeyboardInterrupt:
334             self._exception_info = sys.exc_info()
335             _log.debug("%s interrupted" % self.getName())
336         except:
337             # Save the exception for our caller to see.
338             self._exception_info = sys.exc_info()
339             self._stop_time = time.time()
340             _log.error('%s dying, exception raised' % self.getName())
341
342         self._stop_time = time.time()
343
344     def run_in_main_thread(self, test_runner, result_summary):
345         """This hook allows us to run the tests from the main thread if
346         --num-test-shells==1, instead of having to always run two or more
347         threads. This allows us to debug the test harness without having to
348         do multi-threaded debugging."""
349         self._run(test_runner, result_summary)
350
351     def cancel(self):
352         """Clean up http lock and set a flag telling this thread to quit."""
353         self._stop_servers_with_lock()
354         WatchableThread.cancel(self)
355
356     def next_timeout(self):
357         """Return the time the test is supposed to finish by."""
358         if self._next_timeout:
359             return self._next_timeout + self._http_lock_wait_time()
360         return self._next_timeout
361
362     def _http_lock_wait_time(self):
363         """Return the time what http locking takes."""
364         if self._http_lock_wait_begin == 0:
365             return 0
366         if self._http_lock_wait_end == 0:
367             return time.time() - self._http_lock_wait_begin
368         return self._http_lock_wait_end - self._http_lock_wait_begin
369
370     def _run(self, test_runner, result_summary):
371         """Main work entry point of the thread. Basically we pull urls from the
372         filename queue and run the tests until we run out of urls.
373
374         If test_runner is not None, then we call test_runner.UpdateSummary()
375         with the results of each test."""
376         batch_size = self._options.batch_size
377         batch_count = 0
378
379         # Append tests we're running to the existing tests_run.txt file.
380         # This is created in run_webkit_tests.py:_PrepareListsAndPrintOutput.
381         tests_run_filename = os.path.join(self._options.results_directory,
382                                           "tests_run.txt")
383         tests_run_file = codecs.open(tests_run_filename, "a", "utf-8")
384
385         while True:
386             if self._canceled:
387                 _log.debug('Testing cancelled')
388                 tests_run_file.close()
389                 return
390
391             if len(self._filename_list) is 0:
392                 if self._current_group is not None:
393                     self._test_group_timing_stats[self._current_group] = \
394                         (self._num_tests_in_current_group,
395                          time.time() - self._current_group_start_time)
396
397                 try:
398                     self._current_group, self._filename_list = \
399                         self._filename_list_queue.get_nowait()
400                 except Queue.Empty:
401                     self._stop_servers_with_lock()
402                     self._kill_dump_render_tree()
403                     tests_run_file.close()
404                     return
405
406                 if self._current_group == "tests_to_http_lock":
407                     self._start_servers_with_lock()
408                 elif self._have_http_lock:
409                     self._stop_servers_with_lock()
410
411                 self._num_tests_in_current_group = len(self._filename_list)
412                 self._current_group_start_time = time.time()
413
414             test_input = self._filename_list.pop()
415
416             # We have a url, run tests.
417             batch_count += 1
418             self._num_tests += 1
419             if self._options.run_singly:
420                 result = self._run_test_singly(test_input)
421             else:
422                 result = self._run_test(test_input)
423
424             filename = test_input.filename
425             tests_run_file.write(filename + "\n")
426             if result.failures:
427                 # Check and kill DumpRenderTree if we need to.
428                 if len([1 for f in result.failures
429                         if f.should_kill_dump_render_tree()]):
430                     self._kill_dump_render_tree()
431                     # Reset the batch count since the shell just bounced.
432                     batch_count = 0
433                 # Print the error message(s).
434                 error_str = '\n'.join(['  ' + f.message() for
435                                        f in result.failures])
436                 _log.debug("%s %s failed:\n%s" % (self.getName(),
437                            self._port.relative_test_filename(filename),
438                            error_str))
439             else:
440                 _log.debug("%s %s passed" % (self.getName(),
441                            self._port.relative_test_filename(filename)))
442             self._result_queue.put(result.dumps())
443
444             if batch_size > 0 and batch_count >= batch_size:
445                 # Bounce the shell and reset count.
446                 self._kill_dump_render_tree()
447                 batch_count = 0
448
449             if test_runner:
450                 test_runner.update_summary(result_summary)
451
452     def _run_test_singly(self, test_input):
453         """Run a test in a separate thread, enforcing a hard time limit.
454
455         Since we can only detect the termination of a thread, not any internal
456         state or progress, we can only run per-test timeouts when running test
457         files singly.
458
459         Args:
460           test_input: Object containing the test filename, uri and timeout
461
462         Returns:
463           A TestResult
464
465         """
466         worker = SingleTestThread(self._port,
467                                   self._options,
468                                   test_input,
469                                   self._test_types,
470                                   self._test_args)
471
472         worker.start()
473
474         thread_timeout = _milliseconds_to_seconds(
475             _pad_timeout(int(test_input.timeout)))
476         thread._next_timeout = time.time() + thread_timeout
477         worker.join(thread_timeout)
478         if worker.isAlive():
479             # If join() returned with the thread still running, the
480             # DumpRenderTree is completely hung and there's nothing
481             # more we can do with it.  We have to kill all the
482             # DumpRenderTrees to free it up. If we're running more than
483             # one DumpRenderTree thread, we'll end up killing the other
484             # DumpRenderTrees too, introducing spurious crashes. We accept
485             # that tradeoff in order to avoid losing the rest of this
486             # thread's results.
487             _log.error('Test thread hung: killing all DumpRenderTrees')
488             if worker._driver:
489                 worker._driver.stop()
490
491         try:
492             result = worker.get_test_result()
493         except AttributeError, e:
494             # This gets raised if the worker thread has already exited.
495             failures = []
496             _log.error('Cannot get results of test: %s' %
497                        test_input.filename)
498             result = test_results.TestResult(test_input.filename, failures=[],
499                 test_run_time=0, total_time_for_all_diffs=0, time_for_diffs=0)
500
501         return result
502
503     def _run_test(self, test_input):
504         """Run a single test file using a shared DumpRenderTree process.
505
506         Args:
507           test_input: Object containing the test filename, uri and timeout
508
509         Returns: a TestResult object.
510         """
511         self._ensure_dump_render_tree_is_running()
512         thread_timeout = _milliseconds_to_seconds(
513              _pad_timeout(int(test_input.timeout)))
514         self._next_timeout = time.time() + thread_timeout
515         test_result = _run_single_test(self._port, self._options, test_input,
516                                        self._test_types, self._test_args,
517                                        self._driver)
518         self._test_results.append(test_result)
519         return test_result
520
521     def _ensure_dump_render_tree_is_running(self):
522         """Start the shared DumpRenderTree, if it's not running.
523
524         This is not for use when running tests singly, since those each start
525         a separate DumpRenderTree in their own thread.
526
527         """
528         # poll() is not threadsafe and can throw OSError due to:
529         # http://bugs.python.org/issue1731717
530         if (not self._driver or self._driver.poll() is not None):
531             self._driver = self._port.create_driver(self._test_args.png_path,
532                                                     self._options)
533             self._driver.start()
534
535     def _start_servers_with_lock(self):
536         """Acquire http lock and start the servers."""
537         self._http_lock_wait_begin = time.time()
538         _log.debug('Acquire http lock ...')
539         self._port.acquire_http_lock()
540         _log.debug('Starting HTTP server ...')
541         self._port.start_http_server()
542         _log.debug('Starting WebSocket server ...')
543         self._port.start_websocket_server()
544         self._http_lock_wait_end = time.time()
545         self._have_http_lock = True
546
547     def _stop_servers_with_lock(self):
548         """Stop the servers and release http lock."""
549         if self._have_http_lock:
550             _log.debug('Stopping HTTP server ...')
551             self._port.stop_http_server()
552             _log.debug('Stopping WebSocket server ...')
553             self._port.stop_websocket_server()
554             _log.debug('Release http lock ...')
555             self._port.release_http_lock()
556             self._have_http_lock = False
557
558     def _kill_dump_render_tree(self):
559         """Kill the DumpRenderTree process if it's running."""
560         if self._driver:
561             self._driver.stop()
562             self._driver = None