OLD | NEW |
| (Empty) |
1 # Copyright (c) 2006-2009 The Chromium Authors. All rights reserved. | |
2 # Use of this source code is governed by a BSD-style license that can be | |
3 # found in the LICENSE file. | |
4 | |
5 """A Thread object for running the test shell and processing URLs from a | |
6 shared queue. | |
7 | |
8 Each thread runs a separate instance of the test_shell binary and validates | |
9 the output. When there are no more URLs to process in the shared queue, the | |
10 thread exits. | |
11 """ | |
12 | |
13 import copy | |
14 import logging | |
15 import os | |
16 import Queue | |
17 import signal | |
18 import subprocess | |
19 import sys | |
20 import thread | |
21 import threading | |
22 import time | |
23 | |
24 import path_utils | |
25 import test_failures | |
26 | |
27 | |
28 def ProcessOutput(proc, test_info, test_types, test_args, target, output_dir): | |
29 """Receives the output from a test_shell process, subjects it to a number | |
30 of tests, and returns a list of failure types the test produced. | |
31 | |
32 Args: | |
33 proc: an active test_shell process | |
34 test_info: Object containing the test filename, uri and timeout | |
35 test_types: list of test types to subject the output to | |
36 test_args: arguments to be passed to each test | |
37 target: Debug or Release | |
38 output_dir: directory to put crash stack traces into | |
39 | |
40 Returns: a list of failure objects and times for the test being processed | |
41 """ | |
42 outlines = [] | |
43 extra_lines = [] | |
44 failures = [] | |
45 crash = False | |
46 | |
47 # Some test args, such as the image hash, may be added or changed on a | |
48 # test-by-test basis. | |
49 local_test_args = copy.copy(test_args) | |
50 | |
51 start_time = time.time() | |
52 | |
53 line = proc.stdout.readline() | |
54 | |
55 # Only start saving output lines once we've loaded the URL for the test. | |
56 url = None | |
57 test_string = test_info.uri.strip() | |
58 | |
59 while line.rstrip() != "#EOF": | |
60 # Make sure we haven't crashed. | |
61 if line == '' and proc.poll() is not None: | |
62 failures.append(test_failures.FailureCrash()) | |
63 | |
64 # This is hex code 0xc000001d, which is used for abrupt | |
65 # termination. This happens if we hit ctrl+c from the prompt and | |
66 # we happen to be waiting on the test_shell. | |
67 # sdoyon: Not sure for which OS and in what circumstances the | |
68 # above code is valid. What works for me under Linux to detect | |
69 # ctrl+c is for the subprocess returncode to be negative SIGINT. | |
70 # And that agrees with the subprocess documentation. | |
71 if (-1073741510 == proc.returncode or | |
72 - signal.SIGINT == proc.returncode): | |
73 raise KeyboardInterrupt | |
74 crash = True | |
75 break | |
76 | |
77 # Don't include #URL lines in our output | |
78 if line.startswith("#URL:"): | |
79 url = line.rstrip()[5:] | |
80 if url != test_string: | |
81 logging.fatal("Test got out of sync:\n|%s|\n|%s|" % | |
82 (url, test_string)) | |
83 raise AssertionError("test out of sync") | |
84 elif line.startswith("#MD5:"): | |
85 local_test_args.hash = line.rstrip()[5:] | |
86 elif line.startswith("#TEST_TIMED_OUT"): | |
87 # Test timed out, but we still need to read until #EOF. | |
88 failures.append(test_failures.FailureTimeout()) | |
89 elif url: | |
90 outlines.append(line) | |
91 else: | |
92 extra_lines.append(line) | |
93 | |
94 line = proc.stdout.readline() | |
95 | |
96 end_test_time = time.time() | |
97 | |
98 if len(extra_lines): | |
99 extra = "".join(extra_lines) | |
100 if crash: | |
101 logging.debug("Stacktrace for %s:\n%s" % (test_string, extra)) | |
102 # Strip off "file://" since RelativeTestFilename expects | |
103 # filesystem paths. | |
104 filename = os.path.join(output_dir, | |
105 path_utils.RelativeTestFilename(test_string[7:])) | |
106 filename = os.path.splitext(filename)[0] + "-stack.txt" | |
107 path_utils.MaybeMakeDirectory(os.path.split(filename)[0]) | |
108 open(filename, "wb").write(extra) | |
109 else: | |
110 logging.debug("Previous test output extra lines after dump:\n%s" % | |
111 extra) | |
112 | |
113 # Check the output and save the results. | |
114 time_for_diffs = {} | |
115 for test_type in test_types: | |
116 start_diff_time = time.time() | |
117 new_failures = test_type.CompareOutput(test_info.filename, | |
118 proc, | |
119 ''.join(outlines), | |
120 local_test_args, | |
121 target) | |
122 # Don't add any more failures if we already have a crash, so we don't | |
123 # double-report those tests. We do double-report for timeouts since | |
124 # we still want to see the text and image output. | |
125 if not crash: | |
126 failures.extend(new_failures) | |
127 time_for_diffs[test_type.__class__.__name__] = ( | |
128 time.time() - start_diff_time) | |
129 | |
130 total_time_for_all_diffs = time.time() - end_test_time | |
131 test_run_time = end_test_time - start_time | |
132 return TestStats(test_info.filename, failures, test_run_time, | |
133 total_time_for_all_diffs, time_for_diffs) | |
134 | |
135 | |
136 def StartTestShell(command, args): | |
137 """Returns the process for a new test_shell started in layout-tests mode. | |
138 """ | |
139 cmd = [] | |
140 # Hook for injecting valgrind or other runtime instrumentation, | |
141 # used by e.g. tools/valgrind/valgrind_tests.py. | |
142 wrapper = os.environ.get("BROWSER_WRAPPER", None) | |
143 if wrapper != None: | |
144 cmd += [wrapper] | |
145 cmd += command + ['--layout-tests'] + args | |
146 return subprocess.Popen(cmd, | |
147 stdin=subprocess.PIPE, | |
148 stdout=subprocess.PIPE, | |
149 stderr=subprocess.STDOUT) | |
150 | |
151 | |
152 class TestStats: | |
153 | |
154 def __init__(self, filename, failures, test_run_time, | |
155 total_time_for_all_diffs, time_for_diffs): | |
156 self.filename = filename | |
157 self.failures = failures | |
158 self.test_run_time = test_run_time | |
159 self.total_time_for_all_diffs = total_time_for_all_diffs | |
160 self.time_for_diffs = time_for_diffs | |
161 | |
162 | |
163 class SingleTestThread(threading.Thread): | |
164 """Thread wrapper for running a single test file.""" | |
165 | |
166 def __init__(self, test_shell_command, shell_args, test_info, test_types, | |
167 test_args, target, output_dir): | |
168 """ | |
169 Args: | |
170 test_info: Object containing the test filename, uri and timeout | |
171 output_dir: Directory to put crash stacks into. | |
172 See TestShellThread for documentation of the remaining arguments. | |
173 """ | |
174 | |
175 threading.Thread.__init__(self) | |
176 self._command = test_shell_command | |
177 self._shell_args = shell_args | |
178 self._test_info = test_info | |
179 self._test_types = test_types | |
180 self._test_args = test_args | |
181 self._target = target | |
182 self._output_dir = output_dir | |
183 | |
184 def run(self): | |
185 proc = StartTestShell(self._command, self._shell_args + | |
186 ["--time-out-ms=" + self._test_info.timeout, self._test_info.uri]) | |
187 self._test_stats = ProcessOutput(proc, self._test_info, | |
188 self._test_types, self._test_args, self._target, self._output_dir) | |
189 | |
190 def GetTestStats(self): | |
191 return self._test_stats | |
192 | |
193 | |
194 class TestShellThread(threading.Thread): | |
195 | |
196 def __init__(self, filename_list_queue, result_queue, test_shell_command, | |
197 test_types, test_args, shell_args, options): | |
198 """Initialize all the local state for this test shell thread. | |
199 | |
200 Args: | |
201 filename_list_queue: A thread safe Queue class that contains lists | |
202 of tuples of (filename, uri) pairs. | |
203 result_queue: A thread safe Queue class that will contain tuples of | |
204 (test, failure lists) for the test results. | |
205 test_shell_command: A list specifying the command+args for | |
206 test_shell | |
207 test_types: A list of TestType objects to run the test output | |
208 against. | |
209 test_args: A TestArguments object to pass to each TestType. | |
210 shell_args: Any extra arguments to be passed to test_shell.exe. | |
211 options: A property dictionary as produced by optparse. The | |
212 command-line options should match those expected by | |
213 run_webkit_tests; they are typically passed via the | |
214 run_webkit_tests.TestRunner class.""" | |
215 threading.Thread.__init__(self) | |
216 self._filename_list_queue = filename_list_queue | |
217 self._result_queue = result_queue | |
218 self._filename_list = [] | |
219 self._test_shell_command = test_shell_command | |
220 self._test_types = test_types | |
221 self._test_args = test_args | |
222 self._test_shell_proc = None | |
223 self._shell_args = shell_args | |
224 self._options = options | |
225 self._canceled = False | |
226 self._exception_info = None | |
227 self._directory_timing_stats = {} | |
228 self._test_stats = [] | |
229 self._num_tests = 0 | |
230 self._start_time = 0 | |
231 self._stop_time = 0 | |
232 | |
233 # Current directory of tests we're running. | |
234 self._current_dir = None | |
235 # Number of tests in self._current_dir. | |
236 self._num_tests_in_current_dir = None | |
237 # Time at which we started running tests from self._current_dir. | |
238 self._current_dir_start_time = None | |
239 | |
240 def GetDirectoryTimingStats(self): | |
241 """Returns a dictionary mapping test directory to a tuple of | |
242 (number of tests in that directory, time to run the tests)""" | |
243 return self._directory_timing_stats | |
244 | |
245 def GetIndividualTestStats(self): | |
246 """Returns a list of (test_filename, time_to_run_test, | |
247 total_time_for_all_diffs, time_for_diffs) tuples.""" | |
248 return self._test_stats | |
249 | |
250 def Cancel(self): | |
251 """Set a flag telling this thread to quit.""" | |
252 self._canceled = True | |
253 | |
254 def GetExceptionInfo(self): | |
255 """If run() terminated on an uncaught exception, return it here | |
256 ((type, value, traceback) tuple). | |
257 Returns None if run() terminated normally. Meant to be called after | |
258 joining this thread.""" | |
259 return self._exception_info | |
260 | |
261 def GetTotalTime(self): | |
262 return max(self._stop_time - self._start_time, 0.0) | |
263 | |
264 def GetNumTests(self): | |
265 return self._num_tests | |
266 | |
267 def run(self): | |
268 """Delegate main work to a helper method and watch for uncaught | |
269 exceptions.""" | |
270 self._start_time = time.time() | |
271 self._num_tests = 0 | |
272 try: | |
273 logging.debug('%s starting' % (self.getName())) | |
274 self._Run(test_runner=None, result_summary=None) | |
275 logging.debug('%s done (%d tests)' % (self.getName(), | |
276 self.GetNumTests())) | |
277 except: | |
278 # Save the exception for our caller to see. | |
279 self._exception_info = sys.exc_info() | |
280 self._stop_time = time.time() | |
281 # Re-raise it and die. | |
282 logging.error('%s dying: %s' % (self.getName(), | |
283 self._exception_info)) | |
284 raise | |
285 self._stop_time = time.time() | |
286 | |
287 def RunInMainThread(self, test_runner, result_summary): | |
288 """This hook allows us to run the tests from the main thread if | |
289 --num-test-shells==1, instead of having to always run two or more | |
290 threads. This allows us to debug the test harness without having to | |
291 do multi-threaded debugging.""" | |
292 self._Run(test_runner, result_summary) | |
293 | |
294 def _Run(self, test_runner, result_summary): | |
295 """Main work entry point of the thread. Basically we pull urls from the | |
296 filename queue and run the tests until we run out of urls. | |
297 | |
298 If test_runner is not None, then we call test_runner.UpdateSummary() | |
299 with the results of each test.""" | |
300 batch_size = 0 | |
301 batch_count = 0 | |
302 if self._options.batch_size: | |
303 try: | |
304 batch_size = int(self._options.batch_size) | |
305 except: | |
306 logging.info("Ignoring invalid batch size '%s'" % | |
307 self._options.batch_size) | |
308 | |
309 # Append tests we're running to the existing tests_run.txt file. | |
310 # This is created in run_webkit_tests.py:_PrepareListsAndPrintOutput. | |
311 tests_run_filename = os.path.join(self._options.results_directory, | |
312 "tests_run.txt") | |
313 tests_run_file = open(tests_run_filename, "a") | |
314 | |
315 while True: | |
316 if self._canceled: | |
317 logging.info('Testing canceled') | |
318 tests_run_file.close() | |
319 return | |
320 | |
321 if len(self._filename_list) is 0: | |
322 if self._current_dir is not None: | |
323 self._directory_timing_stats[self._current_dir] = \ | |
324 (self._num_tests_in_current_dir, | |
325 time.time() - self._current_dir_start_time) | |
326 | |
327 try: | |
328 self._current_dir, self._filename_list = \ | |
329 self._filename_list_queue.get_nowait() | |
330 except Queue.Empty: | |
331 self._KillTestShell() | |
332 tests_run_file.close() | |
333 return | |
334 | |
335 self._num_tests_in_current_dir = len(self._filename_list) | |
336 self._current_dir_start_time = time.time() | |
337 | |
338 test_info = self._filename_list.pop() | |
339 | |
340 # We have a url, run tests. | |
341 batch_count += 1 | |
342 self._num_tests += 1 | |
343 if self._options.run_singly: | |
344 failures = self._RunTestSingly(test_info) | |
345 else: | |
346 failures = self._RunTest(test_info) | |
347 | |
348 filename = test_info.filename | |
349 tests_run_file.write(filename + "\n") | |
350 if failures: | |
351 # Check and kill test shell if we need too. | |
352 if len([1 for f in failures if f.ShouldKillTestShell()]): | |
353 self._KillTestShell() | |
354 # Reset the batch count since the shell just bounced. | |
355 batch_count = 0 | |
356 # Print the error message(s). | |
357 error_str = '\n'.join([' ' + f.Message() for f in failures]) | |
358 logging.debug("%s %s failed:\n%s" % (self.getName(), | |
359 path_utils.RelativeTestFilename(filename), | |
360 error_str)) | |
361 else: | |
362 logging.debug("%s %s passed" % (self.getName(), | |
363 path_utils.RelativeTestFilename(filename))) | |
364 self._result_queue.put((filename, failures)) | |
365 | |
366 if batch_size > 0 and batch_count > batch_size: | |
367 # Bounce the shell and reset count. | |
368 self._KillTestShell() | |
369 batch_count = 0 | |
370 | |
371 if test_runner: | |
372 test_runner.UpdateSummary(result_summary) | |
373 | |
374 def _RunTestSingly(self, test_info): | |
375 """Run a test in a separate thread, enforcing a hard time limit. | |
376 | |
377 Since we can only detect the termination of a thread, not any internal | |
378 state or progress, we can only run per-test timeouts when running test | |
379 files singly. | |
380 | |
381 Args: | |
382 test_info: Object containing the test filename, uri and timeout | |
383 | |
384 Return: | |
385 A list of TestFailure objects describing the error. | |
386 """ | |
387 worker = SingleTestThread(self._test_shell_command, | |
388 self._shell_args, | |
389 test_info, | |
390 self._test_types, | |
391 self._test_args, | |
392 self._options.target, | |
393 self._options.results_directory) | |
394 | |
395 worker.start() | |
396 | |
397 # When we're running one test per test_shell process, we can enforce | |
398 # a hard timeout. the test_shell watchdog uses 2.5x the timeout | |
399 # We want to be larger than that. | |
400 worker.join(int(test_info.timeout) * 3.0 / 1000.0) | |
401 if worker.isAlive(): | |
402 # If join() returned with the thread still running, the | |
403 # test_shell.exe is completely hung and there's nothing | |
404 # more we can do with it. We have to kill all the | |
405 # test_shells to free it up. If we're running more than | |
406 # one test_shell thread, we'll end up killing the other | |
407 # test_shells too, introducing spurious crashes. We accept that | |
408 # tradeoff in order to avoid losing the rest of this thread's | |
409 # results. | |
410 logging.error('Test thread hung: killing all test_shells') | |
411 path_utils.KillAllTestShells() | |
412 | |
413 try: | |
414 stats = worker.GetTestStats() | |
415 self._test_stats.append(stats) | |
416 failures = stats.failures | |
417 except AttributeError, e: | |
418 failures = [] | |
419 logging.error('Cannot get results of test: %s' % | |
420 test_info.filename) | |
421 | |
422 return failures | |
423 | |
424 def _RunTest(self, test_info): | |
425 """Run a single test file using a shared test_shell process. | |
426 | |
427 Args: | |
428 test_info: Object containing the test filename, uri and timeout | |
429 | |
430 Return: | |
431 A list of TestFailure objects describing the error. | |
432 """ | |
433 self._EnsureTestShellIsRunning() | |
434 # Args to test_shell is a space-separated list of | |
435 # "uri timeout pixel_hash" | |
436 # The timeout and pixel_hash are optional. The timeout is used if this | |
437 # test has a custom timeout. The pixel_hash is used to avoid doing an | |
438 # image dump if the checksums match, so it should be set to a blank | |
439 # value if we are generating a new baseline. | |
440 # (Otherwise, an image from a previous run will be copied into | |
441 # the baseline.) | |
442 image_hash = test_info.image_hash | |
443 if image_hash and self._test_args.new_baseline: | |
444 image_hash = "" | |
445 self._test_shell_proc.stdin.write(("%s %s %s\n" % | |
446 (test_info.uri, test_info.timeout, image_hash))) | |
447 | |
448 # If the test shell is dead, the above may cause an IOError as we | |
449 # try to write onto the broken pipe. If this is the first test for | |
450 # this test shell process, than the test shell did not | |
451 # successfully start. If this is not the first test, then the | |
452 # previous tests have caused some kind of delayed crash. We don't | |
453 # try to recover here. | |
454 self._test_shell_proc.stdin.flush() | |
455 | |
456 stats = ProcessOutput(self._test_shell_proc, test_info, | |
457 self._test_types, self._test_args, | |
458 self._options.target, | |
459 self._options.results_directory) | |
460 | |
461 self._test_stats.append(stats) | |
462 return stats.failures | |
463 | |
464 def _EnsureTestShellIsRunning(self): | |
465 """Start the shared test shell, if it's not running. Not for use when | |
466 running tests singly, since those each start a separate test shell in | |
467 their own thread. | |
468 """ | |
469 if (not self._test_shell_proc or | |
470 self._test_shell_proc.poll() is not None): | |
471 self._test_shell_proc = StartTestShell(self._test_shell_command, | |
472 self._shell_args) | |
473 | |
474 def _KillTestShell(self): | |
475 """Kill the test shell process if it's running.""" | |
476 if self._test_shell_proc: | |
477 self._test_shell_proc.stdin.close() | |
478 self._test_shell_proc.stdout.close() | |
479 if self._test_shell_proc.stderr: | |
480 self._test_shell_proc.stderr.close() | |
481 if (sys.platform not in ('win32', 'cygwin') and | |
482 not self._test_shell_proc.poll()): | |
483 # Closing stdin/stdout/stderr hangs sometimes on OS X. | |
484 null = open(os.devnull, "w") | |
485 subprocess.Popen(["kill", "-9", | |
486 str(self._test_shell_proc.pid)], stderr=null) | |
487 null.close() | |
488 self._test_shell_proc = None | |
OLD | NEW |