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 11983 2010-10-29 23:47:56Z 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):

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.package = roslib.packages.get_dir_pkg(exe) 80 self.exe = os.path.abspath(exe) 81 if test_name is None: 82 self.test_name = os.path.basename(exe) 83 else: 84 self.test_name = test_name 85 86 # invoke pyunit tests with python executable 87 if self.exe.endswith('.py'): 88 self.args = ['python', self.exe] + args 89 else: 90 self.args = [self.exe] + args 91 92 self.retry = retry 93 self.time_limit = time_limit or BARE_TIME_LIMIT 94 self.pmon = None 95 self.results = junitxml.Result(self.test_name)

96

97 - def setUp(self):

98 self.pmon = pmon.start_process_monitor()

99

100 - def tearDown(self):

101 if self.pmon is not None: 102 pmon.shutdown_process_monitor(self.pmon) 103 self.pmon = None

104

105 - def runTest(self):

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

175 176 177 #TODO: this is a straight copy from roslaunch. Need to reduce, refactor

178 -class LocalProcess(pmon.Process):

179 """ 180 Process launched on local machine 181 """ 182

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

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

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

218 - def get_info(self):

219 """ 220 Get all data about this process in dictionary form 221 """ 222 info = super(LocalProcess, self).get_info() 223 info['pid'] = self.pid 224 if self.run_id: 225 info['run_id'] = self.run_id 226 info['log_output'] = self.log_output 227 if self.cwd is not None: 228 info['cwd'] = self.cwd 229 return info

230

231 - def _configure_logging(self):

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

276

277 - def start(self):

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

349

350 - def is_alive(self):

351 """ 352 @return: True if process is still running 353 @rtype: bool 354 """ 355 if not self.started: #not started yet 356 return True 357 if self.stopped or self.popen is None: 358 return False 359 self.exit_code = self.popen.poll() 360 if self.exit_code is not None: 361 return False 362 return True

363

364 - def get_exit_description(self):

365 """ 366 @return: human-readable description of exit state 367 @rtype: str 368 """ 369 # #973: include location of output location in message 370 if self.exit_code is not None: 371 if self.exit_code: 372 if self.log_dir: 373 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)) 374 else: 375 return 'process has died [pid %s, exit code %s]'%(self.pid, self.exit_code) 376 else: 377 if self.log_dir: 378 return 'process has finished cleanly.\nlog file: %s*.log'%(os.path.join(self.log_dir, self.name)) 379 else: 380 return 'process has finished cleanly' 381 else: 382 return 'process has died'

383

384 - def _stop_unix(self, errors):

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

447

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

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

471

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

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

524

525 -def print_unittest_summary(result):

526 """ 527 Print summary of python unittest result to stdout 528 @param result: test results 529 """ 530 buff = cStringIO.StringIO() 531 buff.write("-------------------------------------------------------------\nSUMMARY:\n") 532 if result.wasSuccessful(): 533 buff.write("\033[32m * RESULT: SUCCESS\033[0m\n") 534 else: 535 buff.write(" * RESULT: FAIL\n") 536 buff.write(" * TESTS: %s\n"%result.testsRun) 537 buff.write(" * ERRORS: %s [%s]\n"%(len(result.errors), ', '.join([e[0]._testMethodName for e in result.errors]))) 538 buff.write(" * FAILURES: %s [%s]\n"%(len(result.failures), ','.join([e[0]._testMethodName for e in result.failures]))) 539 print buff.getvalue()

540

Source Code for Module rosunit.baretest