From c0328389f174702759dbf75dde2fc6c6647cda73 Mon Sep 17 00:00:00 2001
From: Josh Usiskin <56369778+jusiskin@users.noreply.github.com>
Date: Fri, 6 Oct 2023 15:07:02 -0500
Subject: [PATCH] feat: log completed session actions (#49)

Signed-off-by: Josh Usiskin <56369778+jusiskin@users.noreply.github.com>
Signed-off-by: Graeme McHale <gmchale@amazon.com>
---
 src/deadline_worker_agent/sessions/session.py |  14 ++-
 test/unit/sessions/test_session.py            | 100 ++++++++++++++++++
 2 files changed, 111 insertions(+), 3 deletions(-)

diff --git a/src/deadline_worker_agent/sessions/session.py b/src/deadline_worker_agent/sessions/session.py
index 43e4f548..20144fe0 100644
--- a/src/deadline_worker_agent/sessions/session.py
+++ b/src/deadline_worker_agent/sessions/session.py
@@ -997,6 +997,9 @@ def _action_updated_impl(
             # UpdateWorkerSchedule request if so.
             self._current_action = None
 
+        completed_status = OPENJD_ACTION_STATE_TO_DEADLINE_COMPLETED_STATUS.get(
+            action_status.state, None
+        )
         self._report_action_update(
             SessionActionStatus(
                 id=current_action.definition.id,
@@ -1004,11 +1007,16 @@ def _action_updated_impl(
                 start_time=current_action.start_time,
                 end_time=now if action_status.state != ActionState.RUNNING else None,
                 update_time=now if action_status.state == ActionState.RUNNING else None,
-                completed_status=OPENJD_ACTION_STATE_TO_DEADLINE_COMPLETED_STATUS.get(
-                    action_status.state, None
-                ),
+                completed_status=completed_status,
             )
         )
+        logger.info(
+            "[%s] Action %s: %s completed as %s",
+            self.id,
+            current_action.definition.id,
+            current_action.definition.human_readable(),
+            completed_status,
+        )
 
     def _sync_asset_outputs(
         self,
diff --git a/test/unit/sessions/test_session.py b/test/unit/sessions/test_session.py
index 78904756..9ea2581b 100644
--- a/test/unit/sessions/test_session.py
+++ b/test/unit/sessions/test_session.py
@@ -212,6 +212,34 @@ def failed_action_status(request: pytest.FixtureRequest) -> ActionStatus:
     return request.param
 
 
+@pytest.fixture(
+    params=(
+        ActionStatus(
+            exit_code=1,
+            state=ActionState.CANCELED,
+        ),
+        ActionStatus(
+            exit_code=1,
+            state=ActionState.CANCELED,
+            fail_message="canceled message",
+        ),
+        ActionStatus(
+            exit_code=1,
+            state=ActionState.CANCELED,
+            progress=50,
+        ),
+    ),
+    ids=(
+        "no-fail-msg-progress",
+        "no-progress",
+        "no-fail-msg",
+    ),
+)
+def canceled_action_status(request: pytest.FixtureRequest) -> ActionStatus:
+    """A fixture providing a canceled Open Job Description ActionStatus"""
+    return request.param
+
+
 @pytest.fixture(
     params=(
         ActionStatus(
@@ -1147,6 +1175,78 @@ def test_success_task_run_fail_output_sync(
         assert session._current_action is None, "Current session action emptied"
         mock_sync_asset_outputs.assert_called_once_with(current_action=current_action)
 
+    def test_logs_succeeded(
+        self,
+        action_complete_time: datetime,
+        current_action: CurrentAction,
+        mock_mod_logger: MagicMock,
+        session: Session,
+        succeess_action_status: ActionStatus,
+    ) -> None:
+        """Tests that succeeded actions are logged"""
+        # WHEN
+        session._action_updated_impl(
+            action_status=succeess_action_status,
+            now=action_complete_time,
+        )
+
+        # THEN
+        mock_mod_logger.info.assert_called_once_with(
+            "[%s] Action %s: %s completed as %s",
+            session.id,
+            current_action.definition.id,
+            current_action.definition.human_readable(),
+            "SUCCEEDED",
+        )
+
+    def test_logs_failed(
+        self,
+        action_complete_time: datetime,
+        current_action: CurrentAction,
+        mock_mod_logger: MagicMock,
+        session: Session,
+        failed_action_status: ActionStatus,
+    ) -> None:
+        """Tests that failed actions are logged"""
+        # WHEN
+        session._action_updated_impl(
+            action_status=failed_action_status,
+            now=action_complete_time,
+        )
+
+        # THEN
+        mock_mod_logger.info.assert_called_once_with(
+            "[%s] Action %s: %s completed as %s",
+            session.id,
+            current_action.definition.id,
+            current_action.definition.human_readable(),
+            "FAILED",
+        )
+
+    def test_logs_canceled(
+        self,
+        action_complete_time: datetime,
+        current_action: CurrentAction,
+        mock_mod_logger: MagicMock,
+        session: Session,
+        canceled_action_status: ActionStatus,
+    ) -> None:
+        """Tests that canceled actions are logged"""
+        # WHEN
+        session._action_updated_impl(
+            action_status=canceled_action_status,
+            now=action_complete_time,
+        )
+
+        # THEN
+        mock_mod_logger.info.assert_called_once_with(
+            "[%s] Action %s: %s completed as %s",
+            session.id,
+            current_action.definition.id,
+            current_action.definition.human_readable(),
+            "CANCELED",
+        )
+
 
 @pytest.mark.usefixtures("mock_openjd_session")
 class TestStartCancelingCurrentAction: