diff --git a/src/deadline_worker_agent/sessions/session.py b/src/deadline_worker_agent/sessions/session.py index 20144fe0..caf7b44e 100644 --- a/src/deadline_worker_agent/sessions/session.py +++ b/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, diff --git a/test/unit/sessions/test_session.py b/test/unit/sessions/test_session.py index 9ea2581b..a7920653 100644 --- a/test/unit/sessions/test_session.py +++ b/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, )