feat: implement comprehensive logging system
- Created src/server/utils/logging.py with structured JSON logging - Multiple log handlers for app, error, download, security, performance - Request logging middleware with unique request IDs and timing - Log rotation and cleanup functionality - Comprehensive test suite with 19 passing tests - Context variables for request and user tracking - Security event logging and download progress tracking Features: - JSON formatted logs with consistent structure - Automatic log rotation (10MB files, 5 backups) - Request/response logging middleware - Performance monitoring - Security auditing - Download progress tracking - Old log cleanup functionality Tests: All 19 tests passing for logging system functionality
This commit is contained in:
400
tests/unit/test_logging.py
Normal file
400
tests/unit/test_logging.py
Normal file
@@ -0,0 +1,400 @@
|
||||
"""
|
||||
Tests for the logging system.
|
||||
"""
|
||||
|
||||
import json
|
||||
import logging
|
||||
import tempfile
|
||||
from pathlib import Path
|
||||
from unittest.mock import MagicMock, patch
|
||||
|
||||
import pytest
|
||||
|
||||
from src.server.utils.logging import (
|
||||
JSONFormatter,
|
||||
LoggingConfig,
|
||||
RequestLoggingMiddleware,
|
||||
cleanup_old_logs,
|
||||
get_logger,
|
||||
init_logging,
|
||||
log_download_progress,
|
||||
log_security_event,
|
||||
request_id_var,
|
||||
setup_logging,
|
||||
user_id_var,
|
||||
)
|
||||
|
||||
|
||||
class TestJSONFormatter:
|
||||
"""Test the JSON log formatter."""
|
||||
|
||||
def test_format_basic_log(self):
|
||||
"""Test basic log formatting."""
|
||||
formatter = JSONFormatter()
|
||||
record = logging.LogRecord(
|
||||
name="test",
|
||||
level=logging.INFO,
|
||||
pathname="/test.py",
|
||||
lineno=42,
|
||||
msg="Test message",
|
||||
args=(),
|
||||
exc_info=None
|
||||
)
|
||||
|
||||
result = formatter.format(record)
|
||||
log_data = json.loads(result)
|
||||
|
||||
assert log_data["level"] == "INFO"
|
||||
assert log_data["logger"] == "test"
|
||||
assert log_data["message"] == "Test message"
|
||||
assert log_data["module"] == "test"
|
||||
assert log_data["line"] == 42
|
||||
assert "timestamp" in log_data
|
||||
|
||||
def test_format_with_context(self):
|
||||
"""Test log formatting with request context."""
|
||||
request_id_var.set("test-request-123")
|
||||
user_id_var.set("user-456")
|
||||
|
||||
formatter = JSONFormatter()
|
||||
record = logging.LogRecord(
|
||||
name="test",
|
||||
level=logging.INFO,
|
||||
pathname="/test.py",
|
||||
lineno=42,
|
||||
msg="Test message",
|
||||
args=(),
|
||||
exc_info=None
|
||||
)
|
||||
|
||||
result = formatter.format(record)
|
||||
log_data = json.loads(result)
|
||||
|
||||
assert log_data["request_id"] == "test-request-123"
|
||||
assert log_data["user_id"] == "user-456"
|
||||
|
||||
# Clean up context
|
||||
request_id_var.set(None)
|
||||
user_id_var.set(None)
|
||||
|
||||
def test_format_with_exception(self):
|
||||
"""Test log formatting with exception."""
|
||||
formatter = JSONFormatter()
|
||||
|
||||
try:
|
||||
raise ValueError("Test error")
|
||||
except ValueError:
|
||||
import sys
|
||||
exc_info = sys.exc_info()
|
||||
record = logging.LogRecord(
|
||||
name="test",
|
||||
level=logging.ERROR,
|
||||
pathname="/test.py",
|
||||
lineno=42,
|
||||
msg="Error occurred",
|
||||
args=(),
|
||||
exc_info=exc_info
|
||||
)
|
||||
|
||||
result = formatter.format(record)
|
||||
log_data = json.loads(result)
|
||||
|
||||
assert log_data["level"] == "ERROR"
|
||||
assert "exception" in log_data
|
||||
assert "ValueError" in log_data["exception"]
|
||||
|
||||
def test_format_with_extra_fields(self):
|
||||
"""Test log formatting with extra fields."""
|
||||
formatter = JSONFormatter()
|
||||
record = logging.LogRecord(
|
||||
name="test",
|
||||
level=logging.INFO,
|
||||
pathname="/test.py",
|
||||
lineno=42,
|
||||
msg="Test message",
|
||||
args=(),
|
||||
exc_info=None
|
||||
)
|
||||
# Add extra fields
|
||||
record.episode_id = "episode-123"
|
||||
record.download_speed = 1024.5
|
||||
|
||||
result = formatter.format(record)
|
||||
log_data = json.loads(result)
|
||||
|
||||
assert "extra" in log_data
|
||||
assert log_data["extra"]["episode_id"] == "episode-123"
|
||||
assert log_data["extra"]["download_speed"] == 1024.5
|
||||
|
||||
|
||||
class TestLoggingConfig:
|
||||
"""Test the logging configuration."""
|
||||
|
||||
def test_init_with_defaults(self):
|
||||
"""Test initialization with default values."""
|
||||
with tempfile.TemporaryDirectory() as temp_dir:
|
||||
config = LoggingConfig(log_dir=temp_dir)
|
||||
|
||||
assert config.log_dir == Path(temp_dir)
|
||||
assert config.log_level == logging.INFO
|
||||
assert config.enable_console is True
|
||||
assert config.enable_json_format is True
|
||||
|
||||
# Check that log files would be created
|
||||
# No logs yet, files created on first log
|
||||
assert config.log_dir.exists()
|
||||
|
||||
def test_log_directory_creation(self):
|
||||
"""Test that log directory is created."""
|
||||
with tempfile.TemporaryDirectory() as temp_dir:
|
||||
log_dir = Path(temp_dir) / "logs" / "subdir"
|
||||
config = LoggingConfig(log_dir=log_dir)
|
||||
|
||||
assert log_dir.exists()
|
||||
assert config.log_dir == log_dir
|
||||
|
||||
def test_logger_setup(self):
|
||||
"""Test that loggers are properly configured."""
|
||||
with tempfile.TemporaryDirectory() as temp_dir:
|
||||
LoggingConfig(log_dir=temp_dir)
|
||||
|
||||
# Test main logger
|
||||
logger = logging.getLogger()
|
||||
assert logger.level == logging.INFO
|
||||
|
||||
# Test specific loggers
|
||||
download_logger = logging.getLogger("download")
|
||||
assert download_logger.level == logging.INFO
|
||||
assert download_logger.propagate is False
|
||||
|
||||
security_logger = logging.getLogger("security")
|
||||
assert security_logger.level == logging.INFO
|
||||
assert security_logger.propagate is False
|
||||
|
||||
performance_logger = logging.getLogger("performance")
|
||||
assert performance_logger.level == logging.INFO
|
||||
assert performance_logger.propagate is False
|
||||
|
||||
def test_file_logging(self):
|
||||
"""Test that log files are created and written to."""
|
||||
with tempfile.TemporaryDirectory() as temp_dir:
|
||||
LoggingConfig(log_dir=temp_dir, enable_console=False)
|
||||
|
||||
# Write some logs
|
||||
logger = logging.getLogger("test")
|
||||
logger.info("Test info message")
|
||||
logger.error("Test error message")
|
||||
|
||||
# Force handler flush
|
||||
for handler in logging.getLogger().handlers:
|
||||
handler.flush()
|
||||
|
||||
# Check that log files exist and contain content
|
||||
app_log = Path(temp_dir) / "app.log"
|
||||
error_log = Path(temp_dir) / "error.log"
|
||||
|
||||
# Files should exist after logging
|
||||
assert app_log.exists()
|
||||
assert error_log.exists()
|
||||
|
||||
|
||||
class TestRequestLoggingMiddleware:
|
||||
"""Test the request logging middleware."""
|
||||
|
||||
@pytest.fixture
|
||||
def mock_request(self):
|
||||
"""Create a mock request."""
|
||||
request = MagicMock()
|
||||
request.method = "GET"
|
||||
request.url = "http://test.com/api/test"
|
||||
request.headers = {
|
||||
"user-agent": "test-agent",
|
||||
"content-length": "100"
|
||||
}
|
||||
request.client.host = "127.0.0.1"
|
||||
return request
|
||||
|
||||
@pytest.fixture
|
||||
def mock_response(self):
|
||||
"""Create a mock response."""
|
||||
response = MagicMock()
|
||||
response.status_code = 200
|
||||
response.headers = {"content-length": "200"}
|
||||
return response
|
||||
|
||||
@pytest.mark.asyncio
|
||||
async def test_successful_request_logging(
|
||||
self, mock_request, mock_response):
|
||||
"""Test logging of successful requests."""
|
||||
app = MagicMock()
|
||||
middleware = RequestLoggingMiddleware(app)
|
||||
|
||||
async def mock_call_next(request):
|
||||
return mock_response
|
||||
|
||||
with patch.object(middleware.logger, 'info') as mock_log_info:
|
||||
with patch.object(
|
||||
middleware.performance_logger, 'info') as mock_perf_log:
|
||||
response = await middleware.dispatch(
|
||||
mock_request, mock_call_next)
|
||||
|
||||
assert response == mock_response
|
||||
assert mock_log_info.call_count == 2 # Start and completion
|
||||
assert mock_perf_log.call_count == 1
|
||||
|
||||
# Check log messages
|
||||
start_call = mock_log_info.call_args_list[0]
|
||||
assert "Request started" in start_call[0][0]
|
||||
|
||||
completion_call = mock_log_info.call_args_list[1]
|
||||
assert "Request completed" in completion_call[0][0]
|
||||
|
||||
@pytest.mark.asyncio
|
||||
async def test_failed_request_logging(self, mock_request):
|
||||
"""Test logging of failed requests."""
|
||||
app = MagicMock()
|
||||
middleware = RequestLoggingMiddleware(app)
|
||||
|
||||
async def mock_call_next(request):
|
||||
raise ValueError("Test error")
|
||||
|
||||
with patch.object(middleware.logger, 'info') as mock_log_info:
|
||||
with patch.object(middleware.logger, 'error') as mock_log_error:
|
||||
with pytest.raises(ValueError):
|
||||
await middleware.dispatch(mock_request, mock_call_next)
|
||||
|
||||
assert mock_log_info.call_count == 1 # Only start
|
||||
assert mock_log_error.call_count == 1 # Error
|
||||
|
||||
error_call = mock_log_error.call_args_list[0]
|
||||
assert "Request failed" in error_call[0][0]
|
||||
|
||||
def test_get_client_ip_forwarded_for(self):
|
||||
"""Test client IP extraction with X-Forwarded-For header."""
|
||||
app = MagicMock()
|
||||
middleware = RequestLoggingMiddleware(app)
|
||||
|
||||
request = MagicMock()
|
||||
request.headers = {"x-forwarded-for": "192.168.1.1, 10.0.0.1"}
|
||||
|
||||
ip = middleware._get_client_ip(request)
|
||||
assert ip == "192.168.1.1"
|
||||
|
||||
def test_get_client_ip_real_ip(self):
|
||||
"""Test client IP extraction with X-Real-IP header."""
|
||||
app = MagicMock()
|
||||
middleware = RequestLoggingMiddleware(app)
|
||||
|
||||
request = MagicMock()
|
||||
request.headers = {"x-real-ip": "192.168.1.2"}
|
||||
|
||||
ip = middleware._get_client_ip(request)
|
||||
assert ip == "192.168.1.2"
|
||||
|
||||
def test_get_client_ip_direct(self):
|
||||
"""Test client IP extraction from direct connection."""
|
||||
app = MagicMock()
|
||||
middleware = RequestLoggingMiddleware(app)
|
||||
|
||||
request = MagicMock()
|
||||
request.headers = {}
|
||||
request.client.host = "192.168.1.3"
|
||||
|
||||
ip = middleware._get_client_ip(request)
|
||||
assert ip == "192.168.1.3"
|
||||
|
||||
|
||||
class TestUtilityFunctions:
|
||||
"""Test utility functions."""
|
||||
|
||||
def test_setup_logging(self):
|
||||
"""Test setup_logging function."""
|
||||
with tempfile.TemporaryDirectory() as temp_dir:
|
||||
config = setup_logging(log_dir=temp_dir, log_level="DEBUG")
|
||||
|
||||
assert isinstance(config, LoggingConfig)
|
||||
assert config.log_dir == Path(temp_dir)
|
||||
assert config.log_level == logging.DEBUG
|
||||
|
||||
def test_get_logger(self):
|
||||
"""Test get_logger function."""
|
||||
logger = get_logger("test.module")
|
||||
|
||||
assert isinstance(logger, logging.Logger)
|
||||
assert logger.name == "test.module"
|
||||
|
||||
def test_log_download_progress(self):
|
||||
"""Test download progress logging."""
|
||||
with patch('logging.getLogger') as mock_get_logger:
|
||||
mock_logger = MagicMock()
|
||||
mock_get_logger.return_value = mock_logger
|
||||
|
||||
log_download_progress(
|
||||
episode_id="ep-123",
|
||||
progress=0.75,
|
||||
status="downloading",
|
||||
speed=1024.5,
|
||||
eta="5 minutes"
|
||||
)
|
||||
|
||||
mock_get_logger.assert_called_with("download")
|
||||
mock_logger.info.assert_called_once()
|
||||
|
||||
call_args = mock_logger.info.call_args
|
||||
assert "Download progress" in call_args[0][0]
|
||||
assert call_args[1]["extra"]["episode_id"] == "ep-123"
|
||||
assert call_args[1]["extra"]["progress"] == 0.75
|
||||
|
||||
def test_log_security_event(self):
|
||||
"""Test security event logging."""
|
||||
with patch('logging.getLogger') as mock_get_logger:
|
||||
mock_logger = MagicMock()
|
||||
mock_get_logger.return_value = mock_logger
|
||||
|
||||
log_security_event(
|
||||
event_type="login_attempt",
|
||||
details={"user_ip": "192.168.1.1", "success": True},
|
||||
severity="INFO"
|
||||
)
|
||||
|
||||
mock_get_logger.assert_called_with("security")
|
||||
mock_logger.info.assert_called_once()
|
||||
|
||||
call_args = mock_logger.info.call_args
|
||||
assert "Security event: login_attempt" in call_args[0][0]
|
||||
|
||||
def test_cleanup_old_logs(self):
|
||||
"""Test log cleanup function."""
|
||||
with tempfile.TemporaryDirectory() as temp_dir:
|
||||
log_dir = Path(temp_dir)
|
||||
|
||||
# Create some test log files
|
||||
old_log = log_dir / "old.log"
|
||||
new_log = log_dir / "new.log"
|
||||
|
||||
old_log.touch()
|
||||
new_log.touch()
|
||||
|
||||
# Test that function runs without error
|
||||
# (Real test would require complex mocking of file system)
|
||||
try:
|
||||
cleanup_old_logs(log_dir, days_to_keep=30)
|
||||
# If no exception is raised, the function works
|
||||
success = True
|
||||
except Exception:
|
||||
success = False
|
||||
|
||||
assert success
|
||||
|
||||
# Both files should still exist since they're new
|
||||
assert old_log.exists()
|
||||
assert new_log.exists()
|
||||
|
||||
def test_init_logging(self):
|
||||
"""Test init_logging function."""
|
||||
with tempfile.TemporaryDirectory() as temp_dir:
|
||||
init_logging(log_dir=temp_dir, log_level="DEBUG")
|
||||
|
||||
# Should set up global logging
|
||||
logger = logging.getLogger()
|
||||
assert logger.level == logging.DEBUG
|
||||
Reference in New Issue
Block a user