rosunit.baretest

1 # Software License Agreement (BSD License) 2 # 3 # Copyright (c) 2010, Willow Garage, Inc. 4 # All rights reserved. 5 # 6 # Redistribution and use in source and binary forms, with or without 7 # modification, are permitted provided that the following conditions 8 # are met: 9 # 10 # * Redistributions of source code must retain the above copyright 11 # notice, this list of conditions and the following disclaimer. 12 # * Redistributions in binary form must reproduce the above 13 # copyright notice, this list of conditions and the following 14 # disclaimer in the documentation and/or other materials provided 15 # with the distribution. 16 # * Neither the name of Willow Garage, Inc. nor the names of its 17 # contributors may be used to endorse or promote products derived 18 # from this software without specific prior written permission. 19 # 20 # THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS 21 # "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT 22 # LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS 23 # FOR A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE 24 # COPYRIGHT OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, 25 # INCIDENTAL, SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, 26 # BUT NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; 27 # LOSS OF USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER 28 # CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT 29 # LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN 30 # ANY WAY OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE 31 # POSSIBILITY OF SUCH DAMAGE. 32 # 33 # Revision $Id: baretest.py 15181 2011-10-11 20:21:22Z kwc $ 34 35 """ 36 rostest implementation of running bare (gtest-compatible) unit test 37 executables. These do not run in a ROS environment. 38 """ 39 40 import os 41 import cStringIO 42 import unittest 43 import logging 44 import time 45 import signal 46 import subprocess 47 import traceback 48 49 import roslib.packages 50 51 from .core import xml_results_file, rostest_name_from_path, create_xml_runner, printlog, printerrlog, printlog_bold 52 53 from . import pmon 54 from . import junitxml 55 56 _logger = logging.getLogger('rosunit') 57 58 BARE_TIME_LIMIT = 60. 59 TIMEOUT_SIGINT = 15.0 #seconds 60 TIMEOUT_SIGTERM = 2.0 #seconds 61

62 -class TestTimeoutException(Exception): pass

63

64 -class BareTestCase(unittest.TestCase):

65

66 - def __init__(self, exe, args, retry=0, time_limit=None, test_name=None, text_mode=False):

67 """ 68 @param exe: path to executable to run 69 @type exe: str 70 @param args: arguments to exe 71 @type args: [str] 72 @type retry: int 73 @param time_limit: (optional) time limit for test. Defaults to BARE_TIME_LIMIT. 74 @type time_limit: float 75 @param test_name: (optional) override automatically generated test name 76 @type test_name: str 77 """ 78 super(BareTestCase, self).__init__() 79 self.text_mode = text_mode 80 _, self.package = roslib.packages.get_dir_pkg(exe) 81 self.exe = os.path.abspath(exe) 82 if test_name is None: 83 self.test_name = os.path.basename(exe) 84 else: 85 self.test_name = test_name 86 87 # invoke pyunit tests with python executable 88 if self.exe.endswith('.py'): 89 self.args = ['python', self.exe] + args 90 else: 91 self.args = [self.exe] + args 92 if text_mode: 93 self.args = self.args + ['--text'] 94 95 self.retry = retry 96 self.time_limit = time_limit or BARE_TIME_LIMIT 97 self.pmon = None 98 self.results = junitxml.Result(self.test_name)

99

100 - def setUp(self):

101 self.pmon = pmon.start_process_monitor()

102

103 - def tearDown(self):

104 if self.pmon is not None: 105 pmon.shutdown_process_monitor(self.pmon) 106 self.pmon = None

107

108 - def runTest(self):

