Output check record: introduce control for process execution

And the support for combined mode.  So far, there was no need to
determine how processes would be run, and how their output would be
collected: the stdout and stderr would always be collcted separately.

Now, with the need to support the "combined" mode, the
`--output-check-record` command line switch not only has to control
which files are populated (stdout.expected, stderr.expected) but also
it needs to control the execution of process, because it's what will
generate the "raw material" for a possible "output.expected" file.
Signed-off-by: NCleber Rosa <crosa@redhat.com>

avocado/core/test.py

@@ -662,6 +662,7 @@ class Test(unittest.TestCase, TestData):
 
         log_test_stdout = LOG_JOB.getChild("stdout")
         log_test_stderr = LOG_JOB.getChild("stderr")
+        log_test_output = LOG_JOB.getChild("output")
 
         self._register_log_file_handler(log_test_stdout,
                                         stream_formatter,
@@ -671,20 +672,15 @@ class Test(unittest.TestCase, TestData):
                                         stream_formatter,
                                         self._stderr_file,
                                         raw=True)
-        self._register_log_file_handler(logging.getLogger('paramiko'),
-                                        formatter,
-                                        self._ssh_logfile)
-
-        # combined output logging
-        self._register_log_file_handler(log_test_stdout,
-                                        stream_formatter,
-                                        self._output_file,
-                                        raw=True)
-        self._register_log_file_handler(log_test_stderr,
+        self._register_log_file_handler(log_test_output,
                                         stream_formatter,
                                         self._output_file,
                                         raw=True)
 
+        self._register_log_file_handler(logging.getLogger('paramiko'),
+                                        formatter,
+                                        self._ssh_logfile)
+
         if isinstance(sys.stdout, output.LoggingFile):
             sys.stdout.add_logger(log_test_stdout)
         if isinstance(sys.stderr, output.LoggingFile):
@@ -714,6 +710,12 @@ class Test(unittest.TestCase, TestData):
             utils_path.init_dir(os.path.dirname(stderr_expected))
             shutil.copyfile(self._stderr_file, stderr_expected)
 
+    def _record_reference_combined(self):
+        expected = self.get_data('output.expected', must_exist=False)
+        if expected is not None:
+            utils_path.init_dir(os.path.dirname(expected))
+            shutil.copyfile(self._output_file, expected)
+
     def _check_reference_stdout(self):
         expected_path = self.get_data('stdout.expected')
         if expected_path is not None:
@@ -878,10 +880,13 @@ class Test(unittest.TestCase, TestData):
                                                 logger=LOG_JOB)
                         stderr_check_exception = details
             elif not job_standalone:
-                if output_check_record in ['all', 'stdout']:
-                    self._record_reference_stdout()
-                if output_check_record in ['all', 'stderr']:
-                    self._record_reference_stderr()
+                if output_check_record == 'combined':
+                    self._record_reference_combined()
+                else:
+                    if output_check_record in ['all', 'both', 'stdout']:
+                        self._record_reference_stdout()
+                    if output_check_record in ['all', 'both', 'stderr']:
+                        self._record_reference_stderr()
 
         # pylint: disable=E0702
         if test_exception is not None:

avocado/plugins/run.py

@@ -29,6 +29,7 @@ from avocado.core.dispatcher import ResultDispatcher
 from avocado.core.dispatcher import JobPrePostDispatcher
 from avocado.core.settings import settings
 from avocado.utils.data_structures import time_to_seconds
+from avocado.utils import process
 
 
 class Run(CLICmd):
