Merge pull request #154 from rosswhitfield/make_some_debug_logging_more_useful

Add better debug info from ServiceResponseMessage

Author: rosswhitfield

.github/workflows/conda_env/environment_linux.yml

@@ -6,5 +6,5 @@ dependencies:
 - pytest-timeout
 - psutil
 - mpi4py
-- dask=2021.11.2
+- dask=2021.12.0
 - dakota

.github/workflows/conda_env/environment_macos.yml

@@ -5,4 +5,4 @@ dependencies:
 - pytest-cov
 - pytest-timeout
 - psutil
-- dask=2021.11.2
+- dask=2021.12.0

.github/workflows/conda_env/environment_static_analysis.yml

@@ -7,5 +7,5 @@ dependencies:
 - pylint=2.11.1
 - bandit=1.7.1
 - codespell=2.1.0
-- dask=2021.11.2
+- dask=2021.12.0
 - pytest

ipsframework/ips.py

@@ -350,8 +350,7 @@ def _invoke_framework_comps(self, fwk_comps, method_name):
                     self._dispatch_service_request(msg)
                     continue
                 elif msg.__class__.__name__ == 'MethodResultMessage':
-                    self.debug('Received Result for call %s' %
-                               (msg.call_id))
+                    self.debug('Received Result for call %s', msg.call_id)
                     if msg.call_id not in outstanding_fwk_calls:
                         self.task_manager.return_call(msg)
                     else:

ipsframework/messages.py

@@ -76,6 +76,10 @@ def __init__(self, sender_id, receiver_id, request_msg_id, status, *args):
         self.args = args
         self.message_id = self.get_message_id()
 
+    def __repr__(self):
+        return (f'ServiceResponseMessage(sender_id={self.sender_id}, receiver_id={self.receiver_id}, request_msg_id={self.request_msg_id},'
+                f'status={self.status}, args={self.args}, message_id={self.message_id})')
+
 
 class MethodInvokeMessage(Message):
     r"""

ipsframework/services.py

@@ -229,7 +229,7 @@ def __initialize__(self, component_ref):
             elif pn_compconf.upper() == 'EXCLUSIVE':
                 self.shared_nodes = False
             else:
-                self.fwk.error("Bad 'NODE_ALLOCATION_MODE' value %s" % pn_compconf)
+                self.fwk.error("Bad 'NODE_ALLOCATION_MODE' value %s", pn_compconf)
                 raise Exception("Bad 'NODE_ALLOCATION_MODE' value %s")
         except Exception:
             self.shared_nodes = self.sim_conf['NODE_ALLOCATION_MODE'] == 'SHARED'
@@ -306,13 +306,12 @@ def _wait_msg_response(self, msg_id, block=True):
         :py:meth:`messages.ServiceResponseMessage` when available, otherwise
         ``None``.
         """
-        if msg_id in list(self.finished_calls.keys()):
-            response = self.finished_calls[msg_id]
-            del self.finished_calls[msg_id]
-            return response
-        elif msg_id not in self.incomplete_calls:
-            self.error('Invalid call ID : %s ', str(msg_id))
-            raise Exception('Invalid message request ID argument')
+        try:
+            return self.finished_calls.pop(msg_id)
+        except KeyError:
+            if msg_id not in self.incomplete_calls:
+                self.error('Invalid call ID : %s ', str(msg_id))
+                raise Exception('Invalid message request ID argument')
 
         keep_going = True
         while keep_going:
@@ -340,11 +339,7 @@ def _wait_msg_response(self, msg_id, block=True):
             if not block:
                 keep_going = False
         # if this message corresponds to a finish invocation, return the response message
-        if msg_id in list(self.finished_calls.keys()):
-            response = self.finished_calls[msg_id]
-            del self.finished_calls[msg_id]
-            return response
-        return None
+        return self.finished_calls.pop(msg_id, None)
 
     def _invoke_service(self, component_id, method_name, *args, **keywords):
         r"""
@@ -612,7 +607,7 @@ def launch_task(self, nproc, working_dir, binary, *args, **keywords):
         except KeyError:
             binary_fullpath = ipsutil.which(binary)
         if not binary_fullpath:
-            self.error("Program %s is not in path or is not executable" % binary)
+            self.error("Program %s is not in path or is not executable", binary)
             raise Exception("Program %s is not in path or is not executable" % binary)
         else:
             self.binary_fullpath_cache[binary] = binary_fullpath
@@ -987,18 +982,17 @@ def get_time_loop(self):
         """
         if self.time_loop is not None:
             return self.time_loop
-        sim_conf = self.sim_conf
         tlist = []
-        time_conf = sim_conf['TIME_LOOP']
+        time_conf = self.sim_conf['TIME_LOOP']
 
         def safe(nums):
             return len(set(str(nums)).difference(set("1234567890-+/*.e "))) == 0
         # generate tlist in regular mode (start, finish, step)
         if time_conf['MODE'] == 'REGULAR':
             for entry in ['FINISH', 'START', 'NSTEP']:
                 if not safe(time_conf[entry]):
-                    self.error('Invalid TIME_LOOP value of %s = %s' % (entry, time_conf[entry]))
-                    raise Exception('Invalid TIME_LOOP value of %s = %s' % (entry, time_conf[entry]))
+                    self.error('Invalid TIME_LOOP value of %s = %s', entry, time_conf[entry])
+                    raise ValueError('Invalid TIME_LOOP value of %s = %s' % (entry, time_conf[entry]))
             finish = float(eval(time_conf['FINISH']))
             start = float(eval(time_conf['START']))
             nstep = int(eval(time_conf['NSTEP']))