109 self.failIf(self.package is None, "unable to determine package of executable") 110 111 done = False 112 while not done: 113 test_name = self.test_name 114 115 printlog("Running test [%s]", test_name) 116 117 #setup the test 118 # - we pass in the output test_file name so we can scrape it 119 test_file = xml_results_file(self.package, test_name, False) 120 if os.path.exists(test_file): 121 printlog("removing previous test results file [%s]", test_file) 122 os.remove(test_file) 123 124 self.args.append('--gtest_output=xml:%s'%test_file) 125 126 # run the test, blocks until completion 127 printlog("running test %s"%test_name) 128 timeout_failure = False 129 130 run_id = None 131 #TODO: really need different, non-node version of LocalProcess instead of these extra args 132 process = LocalProcess(run_id, self.package, self.test_name, self.args, os.environ, False, cwd='cwd', is_node=False) 133 134 pm = self.pmon 135 pm.register(process) 136 success = process.start() 137 self.assert_(success, "test failed to start") 138 139 #poll until test terminates or alloted time exceed 140 timeout_t = time.time() + self.time_limit 141 try: 142 while process.is_alive(): 143 #test fails on timeout 144 if time.time() > timeout_t: 145 raise TestTimeoutException("test max time allotted") 146 time.sleep(0.1) 147 148 except TestTimeoutException, e: 149 if self.retry: 150 timeout_failure = True 151 else: 152 raise 153 154 if not timeout_failure: 155 printlog("test [%s] finished"%test_name) 156 else: 157 printerrlog("test [%s] timed out"%test_name) 158 159 160 if self.text_mode: 161 results = self.results 162 elif not self.text_mode: 163 # load in test_file 164 if not timeout_failure: 165 self.assert_(os.path.isfile(test_file), "test [%s] did not generate test results"%test_name) 166 printlog("test [%s] results are in [%s]", test_name, test_file) 167 results = junitxml.read(test_file, test_name) 168 test_fail = results.num_errors or results.num_failures 169 else: 170 test_fail = True 171 172 if self.retry > 0 and test_fail: 173 self.retry -= 1 174 printlog("test [%s] failed, retrying. Retries left: %s"%(test_name, self.retry)) 175 else: 176 done = True 177 self.results = results 178 printlog("test [%s] results summary: %s errors, %s failures, %s tests", 179 test_name, results.num_errors, results.num_failures, results.num_tests) 180 181 printlog("[ROSTEST] test [%s] done", test_name)

182 183 184 #TODO: this is a straight copy from roslaunch. Need to reduce, refactor

185 -class LocalProcess(pmon.Process):

186 """ 187 Process launched on local machine 188 """ 189

190 - def __init__(self, run_id, package, name, args, env, log_output, respawn=False, required=False, cwd=None, is_node=True):

191 """ 192 @param run_id: unique run ID for this roslaunch. Used to 193 generate log directory location. run_id may be None if this 194 feature is not being used. 195 @type run_id: str 196 @param package: name of package process is part of 197 @type package: str 198 @param name: name of process 199 @type name: str 200 @param args: list of arguments to process 201 @type args: [str] 202 @param env: environment dictionary for process 203 @type env: {str : str} 204 @param log_output: if True, log output streams of process 205 @type log_output: bool 206 @param respawn: respawn process if it dies (default is False) 207 @type respawn: bool 208 @param cwd: working directory of process, or None 209 @type cwd: str 210 @param is_node: (optional) if True, process is ROS node and accepts ROS node command-line arguments. Default: True 211 @type is_node: False 212 """ 213 super(LocalProcess, self).__init__(package, name, args, env, respawn, required) 214 self.run_id = run_id 215 self.popen = None 216 self.log_output = log_output 217 self.started = False 218 self.stopped = False 219 self.cwd = cwd 220 self.log_dir = None 221 self.pid = -1 222 self.is_node = is_node

223 224 # NOTE: in the future, info() is going to have to be sufficient for relaunching a process

225 - def get_info(self):

226 """ 227 Get all data about this process in dictionary form 228 """ 229 info = super(LocalProcess, self).get_info() 230 info['pid'] = self.pid 231 if self.run_id: 232 info['run_id'] = self.run_id 233 info['log_output'] = self.log_output 234 if self.cwd is not None: 235 info['cwd'] = self.cwd 236 return info

237

238 - def _configure_logging(self):

