fleet-memory/hindsight-api/tests/test_tracing.py
Nicolò Boschi 69dec8ec34
feat: add otel traceability (#330)
* feat: add comprehensive OpenTelemetry tracing

- Add tool execution spans for reflect operations
- Add tool call information (names, params) to spans
- Change verification scope from 'test' to 'verification'
- Add hindsight.reflect_generation span for done() processing
- Implement no-op tracer for improved code readability
- Update documentation for OTEL configuration
- Resolve merge conflicts from rebase

* fix: properly serialize Pydantic models in span recording

- Add _serialize_for_span() helper to handle Pydantic models
- Update all providers to use the helper function
- Fixes test failures with 'Object of type X is not JSON serializable'

* feat: add Grafana LGTM stack for unified local observability

Add Grafana LGTM (Loki, Grafana, Tempo, Mimir) as the recommended
local development observability stack. This provides traces, metrics,
and logs in a single Docker container instead of separate tools.

Changes:
- Add scripts/dev/grafana/ with docker-compose and README
- Add scripts/dev/start-grafana.sh startup script
- Update .env.example to reference Grafana LGTM
- Update configuration docs to emphasize Grafana LGTM as primary option
- Reorder OTLP backend list to show Grafana LGTM first

Benefits:
- Single container vs multiple separate tools (Jaeger, SigNoz, etc.)
- ~515MB image with full observability stack
- Compatible with existing OTLP configuration
- Simpler local development setup

* chore: remove SigNoz scripts and references

Remove SigNoz observability stack in favor of Grafana LGTM as the
sole recommended local development tracing solution.

Changes:
- Delete scripts/dev/signoz/ directory and all SigNoz configurations
- Delete scripts/dev/start-signoz.sh startup script
- Remove SigNoz references from .env.example
- Remove SigNoz from OTLP backends list in configuration docs

Grafana LGTM provides the same capabilities (traces, metrics, logs)
in a simpler single-container setup.

* feat: add consolidation span hierarchy for tracing

Add parent-child span structure for consolidation operations:
- hindsight.consolidation: Parent span for each memory being processed
- hindsight.consolidation_recall: Child span for finding related observations
- LLM call span: Automatically created by LLM provider (scope="consolidation")

This enables detailed timing breakdown in Grafana Tempo:
- Total consolidation time per memory
- Time spent in recall
- Time spent in LLM call
- Time spent executing actions (create/update)

All consolidation tests pass (31/31).

* feat: add Prometheus metrics and GenAI dashboard to Grafana stack

Add comprehensive metrics and dashboarding to the Grafana LGTM stack:

Metrics Collection:
- Configure Prometheus to scrape Hindsight API /metrics endpoint
- Scrape interval: 10 seconds
- Targets hindsight-api on host.docker.internal:8888

GenAI Dashboard:
- Pre-configured dashboard with 6 panels:
  - LLM call rate (by provider/model)
  - LLM call duration (p50/p95 by scope)
  - Token usage - input tokens/sec by scope
  - Token usage - output tokens/sec by scope
  - Operations rate (retain/recall/reflect/consolidation)
  - Operation duration p95 by operation type

Configuration:
- Mount prometheus.yml for metrics scraping
- Mount dashboards directory for auto-provisioning
- Add host.docker.internal mapping for container->host access
- Dashboard provisioning with auto-reload every 10s

Documentation:
- Updated README with metrics viewing instructions
- Added PromQL query examples
- Documented dashboard access and navigation

This provides full observability: traces (Tempo) + metrics (Prometheus/Mimir) + dashboards (Grafana)

* refactor: merge Grafana setup into existing monitoring stack

Consolidate the separate scripts/dev/grafana/ setup into the existing
scripts/dev/monitoring/ stack, using Grafana LGTM (Loki, Grafana, Tempo, Mimir).

Changes:
- Remove separate scripts/dev/grafana/ directory and start-grafana.sh
- Rewrite scripts/dev/monitoring/start.sh to use Docker + Grafana LGTM
  (was: download native Prometheus/Grafana binaries)
- Add docker-compose.yaml for Grafana LGTM container
- Add prometheus.yml for scraping Hindsight API metrics
- Mount existing dashboards from monitoring/grafana/dashboards/
- Add comprehensive README.md

Benefits:
- Single unified monitoring command: ./scripts/dev/start-monitoring.sh
- Uses existing dashboard files (hindsight-operations, hindsight-llm, hindsight-api-service)
- Simpler setup: Docker-based vs downloading/running native binaries
- Full observability: traces + metrics + logs + dashboards in one container
- Standard ports: Grafana on 3000, OTLP on 4317/4318

Architecture:
- Grafana LGTM container (~515MB) provides all components
- Dashboards auto-provisioned from monitoring/grafana/dashboards/
- Prometheus scrapes host.docker.internal:8888/metrics
- Shared hindsight-network for future service-to-service tracing

* fix: run monitoring stack in foreground for easy Ctrl+C stop

Change docker-compose from detached (-d) to foreground mode.
Users can now stop the stack with Ctrl+C instead of needing
to run docker-compose down separately.

* fix: remove invalid home dashboard path and obsolete version field

- Remove GF_DASHBOARDS_DEFAULT_HOME_DASHBOARD_PATH environment variable
  (was pointing to wrong path causing 'Failed to load home dashboard' error)
- Remove obsolete 'version' field from docker-compose.yaml
  (docker-compose v2+ doesn't require version field)

* fix: load Hindsight dashboards in Grafana LGTM

Mount Hindsight dashboard JSON files and custom provisioning config
to make dashboards visible in Grafana.

Changes:
- Mount hindsight-operations.json, hindsight-llm.json, hindsight-api-service.json to /otel-lgtm/
- Create grafana-dashboards.yaml with all dashboard providers (default + Hindsight)
- Mount custom provisioning config to override LGTM default

All 3 Hindsight dashboards now appear in Grafana UI with metrics
from Prometheus scraping the Hindsight API /metrics endpoint.

* fix: configure Prometheus to scrape Hindsight API metrics

Update prometheus.yml to include both OTLP receiver config (from LGTM)
and scrape_configs for pulling metrics from Hindsight API.

Changes:
- Mount prometheus.yml to /otel-lgtm/prometheus.yaml (where LGTM reads it)
- Add scrape_configs section to pull from host.docker.internal:8888/metrics
- Keep OTLP receiver configuration for trace metrics
- Set scrape_interval to 5s

Verified: Prometheus now successfully scrapes hindsight_llm_calls_total
and other Hindsight metrics. Dashboards now show live data!

* feat: add comprehensive tracing for recall and improve reflect/mental_model_refresh spans

- Add recall operation tracing with parent-child span hierarchy
  - Parent: hindsight.recall with attributes (bank_id, query, fact_types, etc.)
  - Children: recall_embedding, recall_retrieval, recall_fusion, recall_rerank
  - Fixed context propagation using start_as_current_span()

- Improve reflect tracing spans
  - Remove reflect_generation spans, use reflect instead
  - Change done() tool processing to hindsight.reflect_tool_call

- Fix mental_model_refresh span nesting
  - Add _skip_span parameter to reflect_async to avoid duplicate hindsight.reflect spans
  - Mental model refresh now has clean span hierarchy without nested reflect parent

- Add comprehensive tracing verification tests
  - Test span hierarchy and attributes for all operations
  - Verify parent-child relationships
  - 5 passing tests covering recall, reflect, consolidation, and mental_model_refresh

* refactor: remove redundant is_tracing_enabled() checks

- Remove all is_tracing_enabled() conditional checks before tracing calls
- NoOpTracer/NoOpSpan handle disabled tracing automatically
- Simplify code by always calling tracer methods directly
- Fix NoOpTracer.start_as_current_span() to yield NoOpSpan instead of None

Changes:
- memory_engine.py: Remove 5 is_tracing_enabled checks in recall spans
- agent.py: Remove 2 is_tracing_enabled checks in reflect tool spans
- tracing.py: Fix NoOpTracer context manager to yield proper NoOpSpan

This eliminates ~50 lines of redundant conditional code while maintaining
identical behavior.

* docs: simplify distributed tracing section in monitoring.md

- Make tracing documentation more concise
- Focus on span hierarchy and attributes
- Remove verbose troubleshooting and performance sections
- Keep configuration.md for env vars only
2026-02-10 12:20:48 +01:00

407 lines
13 KiB
Python

"""
Unit tests for OpenTelemetry tracing instrumentation.
Tests the tracing module's ability to record LLM calls with GenAI semantic conventions.
"""
import json
from unittest.mock import MagicMock, patch
import pytest
from hindsight_api.tracing import (
PROVIDER_NAME_MAPPING,
GenAIAttributes,
LLMSpanRecorder,
NoOpLLMSpanRecorder,
_truncate_content,
create_operation_span,
initialize_tracing,
is_tracing_enabled,
)
def test_provider_name_mapping():
"""Test that provider names are correctly mapped to GenAI conventions."""
assert PROVIDER_NAME_MAPPING["openai"] == "openai"
assert PROVIDER_NAME_MAPPING["anthropic"] == "anthropic"
assert PROVIDER_NAME_MAPPING["gemini"] == "google"
assert PROVIDER_NAME_MAPPING["vertexai"] == "google"
assert PROVIDER_NAME_MAPPING["groq"] == "groq"
assert PROVIDER_NAME_MAPPING["ollama"] == "ollama"
assert PROVIDER_NAME_MAPPING["openai-codex"] == "openai"
assert PROVIDER_NAME_MAPPING["claude-code"] == "anthropic"
def test_truncate_content_short():
"""Test that short content is not truncated."""
content = "This is a short message"
result = _truncate_content(content)
assert result == content
def test_truncate_content_long():
"""Test that long content is truncated."""
content = "x" * 150000 # Exceeds MAX_CONTENT_LENGTH
result = _truncate_content(content)
assert len(result) < len(content)
assert "[TRUNCATED:" in result
assert result.startswith("x" * 100)
def test_noop_span_recorder():
"""Test that NoOpLLMSpanRecorder doesn't raise errors."""
recorder = NoOpLLMSpanRecorder()
# Should not raise any errors
recorder.record_llm_call(
provider="openai",
model="gpt-4",
scope="test",
messages=[{"role": "user", "content": "test"}],
response_content="test response",
input_tokens=10,
output_tokens=5,
duration=1.0,
)
def test_llm_span_recorder_format_messages():
"""Test message formatting to GenAI convention."""
mock_tracer = MagicMock()
recorder = LLMSpanRecorder(mock_tracer)
messages = [
{"role": "system", "content": "You are helpful"},
{"role": "user", "content": "Hello"},
]
result = recorder._format_messages(messages)
parsed = json.loads(result)
assert len(parsed) == 2
assert parsed[0]["role"] == "system"
assert parsed[0]["content"] == "You are helpful"
assert parsed[1]["role"] == "user"
assert parsed[1]["content"] == "Hello"
def test_llm_span_recorder_format_output():
"""Test output formatting to GenAI convention."""
mock_tracer = MagicMock()
recorder = LLMSpanRecorder(mock_tracer)
result = recorder._format_output("Hello world", "stop")
parsed = json.loads(result)
assert len(parsed) == 1
assert parsed[0]["role"] == "assistant"
assert parsed[0]["content"] == "Hello world"
def test_llm_span_recorder_format_output_none():
"""Test output formatting with None content."""
mock_tracer = MagicMock()
recorder = LLMSpanRecorder(mock_tracer)
result = recorder._format_output(None, None)
parsed = json.loads(result)
assert parsed == []
def test_llm_span_recorder_extract_system_instructions():
"""Test system instruction extraction."""
mock_tracer = MagicMock()
recorder = LLMSpanRecorder(mock_tracer)
messages = [
{"role": "system", "content": "You are helpful"},
{"role": "user", "content": "Hello"},
]
result = recorder._extract_system_instructions(messages)
assert result == "You are helpful"
def test_llm_span_recorder_extract_system_instructions_none():
"""Test system instruction extraction with no system message."""
mock_tracer = MagicMock()
recorder = LLMSpanRecorder(mock_tracer)
messages = [
{"role": "user", "content": "Hello"},
]
result = recorder._extract_system_instructions(messages)
assert result is None
@patch("hindsight_api.tracing.time")
def test_llm_span_recorder_record_success(mock_time):
"""Test successful LLM call recording."""
# Mock time
mock_time.time_ns.return_value = 1000000000000 # 1 second in nanoseconds
# Create mock tracer and span
mock_span = MagicMock()
mock_tracer = MagicMock()
mock_tracer.start_as_current_span.return_value.__enter__.return_value = mock_span
recorder = LLMSpanRecorder(mock_tracer)
messages = [{"role": "user", "content": "Hello"}]
response_content = "Hi there!"
recorder.record_llm_call(
provider="openai",
model="gpt-4",
scope="test",
messages=messages,
response_content=response_content,
input_tokens=10,
output_tokens=5,
duration=1.5,
finish_reason="stop",
error=None,
)
# Verify span was created with correct name (hindsight.{scope})
mock_tracer.start_as_current_span.assert_called_once()
call_args = mock_tracer.start_as_current_span.call_args
assert call_args[0][0] == "hindsight.test"
# Verify attributes were set
assert mock_span.set_attribute.called
attribute_calls = {call[0][0]: call[0][1] for call in mock_span.set_attribute.call_args_list}
assert attribute_calls[GenAIAttributes.OPERATION_NAME] == "chat"
assert attribute_calls[GenAIAttributes.PROVIDER_NAME] == "openai"
assert attribute_calls[GenAIAttributes.REQUEST_MODEL] == "gpt-4"
assert attribute_calls[GenAIAttributes.RESPONSE_MODEL] == "gpt-4"
assert attribute_calls[GenAIAttributes.USAGE_INPUT_TOKENS] == 10
assert attribute_calls[GenAIAttributes.USAGE_OUTPUT_TOKENS] == 5
assert attribute_calls["hindsight.scope"] == "test"
# Verify event was added
mock_span.add_event.assert_called_once()
event_call = mock_span.add_event.call_args
assert event_call[0][0] == "gen_ai.client.inference.operation.details"
# Verify status was set to OK
mock_span.set_status.assert_called()
# Verify span was ended
mock_span.end.assert_called_once()
@patch("hindsight_api.tracing.time")
def test_llm_span_recorder_record_error(mock_time):
"""Test error LLM call recording."""
# Mock time
mock_time.time_ns.return_value = 1000000000000
# Create mock tracer and span
mock_span = MagicMock()
mock_tracer = MagicMock()
mock_tracer.start_as_current_span.return_value.__enter__.return_value = mock_span
recorder = LLMSpanRecorder(mock_tracer)
messages = [{"role": "user", "content": "Hello"}]
error = ValueError("Test error")
recorder.record_llm_call(
provider="anthropic",
model="claude-3",
scope="test",
messages=messages,
response_content=None,
input_tokens=10,
output_tokens=0,
duration=0.5,
finish_reason=None,
error=error,
)
# Verify error status was set
mock_span.set_status.assert_called()
status_call = mock_span.set_status.call_args[0][0]
assert status_call.status_code.name == "ERROR"
# Verify error type attribute was set
attribute_calls = {call[0][0]: call[0][1] for call in mock_span.set_attribute.call_args_list}
assert attribute_calls[GenAIAttributes.ERROR_TYPE] == "ValueError"
# Verify exception was recorded
mock_span.record_exception.assert_called_once_with(error)
@patch("hindsight_api.tracing.time")
def test_llm_span_recorder_provider_mapping(mock_time):
"""Test that provider names are mapped correctly."""
mock_time.time_ns.return_value = 1000000000000
mock_span = MagicMock()
mock_tracer = MagicMock()
mock_tracer.start_as_current_span.return_value.__enter__.return_value = mock_span
recorder = LLMSpanRecorder(mock_tracer)
# Test gemini -> google mapping
recorder.record_llm_call(
provider="gemini",
model="gemini-pro",
scope="test",
messages=[{"role": "user", "content": "test"}],
response_content="test",
input_tokens=5,
output_tokens=3,
duration=1.0,
)
attribute_calls = {call[0][0]: call[0][1] for call in mock_span.set_attribute.call_args_list}
assert attribute_calls[GenAIAttributes.PROVIDER_NAME] == "google"
# ==================== Parent Span Tests ====================
def test_create_operation_span_disabled():
"""Test that create_operation_span returns no-op when tracing is disabled."""
# Tracing should be disabled by default
assert not is_tracing_enabled()
# Should return a no-op context manager
span = create_operation_span("test_operation", "test_bank_id")
# Should be usable as context manager without errors
with span:
pass
@patch("hindsight_api.tracing._tracer")
@patch("hindsight_api.tracing._tracing_enabled", True)
def test_create_operation_span_enabled(mock_tracer):
"""Test that create_operation_span creates a span when tracing is enabled."""
# Mock the tracer
mock_span = MagicMock()
mock_tracer.start_as_current_span.return_value = mock_span
# Create operation span
span = create_operation_span("retain", "bank123")
# Verify span was created with correct name
mock_tracer.start_as_current_span.assert_called_once_with("hindsight.retain")
# Verify attributes were set
mock_span.set_attribute.assert_any_call("hindsight.operation", "retain")
mock_span.set_attribute.assert_any_call("hindsight.bank_id", "bank123")
@patch("hindsight_api.tracing._tracer")
@patch("hindsight_api.tracing._tracing_enabled", True)
def test_create_operation_span_no_bank_id(mock_tracer):
"""Test that create_operation_span works without bank_id."""
mock_span = MagicMock()
mock_tracer.start_as_current_span.return_value = mock_span
# Create operation span without bank_id
span = create_operation_span("consolidation")
# Verify span was created
mock_tracer.start_as_current_span.assert_called_once_with("hindsight.consolidation")
# Verify only operation attribute was set (not bank_id)
assert mock_span.set_attribute.call_count == 1
mock_span.set_attribute.assert_called_once_with("hindsight.operation", "consolidation")
@patch("hindsight_api.tracing._tracer")
@patch("hindsight_api.tracing._tracing_enabled", True)
def test_create_operation_span_all_operations(mock_tracer):
"""Test that all 4 operations can create parent spans."""
mock_span = MagicMock()
mock_tracer.start_as_current_span.return_value = mock_span
operations = ["retain", "consolidation", "reflect", "mental_model_refresh"]
for operation in operations:
mock_tracer.reset_mock()
mock_span.reset_mock()
span = create_operation_span(operation, "test_bank")
# Verify span was created with correct name
mock_tracer.start_as_current_span.assert_called_once_with(f"hindsight.{operation}")
# Verify attributes
mock_span.set_attribute.assert_any_call("hindsight.operation", operation)
mock_span.set_attribute.assert_any_call("hindsight.bank_id", "test_bank")
@patch("hindsight_api.tracing.time")
@patch("hindsight_api.tracing._tracer")
@patch("hindsight_api.tracing._tracing_enabled", True)
def test_parent_child_span_hierarchy(mock_tracer, mock_time):
"""Test that child LLM spans are created under parent operation spans."""
mock_time.time_ns.return_value = 1000000000000
# Create mock parent span
mock_parent_span = MagicMock()
mock_parent_span.__enter__ = MagicMock(return_value=mock_parent_span)
mock_parent_span.__exit__ = MagicMock(return_value=False)
# Create mock child span
mock_child_span = MagicMock()
# Mock tracer to return parent span first, then child span
mock_tracer.start_as_current_span.side_effect = [
mock_parent_span, # Parent span
MagicMock(__enter__=MagicMock(return_value=mock_child_span), __exit__=MagicMock(return_value=False)), # Child
]
# Create parent operation span
with create_operation_span("retain", "bank123"):
# Simulate creating a child LLM span
recorder = LLMSpanRecorder(mock_tracer)
recorder.record_llm_call(
provider="openai",
model="gpt-4",
scope="retain_extract_facts",
messages=[{"role": "user", "content": "test"}],
response_content="response",
input_tokens=10,
output_tokens=5,
duration=1.0,
)
# Verify both parent and child spans were created
assert mock_tracer.start_as_current_span.call_count == 2
# Verify parent span was created first
first_call = mock_tracer.start_as_current_span.call_args_list[0]
assert first_call[0][0] == "hindsight.retain"
# Verify child span was created second (hindsight.{scope})
second_call = mock_tracer.start_as_current_span.call_args_list[1]
assert second_call[0][0] == "hindsight.retain_extract_facts"
@patch("hindsight_api.tracing._tracer")
@patch("hindsight_api.tracing._tracing_enabled", True)
def test_operation_span_context_manager(mock_tracer):
"""Test that operation spans work as context managers."""
mock_span = MagicMock()
mock_span.__enter__ = MagicMock(return_value=mock_span)
mock_span.__exit__ = MagicMock(return_value=False)
mock_tracer.start_as_current_span.return_value = mock_span
# Use span as context manager
with create_operation_span("reflect", "bank456"):
# Do some work
pass
# Verify span lifecycle
mock_tracer.start_as_current_span.assert_called_once()
mock_span.__enter__.assert_called_once()
mock_span.__exit__.assert_called_once()