""" 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