pkgtest: print the contents of the output files when the comparison fails

Author: steve-s

com.oracle.truffle.r.test.packages/pkgtest/__init__.py

@@ -592,6 +592,24 @@ def _gnur_install_test(forwarded_args, pkgs, gnur_libinstall, gnur_install_tmp):
     log_step('END', 'install/test', 'GnuR')
 
 
+def get_contents(files):
+    def robust_readlines(file):
+        try:
+            with open(file) as f:
+                return f.readlines()
+        except:
+            return ["Could not read the contents of " + file]
+
+    # normalize to a list
+    list = [files] if isinstance(files, str) else files
+    # print contents of all the files
+    '\n'.join([format_contents(x, robust_readlines(x)) for x in list])
+
+
+def format_contents(filename, contents):
+    return '\n' + filename + "\n########\n{0}########".format('\n'.join(contents))
+
+
 def _set_test_status(fastr_test_info):
     def _failed_outputs(outputs):
         '''
@@ -619,13 +637,14 @@ def _failed_outputs(outputs):
             # What this likely means is that some native package is not
             # installed on the system so GNUR can't run the tests.
             # Ideally this never happens.
-            logging.info("{0}: GnuR test had .fail outputs: {1}".format(pkg, str([s + '.fail' for s in gnur_failed_outputs])))
+            failed_outputs = [s + '.fail' for s in gnur_failed_outputs]
+            logging.info("{0}: GnuR test had .fail outputs: {1}\n{2}".format(pkg, str(failed_outputs), get_contents(failed_outputs)))
 
         fastr_failed_outputs = _failed_outputs(fastr_outputs)
         if fastr_failed_outputs:
             # In addition to the similar comment for GNU R, this can happen
             # if, say, the JVM crashes (possible with native code packages)
-            logging.info("{0}: FastR test had .fail outputs: {1}".format(pkg, str(fastr_failed_outputs)))
+            logging.info("{0}: FastR test had .fail outputs: {1}\n{2}".format(pkg, str(fastr_failed_outputs), get_contents(fastr_failed_outputs)))
             fastr_test_status.set_status_code("FAILED")
 
         # Now for each successful GNU R output we compare content (assuming FastR didn't fail)
@@ -665,6 +684,7 @@ def _failed_outputs(outputs):
 
             # first, parse file and see if a known test framework has been used
             detected, ok, skipped, failed = handle_output_file(fastr_testfile_status.abspath, fastr_content)
+            log_files = False
             if detected:
                 # If a test framework is used, also parse the summary generated by GnuR to compare numbers.
                 detected, gnur_ok, gnur_skipped, gnur_failed = handle_output_file(gnur_testfile_status.abspath,
@@ -676,9 +696,11 @@ def _failed_outputs(outputs):
 
                 if not fastr_invalid_numbers and total_fastr != total_gnur:
                     logging.info(
-                        "Different number of tests executed. FastR = {} vs. GnuR = {}".format(total_fastr, total_gnur))
+                        "Different number of tests executed. FastR = {} vs. GnuR = {}\n".format(total_fastr, total_gnur))
+                    log_files = True
                 elif fastr_invalid_numbers:
                     logging.info("FastR reported invalid numbers of executed tests.")
+                    log_files = True
 
                 if fastr_invalid_numbers or total_fastr > total_gnur:
                     # If FastR's numbers are invalid or GnuR ran fewer tests than FastR, we cannot trust the FastR numbers
@@ -705,17 +727,24 @@ def _failed_outputs(outputs):
                     fastr_test_status.set_status_code("INDETERMINATE")
                     # we don't know how many tests are in there, so consider the whole file to be one big skipped test
                     fastr_testfile_status.set_report(0, 1, 0)
+                    log_files = True
                 elif result != 0:
                     fastr_test_status.set_status_code("FAILED")
                     fastr_testfile_status.status = "FAILED"
                     fastr_testfile_status.set_report(n_tests_passed, 0, n_tests_failed)
                     logging.info("{0}: FastR output mismatch: {1}".format(pkg, gnur_test_output_relpath))
                     logging.info("    output mismatch file: {0}".format(join(_pkg_testdir(RVM_FASTR, pkg), gnur_test_output_relpath)))
                     logging.info("    output mismatch file: {0}".format(join(_pkg_testdir(RVM_GNUR, pkg), gnur_test_output_relpath)))
+                    log_files = True
                 else:
                     fastr_testfile_status.status = "OK"
                     fastr_testfile_status.set_report(n_tests_passed, 0, n_tests_failed)
 
+            # print out the full output files if the test failed
+            if log_files:
+                logging.info(format_contents(gnur_testfile_status.abspath, gnur_content) + format_contents(
+                    fastr_testfile_status.abspath, fastr_content))
+
         # we started out as UNKNOWN
         if not (fastr_test_status.status == "INDETERMINATE" or fastr_test_status.status == "FAILED"):
             fastr_test_status.set_status_code("OK")

com.oracle.truffle.r.test.packages/pkgtest/fuzzy_compare.py

@@ -1,5 +1,5 @@
 #
-# Copyright (c) 2019, Oracle and/or its affiliates. All rights reserved.
+# Copyright (c) 2019, 2020, Oracle and/or its affiliates. All rights reserved.
 # DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
 #
 # This code is free software; you can redistribute it and/or modify it
@@ -45,10 +45,12 @@ def fuzzy_compare(gnur_content, fastr_content, gnur_filename, fastr_filename, cu
     fastr_start = _find_start(fastr_content)
     fastr_len = len(fastr_content)
     if not gnur_start or not gnur_end or not fastr_start:
-        if not gnur_start or not gnur_end:
-            logging.info("malformed GnuR output file {0}: ########\n{1}########".format(gnur_filename, gnur_content))
+        if not gnur_start:
+            logging.info("malformed start of the GnuR output")
+        if not gnur_end:
+            logging.info("malformed end of the GnuR output")
         if not fastr_start:
-            logging.info("malformed FastR output file {0}: ########\n{1}########".format(fastr_filename, fastr_content))
+            logging.info("malformed start of the FastR output")
         return -1, 0, 0
     gnur_i = gnur_start
     fastr_i = fastr_start
@@ -72,7 +74,7 @@ def fuzzy_compare(gnur_content, fastr_content, gnur_filename, fastr_filename, cu
         if gnur_line is None or fastr_line is None:
             # fail if FastR's output is shorter than GnuR's
             if gnur_line is not None and fastr_line is None:
-                logging.debug("FastR's output is shorter than GnuR's")
+                logging.info("FastR's output is shorter than GnuR's")
                 overall_result = 1
             break
 
@@ -131,9 +133,9 @@ def fuzzy_compare(gnur_content, fastr_content, gnur_filename, fastr_filename, cu
 
         # report a mismatch or success
         if result == 1:
-            logging.debug(gnur_filename + ':%d' % (gnur_cur_statement_start + 1) + ' vs. ' + fastr_filename + ':%d' % (
+            logging.info(gnur_filename + ':%d' % (gnur_cur_statement_start + 1) + ' vs. ' + fastr_filename + ':%d' % (
                     fastr_cur_statement_start + 1))
-            logging.debug("%s\nvs.\n%s" % (gnur_line.strip(), fastr_line.strip()))
+            logging.info("%s\nvs.\n%s" % (gnur_line.strip(), fastr_line.strip()))
 
             # we need to synchronize the indices such that we can continue
             gnur_i = gnur_i + 1