diff --git a/backend/routes/api_keys.py b/backend/routes/api_keys.py index f6f46ea..20b4509 100644 --- a/backend/routes/api_keys.py +++ b/backend/routes/api_keys.py @@ -1,9 +1,16 @@ """API key management and metrics routes.""" -from fastapi import APIRouter, Depends +from fastapi import APIRouter, HTTPException, Depends from pydantic import BaseModel from dependencies import api_key_manager, rate_limiter, metrics from middleware.auth import require_auth, AuthContext +from services.observability import ( + logger, + capture_exception, + track_time, + add_breadcrumb, + set_operation_context +) router = APIRouter(prefix="", tags=["API Keys"]) @@ -18,7 +25,19 @@ async def get_performance_metrics( auth: AuthContext = Depends(require_auth) ): """Get performance metrics and monitoring data.""" - return metrics.get_metrics() + set_operation_context("get_metrics", user_id=auth.user_id) + + logger.debug("Metrics requested", user_id=auth.user_id) + + try: + with track_time("get_metrics"): + result = metrics.get_metrics() + + return result + except Exception as e: + logger.error("Failed to get metrics", user_id=auth.user_id, error=str(e)) + capture_exception(e, operation="get_metrics", user_id=auth.user_id) + raise HTTPException(status_code=500, detail="Failed to retrieve metrics") @router.post("/keys/generate") @@ -27,18 +46,51 @@ async def generate_api_key( auth: AuthContext = Depends(require_auth) ): """Generate a new API key.""" - new_key = api_key_manager.generate_key( - name=request.name, - tier=request.tier, - user_id=auth.user_id + set_operation_context("generate_api_key", user_id=auth.user_id, tier=request.tier) + add_breadcrumb("API key generation requested", category="api_keys", tier=request.tier) + + logger.info( + "API key generation requested", + user_id=auth.user_id, + key_name=request.name, + tier=request.tier ) - return { - "api_key": new_key, - "tier": request.tier, - "name": request.name, - "message": "Save this key securely - it won't be shown again" - } + try: + with track_time("generate_api_key", tier=request.tier): + new_key = api_key_manager.generate_key( + name=request.name, + tier=request.tier, + user_id=auth.user_id + ) + + logger.info( + "API key generated successfully", + user_id=auth.user_id, + key_name=request.name, + tier=request.tier + ) + + return { + "api_key": new_key, + "tier": request.tier, + "name": request.name, + "message": "Save this key securely - it won't be shown again" + } + except Exception as e: + logger.error( + "API key generation failed", + user_id=auth.user_id, + key_name=request.name, + error=str(e) + ) + capture_exception( + e, + operation="generate_api_key", + user_id=auth.user_id, + key_name=request.name + ) + raise HTTPException(status_code=500, detail="Failed to generate API key") @router.get("/keys/usage") @@ -46,14 +98,24 @@ async def get_api_usage( auth: AuthContext = Depends(require_auth) ): """Get current API usage stats.""" - usage = rate_limiter.get_usage(auth.identifier) + set_operation_context("get_api_usage", user_id=auth.user_id, tier=auth.tier) + + logger.debug("API usage requested", user_id=auth.user_id, tier=auth.tier) - return { - "tier": auth.tier, - "limits": { - "free": {"minute": 20, "hour": 200, "day": 1000}, - "pro": {"minute": 100, "hour": 2000, "day": 20000}, - "enterprise": {"minute": 500, "hour": 10000, "day": 100000} - }[auth.tier], - "usage": usage - } + try: + with track_time("get_api_usage"): + usage = rate_limiter.get_usage(auth.identifier) + + return { + "tier": auth.tier, + "limits": { + "free": {"minute": 20, "hour": 200, "day": 1000}, + "pro": {"minute": 100, "hour": 2000, "day": 20000}, + "enterprise": {"minute": 500, "hour": 10000, "day": 100000} + }[auth.tier], + "usage": usage + } + except Exception as e: + logger.error("Failed to get API usage", user_id=auth.user_id, error=str(e)) + capture_exception(e, operation="get_api_usage", user_id=auth.user_id) + raise HTTPException(status_code=500, detail="Failed to retrieve usage data") diff --git a/backend/routes/auth.py b/backend/routes/auth.py index 321af13..b785780 100644 --- a/backend/routes/auth.py +++ b/backend/routes/auth.py @@ -7,6 +7,13 @@ from typing import Optional, Dict, Any from services.auth import get_auth_service from middleware.auth import get_current_user +from services.observability import ( + logger, + capture_exception, + track_time, + add_breadcrumb, + set_operation_context +) # Create router router = APIRouter(prefix="/auth", tags=["Authentication"]) @@ -45,12 +52,31 @@ async def signup(request: SignupRequest): Returns user data and session tokens (access_token, refresh_token) """ - auth_service = get_auth_service() - return await auth_service.signup( - email=request.email, - password=request.password, - github_username=request.github_username - ) + set_operation_context("auth_signup", email=request.email) + add_breadcrumb("Signup attempt", category="auth", email=request.email) + + logger.info("Signup attempt", email=request.email, has_github=bool(request.github_username)) + + try: + auth_service = get_auth_service() + + with track_time("auth_signup"): + result = await auth_service.signup( + email=request.email, + password=request.password, + github_username=request.github_username + ) + + logger.info("Signup successful", email=request.email) + return result + + except HTTPException: + logger.warning("Signup failed (client error)", email=request.email) + raise + except Exception as e: + logger.error("Signup failed", email=request.email, error=str(e)) + capture_exception(e, operation="auth_signup", email=request.email) + raise HTTPException(status_code=500, detail="Signup failed") @router.post("/login", response_model=AuthResponse) @@ -63,11 +89,30 @@ async def login(request: LoginRequest): Returns user data and session tokens """ - auth_service = get_auth_service() - return await auth_service.login( - email=request.email, - password=request.password - ) + set_operation_context("auth_login", email=request.email) + add_breadcrumb("Login attempt", category="auth", email=request.email) + + logger.info("Login attempt", email=request.email) + + try: + auth_service = get_auth_service() + + with track_time("auth_login"): + result = await auth_service.login( + email=request.email, + password=request.password + ) + + logger.info("Login successful", email=request.email) + return result + + except HTTPException: + logger.warning("Login failed (invalid credentials)", email=request.email) + raise + except Exception as e: + logger.error("Login failed", email=request.email, error=str(e)) + capture_exception(e, operation="auth_login", email=request.email) + raise HTTPException(status_code=500, detail="Login failed") @router.post("/refresh") @@ -79,8 +124,27 @@ async def refresh(request: RefreshRequest): Returns new access token """ - auth_service = get_auth_service() - return await auth_service.refresh_session(request.refresh_token) + set_operation_context("auth_refresh") + add_breadcrumb("Token refresh attempt", category="auth") + + logger.debug("Token refresh attempt") + + try: + auth_service = get_auth_service() + + with track_time("auth_refresh"): + result = await auth_service.refresh_session(request.refresh_token) + + logger.debug("Token refresh successful") + return result + + except HTTPException: + logger.warning("Token refresh failed (invalid token)") + raise + except Exception as e: + logger.error("Token refresh failed", error=str(e)) + capture_exception(e, operation="auth_refresh") + raise HTTPException(status_code=500, detail="Token refresh failed") @router.post("/logout") @@ -90,8 +154,25 @@ async def logout(user: Dict = Depends(get_current_user)): Requires: Valid JWT token in Authorization header """ - auth_service = get_auth_service() - return await auth_service.logout(token="") # Supabase handles session + user_id = user.get("id") or user.get("user_id") + set_operation_context("auth_logout", user_id=user_id) + add_breadcrumb("Logout attempt", category="auth", user_id=user_id) + + logger.info("Logout attempt", user_id=user_id) + + try: + auth_service = get_auth_service() + + with track_time("auth_logout"): + result = await auth_service.logout(token="") # Supabase handles session + + logger.info("Logout successful", user_id=user_id) + return result + + except Exception as e: + logger.error("Logout failed", user_id=user_id, error=str(e)) + capture_exception(e, operation="auth_logout", user_id=user_id) + raise HTTPException(status_code=500, detail="Logout failed") @router.get("/me") @@ -103,4 +184,9 @@ async def get_current_user_info(user: Dict = Depends(get_current_user)): Returns user profile data """ + user_id = user.get("id") or user.get("user_id") + set_operation_context("auth_me", user_id=user_id) + + logger.debug("User info requested", user_id=user_id) + return {"user": user} diff --git a/backend/routes/search.py b/backend/routes/search.py index a907a81..15e46ae 100644 --- a/backend/routes/search.py +++ b/backend/routes/search.py @@ -10,6 +10,13 @@ ) from services.input_validator import InputValidator from middleware.auth import require_auth, AuthContext +from services.observability import ( + logger, + capture_exception, + track_time, + add_breadcrumb, + set_operation_context +) router = APIRouter(prefix="", tags=["Search"]) @@ -32,11 +39,25 @@ async def search_code( auth: AuthContext = Depends(require_auth) ): """Search code semantically with caching.""" + set_operation_context( + "search", + user_id=auth.user_id, + repo_id=request.repo_id, + query_length=len(request.query) + ) + add_breadcrumb("Search request received", category="search", repo_id=request.repo_id) + verify_repo_access(request.repo_id, auth.user_id) # Validate query valid_query, query_error = InputValidator.validate_search_query(request.query) if not valid_query: + logger.warning( + "Invalid search query rejected", + user_id=auth.user_id, + repo_id=request.repo_id, + error=query_error + ) raise HTTPException(status_code=400, detail=f"Invalid query: {query_error}") sanitized_query = InputValidator.sanitize_string(request.query, max_length=500) @@ -44,29 +65,58 @@ async def search_code( try: # Check cache - cached_results = cache.get_search_results(sanitized_query, request.repo_id) + with track_time("search_cache_check", repo_id=request.repo_id): + cached_results = cache.get_search_results(sanitized_query, request.repo_id) + if cached_results: duration = time.time() - start_time metrics.record_search(duration, cached=True) + logger.info( + "Search completed (cache hit)", + user_id=auth.user_id, + repo_id=request.repo_id, + result_count=len(cached_results), + duration_ms=round(duration * 1000, 2) + ) return {"results": cached_results, "count": len(cached_results), "cached": True} # Search - results = await indexer.semantic_search( - query=sanitized_query, - repo_id=request.repo_id, - max_results=min(request.max_results, 50), - use_query_expansion=True, - use_reranking=True - ) + with track_time("semantic_search", repo_id=request.repo_id): + results = await indexer.semantic_search( + query=sanitized_query, + repo_id=request.repo_id, + max_results=min(request.max_results, 50), + use_query_expansion=True, + use_reranking=True + ) # Cache results - cache.set_search_results(sanitized_query, request.repo_id, results, ttl=3600) + with track_time("search_cache_set", repo_id=request.repo_id): + cache.set_search_results(sanitized_query, request.repo_id, results, ttl=3600) duration = time.time() - start_time metrics.record_search(duration, cached=False) + logger.info( + "Search completed", + user_id=auth.user_id, + repo_id=request.repo_id, + result_count=len(results), + duration_ms=round(duration * 1000, 2), + cached=False + ) + return {"results": results, "count": len(results), "cached": False} + except HTTPException: + raise except Exception as e: + logger.error( + "Search failed", + user_id=auth.user_id, + repo_id=request.repo_id, + error=str(e) + ) + capture_exception(e, operation="search", repo_id=request.repo_id, user_id=auth.user_id) raise HTTPException(status_code=500, detail=str(e)) @@ -76,17 +126,55 @@ async def explain_code( auth: AuthContext = Depends(require_auth) ): """Generate code explanation.""" + set_operation_context( + "explain", + user_id=auth.user_id, + repo_id=request.repo_id, + file_path=request.file_path + ) + add_breadcrumb("Explain request received", category="explain", file_path=request.file_path) + try: repo = get_repo_or_404(request.repo_id, auth.user_id) - explanation = await indexer.explain_code( + logger.info( + "Generating code explanation", + user_id=auth.user_id, repo_id=request.repo_id, file_path=request.file_path, function_name=request.function_name ) + with track_time("explain_code", repo_id=request.repo_id, file_path=request.file_path): + explanation = await indexer.explain_code( + repo_id=request.repo_id, + file_path=request.file_path, + function_name=request.function_name + ) + + logger.info( + "Code explanation generated", + user_id=auth.user_id, + repo_id=request.repo_id, + file_path=request.file_path + ) + return {"explanation": explanation} except HTTPException: raise except Exception as e: + logger.error( + "Explain failed", + user_id=auth.user_id, + repo_id=request.repo_id, + file_path=request.file_path, + error=str(e) + ) + capture_exception( + e, + operation="explain", + repo_id=request.repo_id, + user_id=auth.user_id, + file_path=request.file_path + ) raise HTTPException(status_code=500, detail=str(e)) diff --git a/backend/routes/search_v2.py b/backend/routes/search_v2.py index 4e591e6..feeff12 100644 --- a/backend/routes/search_v2.py +++ b/backend/routes/search_v2.py @@ -8,6 +8,13 @@ from dependencies import indexer, cache, metrics, verify_repo_access from services.input_validator import InputValidator from middleware.auth import require_auth, AuthContext +from services.observability import ( + logger, + capture_exception, + track_time, + add_breadcrumb, + set_operation_context +) router = APIRouter(prefix="/search", tags=["Search V2"]) @@ -50,13 +57,29 @@ async def search_v2( auth: AuthContext = Depends(require_auth) ): """Function-level semantic search with hybrid BM25 + vector ranking.""" + set_operation_context( + "search_v2", + user_id=auth.user_id, + repo_id=request.repo_id, + query_length=len(request.query), + top_k=request.top_k + ) + add_breadcrumb("Search V2 request received", category="search_v2", repo_id=request.repo_id) + if not SEARCH_V2_ENABLED: + logger.warning("Search V2 disabled but request received", user_id=auth.user_id) raise HTTPException(status_code=503, detail="Search V2 is not enabled") verify_repo_access(request.repo_id, auth.user_id) valid_query, query_error = InputValidator.validate_search_query(request.query) if not valid_query: + logger.warning( + "Invalid search query rejected", + user_id=auth.user_id, + repo_id=request.repo_id, + error=query_error + ) raise HTTPException(status_code=400, detail=f"Invalid query: {query_error}") sanitized_query = InputValidator.sanitize_string(request.query, max_length=500) @@ -64,9 +87,20 @@ async def search_v2( try: cache_key = f"v2:{sanitized_query}:{request.repo_id}:{request.top_k}" - cached = cache.get_search_results(cache_key, request.repo_id) + + with track_time("search_v2_cache_check", repo_id=request.repo_id): + cached = cache.get_search_results(cache_key, request.repo_id) + if cached: - metrics.record_search(time.time() - start_time, cached=True) + duration = time.time() - start_time + metrics.record_search(duration, cached=True) + logger.info( + "Search V2 completed (cache hit)", + user_id=auth.user_id, + repo_id=request.repo_id, + result_count=len(cached), + duration_ms=round(duration * 1000, 2) + ) return SearchV2Response( results=cached, query=sanitized_query, @@ -74,16 +108,30 @@ async def search_v2( cached=True, ) - results = await indexer.search_v2( - query=sanitized_query, + with track_time("search_v2_execution", repo_id=request.repo_id, use_reranking=request.use_reranking): + results = await indexer.search_v2( + query=sanitized_query, + repo_id=request.repo_id, + top_k=request.top_k, + use_reranking=request.use_reranking, + ) + + with track_time("search_v2_cache_set", repo_id=request.repo_id): + cache.set_search_results(cache_key, request.repo_id, results, ttl=3600) + + duration = time.time() - start_time + metrics.record_search(duration, cached=False) + + logger.info( + "Search V2 completed", + user_id=auth.user_id, repo_id=request.repo_id, - top_k=request.top_k, - use_reranking=request.use_reranking, + result_count=len(results), + duration_ms=round(duration * 1000, 2), + cached=False, + use_reranking=request.use_reranking ) - cache.set_search_results(cache_key, request.repo_id, results, ttl=3600) - metrics.record_search(time.time() - start_time, cached=False) - return SearchV2Response( results=results, query=sanitized_query, @@ -91,5 +139,19 @@ async def search_v2( cached=False, ) + except HTTPException: + raise except Exception as e: + logger.error( + "Search V2 failed", + user_id=auth.user_id, + repo_id=request.repo_id, + error=str(e) + ) + capture_exception( + e, + operation="search_v2", + repo_id=request.repo_id, + user_id=auth.user_id + ) raise HTTPException(status_code=500, detail=str(e)) diff --git a/backend/tests/test_observability_routes.py b/backend/tests/test_observability_routes.py new file mode 100644 index 0000000..1ea8e79 --- /dev/null +++ b/backend/tests/test_observability_routes.py @@ -0,0 +1,441 @@ +""" +Tests for Observability Instrumentation in Routes + +Verifies that all routes properly use the observability module for: +- Structured logging +- Sentry context/breadcrumbs +- Performance tracking +- Error capture + +Issue: #163 +""" +import pytest +from unittest.mock import AsyncMock, MagicMock, patch, call +from fastapi import HTTPException + + +class TestSearchRouteObservability: + """Tests for observability in routes/search.py""" + + @pytest.fixture + def mock_observability(self): + """Mock all observability functions""" + with patch("routes.search.logger") as mock_logger, \ + patch("routes.search.capture_exception") as mock_capture, \ + patch("routes.search.track_time") as mock_track, \ + patch("routes.search.add_breadcrumb") as mock_breadcrumb, \ + patch("routes.search.set_operation_context") as mock_context: + + # Make track_time work as a context manager + mock_track.return_value.__enter__ = MagicMock() + mock_track.return_value.__exit__ = MagicMock(return_value=False) + + yield { + "logger": mock_logger, + "capture_exception": mock_capture, + "track_time": mock_track, + "add_breadcrumb": mock_breadcrumb, + "set_operation_context": mock_context + } + + @pytest.fixture + def mock_dependencies(self): + """Mock route dependencies""" + with patch("routes.search.indexer") as mock_indexer, \ + patch("routes.search.cache") as mock_cache, \ + patch("routes.search.metrics") as mock_metrics, \ + patch("routes.search.verify_repo_access") as mock_verify: + + mock_indexer.semantic_search = AsyncMock(return_value=[ + {"name": "test_func", "file_path": "test.py", "score": 0.9} + ]) + mock_cache.get_search_results = MagicMock(return_value=None) + mock_cache.set_search_results = MagicMock() + mock_metrics.record_search = MagicMock() + + yield { + "indexer": mock_indexer, + "cache": mock_cache, + "metrics": mock_metrics, + "verify": mock_verify + } + + @pytest.mark.asyncio + async def test_search_sets_operation_context(self, mock_observability, mock_dependencies): + """Search endpoint should set Sentry operation context""" + from routes.search import search_code, SearchRequest + from middleware.auth import AuthContext + + request = SearchRequest(query="test query", repo_id="test-repo") + auth = AuthContext(user_id="user-123", email="test@test.com") + + await search_code(request, auth) + + mock_observability["set_operation_context"].assert_called_once() + call_args = mock_observability["set_operation_context"].call_args + assert call_args[0][0] == "search" + assert call_args[1]["user_id"] == "user-123" + assert call_args[1]["repo_id"] == "test-repo" + + @pytest.mark.asyncio + async def test_search_adds_breadcrumb(self, mock_observability, mock_dependencies): + """Search endpoint should add Sentry breadcrumb""" + from routes.search import search_code, SearchRequest + from middleware.auth import AuthContext + + request = SearchRequest(query="auth function", repo_id="repo-1") + auth = AuthContext(user_id="user-1", email="test@test.com") + + await search_code(request, auth) + + mock_observability["add_breadcrumb"].assert_called() + + @pytest.mark.asyncio + async def test_search_logs_completion(self, mock_observability, mock_dependencies): + """Search endpoint should log successful completion""" + from routes.search import search_code, SearchRequest + from middleware.auth import AuthContext + + request = SearchRequest(query="test", repo_id="repo") + auth = AuthContext(user_id="user", email="test@test.com") + + await search_code(request, auth) + + # Check that info was logged with result count + mock_observability["logger"].info.assert_called() + info_calls = [c for c in mock_observability["logger"].info.call_args_list] + assert any("completed" in str(c).lower() for c in info_calls) + + @pytest.mark.asyncio + async def test_search_tracks_time(self, mock_observability, mock_dependencies): + """Search endpoint should track operation timing""" + from routes.search import search_code, SearchRequest + from middleware.auth import AuthContext + + request = SearchRequest(query="test", repo_id="repo") + auth = AuthContext(user_id="user", email="test@test.com") + + await search_code(request, auth) + + # Should track cache check and semantic search + track_calls = mock_observability["track_time"].call_args_list + assert len(track_calls) >= 2 # cache check + search + cache set + + @pytest.mark.asyncio + async def test_search_captures_exception_on_error(self, mock_observability, mock_dependencies): + """Search endpoint should capture exceptions to Sentry""" + from routes.search import search_code, SearchRequest + from middleware.auth import AuthContext + + mock_dependencies["indexer"].semantic_search = AsyncMock( + side_effect=Exception("Search engine error") + ) + + request = SearchRequest(query="test", repo_id="repo") + auth = AuthContext(user_id="user", email="test@test.com") + + with pytest.raises(HTTPException): + await search_code(request, auth) + + mock_observability["capture_exception"].assert_called_once() + mock_observability["logger"].error.assert_called() + + @pytest.mark.asyncio + async def test_search_logs_invalid_query_warning(self, mock_observability, mock_dependencies): + """Search endpoint should warn on invalid queries""" + from routes.search import search_code, SearchRequest + from middleware.auth import AuthContext + + # SQL injection attempt + request = SearchRequest(query="DROP TABLE users;--", repo_id="repo") + auth = AuthContext(user_id="user", email="test@test.com") + + with pytest.raises(HTTPException) as exc: + await search_code(request, auth) + + assert exc.value.status_code == 400 + mock_observability["logger"].warning.assert_called() + + +class TestSearchV2RouteObservability: + """Tests for observability in routes/search_v2.py""" + + @pytest.fixture + def mock_observability(self): + with patch("routes.search_v2.logger") as mock_logger, \ + patch("routes.search_v2.capture_exception") as mock_capture, \ + patch("routes.search_v2.track_time") as mock_track, \ + patch("routes.search_v2.add_breadcrumb") as mock_breadcrumb, \ + patch("routes.search_v2.set_operation_context") as mock_context: + + mock_track.return_value.__enter__ = MagicMock() + mock_track.return_value.__exit__ = MagicMock(return_value=False) + + yield { + "logger": mock_logger, + "capture_exception": mock_capture, + "track_time": mock_track, + "add_breadcrumb": mock_breadcrumb, + "set_operation_context": mock_context + } + + @pytest.fixture + def mock_dependencies(self): + with patch("routes.search_v2.indexer") as mock_indexer, \ + patch("routes.search_v2.cache") as mock_cache, \ + patch("routes.search_v2.metrics") as mock_metrics, \ + patch("routes.search_v2.verify_repo_access") as mock_verify, \ + patch("routes.search_v2.SEARCH_V2_ENABLED", True): + + mock_indexer.search_v2 = AsyncMock(return_value=[ + { + "name": "test", "qualified_name": "test", "file_path": "t.py", + "code": "def t(): pass", "signature": "def t()", "language": "python", + "score": 0.9, "line_start": 1, "line_end": 2 + } + ]) + mock_cache.get_search_results = MagicMock(return_value=None) + mock_cache.set_search_results = MagicMock() + mock_metrics.record_search = MagicMock() + + yield { + "indexer": mock_indexer, + "cache": mock_cache, + "metrics": mock_metrics, + "verify": mock_verify + } + + @pytest.mark.asyncio + async def test_search_v2_sets_operation_context(self, mock_observability, mock_dependencies): + """Search V2 should set operation context with query metadata""" + from routes.search_v2 import search_v2, SearchV2Request + from middleware.auth import AuthContext + + request = SearchV2Request(query="authentication", repo_id="repo", top_k=10) + auth = AuthContext(user_id="user-123", email="test@test.com") + + await search_v2(request, auth) + + mock_observability["set_operation_context"].assert_called_once() + call_args = mock_observability["set_operation_context"].call_args + assert call_args[0][0] == "search_v2" + assert call_args[1]["top_k"] == 10 + + @pytest.mark.asyncio + async def test_search_v2_logs_reranking_status(self, mock_observability, mock_dependencies): + """Search V2 should log whether reranking was used""" + from routes.search_v2 import search_v2, SearchV2Request + from middleware.auth import AuthContext + + request = SearchV2Request(query="test", repo_id="repo", use_reranking=True) + auth = AuthContext(user_id="user", email="test@test.com") + + await search_v2(request, auth) + + # Check info log includes reranking status + info_calls = mock_observability["logger"].info.call_args_list + assert any("reranking" in str(c).lower() for c in info_calls) + + +class TestAuthRouteObservability: + """Tests for observability in routes/auth.py""" + + @pytest.fixture + def mock_observability(self): + with patch("routes.auth.logger") as mock_logger, \ + patch("routes.auth.capture_exception") as mock_capture, \ + patch("routes.auth.track_time") as mock_track, \ + patch("routes.auth.add_breadcrumb") as mock_breadcrumb, \ + patch("routes.auth.set_operation_context") as mock_context: + + mock_track.return_value.__enter__ = MagicMock() + mock_track.return_value.__exit__ = MagicMock(return_value=False) + + yield { + "logger": mock_logger, + "capture_exception": mock_capture, + "track_time": mock_track, + "add_breadcrumb": mock_breadcrumb, + "set_operation_context": mock_context + } + + @pytest.fixture + def mock_auth_service(self): + with patch("routes.auth.get_auth_service") as mock: + service = MagicMock() + service.signup = AsyncMock(return_value={ + "user": {"id": "user-123", "email": "test@test.com"}, + "session": {"access_token": "token", "refresh_token": "refresh"} + }) + service.login = AsyncMock(return_value={ + "user": {"id": "user-123", "email": "test@test.com"}, + "session": {"access_token": "token", "refresh_token": "refresh"} + }) + service.refresh_session = AsyncMock(return_value={"access_token": "new_token"}) + service.logout = AsyncMock(return_value={"message": "success"}) + mock.return_value = service + yield service + + @pytest.mark.asyncio + async def test_signup_logs_attempt(self, mock_observability, mock_auth_service): + """Signup should log the attempt with email""" + from routes.auth import signup, SignupRequest + + request = SignupRequest(email="new@test.com", password="password123") + await signup(request) + + mock_observability["logger"].info.assert_called() + # Check email is logged (but not password!) + info_calls = str(mock_observability["logger"].info.call_args_list) + assert "new@test.com" in info_calls + assert "password" not in info_calls.lower() + + @pytest.mark.asyncio + async def test_login_tracks_time(self, mock_observability, mock_auth_service): + """Login should track authentication time""" + from routes.auth import login, LoginRequest + + request = LoginRequest(email="test@test.com", password="pass") + await login(request) + + mock_observability["track_time"].assert_called_with("auth_login") + + @pytest.mark.asyncio + async def test_login_captures_exception_on_failure(self, mock_observability, mock_auth_service): + """Login should capture exceptions to Sentry""" + from routes.auth import login, LoginRequest + + mock_auth_service.login = AsyncMock(side_effect=Exception("DB error")) + + request = LoginRequest(email="test@test.com", password="pass") + + with pytest.raises(HTTPException): + await login(request) + + mock_observability["capture_exception"].assert_called_once() + + @pytest.mark.asyncio + async def test_auth_sets_breadcrumb(self, mock_observability, mock_auth_service): + """Auth endpoints should add breadcrumbs""" + from routes.auth import signup, SignupRequest + + request = SignupRequest(email="test@test.com", password="pass") + await signup(request) + + mock_observability["add_breadcrumb"].assert_called() + call_args = mock_observability["add_breadcrumb"].call_args + assert call_args[1]["category"] == "auth" + + +class TestApiKeysRouteObservability: + """Tests for observability in routes/api_keys.py""" + + @pytest.fixture + def mock_observability(self): + with patch("routes.api_keys.logger") as mock_logger, \ + patch("routes.api_keys.capture_exception") as mock_capture, \ + patch("routes.api_keys.track_time") as mock_track, \ + patch("routes.api_keys.add_breadcrumb") as mock_breadcrumb, \ + patch("routes.api_keys.set_operation_context") as mock_context: + + mock_track.return_value.__enter__ = MagicMock() + mock_track.return_value.__exit__ = MagicMock(return_value=False) + + yield { + "logger": mock_logger, + "capture_exception": mock_capture, + "track_time": mock_track, + "add_breadcrumb": mock_breadcrumb, + "set_operation_context": mock_context + } + + @pytest.fixture + def mock_dependencies(self): + with patch("routes.api_keys.api_key_manager") as mock_manager, \ + patch("routes.api_keys.rate_limiter") as mock_limiter, \ + patch("routes.api_keys.metrics") as mock_metrics: + + mock_manager.generate_key = MagicMock(return_value="sk-test-key-123") + mock_limiter.get_usage = MagicMock(return_value={"minute": 5, "hour": 50}) + mock_metrics.get_metrics = MagicMock(return_value={"searches": 100}) + + yield { + "api_key_manager": mock_manager, + "rate_limiter": mock_limiter, + "metrics": mock_metrics + } + + @pytest.mark.asyncio + async def test_generate_key_logs_request(self, mock_observability, mock_dependencies): + """API key generation should log the request with tier""" + from routes.api_keys import generate_api_key, CreateAPIKeyRequest + from middleware.auth import AuthContext + + request = CreateAPIKeyRequest(name="Production Key", tier="pro") + auth = AuthContext(user_id="user-123", email="test@test.com", tier="pro") + + await generate_api_key(request, auth) + + mock_observability["logger"].info.assert_called() + info_calls = str(mock_observability["logger"].info.call_args_list) + assert "pro" in info_calls + assert "Production Key" in info_calls + + @pytest.mark.asyncio + async def test_generate_key_sets_context_with_tier(self, mock_observability, mock_dependencies): + """API key generation should set context with tier info""" + from routes.api_keys import generate_api_key, CreateAPIKeyRequest + from middleware.auth import AuthContext + + request = CreateAPIKeyRequest(name="Key", tier="enterprise") + auth = AuthContext(user_id="user", email="test@test.com", tier="enterprise") + + await generate_api_key(request, auth) + + mock_observability["set_operation_context"].assert_called() + call_args = mock_observability["set_operation_context"].call_args + assert call_args[1]["tier"] == "enterprise" + + @pytest.mark.asyncio + async def test_get_usage_tracks_time(self, mock_observability, mock_dependencies): + """Get usage should track operation time""" + from routes.api_keys import get_api_usage + from middleware.auth import AuthContext + + # AuthContext.identifier is a property that returns user_id or api_key_name + auth = AuthContext(user_id="user", email="test@test.com", tier="free") + + await get_api_usage(auth) + + mock_observability["track_time"].assert_called_with("get_api_usage") + + +class TestObservabilityConsistency: + """Cross-cutting tests to ensure observability is consistent across all routes""" + + def test_all_routes_import_observability(self): + """All 4 routes should import observability module""" + import routes.search + import routes.search_v2 + import routes.auth + import routes.api_keys + + # Check each module has the observability imports + for module in [routes.search, routes.search_v2, routes.auth, routes.api_keys]: + assert hasattr(module, "logger") or "logger" in dir(module) + + def test_observability_module_exports(self): + """Observability module should export all required functions""" + from services.observability import ( + logger, + capture_exception, + track_time, + add_breadcrumb, + set_operation_context + ) + + assert logger is not None + assert callable(capture_exception) + assert callable(track_time) + assert callable(add_breadcrumb) + assert callable(set_operation_context)