Add demo logging feature and enhance structured logging system

- Introduced a new demo_logging.py file to showcase the logging capabilities of the TaskLogger, including navigation, interaction, and data extraction phases.
- Enhanced the structured logging system with color-coded log levels, task states, and visual separators for better readability.
- Implemented error handling improvements with smart retry logic and structured error logging.
- Added support for detailed performance metrics and progress tracking in task execution.
- Updated README.md to reflect the new logging features and improvements in the logging system.
- Introduced new utility functions for structured logging and error handling in the src/utils directory.
- Added comprehensive tests for the new logging features and error handling mechanisms.

Author: drumnation

README.md

@@ -257,3 +257,40 @@ playwright install
 
 - [x] **2025/01/10:** Thanks to @casistack. Now we have Docker Setup option and also Support keep browser open between tasks.[Video tutorial demo](https://github.com/browser-use/web-ui/issues/1#issuecomment-2582511750).
 - [x] **2025/01/06:** Thanks to @richard-devbot. A New and Well-Designed WebUI is released. [Video tutorial demo](https://github.com/warmshao/browser-use-webui/issues/1#issuecomment-2573393113).
+
+## Fork Information
+This is a fork of the original browser-use project with additional features and improvements.
+
+## Changelog
+
+### January 2025 - Logging System Overhaul
+- **Enhanced Logging System**
+  - Added structured task logging with context and state tracking
+  - Implemented color-coded log levels and task states
+  - Added visual separators between task phases
+  - Introduced emoji indicators for different action types (🌐 navigation, 🖱️ interaction, 📑 extraction)
+  - Added status symbols for task states (→ running, ✓ complete, × failed)
+
+- **Error Handling Improvements**
+  - Implemented smart retry logic with exponential backoff
+  - Added structured error logging with context
+  - Introduced visual error separators
+  - Added retry history and statistics tracking
+
+- **Progress Tracking**
+  - Added percentage-based progress tracking
+  - Implemented step duration tracking
+  - Added detailed browser state information
+  - Introduced performance metrics breakdown
+
+- **Log Management**
+  - Added semantic step descriptions
+  - Implemented message filtering and deduplication
+  - Added support for both JSON and human-readable output
+  - Introduced custom color schemes and formatting options
+
+### Coming Soon
+- Log buffering for high-frequency events
+- Recovery suggestions for common errors
+- Real-time monitoring dashboard
+- Interactive log viewer interface

demo_logging.py

@@ -0,0 +1,99 @@
+import asyncio
+from src.utils.task_logging import (
+    TaskLogger, TaskStatus, ActionType, RetryConfig,
+    ColorScheme, SeparatorStyle
+)
+
+async def demo_logging():
+    # Initialize logger with custom styles
+    logger = TaskLogger(
+        "demo_task",
+        "Demonstrate all logging features",
+        color_scheme=ColorScheme(),
+        separator_style=SeparatorStyle(
+            task="★" * 40,
+            phase="•" * 30,
+            error="!" * 35
+        )
+    )
+    
+    # Start navigation phase
+    logger.start_phase("Navigation Phase")
+    logger.update_step(
+        "Navigate to example.com",
+        TaskStatus.RUNNING,
+        action_type=ActionType.NAVIGATION,
+        context={"url": "https://example.com"}
+    )
+    
+    # Update browser state
+    logger.update_browser_state(
+        url="https://example.com",
+        page_ready=True,
+        dynamic_content_loaded=True,
+        visible_elements=15,
+        page_title="Example Domain"
+    )
+    
+    # Complete navigation
+    logger.update_step(
+        "Page loaded successfully",
+        TaskStatus.COMPLETE,
+        action_type=ActionType.NAVIGATION,
+        progress=0.25,
+        results={"status": 200, "load_time": 0.5}
+    )
+    
+    # Start interaction phase
+    logger.start_phase("Interaction Phase")
+    logger.update_step(
+        "Click search button",
+        TaskStatus.RUNNING,
+        action_type=ActionType.INTERACTION,
+        context={"element": "search_button"}
+    )
+    
+    # Simulate error and retry
+    async def failing_operation():
+        raise ValueError("Search button not found")
+    
+    try:
+        await logger.execute_with_retry(
+            failing_operation,
+            "click_search",
+            RetryConfig(max_retries=2, base_delay=0.1)
+        )
+    except ValueError:
+        pass
+    
+    # Start extraction phase
+    logger.start_phase("Data Extraction Phase")
+    logger.update_step(
+        "Extract search results",
+        TaskStatus.RUNNING,
+        action_type=ActionType.EXTRACTION,
+        progress=0.75
+    )
+    
+    # Complete extraction
+    logger.update_step(
+        "Data extracted successfully",
+        TaskStatus.COMPLETE,
+        action_type=ActionType.EXTRACTION,
+        progress=1.0,
+        results={"items_found": 10}
+    )
+    
+    # Display log history
+    print("\nLog History:")
+    print("=" * 80)
+    for entry in logger.get_log_history():
+        print(entry)
+    print("=" * 80)
+    
+    # Log final state
+    print("\nFinal State:")
+    logger.log_state()
+
+if __name__ == "__main__":
+    asyncio.run(demo_logging()) 

src/agent/custom_agent.py

@@ -8,11 +8,12 @@
 import logging
 import pdb
 import traceback
-from typing import Optional, Type
+from typing import Optional, Type, Any, Dict
 from PIL import Image, ImageDraw, ImageFont
 import os
 import base64
 import io
+import datetime
 
 from browser_use.agent.prompts import SystemPrompt
 from browser_use.agent.service import Agent
@@ -37,11 +38,13 @@
     BaseMessage,
 )
 from src.utils.agent_state import AgentState
+from src.utils.logging import BatchedEventLogger
 
 from .custom_massage_manager import CustomMassageManager
 from .custom_views import CustomAgentOutput, CustomAgentStepInfo
 
 logger = logging.getLogger(__name__)
+batched_logger = BatchedEventLogger(logger)
 
 
 class CustomAgent(Agent):
@@ -117,23 +120,41 @@ def _setup_action_models(self) -> None:
         self.AgentOutput = CustomAgentOutput.type_with_custom_actions(self.ActionModel)
 
     def _log_response(self, response: CustomAgentOutput) -> None:
-        """Log the model's response"""
-        if "Success" in response.current_state.prev_action_evaluation:
-            emoji = "✅"
-        elif "Failed" in response.current_state.prev_action_evaluation:
-            emoji = "❌"
-        else:
-            emoji = "🤷"
-
-        logger.info(f"{emoji} Eval: {response.current_state.prev_action_evaluation}")
-        logger.info(f"🧠 New Memory: {response.current_state.important_contents}")
-        logger.info(f"⏳ Task Progress: {response.current_state.completed_contents}")
-        logger.info(f"🤔 Thought: {response.current_state.thought}")
-        logger.info(f"🎯 Summary: {response.current_state.summary}")
+        """Log the model's response in a structured format"""
+        evaluation_status = "success" if "Success" in response.current_state.prev_action_evaluation else "failed"
+        
+        log_data = {
+            "timestamp": datetime.datetime.now().isoformat(),
+            "action": "model_response",
+            "status": evaluation_status,
+            "state": {
+                "evaluation": response.current_state.prev_action_evaluation,
+                "memory": response.current_state.important_contents,
+                "progress": response.current_state.completed_contents,
+                "thought": response.current_state.thought,
+                "summary": response.current_state.summary
+            }
+        }
+        
+        logger.info(
+            f"Model Response: {evaluation_status}",
+            extra={
+                "event_type": "model_response",
+                "event_data": log_data
+            }
+        )
+        
+        # Batch action logging
         for i, action in enumerate(response.action):
-            logger.info(
-                f"🛠️  Action {i + 1}/{len(response.action)}: {action.model_dump_json(exclude_unset=True)}"
+            batched_logger.add_event(
+                "action",
+                {
+                    "action_number": i + 1,
+                    "total_actions": len(response.action),
+                    "action_data": json.loads(action.model_dump_json(exclude_unset=True))
+                }
             )
+        batched_logger.flush()
 
     def update_step_info(
             self, model_output: CustomAgentOutput, step_info: CustomAgentStepInfo = None
@@ -193,7 +214,19 @@ async def get_next_action(self, input_messages: list[BaseMessage]) -> AgentOutpu
     @time_execution_async("--step")
     async def step(self, step_info: Optional[CustomAgentStepInfo] = None) -> None:
         """Execute one step of the task"""
-        logger.info(f"\n📍 Step {self.n_steps}")
+        step_data = {
+            "step_number": self.n_steps,
+            "timestamp": datetime.datetime.now().isoformat()
+        }
+        
+        logger.info(
+            f"Starting step {self.n_steps}",
+            extra={
+                "event_type": "step_start",
+                "event_data": step_data
+            }
+        )
+        
         state = None
         model_output = None
         result: list[ActionResult] = []
@@ -204,9 +237,18 @@ async def step(self, step_info: Optional[CustomAgentStepInfo] = None) -> None:
             input_messages = self.message_manager.get_messages()
             model_output = await self.get_next_action(input_messages)
             self.update_step_info(model_output, step_info)
-            logger.info(f"🧠 All Memory: {step_info.memory}")
+            
+            if step_info:
+                logger.debug(
+                    "Step memory updated",
+                    extra={
+                        "event_type": "memory_update",
+                        "event_data": {"memory": step_info.memory}
+                    }
+                )
+            
             self._save_conversation(input_messages, model_output)
-            self.message_manager._remove_last_state_message()  # we dont want the whole state in the chat history
+            self.message_manager._remove_last_state_message()
             self.message_manager.add_model_output(model_output)
 
             result: list[ActionResult] = await self.controller.multi_act(
@@ -215,17 +257,37 @@ async def step(self, step_info: Optional[CustomAgentStepInfo] = None) -> None:
             self._last_result = result
 
             if len(result) > 0 and result[-1].is_done:
-                logger.info(f"📄 Result: {result[-1].extracted_content}")
+                logger.info(
+                    "Task completed",
+                    extra={
+                        "event_type": "task_complete",
+                        "event_data": {
+                            "result": result[-1].extracted_content
+                        }
+                    }
+                )
 
             self.consecutive_failures = 0
 
         except Exception as e:
             result = self._handle_step_error(e)
             self._last_result = result
+            logger.error(
+                f"Step error: {str(e)}",
+                extra={
+                    "event_type": "step_error",
+                    "event_data": {
+                        "error": str(e),
+                        "traceback": traceback.format_exc()
+                    }
+                },
+                exc_info=True
+            )
 
         finally:
             if not result:
                 return
+            
             for r in result:
                 if r.error:
                     self.telemetry.capture(
@@ -234,8 +296,28 @@ async def step(self, step_info: Optional[CustomAgentStepInfo] = None) -> None:
                             error=r.error,
                         )
                     )
+                    logger.error(
+                        f"Action error: {r.error}",
+                        extra={
+                            "event_type": "action_error",
+                            "event_data": {
+                                "error": r.error
+                            }
+                        }
+                    )
+            
             if state:
                 self._make_history_item(model_output, state, result)
+            
+            step_data["status"] = "completed"
+            logger.info(
+                f"Step {self.n_steps} completed",
+                extra={
+                    "event_type": "step_complete",
+                    "event_data": step_data
+                }
+            )
+
     def create_history_gif(
             self,
             output_path: str = 'agent_history.gif',