* 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
407 lines
13 KiB
Python
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()
|