test: check-output to record diffs

The output check functionality logs, on failures, the complete contents
of the both the actual output, and the expected one. Most often than not,
the most relevant information is the difference between both.

This patch logs the unified diffs and records the diff files
(`stdout.diff` and `stderr.diff`) containing the unified diff between
the expected outputs and the actual outputs.

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

avocado/core/test.py

@@ -28,6 +28,7 @@ import sys
 import time
 import unittest
 
+from difflib import unified_diff
 from six import string_types, iteritems
 
 from . import data_dir
@@ -718,18 +719,56 @@ class Test(unittest.TestCase, TestData):
         if expected_path is not None:
             expected = genio.read_file(expected_path)
             actual = genio.read_file(self._stdout_file)
-            msg = ('Actual test sdtout differs from expected one:\n'
-                   'Actual:\n%s\nExpected:\n%s' % (actual, expected))
-            self.assertEqual(expected, actual, msg)
+
+            stdout_diff = os.path.join(self.logdir, 'stdout.diff')
+
+            fmt = '%(message)s'
+            formatter = logging.Formatter(fmt=fmt)
+            log_stdout_diff = LOG_JOB.getChild("stdout_diff")
+            self._register_log_file_handler(log_stdout_diff,
+                                            formatter,
+                                            stdout_diff)
+
+            diff = unified_diff(expected.splitlines(), actual.splitlines(),
+                                fromfile=expected_path,
+                                tofile=self._stdout_file)
+            diff_content = []
+            for diff_line in diff:
+                diff_content.append(diff_line.rstrip('\n'))
+
+            if diff_content:
+                self.log.debug('Stdout Diff:')
+                for line in diff_content:
+                    log_stdout_diff.debug(line)
+                self.fail('Actual test sdtout differs from expected one')
 
     def _check_reference_stderr(self):
         expected_path = self.get_data('stderr.expected')
         if expected_path is not None:
             expected = genio.read_file(expected_path)
             actual = genio.read_file(self._stderr_file)
