Streamline Logging Events (#2532)

* Skip duplicate log

* log user actions

* fix tests

* log all action _step

* refactor log

* revert test

* refactor log

* visual diff

* disable overriding event source

* Revert "disable overriding event source"

This reverts commit b0047cc0cdead215044ad8ce73f5bad47df99e08.

* Refactor logic

* refactored runtime on_event

* fix merge conflict

in Web UI, it shows as red color (seems deletion but added)

* linted

---------

Co-authored-by: Xingyao Wang <xingyao6@illinois.edu>

opendevin/controller/agent_controller.py

@@ -153,12 +153,10 @@ class AgentController:
             await self.set_agent_state_to(event.agent_state)  # type: ignore
         elif isinstance(event, MessageAction):
             if event.source == EventSource.USER:
-                logger.info(event, extra={'msg_type': 'OBSERVATION'})
                 await self.add_history(event, NullObservation(''))
                 if self.get_agent_state() != AgentState.RUNNING:
                     await self.set_agent_state_to(AgentState.RUNNING)
             elif event.source == EventSource.AGENT and event.wait_for_response:
-                logger.info(event, extra={'msg_type': 'ACTION'})
                 await self.set_agent_state_to(AgentState.AWAITING_USER_INPUT)
         elif isinstance(event, AgentDelegateAction):
             await self.start_delegate(event)
@@ -347,8 +345,6 @@ class AgentController:
             await self.report_error(str(e))
             return
 
-        logger.info(action, extra={'msg_type': 'ACTION'})
-
         if action.runnable:
             self._pending_action = action
         else:
@@ -358,6 +354,7 @@ class AgentController:
             self.event_stream.add_event(action, EventSource.AGENT)
 
         await self.update_state_after_step()
+        logger.info(action, extra={'msg_type': 'ACTION'})
 
         if self._is_stuck():
             await self.report_error('Agent got stuck in a loop')

opendevin/core/logger.py

@@ -32,7 +32,9 @@ ColorType = Literal[
 
 LOG_COLORS: Mapping[str, ColorType] = {
     'ACTION': 'green',
+    'USER_ACTION': 'light_red',
     'OBSERVATION': 'yellow',
+    'USER_OBSERVATION': 'light_green',
     'DETAIL': 'cyan',
     'ERROR': 'red',
     'PLAN': 'light_magenta',
@@ -41,7 +43,12 @@ LOG_COLORS: Mapping[str, ColorType] = {
 
 class ColoredFormatter(logging.Formatter):
     def format(self, record):
-        msg_type = record.__dict__.get('msg_type', None)
+        msg_type = record.__dict__.get('msg_type')
+        event_source = record.__dict__.get('event_source')
+        if event_source:
+            new_msg_type = f'{event_source.upper()}_{msg_type}'
+            if new_msg_type in LOG_COLORS:
+                msg_type = new_msg_type
         if msg_type in LOG_COLORS and not DISABLE_COLOR_PRINTING:
             msg_type_color = colored(msg_type, LOG_COLORS[msg_type])
             msg = colored(record.msg, LOG_COLORS[msg_type])
@@ -50,7 +57,7 @@ class ColoredFormatter(logging.Formatter):
             )
             name_str = colored(record.name, LOG_COLORS[msg_type])
             level_str = colored(record.levelname, LOG_COLORS[msg_type])
-            if msg_type in ['ERROR']:
+            if msg_type in ['ERROR'] or config.debug:
                 return f'{time_str} - {name_str}:{level_str}: {record.filename}:{record.lineno}\n{msg_type_color}\n{msg}'
             return f'{time_str} - {msg_type_color}\n{msg}'
         elif msg_type == 'STEP':

opendevin/events/action/commands.py

@@ -18,7 +18,7 @@ class CmdRunAction(Action):
         return f'Running command: {self.command}'
 
     def __str__(self) -> str:
-        ret = '**CmdRunAction**\n'
+        ret = f'**CmdRunAction (source={self.source})**\n'
         if self.thought:
             ret += f'THOUGHT: {self.thought}\n'
         ret += f'COMMAND:\n{self.command}'

opendevin/events/observation/commands.py

@@ -25,7 +25,7 @@ class CmdOutputObservation(Observation):
         return f'Command `{self.command}` executed with exit code {self.exit_code}.'
 
     def __str__(self) -> str:
-        return f'**CmdOutputObservation (exit code={self.exit_code})**\n{self.content}'
+        return f'**CmdOutputObservation (source={self.source}, exit code={self.exit_code})**\n{self.content}'
 
 
 @dataclass

opendevin/runtime/runtime.py

@@ -4,7 +4,7 @@ from typing import Any, Optional
 from opendevin.core.config import config
 from opendevin.core.exceptions import BrowserInitException
 from opendevin.core.logger import opendevin_logger as logger
-from opendevin.events import EventSource, EventStream, EventStreamSubscriber
+from opendevin.events import EventStream, EventStreamSubscriber
 from opendevin.events.action import (
     Action,
     AgentRecallAction,
@@ -105,8 +105,7 @@ class Runtime:
         if isinstance(event, Action):
             observation = await self.run_action(event)
             observation._cause = event.id  # type: ignore[attr-defined]
-            source = event.source if event.source else EventSource.AGENT
-            self.event_stream.add_event(observation, source)
+            self.event_stream.add_event(observation, event.source)  # type: ignore[arg-type]
 
     async def run_action(self, action: Action) -> Observation:
         """

opendevin/server/session/session.py

@@ -7,7 +7,7 @@ from opendevin.core.const.guide_url import TROUBLESHOOTING_URL
 from opendevin.core.logger import opendevin_logger as logger
 from opendevin.core.schema import AgentState
 from opendevin.core.schema.action import ActionType
-from opendevin.events.action import ChangeAgentStateAction, NullAction
+from opendevin.events.action import Action, ChangeAgentStateAction, NullAction
 from opendevin.events.event import Event, EventSource
 from opendevin.events.observation import (
     AgentStateChangedObservation,
@@ -103,6 +103,10 @@ class Session:
             return
         event = event_from_dict(data.copy())
         self.agent_session.event_stream.add_event(event, EventSource.USER)
+        if isinstance(event, Action):
+            logger.info(
+                event, extra={'msg_type': 'ACTION', 'event_source': EventSource.USER}
+            )
 
     async def send(self, data: dict[str, object]) -> bool:
         try: