Improved logging for agent controller, including pending action time (#7897)

Co-authored-by: openhands <openhands@all-hands.dev>

frontend/__tests__/components/chat/chat-input.test.tsx

@@ -223,7 +223,7 @@ describe("ChatInput", () => {
     render(<ChatInput onSubmit={onSubmitMock} />);
     const textarea = screen.getByRole("textbox");
     expect(textarea).toBeInTheDocument();
-    
+
     // The actual verification of maxRows=16 is handled internally by the TextareaAutosize component
     // and affects how many rows the textarea can expand to
   });

frontend/__tests__/services/observations.test.ts

@@ -48,4 +48,4 @@ describe("Observations Service", () => {
       });
     });
   });
-});
+});

openhands/controller/agent_controller.py

@@ -1,8 +1,9 @@
 import asyncio
 import copy
 import os
+import time
 import traceback
-from typing import Callable, ClassVar, Type
+from typing import Callable, ClassVar, Tuple, Type
 
 import litellm  # noqa
 from litellm.exceptions import (  # noqa
@@ -85,7 +86,7 @@ class AgentController:
     agent_configs: dict[str, AgentConfig]
     parent: 'AgentController | None' = None
     delegate: 'AgentController | None' = None
-    _pending_action: Action | None = None
+    _pending_action_info: Tuple[Action, float] | None = None  # (action, timestamp)
     _closed: bool = False
     filter_out: ClassVar[tuple[type[Event], ...]] = (
         NullAction,
@@ -407,8 +408,21 @@ class AgentController:
         elif isinstance(event, Observation):
             await self._handle_observation(event)
 
-        if self.should_step(event):
+        should_step = self.should_step(event)
+        if should_step:
+            self.log(
+                'info',
+                f'Stepping agent after event: {type(event).__name__}',
+                extra={'msg_type': 'STEPPING_AGENT'},
+            )
             self.step()
+        elif isinstance(event, MessageAction) and event.source == EventSource.USER:
+            # If we received a user message but aren't stepping, log why
+            self.log(
+                'warning',
+                f'Not stepping agent after user message. Current state: {self.get_agent_state()}',
+                extra={'msg_type': 'NOT_STEPPING_AFTER_USER_MESSAGE'},
+            )
 
     async def _handle_action(self, action: Action) -> None:
         """Handles an Action from the agent or delegate."""
@@ -461,7 +475,9 @@ class AgentController:
         if self._pending_action and self._pending_action.id == observation.cause:
             if self.state.agent_state == AgentState.AWAITING_USER_CONFIRMATION:
                 return
+
             self._pending_action = None
+
             if self.state.agent_state == AgentState.USER_CONFIRMED:
                 await self.set_agent_state_to(AgentState.RUNNING)
             if self.state.agent_state == AgentState.USER_REJECTED:
@@ -742,9 +758,21 @@ class AgentController:
     async def _step(self) -> None:
         """Executes a single step of the parent or delegate agent. Detects stuck agents and limits on the number of iterations and the task budget."""
         if self.get_agent_state() != AgentState.RUNNING:
+            self.log(
+                'info',
+                f'Agent not stepping because state is {self.get_agent_state()} (not RUNNING)',
+                extra={'msg_type': 'STEP_BLOCKED_STATE'},
+            )
             return
 
         if self._pending_action:
+            action_id = getattr(self._pending_action, 'id', 'unknown')
+            action_type = type(self._pending_action).__name__
+            self.log(
+                'info',
+                f'Agent not stepping because of pending action: {action_type} (id={action_id})',
+                extra={'msg_type': 'STEP_BLOCKED_PENDING_ACTION'},
+            )
             return
 
         self.log(
@@ -897,6 +925,61 @@ class AgentController:
             stop_step = True
         return stop_step
 
+    @property
+    def _pending_action(self) -> Action | None:
+        """Get the current pending action with time tracking.
+
+        Returns:
+            Action | None: The current pending action, or None if there isn't one.
+        """
+        if self._pending_action_info is None:
+            return None
+
+        action, timestamp = self._pending_action_info
+        current_time = time.time()
+        elapsed_time = current_time - timestamp
+
+        # Log if the pending action has been active for a long time (but don't clear it)
+        if elapsed_time > 60.0:  # 1 minute - just for logging purposes
+            action_id = getattr(action, 'id', 'unknown')
+            action_type = type(action).__name__
+            self.log(
+                'warning',
+                f'Pending action active for {elapsed_time:.2f}s: {action_type} (id={action_id})',
+                extra={'msg_type': 'PENDING_ACTION_TIMEOUT'},
+            )
+
+        return action
+
+    @_pending_action.setter
+    def _pending_action(self, action: Action | None) -> None:
+        """Set or clear the pending action with timestamp and logging.
+
+        Args:
+            action: The action to set as pending, or None to clear.
+        """
+        if action is None:
+            if self._pending_action_info is not None:
+                prev_action, timestamp = self._pending_action_info
+                action_id = getattr(prev_action, 'id', 'unknown')
+                action_type = type(prev_action).__name__
+                elapsed_time = time.time() - timestamp
+                self.log(
+                    'info',
+                    f'Cleared pending action after {elapsed_time:.2f}s: {action_type} (id={action_id})',
+                    extra={'msg_type': 'PENDING_ACTION_CLEARED'},
+                )
+            self._pending_action_info = None
+        else:
+            action_id = getattr(action, 'id', 'unknown')
+            action_type = type(action).__name__
+            self.log(
+                'info',
+                f'Set pending action: {action_type} (id={action_id})',
+                extra={'msg_type': 'PENDING_ACTION_SET'},
+            )
+            self._pending_action_info = (action, time.time())
+
     def get_state(self) -> State:
         """Returns the current running state object.
 
@@ -1181,13 +1264,26 @@ class AgentController:
         )
 
     def __repr__(self):
+        pending_action_info = '<none>'
+        if (
+            hasattr(self, '_pending_action_info')
+            and self._pending_action_info is not None
+        ):
+            action, timestamp = self._pending_action_info
+            action_id = getattr(action, 'id', 'unknown')
+            action_type = type(action).__name__
+            elapsed_time = time.time() - timestamp
+            pending_action_info = (
+                f'{action_type}(id={action_id}, elapsed={elapsed_time:.2f}s)'
+            )
+
         return (
             f'AgentController(id={getattr(self, "id", "<uninitialized>")}, '
             f'agent={getattr(self, "agent", "<uninitialized>")!r}, '
             f'event_stream={getattr(self, "event_stream", "<uninitialized>")!r}, '
             f'state={getattr(self, "state", "<uninitialized>")!r}, '
             f'delegate={getattr(self, "delegate", "<uninitialized>")!r}, '
-            f'_pending_action={getattr(self, "_pending_action", "<uninitialized>")!r})'
+            f'_pending_action={pending_action_info})'
         )
 
     def _is_awaiting_observation(self):

pyproject.toml

@@ -97,6 +97,7 @@ gevent = "^24.2.1"
 [tool.coverage.run]
 concurrency = ["gevent"]
 
+
 [tool.poetry.group.runtime.dependencies]
 jupyterlab = "*"
 notebook = "*"
@@ -125,6 +126,7 @@ ignore = ["D1"]
 [tool.ruff.lint.pydocstyle]
 convention = "google"
 
+
 [tool.poetry.group.evaluation.dependencies]
 streamlit = "*"
 whatthepatch = "*"