Merge pull request #96 from avocado-framework/test-execution-subprocess

Test execution isolation using subprocesses and timeout feature

avocado/core/exceptions.py

@@ -58,7 +58,19 @@ class TestSetupFail(TestBaseException):
 class TestError(TestBaseException):
 
     """
-    Indicates that something went wrong with the test harness itself.
+    Indicates that the test was not fully executed and an error happened.
+
+    This is the sort of exception you raise if the test was partially
+    executed and could not complete due to a setup, configuration,
+    or another fatal condition.
+    """
+    status = "ERROR"
+
+
+class TestTimeoutError(TestBaseException):
+
+    """
+    Indicates that the test did not finish before the timeout specified.
     """
     status = "ERROR"
 
@@ -94,15 +106,18 @@ class TestWarn(TestBaseException):
 
 class CmdError(Exception):
 
-    def __init__(self, command, result):
+    def __init__(self, command=None, result=None):
         self.command = command
         self.result = result
 
     def __str__(self):
-        if self.result.exit_status is None:
-            msg = "Command '%s' failed and is not responding to signals"
-            msg %= self.command
+        if self.result is not None:
+            if self.result.exit_status is None:
+                msg = "Command '%s' failed and is not responding to signals"
+                msg %= self.command
+            else:
+                msg = "Command '%s' failed (rc=%d)"
+                msg %= (self.command, self.result.exit_status)
+            return msg
         else:
-            msg = "Command '%s' failed (rc=%d)"
-            msg %= (self.command, self.result.exit_status)
-        return msg
+            return "CmdError"

avocado/job.py

@@ -19,7 +19,9 @@ Module that describes a sequence of automated test operations.
 
 import imp
 import logging
+import multiprocessing
 import os
+import signal
 import sys
 import traceback
 import uuid
@@ -85,6 +87,25 @@ class TestRunner(object):
                                            job=self.job)
         return test_instance
 
+    def run_test(self, instance, queue):
+        """
+        Run a test instance in a subprocess.
+
+        :param instance: Test instance.
+        :type instance: :class:`avocado.test.Test` instance.
+        :param queue: Multiprocess queue.
+        :type queue: :class`multiprocessing.Queue` instance.
+        """
+        def timeout_handler(signum, frame):
+            e_msg = "Timeout reached waiting for %s to end" % instance
+            raise exceptions.TestTimeoutError(e_msg)
+
+        signal.signal(signal.SIGTERM, timeout_handler)
+        try:
+            instance.run_avocado()
+        finally:
+            queue.put(instance)
+
     def run(self, params_list):
         """
         Run one or more tests and report with test result.
@@ -95,10 +116,29 @@ class TestRunner(object):
         """
         failures = []
         self.result.start_tests()
+        q = multiprocessing.Queue()
         for params in params_list:
             test_instance = self.load_test(params)
             self.result.start_test(test_instance)
-            test_instance.run_avocado()
+            p = multiprocessing.Process(target=self.run_test,
+                                        args=(test_instance, q,))
+            p.start()
+            # The test timeout can come from:
+            # 1) Test params dict (params)
+            # 2) Test default params dict (test_instance.params.timeout)
+            timeout = params.get('timeout')
+            if timeout is None:
+                if hasattr(test_instance.params, 'timeout'):
+                    timeout = test_instance.params.timeout
+            if timeout is not None:
+                timeout = float(timeout)
+            # Wait for the test to end for [timeout] s
+            p.join(timeout)
+            # If there's no exit code, the test is still running.
+            # It must be terminated.
+            if p.exitcode is None:
+                p.terminate()
+            test_instance = q.get()
             self.result.check_test(test_instance)
             if not status.mapping[test_instance.status]:
                 failures.append(test_instance.name)

avocado/test.py

@@ -51,9 +51,11 @@ def log_exc_info(exc_info):
 
     :param exc_info: Exception info produced by sys.exc_info()
     """
+    log.error('')
     for line in tb_info(exc_info):
         for l in line.splitlines():
             log.error(l)
+    log.error('')
 
 
 def prepare_exc_info(exc_info):
@@ -102,6 +104,7 @@ class Test(unittest.TestCase):
         if params is None:
             params = {}
         self.params = Params(params)
+        self._raw_params = params
 
         shortname = self.params.get('shortname')
         s_tag = None
@@ -152,6 +155,13 @@ class Test(unittest.TestCase):
         self.log.debug('Test instance params override defaults whenever available')
         self.log.debug('')
 
+        # If there's a timeout set, log a timeout reminder
+        if hasattr(self.params, 'timeout'):
+            self.log.info('Test timeout set. Will wait %.2f s for '
+                          'PID %s to end',
+                          float(self.params.timeout), os.getpid())
+            self.log.info('')
+
         self.debugdir = None
         self.resultsdir = None
         self.status = None
@@ -169,6 +179,26 @@ class Test(unittest.TestCase):
     def __repr__(self):
         return "Test(%r)" % self.tagged_name
 
+    def __getstate__(self):
+        """
+        Pickle only selected attributes of the class for serialization.
+
+        The fact we serialize the class means you'll have to modify this
+        class if you intend to make significant changes to its structure.
+        """
+        orig = dict(self.__dict__)
+        d = {}
+        preserve_attr = ['basedir', 'debugdir', 'depsdir', 'fail_class',
+                         'fail_reason', 'logdir', 'logfile', 'name',
+                         'resultsdir', 'srcdir', 'status', 'sysinfodir',
+                         'tag', 'tagged_name', 'text_output', 'time_elapsed',
+                         'traceback', 'workdir']
+        for key in sorted(orig):
+            if key in preserve_attr:
+                d[key] = orig[key]
+        d['params'] = orig['_raw_params']
+        return d
+
     def _set_default(self, key, default):
         try:
             self.params[key]

docs/source/WritingTests.rst

@@ -250,6 +250,164 @@ The ``action`` method just gets into the base directory of the compiled suite
 and executes the ``./synctest`` command, with appropriate parameters, using
 :func:`avocado.utils.process.system`.
 
+Avocado Tests run on a separate process
+=======================================
+
+In order to avoid tests to mess around the environment used by the main
+avocado runner process, tests are run on a forked subprocess. This allows
+for more robustness (tests are not easily able to mess/break avocado) and
+some nifty features, such as setting test timeouts.
+
+Setting a Test Timeout
+======================
+
+Sometimes your test suite/test might get stuck forever, and this might
+impact your test grid. You can account for that possibility and set up a
+``timeout`` parameter for your test. The test timeout can be set through
+2 means, in the following order of precedence:
+
+* Multiplex variable parameters. You may just set the timeout parameter, like
+  in the following simplistic example:
+
+::
+
+    variants:
+        - sleeptest:
+            sleep_length = 5
+            sleep_length_type = float
+            timeout = 3
+            timeout_type = float
+
+::
+
+    avocado run sleeptest --multiplex /tmp/sleeptest-example.mplx
+    DEBUG LOG: /home/lmr/avocado/logs/run-2014-06-10-16.13.33/debug.log
+    TOTAL TESTS: 1
+    (1/1) sleeptest.1: ERROR (3.00 s)
+    TOTAL PASSED: 0
+    TOTAL ERROR: 1
+    TOTAL FAILED: 0
+    TOTAL SKIPPED: 0
+    TOTAL WARNED: 0
+    ELAPSED TIME: 3.00 s
+
+::
+
+    $ cat /home/lmr/avocado/logs/run-2014-06-10-16.13.33/debug.log
+    16:13:33 test       L0136 INFO | START sleeptest.1
+    16:13:33 test       L0137 DEBUG|
+    16:13:33 test       L0138 DEBUG| Test instance parameters:
+    16:13:33 test       L0145 DEBUG|     _name_map_file = {'sleeptest-example.mplx': 'sleeptest'}
+    16:13:33 test       L0145 DEBUG|     _short_name_map_file = {'sleeptest-example.mplx': 'sleeptest'}
+    16:13:33 test       L0145 DEBUG|     dep =
+    16:13:33 test       L0145 DEBUG|     name = sleeptest
+    16:13:33 test       L0145 DEBUG|     shortname = sleeptest
+    16:13:33 test       L0145 DEBUG|     sleep_length = 5.0
+    16:13:33 test       L0145 DEBUG|     sleep_length_type = float
+    16:13:33 test       L0145 DEBUG|     timeout = 3.0
+    16:13:33 test       L0145 DEBUG|     timeout_type = float
+    16:13:33 test       L0147 DEBUG|
+    16:13:33 test       L0150 DEBUG| Default parameters:
+    16:13:33 test       L0152 DEBUG|     sleep_length = 1.0
+    16:13:33 test       L0154 DEBUG|
+    16:13:33 test       L0155 DEBUG| Test instance params override defaults whenever available
+    16:13:33 test       L0156 DEBUG|
+    16:13:33 test       L0162 INFO | Test timeout set. Will wait 3.00 s for PID 23953 to end
+    16:13:33 test       L0163 INFO |
+    16:13:33 sysinfo    L0154 DEBUG| Not logging /proc/slabinfo (lack of permissions)
+    16:13:33 sleeptest  L0035 DEBUG| Sleeping for 5.00 seconds
+    16:13:36 test       L0054 ERROR|
+    16:13:36 test       L0057 ERROR| Traceback (most recent call last):
+    16:13:36 test       L0057 ERROR|   File "/home/lmr/Code/avocado/tests/sleeptest/sleeptest.py", line 36, in action
+    16:13:36 test       L0057 ERROR|     time.sleep(self.params.sleep_length)
+    16:13:36 test       L0057 ERROR|   File "/home/lmr/Code/avocado/avocado/job.py", line 101, in timeout_handler
+    16:13:36 test       L0057 ERROR|     raise exceptions.TestTimeoutError(e_msg)
+    16:13:36 test       L0057 ERROR| TestTimeoutError: Timeout reached waiting for sleeptest to end
+    16:13:36 test       L0058 ERROR|
+    16:13:36 test       L0376 ERROR| ERROR sleeptest.1 -> TestTimeoutError: Timeout reached waiting for sleeptest to end
+    16:13:36 test       L0363 INFO |
+
+
+If you pass that multiplex file to the runner multiplexer, this will register
+a timeout of 3 seconds before avocado ends the test forcefully by sending a
+:class:`signal.SIGTERM` to the test, making it raise a
+:class:`avocado.core.exceptions.TestTimeoutError`.
+
+* Default params attribute. Consider the following example:
+
+::
+
+    import time
+
+    from avocado import test
+    from avocado import job
+
+
+    class timeouttest(test.Test):
+
+        """
+        Functional test for avocado. Throw a TestTimeoutError.
+        """
+        default_params = {'timeout': 3.0,
+                          'sleep_time': 5.0}
+
+        def action(self):
+            """
+            This should throw a TestTimeoutError.
+            """
+            self.log.info('Sleeping for %.2f seconds (2 more than the timeout)',
+                          self.params.sleep_time)
+            time.sleep(self.params.sleep_time)
+
+
+    if __name__ == "__main__":
+        job.main()
+
+This accomplishes a similar effect to the multiplex setup defined in there.
+
+::
+
+    $ scripts/avocado run timeouttest
+    DEBUG LOG: /home/lmr/avocado/logs/run-2014-06-10-16.14.19/debug.log
+    TOTAL TESTS: 1
+    (1/1) timeouttest.1: ERROR (3.00 s)
+    TOTAL PASSED: 0
+    TOTAL ERROR: 1
+    TOTAL FAILED: 0
+    TOTAL SKIPPED: 0
+    TOTAL WARNED: 0
+    ELAPSED TIME: 3.00 s
+
+::
+
+    $ cat /home/lmr/avocado/logs/run-2014-06-10-16.14.19/debug.log
+    16:14:19 test       L0136 INFO | START timeouttest.1
+    16:14:19 test       L0137 DEBUG|
+    16:14:19 test       L0138 DEBUG| Test instance parameters:
+    16:14:19 test       L0145 DEBUG|     shortname = timeouttest
+    16:14:19 test       L0147 DEBUG|
+    16:14:19 test       L0150 DEBUG| Default parameters:
+    16:14:19 test       L0152 DEBUG|     sleep_time = 5.0
+    16:14:19 test       L0152 DEBUG|     timeout = 3.0
+    16:14:19 test       L0154 DEBUG|
+    16:14:19 test       L0155 DEBUG| Test instance params override defaults whenever available
+    16:14:19 test       L0156 DEBUG|
+    16:14:19 test       L0162 INFO | Test timeout set. Will wait 3.00 s for PID 24008 to end
+    16:14:19 test       L0163 INFO |
+    16:14:19 sysinfo    L0154 DEBUG| Not logging /proc/slabinfo (lack of permissions)
+    16:14:20 timeouttes L0036 INFO | Sleeping for 5.00 seconds (2 more than the timeout)
+    16:14:22 test       L0054 ERROR|
+    16:14:22 test       L0057 ERROR| Traceback (most recent call last):
+    16:14:22 test       L0057 ERROR|   File "/home/lmr/Code/avocado/tests/timeouttest/timeouttest.py", line 37, in action
+    16:14:22 test       L0057 ERROR|     time.sleep(self.params.sleep_time)
+    16:14:22 test       L0057 ERROR|   File "/home/lmr/Code/avocado/avocado/job.py", line 101, in timeout_handler
+    16:14:22 test       L0057 ERROR|     raise exceptions.TestTimeoutError(e_msg)
+    16:14:22 test       L0057 ERROR| TestTimeoutError: Timeout reached waiting for timeouttest to end
+    16:14:22 test       L0058 ERROR|
+    16:14:22 test       L0376 ERROR| ERROR timeouttest.1 -> TestTimeoutError: Timeout reached waiting for timeouttest to end
+    16:14:22 test       L0363 INFO |
+
+
 Wrap Up
 =======
 

selftests/all/functional/avocado/basic_tests.py

@@ -82,6 +82,21 @@ class RunnerOperationTest(unittest.TestCase):
                       output,
                       "Test did not fail with action exception")
 
+    def test_runner_timeout(self):
+        os.chdir(basedir)
+        cmd_line = './scripts/avocado --xunit run timeouttest'
+        result = process.run(cmd_line, ignore_status=True)
+        output = result.stdout
+        expected_rc = 1
+        unexpected_rc = 3
+        self.assertNotEqual(result.exit_status, unexpected_rc,
+                            "Avocado crashed (rc %d):\n%s" % (unexpected_rc, result))
+        self.assertEqual(result.exit_status, expected_rc,
+                         "Avocado did not return rc %d:\n%s" % (expected_rc, result))
+        self.assertIn("ERROR timeouttest.1 -> TestTimeoutError: Timeout reached waiting for timeouttest to end",
+                      output,
+                      "Test did not fail with timeout exception")
+
 
 class RunnerDropinTest(unittest.TestCase):
 

selftests/all/functional/avocado/multiplex_tests.py

@@ -17,6 +17,7 @@
 import unittest
 import os
 import sys
+import tempfile
 
 # simple magic for using scripts within a source tree
 basedir = os.path.join(os.path.dirname(os.path.abspath(__file__)), '..', '..', '..', '..')
@@ -26,6 +27,15 @@ if os.path.isdir(os.path.join(basedir, 'avocado')):
 
 from avocado.utils import process
 
+timeout_multiplex = """
+variants:
+    - sleeptest:
+        sleep_length = 5
+        sleep_length_type = float
+        timeout = 3
+        timeout_type = float
+"""
+
 
 class MultiplexTests(unittest.TestCase):
 
@@ -61,5 +71,17 @@ class MultiplexTests(unittest.TestCase):
         expected_rc = 1
         self.run_and_check(cmd_line, expected_rc)
 
+    def test_run_mplex_timeout(self):
+        with tempfile.NamedTemporaryFile(delete=False) as multiplex_file:
+            multiplex_file.write(timeout_multiplex)
+            multiplex_file.close()
+            cmd_line = ('./scripts/avocado run "sleeptest" --multiplex %s' %
+                        multiplex_file.name)
+            expected_rc = 1
+            try:
+                self.run_and_check(cmd_line, expected_rc)
+            finally:
+                os.unlink(multiplex_file.name)
+
 if __name__ == '__main__':
     unittest.main()

tests/timeouttest/timeouttest.py

+#!/usr/bin/python
+
+# This program is free software; you can redistribute it and/or modify
+# it under the terms of the GNU General Public License as published by
+# the Free Software Foundation; either version 2 of the License, or
+# (at your option) any later version.
+#
+# This program is distributed in the hope that it will be useful,
+# but WITHOUT ANY WARRANTY; without even the implied warranty of
+# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.
+#
+# See LICENSE for more details.
+#
+# Copyright: Red Hat Inc. 2013-2014
+# Author: Lucas Meneghel Rodrigues <lmr@redhat.com>
+
+import time
+
+from avocado import test
+from avocado import job
+
+
+class timeouttest(test.Test):
+
+    """
+    Functional test for avocado. Throw a TestTimeoutError.
+    """
+    default_params = {'timeout': 3.0,
+                      'sleep_time': 5.0}
+
+    def action(self):
+        """
+        This should throw a TestTimeoutError.
+        """
+        self.log.info('Sleeping for %.2f seconds (2 more than the timeout)',
+                      self.params.sleep_time)
+        time.sleep(self.params.sleep_time)
+
+
+if __name__ == "__main__":
+    job.main()