@@ -133,7 +134,8 @@ class Run(CLICmd):
         out_check = parser.add_argument_group('output check arguments')
 
         out_check.add_argument('--output-check-record',
-                               choices=('none', 'all', 'stdout', 'stderr'),
+                               choices=('none', 'all', 'stdout', 'stderr',
+                                        'both', 'combined'),
                                default='none',
                                help="Record output streams of your tests "
                                "to reference files (valid options: none (do "
@@ -171,6 +173,9 @@ class Run(CLICmd):
 
         :param args: Command line args received from the run subparser.
         """
+        if 'output_check_record' in args:
+            process.OUTPUT_CHECK_RECORD_MODE = getattr(args, 'output_check_record')
+
         if args.unique_job_id is not None:
             try:
                 int(args.unique_job_id, 16)

avocado/utils/process.py

@@ -48,6 +48,7 @@ from . import path
 log = logging.getLogger('avocado.test')
 stdout_log = logging.getLogger('avocado.test.stdout')
 stderr_log = logging.getLogger('avocado.test.stderr')
+output_log = logging.getLogger('avocado.test.output')
 
 #: The active wrapper utility script.
 CURRENT_WRAPPER = None
@@ -69,6 +70,11 @@ WRAP_PROCESS_NAMES_EXPR = []
 #: undefined, this situation will be flagged by an exception.
 UNDEFINED_BEHAVIOR_EXCEPTION = None
 
+#: The current output record mode.  It's not possible to record
+#: both the 'stdout' and 'stderr' streams, and at the same time
+#: in the right order, the combined 'output' stream.  So this
+#: setting defines the mode.
+OUTPUT_CHECK_RECORD_MODE = None
 
 # variable=value bash assignment
 _RE_BASH_SET_VARIABLE = re.compile(r"[a-zA-Z]\w*=.*")
@@ -386,7 +392,7 @@ class SubProcess(object):
     Run a subprocess in the background, collecting stdout/stderr streams.
     """
 
-    def __init__(self, cmd, verbose=True, allow_output_check='all',
+    def __init__(self, cmd, verbose=True, allow_output_check=None,
                  shell=False, env=None, sudo=False,
                  ignore_bg_processes=False):
         """
@@ -396,14 +402,17 @@ class SubProcess(object):
         :type cmd: str
         :param verbose: Whether to log the command run and stdout/stderr.
         :type verbose: bool
-        :param allow_output_check: Whether to log the command stream outputs
-                                   (stdout and stderr) in the test stream
-                                   files. Valid values: 'stdout', for
-                                   allowing only standard output, 'stderr',
-                                   to allow only standard error, 'all',
-                                   to allow both standard output and error
-                                   (default), and 'none', to allow
-                                   none to be recorded.
+        :param allow_output_check: Whether to record the output from this
+                                   process (from stdout and stderr) in the
+                                   test's output record files. Valid values:
+                                   'stdout', for standard output *only*,
+                                   'stderr' for standard error *only*,
+                                   'both' for both standard output and error
+                                   in separate files (default), 'combined' for
+                                   standard output and error in a single file,
+                                   and 'none' to disable all recording. 'all'
+                                   is also a valid, but deprecated, option that
+                                   is a synonym of 'both'.
         :type allow_output_check: str
         :param shell: Whether to run the subprocess in a subshell.
         :type shell: bool
@@ -427,7 +436,12 @@ class SubProcess(object):
         # Now assemble the final command considering the need for sudo
         self.cmd = self._prepend_sudo(cmd, sudo, shell)
         self.verbose = verbose
-        if allow_output_check not in ('none', 'stderr', 'stdout', 'all'):
+        if allow_output_check is None:
+            allow_output_check = OUTPUT_CHECK_RECORD_MODE
+        if allow_output_check is None:
+            allow_output_check = 'both'
+        if allow_output_check not in ('stdout', 'stderr', 'both',
+                                      'combined', 'none', 'all'):
             msg = ("Invalid value (%s) set in allow_output_check" %
                    allow_output_check)
             raise ValueError(msg)
@@ -445,6 +459,7 @@ class SubProcess(object):
         # files and logs
         self._stdout_drainer = None
         self._stderr_drainer = None
+        self._combined_drainer = None
 
         self._ignore_bg_processes = ignore_bg_processes
 
@@ -492,9 +507,13 @@ class SubProcess(object):
             else:
                 cmd = self.cmd
             try:
+                if self.allow_output_check == 'combined':
+                    stderr = subprocess.STDOUT
+                else:
+                    stderr = subprocess.PIPE
                 self._popen = subprocess.Popen(cmd,
                                                stdout=subprocess.PIPE,
-                                               stderr=subprocess.PIPE,
+                                               stderr=stderr,
                                                shell=self.shell,
                                                env=self.env)
             except OSError as details:
@@ -504,28 +523,42 @@ class SubProcess(object):
             self.start_time = time.time()
 
             # prepare fd drainers
-            self._stdout_drainer = FDDrainer(
-                self._popen.stdout.fileno(),
-                self.result,
-                name="%s-stdout" % self.cmd,
-                logger=log,
-                logger_prefix="[stdout] %s",
-                stream_logger=stdout_log,
-                ignore_bg_processes=self._ignore_bg_processes,
-                verbose=self.verbose)
-            self._stderr_drainer = FDDrainer(
-                self._popen.stderr.fileno(),
-                self.result,
-                name="%s-stderr" % self.cmd,
-                logger=log,
-                logger_prefix="[stderr] %s",
-                stream_logger=stderr_log,
-                ignore_bg_processes=self._ignore_bg_processes,
-                verbose=self.verbose)
-
-            # start stdout/stderr threads
-            self._stdout_drainer.start()
-            self._stderr_drainer.start()
+            if self.allow_output_check == 'combined':
+                self._combined_drainer = FDDrainer(
+                    self._popen.stdout.fileno(),
+                    self.result,
+                    name="%s-combined" % self.cmd,
+                    logger=log,
+                    logger_prefix="[output] %s",
+                    # FIXME, in fact, a new log has to be used here
+                    stream_logger=output_log,
+                    ignore_bg_processes=self._ignore_bg_processes,
+                    verbose=self.verbose)
+                self._combined_drainer.start()
+
+            else:
+                self._stdout_drainer = FDDrainer(
+                    self._popen.stdout.fileno(),
+                    self.result,
+                    name="%s-stdout" % self.cmd,
+                    logger=log,
+                    logger_prefix="[stdout] %s",
+                    stream_logger=stdout_log,
+                    ignore_bg_processes=self._ignore_bg_processes,
+                    verbose=self.verbose)
+                self._stderr_drainer = FDDrainer(
+                    self._popen.stderr.fileno(),
+                    self.result,
+                    name="%s-stderr" % self.cmd,
+                    logger=log,
+                    logger_prefix="[stderr] %s",
+                    stream_logger=stderr_log,
+                    ignore_bg_processes=self._ignore_bg_processes,
+                    verbose=self.verbose)
+
+                # start stdout/stderr threads
+                self._stdout_drainer.start()
+                self._stderr_drainer.start()
 
             def signal_handler(signum, frame):
                 self.result.interrupted = "signal/ctrl+c"
@@ -553,8 +586,10 @@ class SubProcess(object):
         Close subprocess stdout and stderr, and put values into result obj.
         """
         # Cleaning up threads
-        self._stdout_drainer.join()
-        self._stderr_drainer.join()
+        if self._stdout_drainer is not None:
+            self._stdout_drainer.join()
+        if self._stderr_drainer is not None:
+            self._stderr_drainer.join()
         # Clean subprocess pipes and populate stdout/err
         self.result.stdout = self.get_stdout()
         self.result.stderr = self.get_stderr()
@@ -580,6 +615,8 @@ class SubProcess(object):
         :rtype: str
         """
         self._init_subprocess()
+        if self._combined_drainer is not None:
+            return self._combined_drainer.data.getvalue()
         return self._stdout_drainer.data.getvalue()
 
     def get_stderr(self):
@@ -590,6 +627,8 @@ class SubProcess(object):
         :rtype: str
         """
         self._init_subprocess()
+        if self._combined_drainer is not None:
+            return ''
         return self._stderr_drainer.data.getvalue()
 
     def terminate(self):
@@ -710,7 +749,8 @@ class WrapSubProcess(SubProcess):
     Wrap subprocess inside an utility program.
     """
 
-    def __init__(self, cmd, verbose=True, allow_output_check='all',
+    def __init__(self, cmd, verbose=True,
+                 allow_output_check=None,
                  shell=False, env=None, wrapper=None, sudo=False,
                  ignore_bg_processes=False):
         if wrapper is None and CURRENT_WRAPPER is not None:
@@ -731,8 +771,9 @@ class GDBSubProcess(object):
     Runs a subprocess inside the GNU Debugger
     """
 
-    def __init__(self, cmd, verbose=True, allow_output_check='all',
-                 shell=False, env=None, sudo=False, ignore_bg_processes=False):
+    def __init__(self, cmd, verbose=True,
+                 allow_output_check=None, shell=False,
+                 env=None, sudo=False, ignore_bg_processes=False):
         """
         Creates the subprocess object, stdout/err, reader threads and locks.
 
@@ -1107,8 +1148,8 @@ def get_sub_process_klass(cmd):
 
 
 def run(cmd, timeout=None, verbose=True, ignore_status=False,
-        allow_output_check='all', shell=False, env=None, sudo=False,
-        ignore_bg_processes=False):
+        allow_output_check=None, shell=False,
+        env=None, sudo=False, ignore_bg_processes=False):
     """
     Run a subprocess, returning a CmdResult object.
 
@@ -1159,8 +1200,8 @@ def run(cmd, timeout=None, verbose=True, ignore_status=False,
 
 
 def system(cmd, timeout=None, verbose=True, ignore_status=False,
-           allow_output_check='all', shell=False, env=None, sudo=False,
-           ignore_bg_processes=False):
+           allow_output_check=None, shell=False,
+           env=None, sudo=False, ignore_bg_processes=False):
     """
     Run a subprocess, returning its exit code.
 
@@ -1207,8 +1248,9 @@ def system(cmd, timeout=None, verbose=True, ignore_status=False,
 
 
 def system_output(cmd, timeout=None, verbose=True, ignore_status=False,
-                  allow_output_check='all', shell=False, env=None, sudo=False,
-                  ignore_bg_processes=False, strip_trail_nl=True):
+                  allow_output_check=None, shell=False,
+                  env=None, sudo=False, ignore_bg_processes=False,
+                  strip_trail_nl=True):
     """
     Run a subprocess, returning its output.
 

selftests/functional/test_output.py

@@ -58,6 +58,9 @@ class OutputTest(Test):
         sys.stdout.write("test_stdout\\n")
         sys.stderr.write("test_stderr\\n")
         process.run("/bin/echo -n test_process")
+        process.run("/bin/echo -n __test_stderr__ > /dev/stderr",
+                    shell=True)
+        process.run("/bin/echo -n __test_stdout__")
 
     def __del__(self):
         print "del_print"
@@ -145,12 +148,23 @@ class OutputTest(unittest.TestCase):
                 "[stderr] test_stderr", "[stdout] test_process"]
         _check_output(joblog, exps, "job.log")
         testdir = res["tests"][0]["logdir"]
-        self.assertEqual("test_print\ntest_stdout\ntest_process",
+        self.assertEqual("test_print\ntest_stdout\ntest_process__test_stdout__",
                          open(os.path.join(testdir, "stdout")).read())
-        self.assertEqual("test_stderr\n",
+        self.assertEqual("test_stderr\n__test_stderr__",
                          open(os.path.join(testdir, "stderr")).read())
-        self.assertEqual("test_print\ntest_stdout\ntest_stderr\n"
-                         "test_process",
+
+        # Now run the same test, but with combined output
+        # combined output can not keep track of sys.stdout and sys.stdout
+        # writes, as they will eventually be out of sync.  In fact,
+        # the correct fix is to run the entire test process with redirected
+        # stdout and stderr, and *not* play with sys.stdout and sys.stderr.
+        # But this change will come later
+        result = process.run("%s run --job-results-dir %s --sysinfo=off "
+                             "--output-check-record=combined "
+                             "--json - -- %s" % (AVOCADO, self.tmpdir, test))
+        res = json.loads(result.stdout)
+        testdir = res["tests"][0]["logdir"]
+        self.assertEqual("test_process__test_stderr____test_stdout__",
                          open(os.path.join(testdir, "output")).read())
 
     def tearDown(self):