Initial commit: Complete DevServer monitoring framework
- FastAPI application with OpenTelemetry instrumentation - Redis caching and Celery task processing - Docker Compose setup with monitoring stack - Grafana dashboards and Prometheus metrics - Jaeger distributed tracing - Comprehensive documentation in docs/ folder - Monitoring configuration and troubleshooting guides
This commit is contained in:
0
app/__init__.py
Normal file
0
app/__init__.py
Normal file
434
app/client.py
Normal file
434
app/client.py
Normal file
@@ -0,0 +1,434 @@
|
||||
"""
|
||||
DevServer API Client
|
||||
Demonstrates usage of all API endpoints with Redis and Celery integration
|
||||
"""
|
||||
|
||||
import requests
|
||||
import time
|
||||
import json
|
||||
import logging
|
||||
from typing import Optional, Dict, Any
|
||||
from datetime import datetime
|
||||
|
||||
# Setup client logging
|
||||
logging.basicConfig(
|
||||
level=logging.INFO,
|
||||
format='%(asctime)s | %(levelname)-8s | %(message)s',
|
||||
datefmt='%H:%M:%S'
|
||||
)
|
||||
logger = logging.getLogger("devserver_client")
|
||||
|
||||
|
||||
class DevServerClient:
|
||||
"""Client for interacting with DevServer API"""
|
||||
|
||||
def __init__(self, base_url: str = "http://localhost:8000"):
|
||||
self.base_url = base_url
|
||||
self.session = requests.Session()
|
||||
logger.info(f"DevServer client initialized: {base_url}")
|
||||
|
||||
def get_api_info(self) -> Dict[str, Any]:
|
||||
"""Get API information and available endpoints"""
|
||||
logger.debug("Fetching API information...")
|
||||
response = self.session.get(f"{self.base_url}/")
|
||||
response.raise_for_status()
|
||||
logger.info("API information retrieved")
|
||||
return response.json()
|
||||
|
||||
def roll_dice(self) -> Dict[str, Any]:
|
||||
"""Roll dice and get results"""
|
||||
logger.debug("Rolling dice...")
|
||||
response = self.session.get(f"{self.base_url}/api/dice/roll")
|
||||
response.raise_for_status()
|
||||
result = response.json()
|
||||
total_rolls = result.get('total', 0)
|
||||
logger.info(f"Dice rolled: {total_rolls} total rolls")
|
||||
return result
|
||||
|
||||
def create_fibonacci_task(self, n: int) -> Dict[str, Any]:
|
||||
"""
|
||||
Create a Celery task to calculate Fibonacci number
|
||||
|
||||
Args:
|
||||
n: Number to calculate (0-40)
|
||||
|
||||
Returns:
|
||||
Dict containing task_id and status
|
||||
"""
|
||||
logger.debug(f"Creating Fibonacci task: n={n}")
|
||||
response = self.session.post(f"{self.base_url}/api/tasks/fibonacci?n={n}")
|
||||
response.raise_for_status()
|
||||
result = response.json()
|
||||
logger.info(f"Fibonacci task created: task_id={result['task_id']}")
|
||||
return result
|
||||
|
||||
def get_task_result(self, task_id: str) -> Dict[str, Any]:
|
||||
"""
|
||||
Get the result of a Celery task
|
||||
|
||||
Args:
|
||||
task_id: Task ID returned from create_fibonacci_task
|
||||
|
||||
Returns:
|
||||
Dict containing task status and result (if completed)
|
||||
"""
|
||||
logger.debug(f"Checking task status: task_id={task_id}")
|
||||
response = self.session.get(f"{self.base_url}/api/tasks/{task_id}")
|
||||
response.raise_for_status()
|
||||
result = response.json()
|
||||
status = result.get('status')
|
||||
logger.debug(f"Task status: {status}")
|
||||
return result
|
||||
|
||||
def wait_for_task(self, task_id: str, timeout: int = 30, poll_interval: float = 1.0) -> Dict[str, Any]:
|
||||
"""
|
||||
Wait for a task to complete with timeout
|
||||
|
||||
Args:
|
||||
task_id: Task ID to wait for
|
||||
timeout: Maximum seconds to wait
|
||||
poll_interval: Seconds between status checks
|
||||
|
||||
Returns:
|
||||
Final task result
|
||||
|
||||
Raises:
|
||||
TimeoutError: If task doesn't complete within timeout
|
||||
"""
|
||||
logger.info(f"Waiting for task completion: task_id={task_id}, timeout={timeout}s")
|
||||
start_time = time.time()
|
||||
checks = 0
|
||||
|
||||
while time.time() - start_time < timeout:
|
||||
checks += 1
|
||||
result = self.get_task_result(task_id)
|
||||
|
||||
if result.get("status") == "completed":
|
||||
elapsed = time.time() - start_time
|
||||
logger.info(f"Task completed after {elapsed:.2f}s ({checks} checks)")
|
||||
return result
|
||||
|
||||
time.sleep(poll_interval)
|
||||
|
||||
logger.error(f"Task timeout after {timeout}s")
|
||||
raise TimeoutError(f"Task {task_id} did not complete within {timeout} seconds")
|
||||
|
||||
def set_cache(self, key: str, value: str, ttl: int = 300) -> Dict[str, Any]:
|
||||
"""
|
||||
Set a value in Redis cache
|
||||
|
||||
Args:
|
||||
key: Cache key
|
||||
value: Value to store
|
||||
ttl: Time to live in seconds (default 300)
|
||||
|
||||
Returns:
|
||||
Dict containing success message
|
||||
"""
|
||||
logger.debug(f"Setting cache: key={key}, ttl={ttl}s")
|
||||
response = self.session.post(
|
||||
f"{self.base_url}/api/cache/set",
|
||||
params={"key": key, "value": value, "ttl": ttl}
|
||||
)
|
||||
response.raise_for_status()
|
||||
logger.info(f"Cache set: key={key}")
|
||||
return response.json()
|
||||
|
||||
def get_cache(self, key: str) -> Optional[Dict[str, Any]]:
|
||||
"""
|
||||
Get a value from Redis cache
|
||||
|
||||
Args:
|
||||
key: Cache key
|
||||
|
||||
Returns:
|
||||
Dict containing key and value, or None if not found
|
||||
"""
|
||||
logger.debug(f"Getting cache: key={key}")
|
||||
try:
|
||||
response = self.session.get(f"{self.base_url}/api/cache/{key}")
|
||||
response.raise_for_status()
|
||||
logger.info(f"Cache hit: key={key}")
|
||||
return response.json()
|
||||
except requests.exceptions.HTTPError as e:
|
||||
if e.response.status_code == 404:
|
||||
logger.warning(f"Cache miss: key={key}")
|
||||
return None
|
||||
raise
|
||||
|
||||
def process_data(self, data: Dict[str, Any]) -> Dict[str, Any]:
|
||||
"""
|
||||
Process data with Redis caching and Celery
|
||||
|
||||
Args:
|
||||
data: Dictionary of data to process
|
||||
|
||||
Returns:
|
||||
Dict with source (cache/celery_task) and result or task_id
|
||||
"""
|
||||
logger.debug(f"Processing data: {len(data)} keys")
|
||||
response = self.session.post(
|
||||
f"{self.base_url}/api/process",
|
||||
json=data
|
||||
)
|
||||
response.raise_for_status()
|
||||
result = response.json()
|
||||
source = result.get('source')
|
||||
logger.info(f"Data processing initiated: source={source}")
|
||||
return result
|
||||
|
||||
|
||||
def demo_basic_endpoints():
|
||||
"""Demonstrate basic API endpoints"""
|
||||
print("=" * 60)
|
||||
print("DEMO: Basic Endpoints")
|
||||
print("=" * 60)
|
||||
|
||||
client = DevServerClient()
|
||||
|
||||
# 1. Get API info
|
||||
print("\n1. Getting API information...")
|
||||
info = client.get_api_info()
|
||||
print(f" API: {info['message']}")
|
||||
print(f" Available endpoints: {len(info['endpoints'])}")
|
||||
|
||||
# 2. Roll dice
|
||||
print("\n2. Rolling dice...")
|
||||
result = client.roll_dice()
|
||||
print(f" Dice rolls: {result['dice_rolls']}")
|
||||
print(f" Total rolls: {sum(len(rolls) for rolls in result['dice_rolls'])}")
|
||||
|
||||
|
||||
def demo_celery_tasks():
|
||||
"""Demonstrate Celery task functionality"""
|
||||
print("\n" + "=" * 60)
|
||||
print("DEMO: Celery Tasks (Fibonacci)")
|
||||
print("=" * 60)
|
||||
|
||||
client = DevServerClient()
|
||||
|
||||
# Calculate multiple Fibonacci numbers
|
||||
fibonacci_numbers = [5, 10, 15, 20]
|
||||
|
||||
print("\n1. Submitting Fibonacci tasks...")
|
||||
tasks = []
|
||||
for n in fibonacci_numbers:
|
||||
result = client.create_fibonacci_task(n)
|
||||
tasks.append((n, result['task_id']))
|
||||
print(f" Fibonacci({n}): Task ID = {result['task_id']}")
|
||||
|
||||
print("\n2. Waiting for tasks to complete...")
|
||||
for n, task_id in tasks:
|
||||
try:
|
||||
result = client.wait_for_task(task_id, timeout=30)
|
||||
fib_result = result['result']
|
||||
print(f" Fibonacci({n}) = {fib_result['fibonacci']}")
|
||||
except TimeoutError as e:
|
||||
print(f" ERROR: {e}")
|
||||
|
||||
|
||||
def demo_redis_cache():
|
||||
"""Demonstrate Redis caching functionality"""
|
||||
print("\n" + "=" * 60)
|
||||
print("DEMO: Redis Cache Operations")
|
||||
print("=" * 60)
|
||||
|
||||
client = DevServerClient()
|
||||
|
||||
# 1. Set cache values
|
||||
print("\n1. Setting cache values...")
|
||||
cache_data = [
|
||||
("user:1", "Alice", 60),
|
||||
("user:2", "Bob", 60),
|
||||
("config:theme", "dark", 300),
|
||||
("session:abc123", "active", 3600),
|
||||
]
|
||||
|
||||
for key, value, ttl in cache_data:
|
||||
result = client.set_cache(key, value, ttl)
|
||||
print(f" Set {key} = {value} (TTL: {ttl}s)")
|
||||
|
||||
# 2. Get cache values
|
||||
print("\n2. Getting cache values...")
|
||||
for key, expected_value, _ in cache_data:
|
||||
result = client.get_cache(key)
|
||||
if result:
|
||||
print(f" Get {key} = {result['value']}")
|
||||
else:
|
||||
print(f" Get {key} = NOT FOUND")
|
||||
|
||||
# 3. Try to get non-existent key
|
||||
print("\n3. Getting non-existent key...")
|
||||
result = client.get_cache("nonexistent:key")
|
||||
print(f" Result: {result}")
|
||||
|
||||
|
||||
def demo_combined_workflow():
|
||||
"""Demonstrate combined Redis + Celery workflow"""
|
||||
print("\n" + "=" * 60)
|
||||
print("DEMO: Combined Redis + Celery Workflow")
|
||||
print("=" * 60)
|
||||
|
||||
client = DevServerClient()
|
||||
|
||||
test_data = {
|
||||
"name": "test_user",
|
||||
"email": "test@example.com",
|
||||
"age": 25,
|
||||
"interests": ["coding", "music", "sports"]
|
||||
}
|
||||
|
||||
# 1. First request - should process with Celery
|
||||
print("\n1. First request (cache miss - will process with Celery)...")
|
||||
result1 = client.process_data(test_data)
|
||||
print(f" Source: {result1['source']}")
|
||||
|
||||
if result1['source'] == 'celery_task':
|
||||
task_id = result1['task_id']
|
||||
print(f" Task ID: {task_id}")
|
||||
print(" Waiting for task to complete...")
|
||||
|
||||
task_result = client.wait_for_task(task_id, timeout=30)
|
||||
print(f" Result: {json.dumps(task_result['result'], indent=2)}")
|
||||
|
||||
# 2. Second request with same data - should return from cache
|
||||
print("\n2. Second request (cache hit - should be instant)...")
|
||||
time.sleep(2) # Wait a bit for cache to be set
|
||||
result2 = client.process_data(test_data)
|
||||
print(f" Source: {result2['source']}")
|
||||
|
||||
if result2['source'] == 'cache':
|
||||
print(f" Cached Result: {json.dumps(result2['result'], indent=2)}")
|
||||
print(" Cache working correctly!")
|
||||
|
||||
|
||||
def demo_performance_comparison():
|
||||
"""Compare performance with and without caching"""
|
||||
print("\n" + "=" * 60)
|
||||
print("DEMO: Performance Comparison (Cache vs No Cache)")
|
||||
print("=" * 60)
|
||||
|
||||
client = DevServerClient()
|
||||
|
||||
# Test data
|
||||
test_data = {
|
||||
"operation": "performance_test",
|
||||
"data_size": "medium",
|
||||
"timestamp": time.time()
|
||||
}
|
||||
|
||||
# First request (no cache)
|
||||
print("\n1. First request (processing with Celery)...")
|
||||
start_time = time.time()
|
||||
result1 = client.process_data(test_data)
|
||||
first_duration = 0.0
|
||||
|
||||
if result1['source'] == 'celery_task':
|
||||
task_result = client.wait_for_task(result1['task_id'])
|
||||
first_duration = time.time() - start_time
|
||||
print(f" Duration: {first_duration:.2f} seconds")
|
||||
else:
|
||||
print(" Unexpected: got cached result on first try")
|
||||
return
|
||||
|
||||
# Second request (with cache)
|
||||
print("\n2. Second request (from cache)...")
|
||||
start_time = time.time()
|
||||
result2 = client.process_data(test_data)
|
||||
second_duration = time.time() - start_time
|
||||
print(f" Duration: {second_duration:.2f} seconds")
|
||||
|
||||
if first_duration > 0:
|
||||
speedup = first_duration / second_duration if second_duration > 0 else 0
|
||||
print(f"\n Cache Speedup: {speedup:.1f}x faster!")
|
||||
|
||||
|
||||
def run_simple_demo():
|
||||
"""Run a simple demo of the main features"""
|
||||
print("\n" + "=" * 60)
|
||||
print("DevServer API - Simple Demo")
|
||||
print("=" * 60)
|
||||
print("\nTesting: FastAPI + Redis + Celery + OpenTelemetry")
|
||||
print("View traces at: http://localhost:16686")
|
||||
print("=" * 60)
|
||||
|
||||
start_time = time.time()
|
||||
|
||||
try:
|
||||
logger.info("Starting DevServer demo...")
|
||||
client = DevServerClient()
|
||||
|
||||
# 1. Test basic endpoint
|
||||
print("\n1. Testing dice roll endpoint...")
|
||||
logger.info("TEST 1: Dice roll")
|
||||
result = client.roll_dice()
|
||||
print(f" Dice rolls: {result['dice_rolls']}")
|
||||
logger.info(f"Result: {sum(len(r) for r in result['dice_rolls'])} dice rolled")
|
||||
|
||||
# 2. Test Redis cache
|
||||
print("\n2. Testing Redis cache...")
|
||||
logger.info("TEST 2: Redis caching")
|
||||
test_key = f"test_key_{int(time.time())}"
|
||||
test_value = f"test_value_{datetime.now().isoformat()}"
|
||||
|
||||
client.set_cache(test_key, test_value, 60)
|
||||
cached = client.get_cache(test_key)
|
||||
if cached:
|
||||
print(f" Cached value: {cached['value']}")
|
||||
logger.info(f"Cache verified: key={test_key}")
|
||||
else:
|
||||
print(" Cache not found")
|
||||
logger.warning("Cache verification failed")
|
||||
|
||||
# 3. Test Celery task
|
||||
print("\n3. Testing Celery task (Fibonacci)...")
|
||||
logger.info("TEST 3: Celery task")
|
||||
task = client.create_fibonacci_task(10)
|
||||
print(f" Task submitted: {task['task_id']}")
|
||||
logger.info(f"Fibonacci task submitted: task_id={task['task_id']}")
|
||||
|
||||
result = client.wait_for_task(task['task_id'], timeout=30)
|
||||
fib_value = result['result']['fibonacci']
|
||||
calc_time = result['result'].get('calculation_time', 'N/A')
|
||||
print(f" Fibonacci(10) = {fib_value} (calculated in {calc_time})")
|
||||
logger.info(f"Fibonacci result: {fib_value}")
|
||||
|
||||
elapsed = time.time() - start_time
|
||||
|
||||
print("\n" + "=" * 60)
|
||||
print(f"All tests passed in {elapsed:.2f}s!")
|
||||
print("Check Jaeger UI at: http://localhost:16686")
|
||||
print("=" * 60)
|
||||
|
||||
logger.info(f"Demo completed successfully in {elapsed:.2f}s")
|
||||
|
||||
except requests.exceptions.ConnectionError:
|
||||
print("\nERROR: Cannot connect to DevServer")
|
||||
print(" Run: docker-compose up -d")
|
||||
logger.error("Connection error: DevServer not reachable")
|
||||
except Exception as e:
|
||||
print(f"\nERROR: {e}")
|
||||
logger.error(f"Demo failed: {e}", exc_info=True)
|
||||
import traceback
|
||||
traceback.print_exc()
|
||||
|
||||
|
||||
# Uncomment to run all detailed demos
|
||||
# def run_all_demos():
|
||||
# """Run all demonstration scenarios"""
|
||||
# demo_basic_endpoints()
|
||||
# time.sleep(1)
|
||||
# demo_redis_cache()
|
||||
# time.sleep(1)
|
||||
# demo_celery_tasks()
|
||||
# time.sleep(1)
|
||||
# demo_combined_workflow()
|
||||
# time.sleep(1)
|
||||
# demo_performance_comparison()
|
||||
|
||||
|
||||
if __name__ == "__main__":
|
||||
run_simple_demo()
|
||||
|
||||
# Uncomment to run all detailed demos:
|
||||
# run_all_demos()
|
||||
205
app/logging.py
Normal file
205
app/logging.py
Normal file
@@ -0,0 +1,205 @@
|
||||
import logging
|
||||
import sys
|
||||
from enum import StrEnum
|
||||
from pathlib import Path
|
||||
from logging.handlers import RotatingFileHandler, TimedRotatingFileHandler
|
||||
from datetime import datetime
|
||||
import json
|
||||
|
||||
|
||||
class LogLevel(StrEnum):
|
||||
DEBUG = "DEBUG"
|
||||
INFO = "INFO"
|
||||
WARNING = "WARNING"
|
||||
ERROR = "ERROR"
|
||||
CRITICAL = "CRITICAL"
|
||||
|
||||
|
||||
class CustomFormatter(logging.Formatter):
|
||||
"""Custom formatter with colors and detailed information"""
|
||||
|
||||
# ANSI color codes
|
||||
COLORS = {
|
||||
'DEBUG': '\033[36m', # Cyan
|
||||
'INFO': '\033[32m', # Green
|
||||
'WARNING': '\033[33m', # Yellow
|
||||
'ERROR': '\033[31m', # Red
|
||||
'CRITICAL': '\033[35m', # Magenta
|
||||
'RESET': '\033[0m' # Reset
|
||||
}
|
||||
|
||||
def format(self, record):
|
||||
# Add color to level name
|
||||
if hasattr(sys.stdout, 'isatty') and sys.stdout.isatty():
|
||||
levelname = record.levelname
|
||||
if levelname in self.COLORS:
|
||||
record.levelname = f"{self.COLORS[levelname]}{levelname}{self.COLORS['RESET']}"
|
||||
|
||||
# Add extra context
|
||||
record.service = getattr(record, 'service', 'unknown')
|
||||
record.trace_id = getattr(record, 'trace_id', 'N/A')
|
||||
record.span_id = getattr(record, 'span_id', 'N/A')
|
||||
|
||||
return super().format(record)
|
||||
|
||||
|
||||
class JSONFormatter(logging.Formatter):
|
||||
"""JSON formatter for structured logging"""
|
||||
|
||||
def format(self, record):
|
||||
log_data = {
|
||||
'timestamp': datetime.utcnow().isoformat(),
|
||||
'level': record.levelname,
|
||||
'logger': record.name,
|
||||
'message': record.getMessage(),
|
||||
'module': record.module,
|
||||
'function': record.funcName,
|
||||
'line': record.lineno,
|
||||
'process': record.process,
|
||||
'thread': record.thread,
|
||||
'service': getattr(record, 'service', 'unknown'),
|
||||
'trace_id': getattr(record, 'trace_id', None),
|
||||
'span_id': getattr(record, 'span_id', None),
|
||||
}
|
||||
|
||||
# Add exception info if present
|
||||
if record.exc_info:
|
||||
log_data['exception'] = self.formatException(record.exc_info)
|
||||
|
||||
# Add extra fields
|
||||
if hasattr(record, 'extra_data'):
|
||||
log_data['extra'] = record.extra_data # type: ignore
|
||||
|
||||
return json.dumps(log_data)
|
||||
|
||||
|
||||
def setup_logging(
|
||||
service_name: str = "devserver",
|
||||
log_level: str = "INFO",
|
||||
log_dir: str = "logs",
|
||||
enable_console: bool = True,
|
||||
enable_file: bool = True,
|
||||
enable_json: bool = True
|
||||
) -> logging.Logger:
|
||||
"""
|
||||
Setup comprehensive logging configuration
|
||||
|
||||
Args:
|
||||
service_name: Name of the service for logging context
|
||||
log_level: Logging level (DEBUG, INFO, WARNING, ERROR, CRITICAL)
|
||||
log_dir: Directory to store log files
|
||||
enable_console: Enable console output
|
||||
enable_file: Enable file output
|
||||
enable_json: Enable JSON structured logging
|
||||
|
||||
Returns:
|
||||
Configured logger instance
|
||||
"""
|
||||
# Create logs directory
|
||||
log_path = Path(log_dir)
|
||||
log_path.mkdir(exist_ok=True)
|
||||
|
||||
# Get root logger
|
||||
logger = logging.getLogger(service_name)
|
||||
logger.setLevel(getattr(logging, log_level.upper()))
|
||||
logger.handlers.clear()
|
||||
|
||||
# Console Handler with colors
|
||||
if enable_console:
|
||||
console_handler = logging.StreamHandler(sys.stdout)
|
||||
console_handler.setLevel(logging.DEBUG)
|
||||
console_format = CustomFormatter(
|
||||
fmt='%(asctime)s | %(levelname)-8s | %(service)-12s | %(name)-20s | %(funcName)-25s:%(lineno)-4d | %(message)s',
|
||||
datefmt='%Y-%m-%d %H:%M:%S'
|
||||
)
|
||||
console_handler.setFormatter(console_format)
|
||||
logger.addHandler(console_handler)
|
||||
|
||||
# File Handler (Rotating) - Text format
|
||||
if enable_file:
|
||||
file_handler = RotatingFileHandler(
|
||||
filename=log_path / f"{service_name}.log",
|
||||
maxBytes=10 * 1024 * 1024, # 10MB
|
||||
backupCount=5,
|
||||
encoding='utf-8'
|
||||
)
|
||||
file_handler.setLevel(logging.DEBUG)
|
||||
file_format = logging.Formatter(
|
||||
fmt='%(asctime)s | %(levelname)-8s | %(service)-12s | %(name)-20s | %(module)-15s | %(funcName)-25s:%(lineno)-4d | TraceID:%(trace_id)s | %(message)s',
|
||||
datefmt='%Y-%m-%d %H:%M:%S'
|
||||
)
|
||||
file_handler.setFormatter(file_format)
|
||||
logger.addHandler(file_handler)
|
||||
|
||||
# JSON File Handler (Daily rotation) - Structured logging
|
||||
if enable_json:
|
||||
json_handler = TimedRotatingFileHandler(
|
||||
filename=log_path / f"{service_name}_json.log",
|
||||
when='midnight',
|
||||
interval=1,
|
||||
backupCount=30,
|
||||
encoding='utf-8'
|
||||
)
|
||||
json_handler.setLevel(logging.INFO)
|
||||
json_handler.setFormatter(JSONFormatter())
|
||||
logger.addHandler(json_handler)
|
||||
|
||||
# Error Handler (Separate file for errors)
|
||||
error_handler = RotatingFileHandler(
|
||||
filename=log_path / f"{service_name}_errors.log",
|
||||
maxBytes=5 * 1024 * 1024, # 5MB
|
||||
backupCount=5,
|
||||
encoding='utf-8'
|
||||
)
|
||||
error_handler.setLevel(logging.ERROR)
|
||||
error_format = logging.Formatter(
|
||||
fmt='%(asctime)s | %(levelname)-8s | %(service)-12s | %(name)-20s | %(module)-15s | %(funcName)-25s:%(lineno)-4d | TraceID:%(trace_id)s\nMessage: %(message)s\n%(pathname)s\n',
|
||||
datefmt='%Y-%m-%d %H:%M:%S'
|
||||
)
|
||||
error_handler.setFormatter(error_format)
|
||||
logger.addHandler(error_handler)
|
||||
|
||||
# Set default service name
|
||||
old_factory = logging.getLogRecordFactory()
|
||||
|
||||
def record_factory(*args, **kwargs):
|
||||
record = old_factory(*args, **kwargs)
|
||||
record.service = service_name
|
||||
record.trace_id = 'N/A'
|
||||
record.span_id = 'N/A'
|
||||
return record
|
||||
|
||||
logging.setLogRecordFactory(record_factory)
|
||||
|
||||
logger.info(f"Logging initialized for service: {service_name}")
|
||||
logger.info(f"Log level: {log_level}")
|
||||
logger.info(f"Log directory: {log_path.absolute()}")
|
||||
|
||||
return logger
|
||||
|
||||
|
||||
def get_logger(name: str) -> logging.Logger:
|
||||
"""Get a logger instance with the specified name"""
|
||||
return logging.getLogger(name)
|
||||
|
||||
|
||||
def log_with_trace(logger: logging.Logger, level: str, message: str, trace_id: str | None = None, span_id: str | None = None, **kwargs):
|
||||
"""
|
||||
Log a message with OpenTelemetry trace context
|
||||
|
||||
Args:
|
||||
logger: Logger instance
|
||||
level: Log level (debug, info, warning, error, critical)
|
||||
message: Log message
|
||||
trace_id: OpenTelemetry trace ID
|
||||
span_id: OpenTelemetry span ID
|
||||
**kwargs: Additional context data
|
||||
"""
|
||||
extra = {
|
||||
'trace_id': trace_id or 'N/A',
|
||||
'span_id': span_id or 'N/A',
|
||||
'extra_data': kwargs
|
||||
}
|
||||
|
||||
log_func = getattr(logger, level.lower())
|
||||
log_func(message, extra=extra)
|
||||
723
app/main.py
Normal file
723
app/main.py
Normal file
@@ -0,0 +1,723 @@
|
||||
from fastapi import FastAPI, HTTPException, Request, Path
|
||||
from random import randint
|
||||
import copy
|
||||
import json
|
||||
import redis
|
||||
from celery.result import AsyncResult
|
||||
from opentelemetry import trace
|
||||
from app.logging import setup_logging, get_logger, log_with_trace
|
||||
from prometheus_fastapi_instrumentator import Instrumentator
|
||||
import time
|
||||
|
||||
# Setup logging
|
||||
logger = setup_logging(service_name="devserver.api.fastapi", log_level="DEBUG")
|
||||
|
||||
tracer = trace.get_tracer("devserver.api.tracer")
|
||||
|
||||
# Initialize Redis client
|
||||
logger.info("Initializing Redis connection...")
|
||||
try:
|
||||
redis_client = redis.Redis(host='redis', port=6379, db=0, decode_responses=True)
|
||||
redis_client.ping()
|
||||
logger.info("Redis connection established successfully")
|
||||
except Exception as e:
|
||||
logger.error(f"Failed to connect to Redis: {e}", exc_info=True)
|
||||
raise
|
||||
|
||||
app = FastAPI(
|
||||
title="DevServer API",
|
||||
version="1.0.0",
|
||||
description="FastAPI with OpenTelemetry, Redis, and Celery"
|
||||
)
|
||||
|
||||
# ============================================================================
|
||||
# INITIALIZE OPENTELEMETRY - Explicit Instrumentation
|
||||
# ============================================================================
|
||||
# Import and apply OpenTelemetry instrumentation BEFORE any requests
|
||||
from app.opentelemetry_config import instrument_fastapi_app
|
||||
|
||||
logger.info("=" * 80)
|
||||
logger.info("🔧 Applying OpenTelemetry Instrumentation...")
|
||||
logger.info("=" * 80)
|
||||
|
||||
try:
|
||||
instrument_fastapi_app(app)
|
||||
logger.info("=" * 80)
|
||||
logger.info("✅ OpenTelemetry instrumentation applied successfully!")
|
||||
logger.info("=" * 80)
|
||||
except Exception as e:
|
||||
logger.error("=" * 80)
|
||||
logger.error(f"❌ Failed to apply OpenTelemetry instrumentation: {e}")
|
||||
logger.error("⚠️ Traces will NOT be generated!")
|
||||
logger.error("=" * 80)
|
||||
# ============================================================================
|
||||
|
||||
# Initialize Prometheus metrics
|
||||
instrumentator = Instrumentator(
|
||||
should_group_status_codes=False,
|
||||
should_ignore_untemplated=True,
|
||||
should_respect_env_var=False,
|
||||
should_instrument_requests_inprogress=True,
|
||||
excluded_handlers=[".*admin.*", "/metrics"],
|
||||
env_var_name="ENABLE_METRICS",
|
||||
inprogress_name="http_requests_inprogress",
|
||||
inprogress_labels=True,
|
||||
)
|
||||
instrumentator.instrument(app).expose(app, endpoint="/metrics")
|
||||
|
||||
dice_rolls = [[], [], []]
|
||||
|
||||
|
||||
# Middleware to log all requests
|
||||
@app.middleware("http")
|
||||
async def log_requests(request: Request, call_next):
|
||||
"""Log all incoming requests with trace context"""
|
||||
start_time = time.time()
|
||||
|
||||
# Get trace context
|
||||
span = trace.get_current_span()
|
||||
span_context = span.get_span_context()
|
||||
trace_id = format(span_context.trace_id, '032x') if span_context.trace_id else 'N/A'
|
||||
|
||||
logger.info(f"→ Incoming request: {request.method} {request.url.path}")
|
||||
logger.debug(f" TraceID: {trace_id}")
|
||||
logger.debug(f" Client: {request.client.host if request.client else 'unknown'}")
|
||||
|
||||
response = await call_next(request)
|
||||
|
||||
duration = time.time() - start_time
|
||||
logger.info(f"← Response: {response.status_code} | Duration: {duration:.3f}s | {request.method} {request.url.path}")
|
||||
|
||||
return response
|
||||
|
||||
|
||||
@app.on_event("startup")
|
||||
async def startup_event():
|
||||
"""Log application startup"""
|
||||
logger.info("=" * 60)
|
||||
logger.info("DevServer FastAPI Application Starting...")
|
||||
logger.info("=" * 60)
|
||||
logger.info("Service: devserver.api.fastapi")
|
||||
logger.info("OpenTelemetry tracing: ENABLED")
|
||||
logger.info("Redis caching: ENABLED")
|
||||
logger.info("Celery tasks: ENABLED")
|
||||
logger.info("API Base URL: http://localhost:8000")
|
||||
logger.info("=" * 60)
|
||||
|
||||
|
||||
@app.on_event("shutdown")
|
||||
async def shutdown_event():
|
||||
"""Log application shutdown"""
|
||||
logger.info("=" * 60)
|
||||
logger.info("DevServer FastAPI Application Shutting Down...")
|
||||
logger.info("=" * 60)
|
||||
|
||||
|
||||
@app.get("/", tags=["Info"])
|
||||
async def root():
|
||||
"""Root endpoint with basic info."""
|
||||
logger.info("API information requested")
|
||||
return {
|
||||
"service": "devserver.api.fastapi",
|
||||
"message": "DevServer API with OpenTelemetry, Redis, and Celery",
|
||||
"version": "1.0.0",
|
||||
"endpoints": {
|
||||
"info": {
|
||||
"GET /": "API information",
|
||||
"GET /health": "Health check",
|
||||
"GET /docs": "Interactive API documentation (Swagger UI)"
|
||||
},
|
||||
"dice_game": {
|
||||
"GET /api/dice/roll?session_id=xxx&use_cache=true": "Roll dice with Redis caching and session tracking",
|
||||
"Description": "Returns 15 dice rolls with statistics. Use session_id for unique sessions, use_cache to enable/disable caching (5min TTL)"
|
||||
},
|
||||
"celery_tasks": {
|
||||
"POST /api/tasks/fibonacci?n={number}&use_cache=true": "Calculate Fibonacci with Redis caching",
|
||||
"GET /api/tasks/{task_id}": "Get task result by ID",
|
||||
"Description": "Fibonacci results are cached for 1 hour. Set use_cache=false to force recalculation"
|
||||
},
|
||||
"redis_cache": {
|
||||
"POST /api/cache/set": "Set cache value",
|
||||
"GET /api/cache/{key}": "Get cache value",
|
||||
"DELETE /api/cache/{key}": "Delete cache entry",
|
||||
"GET /api/cache/keys?pattern=*": "List all cache keys",
|
||||
"GET /api/cache/stats": "Get Redis statistics",
|
||||
"POST /api/cache/flush": "Clear all cache (danger)",
|
||||
"POST /api/cache/batch-set": "Set multiple cache values",
|
||||
"GET /api/cache/batch-get?keys=k1,k2": "Get multiple cache values"
|
||||
},
|
||||
"data_processing": {
|
||||
"POST /api/process": "Process data with cache + Celery workflow"
|
||||
}
|
||||
},
|
||||
"monitoring": {
|
||||
"jaeger_ui": "http://localhost:16686",
|
||||
"rabbitmq_ui": "http://localhost:15672"
|
||||
}
|
||||
}
|
||||
|
||||
|
||||
@app.get("/health", tags=["Info"])
|
||||
async def health_check():
|
||||
"""Health check endpoint"""
|
||||
with tracer.start_as_current_span("health_check") as span:
|
||||
span.set_attribute("service.name", "devserver.api.fastapi")
|
||||
|
||||
# Check Redis
|
||||
try:
|
||||
redis_client.ping()
|
||||
redis_status = "healthy"
|
||||
except Exception as e:
|
||||
redis_status = f"unhealthy: {e}"
|
||||
logger.error(f"Redis health check failed: {e}")
|
||||
|
||||
logger.debug("Health check performed")
|
||||
|
||||
return {
|
||||
"status": "healthy",
|
||||
"service": "devserver.api.fastapi",
|
||||
"redis": redis_status
|
||||
}
|
||||
|
||||
|
||||
@app.get("/api/dice/roll", tags=["Dice Game"])
|
||||
async def roll_dice(session_id: str = "default", use_cache: bool = True):
|
||||
"""Roll dice 15 times with distributed tracing and Redis caching.
|
||||
|
||||
Args:
|
||||
session_id: Unique session identifier for caching results
|
||||
use_cache: If True, check cache first and store results
|
||||
"""
|
||||
with tracer.start_as_current_span("api.dice.roll") as span:
|
||||
span.set_attribute("service.name", "devserver.api.fastapi")
|
||||
span.set_attribute("operation", "dice_roll")
|
||||
span.set_attribute("session_id", session_id)
|
||||
span.set_attribute("use_cache", use_cache)
|
||||
|
||||
cache_key = f"dice:session:{session_id}"
|
||||
logger.info(f"Received dice roll request: session_id={session_id}, use_cache={use_cache}")
|
||||
|
||||
# Check cache first if enabled
|
||||
if use_cache:
|
||||
try:
|
||||
cached_result = redis_client.get(cache_key)
|
||||
if cached_result:
|
||||
span.set_attribute("cache.hit", True)
|
||||
logger.info(f"Cache hit! Returning cached dice rolls for session: {session_id}")
|
||||
result = json.loads(str(cached_result))
|
||||
result["source"] = "cache"
|
||||
result["cache_key"] = cache_key
|
||||
return result
|
||||
except Exception as e:
|
||||
logger.warning(f"Cache check failed: {e}")
|
||||
|
||||
span.set_attribute("cache.hit", False)
|
||||
logger.info("Cache miss - rolling new dice")
|
||||
|
||||
count = 0
|
||||
# Roll a dice 15 times and store the results in three separate lists
|
||||
while count < 15:
|
||||
if count < 5:
|
||||
dice_rolls[0].append(roll()) # Append to the first list
|
||||
elif count < 10:
|
||||
dice_rolls[1].append(roll()) # Append to the second list
|
||||
else:
|
||||
dice_rolls[2].append(roll()) # Append to the third list
|
||||
count += 1
|
||||
|
||||
# Store the results to return
|
||||
results = copy.deepcopy(dice_rolls)
|
||||
|
||||
total_rolls = sum(len(r) for r in results)
|
||||
span.set_attribute("dice.total_rolls", total_rolls)
|
||||
|
||||
# Calculate statistics
|
||||
flat_results = [roll for sublist in results for roll in sublist]
|
||||
avg_roll = sum(flat_results) / len(flat_results)
|
||||
|
||||
logger.info(f"Dice rolled successfully: {total_rolls} total rolls, avg={avg_roll:.2f}")
|
||||
logger.debug(f"Roll results: {results}")
|
||||
|
||||
# Clear the original lists for the next request
|
||||
dice_rolls[0] = []
|
||||
dice_rolls[1] = []
|
||||
dice_rolls[2] = []
|
||||
|
||||
response = {
|
||||
"service": "devserver.api.fastapi",
|
||||
"operation": "dice_roll",
|
||||
"session_id": session_id,
|
||||
"dice_rolls": results,
|
||||
"total": total_rolls,
|
||||
"statistics": {
|
||||
"average": round(avg_roll, 2),
|
||||
"min": min(flat_results),
|
||||
"max": max(flat_results),
|
||||
"sum": sum(flat_results)
|
||||
},
|
||||
"source": "fresh",
|
||||
"cache_key": cache_key
|
||||
}
|
||||
|
||||
# Store in cache if enabled (TTL: 5 minutes)
|
||||
if use_cache:
|
||||
try:
|
||||
redis_client.setex(cache_key, 300, json.dumps(response))
|
||||
span.set_attribute("cache.stored", True)
|
||||
logger.info(f"Stored dice rolls in cache: {cache_key} (TTL: 300s)")
|
||||
except Exception as e:
|
||||
logger.error(f"Failed to store in cache: {e}")
|
||||
|
||||
return response
|
||||
|
||||
|
||||
def roll():
|
||||
"""Simulates rolling a six-sided dice with tracing."""
|
||||
with tracer.start_as_current_span("dice.single_roll") as roll_span:
|
||||
result = randint(1, 6)
|
||||
roll_span.set_attribute("dice.value", result)
|
||||
roll_span.set_attribute("service.name", "devserver.api.fastapi")
|
||||
logger.debug(f"Single dice roll: {result}")
|
||||
return result
|
||||
|
||||
|
||||
@app.post("/api/tasks/fibonacci", tags=["Celery Tasks"])
|
||||
async def create_fibonacci_task(n: int, use_cache: bool = True):
|
||||
"""Create a Celery task to calculate Fibonacci number with Redis caching.
|
||||
|
||||
Args:
|
||||
n: The Fibonacci number to calculate (0-40)
|
||||
use_cache: If True, check cache before creating task
|
||||
"""
|
||||
with tracer.start_as_current_span("api.tasks.fibonacci.create") as span:
|
||||
span.set_attribute("service.name", "devserver.api.fastapi")
|
||||
span.set_attribute("operation", "create_task")
|
||||
span.set_attribute("task.type", "fibonacci")
|
||||
span.set_attribute("fibonacci.n", n)
|
||||
span.set_attribute("use_cache", use_cache)
|
||||
|
||||
logger.info(f"Creating Fibonacci task for n={n}, use_cache={use_cache}")
|
||||
|
||||
if n < 0 or n > 40:
|
||||
logger.warning(f"Invalid Fibonacci number requested: n={n}")
|
||||
raise HTTPException(status_code=400, detail="n must be between 0 and 40")
|
||||
|
||||
cache_key = f"fibonacci:result:{n}"
|
||||
|
||||
# Check cache first if enabled
|
||||
if use_cache:
|
||||
try:
|
||||
cached_result = redis_client.get(cache_key)
|
||||
if cached_result:
|
||||
span.set_attribute("cache.hit", True)
|
||||
span.set_attribute("result.source", "cache")
|
||||
result_value = int(str(cached_result))
|
||||
logger.info(f"Cache hit! Returning cached Fibonacci({n}) = {result_value}")
|
||||
return {
|
||||
"service": "devserver.api.fastapi",
|
||||
"operation": "fibonacci",
|
||||
"n": n,
|
||||
"result": result_value,
|
||||
"source": "cache",
|
||||
"cache_key": cache_key,
|
||||
"status": "completed"
|
||||
}
|
||||
except (ValueError, TypeError) as e:
|
||||
logger.warning(f"Cache value conversion failed: {e}")
|
||||
except Exception as e:
|
||||
logger.warning(f"Cache check failed: {e}")
|
||||
|
||||
span.set_attribute("cache.hit", False)
|
||||
logger.debug(f"Cache miss - submitting Fibonacci calculation task to Celery: n={n}")
|
||||
|
||||
from app.worker import calculate_fibonacci
|
||||
task = calculate_fibonacci.delay(n) # type: ignore
|
||||
span.set_attribute("task.id", task.id)
|
||||
span.set_attribute("task.status", "submitted")
|
||||
|
||||
logger.info(f"Fibonacci task created successfully: task_id={task.id}, n={n}")
|
||||
|
||||
return {
|
||||
"service": "devserver.api.fastapi",
|
||||
"operation": "create_fibonacci_task",
|
||||
"n": n,
|
||||
"task_id": task.id,
|
||||
"status": "submitted",
|
||||
"source": "celery_task",
|
||||
"message": f"Calculating fibonacci({n})",
|
||||
"check_result_at": f"/api/tasks/{task.id}",
|
||||
"cache_key": cache_key
|
||||
}
|
||||
|
||||
|
||||
@app.get("/api/tasks/{task_id}", tags=["Celery Tasks"])
|
||||
async def get_task_result(task_id: str):
|
||||
"""Get the result of a Celery task."""
|
||||
with tracer.start_as_current_span("api.tasks.get_result") as span:
|
||||
span.set_attribute("service.name", "devserver.api.fastapi")
|
||||
span.set_attribute("operation", "get_task_result")
|
||||
span.set_attribute("task.id", task_id)
|
||||
|
||||
logger.info(f"Checking task status: task_id={task_id}")
|
||||
from app.worker import app as celery_app
|
||||
|
||||
try:
|
||||
task_result = AsyncResult(task_id, app=celery_app)
|
||||
|
||||
if task_result.ready():
|
||||
result = task_result.result
|
||||
span.set_attribute("task.status", "completed")
|
||||
logger.info(f"Task completed: task_id={task_id}")
|
||||
logger.debug(f"Task result: {result}")
|
||||
return {
|
||||
"service": "devserver.api.fastapi",
|
||||
"operation": "get_task_result",
|
||||
"task_id": task_id,
|
||||
"status": "completed",
|
||||
"result": result
|
||||
}
|
||||
else:
|
||||
span.set_attribute("task.status", "pending")
|
||||
logger.debug(f"Task still pending: task_id={task_id}")
|
||||
return {
|
||||
"service": "devserver.api.fastapi",
|
||||
"operation": "get_task_result",
|
||||
"task_id": task_id,
|
||||
"status": "pending",
|
||||
"message": "Task is still processing"
|
||||
}
|
||||
except Exception as e:
|
||||
logger.error(f"Error retrieving task result: task_id={task_id}, error={e}", exc_info=True)
|
||||
raise HTTPException(status_code=500, detail=f"Error retrieving task: {str(e)}")
|
||||
|
||||
|
||||
@app.post("/api/cache/set", tags=["Redis Cache"])
|
||||
async def set_cache(key: str, value: str, ttl: int = 300):
|
||||
"""Set a value in Redis cache with optional TTL."""
|
||||
with tracer.start_as_current_span("api.cache.set") as span:
|
||||
span.set_attribute("service.name", "devserver.api.fastapi")
|
||||
span.set_attribute("operation", "cache_set")
|
||||
span.set_attribute("cache.key", key)
|
||||
span.set_attribute("cache.ttl", ttl)
|
||||
|
||||
logger.info(f"Setting cache: key={key}, ttl={ttl}s")
|
||||
|
||||
try:
|
||||
redis_client.setex(key, ttl, value)
|
||||
span.set_attribute("cache.operation", "success")
|
||||
logger.info(f"Cache set successfully: key={key}")
|
||||
logger.debug(f"Cache value: {value[:50]}..." if len(value) > 50 else f"Cache value: {value}")
|
||||
|
||||
return {
|
||||
"service": "devserver.api.fastapi",
|
||||
"operation": "cache_set",
|
||||
"message": "Cache set successfully",
|
||||
"key": key,
|
||||
"ttl": ttl
|
||||
}
|
||||
except Exception as e:
|
||||
span.set_attribute("cache.operation", "failed")
|
||||
logger.error(f"Failed to set cache: key={key}, error={e}", exc_info=True)
|
||||
raise HTTPException(status_code=500, detail=f"Cache error: {str(e)}")
|
||||
|
||||
|
||||
@app.get("/api/cache/batch-get", tags=["Redis Cache"])
|
||||
async def batch_get_cache(keys: str):
|
||||
"""Get multiple cache values at once (comma-separated keys)"""
|
||||
with tracer.start_as_current_span("api.cache.batch_get") as span:
|
||||
span.set_attribute("service.name", "devserver.api.fastapi")
|
||||
span.set_attribute("operation", "cache_batch_get")
|
||||
|
||||
key_list = [k.strip() for k in keys.split(',')]
|
||||
span.set_attribute("cache.batch_size", len(key_list))
|
||||
|
||||
logger.info(f"Batch getting {len(key_list)} cache entries")
|
||||
|
||||
try:
|
||||
pipeline = redis_client.pipeline()
|
||||
for key in key_list:
|
||||
pipeline.get(key)
|
||||
values = pipeline.execute()
|
||||
|
||||
result = {}
|
||||
found_count = 0
|
||||
for key, value in zip(key_list, values):
|
||||
if value is not None:
|
||||
result[key] = value
|
||||
found_count += 1
|
||||
|
||||
span.set_attribute("cache.found_count", found_count)
|
||||
span.set_attribute("cache.hit_ratio", (found_count / len(key_list) * 100) if key_list else 0)
|
||||
|
||||
logger.info(f"Batch get complete: {found_count}/{len(key_list)} found")
|
||||
|
||||
return {
|
||||
"service": "devserver.api.fastapi",
|
||||
"operation": "cache_batch_get",
|
||||
"requested": len(key_list),
|
||||
"found": found_count,
|
||||
"data": result
|
||||
}
|
||||
except Exception as e:
|
||||
logger.error(f"Failed to batch get: error={e}", exc_info=True)
|
||||
raise HTTPException(status_code=500, detail=f"Cache error: {str(e)}")
|
||||
|
||||
|
||||
|
||||
@app.post("/api/process", tags=["Data Processing"])
|
||||
async def process_data(data: dict):
|
||||
"""Process data using both Redis cache and Celery task."""
|
||||
with tracer.start_as_current_span("api.process.data") as span:
|
||||
span.set_attribute("service.name", "devserver.api.fastapi")
|
||||
span.set_attribute("operation", "process_data")
|
||||
span.set_attribute("data.keys_count", len(data))
|
||||
|
||||
logger.info(f"Processing data request received")
|
||||
logger.debug(f"Data keys: {list(data.keys())}")
|
||||
|
||||
from app.worker import process_data_with_cache
|
||||
|
||||
# Generate a cache key based on data
|
||||
cache_key = f"processed:{hash(json.dumps(data, sort_keys=True))}"
|
||||
span.set_attribute("cache.key", cache_key)
|
||||
logger.debug(f"Generated cache key: {cache_key}")
|
||||
|
||||
# Check cache first
|
||||
try:
|
||||
cached_result = redis_client.get(cache_key)
|
||||
if cached_result:
|
||||
span.set_attribute("cache.hit", True)
|
||||
span.set_attribute("result.source", "cache")
|
||||
logger.info(f"Cache hit! Returning cached result: cache_key={cache_key}")
|
||||
result = json.loads(str(cached_result))
|
||||
logger.debug(f"Cached result: {result}")
|
||||
return {
|
||||
"service": "devserver.api.fastapi",
|
||||
"operation": "process_data",
|
||||
"source": "cache",
|
||||
"result": result
|
||||
}
|
||||
except Exception as e:
|
||||
logger.warning(f"Cache check failed: {e}")
|
||||
|
||||
span.set_attribute("cache.hit", False)
|
||||
span.set_attribute("result.source", "celery_task")
|
||||
logger.info(f"Cache miss - submitting to Celery: cache_key={cache_key}")
|
||||
|
||||
# If not in cache, process with Celery
|
||||
try:
|
||||
task = process_data_with_cache.delay(data, cache_key) # type: ignore
|
||||
span.set_attribute("task.id", task.id)
|
||||
logger.info(f"Task submitted to Celery: task_id={task.id}")
|
||||
|
||||
return {
|
||||
"service": "devserver.api.fastapi",
|
||||
"operation": "process_data",
|
||||
"source": "celery_task",
|
||||
"task_id": task.id,
|
||||
"message": "Processing data, check /api/tasks/{task_id} for result"
|
||||
}
|
||||
except Exception as e:
|
||||
logger.error(f"Failed to submit task: error={e}", exc_info=True)
|
||||
raise HTTPException(status_code=500, detail=f"Task submission failed: {str(e)}")
|
||||
|
||||
|
||||
@app.get("/api/cache/keys", tags=["Redis Cache"])
|
||||
async def list_cache_keys(pattern: str = "*"):
|
||||
"""List all cache keys matching a pattern"""
|
||||
with tracer.start_as_current_span("api.cache.list_keys") as span:
|
||||
span.set_attribute("service.name", "devserver.api.fastapi")
|
||||
span.set_attribute("operation", "list_cache_keys")
|
||||
span.set_attribute("cache.pattern", pattern)
|
||||
|
||||
logger.info(f"Listing cache keys with pattern: {pattern}")
|
||||
|
||||
try:
|
||||
keys = redis_client.keys(pattern)
|
||||
key_count = len(keys) if keys else 0 # type: ignore
|
||||
span.set_attribute("cache.keys_found", key_count)
|
||||
|
||||
logger.info(f"Found {key_count} cache keys")
|
||||
|
||||
return {
|
||||
"service": "devserver.api.fastapi",
|
||||
"operation": "list_cache_keys",
|
||||
"pattern": pattern,
|
||||
"count": key_count,
|
||||
"keys": keys
|
||||
}
|
||||
except Exception as e:
|
||||
logger.error(f"Failed to list keys: error={e}", exc_info=True)
|
||||
raise HTTPException(status_code=500, detail=f"Cache error: {str(e)}")
|
||||
|
||||
|
||||
|
||||
@app.post("/api/cache/flush", tags=["Redis Cache"])
|
||||
async def flush_cache():
|
||||
"""Flush all cache entries (use with caution!)"""
|
||||
with tracer.start_as_current_span("api.cache.flush") as span:
|
||||
span.set_attribute("service.name", "devserver.api.fastapi")
|
||||
span.set_attribute("operation", "cache_flush")
|
||||
|
||||
logger.warning("Flushing entire cache!")
|
||||
|
||||
try:
|
||||
redis_client.flushdb()
|
||||
span.set_attribute("cache.flushed", True)
|
||||
|
||||
logger.info("Cache flushed successfully")
|
||||
|
||||
return {
|
||||
"service": "devserver.api.fastapi",
|
||||
"operation": "cache_flush",
|
||||
"message": "All cache entries deleted",
|
||||
"status": "success"
|
||||
}
|
||||
except Exception as e:
|
||||
logger.error(f"Failed to flush cache: error={e}", exc_info=True)
|
||||
raise HTTPException(status_code=500, detail=f"Cache error: {str(e)}")
|
||||
|
||||
|
||||
@app.get("/api/cache/stats", tags=["Redis Cache"])
|
||||
async def cache_stats():
|
||||
"""Get Redis cache statistics"""
|
||||
with tracer.start_as_current_span("api.cache.stats") as span:
|
||||
span.set_attribute("service.name", "devserver.api.fastapi")
|
||||
span.set_attribute("operation", "cache_stats")
|
||||
|
||||
logger.info("Fetching cache statistics")
|
||||
|
||||
try:
|
||||
info = redis_client.info() # type: ignore
|
||||
stats = {
|
||||
"used_memory": info.get('used_memory_human', 'N/A'), # type: ignore
|
||||
"connected_clients": info.get('connected_clients', 0), # type: ignore
|
||||
"total_keys": redis_client.dbsize(),
|
||||
"uptime_seconds": info.get('uptime_in_seconds', 0), # type: ignore
|
||||
"hits": info.get('keyspace_hits', 0), # type: ignore
|
||||
"misses": info.get('keyspace_misses', 0) # type: ignore
|
||||
}
|
||||
|
||||
# Calculate hit ratio
|
||||
total_ops = stats['hits'] + stats['misses']
|
||||
hit_ratio = (stats['hits'] / total_ops * 100) if total_ops > 0 else 0
|
||||
stats['hit_ratio_percent'] = round(hit_ratio, 2)
|
||||
|
||||
span.set_attribute("cache.total_keys", stats['total_keys'])
|
||||
span.set_attribute("cache.hit_ratio", hit_ratio)
|
||||
|
||||
logger.info(f"Cache stats: {stats['total_keys']} keys, {hit_ratio:.2f}% hit ratio")
|
||||
|
||||
return {
|
||||
"service": "devserver.api.fastapi",
|
||||
"operation": "cache_stats",
|
||||
"stats": stats
|
||||
}
|
||||
except Exception as e:
|
||||
logger.error(f"Failed to get cache stats: error={e}", exc_info=True)
|
||||
raise HTTPException(status_code=500, detail=f"Cache error: {str(e)}")
|
||||
|
||||
|
||||
@app.post("/api/cache/batch-set", tags=["Redis Cache"])
|
||||
async def batch_set_cache(items: dict):
|
||||
"""Set multiple cache values at once"""
|
||||
with tracer.start_as_current_span("api.cache.batch_set") as span:
|
||||
span.set_attribute("service.name", "devserver.api.fastapi")
|
||||
span.set_attribute("operation", "cache_batch_set")
|
||||
span.set_attribute("cache.batch_size", len(items))
|
||||
|
||||
logger.info(f"Batch setting {len(items)} cache entries")
|
||||
|
||||
try:
|
||||
pipeline = redis_client.pipeline()
|
||||
for key, value in items.items():
|
||||
# Convert value to JSON string if it's a dict, list, or other complex type
|
||||
if isinstance(value, (dict, list)):
|
||||
value_str = json.dumps(value)
|
||||
else:
|
||||
value_str = str(value)
|
||||
pipeline.set(key, value_str)
|
||||
results = pipeline.execute()
|
||||
|
||||
success_count = sum(1 for r in results if r)
|
||||
span.set_attribute("cache.success_count", success_count)
|
||||
|
||||
logger.info(f"Batch set complete: {success_count}/{len(items)} successful")
|
||||
|
||||
return {
|
||||
"service": "devserver.api.fastapi",
|
||||
"operation": "cache_batch_set",
|
||||
"total": len(items),
|
||||
"successful": success_count,
|
||||
"keys": list(items.keys())
|
||||
}
|
||||
except Exception as e:
|
||||
logger.error(f"Failed to batch set: error={e}", exc_info=True)
|
||||
raise HTTPException(status_code=500, detail=f"Cache error: {str(e)}")
|
||||
|
||||
|
||||
@app.get("/api/cache/item/{key:path}", tags=["Redis Cache"])
|
||||
async def get_cache(key: str):
|
||||
"""Get a value from Redis cache."""
|
||||
with tracer.start_as_current_span("api.cache.get") as span:
|
||||
span.set_attribute("service.name", "devserver.api.fastapi")
|
||||
span.set_attribute("operation", "cache_get")
|
||||
span.set_attribute("cache.key", key)
|
||||
|
||||
logger.info(f"Getting cache: key={key}")
|
||||
|
||||
try:
|
||||
value = redis_client.get(key)
|
||||
|
||||
if value is None:
|
||||
span.set_attribute("cache.hit", False)
|
||||
logger.warning(f"Cache miss: key={key}")
|
||||
raise HTTPException(status_code=404, detail="Key not found in cache")
|
||||
|
||||
span.set_attribute("cache.hit", True)
|
||||
logger.info(f"Cache hit: key={key}")
|
||||
value_str = str(value)
|
||||
logger.debug(f"Cache value: {value_str[:50]}..." if len(value_str) > 50 else f"Cache value: {value_str}")
|
||||
|
||||
return {
|
||||
"service": "devserver.api.fastapi",
|
||||
"operation": "cache_get",
|
||||
"key": key,
|
||||
"value": value
|
||||
}
|
||||
except HTTPException:
|
||||
raise
|
||||
except Exception as e:
|
||||
logger.error(f"Failed to get cache: key={key}, error={e}", exc_info=True)
|
||||
raise HTTPException(status_code=500, detail=f"Cache error: {str(e)}")
|
||||
|
||||
|
||||
@app.delete("/api/cache/item/{key:path}", tags=["Redis Cache"])
|
||||
async def delete_cache(key: str):
|
||||
"""Delete a cache entry"""
|
||||
with tracer.start_as_current_span("api.cache.delete") as span:
|
||||
span.set_attribute("service.name", "devserver.api.fastapi")
|
||||
span.set_attribute("operation", "cache_delete")
|
||||
span.set_attribute("cache.key", key)
|
||||
|
||||
logger.info(f"Deleting cache key: {key}")
|
||||
|
||||
try:
|
||||
result = redis_client.delete(key)
|
||||
deleted = result > 0 # type: ignore
|
||||
span.set_attribute("cache.deleted", deleted)
|
||||
|
||||
if deleted:
|
||||
logger.info(f"Cache key deleted: {key}")
|
||||
else:
|
||||
logger.warning(f"Cache key not found: {key}")
|
||||
|
||||
return {
|
||||
"service": "devserver.api.fastapi",
|
||||
"operation": "cache_delete",
|
||||
"key": key,
|
||||
"deleted": deleted
|
||||
}
|
||||
except Exception as e:
|
||||
logger.error(f"Failed to delete key: error={e}", exc_info=True)
|
||||
raise HTTPException(status_code=500, detail=f"Cache error: {str(e)}")
|
||||
140
app/opentelemetry_config.py
Normal file
140
app/opentelemetry_config.py
Normal file
@@ -0,0 +1,140 @@
|
||||
"""
|
||||
OpenTelemetry Configuration for DevServer
|
||||
|
||||
This module provides explicit OpenTelemetry initialization to ensure
|
||||
proper trace generation and export to the OTEL Collector.
|
||||
"""
|
||||
|
||||
import os
|
||||
import logging
|
||||
from opentelemetry import trace
|
||||
from opentelemetry.sdk.trace import TracerProvider
|
||||
from opentelemetry.sdk.trace.export import BatchSpanProcessor
|
||||
from opentelemetry.exporter.otlp.proto.grpc.trace_exporter import OTLPSpanExporter
|
||||
from opentelemetry.sdk.resources import Resource, SERVICE_NAME, SERVICE_VERSION
|
||||
from opentelemetry.instrumentation.fastapi import FastAPIInstrumentor
|
||||
from opentelemetry.instrumentation.redis import RedisInstrumentor
|
||||
|
||||
logger = logging.getLogger(__name__)
|
||||
|
||||
|
||||
def init_opentelemetry():
|
||||
"""
|
||||
Initialize OpenTelemetry with OTLP exporter.
|
||||
|
||||
This function:
|
||||
1. Creates a TracerProvider with service metadata
|
||||
2. Configures OTLP gRPC exporter to send traces to the OTEL Collector
|
||||
3. Sets up batch span processing for efficient trace export
|
||||
4. Registers the provider globally
|
||||
|
||||
Environment Variables:
|
||||
OTEL_SERVICE_NAME: Name of the service (default: devserver.api.fastapi)
|
||||
OTEL_EXPORTER_OTLP_ENDPOINT: OTLP endpoint (default: http://otel-collector:4317)
|
||||
OTEL_PYTHON_LOG_LEVEL: OpenTelemetry log level (optional)
|
||||
"""
|
||||
|
||||
# Get configuration from environment
|
||||
service_name = os.getenv("OTEL_SERVICE_NAME", "devserver.api.fastapi")
|
||||
otlp_endpoint = os.getenv("OTEL_EXPORTER_OTLP_ENDPOINT", "http://otel-collector:4317")
|
||||
|
||||
logger.info(f"🔧 Initializing OpenTelemetry for service: {service_name}")
|
||||
logger.info(f"📡 OTLP Endpoint: {otlp_endpoint}")
|
||||
|
||||
# Create resource with service metadata
|
||||
resource = Resource(attributes={
|
||||
SERVICE_NAME: service_name,
|
||||
SERVICE_VERSION: "1.0.0",
|
||||
"deployment.environment": os.getenv("ENVIRONMENT", "development"),
|
||||
})
|
||||
|
||||
# Create tracer provider with resource
|
||||
provider = TracerProvider(resource=resource)
|
||||
|
||||
try:
|
||||
# Create OTLP exporter for traces
|
||||
otlp_exporter = OTLPSpanExporter(
|
||||
endpoint=otlp_endpoint,
|
||||
insecure=True # Use insecure channel (no TLS) for internal network
|
||||
)
|
||||
|
||||
# Add batch span processor for efficient export
|
||||
span_processor = BatchSpanProcessor(otlp_exporter)
|
||||
provider.add_span_processor(span_processor)
|
||||
|
||||
# Set as global tracer provider
|
||||
trace.set_tracer_provider(provider)
|
||||
|
||||
logger.info("✅ OpenTelemetry TracerProvider initialized successfully")
|
||||
logger.info("✅ OTLP exporter configured and ready")
|
||||
|
||||
except Exception as e:
|
||||
logger.error(f"❌ Failed to initialize OpenTelemetry: {e}")
|
||||
logger.error("Traces will not be exported!")
|
||||
raise
|
||||
|
||||
return provider
|
||||
|
||||
|
||||
def instrument_fastapi_app(app):
|
||||
"""
|
||||
Instrument a FastAPI application with OpenTelemetry.
|
||||
|
||||
This function:
|
||||
1. Initializes the global OpenTelemetry tracer provider
|
||||
2. Instruments the FastAPI app to generate spans for HTTP requests
|
||||
3. Instruments Redis client to trace cache operations
|
||||
|
||||
Args:
|
||||
app: FastAPI application instance to instrument
|
||||
|
||||
Returns:
|
||||
TracerProvider: The initialized tracer provider
|
||||
"""
|
||||
|
||||
logger.info("🚀 Starting OpenTelemetry instrumentation...")
|
||||
|
||||
# Initialize OpenTelemetry first
|
||||
provider = init_opentelemetry()
|
||||
|
||||
# Instrument FastAPI
|
||||
try:
|
||||
FastAPIInstrumentor.instrument_app(app)
|
||||
logger.info("✅ FastAPI instrumented - HTTP requests will generate spans")
|
||||
except Exception as e:
|
||||
logger.error(f"❌ Failed to instrument FastAPI: {e}")
|
||||
|
||||
# Instrument Redis
|
||||
try:
|
||||
RedisInstrumentor().instrument()
|
||||
logger.info("✅ Redis instrumented - Cache operations will generate spans")
|
||||
except Exception as e:
|
||||
logger.error(f"❌ Failed to instrument Redis: {e}")
|
||||
|
||||
logger.info("🎉 OpenTelemetry instrumentation complete!")
|
||||
|
||||
return provider
|
||||
|
||||
|
||||
def get_tracer(name: str = __name__):
|
||||
"""
|
||||
Get a tracer instance for manual span creation.
|
||||
|
||||
Args:
|
||||
name: Name of the tracer (usually __name__ of the calling module)
|
||||
|
||||
Returns:
|
||||
Tracer: OpenTelemetry tracer instance
|
||||
|
||||
Example:
|
||||
```python
|
||||
from app.opentelemetry_config import get_tracer
|
||||
|
||||
tracer = get_tracer(__name__)
|
||||
|
||||
with tracer.start_as_current_span("my-operation"):
|
||||
# Your code here
|
||||
pass
|
||||
```
|
||||
"""
|
||||
return trace.get_tracer(name)
|
||||
203
app/worker.py
Normal file
203
app/worker.py
Normal file
@@ -0,0 +1,203 @@
|
||||
import os
|
||||
import time
|
||||
import json
|
||||
import redis
|
||||
from celery import Celery
|
||||
from celery.signals import task_prerun, task_postrun, task_failure
|
||||
from app.logging import setup_logging, get_logger
|
||||
from opentelemetry import trace
|
||||
|
||||
# Setup logging for Celery worker
|
||||
logger = setup_logging(service_name="devserver.celery.worker", log_level="DEBUG")
|
||||
|
||||
logger.info("=" * 60)
|
||||
logger.info("DevServer Celery Worker Initializing...")
|
||||
logger.info("=" * 60)
|
||||
logger.info("Service: devserver.celery.worker")
|
||||
|
||||
# Get tracer for worker
|
||||
tracer = trace.get_tracer("devserver.celery.tracer")
|
||||
|
||||
app = Celery(
|
||||
"DevServerTasks",
|
||||
broker=os.getenv("CELERY_BROKER_URL"),
|
||||
backend=os.getenv("CELERY_RESULT_BACKEND"),
|
||||
)
|
||||
|
||||
logger.info(f"Celery broker: {os.getenv('CELERY_BROKER_URL')}")
|
||||
logger.info(f"Celery backend: {os.getenv('CELERY_RESULT_BACKEND')}")
|
||||
|
||||
# Initialize Redis client for worker
|
||||
logger.info("Initializing Redis connection for worker...")
|
||||
try:
|
||||
redis_client = redis.Redis(host='redis', port=6379, db=0, decode_responses=True)
|
||||
redis_client.ping()
|
||||
logger.info("Redis connection established successfully")
|
||||
except Exception as e:
|
||||
logger.error(f"Failed to connect to Redis: {e}", exc_info=True)
|
||||
|
||||
|
||||
# Celery signal handlers
|
||||
@task_prerun.connect
|
||||
def task_prerun_handler(sender=None, task_id=None, task=None, args=None, kwargs=None, **extra):
|
||||
"""Log before task execution"""
|
||||
task_name = task.name if task else sender.name if sender else "unknown" # type: ignore
|
||||
logger.info(f"⏳ Task starting: {task_name}")
|
||||
logger.info(f" Service: devserver.celery.worker")
|
||||
logger.info(f" Task ID: {task_id}")
|
||||
logger.debug(f" Args: {args}")
|
||||
logger.debug(f" Kwargs: {kwargs}")
|
||||
|
||||
|
||||
@task_postrun.connect
|
||||
def task_postrun_handler(sender=None, task_id=None, task=None, args=None, kwargs=None, retval=None, **extra):
|
||||
"""Log after task execution"""
|
||||
task_name = task.name if task else sender.name if sender else "unknown" # type: ignore
|
||||
logger.info(f"Task completed: {task_name}")
|
||||
logger.info(f" Service: devserver.celery.worker")
|
||||
logger.info(f" Task ID: {task_id}")
|
||||
logger.debug(f" Result: {retval}")
|
||||
|
||||
|
||||
@task_failure.connect
|
||||
def task_failure_handler(sender=None, task_id=None, exception=None, args=None, kwargs=None, traceback=None, **extra):
|
||||
"""Log task failures"""
|
||||
task_name = sender.name if sender else "unknown" # type: ignore
|
||||
logger.error(f"Task failed: {task_name}")
|
||||
logger.error(f" Service: devserver.celery.worker")
|
||||
logger.error(f" Task ID: {task_id}")
|
||||
logger.error(f" Exception: {exception}")
|
||||
logger.error(f" Args: {args}")
|
||||
logger.error(f" Traceback: {traceback}")
|
||||
|
||||
|
||||
@app.task
|
||||
def long_running_task(duration):
|
||||
"""Simulates a long-running task by sleeping for the specified duration."""
|
||||
logger.info(f"Executing long_running_task: duration={duration}s")
|
||||
start_time = time.time()
|
||||
|
||||
time.sleep(duration)
|
||||
|
||||
elapsed = time.time() - start_time
|
||||
result = f"Task completed after {duration} seconds (actual: {elapsed:.2f}s)"
|
||||
logger.info(f"{result}")
|
||||
return result
|
||||
|
||||
|
||||
@app.task(name="devserver.celery.tasks.fibonacci")
|
||||
def calculate_fibonacci(n):
|
||||
"""Calculate the nth Fibonacci number (with intentional delay for demo) and cache the result."""
|
||||
with tracer.start_as_current_span("celery.task.fibonacci") as span:
|
||||
span.set_attribute("service.name", "devserver.celery.worker")
|
||||
span.set_attribute("task.name", "fibonacci")
|
||||
span.set_attribute("fibonacci.n", n)
|
||||
|
||||
cache_key = f"fibonacci:result:{n}"
|
||||
logger.info(f"Calculating Fibonacci number: n={n}, cache_key={cache_key}")
|
||||
start_time = time.time()
|
||||
|
||||
# Check cache first
|
||||
try:
|
||||
cached_result = redis_client.get(cache_key)
|
||||
if cached_result:
|
||||
span.set_attribute("cache.hit", True)
|
||||
result_value = int(str(cached_result))
|
||||
logger.info(f"Cache hit in worker! Fibonacci({n}) = {result_value}")
|
||||
elapsed = time.time() - start_time
|
||||
return {
|
||||
"service": "devserver.celery.worker",
|
||||
"task": "fibonacci",
|
||||
"n": n,
|
||||
"result": result_value,
|
||||
"computation_time_seconds": elapsed,
|
||||
"source": "cache"
|
||||
}
|
||||
except (ValueError, TypeError) as e:
|
||||
logger.warning(f"Cache value conversion failed in worker: {e}")
|
||||
except Exception as e:
|
||||
logger.warning(f"Cache check failed in worker: {e}")
|
||||
|
||||
span.set_attribute("cache.hit", False)
|
||||
|
||||
def fib(num):
|
||||
if num <= 1:
|
||||
return num
|
||||
return fib(num - 1) + fib(num - 2)
|
||||
|
||||
# Add a small delay to make the task more visible in traces
|
||||
logger.debug("Adding artificial delay for visibility (0.5s)")
|
||||
time.sleep(0.5)
|
||||
|
||||
logger.debug(f"Starting Fibonacci calculation for n={n}")
|
||||
result = fib(n)
|
||||
|
||||
elapsed = time.time() - start_time
|
||||
span.set_attribute("fibonacci.result", result)
|
||||
span.set_attribute("task.duration_seconds", elapsed)
|
||||
|
||||
logger.info(f"Fibonacci calculated: n={n}, result={result}, time={elapsed:.2f}s")
|
||||
|
||||
# Store result in cache (TTL: 1 hour for Fibonacci results)
|
||||
try:
|
||||
redis_client.setex(cache_key, 3600, str(result))
|
||||
span.set_attribute("cache.stored", True)
|
||||
logger.info(f"Stored Fibonacci result in cache: {cache_key} = {result} (TTL: 3600s)")
|
||||
except Exception as e:
|
||||
logger.error(f"Failed to store Fibonacci result in cache: {e}")
|
||||
|
||||
return {
|
||||
"service": "devserver.celery.worker",
|
||||
"task": "fibonacci",
|
||||
"n": n,
|
||||
"result": result,
|
||||
"message": f"The {n}th Fibonacci number is {result}",
|
||||
"computation_time_seconds": elapsed,
|
||||
"source": "computation"
|
||||
}
|
||||
|
||||
|
||||
@app.task(name="devserver.celery.tasks.process_data")
|
||||
def process_data_with_cache(data, cache_key):
|
||||
"""Process data and cache the result in Redis."""
|
||||
with tracer.start_as_current_span("celery.task.process_data") as span:
|
||||
span.set_attribute("service.name", "devserver.celery.worker")
|
||||
span.set_attribute("task.name", "process_data")
|
||||
span.set_attribute("cache.key", cache_key)
|
||||
span.set_attribute("data.keys_count", len(data))
|
||||
|
||||
logger.info(f"Processing data with caching")
|
||||
logger.debug(f"Cache key: {cache_key}")
|
||||
logger.debug(f"Data keys: {list(data.keys())}")
|
||||
start_time = time.time()
|
||||
|
||||
# Simulate processing
|
||||
logger.debug("Simulating data processing (1s delay)")
|
||||
time.sleep(1)
|
||||
|
||||
# Process the data (example: count keys and values)
|
||||
processed = {
|
||||
"service": "devserver.celery.worker",
|
||||
"task": "process_data",
|
||||
"input": data,
|
||||
"num_keys": len(data),
|
||||
"total_length": sum(len(str(v)) for v in data.values()),
|
||||
"processed_at": time.time()
|
||||
}
|
||||
|
||||
logger.debug(f"Data processed: num_keys={processed['num_keys']}, total_length={processed['total_length']}")
|
||||
|
||||
# Cache the result for 5 minutes
|
||||
try:
|
||||
redis_client.setex(cache_key, 300, json.dumps(processed))
|
||||
span.set_attribute("cache.operation", "success")
|
||||
logger.info(f"Result cached successfully: cache_key={cache_key}, ttl=300s")
|
||||
except Exception as e:
|
||||
span.set_attribute("cache.operation", "failed")
|
||||
logger.error(f"Failed to cache result: {e}", exc_info=True)
|
||||
|
||||
elapsed = time.time() - start_time
|
||||
span.set_attribute("task.duration_seconds", elapsed)
|
||||
logger.info(f"Data processing complete: time={elapsed:.2f}s")
|
||||
|
||||
return processed
|
||||
Reference in New Issue
Block a user