1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19 """
20 Contains the base class used to perform the execution and audit trail reporting of a set of tests.
21
22 Test selection is by default performed through the pysys.py launch script, which locates and
23 creates a set of class instances representing the tests to be executed. These are passed to the
24 base runner as a list of object references, so that the base runner can then iterate through the
25 list to perform the test execution. For more information see the L{pysys.baserunner.BaseRunner}
26 API documentation.
27
28 """
29 import os, os.path, sys, stat, re, traceback, time, math, logging, string, thread, threading, imp
30
31 from pysys import log, ThreadedFileHandler
32 from pysys.constants import *
33 from pysys.exceptions import *
34 from pysys.utils.threadpool import *
35 from pysys.utils.loader import import_module
36 from pysys.utils.filecopy import filecopy
37 from pysys.utils.filegrep import filegrep
38 from pysys.utils.filediff import filediff
39 from pysys.utils.filegrep import orderedgrep
40 from pysys.utils.linecount import linecount
41 from pysys.process.helper import ProcessWrapper
42 from pysys.basetest import BaseTest
43 from pysys.process.user import ProcessUser
44
45 global_lock = threading.Lock()
46
47 N_CPUS = 1
48 try:
49
50 import multiprocessing
51 N_CPUS = multiprocessing.cpu_count()
52 except ImportError:
53 pass
54
56 """The base class for executing a set of PySys testcases.
57
58 BaseRunner is the parent class for running a set of PySys system testcases. The runner is instantiated
59 with a list of L{pysys.xml.descriptor.XMLDescriptorContainer} objects detailing the set of testcases to be run.
60 The runner iterates through the descriptor list and for each entry imports the L{pysys.basetest.BaseTest}
61 subclass for the testcase, creates an instance of the test class and then calls the setup, execute, validate
62 and cleanup methods of the test class instance. The runner is responsible for ensuring the output
63 subdirectory of each testcase is purged prior to test execution to remove stale output from a previous run,
64 detects any core files produced during execution of a testcase from processes started via the L{pysys.process}
65 module, and performs audit trail logging of the test results on completion of running a set of testcases.
66
67 The base runner contains the hook functions L{setup}, L{testComplete}, L{cycleComplete} and L{cleanup} to
68 allow a subclass to perform custom operations prior to the execution of a set of testcases, between the
69 execution of each testcase in a set, between each cycle of execution of a set of testcases, and on completion
70 of all testcases respectively. Subclasses are typically used should some global conditions need to be setup
71 prior to the set of testcasess being run (i.e. load data into a shared database, start an external process
72 etc), and subsequently cleaned up after test execution.
73
74 @ivar mode: The user defined modes to run the tests within
75 @type mode: string
76 @ivar outsubdir: The directory name for the output subdirectory
77 @type outsubdir: string
78 @ivar log: Reference to the logger instance of this class
79 @type log: logging.Logger
80 @ivar project: Reference to the project details as set on the module load of the launching executable
81 @type project: L{Project}
82
83 """
84
85 - def __init__(self, record, purge, cycle, mode, threads, outsubdir, descriptors, xargs):
86 """Create an instance of the BaseRunner class.
87
88 @param record: Indicates if the test results should be recorded
89 @param purge: Indicates if the output subdirectory should be purged on C{PASSED} result
90 @param cycle: The number of times to execute the set of requested testcases
91 @param mode: The user defined mode to run the testcases in
92 @param threads: The number of worker threads to execute the requested testcases
93 @param outsubdir: The name of the output subdirectory
94 @param descriptors: List of XML descriptor containers detailing the set of testcases to be run
95 @param xargs: The dictionary of additional arguments to be set as data attributes to the class
96
97 """
98 ProcessUser.__init__(self)
99 self.record = record
100 self.purge = purge
101 self.cycle = cycle
102 self.mode = mode
103 self.threads = threads
104 self.outsubdir = outsubdir
105 self.descriptors = descriptors
106 self.xargs = xargs
107 self.setKeywordArgs(xargs)
108 self.log = log
109 self.project = PROJECT
110
111 if self.threads == 0:
112 self.threads = N_CPUS
113
114 self.writers = []
115 for classname, module, filename, properties in PROJECT.writers:
116 module = import_module(module, sys.path)
117 writer = getattr(module, classname)(filename)
118 for key in properties.keys(): setattr(writer, key, properties[key])
119 self.writers.append(writer)
120
121 self.duration = 0
122 self.results = {}
123 self.resultsPointer = 0
124 self.resultsQueue = []
125
126
128 """Set the xargs as data attributes of the class.
129
130 Values in the xargs dictionary are set as data attributes using the builtin C{setattr()} method.
131 Thus an xargs dictionary of the form C{{'foo': 'bar'}} will result in a data attribute of the
132 form C{self.foo} with C{value bar}.
133
134 @param xargs: A dictionary of the user defined extra arguments
135
136 """
137 for key in xargs.keys():
138 setattr(self, key, xargs[key])
139
140
141
142
144 """Setup method which may optionally be overridden to perform custom setup operations prior to execution of a set of testcases.
145
146 """
147 pass
148
149
151 """Test complete method which performs completion actions after execution of a testcase.
152
153 The testComplete method performs purging of the output subdirectory of a testcase on completion
154 of the test execution. Purging involves removing all files with a zero file length in order to
155 only include files with content of interest. Should C{self.purge} be set, the purging will remove
156 all files (excluding the run.log) on a C{PASSED} outcome of the testcase in order to reduce the
157 on-disk memory footprint when running a large number of tests. Should a custom testComplete for
158 a subclass be required, the BaseRunner testComplete method should first be called.
159
160 @param testObj: Reference to the L{pysys.basetest.BaseTest} instance of the test just completed
161 @param dir: The directory to perform the purge on
162
163 """
164 if self.purge:
165 removeNonZero = True
166 for outcome in testObj.outcome:
167 if outcome != PASSED:
168 removeNonZero = False
169 break
170 else:
171 removeNonZero = False
172
173 try:
174 for file in os.listdir(dir):
175 path = "%s/%s" % (dir, file)
176 if PLATFORM in ['sunos', 'linux']:
177 size = os.lstat(path)[stat.ST_SIZE]
178 else:
179 size = os.stat(path)[stat.ST_SIZE]
180
181 if (size == 0) or (removeNonZero and not re.search('run.log', file)):
182 count = 0
183 while count < 3:
184 try:
185 os.remove(path)
186 break
187 except:
188 time.sleep(0.1)
189 count = count + 1
190
191 except OSError as ex:
192 log.warning("Caught OSError while cleaning output directory:")
193 log.warning(ex)
194 log.warning("Output directory may not be completely clean")
195
197 """Cycle complete method which may optionally be overridden to perform custom operations between the repeated execution of a set of testcases.
198
199 """
200 pass
201
202
204 """Cleanup method which may optionally be overridden to perform custom cleanup operations after execution of all testcases.
205
206 """
207 ProcessUser.__del__(self)
208
209
210
211 - def start(self, printSummary=True):
212 """Start the execution of a set of testcases, returning a dictionary of the testcase outcomes.
213
214 The start method is the main method for executing the set of requested testcases. The set of testcases
215 are executed a number of times determined by the C{self.cycle} attribute. When executing a testcase
216 all output from the execution is saved in the testcase output subdirectory; should C{self.cycle} be
217 set to more than 1, the output subdirectory is further split into cycle[n] directories to sandbox the
218 output from each iteration.
219
220 @param printSummary: Indicates if the test results should be reported on test completion
221
222 """
223
224 self.setup()
225
226
227 if self.record:
228 for writer in self.writers:
229 try: writer.setup(numTests=self.cycle * len(self.descriptors), xargs=self.xargs)
230 except: log.warn("caught %s: %s", sys.exc_info()[0], sys.exc_info()[1], exc_info=1)
231
232
233 if self.threads > 1: threadPool = ThreadPool(self.threads)
234
235
236 self.startTime = time.time()
237 for cycle in range(self.cycle):
238
239 try:
240 self.resultsPointer = 0
241 self.resultsQueue = []
242 self.results[cycle] = {}
243 for outcome in PRECEDENT: self.results[cycle][outcome] = []
244
245 counter = 0
246 for descriptor in self.descriptors:
247 self.resultsQueue.append(None)
248 container = TestContainer(counter, descriptor, cycle, self)
249 if self.threads > 1:
250 request = WorkRequest(container, callback=self.containerCallback, exc_callback=self.containerExceptionCallback)
251 threadPool.putRequest(request)
252 else:
253 self.containerCallback(thread.get_ident(), container())
254 counter = counter + 1
255 except KeyboardInterrupt:
256 log.info("test interrupt from keyboard")
257 self.handleKbrdInt()
258
259
260 if self.threads > 1:
261 try:
262 threadPool.wait()
263 except KeyboardInterrupt:
264 log.info("test interrupt from keyboard - joining threads ... ")
265 threadPool.dismissWorkers(self.threads, True)
266 self.handleKbrdInt(prompt=False)
267
268
269 try:
270 self.cycleComplete()
271 except KeyboardInterrupt:
272 log.info("test interrupt from keyboard")
273 self.handleKbrdInt()
274 except:
275 log.warn("caught %s: %s", sys.exc_info()[0], sys.exc_info()[1], exc_info=1)
276
277
278 if self.record:
279 for writer in self.writers:
280 try: writer.cleanup()
281 except: log.warn("caught %s: %s", sys.exc_info()[0], sys.exc_info()[1], exc_info=1)
282
283
284 if printSummary: self.printSummary()
285
286
287 self.cleanup()
288
289
290 return self.results
291
292
294 """Print the output summary at the completion of a test run.
295
296 """
297 log.critical("")
298 if self.threads > 1:
299 log.critical("Test duration (absolute): %.2f (secs)", time.time() - self.startTime)
300 log.critical("Test duration (additive): %.2f (secs)", self.duration)
301 else:
302 log.critical("Test duration: %.2f (secs)", time.time() - self.startTime)
303 log.critical("")
304 log.critical("Summary of non passes: ")
305 fails = 0
306 for cycle in self.results.keys():
307 for outcome in self.results[cycle].keys():
308 if outcome in FAILS : fails = fails + len(self.results[cycle][outcome])
309 if fails == 0:
310 log.critical(" THERE WERE NO NON PASSES")
311 else:
312 if len(self.results) == 1:
313 for outcome in FAILS:
314 for id in self.results[0][outcome]: log.critical(" %s: %s ", LOOKUP[outcome], id)
315 else:
316 for key in self.results.keys():
317 for outcome in FAILS:
318 for id in self.results[key][outcome]: log.critical(" [CYCLE %d] %s: %s ", key+1, LOOKUP[outcome], id)
319
320
322 """Callback method on completion of running a test.
323
324 @param container: A reference to the container object that ran the test
325
326 Called on completion of running a testcase, either directly by the BaseRunner class (or
327 a sub-class thereof), or from the ThreadPool when running with more than one worker thread.
328 The method is responsible for calling of the testComplete() method of the runner, recording
329 of the test result to the result writers, and for deletion of the test container object.
330
331 """
332 self.resultsQueue[container.counter] = container
333 if self.threads > 1: self.log.info("[%s] Queueing result for test %s" % (thread, container.descriptor.id))
334
335 spacer = True
336 for i in range(self.resultsPointer, len(self.resultsQueue)):
337 if self.resultsQueue[i] is None: break
338
339 if self.threads > 1:
340 if spacer: self.log.info(""); spacer = False
341 try:
342 for line in self.resultsQueue[i].testFileHandler.getBuffer(): self.log.info(line)
343 except:
344 pass
345 if stdoutHandler.level >= logging.WARN: log.critical("%s: %s", LOOKUP[self.resultsQueue[i].testObj.getOutcome()], self.resultsQueue[i].descriptor.id)
346
347
348 self.testComplete(self.resultsQueue[i].testObj, self.resultsQueue[i].outsubdir)
349
350
351 if self.record:
352 for writer in self.writers:
353 try: writer.processResult(self.resultsQueue[i].testObj, cycle=self.resultsQueue[i].cycle)
354 except: log.warn("caught %s: %s", sys.exc_info()[0], sys.exc_info()[1], exc_info=1)
355
356
357 if self.resultsQueue[i].kbrdInt == True: self.handleKbrdInt()
358
359
360 self.duration = self.duration + self.resultsQueue[i].testTime
361 self.results[self.resultsQueue[i].cycle][self.resultsQueue[i].testObj.getOutcome()].append(self.resultsQueue[i].descriptor.id)
362
363
364 self.resultsQueue[i] = None
365 self.resultsPointer = self.resultsPointer + 1
366
367
369 """Callback method for unhandled exceptions thrown when running a test.
370
371 @param exc_info: The tuple of values as created from sys.exc_info()
372
373 """
374 log.warn("caught %s: %s", exc_info[0], exc_info[1], exc_info=exc_info)
375
376
378 """Handle a keyboard exception caught during running of a set of testcases.
379
380 """
381 try:
382 if not prompt:
383 print "Keyboard interrupt detected, exiting ... "
384 self.printSummary()
385 self.cycleComplete()
386 self.cleanup()
387 sys.exit(1)
388
389 while 1:
390 print ""
391 print "Keyboard interrupt detected, continue running tests? [yes|no] ... ",
392 line = sys.stdin.readline().strip()
393 if line == "y" or line == "yes":
394 break
395 elif line == "n" or line == "no":
396 self.printSummary()
397 self.cycleComplete()
398 self.cleanup()
399 sys.exit(1)
400 except KeyboardInterrupt:
401 self.handleKbrdInt(prompt)
402
403
405 """Class used for co-ordinating the execution of a single test case.
406
407 """
408
409 - def __init__ (self, counter, descriptor, cycle, runner):
410 """Create an instance of the TestContainer class.
411
412 @param descriptor: A reference to the testcase descriptor
413 @param cycle: The cycle number of the test
414 @param runner: A reference to the runner that created this class
415
416 """
417 self.counter = counter
418 self.descriptor = descriptor
419 self.cycle = cycle
420 self.runner = runner
421 self.outsubdir = ""
422 self.testObj = None
423 self.testTime = None
424 self.testBuffer = []
425 self.testFileHandler = None
426 self.kbrdInt = False
427
428
430 """Over-ridden call builtin to allow the class instance to be called directly.
431
432 """
433 exc_info = []
434 testTime = time.time()
435 try:
436
437 outsubdir = self.runner.outsubdir
438 if not os.path.exists(os.path.join(self.descriptor.output, outsubdir)):
439 os.makedirs(os.path.join(self.descriptor.output, outsubdir))
440
441 if self.cycle == 0: self.purgeDirectory(os.path.join(self.descriptor.output, outsubdir))
442
443 if self.runner.cycle > 1:
444 outsubdir = os.path.join(outsubdir, 'cycle%d' % (self.cycle+1))
445 os.makedirs(os.path.join(self.descriptor.output, outsubdir))
446
447 self.outsubdir = os.path.join(self.descriptor.output, outsubdir)
448
449
450 self.testFileHandler = ThreadedFileHandler(os.path.join(self.outsubdir, 'run.log'))
451 self.testFileHandler.setFormatter(PROJECT.formatters.runlog)
452 self.testFileHandler.setLevel(logging.INFO)
453 if stdoutHandler.level == logging.DEBUG: self.testFileHandler.setLevel(logging.DEBUG)
454 log.addHandler(self.testFileHandler)
455 log.info(42*"="); log.info("%s%s"%(8*" ", self.descriptor.id)); log.info(42*"=")
456
457 except KeyboardInterrupt:
458 self.kbrdInt = True
459
460 except:
461 exc_info.append(sys.exc_info())
462
463
464 global_lock.acquire()
465 try:
466 module = import_module(os.path.basename(self.descriptor.module), [os.path.dirname(self.descriptor.module)], True)
467 self.testObj = getattr(module, self.descriptor.classname)(self.descriptor, self.outsubdir, self.runner)
468
469 except KeyboardInterrupt:
470 self.kbrdInt = True
471
472 except:
473 exc_info.append(sys.exc_info())
474 self.testObj = BaseTest(self.descriptor, self.outsubdir, self.runner)
475 global_lock.release()
476
477
478 try:
479 if self.descriptor.state != 'runnable':
480 self.testObj.addOutcome(SKIPPED)
481
482 elif self.runner.mode and self.runner.mode not in self.descriptor.modes:
483 log.warn("Unable to run test in %s mode", self.runner.mode)
484 self.testObj.addOutcome(SKIPPED)
485
486 elif len(exc_info) > 0:
487 self.testObj.addOutcome(BLOCKED)
488 for info in exc_info:
489 log.warn("caught %s: %s", info[0], info[1], exc_info=info)
490
491 elif self.kbrdInt:
492 log.warn("test interrupt from keyboard")
493 self.testObj.addOutcome(BLOCKED)
494
495 else:
496 self.testObj.setup()
497 self.testObj.execute()
498 self.testObj.validate()
499 if self.detectCore(self.outsubdir):
500 log.warn("core detected in output subdirectory")
501 self.testObj.addOutcome(DUMPEDCORE)
502
503 except KeyboardInterrupt:
504 self.kbrdInt = True
505 log.warn("test interrupt from keyboard")
506 self.testObj.addOutcome(BLOCKED)
507
508 except:
509 log.warn("caught %s: %s", sys.exc_info()[0], sys.exc_info()[1], exc_info=1)
510 self.testObj.addOutcome(BLOCKED)
511
512
513
514 try:
515 self.testObj.cleanup()
516
517 except KeyboardInterrupt:
518 self.kbrdInt = True
519 log.warn("test interrupt from keyboard")
520 self.testObj.addOutcome(BLOCKED)
521
522
523 try:
524 self.testTime = math.floor(100*(time.time() - testTime))/100.0
525 log.info("")
526 log.info("Test duration %.2f secs", self.testTime)
527 log.info("Test final outcome %s", LOOKUP[self.testObj.getOutcome()])
528 log.info("")
529
530 self.testFileHandler.close()
531 log.removeHandler(self.testFileHandler)
532 except:
533 pass
534
535
536 return self
537
538
539
541 """Recursively purge a directory removing all files and sub-directories.
542
543 @param dir: The top level directory to be purged
544 @param delTop: Indicates if the top level directory should also be deleted
545
546 """
547 try:
548 for file in os.listdir(dir):
549 path = os.path.join(dir, file)
550 if PLATFORM in ['sunos', 'linux']:
551 mode = os.lstat(path)[stat.ST_MODE]
552 else:
553 mode = os.stat(path)[stat.ST_MODE]
554
555 if stat.S_ISLNK(mode):
556 os.unlink(path)
557 if stat.S_ISREG(mode):
558 os.remove(path)
559 elif stat.S_ISDIR(mode):
560 self.purgeDirectory(path, delTop=True)
561 if delTop: os.rmdir(dir)
562
563 except OSError as ex:
564 log.warning("Caught OSError in purgeDirectory():")
565 log.warning(ex)
566 log.warning("Directory %s may not be completely purged" % dir)
567
568
570 """Detect any core files in a directory (unix systems only), returning C{True} if a core is present.
571
572 @param dir: The directory to search for core files
573 @return: C{True} if a core detected, None if no core detected
574 @rtype: integer
575 """
576 try:
577 for file in os.listdir(dir):
578 path = os.path.join(dir, file)
579 mode = os.stat(path)[stat.ST_MODE]
580 if stat.S_ISREG(mode):
581 if re.search('^core', file): return True
582
583 except OSError as ex:
584 log.warning("Caught OSError in detectCore():")
585 log.warning(ex)
586