feat: log usage tools when called by LLM (#2916)

* feat: log usage tools when called by LLM

* feat: print llm tool usage in console

Author: lucasgomide

src/crewai/llm.py

@@ -5,7 +5,7 @@
 import threading
 import warnings
 from collections import defaultdict
-from contextlib import contextmanager, redirect_stderr, redirect_stdout
+from contextlib import contextmanager
 from typing import (
     Any,
     DefaultDict,
@@ -18,7 +18,7 @@
     Union,
     cast,
 )
-
+from datetime import datetime
 from dotenv import load_dotenv
 from litellm.types.utils import ChatCompletionDeltaToolCall
 from pydantic import BaseModel, Field
@@ -30,6 +30,11 @@
     LLMCallType,
     LLMStreamChunkEvent,
 )
+from crewai.utilities.events.tool_usage_events import (
+    ToolUsageStartedEvent,
+    ToolUsageFinishedEvent,
+    ToolUsageErrorEvent,
+)
 
 with warnings.catch_warnings():
     warnings.simplefilter("ignore", UserWarning)
@@ -833,7 +838,26 @@ def _handle_tool_call(
                 fn = available_functions[function_name]
 
                 # --- 3.2) Execute function
+                assert hasattr(crewai_event_bus, "emit")
+                started_at = datetime.now()
+                crewai_event_bus.emit(
+                    self,
+                    event=ToolUsageStartedEvent(
+                        tool_name=function_name,
+                        tool_args=function_args,
+                    ),
+                )
                 result = fn(**function_args)
+                crewai_event_bus.emit(
+                    self,
+                    event=ToolUsageFinishedEvent(
+                        output=result,
+                        tool_name=function_name,
+                        tool_args=function_args,
+                        started_at=started_at,
+                        finished_at=datetime.now(),
+                    ),
+                )
 
                 # --- 3.3) Emit success event
                 self._handle_emit_call_events(result, LLMCallType.TOOL_CALL)
@@ -849,6 +873,14 @@ def _handle_tool_call(
                     self,
                     event=LLMCallFailedEvent(error=f"Tool execution error: {str(e)}"),
                 )
+                crewai_event_bus.emit(
+                    self,
+                    event=ToolUsageErrorEvent(
+                        tool_name=function_name,
+                        tool_args=function_args,
+                        error=f"Tool execution error: {str(e)}"
+                    ),
+                )
         return None
 
     def call(

src/crewai/utilities/events/event_listener.py

@@ -2,7 +2,7 @@
 from typing import Any, Dict
 
 from pydantic import Field, PrivateAttr
-
+from crewai.llm import LLM
 from crewai.task import Task
 from crewai.telemetry.telemetry import Telemetry
 from crewai.utilities import Logger
@@ -283,27 +283,43 @@ def on_method_execution_failed(source, event: MethodExecutionFailedEvent):
 
         @crewai_event_bus.on(ToolUsageStartedEvent)
         def on_tool_usage_started(source, event: ToolUsageStartedEvent):
-            self.formatter.handle_tool_usage_started(
-                self.formatter.current_agent_branch,
-                event.tool_name,
+            if isinstance(source, LLM):
+                self.formatter.handle_llm_tool_usage_started(
+                    event.tool_name,
+                )
+            else:
+                self.formatter.handle_tool_usage_started(
+                    self.formatter.current_agent_branch,
+                    event.tool_name,
                 self.formatter.current_crew_tree,
             )
 
         @crewai_event_bus.on(ToolUsageFinishedEvent)
         def on_tool_usage_finished(source, event: ToolUsageFinishedEvent):
-            self.formatter.handle_tool_usage_finished(
-                self.formatter.current_tool_branch,
-                event.tool_name,
-                self.formatter.current_crew_tree,
-            )
+            if isinstance(source, LLM):
+                self.formatter.handle_llm_tool_usage_finished(
+                    event.tool_name,
+                )
+            else:
+                self.formatter.handle_tool_usage_finished(
+                    self.formatter.current_tool_branch,
+                    event.tool_name,
+                    self.formatter.current_crew_tree,
+                )
 
         @crewai_event_bus.on(ToolUsageErrorEvent)
         def on_tool_usage_error(source, event: ToolUsageErrorEvent):
-            self.formatter.handle_tool_usage_error(
-                self.formatter.current_tool_branch,
-                event.tool_name,
-                event.error,
-                self.formatter.current_crew_tree,
+            if isinstance(source, LLM):
+                self.formatter.handle_llm_tool_usage_error(
+                    event.tool_name,
+                    event.error,
+                )
+            else:
+                self.formatter.handle_tool_usage_error(
+                    self.formatter.current_tool_branch,
+                    event.tool_name,
+                    event.error,
+                    self.formatter.current_crew_tree,
             )
 
         # ----------- LLM EVENTS -----------

src/crewai/utilities/events/tool_usage_events.py

@@ -7,11 +7,11 @@
 class ToolUsageEvent(BaseEvent):
     """Base event for tool usage tracking"""
 
-    agent_key: str
-    agent_role: str
+    agent_key: Optional[str] = None
+    agent_role: Optional[str] = None
     tool_name: str
     tool_args: Dict[str, Any] | str
-    tool_class: str
+    tool_class: Optional[str] = None
     run_attempts: int | None = None
     delegations: int | None = None
     agent: Optional[Any] = None

src/crewai/utilities/events/utils/console_formatter.py

@@ -17,6 +17,7 @@ class ConsoleFormatter:
     current_lite_agent_branch: Optional[Tree] = None
     tool_usage_counts: Dict[str, int] = {}
     current_reasoning_branch: Optional[Tree] = None  # Track reasoning status
+    current_llm_tool_tree: Optional[Tree] = None
 
     def __init__(self, verbose: bool = False):
         self.console = Console(width=None)
@@ -426,6 +427,51 @@ def update_method_status(
         self.print()
         return method_branch
 
+    def get_llm_tree(self, tool_name: str):
+        text = Text()
+        text.append(f"🔧 Using {tool_name} from LLM available_function", style="yellow")
+
+        tree = self.current_flow_tree or self.current_crew_tree
+
+        if tree:
+            tree.add(text)
+
+        return tree or Tree(text)
+
+    def handle_llm_tool_usage_started(
+        self,
+        tool_name: str,
+    ):
+        tree = self.get_llm_tree(tool_name)
+        self.add_tree_node(tree, "🔄 Tool Usage Started", "green")
+        self.print(tree)
+        self.print()
+        return tree
+
+    def handle_llm_tool_usage_finished(
+        self,
+        tool_name: str,
+    ):
+        tree = self.get_llm_tree(tool_name)
+        self.add_tree_node(tree, "✅ Tool Usage Completed", "green")
+        self.print(tree)
+        self.print()
+
+    def handle_llm_tool_usage_error(
+        self,
+        tool_name: str,
+        error: str,
+    ):
+        tree = self.get_llm_tree(tool_name)
+        self.add_tree_node(tree, "❌ Tool Usage Failed", "red")
+        self.print(tree)
+        self.print()
+
+        error_content = self.create_status_content(
+            "Tool Usage Failed", tool_name, "red", Error=error
+        )
+        self.print_panel(error_content, "Tool Error", "red")
+
     def handle_tool_usage_started(
         self,
         agent_branch: Optional[Tree],

tests/cassettes/test_handle_streaming_tool_calls_with_error.yaml

@@ -0,0 +1,143 @@
+interactions:
+- request:
+    body: '{"messages": [{"role": "user", "content": "What is the weather in New York?"}],
+      "model": "gpt-4o", "stop": [], "stream": true, "stream_options": {"include_usage":
+      true}, "tools": [{"type": "function", "function": {"name": "get_weather", "description":
+      "Get the current weather in a given location", "parameters": {"type": "object",
+      "properties": {"location": {"type": "string", "description": "The city and state,
+      e.g. San Francisco, CA"}}, "required": ["location"]}}}]}'
+    headers:
+      accept:
+      - application/json
+      accept-encoding:
+      - gzip, deflate
+      connection:
+      - keep-alive
+      content-length:
+      - '470'
+      content-type:
+      - application/json
+      cookie:
+      - _cfuvid=3UeEmz_rnmsoZxrVUv32u35gJOi766GDWNe5_RTjiPk-1736537376739-0.0.1.1-604800000
+      host:
+      - api.openai.com
+      user-agent:
+      - OpenAI/Python 1.68.2
+      x-stainless-arch:
+      - arm64
+      x-stainless-async:
+      - 'false'
+      x-stainless-lang:
+      - python
+      x-stainless-os:
+      - MacOS
+      x-stainless-package-version:
+      - 1.68.2
+      x-stainless-raw-response:
+      - 'true'
+      x-stainless-read-timeout:
+      - '600.0'
+      x-stainless-retry-count:
+      - '0'
+      x-stainless-runtime:
+      - CPython
+      x-stainless-runtime-version:
+      - 3.12.9
+    method: POST
+    uri: https://api.openai.com/v1/chat/completions
+  response:
+    body:
+      string: 'data: {"id":"chatcmpl-BcY6NFDeu4HFOAIarpwSNAUEMuPTg","object":"chat.completion.chunk","created":1748527251,"model":"gpt-4o-2024-08-06","service_tier":"default","system_fingerprint":"fp_07871e2ad8","choices":[{"index":0,"delta":{"role":"assistant","content":null,"tool_calls":[{"index":0,"id":"call_UkMsNK0RTJ1nlT19WqgLJYV9","type":"function","function":{"name":"get_weather","arguments":""}}],"refusal":null},"logprobs":null,"finish_reason":null}],"usage":null}
+
+
+        data: {"id":"chatcmpl-BcY6NFDeu4HFOAIarpwSNAUEMuPTg","object":"chat.completion.chunk","created":1748527251,"model":"gpt-4o-2024-08-06","service_tier":"default","system_fingerprint":"fp_07871e2ad8","choices":[{"index":0,"delta":{"tool_calls":[{"index":0,"function":{"arguments":"{\""}}]},"logprobs":null,"finish_reason":null}],"usage":null}
+
+
+        data: {"id":"chatcmpl-BcY6NFDeu4HFOAIarpwSNAUEMuPTg","object":"chat.completion.chunk","created":1748527251,"model":"gpt-4o-2024-08-06","service_tier":"default","system_fingerprint":"fp_07871e2ad8","choices":[{"index":0,"delta":{"tool_calls":[{"index":0,"function":{"arguments":"location"}}]},"logprobs":null,"finish_reason":null}],"usage":null}
+
+
+        data: {"id":"chatcmpl-BcY6NFDeu4HFOAIarpwSNAUEMuPTg","object":"chat.completion.chunk","created":1748527251,"model":"gpt-4o-2024-08-06","service_tier":"default","system_fingerprint":"fp_07871e2ad8","choices":[{"index":0,"delta":{"tool_calls":[{"index":0,"function":{"arguments":"\":\""}}]},"logprobs":null,"finish_reason":null}],"usage":null}
+
+
+        data: {"id":"chatcmpl-BcY6NFDeu4HFOAIarpwSNAUEMuPTg","object":"chat.completion.chunk","created":1748527251,"model":"gpt-4o-2024-08-06","service_tier":"default","system_fingerprint":"fp_07871e2ad8","choices":[{"index":0,"delta":{"tool_calls":[{"index":0,"function":{"arguments":"New"}}]},"logprobs":null,"finish_reason":null}],"usage":null}
+
+
+        data: {"id":"chatcmpl-BcY6NFDeu4HFOAIarpwSNAUEMuPTg","object":"chat.completion.chunk","created":1748527251,"model":"gpt-4o-2024-08-06","service_tier":"default","system_fingerprint":"fp_07871e2ad8","choices":[{"index":0,"delta":{"tool_calls":[{"index":0,"function":{"arguments":"
+        York"}}]},"logprobs":null,"finish_reason":null}],"usage":null}
+
+
+        data: {"id":"chatcmpl-BcY6NFDeu4HFOAIarpwSNAUEMuPTg","object":"chat.completion.chunk","created":1748527251,"model":"gpt-4o-2024-08-06","service_tier":"default","system_fingerprint":"fp_07871e2ad8","choices":[{"index":0,"delta":{"tool_calls":[{"index":0,"function":{"arguments":","}}]},"logprobs":null,"finish_reason":null}],"usage":null}
+
+
+        data: {"id":"chatcmpl-BcY6NFDeu4HFOAIarpwSNAUEMuPTg","object":"chat.completion.chunk","created":1748527251,"model":"gpt-4o-2024-08-06","service_tier":"default","system_fingerprint":"fp_07871e2ad8","choices":[{"index":0,"delta":{"tool_calls":[{"index":0,"function":{"arguments":"
+        NY"}}]},"logprobs":null,"finish_reason":null}],"usage":null}
+
+
+        data: {"id":"chatcmpl-BcY6NFDeu4HFOAIarpwSNAUEMuPTg","object":"chat.completion.chunk","created":1748527251,"model":"gpt-4o-2024-08-06","service_tier":"default","system_fingerprint":"fp_07871e2ad8","choices":[{"index":0,"delta":{"tool_calls":[{"index":0,"function":{"arguments":"\"}"}}]},"logprobs":null,"finish_reason":null}],"usage":null}
+
+
+        data: {"id":"chatcmpl-BcY6NFDeu4HFOAIarpwSNAUEMuPTg","object":"chat.completion.chunk","created":1748527251,"model":"gpt-4o-2024-08-06","service_tier":"default","system_fingerprint":"fp_07871e2ad8","choices":[{"index":0,"delta":{},"logprobs":null,"finish_reason":"tool_calls"}],"usage":null}
+
+
+        data: {"id":"chatcmpl-BcY6NFDeu4HFOAIarpwSNAUEMuPTg","object":"chat.completion.chunk","created":1748527251,"model":"gpt-4o-2024-08-06","service_tier":"default","system_fingerprint":"fp_07871e2ad8","choices":[],"usage":{"prompt_tokens":68,"completion_tokens":17,"total_tokens":85,"prompt_tokens_details":{"cached_tokens":0,"audio_tokens":0},"completion_tokens_details":{"reasoning_tokens":0,"audio_tokens":0,"accepted_prediction_tokens":0,"rejected_prediction_tokens":0}}}
+
+
+        data: [DONE]
+
+
+        '
+    headers:
+      CF-RAY:
+      - 947685373af8a435-GRU
+      Connection:
+      - keep-alive
+      Content-Type:
+      - text/event-stream; charset=utf-8
+      Date:
+      - Thu, 29 May 2025 14:00:51 GMT
+      Server:
+      - cloudflare
+      Set-Cookie:
+      - __cf_bm=fFoq7oCHLgmljA4hsHWxTGHMEWJ.0t1XTuDptZPPkOc-1748527251-1.0.1.1-PP3Hd7XzA4AQFn0JQWjuQdhFwey0Pj9maUWKfFG16Bkl69Uk65A8XKN73UbsvO327TruwxameKb_m_HDePCR.YN0TZlE8Pu45WsA9shDwKY;
+        path=/; expires=Thu, 29-May-25 14:30:51 GMT; domain=.api.openai.com; HttpOnly;
+        Secure; SameSite=None
+      - _cfuvid=ut1CVX5GOYnv03fiV2Dsv7cm5soJmwgSutkPAEuVXWg-1748527251565-0.0.1.1-604800000;
+        path=/; domain=.api.openai.com; HttpOnly; Secure; SameSite=None
+      Transfer-Encoding:
+      - chunked
+      X-Content-Type-Options:
+      - nosniff
+      access-control-expose-headers:
+      - X-Request-ID
+      alt-svc:
+      - h3=":443"; ma=86400
+      cf-cache-status:
+      - DYNAMIC
+      openai-organization:
+      - crewai-iuxna1
+      openai-processing-ms:
+      - '332'
+      openai-version:
+      - '2020-10-01'
+      strict-transport-security:
+      - max-age=31536000; includeSubDomains; preload
+      x-envoy-upstream-service-time:
+      - '334'
+      x-ratelimit-limit-requests:
+      - '10000'
+      x-ratelimit-limit-tokens:
+      - '30000000'
+      x-ratelimit-remaining-requests:
+      - '9999'
+      x-ratelimit-remaining-tokens:
+      - '29999989'
+      x-ratelimit-reset-requests:
+      - 6ms
+      x-ratelimit-reset-tokens:
+      - 0s
+      x-request-id:
+      - req_1dc91fc964a8d23ee023693400e5c181
+    status:
+      code: 200
+      message: OK
+version: 1