Merge pull request #111 from force-h2020/add-more-logging

Added more logging

force_bdss/cli/force_bdss.py

@@ -19,6 +19,8 @@ push_exception_handler(reraise_exceptions=True)
 def run(evaluate, logfile, workflow_filepath):
 
     logging_config = {}
+    logging_config["level"] = logging.INFO
+
     if logfile is not None:
         logging_config["filename"] = logfile
 

force_bdss/cli/tests/test_execution.py

@@ -26,16 +26,19 @@ class TestExecution(unittest.TestCase):
     def test_plain_invocation_mco(self):
         with cd(fixtures.dirpath()):
             try:
-                subprocess.check_output(["force_bdss", "test_empty.json"])
+                subprocess.check_output(["force_bdss", "test_empty.json"],
+                                        stderr=subprocess.STDOUT)
             except subprocess.CalledProcessError:
                 self.fail("force_bdss returned error at plain invocation.")
 
     def test_plain_invocation_evaluate(self):
-        with cd(fixtures.dirpath()):
+        with cd(fixtures.dirpath()), \
+                open(os.devnull, "wb") as devnull:
             proc = subprocess.Popen([
                 "force_bdss", "--evaluate", "test_empty.json"],
                 stdin=subprocess.PIPE,
-                stdout=subprocess.PIPE)
+                stdout=subprocess.PIPE,
+                stderr=devnull)
             proc.communicate(b"1")
             retcode = proc.wait()
             self.assertEqual(retcode, 0)

force_bdss/core_evaluation_driver.py

@@ -35,17 +35,20 @@ class CoreEvaluationDriver(BaseCoreDriver):
             sys.exit(0)
 
         mco_factory = mco_model.factory
+        log.info("Creating communicator")
         mco_communicator = mco_factory.create_communicator()
 
         mco_data_values = _get_data_values_from_mco(
             mco_model, mco_communicator)
 
+        log.info("Computing data layer 1")
         ds_results = _compute_layer_results(
             mco_data_values,
             workflow.data_sources,
             "create_data_source"
         )
 
+        log.info("Computing data layer 2")
         kpi_results = _compute_layer_results(
             ds_results + mco_data_values,
             workflow.kpi_calculators,
@@ -107,7 +110,13 @@ def _compute_layer_results(environment_data_values,
         # execute data source, passing only relevant data values.
         log.info("Evaluating for Data Source {}".format(
             factory.name))
-        res = evaluator.run(model, passed_data_values)
+
+        try:
+            res = evaluator.run(model, passed_data_values)
+        except Exception:
+            log.error("Evaluation could not be performed. Run method raised"
+                      "exception", exc_info=True)
+            raise
 
         if len(res) != len(out_slots):
             error_txt = (
@@ -165,6 +174,9 @@ def _get_data_values_from_mco(model, communicator):
     """
     mco_data_values = communicator.receive_from_mco(model)
 
+    log.info("Received data from MCO: \n{}".format(
+             "\n".join([str(x) for x in mco_data_values])))
+
     if len(mco_data_values) != len(model.parameters):
         error_txt = ("The number of data values returned by"
                      " the MCO ({} values) does not match the"