From c16912ccb841a553389e0af37c569ad73ea72f59 Mon Sep 17 00:00:00 2001 From: Maximilian Linhoff Date: Thu, 28 Nov 2024 14:02:33 +0100 Subject: [PATCH 1/4] Fix order of things when finishing tool, fixes #2661 --- docs/changes/2662.bugfix.rst | 4 ++ src/ctapipe/core/tests/test_tool.py | 86 +++++++++++++++++++++++++ src/ctapipe/core/tool.py | 38 +++++------ src/ctapipe/tools/tests/test_process.py | 20 +++++- 4 files changed, 123 insertions(+), 25 deletions(-) create mode 100644 docs/changes/2662.bugfix.rst diff --git a/docs/changes/2662.bugfix.rst b/docs/changes/2662.bugfix.rst new file mode 100644 index 00000000000..5e806c361b9 --- /dev/null +++ b/docs/changes/2662.bugfix.rst @@ -0,0 +1,4 @@ +Fix order of finalizing ``Component`` instances using ``Tool.enter_context`` +and calling ``Provenance().finish_activity`` in ``ctapipe.core.Tool``. + +Fixes output provenance information missing for e.g. ``ctapipe-process``. diff --git a/src/ctapipe/core/tests/test_tool.py b/src/ctapipe/core/tests/test_tool.py index a9322eb514b..d3a6311c2af 100644 --- a/src/ctapipe/core/tests/test_tool.py +++ b/src/ctapipe/core/tests/test_tool.py @@ -1,7 +1,10 @@ import json import logging import os +import signal +import sys import tempfile +from multiprocessing import Barrier, Process from pathlib import Path import pytest @@ -487,3 +490,86 @@ class MyTool(Tool): assert len(inputs) == 1 assert inputs[0]["role"] == "Tool Configuration" assert inputs[0]["url"] == str(config_path) + + +@pytest.mark.parametrize( + ("exit_code", "expected_status"), + [ + (0, "completed"), + (None, "completed"), + (1, "error"), + (2, "error"), + ], +) +def test_exit_status(exit_code, expected_status, tmp_path, provenance): + """check that the config is correctly in the provenance""" + + class MyTool(Tool): + exit_code = Int(allow_none=True, default_value=None).tag(config=True) + + def start(self): + if self.exit_code is None: + return + + if self.exit_code == 0: + sys.exit(0) + + if self.exit_code == 1: + raise ValueError("Some error happened") + + class CustomError(ValueError): + exit_code = self.exit_code + + raise CustomError("Some error with specific code happened") + + provenance_path = tmp_path / "provlog.json" + run_tool( + MyTool(exit_code=exit_code), + [f"--provenance-log={provenance_path}"], + raises=False, + ) + + activities = json.loads(provenance_path.read_text()) + assert len(activities) == 1 + provlog = activities[0] + assert provlog["status"] == expected_status + + +def test_exit_status_interrupted(tmp_path, provenance): + """check that the config is correctly in the provenance""" + + # to make sure we only kill the process once it is running + barrier = Barrier(2) + + class MyTool(Tool): + name = "test-interrupt" + + def __init__(self, **kwargs): + super().__init__(**kwargs) + + def start(self): + barrier.wait() + signal.pause() + + provenance_path = tmp_path / "provlog.json" + + def main(): + run_tool( + MyTool(), + [f"--provenance-log={provenance_path}", "--log-level=INFO"], + raises=False, + ) + + process = Process(target=main) + process.start() + barrier.wait() + + # process.terminate() + os.kill(process.pid, signal.SIGINT) + process.join() + + activities = json.loads(provenance_path.read_text()) + assert len(activities) == 1 + provlog = activities[0] + assert provlog["activity_name"] == MyTool.name + assert provlog["status"] == "interrupted" diff --git a/src/ctapipe/core/tool.py b/src/ctapipe/core/tool.py index e484c6ef71d..b46acac3321 100644 --- a/src/ctapipe/core/tool.py +++ b/src/ctapipe/core/tool.py @@ -405,6 +405,7 @@ def run(self, argv=None, raises=False): # return codes are taken from: # https://tldp.org/LDP/abs/html/exitcodes.html + status = "completed" exit_status = 0 current_exception = None @@ -430,51 +431,42 @@ def run(self, argv=None, raises=False): self.start() self.finish() - self.log.info("Finished: %s", self.name) - Provenance().finish_activity(activity_name=self.name) except (ToolConfigurationError, TraitError) as err: current_exception = err self.log.error("%s", err) self.log.error("Use --help for more info") exit_status = 2 # wrong cmd line parameter - Provenance().finish_activity( - activity_name=self.name, status="error", exit_code=exit_status - ) + status = "error" except KeyboardInterrupt: self.log.warning("WAS INTERRUPTED BY CTRL-C") exit_status = 130 # Script terminated by Control-C - Provenance().finish_activity( - activity_name=self.name, status="interrupted", exit_code=exit_status - ) + status = "interrupted" except Exception as err: current_exception = err exit_status = getattr(err, "exit_code", 1) + status = "error" self.log.exception("Caught unexpected exception: %s", err) - Provenance().finish_activity( - activity_name=self.name, status="error", exit_code=exit_status - ) except SystemExit as err: exit_status = err.code - if exit_status == 0: - # Finish normally - Provenance().finish_activity(activity_name=self.name) - else: - # Finish with error + if exit_status != 0: + status = "error" current_exception = err self.log.critical( "Caught SystemExit with exit code %s", exit_status ) - Provenance().finish_activity( - activity_name=self.name, - status="error", - exit_code=exit_status, - ) finally: - if not {"-h", "--help", "--help-all"}.intersection(self.argv): - self.write_provenance() if raises and current_exception: + self.write_provenance() raise current_exception + Provenance().finish_activity( + activity_name=self.name, status=status, exit_code=exit_status + ) + + if not {"-h", "--help", "--help-all"}.intersection(self.argv): + self.write_provenance() + + self.log.info("Finished %s", self.name) self.exit(exit_status) def write_provenance(self): diff --git a/src/ctapipe/tools/tests/test_process.py b/src/ctapipe/tools/tests/test_process.py index 49e70144602..b9519d0fac7 100644 --- a/src/ctapipe/tools/tests/test_process.py +++ b/src/ctapipe/tools/tests/test_process.py @@ -3,6 +3,7 @@ Test ctapipe-process on a few different use cases """ +import json from subprocess import CalledProcessError import astropy.units as u @@ -160,17 +161,20 @@ def test_stage1_datalevels(tmp_path): assert isinstance(tool.event_source, DummyEventSource) -def test_stage_2_from_simtel(tmp_path): +def test_stage_2_from_simtel(tmp_path, provenance): """check we can go to DL2 geometry from simtel file""" config = resource_file("stage2_config.json") output = tmp_path / "test_stage2_from_simtel.DL2.h5" + provenance_log = tmp_path / "provenance.log" + input_path = get_dataset_path("gamma_prod5.simtel.zst") run_tool( ProcessorTool(), argv=[ f"--config={config}", - "--input=dataset://gamma_prod5.simtel.zst", + f"--input={input_path}", f"--output={output}", + f"--provenance-log={provenance_log}", "--overwrite", ], cwd=tmp_path, @@ -190,6 +194,18 @@ def test_stage_2_from_simtel(tmp_path): assert dl2["HillasReconstructor_telescopes"].dtype == np.bool_ assert dl2["HillasReconstructor_telescopes"].shape[1] == len(subarray) + activities = json.loads(provenance_log.read_text()) + assert len(activities) == 1 + + activity = activities[0] + assert activity["status"] == "completed" + assert len(activity["input"]) == 2 + assert activity["input"][0]["url"] == str(config) + assert activity["input"][1]["url"] == str(input_path) + + assert len(activity["output"]) == 1 + assert activity["output"][0]["url"] == str(output) + def test_stage_2_from_dl1_images(tmp_path, dl1_image_file): """check we can go to DL2 geometry from DL1 images""" From 41bdb17131870ee3324cacee9e1f0dcd935f05a3 Mon Sep 17 00:00:00 2001 From: Maximilian Linhoff Date: Mon, 2 Dec 2024 20:42:44 +0100 Subject: [PATCH 2/4] Do not pass local func to Process(target=)... --- src/ctapipe/core/tests/test_tool.py | 14 +++----------- 1 file changed, 3 insertions(+), 11 deletions(-) diff --git a/src/ctapipe/core/tests/test_tool.py b/src/ctapipe/core/tests/test_tool.py index d3a6311c2af..29558250fb1 100644 --- a/src/ctapipe/core/tests/test_tool.py +++ b/src/ctapipe/core/tests/test_tool.py @@ -544,23 +544,15 @@ def test_exit_status_interrupted(tmp_path, provenance): class MyTool(Tool): name = "test-interrupt" - def __init__(self, **kwargs): - super().__init__(**kwargs) - def start(self): barrier.wait() signal.pause() provenance_path = tmp_path / "provlog.json" - def main(): - run_tool( - MyTool(), - [f"--provenance-log={provenance_path}", "--log-level=INFO"], - raises=False, - ) - - process = Process(target=main) + args = [f"--provenance-log={provenance_path}", "--log-level=INFO"] + tool = MyTool() + process = Process(target=run_tool, args=(tool, args), kwargs=dict(raises=False)) process.start() barrier.wait() From a287f075963a8f63a536b30d7314d2a761f5878e Mon Sep 17 00:00:00 2001 From: Maximilian Linhoff Date: Tue, 3 Dec 2024 11:26:58 +0100 Subject: [PATCH 3/4] Try to fix test on macos, multiprocessing seems to work different ... --- src/ctapipe/core/tests/test_tool.py | 24 ++++++++++++++---------- 1 file changed, 14 insertions(+), 10 deletions(-) diff --git a/src/ctapipe/core/tests/test_tool.py b/src/ctapipe/core/tests/test_tool.py index 29558250fb1..6a915cce935 100644 --- a/src/ctapipe/core/tests/test_tool.py +++ b/src/ctapipe/core/tests/test_tool.py @@ -535,23 +535,27 @@ class CustomError(ValueError): assert provlog["status"] == expected_status +class InterruptTestTool(Tool): + name = "test-interrupt" + + def __init__(self, barrier): + super().__init__() + self.barrier = barrier + + def start(self): + self.barrier.wait() + signal.pause() + + def test_exit_status_interrupted(tmp_path, provenance): """check that the config is correctly in the provenance""" # to make sure we only kill the process once it is running barrier = Barrier(2) - - class MyTool(Tool): - name = "test-interrupt" - - def start(self): - barrier.wait() - signal.pause() + tool = InterruptTestTool(barrier) provenance_path = tmp_path / "provlog.json" - args = [f"--provenance-log={provenance_path}", "--log-level=INFO"] - tool = MyTool() process = Process(target=run_tool, args=(tool, args), kwargs=dict(raises=False)) process.start() barrier.wait() @@ -563,5 +567,5 @@ def start(self): activities = json.loads(provenance_path.read_text()) assert len(activities) == 1 provlog = activities[0] - assert provlog["activity_name"] == MyTool.name + assert provlog["activity_name"] == InterruptTestTool.name assert provlog["status"] == "interrupted" From b345fc00585d29fcd265d6eaa23bf7e2d23e5261 Mon Sep 17 00:00:00 2001 From: Maximilian Linhoff Date: Tue, 3 Dec 2024 19:01:31 +0100 Subject: [PATCH 4/4] Less technical changelog --- docs/changes/2662.bugfix.rst | 6 ++---- 1 file changed, 2 insertions(+), 4 deletions(-) diff --git a/docs/changes/2662.bugfix.rst b/docs/changes/2662.bugfix.rst index 5e806c361b9..3c5ea534701 100644 --- a/docs/changes/2662.bugfix.rst +++ b/docs/changes/2662.bugfix.rst @@ -1,4 +1,2 @@ -Fix order of finalizing ``Component`` instances using ``Tool.enter_context`` -and calling ``Provenance().finish_activity`` in ``ctapipe.core.Tool``. - -Fixes output provenance information missing for e.g. ``ctapipe-process``. +Fix the order in which ``Tool`` runs final operations to fix an issue +of provenance not being correctly recorded.