Files
crewAI/lib/crewai/tests/telemetry/test_telemetry.py
João Moura 7642e615a3
Some checks failed
CodeQL Advanced / Analyze (actions) (push) Has been cancelled
CodeQL Advanced / Analyze (python) (push) Has been cancelled
Check Documentation Broken Links / Check broken links (push) Has been cancelled
Vulnerability Scan / Detect changes (push) Has been cancelled
Vulnerability Scan / pip-audit (push) Has been cancelled
Nightly Canary Release / Check for new commits (push) Has been cancelled
Nightly Canary Release / Build nightly packages (push) Has been cancelled
Nightly Canary Release / Publish nightly to PyPI (push) Has been cancelled
feat(flow): report flow outcome, duration and human-in-the-loop signals (#6961)
* feat(flow): report flow outcome and human-in-the-loop signals

A flow reported only that it started. FlowFinishedEvent, FlowFailedEvent,
MethodExecutionFailedEvent, MethodExecutionPausedEvent and FlowPausedEvent all
reached the console formatter and stopped there, and FlowInputRequestedEvent,
FlowInputReceivedEvent and ConversationTurnFailedEvent had no listener at all -
so success rate, failure rate and every HITL pause were unmeasurable.

Adds flow:completed, flow:failed, flow:method_failed, flow:paused,
flow:hitl_paused, flow:input_requested, flow:input_received and
flow:conversation_turn_failed as feature-usage spans, which the existing
feature-usage aggregation already reads.

Deliberately does not hold the Flow Execution span open to measure duration:
flow_executions_daily_target counts those spans at start, so a run that never
finishes would disappear from the count entirely. Duration needs its own span.

Counts only - flow names, method names, error text and flow state are never
recorded.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01ASfWmW3RGy4qAQm6s8U9jH

* feat(flow): record how long a flow ran

Adds a Flow Completed span carrying flow_name, duration_ms and outcome,
emitted when a flow finishes or fails. Elapsed time comes from a monotonic
stamp taken at flow start and cleared on use.

Kept separate from the Flow Execution span rather than holding that one open:
it is emitted and closed at start and the daily aggregate counts it, so
holding it would drop every run that is killed or crashes from the execution
count. A killed run now simply has no Flow Completed row, and the count is
unaffected.

Elapsed time is an explicit duration_ms attribute rather than the span's own
duration, which the ingestion pipeline stores as a suffixed string
("0.0000184s") that downstream aggregation parses to zero.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01ASfWmW3RGy4qAQm6s8U9jH

* feat(flow): tag flow origin and report resumed runs

Two gaps found while testing the pause/resume path end to end.

Resumed runs were invisible. There is no resume event: a restored run re-enters
through kickoff(), so it looked identical to a fresh start. flow:resumed is
derived from _is_execution_resuming at flow start, which makes
flow:paused - flow:resumed the abandonment rate.

Flow counts are dominated by CrewAI's own AgentExecutor, which is itself a Flow
and runs once per agent execution - it is the top flow in the warehouse by a
wide margin. Nothing distinguished it from a user's flows except guessing at the
name. Both Flow Execution and Flow Completed now carry origin: "internal" when
the flow class is defined under crewai.*, "user" otherwise. Tagging only the new
span would have left the existing daily count unsplittable.

Both span methods take origin with a default, so their signatures stay
backward compatible.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01ASfWmW3RGy4qAQm6s8U9jH

* fix(flow): scope outcome and resume signals to user flows

Two findings from review, both confirmed against the code.

Outcome features counted CrewAI's own flows. The agent executor, memory
encoding and memory recall are all Flows and all set suppress_flow_events;
they run far more often than anything a user wrote, so flow:completed,
flow:failed and flow:method_failed were mostly bookkeeping. Those three are now
emitted only for flows the caller wrote. Internal outcomes are still recorded
on the Flow Completed span, which carries origin.

flow:resumed counted checkpoint restores. _is_execution_resuming is set both by
from_pending (a human pause) and by a checkpoint restore that never paused for
anyone, so resumes could exceed pauses and the abandonment rate was unusable.
Keyed off _pending_feedback_context instead, which only from_pending sets.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01ASfWmW3RGy4qAQm6s8U9jH

* fix(flow): declare internal flows instead of inferring them

Three findings from review, all confirmed against the code.

Gating on suppress_flow_events was wrong. That flag asks for console quiet and
is a public field, so a caller who set it on their own flow silently lost
flow:completed, flow:failed and flow:method_failed.

Deciding origin from the defining module was also wrong. Flow.from_declaration()
returns a Flow typed in crewai.flow.flow, so a caller's declarative flow was
reported as one of CrewAI's own - the inversion this split exists to prevent.

Both had the same root cause: the discriminator was inferred. Flow now declares
is_crewai_internal, set on the agent executor and the memory encoding/recall
flows, and one helper serves both origin and the outcome gate.

A failed conversational session was reported as completed. Its session closes
with FlowFinishedEvent whatever happened, so a failed turn produced
flow:conversation_turn_failed and flow:completed together. The turn failure is
now recorded on the flow and read back when the session finishes.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01ASfWmW3RGy4qAQm6s8U9jH

* refactor(flow): report flow lifecycle as spans, not feature usage

Flow start, completion, pause and method failure are lifecycle facts, and the
lifecycle is reported as spans everywhere else. Reporting them through
feature usage put them in a table that aggregates on the feature string alone -
it cannot carry origin, duration or outcome, so those signals could never be
split between a user's flows and the ones CrewAI runs for itself.

Adds Flow Paused and Flow Method Failed spans, and a resumed marker on Flow
Execution so a run restored from a pause is not counted as a second fresh
start. Removes the duplicate feature rows for completed, failed, method_failed,
paused and resumed - every one of those facts is now on a span, with more
attached to it than the feature row ever carried.

Feature usage keeps only genuine adoption signals: flow:hitl_paused,
flow:input_requested, flow:input_received and flow:conversation_turn_failed.

Also clears the conversational turn-failure flag on every terminal path. A turn
that failed without deferred finalization ends via FlowFailedEvent, and the flag
left set there marked the next run on that instance as failed.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01ASfWmW3RGy4qAQm6s8U9jH

* test(flow): update the flow_execution_span caller for the resumed argument

Adding the resumed marker changed a signature that tests/utilities/test_events.py
asserts on exactly, and that assertion was not re-run before pushing.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01ASfWmW3RGy4qAQm6s8U9jH

* test(flow): make the checkpoint-restore guard actually guard

The test asserted that flow:resumed was absent from feature usage, but that
signal moved onto the Flow Execution span. The assertion could no longer fail,
so a regression that mis-tagged checkpoint restores as resumes would have gone
unnoticed.

Now asserts the resumed attribute, and waits for the handlers: the manual emit
dispatches asynchronously, so the previous shape also read its result before the
listener had run.

Confirmed it discriminates - keying resumed off _is_execution_resuming again
fails it with [('RestoredFlow', True)] == [('RestoredFlow', False)].

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01ASfWmW3RGy4qAQm6s8U9jH

* fix(telemetry): record the resumed marker as a string

Verified end to end against the live collector and ClickHouse: the pipeline
encodes a boolean attribute as the presence of a vBool key, so false arrives as
the key simply being absent. That is invisible in the schema and easy to read
wrongly - crew_memory is extracted as "the attribute exists" and consequently
reports 1 for 99.8% of crews against a field that defaults to False.

A string leaves nothing to infer. Confirmed in the warehouse: the emitted span
reads resumed = "false".

Adds direct coverage for the attributes each flow span records, including both
resumed values, and resets the Telemetry singleton in the helper so more than
one span method can be exercised per session.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01ASfWmW3RGy4qAQm6s8U9jH

---------

Co-authored-by: Claude Opus 5 (1M context) <noreply@anthropic.com>
2026-08-12 00:42:09 +00:00

374 lines
12 KiB
Python

import os
import threading
from unittest.mock import Mock, patch
import pytest
from crewai import Agent, Crew, Task
from crewai.telemetry import Telemetry
from opentelemetry.sdk.trace import TracerProvider
@pytest.fixture(autouse=True)
def cleanup_telemetry():
Telemetry._instance = None
if hasattr(Telemetry, "_lock"):
Telemetry._lock = threading.Lock()
yield
Telemetry._instance = None
if hasattr(Telemetry, "_lock"):
Telemetry._lock = threading.Lock()
@pytest.mark.parametrize(
"env_var,value,expected_ready",
[
("OTEL_SDK_DISABLED", "true", False),
("OTEL_SDK_DISABLED", "TRUE", False),
("CREWAI_DISABLE_TELEMETRY", "true", False),
("CREWAI_DISABLE_TELEMETRY", "TRUE", False),
("OTEL_SDK_DISABLED", "false", True),
("CREWAI_DISABLE_TELEMETRY", "false", True),
],
)
def test_telemetry_environment_variables(env_var, value, expected_ready):
"""Test telemetry state with different environment variable configurations."""
# Clear all telemetry-related env vars first, then set only the one being tested
env_overrides = {
"OTEL_SDK_DISABLED": "false",
"CREWAI_DISABLE_TELEMETRY": "false",
"CREWAI_DISABLE_TRACKING": "false",
env_var: value,
}
with patch.dict(os.environ, env_overrides):
with patch("crewai.telemetry.telemetry.TracerProvider"):
telemetry = Telemetry()
assert telemetry.ready is expected_ready
def test_telemetry_enabled_by_default():
"""Test that telemetry is enabled by default."""
with patch.dict(os.environ, {}, clear=True):
with patch("crewai.telemetry.telemetry.TracerProvider"):
telemetry = Telemetry()
assert telemetry.ready is True
def test_set_tracer_never_installs_a_global_provider():
"""Telemetry must not hijack the process-wide TracerProvider.
Installing it globally made every OTel-instrumented library in the host
process export to CrewAI's collector, so the global provider must be left
exactly as it was found whether or not an application installed one.
"""
import opentelemetry.trace as ot
with patch.dict(os.environ, {}, clear=True):
before = ot.get_tracer_provider()
telemetry = Telemetry()
telemetry.set_tracer()
after = ot.get_tracer_provider()
assert after is before
assert telemetry.trace_set is True
def test_flow_execution_span_records_crewai_version():
tracer = Mock()
span = Mock()
tracer.start_span.return_value = span
with (
patch.dict(
os.environ,
{
"CREWAI_DISABLE_TELEMETRY": "false",
"CREWAI_DISABLE_TRACKING": "false",
"OTEL_SDK_DISABLED": "false",
},
),
patch(
"crewai.telemetry.telemetry.TracerProvider",
return_value=Mock(get_tracer=Mock(return_value=tracer)),
),
patch("crewai.telemetry.telemetry.version", return_value="9.9.9"),
):
telemetry = Telemetry()
telemetry.flow_execution_span("ResearchFlow", ["start", "finish"])
tracer.start_span.assert_called_once_with("Flow Execution")
span.set_attribute.assert_any_call("crewai_version", "9.9.9")
span.set_attribute.assert_any_call("flow_name", "ResearchFlow")
def test_flow_creation_span_records_crewai_version():
tracer = Mock()
span = Mock()
tracer.start_span.return_value = span
with (
patch.dict(
os.environ,
{
"CREWAI_DISABLE_TELEMETRY": "false",
"CREWAI_DISABLE_TRACKING": "false",
"OTEL_SDK_DISABLED": "false",
},
),
patch(
"crewai.telemetry.telemetry.TracerProvider",
return_value=Mock(get_tracer=Mock(return_value=tracer)),
),
patch("crewai.telemetry.telemetry.version", return_value="9.9.9"),
):
telemetry = Telemetry()
# Flow creation also emits a once-per-process coding_agent feature span;
# stub it so this test stays focused on the Flow Creation span.
with patch.object(telemetry, "coding_agent_span"):
telemetry.flow_creation_span("ResearchFlow")
tracer.start_span.assert_called_once_with("Flow Creation")
span.set_attribute.assert_any_call("crewai_version", "9.9.9")
span.set_attribute.assert_any_call("flow_name", "ResearchFlow")
@patch("crewai.telemetry.telemetry.logger.error")
@patch(
"opentelemetry.exporter.otlp.proto.http.trace_exporter.OTLPSpanExporter.export",
side_effect=Exception("Test exception"),
)
@pytest.mark.vcr()
def test_telemetry_fails_due_connect_timeout(export_mock, logger_mock):
error = Exception("Test exception")
export_mock.side_effect = error
with patch.dict(
os.environ, {"CREWAI_DISABLE_TELEMETRY": "false", "OTEL_SDK_DISABLED": "false"}
):
telemetry = Telemetry()
tracer = telemetry.provider.get_tracer(__name__)
with tracer.start_as_current_span("test-span"):
agent = Agent(
role="agent",
llm="gpt-4o-mini",
goal="Just say hi",
backstory="You are a helpful assistant that just says hi",
)
task = Task(
description="Just say hi",
expected_output="hi",
agent=agent,
)
crew = Crew(agents=[agent], tasks=[task], name="TestCrew")
crew.kickoff()
telemetry.provider.force_flush()
assert export_mock.called
assert logger_mock.call_count == export_mock.call_count
for call in logger_mock.call_args_list:
assert call[0][0] == error
@pytest.mark.telemetry
def test_telemetry_singleton_pattern():
"""Test that Telemetry uses the singleton pattern correctly."""
Telemetry._instance = None
telemetry1 = Telemetry()
telemetry2 = Telemetry()
assert telemetry1 is telemetry2
telemetry1.test_attribute = "test_value"
assert hasattr(telemetry2, "test_attribute")
assert telemetry2.test_attribute == "test_value"
import threading
instances = []
def create_instance():
instances.append(Telemetry())
threads = [threading.Thread(target=create_instance) for _ in range(5)]
for thread in threads:
thread.start()
for thread in threads:
thread.join()
assert all(instance is telemetry1 for instance in instances)
def test_no_signal_handler_traceback_in_non_main_thread():
"""Signal handler registration should be silently skipped in non-main threads.
Regression test for https://github.com/crewAIInc/crewAI/issues/4289
"""
errors: list[Exception] = []
mock_holder: dict = {}
def init_in_thread():
try:
Telemetry._instance = None
with (
patch.dict(
os.environ,
{"CREWAI_DISABLE_TELEMETRY": "false", "OTEL_SDK_DISABLED": "false"},
),
patch("crewai.telemetry.telemetry.TracerProvider"),
patch("signal.signal") as mock_signal,
patch("crewai.telemetry.telemetry.logger") as mock_logger,
):
Telemetry()
mock_holder["signal"] = mock_signal
mock_holder["logger"] = mock_logger
except Exception as exc:
errors.append(exc)
thread = threading.Thread(target=init_in_thread)
thread.start()
thread.join()
assert not errors, f"Unexpected error: {errors}"
assert mock_holder, "Thread did not execute"
mock_holder["signal"].assert_not_called()
mock_holder["logger"].debug.assert_any_call(
"Skipping signal handler registration: not running in main thread"
)
def test_hook_dispatched_span_counts_point_usage():
with (
patch.dict(
os.environ,
{
"CREWAI_DISABLE_TELEMETRY": "false",
"CREWAI_DISABLE_TRACKING": "false",
"OTEL_SDK_DISABLED": "false",
},
),
patch("crewai.telemetry.telemetry.TracerProvider"),
):
telemetry = Telemetry()
with patch.object(telemetry, "feature_usage_span") as feature_usage_span:
telemetry.hook_dispatched_span("pre_tool_call", "proceeded")
feature_usage_span.assert_called_once_with("hooks:pre_tool_call")
def test_hook_dispatched_span_counts_aborts():
with (
patch.dict(
os.environ,
{
"CREWAI_DISABLE_TELEMETRY": "false",
"CREWAI_DISABLE_TRACKING": "false",
"OTEL_SDK_DISABLED": "false",
},
),
patch("crewai.telemetry.telemetry.TracerProvider"),
):
telemetry = Telemetry()
with patch.object(telemetry, "feature_usage_span") as feature_usage_span:
telemetry.hook_dispatched_span("pre_tool_call", "aborted")
feature_usage_span.assert_any_call("hooks:pre_tool_call")
feature_usage_span.assert_any_call("hooks:aborted")
assert feature_usage_span.call_count == 2
def test_event_listener_tracks_hook_dispatched_events():
from crewai.events.event_bus import crewai_event_bus
from crewai.events.event_listener import event_listener
from crewai.events.types.hook_events import HookDispatchedEvent
with (
crewai_event_bus.scoped_handlers(),
patch.object(
event_listener._telemetry,
"hook_dispatched_span",
) as hook_dispatched_span,
):
event_listener.setup_listeners(crewai_event_bus)
crewai_event_bus.emit(
"test",
HookDispatchedEvent(
interception_point="pre_tool_call",
outcome="aborted",
hook_count=1,
duration_ms=1.5,
),
)
crewai_event_bus.flush()
hook_dispatched_span.assert_called_once_with(
interception_point="pre_tool_call",
outcome="aborted",
)
def _emit(method: str, *args, **kwargs):
"""Run one telemetry span method against a mocked tracer.
The singleton is reset first: it caches the provider built on the very
first construction, so without this only the earliest caller in a session
would see the mocked tracer.
"""
tracer = Mock()
span = Mock()
tracer.start_span.return_value = span
Telemetry._instance = None
with (
patch.dict(
os.environ,
{
"CREWAI_DISABLE_TELEMETRY": "false",
"CREWAI_DISABLE_TRACKING": "false",
"OTEL_SDK_DISABLED": "false",
},
),
patch(
"crewai.telemetry.telemetry.TracerProvider",
return_value=Mock(get_tracer=Mock(return_value=tracer)),
),
patch("crewai.telemetry.telemetry.version", return_value="9.9.9"),
):
getattr(Telemetry(), method)(*args, **kwargs)
Telemetry._instance = None
return tracer, span
@pytest.mark.parametrize(("resumed", "expected"), [(True, "true"), (False, "false")])
def test_resumed_is_recorded_as_a_string(resumed: bool, expected: str) -> None:
"""A boolean is encoded as the presence of a key, not as a value.
``false`` arrives as the key simply being absent, which is invisible in the
schema and easy to extract wrongly - crew_memory reads 1 for 99.8% of crews
for exactly that reason. A string leaves nothing to infer.
"""
_tracer, span = _emit(
"flow_execution_span", "ResearchFlow", ["start"], "user", resumed
)
span.set_attribute.assert_any_call("resumed", expected)
for call in span.set_attribute.call_args_list:
assert call.args[1] is not True and call.args[1] is not False
def test_flow_completed_records_duration_outcome_and_origin() -> None:
_tracer, span = _emit("flow_completed_span", "ResearchFlow", 12.5, "failed", "user")
span.set_attribute.assert_any_call("flow_name", "ResearchFlow")
span.set_attribute.assert_any_call("duration_ms", 12.5)
span.set_attribute.assert_any_call("outcome", "failed")
span.set_attribute.assert_any_call("origin", "user")
def test_paused_and_method_failed_record_flow_and_origin() -> None:
for method in ("flow_paused_span", "flow_method_failed_span"):
_tracer, span = _emit(method, "ResearchFlow", "internal")
span.set_attribute.assert_any_call("flow_name", "ResearchFlow")
span.set_attribute.assert_any_call("origin", "internal")