log the raw output on stdout/stderr

Avocado process module has a routine to drain the std* buffer with a
per-line basis loop. This loop makes the new-line character to be
dropped.

On the other hand, the Python logging system is hard-coded to add a new-line
character at the end of the msg string.

The problem takes place when `process` writes a line which originally
had new-line character at the end but the logging system still adds the
new-line character to that line.

In this patch:
- avocado.utils.process to include the new-line character in the lines
  that originally had one.
- avocado.core.test to use for raw outputs a custom logging FileHandler
  that does not add a new-line character at the end of each line.

Verified with (checking `.../test-results/1-.../[stdout|stderr|output]`):

    $ avocado run --external-runner '/bin/echo' 'foo'

    $ avocado run --external-runner '/bin/echo -n' 'foo'

    $ avocado run --external-runner '/bin/ls' '.'

    $ avocado run --external-runner '/bin/ls' 'nonexistingfile

Reference: https://trello.com/c/dH7FLT75Signed-off-by: NAmador Pahim <apahim@redhat.com>

avocado/core/test.py

@@ -52,6 +52,33 @@ from .output import LOG_JOB
 COMMON_TMPDIR_NAME = 'AVOCADO_TESTS_COMMON_TMPDIR'
 
 
+class RawFileHandler(logging.FileHandler):
+
+    """
+    File Handler that doesn't include arbitrary characters to the
+    logged stream but still respects the formatter.
+    """
+
+    def __init__(self, *args, **kwargs):
+        logging.FileHandler.__init__(self, *args, **kwargs)
+
+    def emit(self, record):
+        """
+        Modifying the original emit() to avoid including a new line
+        in streams that should be logged in its purest form, like in
+        stdout/stderr recordings.
+        """
+        if self.stream is None:
+            self.stream = self._open()
+        try:
+            msg = self.format(record)
+            stream = self.stream
+            stream.write('%s' % msg)
+            self.flush()
+        except Exception:
+            self.handleError(record)
+
+
 class TestID(object):
 
     """
@@ -494,8 +521,11 @@ class Test(unittest.TestCase):
         return state
 
     def _register_log_file_handler(self, logger, formatter, filename,
-                                   log_level=logging.DEBUG):
-        file_handler = logging.FileHandler(filename=filename)
+                                   log_level=logging.DEBUG, raw=False):
+        if raw:
+            file_handler = RawFileHandler(filename=filename)
+        else:
+            file_handler = logging.FileHandler(filename=filename)
         file_handler.setLevel(log_level)
         file_handler.setFormatter(formatter)
         logger.addHandler(file_handler)
@@ -522,10 +552,12 @@ class Test(unittest.TestCase):
 
         self._register_log_file_handler(log_test_stdout,
                                         stream_formatter,
-                                        self._stdout_file)
+                                        self._stdout_file,
+                                        raw=True)
         self._register_log_file_handler(log_test_stderr,
                                         stream_formatter,
-                                        self._stderr_file)
+                                        self._stderr_file,
+                                        raw=True)
         self._register_log_file_handler(logging.getLogger('paramiko'),
                                         formatter,
                                         self._ssh_logfile)
@@ -533,10 +565,12 @@ class Test(unittest.TestCase):
         # combined output logging
         self._register_log_file_handler(log_test_stdout,
                                         stream_formatter,
-                                        self._output_file)
+                                        self._output_file,
+                                        raw=True)
         self._register_log_file_handler(log_test_stderr,
                                         stream_formatter,
-                                        self._output_file)
+                                        self._output_file,
+                                        raw=True)
 
         if isinstance(sys.stdout, output.LoggingFile):
             sys.stdout.add_logger(log_test_stdout)

avocado/utils/process.py

@@ -478,7 +478,7 @@ class SubProcess(object):
                         for line in bfr.splitlines():
                             log.debug(prefix, line)
                             if stream_logger is not None:
-                                stream_logger.debug(stream_prefix, line)
+                                stream_logger.debug(stream_prefix, '%s\n' % line)
                         bfr = ''
             finally:
                 lock.release()

selftests/functional/test_output.py

@@ -145,11 +145,11 @@ 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\n",
+        self.assertEqual("test_printtest_stdouttest_process\n",
                          open(os.path.join(testdir, "stdout")).read())
-        self.assertEqual("test_stderr\n",
+        self.assertEqual("test_stderr",
                          open(os.path.join(testdir, "stderr")).read())
-        self.assertEqual("test_print\ntest_stdout\ntest_stderr\n"
+        self.assertEqual("test_printtest_stdouttest_stderr"
                          "test_process\n",
                          open(os.path.join(testdir, "output")).read())