From 0dfdd3c9b6f6fff56f55183b53e0ab6896cb6ff5 Mon Sep 17 00:00:00 2001 From: Ross Whitfield Date: Fri, 8 Jul 2022 17:03:02 -0400 Subject: [PATCH] Log failed call, should also fix disconnected traces --- ipsframework/services.py | 26 +++++++++---- tests/new/test_bad_components.py | 63 ++++++++++++++++++++++++++++++++ tests/new/test_dask.py | 2 +- 3 files changed, 83 insertions(+), 8 deletions(-) diff --git a/ipsframework/services.py b/ipsframework/services.py index 7d6967b5..f32fe253 100644 --- a/ipsframework/services.py +++ b/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 diff --git a/tests/new/test_bad_components.py b/tests/new/test_bad_components.py index 8aaa13e5..1d6dd32e 100644 --- a/tests/new/test_bad_components.py +++ b/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] diff --git a/tests/new/test_dask.py b/tests/new/test_dask.py index 76aadfc9..08aa16f9 100644 --- a/tests/new/test_dask.py +++ b/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"