@@ -1628,7 +1622,7 @@ def merge_current_state(self, partial_state_file, logfile=None, merge_binary=Non
         bin_name = merge_binary if merge_binary else "update_state"
         full_path_binary = ipsutil.which(bin_name)
         if not full_path_binary:
-            self.error("Missing executable %s in PATH" % bin_name)
+            self.error("Missing executable %s in PATH", bin_name)
             raise FileNotFoundError("Missing executable file %s in PATH" % bin_name)
         try:
             msg_id = self._invoke_service(self.fwk.component_id,
@@ -1827,7 +1821,7 @@ def create_sub_workflow(self, sub_name, config_file, override=None, input_dir=No
             sub_conf_new = ConfigObj(infile=config_file, interpolation='template', file_error=True)
             sub_conf_old = ConfigObj(infile=config_file, interpolation='template', file_error=True)
         except Exception:
-            self.exception("Error accessing sub-workflow config file %s" % config_file)
+            self.exception("Error accessing sub-workflow config file %s", config_file)
             raise
         # Update undefined sub workflow configuration entries using top level configuration
         # only applicable to non-component entries (ones with non-dictionary values)
@@ -1983,7 +1977,7 @@ def add_task(self, task_name, nproc, working_dir, binary, *args, **keywords):
             except KeyError:
                 binary_fullpath = ipsutil.which(binary)
             if not binary_fullpath:
-                self.services.error("Program %s is not in path or is not executable" % binary)
+                self.services.error("Program %s is not in path or is not executable", binary)
                 raise Exception("Program %s is not in path or is not executable" % binary)
             else:
                 self.services.binary_fullpath_cache[binary] = binary_fullpath

tests/dakota/test_dakota.py

@@ -21,7 +21,7 @@ def copy_config_and_replace(infile, outfile, tmpdir):
 
 @pytest.mark.skipif(shutil.which('dakota') is None,
                     reason="Requires dakota to run this test")
-@pytest.mark.timeout(120)
+@pytest.mark.timeout(200)
 def test_dakota(tmpdir):
     data_dir = os.path.dirname(__file__)
     copy_config_and_replace(os.path.join(data_dir, "dakota_test_Gaussian.ips"), tmpdir.join("dakota_test_Gaussian.ips"), tmpdir)

tests/new/test_timeloop_checkpoint.py

@@ -1,4 +1,6 @@
-from ipsframework import Framework
+from unittest.mock import MagicMock
+import pytest
+from ipsframework import Framework, ServicesProxy
 
 
 def write_basic_config_and_platform_files(tmpdir, restart=False):
@@ -275,3 +277,53 @@ def test_timeloop_checkpoint_restart(tmpdir):
         assert results_dir.join('TIMELOOP_COMP__timeloop_comp_8').join(f'w1_2_{time}.dat').exists()
         assert results_dir.join('TIMELOOP_COMP2__timeloop_comp_9').join(f'w2_1_{time}.dat').exists()
         assert results_dir.join('TIMELOOP_COMP2__timeloop_comp_9').join(f'w2_2_{time}.dat').exists()
+
+
+def test_TIME_LOOP():
+    sim_conf = {'TIME_LOOP': {'MODE': 'REGULAR',
+                              'START': '0',
+                              'FINISH': '10',
+                              'NSTEP': '10'}}
+    servicesProxy = ServicesProxy(None, None, None, sim_conf, None)
+    tl = servicesProxy.get_time_loop()
+    assert tl == list(range(11))
+
+    sim_conf = {'TIME_LOOP': {'MODE': 'REGULAR',
+                              'START': '0 + 20 / 2',
+                              'FINISH': '13 - 1',
+                              'NSTEP': '2'}}
+    servicesProxy = ServicesProxy(None, None, None, sim_conf, None)
+    tl = servicesProxy.get_time_loop()
+    assert tl == [10, 11, 12]
+
+    sim_conf = {'TIME_LOOP': {'MODE': 'REGULAR',
+                              'START': '10 * 2',
+                              'FINISH': '10 ** 2',
+                              'NSTEP': '2'}}
+    servicesProxy = ServicesProxy(None, None, None, sim_conf, None)
+    tl = servicesProxy.get_time_loop()
+    assert tl == [20, 60, 100]
+
+    sim_conf = {'TIME_LOOP': {'MODE': 'REGULAR',
+                              'START': '1e2',
+                              'FINISH': '5e1',
+                              'NSTEP': '2'}}
+    servicesProxy = ServicesProxy(None, None, None, sim_conf, None)
+    tl = servicesProxy.get_time_loop()
+    assert tl == [100, 75, 50]
+
+    sim_conf = {'TIME_LOOP': {'MODE': 'EXPLICIT',
+                              'VALUES': '7 13 -42 1000'}}
+    servicesProxy = ServicesProxy(None, None, None, sim_conf, None)
+    tl = servicesProxy.get_time_loop()
+    assert tl == [7, 13, -42, 1000]
+
+    sim_conf = {'TIME_LOOP': {'MODE': 'REGULAR',
+                              'START': '1p2',
+                              'FINISH': '10',
+                              'NSTEP': '2'}}
+    servicesProxy = ServicesProxy(None, None, None, sim_conf, None)
+    servicesProxy.error = MagicMock(name='error')
+    with pytest.raises(ValueError) as excinfo:
+        servicesProxy.get_time_loop()
+    assert str(excinfo.value) == "Invalid TIME_LOOP value of START = 1p2"