Merge pull request #165 from rosswhitfield/log_failed_call

Log failed call, should also fix disconnected traces

ipsframework/services.py

@@ -538,16 +538,28 @@ def wait_call(self, call_id, block=True):
             raise
         msg_id = self._invoke_service(self.fwk.component_id, 'wait_call',
                                       call_id, block)
-        response = self._get_service_response(msg_id, block=True)
         formatted_args = ','.join('%.3f' % (x) if isinstance(x, float)
                                   else str(x) for x in args)
         target_full = f'{target}:{method_name}({formatted_args})'
-        self._send_monitor_event('IPS_CALL_END', 'Target = ' + target_full,
-                                 start_time=start_time,
-                                 end_time=time.time(),
-                                 elapsed_time=time.time()-start_time,
-                                 target=target,
-                                 operation=f'{method_name}({formatted_args})')
+        try:
+            response = self._get_service_response(msg_id, block=True)
+            self._send_monitor_event('IPS_CALL_END', 'Target = ' + target_full,
+                                     start_time=start_time,
+                                     end_time=time.time(),
+                                     elapsed_time=time.time()-start_time,
+                                     target=target,
+                                     operation=f'{method_name}({formatted_args})')
+        except Exception as e:
+            self._send_monitor_event('IPS_CALL_END',
+                                     f'Error: "{e}" Target = {target_full}',
+                                     start_time=start_time,
+                                     end_time=time.time(),
+                                     elapsed_time=time.time()-start_time,
+                                     target=target,
+                                     operation=f'{method_name}({formatted_args})',
+                                     ok=False)
+            raise
+
         del self.call_targets[call_id]
         return response
 

tests/new/test_bad_components.py

@@ -1,3 +1,5 @@
+import os
+import json
 from ipsframework import Framework
 
 
@@ -84,6 +86,23 @@ def test_exception(tmpdir):
     assert "WORKER__exception_worker_2 ERROR    Uncaught Exception in component method.\n" in lines
     assert "DRIVER__driver_1 ERROR    Uncaught Exception in component method.\n" in lines
 
+    # check event log
+    events = read_event_log(tmpdir)
+    assert len(events) == 11
+
+    worker_call_end_event = events[8]
+
+    assert worker_call_end_event["code"] == "DRIVER__driver"
+    assert worker_call_end_event["eventtype"] == "IPS_CALL_END"
+    assert not worker_call_end_event['ok']
+    assert worker_call_end_event["comment"] == "Error: \"Runtime error\" Target = test@exception_worker@2:step(0)"
+
+    sim_end_event = events[10]
+    assert sim_end_event["code"] == "Framework"
+    assert sim_end_event["eventtype"] == "IPS_END"
+    assert not sim_end_event['ok']
+    assert sim_end_event["comment"] == "Simulation Execution Error"
+
 
 def test_bad_task(tmpdir):
     platform_file, config_file = write_basic_config_and_platform_files(tmpdir, worker='bad_task_worker')
@@ -111,6 +130,23 @@ def test_bad_task(tmpdir):
     assert "WORKER__bad_task_worker_2 ERROR    Uncaught Exception in component method.\n" in lines
     assert "DRIVER__driver_1 ERROR    Uncaught Exception in component method.\n" in lines
 
+    # check event log
+    events = read_event_log(tmpdir)
+    assert len(events) == 11
+
+    worker_call_end_event = events[8]
+
+    assert worker_call_end_event["code"] == "DRIVER__driver"
+    assert worker_call_end_event["eventtype"] == "IPS_CALL_END"
+    assert not worker_call_end_event['ok']
+    assert worker_call_end_event["comment"] == "Error: \"task binary of wrong type, expected str but found int\" Target = test@bad_task_worker@2:step(0)"
+
+    sim_end_event = events[10]
+    assert sim_end_event["code"] == "Framework"
+    assert sim_end_event["eventtype"] == "IPS_END"
+    assert not sim_end_event['ok']
+    assert sim_end_event["comment"] == "Simulation Execution Error"
+
 
 def test_bad_task_pool1(tmpdir):
     platform_file, config_file = write_basic_config_and_platform_files(tmpdir, worker='bad_task_pool_worker1')
@@ -192,3 +228,30 @@ def test_assign_protected_attribute(tmpdir):
 
     assert "WORKER__assign_protected_attribute_2 ERROR    Uncaught Exception in component method.\n" in lines
     assert "DRIVER__driver_1 ERROR    Uncaught Exception in component method.\n" in lines
+
+    # check event log
+    events = read_event_log(tmpdir)
+    assert len(events) == 11
+
+    worker_call_end_event = events[8]
+
+    assert worker_call_end_event["code"] == "DRIVER__driver"
+    assert worker_call_end_event["eventtype"] == "IPS_CALL_END"
+    assert not worker_call_end_event['ok']
+    # python 3.10 includes the attribute name in the error message
+    assert worker_call_end_event["comment"] in ("Error: \"can't set attribute\" Target = test@assign_protected_attribute@2:step(0)",
+                                                "Error: \"can't set attribute 'args'\" Target = test@assign_protected_attribute@2:step(0)")
+
+    sim_end_event = events[10]
+    assert sim_end_event["code"] == "Framework"
+    assert sim_end_event["eventtype"] == "IPS_END"
+    assert not sim_end_event['ok']
+    assert sim_end_event["comment"] == "Simulation Execution Error"
+
+
+def read_event_log(tmpdir):
+    sim_event_log_json = next(f for f in os.listdir(tmpdir.join("simulation_log")) if f.endswith(".json"))
+    with open(str(tmpdir.join("simulation_log").join(sim_event_log_json)), 'r') as f:
+        lines = f.readlines()
+
+    return [json.loads(line) for line in lines]

tests/new/test_dask.py

@@ -154,7 +154,7 @@ def test_dask_shifter_fail(tmpdir):
     with open(json_files[0], 'r') as json_file:
         lines = json_file.readlines()
     lines = [json.loads(line.strip()) for line in lines]
-    assert len(lines) == 12
+    assert len(lines) == 13
 
     assert lines[-1].get('eventtype') == "IPS_END"
     assert lines[-1].get('comment') == "Simulation Execution Error"