-            msg = ('Actual test sdterr differs from expected one:\n'
-                   'Actual:\n%s\nExpected:\n%s' % (actual, expected))
-            self.assertEqual(expected, actual, msg)
+
+            stderr_diff = os.path.join(self.logdir, 'stderr.diff')
+
+            fmt = '%(message)s'
+            formatter = logging.Formatter(fmt=fmt)
+            log_stderr_diff = LOG_JOB.getChild("stderr_diff")
+            self._register_log_file_handler(log_stderr_diff,
+                                            formatter,
+                                            stderr_diff)
+
+            diff = unified_diff(expected.splitlines(), actual.splitlines(),
+                                fromfile=expected_path,
+                                tofile=self._stderr_file)
+            diff_content = []
+            for diff_line in diff:
+                diff_content.append(diff_line.rstrip('\n'))
+
+            if diff_content:
+                self.log.debug('Stderr Diff:')
+                for line in diff_content:
+                    log_stderr_diff.debug(line)
+                self.fail('Actual test sdterr differs from expected one')
 
     def _run_avocado(self):
         """

docs/source/WritingTests.rst

@@ -833,51 +833,45 @@ happens if we change the ``stdout.expected`` file contents to ``Hello, Avocado!`
 
 Verifying the failure reason::
 
-    $ cat $HOME/avocado/job-results/job-2014-09-25T20.52-f0521e5/job.log
-    20:52:38 test       L0163 INFO | START 1-output_record.sh
-    20:52:38 test       L0164 DEBUG|
-    20:52:38 test       L0165 DEBUG| Test instance parameters:
-    20:52:38 test       L0173 DEBUG|
-    20:52:38 test       L0176 DEBUG| Default parameters:
-    20:52:38 test       L0180 DEBUG|
-    20:52:38 test       L0181 DEBUG| Test instance params override defaults whenever available
-    20:52:38 test       L0182 DEBUG|
-    20:52:38 process    L0242 INFO | Running '$HOME/Code/avocado/output_record.sh'
-    20:52:38 process    L0310 DEBUG| [stdout] Hello, world!
-    20:52:38 test       L0565 INFO | Command: $HOME/Code/avocado/output_record.sh
-    20:52:38 test       L0565 INFO | Exit status: 0
-    20:52:38 test       L0565 INFO | Duration: 0.00313782691956
-    20:52:38 test       L0565 INFO | Stdout:
-    20:52:38 test       L0565 INFO | Hello, world!
-    20:52:38 test       L0565 INFO |
-    20:52:38 test       L0565 INFO | Stderr:
-    20:52:38 test       L0565 INFO |
-    20:52:38 test       L0060 ERROR|
-    20:52:38 test       L0063 ERROR| Traceback (most recent call last):
-    20:52:38 test       L0063 ERROR|   File "$HOME/Code/avocado/avocado/test.py", line 397, in check_reference_stdout
-    20:52:38 test       L0063 ERROR|     self.assertEqual(expected, actual, msg)
-    20:52:38 test       L0063 ERROR|   File "/usr/lib64/python2.7/unittest/case.py", line 551, in assertEqual
-    20:52:38 test       L0063 ERROR|     assertion_func(first, second, msg=msg)
-    20:52:38 test       L0063 ERROR|   File "/usr/lib64/python2.7/unittest/case.py", line 544, in _baseAssertEqual
-    20:52:38 test       L0063 ERROR|     raise self.failureException(msg)
-    20:52:38 test       L0063 ERROR| AssertionError: Actual test sdtout differs from expected one:
-    20:52:38 test       L0063 ERROR| Actual:
-    20:52:38 test       L0063 ERROR| Hello, world!
-    20:52:38 test       L0063 ERROR|
-    20:52:38 test       L0063 ERROR| Expected:
-    20:52:38 test       L0063 ERROR| Hello, Avocado!
-    20:52:38 test       L0063 ERROR|
-    20:52:38 test       L0064 ERROR|
-    20:52:38 test       L0529 ERROR| FAIL 1-output_record.sh -> AssertionError: Actual test sdtout differs from expected one:
-    Actual:
-    Hello, world!
-
-    Expected:
-    Hello, Avocado!
-
-    20:52:38 test       L0516 INFO |
-
-As expected, the test failed because we changed its expectations.
+    $ cat $HOME/avocado/job-results/latest/job.log
+	2017-10-16 14:23:02,567 test             L0381 INFO | START 1-output_record.sh
+	2017-10-16 14:23:02,568 test             L0402 DEBUG| Test metadata:
+	2017-10-16 14:23:02,568 test             L0403 DEBUG|   filename: $HOME/output_record.sh
+	2017-10-16 14:23:02,596 process          L0389 INFO | Running '$HOME/output_record.sh'
+	2017-10-16 14:23:02,603 process          L0499 INFO | Command '$HOME/output_record.sh' finished with 0 after 0.00131011009216s
+	2017-10-16 14:23:02,602 process          L0479 DEBUG| [stdout] Hello, world!
+	2017-10-16 14:23:02,603 test             L1084 INFO | Exit status: 0
+	2017-10-16 14:23:02,604 test             L1085 INFO | Duration: 0.00131011009216
+	2017-10-16 14:23:02,604 test             L0274 DEBUG| DATA (filename=stdout.expected) => $HOME/output_record.sh.data/stdout.expected (found at file source dir)
+	2017-10-16 14:23:02,605 test             L0740 DEBUG| Stdout Diff:
+	2017-10-16 14:23:02,605 test             L0742 DEBUG| --- $HOME/output_record.sh.data/stdout.expected
+	2017-10-16 14:23:02,605 test             L0742 DEBUG| +++ $HOME/avocado/job-results/job-2017-10-16T14.23-8cba866/test-results/1-output_record.sh/stdout
+	2017-10-16 14:23:02,605 test             L0742 DEBUG| @@ -1 +1 @@
+	2017-10-16 14:23:02,605 test             L0742 DEBUG| -Hello, Avocado!
+	2017-10-16 14:23:02,605 test             L0742 DEBUG| +Hello, world!
+	2017-10-16 14:23:02,606 stacktrace       L0041 ERROR|
+	2017-10-16 14:23:02,606 stacktrace       L0044 ERROR| Reproduced traceback from: $HOME/git/avocado/avocado/core/test.py:872
+	2017-10-16 14:23:02,606 stacktrace       L0047 ERROR| Traceback (most recent call last):
+	2017-10-16 14:23:02,606 stacktrace       L0047 ERROR|   File "$HOME/git/avocado/avocado/core/test.py", line 743, in _check_reference_stdout
+	2017-10-16 14:23:02,606 stacktrace       L0047 ERROR|     self.fail('Actual test sdtout differs from expected one')
+	2017-10-16 14:23:02,606 stacktrace       L0047 ERROR|   File "$HOME//git/avocado/avocado/core/test.py", line 983, in fail
+	2017-10-16 14:23:02,607 stacktrace       L0047 ERROR|     raise exceptions.TestFail(message)
+	2017-10-16 14:23:02,607 stacktrace       L0047 ERROR| TestFail: Actual test sdtout differs from expected one
+	2017-10-16 14:23:02,607 stacktrace       L0048 ERROR|
+	2017-10-16 14:23:02,607 test             L0274 DEBUG| DATA (filename=stderr.expected) => $HOME//output_record.sh.data/stderr.expected (found at file source dir)
+	2017-10-16 14:23:02,608 test             L0965 ERROR| FAIL 1-output_record.sh -> TestFail: Actual test sdtout differs from expected one
+
+
+As expected, the test failed because we changed its expectations, so an
+unified diff was logged. The unified diffs are also present in the files
+`stdout.diff` and `stderr.diff`, present in the test results directory::
+
+	$ cat $HOME/avocado/job-results/latest/test-results/1-output_record.sh/stdout.diff
+	--- $HOME/output_record.sh.data/stdout.expected
+	+++ $HOME/avocado/job-results/job-2017-10-16T14.23-8cba866/test-results/1-output_record.sh/stdout
+	@@ -1 +1 @@
+	-Hello, Avocado!
+	+Hello, world!
 
 Test log, stdout and stderr in native Avocado modules
 =====================================================

selftests/functional/test_output_check.py

+import json
 import os
 import tempfile
 import shutil
@@ -15,6 +16,7 @@ basedir = os.path.abspath(basedir)
 AVOCADO = os.environ.get("UNITTEST_AVOCADO_CMD", "./scripts/avocado")
 OUTPUT_SCRIPT_CONTENTS = """#!/bin/sh
 echo "Hello, avocado!"
