feat: metrics
This commit is contained in:
@@ -0,0 +1,474 @@
|
||||
"""
|
||||
Health Check System for NFOGuard
|
||||
Provides health and readiness endpoints for monitoring and orchestration
|
||||
"""
|
||||
import time
|
||||
import asyncio
|
||||
from typing import Dict, Any, List, Optional
|
||||
from dataclasses import dataclass
|
||||
from enum import Enum
|
||||
from pathlib import Path
|
||||
|
||||
from config.runtime_validator import RuntimeValidator, HealthCheckResult
|
||||
from monitoring.metrics import metrics
|
||||
|
||||
|
||||
class HealthStatus(Enum):
|
||||
"""Health check status levels"""
|
||||
HEALTHY = "healthy"
|
||||
DEGRADED = "degraded"
|
||||
UNHEALTHY = "unhealthy"
|
||||
|
||||
|
||||
@dataclass
|
||||
class HealthCheck:
|
||||
"""Individual health check result"""
|
||||
name: str
|
||||
status: HealthStatus
|
||||
message: str
|
||||
duration_ms: float
|
||||
details: Dict[str, Any] = None
|
||||
|
||||
def to_dict(self) -> Dict[str, Any]:
|
||||
return {
|
||||
"name": self.name,
|
||||
"status": self.status.value,
|
||||
"message": self.message,
|
||||
"duration_ms": round(self.duration_ms, 2),
|
||||
"details": self.details or {}
|
||||
}
|
||||
|
||||
|
||||
@dataclass
|
||||
class OverallHealth:
|
||||
"""Overall system health status"""
|
||||
status: HealthStatus
|
||||
checks: List[HealthCheck]
|
||||
timestamp: float
|
||||
uptime_seconds: float
|
||||
version: str = "2.0.0"
|
||||
|
||||
def to_dict(self) -> Dict[str, Any]:
|
||||
return {
|
||||
"status": self.status.value,
|
||||
"timestamp": self.timestamp,
|
||||
"uptime_seconds": round(self.uptime_seconds, 2),
|
||||
"version": self.version,
|
||||
"checks": [check.to_dict() for check in self.checks],
|
||||
"summary": {
|
||||
"total_checks": len(self.checks),
|
||||
"healthy_checks": len([c for c in self.checks if c.status == HealthStatus.HEALTHY]),
|
||||
"degraded_checks": len([c for c in self.checks if c.status == HealthStatus.DEGRADED]),
|
||||
"unhealthy_checks": len([c for c in self.checks if c.status == HealthStatus.UNHEALTHY])
|
||||
}
|
||||
}
|
||||
|
||||
|
||||
class HealthChecker:
|
||||
"""Comprehensive health checking system"""
|
||||
|
||||
def __init__(self):
|
||||
self.start_time = time.time()
|
||||
self._last_health_check = None
|
||||
self._health_check_cache_ttl = 30 # Cache for 30 seconds
|
||||
self._runtime_validator = None
|
||||
|
||||
def _get_runtime_validator(self):
|
||||
"""Get runtime validator instance"""
|
||||
if self._runtime_validator is None:
|
||||
try:
|
||||
from config.settings import config
|
||||
self._runtime_validator = RuntimeValidator(config)
|
||||
except Exception as e:
|
||||
# Create a dummy validator if config fails
|
||||
self._runtime_validator = None
|
||||
return self._runtime_validator
|
||||
|
||||
async def check_basic_health(self) -> HealthCheck:
|
||||
"""Basic health check - always succeeds if service is running"""
|
||||
start_time = time.time()
|
||||
|
||||
try:
|
||||
# Basic service availability
|
||||
uptime = time.time() - self.start_time
|
||||
|
||||
if uptime < 30:
|
||||
status = HealthStatus.DEGRADED
|
||||
message = f"Service starting up (uptime: {uptime:.1f}s)"
|
||||
else:
|
||||
status = HealthStatus.HEALTHY
|
||||
message = f"Service running normally (uptime: {uptime:.1f}s)"
|
||||
|
||||
return HealthCheck(
|
||||
name="basic",
|
||||
status=status,
|
||||
message=message,
|
||||
duration_ms=(time.time() - start_time) * 1000,
|
||||
details={"uptime_seconds": uptime}
|
||||
)
|
||||
|
||||
except Exception as e:
|
||||
return HealthCheck(
|
||||
name="basic",
|
||||
status=HealthStatus.UNHEALTHY,
|
||||
message=f"Basic health check failed: {e}",
|
||||
duration_ms=(time.time() - start_time) * 1000
|
||||
)
|
||||
|
||||
async def check_filesystem_health(self) -> HealthCheck:
|
||||
"""Check filesystem access for media paths"""
|
||||
start_time = time.time()
|
||||
|
||||
try:
|
||||
from config.settings import config
|
||||
|
||||
accessible_paths = 0
|
||||
total_paths = len(config.tv_paths) + len(config.movie_paths)
|
||||
issues = []
|
||||
|
||||
# Check TV paths
|
||||
for path in config.tv_paths:
|
||||
try:
|
||||
if path.exists() and path.is_dir():
|
||||
# Try to read directory
|
||||
list(path.iterdir())
|
||||
accessible_paths += 1
|
||||
else:
|
||||
issues.append(f"TV path not accessible: {path}")
|
||||
except PermissionError:
|
||||
issues.append(f"TV path permission denied: {path}")
|
||||
except Exception as e:
|
||||
issues.append(f"TV path error {path}: {e}")
|
||||
|
||||
# Check movie paths
|
||||
for path in config.movie_paths:
|
||||
try:
|
||||
if path.exists() and path.is_dir():
|
||||
list(path.iterdir())
|
||||
accessible_paths += 1
|
||||
else:
|
||||
issues.append(f"Movie path not accessible: {path}")
|
||||
except PermissionError:
|
||||
issues.append(f"Movie path permission denied: {path}")
|
||||
except Exception as e:
|
||||
issues.append(f"Movie path error {path}: {e}")
|
||||
|
||||
# Determine status
|
||||
if accessible_paths == total_paths:
|
||||
status = HealthStatus.HEALTHY
|
||||
message = f"All {total_paths} media paths accessible"
|
||||
elif accessible_paths > 0:
|
||||
status = HealthStatus.DEGRADED
|
||||
message = f"{accessible_paths}/{total_paths} media paths accessible"
|
||||
else:
|
||||
status = HealthStatus.UNHEALTHY
|
||||
message = "No media paths accessible"
|
||||
|
||||
return HealthCheck(
|
||||
name="filesystem",
|
||||
status=status,
|
||||
message=message,
|
||||
duration_ms=(time.time() - start_time) * 1000,
|
||||
details={
|
||||
"accessible_paths": accessible_paths,
|
||||
"total_paths": total_paths,
|
||||
"issues": issues[:5] # Limit to first 5 issues
|
||||
}
|
||||
)
|
||||
|
||||
except Exception as e:
|
||||
return HealthCheck(
|
||||
name="filesystem",
|
||||
status=HealthStatus.UNHEALTHY,
|
||||
message=f"Filesystem check failed: {e}",
|
||||
duration_ms=(time.time() - start_time) * 1000
|
||||
)
|
||||
|
||||
async def check_database_health(self) -> HealthCheck:
|
||||
"""Check database connectivity and performance"""
|
||||
start_time = time.time()
|
||||
|
||||
try:
|
||||
import sqlite3
|
||||
from config.settings import config
|
||||
|
||||
# Test local database
|
||||
db_path = config.db_path
|
||||
|
||||
def test_db():
|
||||
with sqlite3.connect(str(db_path), timeout=5) as conn:
|
||||
cursor = conn.cursor()
|
||||
cursor.execute("SELECT COUNT(*) FROM sqlite_master WHERE type='table'")
|
||||
table_count = cursor.fetchone()[0]
|
||||
return table_count
|
||||
|
||||
# Run database test
|
||||
table_count = await asyncio.get_event_loop().run_in_executor(None, test_db)
|
||||
|
||||
duration = (time.time() - start_time) * 1000
|
||||
|
||||
if duration < 100: # < 100ms is good
|
||||
status = HealthStatus.HEALTHY
|
||||
message = f"Database responsive ({duration:.1f}ms, {table_count} tables)"
|
||||
elif duration < 1000: # < 1s is acceptable
|
||||
status = HealthStatus.DEGRADED
|
||||
message = f"Database slow ({duration:.1f}ms, {table_count} tables)"
|
||||
else:
|
||||
status = HealthStatus.UNHEALTHY
|
||||
message = f"Database very slow ({duration:.1f}ms)"
|
||||
|
||||
return HealthCheck(
|
||||
name="database",
|
||||
status=status,
|
||||
message=message,
|
||||
duration_ms=duration,
|
||||
details={
|
||||
"db_path": str(db_path),
|
||||
"table_count": table_count,
|
||||
"response_time_category": "fast" if duration < 100 else "slow" if duration < 1000 else "very_slow"
|
||||
}
|
||||
)
|
||||
|
||||
except Exception as e:
|
||||
return HealthCheck(
|
||||
name="database",
|
||||
status=HealthStatus.UNHEALTHY,
|
||||
message=f"Database check failed: {e}",
|
||||
duration_ms=(time.time() - start_time) * 1000,
|
||||
details={"error": str(e)}
|
||||
)
|
||||
|
||||
async def check_external_apis_health(self) -> HealthCheck:
|
||||
"""Check external API connectivity"""
|
||||
start_time = time.time()
|
||||
|
||||
try:
|
||||
import aiohttp
|
||||
from config.settings import config
|
||||
|
||||
api_results = []
|
||||
apis_tested = 0
|
||||
apis_healthy = 0
|
||||
|
||||
timeout = aiohttp.ClientTimeout(total=5)
|
||||
|
||||
async with aiohttp.ClientSession(timeout=timeout) as session:
|
||||
# Test Radarr API if configured
|
||||
if hasattr(config, 'radarr_url') and config.radarr_url:
|
||||
apis_tested += 1
|
||||
try:
|
||||
test_url = f"{config.radarr_url.rstrip('/')}/api/v3/health"
|
||||
async with session.get(test_url) as response:
|
||||
if response.status == 200:
|
||||
apis_healthy += 1
|
||||
api_results.append({"api": "radarr", "status": "healthy"})
|
||||
else:
|
||||
api_results.append({"api": "radarr", "status": f"unhealthy (HTTP {response.status})"})
|
||||
except Exception as e:
|
||||
api_results.append({"api": "radarr", "status": f"error: {str(e)[:50]}"})
|
||||
|
||||
# Test Sonarr API if configured
|
||||
if hasattr(config, 'sonarr_url') and config.sonarr_url:
|
||||
apis_tested += 1
|
||||
try:
|
||||
test_url = f"{config.sonarr_url.rstrip('/')}/api/v3/health"
|
||||
async with session.get(test_url) as response:
|
||||
if response.status == 200:
|
||||
apis_healthy += 1
|
||||
api_results.append({"api": "sonarr", "status": "healthy"})
|
||||
else:
|
||||
api_results.append({"api": "sonarr", "status": f"unhealthy (HTTP {response.status})"})
|
||||
except Exception as e:
|
||||
api_results.append({"api": "sonarr", "status": f"error: {str(e)[:50]}"})
|
||||
|
||||
# Determine overall API health
|
||||
if apis_tested == 0:
|
||||
status = HealthStatus.HEALTHY
|
||||
message = "No external APIs configured"
|
||||
elif apis_healthy == apis_tested:
|
||||
status = HealthStatus.HEALTHY
|
||||
message = f"All {apis_tested} external APIs healthy"
|
||||
elif apis_healthy > 0:
|
||||
status = HealthStatus.DEGRADED
|
||||
message = f"{apis_healthy}/{apis_tested} external APIs healthy"
|
||||
else:
|
||||
status = HealthStatus.UNHEALTHY
|
||||
message = "No external APIs responding"
|
||||
|
||||
return HealthCheck(
|
||||
name="external_apis",
|
||||
status=status,
|
||||
message=message,
|
||||
duration_ms=(time.time() - start_time) * 1000,
|
||||
details={
|
||||
"apis_tested": apis_tested,
|
||||
"apis_healthy": apis_healthy,
|
||||
"api_results": api_results
|
||||
}
|
||||
)
|
||||
|
||||
except Exception as e:
|
||||
return HealthCheck(
|
||||
name="external_apis",
|
||||
status=HealthStatus.UNHEALTHY,
|
||||
message=f"API health check failed: {e}",
|
||||
duration_ms=(time.time() - start_time) * 1000
|
||||
)
|
||||
|
||||
async def check_performance_health(self) -> HealthCheck:
|
||||
"""Check system performance metrics"""
|
||||
start_time = time.time()
|
||||
|
||||
try:
|
||||
system_metrics = metrics.get_system_metrics()
|
||||
processing_metrics = metrics.get_processing_metrics()
|
||||
|
||||
issues = []
|
||||
warnings = []
|
||||
|
||||
# Check CPU usage
|
||||
cpu_percent = system_metrics.get("cpu_percent", 0)
|
||||
if cpu_percent > 90:
|
||||
issues.append(f"High CPU usage: {cpu_percent:.1f}%")
|
||||
elif cpu_percent > 70:
|
||||
warnings.append(f"Elevated CPU usage: {cpu_percent:.1f}%")
|
||||
|
||||
# Check memory usage
|
||||
memory_percent = system_metrics.get("memory_percent", 0)
|
||||
if memory_percent > 90:
|
||||
issues.append(f"High memory usage: {memory_percent:.1f}%")
|
||||
elif memory_percent > 80:
|
||||
warnings.append(f"Elevated memory usage: {memory_percent:.1f}%")
|
||||
|
||||
# Check disk space
|
||||
if "db_disk_free" in system_metrics and system_metrics["db_disk_free"]:
|
||||
free_space_gb = system_metrics["db_disk_free"] / (1024**3)
|
||||
if free_space_gb < 1:
|
||||
issues.append(f"Low disk space: {free_space_gb:.1f}GB free")
|
||||
elif free_space_gb < 5:
|
||||
warnings.append(f"Low disk space: {free_space_gb:.1f}GB free")
|
||||
|
||||
# Check active operations
|
||||
active_ops = system_metrics.get("active_operations", 0)
|
||||
if active_ops > 10:
|
||||
warnings.append(f"High concurrent operations: {active_ops}")
|
||||
|
||||
# Determine status
|
||||
if issues:
|
||||
status = HealthStatus.UNHEALTHY
|
||||
message = f"Performance issues detected: {', '.join(issues[:2])}"
|
||||
elif warnings:
|
||||
status = HealthStatus.DEGRADED
|
||||
message = f"Performance warnings: {', '.join(warnings[:2])}"
|
||||
else:
|
||||
status = HealthStatus.HEALTHY
|
||||
message = "System performance normal"
|
||||
|
||||
return HealthCheck(
|
||||
name="performance",
|
||||
status=status,
|
||||
message=message,
|
||||
duration_ms=(time.time() - start_time) * 1000,
|
||||
details={
|
||||
"cpu_percent": cpu_percent,
|
||||
"memory_percent": memory_percent,
|
||||
"active_operations": active_ops,
|
||||
"issues": issues,
|
||||
"warnings": warnings
|
||||
}
|
||||
)
|
||||
|
||||
except Exception as e:
|
||||
return HealthCheck(
|
||||
name="performance",
|
||||
status=HealthStatus.DEGRADED,
|
||||
message=f"Performance check failed: {e}",
|
||||
duration_ms=(time.time() - start_time) * 1000
|
||||
)
|
||||
|
||||
async def get_full_health_status(self) -> OverallHealth:
|
||||
"""Get comprehensive health status"""
|
||||
start_time = time.time()
|
||||
|
||||
# Run all health checks concurrently
|
||||
checks = await asyncio.gather(
|
||||
self.check_basic_health(),
|
||||
self.check_filesystem_health(),
|
||||
self.check_database_health(),
|
||||
self.check_external_apis_health(),
|
||||
self.check_performance_health(),
|
||||
return_exceptions=True
|
||||
)
|
||||
|
||||
# Filter out any exceptions and convert to HealthCheck objects
|
||||
valid_checks = []
|
||||
for check in checks:
|
||||
if isinstance(check, HealthCheck):
|
||||
valid_checks.append(check)
|
||||
elif isinstance(check, Exception):
|
||||
valid_checks.append(HealthCheck(
|
||||
name="unknown",
|
||||
status=HealthStatus.UNHEALTHY,
|
||||
message=f"Health check exception: {check}",
|
||||
duration_ms=0
|
||||
))
|
||||
|
||||
# Determine overall status
|
||||
unhealthy_count = len([c for c in valid_checks if c.status == HealthStatus.UNHEALTHY])
|
||||
degraded_count = len([c for c in valid_checks if c.status == HealthStatus.DEGRADED])
|
||||
|
||||
if unhealthy_count > 0:
|
||||
overall_status = HealthStatus.UNHEALTHY
|
||||
elif degraded_count > 0:
|
||||
overall_status = HealthStatus.DEGRADED
|
||||
else:
|
||||
overall_status = HealthStatus.HEALTHY
|
||||
|
||||
return OverallHealth(
|
||||
status=overall_status,
|
||||
checks=valid_checks,
|
||||
timestamp=start_time,
|
||||
uptime_seconds=time.time() - self.start_time
|
||||
)
|
||||
|
||||
async def get_readiness_status(self) -> Dict[str, Any]:
|
||||
"""Get readiness status for Kubernetes readiness probes"""
|
||||
# Readiness is simpler - just check critical components
|
||||
checks = await asyncio.gather(
|
||||
self.check_basic_health(),
|
||||
self.check_filesystem_health(),
|
||||
self.check_database_health(),
|
||||
return_exceptions=True
|
||||
)
|
||||
|
||||
critical_failures = 0
|
||||
for check in checks:
|
||||
if isinstance(check, HealthCheck) and check.status == HealthStatus.UNHEALTHY:
|
||||
critical_failures += 1
|
||||
|
||||
is_ready = critical_failures == 0
|
||||
|
||||
return {
|
||||
"ready": is_ready,
|
||||
"timestamp": time.time(),
|
||||
"critical_failures": critical_failures,
|
||||
"message": "Service ready" if is_ready else f"{critical_failures} critical failures"
|
||||
}
|
||||
|
||||
async def get_liveness_status(self) -> Dict[str, Any]:
|
||||
"""Get liveness status for Kubernetes liveness probes"""
|
||||
# Liveness is even simpler - just check if service is responsive
|
||||
basic_check = await self.check_basic_health()
|
||||
|
||||
is_alive = basic_check.status != HealthStatus.UNHEALTHY
|
||||
|
||||
return {
|
||||
"alive": is_alive,
|
||||
"timestamp": time.time(),
|
||||
"uptime_seconds": time.time() - self.start_time,
|
||||
"message": basic_check.message
|
||||
}
|
||||
|
||||
|
||||
# Global health checker instance
|
||||
health_checker = HealthChecker()
|
||||
@@ -0,0 +1,404 @@
|
||||
"""
|
||||
Enhanced Logging System for NFOGuard
|
||||
Provides structured logging with correlation IDs, request tracing, and monitoring integration
|
||||
"""
|
||||
import logging
|
||||
import json
|
||||
import time
|
||||
import uuid
|
||||
import threading
|
||||
from typing import Dict, Any, Optional, List, Union
|
||||
from dataclasses import dataclass, field
|
||||
from contextlib import contextmanager
|
||||
from datetime import datetime
|
||||
import sys
|
||||
import traceback
|
||||
|
||||
from monitoring.metrics import metrics
|
||||
|
||||
|
||||
# Thread-local storage for correlation context
|
||||
_context = threading.local()
|
||||
|
||||
|
||||
@dataclass
|
||||
class LogContext:
|
||||
"""Logging context with correlation and tracing information"""
|
||||
correlation_id: str
|
||||
request_id: Optional[str] = None
|
||||
user_id: Optional[str] = None
|
||||
operation: Optional[str] = None
|
||||
media_type: Optional[str] = None
|
||||
media_title: Optional[str] = None
|
||||
webhook_type: Optional[str] = None
|
||||
processing_stage: Optional[str] = None
|
||||
additional_fields: Dict[str, Any] = field(default_factory=dict)
|
||||
|
||||
def to_dict(self) -> Dict[str, Any]:
|
||||
"""Convert context to dictionary for logging"""
|
||||
context = {
|
||||
"correlation_id": self.correlation_id,
|
||||
"timestamp": datetime.utcnow().isoformat(),
|
||||
}
|
||||
|
||||
# Add non-None fields
|
||||
for field_name in ["request_id", "user_id", "operation", "media_type",
|
||||
"media_title", "webhook_type", "processing_stage"]:
|
||||
value = getattr(self, field_name)
|
||||
if value is not None:
|
||||
context[field_name] = value
|
||||
|
||||
# Add additional fields
|
||||
context.update(self.additional_fields)
|
||||
|
||||
return context
|
||||
|
||||
|
||||
class StructuredFormatter(logging.Formatter):
|
||||
"""JSON formatter for structured logging"""
|
||||
|
||||
def __init__(self, include_context: bool = True):
|
||||
super().__init__()
|
||||
self.include_context = include_context
|
||||
|
||||
def format(self, record: logging.LogRecord) -> str:
|
||||
# Base log entry
|
||||
log_entry = {
|
||||
"timestamp": datetime.utcnow().isoformat(),
|
||||
"level": record.levelname,
|
||||
"logger": record.name,
|
||||
"message": record.getMessage(),
|
||||
"module": record.module,
|
||||
"function": record.funcName,
|
||||
"line": record.lineno,
|
||||
}
|
||||
|
||||
# Add thread information
|
||||
log_entry["thread"] = {
|
||||
"id": record.thread,
|
||||
"name": record.threadName
|
||||
}
|
||||
|
||||
# Add correlation context if available
|
||||
if self.include_context and hasattr(_context, 'log_context'):
|
||||
log_entry["context"] = _context.log_context.to_dict()
|
||||
|
||||
# Add exception information if present
|
||||
if record.exc_info:
|
||||
log_entry["exception"] = {
|
||||
"type": record.exc_info[0].__name__,
|
||||
"message": str(record.exc_info[1]),
|
||||
"traceback": traceback.format_exception(*record.exc_info)
|
||||
}
|
||||
|
||||
# Add any extra fields passed to log call
|
||||
if hasattr(record, 'extra_fields') and record.extra_fields:
|
||||
log_entry["extra"] = record.extra_fields
|
||||
|
||||
# Add performance metrics if available
|
||||
if hasattr(record, 'performance_data') and record.performance_data:
|
||||
log_entry["performance"] = record.performance_data
|
||||
|
||||
return json.dumps(log_entry, default=str, ensure_ascii=False)
|
||||
|
||||
|
||||
class CorrelationIDFilter(logging.Filter):
|
||||
"""Filter to add correlation ID to log records"""
|
||||
|
||||
def filter(self, record: logging.LogRecord) -> bool:
|
||||
# Add correlation ID to record if available
|
||||
if hasattr(_context, 'log_context'):
|
||||
record.correlation_id = _context.log_context.correlation_id
|
||||
else:
|
||||
record.correlation_id = "no-correlation"
|
||||
|
||||
return True
|
||||
|
||||
|
||||
class EnhancedLogger:
|
||||
"""Enhanced logger with correlation IDs and structured logging"""
|
||||
|
||||
def __init__(self, name: str):
|
||||
self.logger = logging.getLogger(name)
|
||||
self.name = name
|
||||
|
||||
# Track log events for metrics
|
||||
self._log_counts = {"debug": 0, "info": 0, "warning": 0, "error": 0, "critical": 0}
|
||||
|
||||
def _log_with_context(self, level: int, message: str, extra_fields: Optional[Dict[str, Any]] = None,
|
||||
performance_data: Optional[Dict[str, Any]] = None, **kwargs):
|
||||
"""Log with enhanced context and metrics tracking"""
|
||||
|
||||
# Track log counts for metrics
|
||||
level_name = logging.getLevelName(level).lower()
|
||||
if level_name in self._log_counts:
|
||||
self._log_counts[level_name] += 1
|
||||
metrics.increment_counter(f"log_messages", 1, {"level": level_name, "logger": self.name})
|
||||
|
||||
# Create log record with extra data
|
||||
extra = {}
|
||||
if extra_fields:
|
||||
extra['extra_fields'] = extra_fields
|
||||
if performance_data:
|
||||
extra['performance_data'] = performance_data
|
||||
|
||||
# Log the message
|
||||
self.logger.log(level, message, extra=extra, **kwargs)
|
||||
|
||||
# Track errors in metrics
|
||||
if level >= logging.ERROR:
|
||||
metrics.record_error("logging_error", message, self.name)
|
||||
|
||||
def debug(self, message: str, **kwargs):
|
||||
"""Log debug message"""
|
||||
self._log_with_context(logging.DEBUG, message, **kwargs)
|
||||
|
||||
def info(self, message: str, **kwargs):
|
||||
"""Log info message"""
|
||||
self._log_with_context(logging.INFO, message, **kwargs)
|
||||
|
||||
def warning(self, message: str, **kwargs):
|
||||
"""Log warning message"""
|
||||
self._log_with_context(logging.WARNING, message, **kwargs)
|
||||
|
||||
def error(self, message: str, **kwargs):
|
||||
"""Log error message"""
|
||||
self._log_with_context(logging.ERROR, message, **kwargs)
|
||||
|
||||
def critical(self, message: str, **kwargs):
|
||||
"""Log critical message"""
|
||||
self._log_with_context(logging.CRITICAL, message, **kwargs)
|
||||
|
||||
def exception(self, message: str, **kwargs):
|
||||
"""Log exception with traceback"""
|
||||
kwargs['exc_info'] = True
|
||||
self._log_with_context(logging.ERROR, message, **kwargs)
|
||||
|
||||
def log_operation_start(self, operation: str, **context_fields):
|
||||
"""Log the start of an operation"""
|
||||
self.info(f"Starting operation: {operation}",
|
||||
extra_fields={"operation_event": "start", "operation": operation, **context_fields})
|
||||
|
||||
def log_operation_end(self, operation: str, success: bool = True, duration: Optional[float] = None, **context_fields):
|
||||
"""Log the end of an operation"""
|
||||
outcome = "success" if success else "failure"
|
||||
extra = {"operation_event": "end", "operation": operation, "outcome": outcome, **context_fields}
|
||||
|
||||
if duration is not None:
|
||||
extra["duration_seconds"] = duration
|
||||
|
||||
level = logging.INFO if success else logging.ERROR
|
||||
self._log_with_context(level, f"Operation {outcome}: {operation}", extra_fields=extra)
|
||||
|
||||
def log_webhook_received(self, webhook_type: str, payload_size: int, **context_fields):
|
||||
"""Log webhook reception"""
|
||||
self.info(f"Webhook received: {webhook_type}",
|
||||
extra_fields={
|
||||
"event_type": "webhook_received",
|
||||
"webhook_type": webhook_type,
|
||||
"payload_size_bytes": payload_size,
|
||||
**context_fields
|
||||
})
|
||||
|
||||
def log_nfo_operation(self, operation: str, file_path: str, success: bool = True, **context_fields):
|
||||
"""Log NFO file operations"""
|
||||
outcome = "success" if success else "failure"
|
||||
level = logging.INFO if success else logging.ERROR
|
||||
|
||||
self._log_with_context(level, f"NFO {operation} {outcome}: {file_path}",
|
||||
extra_fields={
|
||||
"event_type": "nfo_operation",
|
||||
"nfo_operation": operation,
|
||||
"file_path": file_path,
|
||||
"outcome": outcome,
|
||||
**context_fields
|
||||
})
|
||||
|
||||
def log_performance_metrics(self, operation: str, duration: float, success: bool = True, **metrics_data):
|
||||
"""Log performance metrics"""
|
||||
self.debug(f"Performance: {operation} took {duration:.3f}s",
|
||||
performance_data={
|
||||
"operation": operation,
|
||||
"duration_seconds": duration,
|
||||
"success": success,
|
||||
**metrics_data
|
||||
})
|
||||
|
||||
def get_log_stats(self) -> Dict[str, int]:
|
||||
"""Get logging statistics"""
|
||||
return self._log_counts.copy()
|
||||
|
||||
|
||||
def setup_enhanced_logging(
|
||||
log_level: str = "INFO",
|
||||
structured: bool = True,
|
||||
log_file: Optional[str] = None,
|
||||
max_bytes: int = 10 * 1024 * 1024, # 10MB
|
||||
backup_count: int = 5
|
||||
) -> None:
|
||||
"""Setup enhanced logging configuration"""
|
||||
|
||||
# Configure root logger
|
||||
root_logger = logging.getLogger()
|
||||
root_logger.setLevel(getattr(logging, log_level.upper()))
|
||||
|
||||
# Clear existing handlers
|
||||
root_logger.handlers.clear()
|
||||
|
||||
# Create console handler
|
||||
console_handler = logging.StreamHandler(sys.stdout)
|
||||
|
||||
if structured:
|
||||
# Use structured JSON formatter
|
||||
formatter = StructuredFormatter(include_context=True)
|
||||
else:
|
||||
# Use simple text formatter with correlation ID
|
||||
formatter = logging.Formatter(
|
||||
'%(asctime)s [%(correlation_id)s] %(levelname)s %(name)s: %(message)s'
|
||||
)
|
||||
|
||||
console_handler.setFormatter(formatter)
|
||||
console_handler.addFilter(CorrelationIDFilter())
|
||||
root_logger.addHandler(console_handler)
|
||||
|
||||
# Add file handler if specified
|
||||
if log_file:
|
||||
from logging.handlers import RotatingFileHandler
|
||||
|
||||
file_handler = RotatingFileHandler(
|
||||
log_file, maxBytes=max_bytes, backupCount=backup_count
|
||||
)
|
||||
file_handler.setFormatter(formatter)
|
||||
file_handler.addFilter(CorrelationIDFilter())
|
||||
root_logger.addHandler(file_handler)
|
||||
|
||||
# Reduce noise from external libraries
|
||||
logging.getLogger("urllib3").setLevel(logging.WARNING)
|
||||
logging.getLogger("requests").setLevel(logging.WARNING)
|
||||
logging.getLogger("aiohttp").setLevel(logging.WARNING)
|
||||
|
||||
|
||||
def get_enhanced_logger(name: str) -> EnhancedLogger:
|
||||
"""Get enhanced logger instance"""
|
||||
return EnhancedLogger(name)
|
||||
|
||||
|
||||
def set_log_context(
|
||||
correlation_id: Optional[str] = None,
|
||||
request_id: Optional[str] = None,
|
||||
operation: Optional[str] = None,
|
||||
**kwargs
|
||||
) -> LogContext:
|
||||
"""Set logging context for current thread"""
|
||||
|
||||
if correlation_id is None:
|
||||
correlation_id = str(uuid.uuid4())
|
||||
|
||||
context = LogContext(
|
||||
correlation_id=correlation_id,
|
||||
request_id=request_id,
|
||||
operation=operation,
|
||||
**kwargs
|
||||
)
|
||||
|
||||
_context.log_context = context
|
||||
return context
|
||||
|
||||
|
||||
def get_log_context() -> Optional[LogContext]:
|
||||
"""Get current logging context"""
|
||||
return getattr(_context, 'log_context', None)
|
||||
|
||||
|
||||
def clear_log_context():
|
||||
"""Clear logging context for current thread"""
|
||||
if hasattr(_context, 'log_context'):
|
||||
delattr(_context, 'log_context')
|
||||
|
||||
|
||||
@contextmanager
|
||||
def log_context(correlation_id: Optional[str] = None, **context_fields):
|
||||
"""Context manager for scoped logging context"""
|
||||
original_context = get_log_context()
|
||||
|
||||
try:
|
||||
# Set new context
|
||||
new_context = set_log_context(correlation_id=correlation_id, **context_fields)
|
||||
yield new_context
|
||||
finally:
|
||||
# Restore original context
|
||||
if original_context:
|
||||
_context.log_context = original_context
|
||||
else:
|
||||
clear_log_context()
|
||||
|
||||
|
||||
@contextmanager
|
||||
def log_operation(operation: str, logger: Optional[EnhancedLogger] = None, **context_fields):
|
||||
"""Context manager for logging operation start/end with timing"""
|
||||
if logger is None:
|
||||
logger = get_enhanced_logger(__name__)
|
||||
|
||||
start_time = time.time()
|
||||
success = True
|
||||
|
||||
# Update context with operation
|
||||
current_context = get_log_context()
|
||||
if current_context:
|
||||
current_context.operation = operation
|
||||
current_context.processing_stage = "executing"
|
||||
|
||||
logger.log_operation_start(operation, **context_fields)
|
||||
|
||||
try:
|
||||
yield
|
||||
except Exception as e:
|
||||
success = False
|
||||
logger.exception(f"Operation failed: {operation}",
|
||||
extra_fields={"operation": operation, "error": str(e), **context_fields})
|
||||
raise
|
||||
finally:
|
||||
duration = time.time() - start_time
|
||||
logger.log_operation_end(operation, success, duration, **context_fields)
|
||||
|
||||
# Update metrics
|
||||
metrics.record_operation_duration(operation, duration, success)
|
||||
|
||||
|
||||
def trace_request(request_id: Optional[str] = None, **context_fields):
|
||||
"""Decorator/context manager for request tracing"""
|
||||
def decorator(func):
|
||||
def wrapper(*args, **kwargs):
|
||||
correlation_id = str(uuid.uuid4())
|
||||
req_id = request_id or f"req_{int(time.time())}"
|
||||
|
||||
with log_context(correlation_id=correlation_id, request_id=req_id, **context_fields):
|
||||
return func(*args, **kwargs)
|
||||
return wrapper
|
||||
|
||||
# Can be used as context manager or decorator
|
||||
if request_id is None and len(context_fields) == 1 and callable(list(context_fields.values())[0]):
|
||||
# Used as decorator without parentheses
|
||||
func = list(context_fields.values())[0]
|
||||
return decorator(func)
|
||||
else:
|
||||
# Used as decorator with parameters or context manager
|
||||
return decorator
|
||||
|
||||
|
||||
# Module-level logger for this module
|
||||
logger = get_enhanced_logger(__name__)
|
||||
|
||||
|
||||
def get_logging_stats() -> Dict[str, Any]:
|
||||
"""Get comprehensive logging statistics"""
|
||||
# Collect stats from all enhanced loggers
|
||||
total_stats = {"debug": 0, "info": 0, "warning": 0, "error": 0, "critical": 0}
|
||||
|
||||
# This is a simplified version - in practice you'd track all logger instances
|
||||
return {
|
||||
"total_log_messages": sum(total_stats.values()),
|
||||
"by_level": total_stats,
|
||||
"structured_logging_enabled": True,
|
||||
"correlation_tracking_enabled": True
|
||||
}
|
||||
@@ -0,0 +1,354 @@
|
||||
"""
|
||||
Metrics Collection System for NFOGuard
|
||||
Provides performance monitoring, counters, and operational metrics
|
||||
"""
|
||||
import time
|
||||
import psutil
|
||||
import threading
|
||||
from datetime import datetime, timedelta
|
||||
from typing import Dict, Any, List, Optional
|
||||
from dataclasses import dataclass, field
|
||||
from collections import defaultdict, deque
|
||||
from contextlib import contextmanager
|
||||
import asyncio
|
||||
|
||||
|
||||
@dataclass
|
||||
class MetricValue:
|
||||
"""Individual metric value with timestamp"""
|
||||
value: float
|
||||
timestamp: float = field(default_factory=time.time)
|
||||
labels: Dict[str, str] = field(default_factory=dict)
|
||||
|
||||
|
||||
@dataclass
|
||||
class TimeSeriesMetric:
|
||||
"""Time series metric with historical data"""
|
||||
name: str
|
||||
values: deque = field(default_factory=lambda: deque(maxlen=1000))
|
||||
total: float = 0.0
|
||||
count: int = 0
|
||||
|
||||
def add_value(self, value: float, labels: Optional[Dict[str, str]] = None):
|
||||
"""Add a new metric value"""
|
||||
metric_value = MetricValue(value, labels=labels or {})
|
||||
self.values.append(metric_value)
|
||||
self.total += value
|
||||
self.count += 1
|
||||
|
||||
def get_average(self, window_seconds: int = 300) -> float:
|
||||
"""Get average value over time window"""
|
||||
cutoff_time = time.time() - window_seconds
|
||||
recent_values = [v.value for v in self.values if v.timestamp > cutoff_time]
|
||||
return sum(recent_values) / len(recent_values) if recent_values else 0.0
|
||||
|
||||
def get_rate_per_minute(self, window_seconds: int = 300) -> float:
|
||||
"""Get rate per minute over time window"""
|
||||
cutoff_time = time.time() - window_seconds
|
||||
recent_count = len([v for v in self.values if v.timestamp > cutoff_time])
|
||||
return (recent_count / window_seconds) * 60 if window_seconds > 0 else 0.0
|
||||
|
||||
|
||||
class MetricsCollector:
|
||||
"""Central metrics collection system"""
|
||||
|
||||
def __init__(self):
|
||||
self._metrics: Dict[str, TimeSeriesMetric] = {}
|
||||
self._counters: Dict[str, int] = defaultdict(int)
|
||||
self._gauges: Dict[str, float] = {}
|
||||
self._histograms: Dict[str, List[float]] = defaultdict(list)
|
||||
self._start_time = time.time()
|
||||
self._lock = threading.RLock()
|
||||
|
||||
# Processing metrics
|
||||
self._active_operations = 0
|
||||
self._operation_durations = deque(maxlen=1000)
|
||||
|
||||
# Error tracking
|
||||
self._error_counts = defaultdict(int)
|
||||
self._last_errors = deque(maxlen=100)
|
||||
|
||||
# System metrics
|
||||
self._system_stats_cache = {}
|
||||
self._system_stats_last_update = 0
|
||||
self._system_stats_cache_ttl = 30 # 30 seconds
|
||||
|
||||
def increment_counter(self, name: str, value: int = 1, labels: Optional[Dict[str, str]] = None):
|
||||
"""Increment a counter metric"""
|
||||
with self._lock:
|
||||
full_name = self._build_metric_name(name, labels)
|
||||
self._counters[full_name] += value
|
||||
|
||||
# Also track in time series for rate calculations
|
||||
if name not in self._metrics:
|
||||
self._metrics[name] = TimeSeriesMetric(name)
|
||||
self._metrics[name].add_value(value, labels)
|
||||
|
||||
def set_gauge(self, name: str, value: float, labels: Optional[Dict[str, str]] = None):
|
||||
"""Set a gauge metric value"""
|
||||
with self._lock:
|
||||
full_name = self._build_metric_name(name, labels)
|
||||
self._gauges[full_name] = value
|
||||
|
||||
def record_histogram(self, name: str, value: float, labels: Optional[Dict[str, str]] = None):
|
||||
"""Record a histogram value"""
|
||||
with self._lock:
|
||||
full_name = self._build_metric_name(name, labels)
|
||||
self._histograms[full_name].append(value)
|
||||
|
||||
# Keep only recent values (last 1000)
|
||||
if len(self._histograms[full_name]) > 1000:
|
||||
self._histograms[full_name] = self._histograms[full_name][-1000:]
|
||||
|
||||
# Also track in time series
|
||||
if name not in self._metrics:
|
||||
self._metrics[name] = TimeSeriesMetric(name)
|
||||
self._metrics[name].add_value(value, labels)
|
||||
|
||||
def record_operation_duration(self, operation: str, duration: float, success: bool = True):
|
||||
"""Record operation duration and outcome"""
|
||||
with self._lock:
|
||||
# Record duration
|
||||
self.record_histogram(f"operation_duration_{operation}", duration)
|
||||
|
||||
# Record outcome
|
||||
outcome = "success" if success else "error"
|
||||
self.increment_counter(f"operation_total", 1, {"operation": operation, "outcome": outcome})
|
||||
|
||||
# Track active operations
|
||||
if operation.endswith("_start"):
|
||||
self._active_operations += 1
|
||||
elif operation.endswith("_end"):
|
||||
self._active_operations = max(0, self._active_operations - 1)
|
||||
|
||||
def record_error(self, error_type: str, error_message: str, operation: Optional[str] = None):
|
||||
"""Record an error occurrence"""
|
||||
with self._lock:
|
||||
self._error_counts[error_type] += 1
|
||||
|
||||
error_info = {
|
||||
"type": error_type,
|
||||
"message": error_message,
|
||||
"operation": operation,
|
||||
"timestamp": time.time()
|
||||
}
|
||||
self._last_errors.append(error_info)
|
||||
|
||||
# Increment error counter
|
||||
labels = {"error_type": error_type}
|
||||
if operation:
|
||||
labels["operation"] = operation
|
||||
self.increment_counter("errors_total", 1, labels)
|
||||
|
||||
@contextmanager
|
||||
def operation_timer(self, operation: str):
|
||||
"""Context manager for timing operations"""
|
||||
start_time = time.time()
|
||||
success = True
|
||||
|
||||
try:
|
||||
self.record_operation_duration(f"{operation}_start", 0)
|
||||
yield
|
||||
except Exception as e:
|
||||
success = False
|
||||
self.record_error("operation_error", str(e), operation)
|
||||
raise
|
||||
finally:
|
||||
duration = time.time() - start_time
|
||||
self.record_operation_duration(operation, duration, success)
|
||||
self.record_operation_duration(f"{operation}_end", 0)
|
||||
|
||||
def get_system_metrics(self) -> Dict[str, Any]:
|
||||
"""Get current system resource metrics"""
|
||||
now = time.time()
|
||||
|
||||
# Use cached values if recent
|
||||
if (now - self._system_stats_last_update) < self._system_stats_cache_ttl:
|
||||
return self._system_stats_cache
|
||||
|
||||
try:
|
||||
# CPU metrics
|
||||
cpu_percent = psutil.cpu_percent(interval=0.1)
|
||||
cpu_count = psutil.cpu_count()
|
||||
|
||||
# Memory metrics
|
||||
memory = psutil.virtual_memory()
|
||||
|
||||
# Disk metrics for database path
|
||||
try:
|
||||
from config.settings import config
|
||||
db_disk = psutil.disk_usage(str(config.db_path.parent))
|
||||
except:
|
||||
db_disk = None
|
||||
|
||||
# Process metrics
|
||||
process = psutil.Process()
|
||||
process_memory = process.memory_info()
|
||||
|
||||
self._system_stats_cache = {
|
||||
"cpu_percent": cpu_percent,
|
||||
"cpu_count": cpu_count,
|
||||
"memory_total": memory.total,
|
||||
"memory_available": memory.available,
|
||||
"memory_percent": memory.percent,
|
||||
"process_memory_rss": process_memory.rss,
|
||||
"process_memory_vms": process_memory.vms,
|
||||
"db_disk_free": db_disk.free if db_disk else None,
|
||||
"db_disk_total": db_disk.total if db_disk else None,
|
||||
"active_operations": self._active_operations,
|
||||
"uptime_seconds": now - self._start_time
|
||||
}
|
||||
|
||||
self._system_stats_last_update = now
|
||||
|
||||
except Exception as e:
|
||||
# Return basic metrics if detailed collection fails
|
||||
self._system_stats_cache = {
|
||||
"uptime_seconds": now - self._start_time,
|
||||
"active_operations": self._active_operations,
|
||||
"error": str(e)
|
||||
}
|
||||
|
||||
return self._system_stats_cache
|
||||
|
||||
def get_processing_metrics(self) -> Dict[str, Any]:
|
||||
"""Get processing-related metrics"""
|
||||
with self._lock:
|
||||
# Calculate rates and averages
|
||||
webhook_rate = self._metrics.get("webhooks_received", TimeSeriesMetric("webhooks_received")).get_rate_per_minute()
|
||||
nfo_rate = self._metrics.get("nfo_created", TimeSeriesMetric("nfo_created")).get_rate_per_minute()
|
||||
|
||||
avg_processing_time = 0.0
|
||||
if "processing_duration" in self._metrics:
|
||||
avg_processing_time = self._metrics["processing_duration"].get_average()
|
||||
|
||||
return {
|
||||
"webhooks_received_per_minute": webhook_rate,
|
||||
"nfo_files_created_per_minute": nfo_rate,
|
||||
"average_processing_time_seconds": avg_processing_time,
|
||||
"active_operations": self._active_operations,
|
||||
"total_webhooks": self._counters.get("webhooks_received", 0),
|
||||
"total_nfo_created": self._counters.get("nfo_created", 0),
|
||||
"total_errors": sum(self._error_counts.values())
|
||||
}
|
||||
|
||||
def get_error_metrics(self) -> Dict[str, Any]:
|
||||
"""Get error-related metrics"""
|
||||
with self._lock:
|
||||
recent_errors = []
|
||||
cutoff_time = time.time() - 3600 # Last hour
|
||||
|
||||
for error in self._last_errors:
|
||||
if error["timestamp"] > cutoff_time:
|
||||
recent_errors.append({
|
||||
"type": error["type"],
|
||||
"message": error["message"][:100], # Truncate long messages
|
||||
"operation": error["operation"],
|
||||
"timestamp": error["timestamp"]
|
||||
})
|
||||
|
||||
return {
|
||||
"error_counts_by_type": dict(self._error_counts),
|
||||
"recent_errors": recent_errors[-10:], # Last 10 errors
|
||||
"total_errors": sum(self._error_counts.values()),
|
||||
"error_rate_per_minute": len([e for e in self._last_errors if e["timestamp"] > time.time() - 300]) / 5
|
||||
}
|
||||
|
||||
def get_prometheus_metrics(self) -> str:
|
||||
"""Generate Prometheus-compatible metrics format"""
|
||||
lines = []
|
||||
|
||||
# Add help and type information
|
||||
lines.append("# HELP nfoguard_webhooks_total Total number of webhooks received")
|
||||
lines.append("# TYPE nfoguard_webhooks_total counter")
|
||||
|
||||
with self._lock:
|
||||
# Counters
|
||||
for name, value in self._counters.items():
|
||||
metric_name = f"nfoguard_{name.replace('-', '_')}"
|
||||
lines.append(f"{metric_name} {value}")
|
||||
|
||||
# Gauges
|
||||
lines.append("# HELP nfoguard_active_operations Current number of active operations")
|
||||
lines.append("# TYPE nfoguard_active_operations gauge")
|
||||
lines.append(f"nfoguard_active_operations {self._active_operations}")
|
||||
|
||||
# System metrics
|
||||
system_metrics = self.get_system_metrics()
|
||||
for key, value in system_metrics.items():
|
||||
if isinstance(value, (int, float)) and value is not None:
|
||||
metric_name = f"nfoguard_system_{key}"
|
||||
lines.append(f"{metric_name} {value}")
|
||||
|
||||
return "\n".join(lines)
|
||||
|
||||
def get_all_metrics(self) -> Dict[str, Any]:
|
||||
"""Get all metrics in a structured format"""
|
||||
return {
|
||||
"system": self.get_system_metrics(),
|
||||
"processing": self.get_processing_metrics(),
|
||||
"errors": self.get_error_metrics(),
|
||||
"timestamp": time.time(),
|
||||
"uptime_seconds": time.time() - self._start_time
|
||||
}
|
||||
|
||||
def reset_metrics(self, metric_types: Optional[List[str]] = None):
|
||||
"""Reset specific metric types or all metrics"""
|
||||
with self._lock:
|
||||
if not metric_types or "counters" in metric_types:
|
||||
self._counters.clear()
|
||||
|
||||
if not metric_types or "histograms" in metric_types:
|
||||
self._histograms.clear()
|
||||
|
||||
if not metric_types or "errors" in metric_types:
|
||||
self._error_counts.clear()
|
||||
self._last_errors.clear()
|
||||
|
||||
if not metric_types or "timeseries" in metric_types:
|
||||
self._metrics.clear()
|
||||
|
||||
def _build_metric_name(self, name: str, labels: Optional[Dict[str, str]]) -> str:
|
||||
"""Build metric name with labels"""
|
||||
if not labels:
|
||||
return name
|
||||
|
||||
label_str = ",".join(f"{k}={v}" for k, v in sorted(labels.items()))
|
||||
return f"{name}{{{label_str}}}"
|
||||
|
||||
|
||||
# Global metrics collector instance
|
||||
metrics = MetricsCollector()
|
||||
|
||||
|
||||
# Convenience functions for common operations
|
||||
def track_webhook_received(webhook_type: str):
|
||||
"""Track webhook received"""
|
||||
metrics.increment_counter("webhooks_received", 1, {"type": webhook_type})
|
||||
|
||||
|
||||
def track_nfo_created(media_type: str, success: bool = True):
|
||||
"""Track NFO file creation"""
|
||||
outcome = "success" if success else "error"
|
||||
metrics.increment_counter("nfo_created", 1, {"media_type": media_type, "outcome": outcome})
|
||||
|
||||
|
||||
def track_api_call(api_name: str, duration: float, success: bool = True):
|
||||
"""Track external API call"""
|
||||
metrics.record_histogram(f"api_call_duration", duration, {"api": api_name})
|
||||
outcome = "success" if success else "error"
|
||||
metrics.increment_counter("api_calls_total", 1, {"api": api_name, "outcome": outcome})
|
||||
|
||||
|
||||
def track_database_operation(operation: str, duration: float, success: bool = True):
|
||||
"""Track database operation"""
|
||||
metrics.record_histogram("database_operation_duration", duration, {"operation": operation})
|
||||
outcome = "success" if success else "error"
|
||||
metrics.increment_counter("database_operations_total", 1, {"operation": operation, "outcome": outcome})
|
||||
|
||||
|
||||
def track_file_operation(operation: str, duration: float, success: bool = True):
|
||||
"""Track file system operation"""
|
||||
metrics.record_histogram("file_operation_duration", duration, {"operation": operation})
|
||||
outcome = "success" if success else "error"
|
||||
metrics.increment_counter("file_operations_total", 1, {"operation": operation, "outcome": outcome})
|
||||
@@ -0,0 +1,413 @@
|
||||
"""
|
||||
Performance Monitoring and Profiling for NFOGuard
|
||||
Provides detailed performance analysis and optimization insights
|
||||
"""
|
||||
import time
|
||||
import asyncio
|
||||
import threading
|
||||
import functools
|
||||
from typing import Dict, Any, List, Optional, Callable, TypeVar, Union
|
||||
from dataclasses import dataclass, field
|
||||
from collections import defaultdict, deque
|
||||
from contextlib import asynccontextmanager, contextmanager
|
||||
import traceback
|
||||
import sys
|
||||
|
||||
from monitoring.metrics import metrics
|
||||
|
||||
|
||||
T = TypeVar('T')
|
||||
|
||||
|
||||
@dataclass
|
||||
class PerformanceProfile:
|
||||
"""Performance profile for an operation"""
|
||||
operation_name: str
|
||||
total_calls: int = 0
|
||||
total_duration: float = 0.0
|
||||
min_duration: float = float('inf')
|
||||
max_duration: float = 0.0
|
||||
recent_durations: deque = field(default_factory=lambda: deque(maxlen=100))
|
||||
error_count: int = 0
|
||||
concurrent_calls: int = 0
|
||||
|
||||
def add_measurement(self, duration: float, success: bool = True):
|
||||
"""Add a performance measurement"""
|
||||
self.total_calls += 1
|
||||
self.total_duration += duration
|
||||
self.min_duration = min(self.min_duration, duration)
|
||||
self.max_duration = max(self.max_duration, duration)
|
||||
self.recent_durations.append(duration)
|
||||
|
||||
if not success:
|
||||
self.error_count += 1
|
||||
|
||||
def get_average_duration(self) -> float:
|
||||
"""Get average duration across all calls"""
|
||||
return self.total_duration / self.total_calls if self.total_calls > 0 else 0.0
|
||||
|
||||
def get_recent_average(self, window: int = 50) -> float:
|
||||
"""Get average of recent calls"""
|
||||
recent = list(self.recent_durations)[-window:]
|
||||
return sum(recent) / len(recent) if recent else 0.0
|
||||
|
||||
def get_percentiles(self) -> Dict[str, float]:
|
||||
"""Get duration percentiles for recent calls"""
|
||||
recent = sorted(list(self.recent_durations))
|
||||
if not recent:
|
||||
return {"p50": 0, "p95": 0, "p99": 0}
|
||||
|
||||
length = len(recent)
|
||||
return {
|
||||
"p50": recent[int(length * 0.5)] if length > 0 else 0,
|
||||
"p95": recent[int(length * 0.95)] if length > 0 else 0,
|
||||
"p99": recent[int(length * 0.99)] if length > 0 else 0
|
||||
}
|
||||
|
||||
def to_dict(self) -> Dict[str, Any]:
|
||||
"""Convert to dictionary for API responses"""
|
||||
percentiles = self.get_percentiles()
|
||||
|
||||
return {
|
||||
"operation_name": self.operation_name,
|
||||
"total_calls": self.total_calls,
|
||||
"error_count": self.error_count,
|
||||
"error_rate": self.error_count / self.total_calls if self.total_calls > 0 else 0,
|
||||
"concurrent_calls": self.concurrent_calls,
|
||||
"duration_stats": {
|
||||
"average": round(self.get_average_duration(), 4),
|
||||
"recent_average": round(self.get_recent_average(), 4),
|
||||
"min": round(self.min_duration if self.min_duration != float('inf') else 0, 4),
|
||||
"max": round(self.max_duration, 4),
|
||||
"p50": round(percentiles["p50"], 4),
|
||||
"p95": round(percentiles["p95"], 4),
|
||||
"p99": round(percentiles["p99"], 4)
|
||||
},
|
||||
"performance_rating": self._get_performance_rating()
|
||||
}
|
||||
|
||||
def _get_performance_rating(self) -> str:
|
||||
"""Get performance rating based on metrics"""
|
||||
avg_duration = self.get_recent_average()
|
||||
error_rate = self.error_count / self.total_calls if self.total_calls > 0 else 0
|
||||
|
||||
if error_rate > 0.1: # >10% error rate
|
||||
return "poor"
|
||||
elif avg_duration > 5.0: # >5 seconds average
|
||||
return "slow"
|
||||
elif avg_duration > 1.0: # >1 second average
|
||||
return "acceptable"
|
||||
else:
|
||||
return "excellent"
|
||||
|
||||
|
||||
class PerformanceMonitor:
|
||||
"""Advanced performance monitoring system"""
|
||||
|
||||
def __init__(self):
|
||||
self._profiles: Dict[str, PerformanceProfile] = {}
|
||||
self._active_operations: Dict[str, float] = {} # operation_id -> start_time
|
||||
self._lock = threading.RLock()
|
||||
|
||||
# Slow operation tracking
|
||||
self._slow_operation_threshold = 1.0 # 1 second
|
||||
self._slow_operations = deque(maxlen=100)
|
||||
|
||||
# Memory monitoring
|
||||
self._memory_samples = deque(maxlen=1000)
|
||||
self._memory_monitoring_enabled = True
|
||||
|
||||
# Async operation tracking
|
||||
self._async_tasks = {}
|
||||
self._task_counter = 0
|
||||
|
||||
def get_profile(self, operation_name: str) -> PerformanceProfile:
|
||||
"""Get or create performance profile for operation"""
|
||||
with self._lock:
|
||||
if operation_name not in self._profiles:
|
||||
self._profiles[operation_name] = PerformanceProfile(operation_name)
|
||||
return self._profiles[operation_name]
|
||||
|
||||
@contextmanager
|
||||
def monitor_operation(self, operation_name: str, **kwargs):
|
||||
"""Context manager for monitoring synchronous operations"""
|
||||
start_time = time.time()
|
||||
operation_id = f"{operation_name}_{id(threading.current_thread())}_{time.time()}"
|
||||
success = True
|
||||
|
||||
profile = self.get_profile(operation_name)
|
||||
|
||||
with self._lock:
|
||||
profile.concurrent_calls += 1
|
||||
self._active_operations[operation_id] = start_time
|
||||
|
||||
try:
|
||||
yield
|
||||
except Exception as e:
|
||||
success = False
|
||||
metrics.record_error("performance_monitor", str(e), operation_name)
|
||||
raise
|
||||
finally:
|
||||
end_time = time.time()
|
||||
duration = end_time - start_time
|
||||
|
||||
with self._lock:
|
||||
profile.concurrent_calls = max(0, profile.concurrent_calls - 1)
|
||||
self._active_operations.pop(operation_id, None)
|
||||
|
||||
# Record measurement
|
||||
profile.add_measurement(duration, success)
|
||||
|
||||
# Track slow operations
|
||||
if duration > self._slow_operation_threshold:
|
||||
self._slow_operations.append({
|
||||
"operation": operation_name,
|
||||
"duration": duration,
|
||||
"timestamp": end_time,
|
||||
"success": success,
|
||||
"metadata": kwargs
|
||||
})
|
||||
|
||||
# Update metrics
|
||||
metrics.record_histogram(f"operation_duration", duration, {"operation": operation_name})
|
||||
if not success:
|
||||
metrics.increment_counter("operation_errors", 1, {"operation": operation_name})
|
||||
|
||||
@asynccontextmanager
|
||||
async def monitor_async_operation(self, operation_name: str, **kwargs):
|
||||
"""Context manager for monitoring asynchronous operations"""
|
||||
start_time = time.time()
|
||||
task_id = f"{operation_name}_{self._task_counter}"
|
||||
self._task_counter += 1
|
||||
success = True
|
||||
|
||||
profile = self.get_profile(operation_name)
|
||||
|
||||
with self._lock:
|
||||
profile.concurrent_calls += 1
|
||||
self._async_tasks[task_id] = {
|
||||
"operation": operation_name,
|
||||
"start_time": start_time,
|
||||
"metadata": kwargs
|
||||
}
|
||||
|
||||
try:
|
||||
yield
|
||||
except Exception as e:
|
||||
success = False
|
||||
metrics.record_error("async_performance_monitor", str(e), operation_name)
|
||||
raise
|
||||
finally:
|
||||
end_time = time.time()
|
||||
duration = end_time - start_time
|
||||
|
||||
with self._lock:
|
||||
profile.concurrent_calls = max(0, profile.concurrent_calls - 1)
|
||||
self._async_tasks.pop(task_id, None)
|
||||
|
||||
# Record measurement
|
||||
profile.add_measurement(duration, success)
|
||||
|
||||
# Track slow operations
|
||||
if duration > self._slow_operation_threshold:
|
||||
self._slow_operations.append({
|
||||
"operation": operation_name,
|
||||
"duration": duration,
|
||||
"timestamp": end_time,
|
||||
"success": success,
|
||||
"async": True,
|
||||
"metadata": kwargs
|
||||
})
|
||||
|
||||
# Update metrics
|
||||
metrics.record_histogram(f"async_operation_duration", duration, {"operation": operation_name})
|
||||
if not success:
|
||||
metrics.increment_counter("async_operation_errors", 1, {"operation": operation_name})
|
||||
|
||||
def monitor_function(self, operation_name: Optional[str] = None):
|
||||
"""Decorator for monitoring function performance"""
|
||||
def decorator(func: Callable[..., T]) -> Callable[..., T]:
|
||||
name = operation_name or f"{func.__module__}.{func.__name__}"
|
||||
|
||||
if asyncio.iscoroutinefunction(func):
|
||||
@functools.wraps(func)
|
||||
async def async_wrapper(*args, **kwargs):
|
||||
async with self.monitor_async_operation(name):
|
||||
return await func(*args, **kwargs)
|
||||
return async_wrapper
|
||||
else:
|
||||
@functools.wraps(func)
|
||||
def sync_wrapper(*args, **kwargs):
|
||||
with self.monitor_operation(name):
|
||||
return func(*args, **kwargs)
|
||||
return sync_wrapper
|
||||
|
||||
return decorator
|
||||
|
||||
def get_performance_summary(self) -> Dict[str, Any]:
|
||||
"""Get comprehensive performance summary"""
|
||||
with self._lock:
|
||||
# Get top operations by various metrics
|
||||
profiles = list(self._profiles.values())
|
||||
|
||||
# Sort by total calls
|
||||
most_called = sorted(profiles, key=lambda p: p.total_calls, reverse=True)[:10]
|
||||
|
||||
# Sort by average duration
|
||||
slowest_avg = sorted(profiles, key=lambda p: p.get_average_duration(), reverse=True)[:10]
|
||||
|
||||
# Sort by recent average
|
||||
slowest_recent = sorted(profiles, key=lambda p: p.get_recent_average(), reverse=True)[:10]
|
||||
|
||||
# Sort by error rate
|
||||
highest_errors = sorted(
|
||||
[p for p in profiles if p.total_calls > 0],
|
||||
key=lambda p: p.error_count / p.total_calls,
|
||||
reverse=True
|
||||
)[:10]
|
||||
|
||||
# Get active operations count
|
||||
total_active = sum(p.concurrent_calls for p in profiles)
|
||||
|
||||
# Get slow operations
|
||||
recent_slow = list(self._slow_operations)[-20:] # Last 20 slow operations
|
||||
|
||||
return {
|
||||
"overview": {
|
||||
"total_operations_tracked": len(profiles),
|
||||
"total_active_operations": total_active,
|
||||
"slow_operation_threshold_seconds": self._slow_operation_threshold,
|
||||
"total_slow_operations": len(self._slow_operations)
|
||||
},
|
||||
"top_operations": {
|
||||
"most_called": [p.to_dict() for p in most_called],
|
||||
"slowest_average": [p.to_dict() for p in slowest_avg],
|
||||
"slowest_recent": [p.to_dict() for p in slowest_recent],
|
||||
"highest_error_rate": [p.to_dict() for p in highest_errors]
|
||||
},
|
||||
"recent_slow_operations": recent_slow,
|
||||
"performance_insights": self._generate_performance_insights(profiles)
|
||||
}
|
||||
|
||||
def get_operation_detail(self, operation_name: str) -> Optional[Dict[str, Any]]:
|
||||
"""Get detailed performance data for specific operation"""
|
||||
with self._lock:
|
||||
if operation_name not in self._profiles:
|
||||
return None
|
||||
|
||||
profile = self._profiles[operation_name]
|
||||
|
||||
# Get related slow operations
|
||||
related_slow = [
|
||||
op for op in self._slow_operations
|
||||
if op["operation"] == operation_name
|
||||
]
|
||||
|
||||
detail = profile.to_dict()
|
||||
detail.update({
|
||||
"detailed_stats": {
|
||||
"total_duration": round(profile.total_duration, 4),
|
||||
"recent_durations": list(profile.recent_durations)[-20:], # Last 20 calls
|
||||
"slow_operations_count": len(related_slow),
|
||||
"recent_slow_operations": related_slow[-10:] # Last 10 slow calls
|
||||
},
|
||||
"recommendations": self._get_operation_recommendations(profile)
|
||||
})
|
||||
|
||||
return detail
|
||||
|
||||
def _generate_performance_insights(self, profiles: List[PerformanceProfile]) -> List[str]:
|
||||
"""Generate performance optimization insights"""
|
||||
insights = []
|
||||
|
||||
# Check for very slow operations
|
||||
very_slow = [p for p in profiles if p.get_recent_average() > 5.0]
|
||||
if very_slow:
|
||||
insights.append(f"Found {len(very_slow)} operations with >5s average duration - consider optimization")
|
||||
|
||||
# Check for high error rates
|
||||
high_error_rate = [p for p in profiles if p.total_calls > 10 and (p.error_count / p.total_calls) > 0.1]
|
||||
if high_error_rate:
|
||||
insights.append(f"Found {len(high_error_rate)} operations with >10% error rate - investigate failures")
|
||||
|
||||
# Check for high concurrency
|
||||
high_concurrency = [p for p in profiles if p.concurrent_calls > 5]
|
||||
if high_concurrency:
|
||||
insights.append(f"Found {len(high_concurrency)} operations with high concurrency - may need rate limiting")
|
||||
|
||||
# Check total active operations
|
||||
total_active = sum(p.concurrent_calls for p in profiles)
|
||||
if total_active > 20:
|
||||
insights.append(f"High total concurrent operations ({total_active}) - system may be under load")
|
||||
|
||||
# Performance trends
|
||||
recent_slow_count = len([op for op in self._slow_operations if op["timestamp"] > time.time() - 300])
|
||||
if recent_slow_count > 10:
|
||||
insights.append(f"Many slow operations recently ({recent_slow_count} in last 5 minutes)")
|
||||
|
||||
if not insights:
|
||||
insights.append("No significant performance issues detected")
|
||||
|
||||
return insights
|
||||
|
||||
def _get_operation_recommendations(self, profile: PerformanceProfile) -> List[str]:
|
||||
"""Get recommendations for optimizing specific operation"""
|
||||
recommendations = []
|
||||
|
||||
avg_duration = profile.get_recent_average()
|
||||
error_rate = profile.error_count / profile.total_calls if profile.total_calls > 0 else 0
|
||||
|
||||
if avg_duration > 5.0:
|
||||
recommendations.append("Consider breaking down this operation into smaller parts")
|
||||
recommendations.append("Review database queries and file I/O for optimization opportunities")
|
||||
elif avg_duration > 1.0:
|
||||
recommendations.append("Monitor for potential optimization opportunities")
|
||||
|
||||
if error_rate > 0.1:
|
||||
recommendations.append("High error rate - investigate common failure causes")
|
||||
recommendations.append("Consider adding retry logic or better error handling")
|
||||
|
||||
if profile.concurrent_calls > 5:
|
||||
recommendations.append("High concurrency - consider adding rate limiting")
|
||||
recommendations.append("Review resource usage and potential bottlenecks")
|
||||
|
||||
percentiles = profile.get_percentiles()
|
||||
if percentiles["p99"] > percentiles["p50"] * 3:
|
||||
recommendations.append("High latency variance - investigate outlier causes")
|
||||
|
||||
if not recommendations:
|
||||
recommendations.append("Performance appears optimal for this operation")
|
||||
|
||||
return recommendations
|
||||
|
||||
def set_slow_operation_threshold(self, threshold_seconds: float):
|
||||
"""Set threshold for what constitutes a slow operation"""
|
||||
with self._lock:
|
||||
self._slow_operation_threshold = threshold_seconds
|
||||
|
||||
def clear_profiles(self, operation_names: Optional[List[str]] = None):
|
||||
"""Clear performance profiles for specific operations or all"""
|
||||
with self._lock:
|
||||
if operation_names:
|
||||
for name in operation_names:
|
||||
self._profiles.pop(name, None)
|
||||
else:
|
||||
self._profiles.clear()
|
||||
self._slow_operations.clear()
|
||||
|
||||
|
||||
# Global performance monitor instance
|
||||
performance_monitor = PerformanceMonitor()
|
||||
|
||||
# Decorator shortcuts
|
||||
def monitor_performance(operation_name: Optional[str] = None):
|
||||
"""Shortcut decorator for performance monitoring"""
|
||||
return performance_monitor.monitor_function(operation_name)
|
||||
|
||||
def monitor_sync_operation(operation_name: str, **kwargs):
|
||||
"""Shortcut for synchronous operation monitoring"""
|
||||
return performance_monitor.monitor_operation(operation_name, **kwargs)
|
||||
|
||||
def monitor_async_operation(operation_name: str, **kwargs):
|
||||
"""Shortcut for asynchronous operation monitoring"""
|
||||
return performance_monitor.monitor_async_operation(operation_name, **kwargs)
|
||||
Reference in New Issue
Block a user