Log error output for runtime errors, fix 112

temci/run/run_driver.py

@@ -12,13 +12,13 @@
 import yaml
 
 from temci.build.build_processor import BuildProcessor
-from temci.setup import setup
+from ..setup import setup
 from temci.utils.config_utils import ATTRIBUTES_TYPE
 from temci.utils.settings import Settings
 from temci.utils.sudo_utils import get_bench_user, bench_as_different_user, get_env_setting
 from temci.utils.typecheck import NoInfo
 from temci.utils.util import has_root_privileges, join_strs, does_command_succeed, sphinx_doc, on_apple_os, \
-    does_program_exist, document, proc_wait_with_rusage
+    does_program_exist, document, proc_wait_with_rusage, rusage_header
 from temci.utils.vcs import VCSDriver
 from ..utils.typecheck import *
 from ..utils.registry import AbstractRegistry, register
@@ -759,7 +759,7 @@ def _exec_command(self, cmds: list, block: RunProgramBlock,
             t = time.time()
             proc = subprocess.Popen(["/bin/sh", "-c", executed_cmd],
                                     stdout=subprocess.PIPE if redirect_out else None,
-                                    stderr= subprocess.PIPE if redirect_out else None,
+                                    stderr=subprocess.PIPE if redirect_out else None,
                                     universal_newlines=True,
                                     cwd=cwd,
                                     env=env, )
@@ -775,7 +775,7 @@ def _exec_command(self, cmds: list, block: RunProgramBlock,
                 t = time.time() - t
                 rusage = proc.rusage
             if redirect_out:
-                ExecValidator(block["validator"]).validate(cmd, out, err, proc.poll())
+                ExecValidator(block["validator"]).validate(cmd, clean_output(out), clean_output(err), proc.poll())
             # if proc.poll() > 0:
             #    msg = "Error executing " + cmd + ": "+ str(err) + " " + str(out)
             # logging.error(msg)
@@ -1187,7 +1187,7 @@ def parse_result_impl(self, exec_res: ExecRunDriver.ExecResult,
         if not self.misc["properties"]:
             return
         m = {"__ov-time": exec_res.time}
-        header = open(setup.script_relative("rusage/header.c")).read().split("\"")[1]
+        header = rusage_header()
         lines = exec_res.stderr.strip().split("\n")
         index = 0
         while lines[index] != header:
@@ -1452,7 +1452,7 @@ def __init__(self, block: RunProgramBlock):
         if not does_command_succeed(time_file() + " -v true"):
             raise KeyboardInterrupt("gnu time seems to be not installed and the time runner can therefore not be used")
         fmts = get_av_time_properties_with_format_specifiers()
-        self._time_format_spec = "### " + " ".join(["%" + fmts[prop][1] for prop in self.misc["properties"]])
+        self._time_format_spec = rusage_header() + " " + " ".join(["%" + fmts[prop][1] for prop in self.misc["properties"]])
 
     def setup_block(self, block: RunProgramBlock, cpuset: CPUSet = None, set_id: int = 0):
 
@@ -1466,7 +1466,7 @@ def parse_result_impl(self, exec_res: ExecRunDriver.ExecResult,
         res = res or BenchmarkingResultBlock()
         m = {"__ov-time": exec_res.time}
         for line in reversed(exec_res.stderr.strip().split("\n")):
-            if line.startswith("### "):
+            if line.startswith(rusage_header()):
                 _, *parts = line.strip().split(" ")
                 if len(parts) == len(self.misc["properties"]):
                     for (i, part) in enumerate(parts):
@@ -1523,6 +1523,25 @@ class BenchmarkingError(RuntimeError):
     """
 
 
+def log_program_error(recorded_error: 'RecordedInternalError'):
+    from temci.report.rundata import RecordedProgramError
+    if isinstance(recorded_error, RecordedProgramError):
+        if recorded_error.out:
+            logging.error("output\n\n" + recorded_error.out)
+        if recorded_error.err:
+            logging.error("error\n\n" + recorded_error.err)
+
+
+def header() -> str:
+    """ A header to use for measurement formatting """
+    return rusage_header()
+
+
+def clean_output(output: str) -> str:
+    """ Remove everything after the header """
+    return output.split(header())[0]
+
+
 class BenchmarkingProgramError(BenchmarkingError):
     """
     Thrown when the benchmarked program fails

temci/run/run_processor.py

@@ -13,7 +13,7 @@
 from temci.utils.typecheck import *
 from temci.run.run_worker_pool import RunWorkerPool, ParallelRunWorkerPool, AbstractRunWorkerPool
 from temci.run.run_driver import RunProgramBlock, BenchmarkingResultBlock, RunDriverRegistry, ExecRunDriver, \
-    is_perf_available, filter_runs
+    is_perf_available, filter_runs, log_program_error
 import temci.run.run_driver_plugin
 from temci.report.rundata import RunDataStatsHelper, RunData
 from temci.utils.settings import Settings
@@ -275,6 +275,7 @@ def _benchmarking_block_run(self, block_size: int = None, discard: bool = False,
                             self.stats_helper.add_data_block(id, result.data)
                         self.stats_helper.add_error(id, result.recorded_error)
                     logging.error("Program block no. {} failed: {}".format(id, result.error))
+                    log_program_error(result.recorded_error)
                     logging.debug("".join(traceback.format_exception(None, result.error, result.error.__traceback__)))
                     self.store_erroneous()
                     if isinstance(result.error, KeyboardInterrupt):

temci/scripts/rusage/header.c

@@ -1,4 +1,4 @@
 #ifndef HEADER
 #define HEADER
-char* header = "#### #### #### rusage 0025988cff4c83472c1c77ea23f3c0a344004a826c7b2631bc51a9825a9a3b21eeeedd54c89134f089e57aaa947e56b755ecc0c0e5e802c96837727484c951ad";
+char* header = "####0025988cff4c83472c1c77ea23f3c0a344004a826c7b2631bc51a9825a9a3b21eeeedd54c89134f089e57aaa947e56b755ecc0c0e5e802c96837727484c951ad";
 #endif

temci/utils/util.py

@@ -1,7 +1,7 @@
 """
 Utility functions and classes that don't depend on the rest of the temci code base.
 """
-
+import functools
 import os
 import resource
 import subprocess
@@ -329,4 +329,10 @@ def parse_timespan(time: str) -> float:
     :param time: time span expression, mixture of different time units is possible
     :return: time span in seconds
     """
-    return pytimeparse.parse(time) if time != "-1" else -1
+    return pytimeparse.parse(time) if time != "-1" else -1
+
+
+@functools.lru_cache()
+def rusage_header() -> str:
+    from ..setup.setup import script_relative
+    return open(script_relative("rusage/header.c")).read().split("\"")[1]