chore: adding logging - tools and agents

build.sh

@@ -1,19 +1,19 @@
 #!/bin/bash
 
 # Remove all files in the 'dist' directory
-rm -f dist/*
+rm -f /mnt/d/Infra/crewAI/dist/*
 
 # Remove all files in the '../ctim/crewAI/dist' directory
-rm -f ../ctim/crewAI/dist/*
+rm -f /mnt/d/agentia/agentia_ctim/ctim/crewAI/dist/*
 
 # Build the project using Poetry
 poetry build
 
 # Copy all files from the 'dist' directory to '../ctim/crewAI/dist'
-cp -r dist/* ../ctim/crewAI/dist/
+cp -r /mnt/d/Infra/crewAI/dist/* /mnt/d/agentia/agentia_ctim/ctim/crewAI/dist/
 
-cd ../ctim/
+cd /mnt/d/agentia/agentia_ctim/ctim/
 
 make build && make up
 
-cd ../crewAI
+cd /mnt/d/agentia/agentia_ctim/crewAI

src/crewai/agent.py

@@ -19,6 +19,10 @@
 from crewai.agents.agent_builder.base_agent import BaseAgent
 from crewai.utilities.training_handler import CrewTrainingHandler
 
+import logging
+
+logger = logging.getLogger(__name__)
+
 
 class Agent(BaseAgent):
     """Represents an agent in a system.
@@ -84,11 +88,11 @@ class Agent(BaseAgent):
     def __init__(__pydantic_self__, **data):
         config = data.pop("config", {})
         super().__init__(**config, **data)
-        print(
+        logger.info(
             f"[CrewAI.Agent.__init__]: Agent: {__pydantic_self__.role} has been init with ToolsHandler: {__pydantic_self__.tools_handler}"
         )
-        print(
-            f"[CrewAI.Agent.__init__]: Agent: {__pydantic_self__.role} has been init with ToolsHandler: {__pydantic_self__.callbacks}"
+        logger.info(
+            f"[CrewAI.Agent.__init__]: Agent: {__pydantic_self__.role} has been init with callbacks: {__pydantic_self__.callbacks}"
         )
 
     @model_validator(mode="after")
@@ -110,8 +114,8 @@ def set_agent_executor(self) -> "Agent":
         if not self.agent_executor:
             if not self.cache_handler:
                 self.cache_handler = CacheHandler()
-            print(
-                f"[CrewAI.Agent.set_agent_executor]: calling set_cache_handler for agent {self}"
+            logger.info(
+                f"[CrewAI.Agent.set_agent_executor]: calling set_cache_handler for agent {self.role}"
             )
             self.set_cache_handler(self.cache_handler)
         return self
@@ -135,11 +139,13 @@ def execute_task(
         if self.tools_handler:
             # type: ignore # Incompatible types in assignment (expression has type "dict[Never, Never]", variable has type "ToolCalling")
             self.tools_handler.last_used_tool = {}
-            print(
+            logger.info(
                 f"[CrewAI.Agent.execute_task]: task has a tools_handler: {self.tools_handler}"
             )
         else:
-            print("[CrewAI.Agent.execute_task]: task DOES NOT HAVE a tools_handler")
+            logger.info(
+                "[CrewAI.Agent.execute_task]: task DOES NOT HAVE a tools_handler"
+            )
 
         task_prompt = task.prompt()
 
@@ -261,11 +267,11 @@ def create_agent_executor(self, tools=None) -> None:
 
         inner_agent = agent_args | execution_prompt | bind | CrewAgentParser(agent=self)
 
-        print(
-            f"[CrewAI.Agent.create_agent_executor]: setting the agent_executor for agent {self}"
+        logger.info(
+            f"[CrewAI.Agent.create_agent_executor]: setting the agent_executor for agent {self.role}"
         )
         callbacks = executor_args.get("callbacks", "No callbacks found")
-        print(f"[CrewAI.Agent.create_agent_executor]: callbacks are: {callbacks}")
+        logger.info(f"[CrewAI.Agent.create_agent_executor]: callbacks are: {callbacks}")
         self.agent_executor = CrewAgentExecutor(
             agent=RunnableAgent(runnable=inner_agent), **executor_args
         )

src/crewai/agents/agent_builder/base_agent.py

@@ -18,6 +18,10 @@
 from crewai.agents import CacheHandler, ToolsHandler
 from crewai.utilities.token_counter_callback import TokenProcess
 
+import logging
+
+logger = logging.getLogger(__name__)
+
 
 class BaseAgent(ABC, BaseModel):
     """Abstract Base Class for all third party agents compatible with CrewAI.
@@ -208,23 +212,20 @@ def set_cache_handler(self, cache_handler: CacheHandler) -> None:
             cache_handler: An instance of the CacheHandler class.
         """
         if not self.tools_handler:
-            print(
-                "[CrewAI.BaseAgent.set_cache_handler]: Using the default ToolsHandler"
-            )
-            print(
-                f"[CrewAI.BaseAgent.set_cache_handler]: default ToolsHandler is being used by agent: {self}"
+            logger.info(
+                f"[CrewAI.BaseAgent.set_cache_handler]: Agent {self.role} 's ToolsHandler is being set to default"
             )
             self.tools_handler = ToolsHandler()
-        print(
-            f"[CrewAI.BaseAgent.set_cache_handler]: ToolsHandler = {self.tools_handler}"
+        logger.info(
+            f"[CrewAI.BaseAgent.set_cache_handler]: Agent {self.role} 's ToolsHandler is = {self.tools_handler}"
         )
         if self.cache:
             self.cache_handler = cache_handler
             self.tools_handler.cache = cache_handler
         self.create_agent_executor()
 
     def increment_formatting_errors(self) -> None:
-        print("Formatting errors incremented")
+        logger.info("Formatting errors incremented")
 
     def copy(self):
         exclude = {

src/crewai/agents/tools_handler.py

@@ -1,9 +1,14 @@
+import logging
+import time
+
 from typing import Any, Optional, Union
 
 from ..tools.cache_tools import CacheTools
 from ..tools.tool_calling import InstructorToolCalling, ToolCalling
 from .cache.cache_handler import CacheHandler
 
+logger = logging.getLogger(__name__)
+
 
 class ToolsHandler:
     """Callback handler for tool usage."""
@@ -15,6 +20,7 @@ def __init__(self, cache: Optional[CacheHandler] = None):
         """Initialize the callback handler."""
         self.cache = cache
         self.last_used_tool = {}  # type: ignore # BUG?: same as above
+        logger.info(f"ToolsHandler initialized with cache: {cache is not None}")
 
     def on_tool_use(
         self,
@@ -23,10 +29,31 @@ def on_tool_use(
         should_cache: bool = True,
     ) -> Any:
         """Run when tool ends running."""
+        start_time = time.time()
+
+        logger.info(f"Tool used: {calling.tool_name}")
+        logger.debug(f"Tool arguments: {calling.arguments}")
+        logger.debug(f"Tool output length: {len(output)} characters")
+
         self.last_used_tool = calling  # type: ignore # BUG?: Incompatible types in assignment (expression has type "Union[ToolCalling, InstructorToolCalling]", variable has type "ToolCalling")
         if self.cache and should_cache and calling.tool_name != CacheTools().name:
-            self.cache.add(
-                tool=calling.tool_name,
-                input=calling.arguments,
-                output=output,
-            )
+            logger.debug(f"Caching result for tool: {calling.tool_name}")
+            try:
+                self.cache.add(
+                    tool=calling.tool_name,
+                    input=calling.arguments,
+                    output=output,
+                )
+                logger.info(f"Successfully cached result for tool: {calling.tool_name}")
+            except Exception as e:
+                logger.error(
+                    f"Error caching result for tool {calling.tool_name}: {str(e)}",
+                    exc_info=True,
+                )
+        elif not should_cache:
+            logger.info(f"Skipped caching for tool: {calling.tool_name}")
+        elif calling.tool_name == CacheTools().name:
+            logger.info("Skipped caching for CacheTools")
+
+        duration = time.time() - start_time
+        logger.info(f"Tool handling completed in {duration:.4f} seconds")

src/crewai/tools/tool_usage.py

@@ -10,6 +10,11 @@
 from crewai.telemetry import Telemetry
 from crewai.tools.tool_calling import InstructorToolCalling, ToolCalling
 from crewai.utilities import I18N, Converter, ConverterError, Printer
+import logging
+import time
+
+logger = logging.getLogger(__name__)
+
 
 OPENAI_BIGGER_MODELS = ["gpt-4"]
 
@@ -70,17 +75,26 @@ def __init__(
                 self._max_parsing_attempts = 2
                 self._remember_format_after_usages = 4
 
+        logger.info(f"ToolUsage initialized with {len(tools)} tools for task: {task}")
+
     def parse(self, tool_string: str):
         """Parse the tool string and return the tool calling."""
         return self._tool_calling(tool_string)
 
     def use(
         self, calling: Union[ToolCalling, InstructorToolCalling], tool_string: str
     ) -> str:
+        start_time = time.time()
+        logger.info(f"Tool usage started for: {calling.tool_name}")
+
         if isinstance(calling, ToolUsageErrorException):
             error = calling.message
             self._printer.print(content=f"\n\n{error}\n", color="red")
             self.task.increment_tools_errors()
+            duration = time.time() - start_time
+            logger.info(
+                f"Tool '{calling.tool_name}' executed in {duration:.2f} seconds"
+            )
             return error
 
         # BUG? The code below seems to be unreachable
@@ -90,15 +104,28 @@ def use(
             error = getattr(e, "message", str(e))
             self.task.increment_tools_errors()
             self._printer.print(content=f"\n\n{error}\n", color="red")
+            duration = time.time() - start_time
+            logger.info(
+                f"Tool '{calling.tool_name}' executed in {duration:.2f} seconds"
+            )
             return error
-        return f"{self._use(tool_string=tool_string, tool=tool, calling=calling)}"  # type: ignore # BUG?: "_use" of "ToolUsage" does not return a value (it only ever returns None)
+
+        result = self._use(tool_string=tool_string, tool=tool, calling=calling)
+
+        duration = time.time() - start_time
+        logger.info(f"Tool '{calling.tool_name}' executed in {duration:.2f} seconds")
+
+        return result  # type: ignore # BUG?: "_use" of "ToolUsage" does not return a value (it only ever returns None)
 
     def _use(
         self,
         tool_string: str,
         tool: BaseTool,
         calling: Union[ToolCalling, InstructorToolCalling],
     ) -> None:  # TODO: Fix this return type
+        logger.debug(f"Executing tool: {tool.name}")
+        logger.debug(f"Tool input: {calling.arguments}")
+        start_time = time.time()
         if self._check_tool_repeated_usage(calling=calling):  # type: ignore # _check_tool_repeated_usage of "ToolUsage" does not return a value (it only ever returns None)
             try:
                 result = self._i18n.errors("task_repeated_usage").format(
@@ -111,10 +138,18 @@ def _use(
                     attempts=self._run_attempts,
                 )
                 result = self._format_result(result=result)  # type: ignore #  "_format_result" of "ToolUsage" does not return a value (it only ever returns None)
-                return result  # type: ignore # Fix the reutrn type of this function
+                logger.info(f"Tool '{tool.name}' output: {result[:100]}...")
 
             except Exception:
+                logger.error(f"Error executing tool '{tool.name}':", exc_info=True)
                 self.task.increment_tools_errors()
+            finally:
+                duration = time.time() - start_time
+                logger.info(
+                    f"Tool '{tool.name}' execution completed in {duration:.2f} seconds"
+                )
+
+            return result  # type: ignore # Fix the reutrn type of this function
 
         result = None  # type: ignore # Incompatible types in assignment (expression has type "None", variable has type "str")
 
@@ -123,6 +158,11 @@ def _use(
                 tool=calling.tool_name, input=calling.arguments
             )
 
+            if result:
+                logger.info(f"Cache hit for tool: {calling.tool_name}")
+            else:
+                logger.info(f"Cache miss for tool: {calling.tool_name}")
+
         if not result:
             try:
                 if calling.tool_name in [
@@ -219,6 +259,7 @@ def _check_tool_repeated_usage(
             )
 
     def _select_tool(self, tool_name: str) -> BaseTool:
+        logger.debug(f"Selecting tool for name: {tool_name}")
         order_tools = sorted(
             self.tools,
             key=lambda tool: SequenceMatcher(
@@ -234,6 +275,7 @@ def _select_tool(self, tool_name: str) -> BaseTool:
                 ).ratio()
                 > 0.85
             ):
+                logger.info(f"Selected tool: {tool.name}")
                 return tool
         self.task.increment_tools_errors()
         if tool_name and tool_name != "":
@@ -270,6 +312,7 @@ def _is_gpt(self, llm) -> bool:
     def _tool_calling(
         self, tool_string: str
     ) -> Union[ToolCalling, InstructorToolCalling]:
+        logger.debug(f"Parsing tool string: {tool_string[:100]}...")
         try:
             if self.function_calling_llm:
                 model = (