239 """ 240 Configure logging of node's log file and stdout/stderr 241 @return: stdout log file name, stderr log file 242 name. Values are None if stdout/stderr are not logged. 243 @rtype: str, str 244 """ 245 log_dir = roslib.rosenv.get_log_dir(env=os.environ) 246 if self.run_id: 247 log_dir = os.path.join(log_dir, self.run_id) 248 if not os.path.exists(log_dir): 249 try: 250 os.makedirs(log_dir) 251 except OSError, (errno, msg): 252 if errno == 13: 253 raise RLException("unable to create directory for log file [%s].\nPlease check permissions."%log_dir) 254 else: 255 raise RLException("unable to create directory for log file [%s]: %s"%(log_dir, msg)) 256 # #973: save log dir for error messages 257 self.log_dir = log_dir 258 259 # send stdout/stderr to file. in the case of respawning, we have to 260 # open in append mode 261 # note: logfileerr: disabling in favor of stderr appearing in the console. 262 # will likely reinstate once roserr/rosout is more properly used. 263 logfileout = logfileerr = None 264 265 if self.log_output: 266 outf, errf = [os.path.join(log_dir, '%s-%s.log'%(self.name, n)) for n in ['stdout', 'stderr']] 267 if self.respawn: 268 mode = 'a' 269 else: 270 mode = 'w' 271 logfileout = open(outf, mode) 272 if is_child_mode(): 273 logfileerr = open(errf, mode) 274 275 # #986: pass in logfile name to node 276 node_log_file = log_dir 277 if self.is_node: 278 # #1595: on respawn, these keep appending 279 self.args = _cleanup_remappings(self.args, '__log:=') 280 self.args.append("__log:=%s"%os.path.join(log_dir, "%s.log"%self.name)) 281 282 return logfileout, logfileerr

283

284 - def start(self):

285 """ 286 Start the process. 287 288 @raise pmon.FatalProcessLaunch: if process cannot be started and it 289 is not likely to ever succeed 290 """ 291 super(LocalProcess, self).start() 292 try: 293 self.lock.acquire() 294 if self.started: 295 _logger.info("process[%s]: restarting os process", self.name) 296 else: 297 _logger.info("process[%s]: starting os process", self.name) 298 self.started = self.stopped = False 299 300 full_env = self.env 301 302 # _configure_logging() can mutate self.args 303 try: 304 logfileout, logfileerr = self._configure_logging() 305 except Exception, e: 306 _logger.error(traceback.format_exc()) 307 printerrlog("[%s] ERROR: unable to configure logging [%s]"%(self.name, str(e))) 308 # it's not safe to inherit from this process as 309 # rostest changes stdout to a StringIO, which is not a 310 # proper file. 311 logfileout, logfileerr = subprocess.PIPE, subprocess.PIPE 312 313 if self.cwd == 'node': 314 cwd = os.path.dirname(self.args[0]) 315 elif self.cwd == 'cwd': 316 cwd = os.getcwd() 317 elif self.cwd == 'ros-root': 318 cwd = get_ros_root() 319 else: 320 cwd = roslib.rosenv.get_ros_home() 321 322 _logger.info("process[%s]: start w/ args [%s]", self.name, self.args) 323 _logger.info("process[%s]: cwd will be [%s]", self.name, cwd) 324 325 try: 326 self.popen = subprocess.Popen(self.args, cwd=cwd, stdout=logfileout, stderr=logfileerr, env=full_env, close_fds=True, preexec_fn=os.setsid) 327 except OSError, (errno, msg): 328 self.started = True # must set so is_alive state is correct 329 _logger.error("OSError(%d, %s)", errno, msg) 330 if errno == 8: #Exec format error 331 raise pmon.FatalProcessLaunch("Unable to launch [%s]. \nIf it is a script, you may be missing a '#!' declaration at the top."%self.name) 332 elif errno == 2: #no such file or directory 333 raise pmon.FatalProcessLaunch("""Roslaunch got a '%s' error while attempting to run: 334 335 %s 336 337 Please make sure that all the executables in this command exist and have 338 executable permission. This is often caused by a bad launch-prefix."""%(msg, ' '.join(self.args))) 339 else: 340 raise pmon.FatalProcessLaunch("unable to launch [%s]: %s"%(' '.join(self.args), msg)) 341 342 self.started = True 343 # Check that the process is either still running (poll returns 344 # None) or that it completed successfully since when we 345 # launched it above (poll returns the return code, 0). 346 poll_result = self.popen.poll() 347 if poll_result is None or poll_result == 0: 348 self.pid = self.popen.pid 349 printlog_bold("process[%s]: started with pid [%s]"%(self.name, self.pid)) 350 return True 351 else: 352 printerrlog("failed to start local process: %s"%(' '.join(self.args))) 353 return False 354 finally: 355 self.lock.release()

