feat!: session lifecycle log improvements (#51)

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

@@ -222,7 +222,7 @@ def run(self) -> None:
         """
         self._warm_job_entities_cache()
 
-        logger.info("[%s] started", self._id)
+        logger.info("[%s]: Session started", self._id)
         self._stopped_running.clear()
 
         try:
@@ -245,7 +245,7 @@ def run(self) -> None:
             finally:
                 self._stopped_running.set()
 
-        logger.info("[%s] session complete", self._id)
+        logger.info("[%s]: Session complete", self._id)
 
     def wait(self, timeout: timedelta | None = None) -> None:
         # Wait until this Session is not running anymore.
@@ -461,8 +461,10 @@ def _cancel_actions_impl(
             #         logger.warning(str(e))
             #     except Exception as e:
             #         logger.error(
-            #             "Unexepected error trying to cancel (%s): %s",
+            #             "[%s] [%s] (%s): Error canceling action: %s",
+            #             self.id,
             #             canceled_action_id,
+            #             self._current_action.definition.human_readable(),
             #             e,
             #         )
 
@@ -473,7 +475,12 @@ def _start_canceling_current_action(self, *, time_limit: timedelta | None = None
             raise ValueError("Current action not assigned")
 
         # Cancel the action
-        logger.info("[%s] Canceling action %s", self._id, current_action.definition.id)
+        logger.info(
+            "[%s] [%s] (%s): Canceling action",
+            self._id,
+            current_action.definition.id,
+            current_action.definition.human_readable(),
+        )
         current_action.definition.cancel(session=self, time_limit=time_limit)
 
     def _start_action(
@@ -538,7 +545,7 @@ def _start_action(
             return
 
         logger.info(
-            "[%s] Running action %s: %s",
+            "[%s] [%s] (%s): Starting action",
             self._id,
             action_definition.id,
             action_definition.human_readable(),
@@ -554,7 +561,13 @@ def _start_action(
                 executor=executor,
             )
         except Exception as e:
-            logger.warn("[%s] Error starting action %s: %s", self.id, action_definition.id, e)
+            logger.warn(
+                "[%s] [%s] (%s): Error starting action: %s",
+                self.id,
+                action_definition.id,
+                action_definition.human_readable(),
+                e,
+            )
             self._report_action_update(
                 SessionActionStatus(
                     id=action_definition.id,
@@ -1010,13 +1023,14 @@ def _action_updated_impl(
                 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,
-        )
+        if completed_status:
+            logger.info(
+                "[%s] [%s] (%s): Action completed as %s",
+                self.id,
+                current_action.definition.id,
+                current_action.definition.human_readable(),
+                completed_status,
+            )
 
     def _sync_asset_outputs(
         self,

test/unit/sessions/test_session.py

@@ -1192,7 +1192,7 @@ def test_logs_succeeded(
 
         # THEN
         mock_mod_logger.info.assert_called_once_with(
-            "[%s] Action %s: %s completed as %s",
+            "[%s] [%s] (%s): Action completed as %s",
             session.id,
             current_action.definition.id,
             current_action.definition.human_readable(),
@@ -1216,7 +1216,7 @@ def test_logs_failed(
 
         # THEN
         mock_mod_logger.info.assert_called_once_with(
-            "[%s] Action %s: %s completed as %s",
+            "[%s] [%s] (%s): Action completed as %s",
             session.id,
             current_action.definition.id,
             current_action.definition.human_readable(),
@@ -1240,7 +1240,7 @@ def test_logs_canceled(
 
         # THEN
         mock_mod_logger.info.assert_called_once_with(
-            "[%s] Action %s: %s completed as %s",
+            "[%s] [%s] (%s): Action completed as %s",
             session.id,
             current_action.definition.id,
             current_action.definition.human_readable(),
@@ -1303,7 +1303,10 @@ def test_logs_cancelation(
 
         # THEN
         logger_info.assert_called_once_with(
-            "[%s] Canceling action %s", session.id, current_action.definition.id
+            "[%s] [%s] (%s): Canceling action",
+            session.id,
+            current_action.definition.id,
+            current_action.definition.human_readable(),
         )
 
 
@@ -1627,7 +1630,7 @@ def test_run_exception(
 
         # THEN
         logger_info.assert_called_once_with(
-            "[%s] Running action %s: %s",
+            "[%s] [%s] (%s): Starting action",
             session.id,
             run_step_task_action.id,
             run_step_task_action.human_readable(),
@@ -1651,5 +1654,9 @@ def test_run_exception(
         )
         assert session._current_action is None
         logger_warn.assert_called_once_with(
-            "[%s] Error starting action %s: %s", session.id, run_step_task_action.id, exception
+            "[%s] [%s] (%s): Error starting action: %s",
+            session.id,
+            run_step_task_action.id,
+            run_step_task_action.human_readable(),
+            exception,
         )