Merge branch 'ldoktor-sysinfo-timeout3'

Signed-off-by: NAmador Pahim <apahim@redhat.com>

avocado/core/sysinfo.py

@@ -18,6 +18,7 @@ import logging
 import os
 import shutil
 import time
+import threading
 
 try:
     import subprocess32 as subprocess
@@ -30,6 +31,7 @@ from ..utils import genio
 from ..utils import process
 from ..utils import software_manager
 from ..utils import path as utils_path
+from ..utils import wait
 
 log = logging.getLogger("avocado.sysinfo")
 
@@ -151,6 +153,16 @@ class Command(Collectible):
 
         :param logdir: Path to a log directory.
         """
+        def destroy(proc, cmd, timeout):
+            log.error("sysinfo: Interrupting cmd '%s' which took longer "
+                      "than %ss to finish", cmd, timeout)
+            try:
+                proc.terminate()
+                if wait.wait_for(lambda: proc.poll() is None, timeout=1,
+                                 step=0.01) is None:
+                    proc.kill()
+            except OSError:
+                pass    # Ignore errors when the process already finished
         env = os.environ.copy()
         if "PATH" not in env:
             env["PATH"] = "/usr/bin:/bin"
@@ -161,8 +173,21 @@ class Command(Collectible):
         stdin = open(os.devnull, "r")
         stdout = open(logf_path, "w")
         try:
-            subprocess.call(self.cmd, stdin=stdin, stdout=stdout,
-                            stderr=subprocess.STDOUT, shell=True, env=env)
+            proc = subprocess.Popen(self.cmd, stdin=stdin, stdout=stdout,
+                                    stderr=subprocess.STDOUT, shell=True,
+                                    env=env)
+            timeout = settings.get_value("sysinfo.collect", "commands_timeout",
+                                         int, -1)
+            if timeout <= 0:
+                proc.wait()
+                return
+            timer = threading.Timer(timeout, destroy, (proc, self.cmd,
+                                                       timeout))
+            try:
+                timer.start()
+                proc.wait()
+            finally:
+                timer.cancel()
         finally:
             for f in (stdin, stdout):
                 f.close()

docs/source/Sysinfo.rst

+==================
+Sysinfo collection
+==================
+
+Avocado comes with a ``sysinfo`` plugin, which automatically gathers some
+system information per each job or even between tests. This is very useful
+when later we want to know what caused the test's failure. This system
+is configurable but we provide a sane set of defaults for you.
+
+In the default Avocado configuration (``/etc/avocado/avocado.conf``) there
+is a section ``sysinfo.collect`` where you can enable/disable the sysinfo
+collection as well as configure the basic environment. In
+``sysinfo.collectibles`` section you can define basic paths of where
+to look for what commands/tasks should be performed before/during
+the sysinfo collection. Avocado supports three types of tasks:
+
+1. commands - file with new-line separated list of commands to be executed
+   before and after the job/test (single execution commands). It is possible
+   to set a timeout which is enforced per each executed command in
+   [sysinfo.collect] by setting "commands_timeout" to a positive number.
+2. files - file with new-line separated list of files to be copied
+3. profilers - file with new-line separated list of commands to be executed
+   before the job/test and killed at the end of the job/test (follow-like
+   commands)
+
+Additionally this plugin tries to follow the system log via ``journalctl``
+if available.
+
+The sysinfo can also be enabled/disabled on the cmdline if needed by
+``--sysinfo on|off``.
+
+After the job execution you can find the collected information in
+``$RESULTS/sysinfo`` of ``$RESULTS/test-results/$TEST/sysinfo``. They
+are categorized into ``pre``, ``post`` and ``profile`` folders and
+the filenames are safely-escaped executed commands or file-names.
+You can also see the sysinfo in html results when you have html
+results plugin enabled.
+
+.. warning:: If you are using avocado from sources, you need to manually place
+   the ``commands``/``files``/``profilers`` into the ``/etc/avocado/sysinfo``
+   directories or adjust the paths in
+   ``$AVOCADO_SRC/etc/avocado/avocado.conf``.

docs/source/index.rst

@@ -14,6 +14,7 @@ Contents:
    Configuration
    Loaders
    LoggingSystem
+   Sysinfo
    Mux
    Replay
    Diff

etc/avocado/avocado.conf

@@ -15,6 +15,8 @@ logs_dir = ~/avocado/job-results
 [sysinfo.collect]
 # Whether to collect system information during avocado jobs
 enabled = True
+# Overall timeout to collect commands, when <=0 no timeout is enforced
+commands_timeout = -1
 # Whether to take a list of installed packages previous to avocado jobs
 installed_packages = False
 # Whether to run certain commands in bg to give extra job debug information

selftests/functional/test_sysinfo.py

@@ -5,12 +5,22 @@ import unittest
 
 from avocado.core import exit_codes
 from avocado.utils import process
+from avocado.utils import script
 
 
 basedir = os.path.join(os.path.dirname(os.path.abspath(__file__)), '..', '..')
 basedir = os.path.abspath(basedir)
 
 
+COMMANDS_TIMEOUT_CONF = """
+[sysinfo.collect]
+commands_timeout = %s
+
+[sysinfo.collectibles]
+commands = %s
+"""
+
+
 class SysInfoTest(unittest.TestCase):
 
     def setUp(self):
@@ -65,6 +75,52 @@ class SysInfoTest(unittest.TestCase):
     def tearDown(self):
         shutil.rmtree(self.tmpdir)
 
+    def run_sysinfo_interrupted(self, sleep, timeout, exp_duration):
+        os.chdir(basedir)
+        commands_path = os.path.join(self.tmpdir, "commands")
+        script.make_script(commands_path, "sleep %s" % sleep)
+        config_path = os.path.join(self.tmpdir, "config.conf")
+        script.make_script(config_path,
+                           COMMANDS_TIMEOUT_CONF % (timeout, commands_path))
+        cmd_line = ("./scripts/avocado --show all --config %s run "
+                    "--job-results-dir %s --sysinfo=on passtest.py"
+                    % (config_path, self.tmpdir))
+        result = process.run(cmd_line)
+        if timeout > 0:
+            self.assertLess(result.duration, exp_duration, "Execution took "
+                            "longer than %ss which is likely due to "
+                            "malfunctioning commands_timeout "
+                            "sysinfo.collect feature:\n%s"
+                            % (exp_duration, result))
+        else:
+            self.assertGreater(result.duration, exp_duration, "Execution took "
+                               "less than %ss which is likely due to "
+                               "malfunctioning commands_timeout "
+                               "sysinfo.collect feature:\n%s"
+                               % (exp_duration, result))
+        expected_rc = exit_codes.AVOCADO_ALL_OK
+        self.assertEqual(result.exit_status, expected_rc,
+                         'Avocado did not return rc %d:\n%s'
+                         % (expected_rc, result))
+        sleep_log = os.path.join(self.tmpdir, "latest", "sysinfo", "pre",
+                                 "sleep_%s" % sleep)
+        if not os.path.exists(sleep_log):
+            path = os.path.abspath(sleep_log)
+            while not os.path.exists(path):
+                tmp = os.path.split(path)[0]
+                if tmp == path:
+                    break
+                path = tmp
+            raise AssertionError("Sleep output not recorded in '%s', first "
+                                 "existing location '%s' contains:\n%s"
+                                 % (sleep_log, path, os.listdir(path)))
+
+    def test_sysinfo_interrupted(self):
+        self.run_sysinfo_interrupted(10, 1, 15)
+
+    def test_sysinfo_not_interrupted(self):
+        self.run_sysinfo_interrupted(5, -1, 10)
+
 
 if __name__ == '__main__':
     unittest.main()