356

357 - def is_alive(self):

358 """ 359 @return: True if process is still running 360 @rtype: bool 361 """ 362 if not self.started: #not started yet 363 return True 364 if self.stopped or self.popen is None: 365 return False 366 self.exit_code = self.popen.poll() 367 if self.exit_code is not None: 368 return False 369 return True

370

371 - def get_exit_description(self):

372 """ 373 @return: human-readable description of exit state 374 @rtype: str 375 """ 376 # #973: include location of output location in message 377 if self.exit_code is not None: 378 if self.exit_code: 379 if self.log_dir: 380 return 'process has died [pid %s, exit code %s].\nlog files: %s*.log'%(self.pid, self.exit_code, os.path.join(self.log_dir, self.name)) 381 else: 382 return 'process has died [pid %s, exit code %s]'%(self.pid, self.exit_code) 383 else: 384 if self.log_dir: 385 return 'process has finished cleanly.\nlog file: %s*.log'%(os.path.join(self.log_dir, self.name)) 386 else: 387 return 'process has finished cleanly' 388 else: 389 return 'process has died'

390

391 - def _stop_unix(self, errors):

392 """ 393 UNIX implementation of process killing 394 395 @param errors: error messages. stop() will record messages into this list. 396 @type errors: [str] 397 """ 398 self.exit_code = self.popen.poll() 399 if self.exit_code is not None: 400 _logger.debug("process[%s].stop(): process has already returned %s", self.name, self.exit_code) 401 #print "process[%s].stop(): process has already returned %s"%(self.name, self.exit_code) 402 self.popen = None 403 self.stopped = True 404 return 405 406 pid = self.popen.pid 407 pgid = os.getpgid(pid) 408 _logger.info("process[%s]: killing os process with pid[%s] pgid[%s]", self.name, pid, pgid) 409 410 try: 411 # Start with SIGINT and escalate from there. 412 _logger.info("[%s] sending SIGINT to pgid [%s]", self.name, pgid) 413 os.killpg(pgid, signal.SIGINT) 414 _logger.info("[%s] sent SIGINT to pgid [%s]", self.name, pgid) 415 timeout_t = time.time() + TIMEOUT_SIGINT 416 retcode = self.popen.poll() 417 while time.time() < timeout_t and retcode is None: 418 time.sleep(0.1) 419 retcode = self.popen.poll() 420 # Escalate non-responsive process 421 if retcode is None: 422 printerrlog("[%s] escalating to SIGTERM"%self.name) 423 timeout_t = time.time() + TIMEOUT_SIGTERM 424 os.killpg(pgid, signal.SIGTERM) 425 _logger.info("[%s] sent SIGTERM to pgid [%s]"%(self.name, pgid)) 426 retcode = self.popen.poll() 427 while time.time() < timeout_t and retcode is None: 428 time.sleep(0.2) 429 _logger.debug('poll for retcode') 430 retcode = self.popen.poll() 431 if retcode is None: 432 printerrlog("[%s] escalating to SIGKILL"%self.name) 433 errors.append("process[%s, pid %s]: required SIGKILL. May still be running."%(self.name, pid)) 434 try: 435 os.killpg(pgid, signal.SIGKILL) 436 _logger.info("[%s] sent SIGKILL to pgid [%s]"%(self.name, pgid)) 437 # #2096: don't block on SIGKILL, because this results in more orphaned processes overall 438 #self.popen.wait() 439 #os.wait() 440 _logger.info("process[%s]: sent SIGKILL", self.name) 441 except OSError, e: 442 if e.args[0] == 3: 443 printerrlog("no [%s] process with pid [%s]"%(self.name, pid)) 444 else: 445 printerrlog("errors shutting down [%s], see log for details"%self.name) 446 _logger.error(traceback.format_exc()) 447 else: 448 _logger.info("process[%s]: SIGTERM killed with return value %s", self.name, retcode) 449 else: 450 _logger.info("process[%s]: SIGINT killed with return value %s", self.name, retcode) 451 452 finally: 453 self.popen = None

454

