Aniworld/tests/unit/test_logging.py

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