Merge pull request #138 from force-h2020/core-mco-driver-for-new-workflow-reader

More robust logging for BDSS

force_bdss/core_evaluation_driver.py

@@ -31,7 +31,16 @@ class CoreEvaluationDriver(BaseCoreDriver):
 
         mco_factory = mco_model.factory
         log.info("Creating communicator")
-        mco_communicator = mco_factory.create_communicator()
+        try:
+            mco_communicator = mco_factory.create_communicator()
+        except Exception:
+            log.exception(
+                "Unable to create communicator from MCO factory '{}' "
+                "in plugin '{}'. This may indicate a programming "
+                "error in the plugin".format(
+                    mco_factory.id,
+                    mco_factory.plugin.id))
+            raise
 
         mco_data_values = _get_data_values_from_mco(
             mco_model, mco_communicator)
@@ -85,7 +94,16 @@ def _compute_layer_results(environment_data_values,
 
     for model in layer.data_sources:
         factory = model.factory
-        data_source = factory.create_data_source()
+        try:
+            data_source = factory.create_data_source()
+        except Exception:
+            log.exception(
+                "Unable to create data source from factory '{}' "
+                "in plugin '{}'. This may indicate a programming "
+                "error in the plugin".format(
+                    factory.id,
+                    factory.plugin.id))
+            raise
 
         # Get the slots for this data source. These must be matched to
         # the appropriate values in the environment data values.
@@ -111,8 +129,9 @@ def _compute_layer_results(environment_data_values,
         try:
             res = data_source.run(model, passed_data_values)
         except Exception:
-            log.error("Evaluation could not be performed. Run method raised"
-                      "exception", exc_info=True)
+            log.exception(
+                "Evaluation could not be performed. "
+                "Run method raised exception.")
             raise
 
         if len(res) != len(out_slots):

force_bdss/core_mco_driver.py

@@ -8,10 +8,6 @@ from force_bdss.mco.base_mco import BaseMCO
 from force_bdss.notification_listeners.base_notification_listener import \
     BaseNotificationListener
 from .base_core_driver import BaseCoreDriver
-from .io.workflow_reader import (
-    InvalidVersionException,
-    InvalidFileException
-)
 from .core_driver_events import MCOStartEvent, MCOFinishEvent, MCOProgressEvent
 
 log = logging.getLogger(__name__)
@@ -29,7 +25,24 @@ class CoreMCODriver(BaseCoreDriver):
 
     @on_trait_change("application:started")
     def application_started(self):
-        self.mco.run(self.workflow.mco)
+        try:
+            mco = self.mco
+        except Exception:
+            log.exception(
+                "Unable to obtain MCO with id '{}' from plugin '{}'."
+            )
+            sys.exit(1)
+
+        try:
+            mco.run(self.workflow.mco)
+        except Exception:
+            log.exception(
+                "Method run() of MCO with id '{}' from plugin '{}' "
+                "raised exception. This might indicate a "
+                "programming error in the plugin.".format(
+                    mco.factory.id,
+                    mco.factory.plugin.id))
+            sys.exit(1)
 
     @on_trait_change("application:stopping")
     def application_stopping(self):
@@ -40,9 +53,9 @@ class CoreMCODriver(BaseCoreDriver):
     def _mco_default(self):
         try:
             workflow = self.workflow
-        except (InvalidVersionException, InvalidFileException) as e:
-            log.exception(e)
-            sys.exit(1)
+        except Exception:
+            log.exception("Unable to open workflow file.")
+            raise
 
         mco_model = workflow.mco
         if mco_model is None:
@@ -50,7 +63,17 @@ class CoreMCODriver(BaseCoreDriver):
             sys.exit(0)
 
         mco_factory = mco_model.factory
-        return mco_factory.create_optimizer()
+        try:
+            optimizer = mco_factory.create_optimizer()
+        except Exception:
+            log.exception("Unable to instantiate optimizer for mco '{}' in "
+                          "plugin '{}'. An exception was raised. "
+                          "This might indicate a programming error in the "
+                          "plugin.".format(mco_factory.id,
+                                           mco_factory.plugin.id))
+            raise
+
+        return optimizer
 
     @on_trait_change("mco:started")
     def _deliver_start_event(self):
@@ -80,11 +103,13 @@ class CoreMCODriver(BaseCoreDriver):
         for listener in self.listeners[:]:
             try:
                 listener.deliver(event)
-            except Exception as e:
-                log.error(
-                    "Exception while delivering to listener {}: {}".format(
-                        listener.__class__.__name__,
-                        str(e)
+            except Exception:
+                log.exception(
+                    "Exception while delivering to listener "
+                    "'{}' in plugin '{}'. The listener will be dropped and "
+                    "computation will continue.".format(
+                        listener.factory.id,
+                        listener.factory.plugin.id
                     ))
                 self._finalize_listener(listener)
                 self.listeners.remove(listener)
@@ -96,14 +121,30 @@ class CoreMCODriver(BaseCoreDriver):
             factory = nl_model.factory
             try:
                 listener = factory.create_listener()
+            except Exception:
+                log.exception(
+                    "Failed to create listener with id '{}' in plugin '{}'. "
+                    "This may indicate a programming error in the "
+                    "plugin.".format(
+                        factory.id,
+                        factory.plugin.id
+                    )
+                )
+                raise
+
+            try:
                 listener.initialize(nl_model)
-            except Exception as e:
-                log.error(
-                    "Failed to create or initialize "
-                    "listener with id {}: {}".format(
-                        factory.id, str(e)))
-            else:
-                listeners.append(listener)
+            except Exception:
+                log.exception(
+                    "Failed to initialize listener with id '{}' in "
+                    "plugin '{}'. The listener will be dropped.".format(
+                        factory.id,
+                        factory.plugin.id
+                    )
+                )
+                continue
+
+            listeners.append(listener)
 
         return listeners
 
@@ -114,9 +155,10 @@ class CoreMCODriver(BaseCoreDriver):
         """
         try:
             listener.finalize()
-        except Exception as e:
-            log.error(
-                "Exception while finalizing listener {}: {}".format(
-                    listener.__class__.__name__,
-                    str(e)
+        except Exception:
+            log.exception(
+                "Exception while finalizing listener '{}'"
+                " in plugin '{}'.".format(
+                    listener.factory.id,
+                    listener.factory.plugin.id
                 ))

force_bdss/tests/probe_classes/mco.py

-from traits.api import Bool, Int, Function
+from traits.api import Bool, Int, Function, Any
 
 from force_bdss.core.data_value import DataValue
 from force_bdss.api import (
@@ -71,6 +71,12 @@ class ProbeMCOFactory(BaseMCOFactory):
     raises_on_create_optimizer = Bool(False)
     raises_on_create_communicator = Bool(False)
 
+    optimizer = Any()
+
+    def __init__(self, *args, **kwargs):
+        super(ProbeMCOFactory, self).__init__(*args, **kwargs)
+        self.optimizer = self.optimizer_class(self)
+
     def get_identifier(self):
         return "probe_mco"
 
@@ -107,7 +113,7 @@ class ProbeMCOFactory(BaseMCOFactory):
         if self.raises_on_create_optimizer:
             raise Exception("ProbeMCOFactory.create_optimizer")
 
-        return self.optimizer_class(self)
+        return self.optimizer
 
     def parameter_factories(self):
         return [ProbeParameterFactory(mco_factory=self)]

force_bdss/tests/test_core_evaluation_driver.py

@@ -288,3 +288,47 @@ class TestCoreEvaluationDriver(unittest.TestCase):
         kpi_results = execute_workflow(wf, data_values)
         self.assertEqual(len(kpi_results), 1)
         self.assertEqual(kpi_results[0].value, 8750)
+
+    def test_mco_communicator_broken(self):
+        self.registry.mco_factories[0].raises_on_create_communicator = True
+        driver = CoreEvaluationDriver(
+            application=self.mock_application,
+        )
+
+        with testfixtures.LogCapture() as capture:
+            with self.assertRaises(Exception):
+                driver.application_started()
+            capture.check(
+                ('force_bdss.core_evaluation_driver', 'INFO',
+                 'Creating communicator'),
+                ("force_bdss.core_evaluation_driver",
+                 "ERROR",
+                 'Unable to create communicator from MCO factory '
+                 "'force.bdss.enthought.plugin.test.v0"
+                 ".factory.probe_mco' in plugin "
+                 "'force.bdss.enthought.plugin.test.v0'. "
+                 "This may indicate a programming error in the plugin"))
+
+    def test_data_source_broken(self):
+        factory = self.registry.data_source_factories[0]
+        factory.raises_on_create_data_source = True
+        driver = CoreEvaluationDriver(
+            application=self.mock_application,
+        )
+
+        with testfixtures.LogCapture() as capture:
+            with self.assertRaises(Exception):
+                driver.application_started()
+            capture.check(
+                ('force_bdss.core_evaluation_driver', 'INFO',
+                 'Creating communicator'),
+                ('force_bdss.core_evaluation_driver', 'INFO',
+                 'Received data from MCO: \n'),
+                ('force_bdss.core_evaluation_driver', 'INFO',
+                 'Computing data layer 0'),
+                ('force_bdss.core_evaluation_driver', 'ERROR',
+                 'Unable to create data source from factory '
+                 "'force.bdss.enthought.plugin.test.v0"
+                 ".factory.probe_data_source' in plugin "
+                 "'force.bdss.enthought.plugin.test.v0'. "
+                 "This may indicate a programming error in the plugin"))

force_bdss/tests/test_core_mco_driver.py

@@ -91,9 +91,11 @@ class TestCoreMCODriver(unittest.TestCase):
             capture.check(
                 ("force_bdss.core_mco_driver",
                  "ERROR",
-                 "Failed to create or initialize listener with id "
-                 "force.bdss.enthought.plugin.test.v0"
-                 ".factory.probe_notification_listener: "))
+                 "Failed to initialize listener with id "
+                 "'force.bdss.enthought.plugin.test.v0"
+                 ".factory.probe_notification_listener' in plugin "
+                 "'force.bdss.enthought.plugin.test.v0'. "
+                 "The listener will be dropped."))
 
             self.assertEqual(len(listeners), 0)
 
@@ -111,7 +113,10 @@ class TestCoreMCODriver(unittest.TestCase):
                 ("force_bdss.core_mco_driver",
                  "ERROR",
                  "Exception while delivering to listener "
-                 "ProbeNotificationListener: "))
+                 "'force.bdss.enthought.plugin.test.v0"
+                 ".factory.probe_notification_listener' in plugin "
+                 "'force.bdss.enthought.plugin.test.v0'. The listener will "
+                 "be dropped and computation will continue."))
 
     def test_finalize_error(self):
         driver = CoreMCODriver(
@@ -127,4 +132,73 @@ class TestCoreMCODriver(unittest.TestCase):
                 ("force_bdss.core_mco_driver",
                  "ERROR",
                  "Exception while finalizing listener "
-                 "ProbeNotificationListener: "))
+                 "'force.bdss.enthought.plugin.test.v0"
+                 ".factory.probe_notification_listener' in plugin "
+                 "'force.bdss.enthought.plugin.test.v0'."))
+
+    def test_listener_creation_error(self):
+        driver = CoreMCODriver(
+            application=self.mock_application,
+        )
+        registry = self.factory_registry_plugin
+        nl_factory = registry.notification_listener_factories[0]
+        nl_factory.raises_on_create_listener = True
+
+        with LogCapture() as capture:
+            with self.assertRaises(Exception):
+                driver.listeners
+            capture.check(('force_bdss.core_mco_driver',
+                           'ERROR',
+                           'Failed to create listener with id '
+                           "'force.bdss.enthought.plugin.test.v0"
+                           ".factory.probe_notification_listener' "
+                           "in plugin 'force.bdss.enthought.plugin"
+                           ".test.v0'. This may indicate a "
+                           'programming error in the plugin.'),)
+
+    def test_create_optimizer_error(self):
+        driver = CoreMCODriver(
+            application=self.mock_application,
+        )
+        registry = self.factory_registry_plugin
+        mco_factory = registry.mco_factories[0]
+        mco_factory.raises_on_create_optimizer = True
+
+        with LogCapture() as capture:
+            with self.assertRaises(Exception):
+                driver.mco
+            capture.check(('force_bdss.core_mco_driver',
+                           'ERROR',
+                           'Unable to instantiate optimizer for mco '
+                           "'force.bdss.enthought.plugin.test.v0"
+                           ".factory.probe_mco' in plugin "
+                           "'force.bdss.enthought.plugin.test.v0'. "
+                           "An exception was raised. This might "
+                           'indicate a programming error in the plugin.'),)
+
+        with LogCapture() as capture:
+            with self.assertRaises(SystemExit):
+                driver.application_started()
+
+    def test_mco_run_exception(self):
+        def run_func(*args, **kwargs):
+            raise Exception("run_func")
+
+        driver = CoreMCODriver(
+            application=self.mock_application,
+        )
+        registry = self.factory_registry_plugin
+        mco_factory = registry.mco_factories[0]
+        mco_factory.optimizer.run_function = run_func
+
+        with LogCapture() as capture:
+            with self.assertRaises(SystemExit):
+                driver.application_started()
+            capture.check(('force_bdss.core_mco_driver',
+                           'ERROR',
+                           'Method run() of MCO with id '
+                           "'force.bdss.enthought.plugin.test.v0"
+                           ".factory.probe_mco' from plugin "
+                           "'force.bdss.enthought.plugin.test.v0'"
+                           " raised exception. This might indicate "
+                           'a programming error in the plugin.'),)