455 - def stop(self, errors=[]):

456 """ 457 Stop the process. Record any significant error messages in the errors parameter 458 459 @param errors: error messages. stop() will record messages into this list. 460 @type errors: [str] 461 """ 462 super(LocalProcess, self).stop(errors) 463 self.lock.acquire() 464 try: 465 try: 466 _logger.debug("process[%s].stop() starting", self.name) 467 if self.popen is None: 468 _logger.debug("process[%s].stop(): popen is None, nothing to kill") 469 return 470 #NOTE: currently POSIX-only. Need to add in Windows code once I have a test environment: 471 # http://aspn.activestate.com/ASPN/Cookbook/Python/Recipe/347462 472 self._stop_unix(errors) 473 except: 474 _logger.error("[%s] EXCEPTION %s", self.name, traceback.format_exc()) 475 finally: 476 self.stopped = True 477 self.lock.release()

478

479 -def print_runner_summary(runner_results, junit_results, runner_name='ROSUNIT'):

480 """ 481 Print summary of runner results and actual test results to 482 stdout. For rosunit and rostest, the test is wrapped in an 483 external runner. The results from this runner are important if the 484 runner itself has a failure. 485 486 @param runner_result: unittest runner result object 487 @type runner_result: _XMLTestResult 488 @param junit_results: Parsed JUnit test results 489 @type junit_results: rosunit.junitxml.Result 490 """ 491 # we have two separate result objects, which can be a bit 492 # confusing. 'result' counts successful _running_ of tests 493 # (i.e. doesn't check for actual test success). The 'r' result 494 # object contains results of the actual tests. 495 496 buff = cStringIO.StringIO() 497 498 buff.write("[%s]"%(runner_name)+'-'*71+'\n\n') 499 for tc_result in junit_results.test_case_results: 500 buff.write(tc_result.description) 501 for tc_result in runner_results.failures: 502 buff.write("[%s][failed]\n"%tc_result[0]._testMethodName) 503 504 buff.write('\nSUMMARY\n') 505 if runner_results.wasSuccessful() and (junit_results.num_errors + junit_results.num_failures) == 0: 506 buff.write("\033[32m * RESULT: SUCCESS\033[0m\n") 507 else: 508 buff.write("\033[1;31m * RESULT: FAIL\033[0m\n") 509 510 # TODO: still some issues with the numbers adding up if tests fail to launch 511 512 # number of errors from the inner tests, plus add in count for tests 513 # that didn't run properly ('result' object). 514 buff.write(" * TESTS: %s\n"%junit_results.num_tests) 515 num_errors = junit_results.num_errors+len(runner_results.errors) 516 if num_errors: 517 buff.write("\033[1;31m * ERRORS: %s\033[0m\n"%num_errors) 518 else: 519 buff.write(" * ERRORS: 0\n") 520 num_failures = junit_results.num_failures+len(runner_results.failures) 521 if num_failures: 522 buff.write("\033[1;31m * FAILURES: %s\033[0m\n"%num_failures) 523 else: 524 buff.write(" * FAILURES: 0\n") 525 526 if runner_results.failures: 527 buff.write("\nERROR: The following tests failed to run:\n") 528 for tc_result in runner_results.failures: 529 buff.write(" * " +tc_result[0]._testMethodName + "\n") 530 531 print buff.getvalue()

532

533 -def print_unittest_summary(result):

534 """ 535 Print summary of python unittest result to stdout 536 @param result: test results 537 """ 538 buff = cStringIO.StringIO() 539 buff.write("-------------------------------------------------------------\nSUMMARY:\n") 540 if result.wasSuccessful(): 541 buff.write("\033[32m * RESULT: SUCCESS\033[0m\n") 542 else: 543 buff.write(" * RESULT: FAIL\n") 544 buff.write(" * TESTS: %s\n"%result.testsRun) 545 buff.write(" * ERRORS: %s [%s]\n"%(len(result.errors), ', '.join([e[0]._testMethodName for e in result.errors]))) 546 buff.write(" * FAILURES: %s [%s]\n"%(len(result.failures), ','.join([e[0]._testMethodName for e in result.failures]))) 547 print buff.getvalue()

548

Source Code for Module rosunit.baretest