+echo "Hello, stderr!" >&2
 """
 
 
@@ -98,6 +100,55 @@ class RunnerSimpleTest(unittest.TestCase):
                          (expected_rc, result))
         self.assertIn(tampered_msg, result.stdout)
 
+    def test_output_diff(self):
+        self.test_output_record_all()
+        tampered_msg_stdout = "I PITY THE FOOL THAT STANDS ON STDOUT!"
+        tampered_msg_stderr = "I PITY THE FOOL THAT STANDS ON STDERR!"
+
+        stdout_file = "%s.data/stdout.expected" % self.output_script.path
+        with open(stdout_file, 'w') as stdout_file_obj:
+            stdout_file_obj.write(tampered_msg_stdout)
+
+        stderr_file = "%s.data/stderr.expected" % self.output_script.path
+        with open(stderr_file, 'w') as stderr_file_obj:
+            stderr_file_obj.write(tampered_msg_stderr)
+
+        cmd_line = ('%s run --job-results-dir %s --sysinfo=off %s --json -'
+                    % (AVOCADO, self.tmpdir, self.output_script.path))
+        result = process.run(cmd_line, ignore_status=True)
+        expected_rc = exit_codes.AVOCADO_TESTS_FAIL
+        self.assertEqual(result.exit_status, expected_rc,
+                         "Avocado did not return rc %d:\n%s" %
+                         (expected_rc, result))
+
+        json_result = json.loads(result.stdout)
+        job_log = json_result['debuglog']
+        stdout_diff = os.path.join(json_result['tests'][0]['logdir'],
+                                   'stdout.diff')
+        stderr_diff = os.path.join(json_result['tests'][0]['logdir'],
+                                   'stderr.diff')
+
+        with open(stdout_diff, 'r') as stdout_diff_obj:
+            stdout_diff_content = stdout_diff_obj.read()
+        self.assertIn('-I PITY THE FOOL THAT STANDS ON STDOUT!',
+                      stdout_diff_content)
+        self.assertIn('+Hello, avocado!', stdout_diff_content)
+
+        with open(stderr_diff, 'r') as stderr_diff_obj:
+            stderr_diff_content = stderr_diff_obj.read()
+        self.assertIn('-I PITY THE FOOL THAT STANDS ON STDERR!',
+                      stderr_diff_content)
+        self.assertIn('+Hello, stderr!', stderr_diff_content)
+
+        with open(job_log, 'r') as job_log_obj:
+            job_log_content = job_log_obj.read()
+        self.assertIn('Stdout Diff:', job_log_content)
+        self.assertIn('-I PITY THE FOOL THAT STANDS ON STDOUT!', job_log_content)
+        self.assertIn('+Hello, avocado!', job_log_content)
+        self.assertIn('Stdout Diff:', job_log_content)
+        self.assertIn('-I PITY THE FOOL THAT STANDS ON STDERR!', job_log_content)
+        self.assertIn('+Hello, stderr!', job_log_content)
+
     def test_disable_output_check(self):
         self.test_output_record_all()
         tampered_msg = "I PITY THE FOOL THAT STANDS ON MY WAY!"