"""Tests for external API log persistence: logging, query, summary, and cleanup.""" from __future__ import annotations from datetime import datetime, timedelta, timezone from unittest.mock import patch import pytest from sqlalchemy import create_engine from sqlalchemy.orm import sessionmaker from app.database import Base from app.models.external_api_log import ExternalApiLog @pytest.fixture def engine(): e = create_engine("sqlite://", connect_args={"check_same_thread": False}) # Import all models so they register with Base.metadata import app.models.admin_user # noqa: F401 import app.models.upstream # noqa: F401 import app.models.website # noqa: F401 import app.models.snapshot # noqa: F401 import app.models.webhook_config # noqa: F401 import app.models.notification_log # noqa: F401 import app.models.custom_page # noqa: F401 import app.models.revoked_token # noqa: F401 import app.models.upstream_key # noqa: F401 import app.models.external_api_log # noqa: F401 Base.metadata.create_all(bind=e) yield e Base.metadata.drop_all(bind=e) @pytest.fixture def session(engine): TestingSession = sessionmaker(bind=engine) db = TestingSession() try: yield db finally: db.close() # ───────────────────────────────────────────── # 1. Model: basic insert and read # ───────────────────────────────────────────── def test_insert_and_read(session): now = datetime.now(timezone.utc) log = ExternalApiLog( direction="upstream", target_type="upstream", target_id=1, target_name="test-upstream", method="GET", path="/api/v1/models", url_host="api.test.local", status_code=200, success=True, duration_ms=150, created_at=now, ) session.add(log) session.commit() rows = session.query(ExternalApiLog).all() assert len(rows) == 1 assert rows[0].direction == "upstream" assert rows[0].duration_ms == 150 assert rows[0].status_code == 200 assert rows[0].success is True # ───────────────────────────────────────────── # 2. Filters (direction, target_type, target_id, success, status_code, path) # ───────────────────────────────────────────── def _seed(session, count: int = 1, **overrides) -> list[ExternalApiLog]: rows = [] for i in range(count): defaults = dict( direction="upstream", target_type="upstream", target_id=10 + i, target_name=f"upstream-{i}", method="GET", path=f"/api/v1/endpoint/{i}", url_host="api.test.local", status_code=200, success=True, duration_ms=100 + i * 10, created_at=datetime.now(timezone.utc), ) defaults.update(overrides) r = ExternalApiLog(**defaults) session.add(r) rows.append(r) session.commit() return rows def test_filter_by_direction(session): _seed(session, 1, direction="upstream") _seed(session, 1, direction="website") rows = session.query(ExternalApiLog).filter(ExternalApiLog.direction == "upstream").all() assert len(rows) == 1 assert rows[0].direction == "upstream" def test_filter_by_success(session): _seed(session, 1, success=True) _seed(session, 1, success=False, status_code=500, error_type="ServerError") rows = session.query(ExternalApiLog).filter(ExternalApiLog.success == False).all() # noqa: E712 assert len(rows) == 1 assert rows[0].success is False def test_filter_by_status_code(session): _seed(session, 1, status_code=200) _seed(session, 1, status_code=404, success=False, error_type="NotFound") rows = session.query(ExternalApiLog).filter(ExternalApiLog.status_code == 404).all() assert len(rows) == 1 assert rows[0].status_code == 404 def test_filter_by_target_id(session): _seed(session, 1, target_id=42) _seed(session, 1, target_id=99) rows = session.query(ExternalApiLog).filter(ExternalApiLog.target_id == 42).all() assert len(rows) == 1 assert rows[0].target_id == 42 def test_filter_by_path_like(session): _seed(session, 1, path="/api/keys/list") _seed(session, 1, path="/api/groups/list") rows = session.query(ExternalApiLog).filter(ExternalApiLog.path.like("%keys%")).all() assert len(rows) == 1 assert "keys" in rows[0].path def test_pagination(session): _seed(session, 5) total = session.query(ExternalApiLog).count() assert total == 5 page = session.query(ExternalApiLog).order_by(ExternalApiLog.id).offset(0).limit(2).all() assert len(page) == 2 page2 = session.query(ExternalApiLog).order_by(ExternalApiLog.id).offset(2).limit(2).all() assert len(page2) == 2 # ───────────────────────────────────────────── # 3. Summary aggregation # ───────────────────────────────────────────── def test_summary_aggregation(session): now = datetime.now(timezone.utc) # 3 calls to same path: 2 success, 1 fail, various durations for i in range(3): session.add(ExternalApiLog( direction="upstream", target_type="upstream", target_id=1, target_name="agg-test", method="GET", path="/api/v1/status", url_host="api.test.local", status_code=200 if i < 2 else 500, success=i < 2, duration_ms=[100, 200, 300][i], created_at=now, )) # A different path session.add(ExternalApiLog( direction="website", target_type="website", target_id=2, target_name="site-2", method="POST", path="/api/v1/accounts", url_host="site.test.local", status_code=201, success=True, duration_ms=500, created_at=now, )) session.commit() from sqlalchemy import cast, case, func, Integer slow_threshold = 250 cols = [ ExternalApiLog.direction, ExternalApiLog.target_type, ExternalApiLog.target_id, ExternalApiLog.target_name, ExternalApiLog.method, ExternalApiLog.path, func.count(ExternalApiLog.id).label("call_count"), func.sum(cast(ExternalApiLog.success, Integer)).label("success_count"), func.sum(cast(1 - cast(ExternalApiLog.success, Integer), Integer)).label("fail_count"), func.avg(ExternalApiLog.duration_ms).label("avg_duration_ms"), func.max(ExternalApiLog.duration_ms).label("max_duration_ms"), func.sum(case((ExternalApiLog.duration_ms >= slow_threshold, 1), else_=0)).label("slow_count"), ] rows = ( session.query(*cols) .group_by( ExternalApiLog.direction, ExternalApiLog.target_type, ExternalApiLog.target_id, ExternalApiLog.target_name, ExternalApiLog.method, ExternalApiLog.path, ) .order_by(func.sum(ExternalApiLog.duration_ms).desc()) .all() ) assert len(rows) == 2 # First row: upstream, 3 calls r1 = rows[0] assert r1.direction == "upstream" assert r1.call_count == 3 assert r1.success_count == 2 assert r1.fail_count == 1 assert r1.slow_count == 1 # only 300ms >= 250 assert r1.max_duration_ms == 300 assert 190 <= r1.avg_duration_ms <= 210 # ~200 # Second row: website, 1 call r2 = rows[1] assert r2.direction == "website" assert r2.call_count == 1 assert r2.success_count == 1 assert r2.fail_count == 0 # ───────────────────────────────────────────── # 4. Cleanup (retention) # ───────────────────────────────────────────── def test_clean_expired_logs(session): now = datetime.now(timezone.utc) # Old record (40 days ago) session.add(ExternalApiLog( direction="upstream", target_type="upstream", method="GET", path="/old", url_host="old.local", status_code=200, success=True, duration_ms=10, created_at=now - timedelta(days=40), )) # Recent record (5 days ago) session.add(ExternalApiLog( direction="upstream", target_type="upstream", method="GET", path="/recent", url_host="recent.local", status_code=200, success=True, duration_ms=10, created_at=now - timedelta(days=5), )) session.commit() assert session.query(ExternalApiLog).count() == 2 # Delete records older than 30 days cutoff = now - timedelta(days=30) deleted = session.query(ExternalApiLog).filter( ExternalApiLog.created_at < cutoff ).delete(synchronize_session=False) session.commit() assert deleted == 1 assert session.query(ExternalApiLog).count() == 1 remaining = session.query(ExternalApiLog).first() assert "/recent" in remaining.path # ───────────────────────────────────────────── # 5. log_external_api_call function # ───────────────────────────────────────────── def test_log_external_api_call_success(session): """Verify the logging helper writes the expected row.""" from app.services.external_api_logger import log_external_api_call with patch("app.services.external_api_logger.SessionLocal", return_value=session): log_external_api_call( direction="upstream", target_type="upstream", method="POST", path="/api/v1/test", url_host="test.local", duration_ms=250, status_code=201, success=True, target_id=7, target_name="gold-upstream", ) rows = session.query(ExternalApiLog).all() assert len(rows) == 1 r = rows[0] assert r.direction == "upstream" assert r.method == "POST" assert r.path == "/api/v1/test" assert r.url_host == "test.local" assert r.duration_ms == 250 assert r.status_code == 201 assert r.success is True assert r.target_id == 7 assert r.target_name == "gold-upstream" assert r.error_type is None assert r.error_message is None def test_log_external_api_call_failure(session): """Failure path: error fields populated, success=False.""" from app.services.external_api_logger import log_external_api_call with patch("app.services.external_api_logger.SessionLocal", return_value=session): log_external_api_call( direction="website", target_type="website", method="GET", path="/api/v1/groups", url_host="site.local", duration_ms=5000, status_code=502, success=False, target_id=3, target_name="bad-site", error_type="BadGateway", error_message="upstream connection refused", ) rows = session.query(ExternalApiLog).all() assert len(rows) == 1 r = rows[0] assert r.direction == "website" assert r.success is False assert r.status_code == 502 assert r.duration_ms == 5000 assert r.error_type == "BadGateway" assert r.error_message == "upstream connection refused" def test_log_no_sensitive_data(session): """Verify no request/response body or credentials are logged.""" from app.services.external_api_logger import log_external_api_call with patch("app.services.external_api_logger.SessionLocal", return_value=session): log_external_api_call( direction="upstream", target_type="upstream", method="GET", path="/api/v1/keys", url_host="secure.local", duration_ms=100, status_code=200, success=True, ) rows = session.query(ExternalApiLog).all() assert len(rows) == 1 r = rows[0] # These fields MUST be empty — we never log bodies or credentials assert not hasattr(r, "request_body") assert not hasattr(r, "response_body") assert not hasattr(r, "authorization") assert not hasattr(r, "cookie") assert not hasattr(r, "api_key") # ───────────────────────────────────────────── # 6. Time window on summary # ───────────────────────────────────────────── def test_summary_time_window(session): now = datetime.now(timezone.utc) # Recent (1 hour ago) session.add(ExternalApiLog( direction="upstream", target_type="upstream", method="GET", path="/recent", url_host="h", status_code=200, success=True, duration_ms=50, created_at=now - timedelta(hours=1), )) # Old (48 hours ago) session.add(ExternalApiLog( direction="upstream", target_type="upstream", method="GET", path="/old", url_host="h", status_code=200, success=True, duration_ms=50, created_at=now - timedelta(hours=48), )) session.commit() # 24-hour window should only include the recent record cutoff = now - timedelta(hours=24) rows = session.query(ExternalApiLog).filter(ExternalApiLog.created_at >= cutoff).all() assert len(rows) == 1 assert "/recent" in rows[0].path # 72-hour window includes both cutoff = now - timedelta(hours=72) rows = session.query(ExternalApiLog).filter(ExternalApiLog.created_at >= cutoff).all() assert len(rows) == 2 # ───────────────────────────────────────────── # 7. UpstreamClient integration: 4xx/5xx logged as failure # ───────────────────────────────────────────── def _make_httpx_mock(status_code: int, body: dict | None = None): """Return a mock for httpx.Client.request that returns a fixed status. Used via patch.object(client._client, 'request', ...) which replaces the bound method, so the signature is (method, url, **kwargs) — no self. """ import httpx def mock_request(method, url, **kwargs): req = httpx.Request(method, url) return httpx.Response(status_code, json=body or {}, request=req) return mock_request def test_upstream_client_500_logged_as_failure(): """UpstreamClient._request() → HTTP 500 → log with success=False, status_code=500.""" from app.services.upstream_client import UpstreamClient captured = {} def capture(**kw): captured.update(kw) with patch("app.services.upstream_client.log_external_api_call", side_effect=capture): client = UpstreamClient( base_url="http://test.local", api_prefix="", auth_type="api_key", auth_config={"key": "test", "header": "Authorization"}, target_id=1, target_name="test-upstream", ) with patch.object(client._client, "request", _make_httpx_mock(500)): try: client._request("GET", "/api/v1/models") except Exception: pass assert captured.get("status_code") == 500 assert captured.get("success") is False assert captured.get("error_type") == "HTTPStatus" assert "500" in (captured.get("error_message") or "") def test_upstream_client_429_logged_as_failure(): """UpstreamClient._request() → HTTP 429 → log with success=False, status_code=429.""" from app.services.upstream_client import UpstreamClient captured = {} def capture(**kw): captured.update(kw) with patch("app.services.upstream_client.log_external_api_call", side_effect=capture): client = UpstreamClient( base_url="http://test.local", api_prefix="", auth_type="api_key", auth_config={"key": "test", "header": "Authorization"}, target_id=1, target_name="test-upstream", ) with patch.object(client._client, "request", _make_httpx_mock(429)): try: client._request("GET", "/api/v1/rate-limited") except Exception: pass assert captured.get("status_code") == 429 assert captured.get("success") is False assert captured.get("error_type") == "HTTPStatus" def test_upstream_client_200_logged_as_success(): """UpstreamClient._request() → HTTP 200 → log with success=True, status_code=200.""" from app.services.upstream_client import UpstreamClient captured = {} def capture(**kw): captured.update(kw) with patch("app.services.upstream_client.log_external_api_call", side_effect=capture): client = UpstreamClient( base_url="http://test.local", api_prefix="", auth_type="api_key", auth_config={"key": "test", "header": "Authorization"}, target_id=1, target_name="test-upstream", ) with patch.object(client._client, "request", _make_httpx_mock(200, {"data": []})): client._request("GET", "/api/v1/groups") assert captured.get("status_code") == 200 assert captured.get("success") is True assert captured.get("error_type") is None # ───────────────────────────────────────────── # 8. Route-level tests — call handlers directly # ───────────────────────────────────────────── def test_route_list_empty(session): """list_external_api_logs with no data returns [].""" from app.routers.external_api_logs import list_external_api_logs result = list_external_api_logs( direction=None, target_type=None, target_id=None, success=None, status_code=None, path=None, limit=100, offset=0, db=session, _=None, ) assert result == [] def test_route_list_with_filters(session): """list_external_api_logs with filters returns filtered results.""" from app.routers.external_api_logs import list_external_api_logs now = datetime.now(timezone.utc) for i in range(3): session.add(ExternalApiLog( direction="upstream" if i < 2 else "website", target_type="upstream" if i < 2 else "website", target_id=i + 1, target_name=f"tgt-{i}", method="GET", path=f"/path/{i}", url_host="h.local", status_code=200 if i < 2 else 500, success=i < 2, duration_ms=100 + i, created_at=now, )) session.commit() _empty = None # sentinel for "no filter" # Filter by direction result = list_external_api_logs( direction="website", target_type=_empty, target_id=_empty, success=_empty, status_code=_empty, path=_empty, limit=100, offset=0, db=session, _=None, ) assert len(result) == 1 and result[0].direction == "website" # Filter by success result = list_external_api_logs( direction=_empty, target_type=_empty, target_id=_empty, success=False, status_code=_empty, path=_empty, limit=100, offset=0, db=session, _=None, ) assert len(result) == 1 and result[0].success is False # Filter by status_code result = list_external_api_logs( direction=_empty, target_type=_empty, target_id=_empty, success=_empty, status_code=500, path=_empty, limit=100, offset=0, db=session, _=None, ) assert len(result) == 1 and result[0].status_code == 500 # Filter by path result = list_external_api_logs( direction=_empty, target_type=_empty, target_id=_empty, success=_empty, status_code=_empty, path="/path/0", limit=100, offset=0, db=session, _=None, ) assert len(result) == 1 and "/path/0" in result[0].path # Filter by target_id result = list_external_api_logs( direction=_empty, target_type=_empty, target_id=2, success=_empty, status_code=_empty, path=_empty, limit=100, offset=0, db=session, _=None, ) assert len(result) == 1 and result[0].target_id == 2 def test_route_list_pagination(session): """list_external_api_logs respects limit/offset.""" from app.routers.external_api_logs import list_external_api_logs now = datetime.now(timezone.utc) for i in range(10): session.add(ExternalApiLog( direction="upstream", target_type="upstream", method="GET", path=f"/p/{i}", url_host="h", status_code=200, success=True, duration_ms=i, created_at=now, )) session.commit() _e = None assert len(list_external_api_logs( direction=_e, target_type=_e, target_id=_e, success=_e, status_code=_e, path=_e, limit=3, offset=0, db=session, _=None, )) == 3 assert len(list_external_api_logs( direction=_e, target_type=_e, target_id=_e, success=_e, status_code=_e, path=_e, limit=3, offset=3, db=session, _=None, )) == 3 assert len(list_external_api_logs( direction=_e, target_type=_e, target_id=_e, success=_e, status_code=_e, path=_e, limit=3, offset=20, db=session, _=None, )) == 0 def test_route_summary_hours_window(session): """get_external_api_log_summary respects hours parameter.""" from app.routers.external_api_logs import get_external_api_log_summary now = datetime.now(timezone.utc) # Recent (30 minutes ago — well within 1-hour window) session.add(ExternalApiLog(direction="upstream", target_type="upstream", method="GET", path="/recent", url_host="h", status_code=200, success=True, duration_ms=50, created_at=now - timedelta(minutes=30))) # Old (48 hours ago — outside 1-hour window) session.add(ExternalApiLog(direction="upstream", target_type="upstream", method="GET", path="/old", url_host="h", status_code=200, success=True, duration_ms=50, created_at=now - timedelta(hours=48))) session.commit() # hours=1 → only recent result = get_external_api_log_summary( slow_ms=None, hours=1, limit=50, db=session, _=None, ) assert len(result) == 1 and result[0].path == "/recent" # hours=72 → both result = get_external_api_log_summary( slow_ms=None, hours=72, limit=50, db=session, _=None, ) assert len(result) == 2 def test_route_summary_limit(session): """get_external_api_log_summary respects limit parameter.""" from app.routers.external_api_logs import get_external_api_log_summary now = datetime.now(timezone.utc) for i in range(10): session.add(ExternalApiLog(direction="upstream", target_type="upstream", method="GET", path=f"/path-{i}", url_host="h", status_code=200, success=True, duration_ms=50 + i, created_at=now)) session.commit() result = get_external_api_log_summary( slow_ms=None, hours=24, limit=3, db=session, _=None, ) assert len(result) == 3 def test_route_summary_slow_threshold(session): """get_external_api_log_summary respects slow_ms parameter.""" from app.routers.external_api_logs import get_external_api_log_summary now = datetime.now(timezone.utc) session.add(ExternalApiLog(direction="upstream", target_type="upstream", method="GET", path="/fast", url_host="h", status_code=200, success=True, duration_ms=100, created_at=now)) session.add(ExternalApiLog(direction="upstream", target_type="upstream", method="GET", path="/fast2", url_host="h", status_code=200, success=True, duration_ms=200, created_at=now)) session.add(ExternalApiLog(direction="upstream", target_type="upstream", method="GET", path="/slow", url_host="h", status_code=200, success=True, duration_ms=5000, created_at=now)) session.commit() result = get_external_api_log_summary( slow_ms=1000, hours=24, limit=50, db=session, _=None, ) slow_paths = [r for r in result if r.slow_count > 0] assert len(slow_paths) == 1 assert slow_paths[0].path == "/slow"