tests/test_logging_config.py

"""Tests for logging configuration module.

Requirements: 10.5, 9.5
"""

import logging
import pytest
from pathlib import Path

from app.logging_config import (
    SensitiveDataFilter,
    RequestIdFilter,
    setup_logging,
    get_logger,
    set_request_id,
    clear_request_id
)


class TestRequestIdFilter:
    """Test request_id filtering in logs.
    
    Requirement 9.5: Logs should include request_id for tracing.
    """
    
    def test_filter_adds_request_id(self):
        """Test that request_id is added to log records."""
        filter_obj = RequestIdFilter()
        
        # Set request_id in context
        set_request_id("test-request-123")
        
        # Create a log record
        record = logging.LogRecord(
            name="test",
            level=logging.INFO,
            pathname="",
            lineno=0,
            msg="Test message",
            args=(),
            exc_info=None
        )
        
        filter_obj.filter(record)
        
        assert hasattr(record, 'request_id')
        assert record.request_id == "test-request-123"
        
        # Clean up
        clear_request_id()
    
    def test_filter_uses_default_when_no_request_id(self):
        """Test that filter uses '-' when no request_id is set."""
        filter_obj = RequestIdFilter()
        
        # Ensure no request_id is set
        clear_request_id()
        
        # Create a log record
        record = logging.LogRecord(
            name="test",
            level=logging.INFO,
            pathname="",
            lineno=0,
            msg="Test message",
            args=(),
            exc_info=None
        )
        
        filter_obj.filter(record)
        
        assert hasattr(record, 'request_id')
        assert record.request_id == "-"


class TestSensitiveDataFilter:
    """Test sensitive data filtering in logs.
    
    Requirement 10.5: System should not output sensitive information in logs.
    """
    
    def test_filter_api_key(self):
        """Test that API keys are masked in log messages."""
        filter_obj = SensitiveDataFilter()
        
        # Create a log record with API key
        record = logging.LogRecord(
            name="test",
            level=logging.INFO,
            pathname="",
            lineno=0,
            msg="Using api_key=sk_1234567890abcdef for request",
            args=(),
            exc_info=None
        )
        
        filter_obj.filter(record)
        
        assert "sk_1234567890abcdef" not in record.msg
        assert "***REDACTED***" in record.msg
    
    def test_filter_zhipu_api_key(self):
        """Test that Zhipu API keys are masked."""
        filter_obj = SensitiveDataFilter()
        
        record = logging.LogRecord(
            name="test",
            level=logging.INFO,
            pathname="",
            lineno=0,
            msg="zhipu_api_key: abc123def456ghi789",
            args=(),
            exc_info=None
        )
        
        filter_obj.filter(record)
        
        assert "abc123def456ghi789" not in record.msg
        assert "***REDACTED***" in record.msg
    
    def test_filter_bearer_token(self):
        """Test that bearer tokens are masked."""
        filter_obj = SensitiveDataFilter()
        
        record = logging.LogRecord(
            name="test",
            level=logging.INFO,
            pathname="",
            lineno=0,
            msg="Authorization: Bearer eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9",
            args=(),
            exc_info=None
        )
        
        filter_obj.filter(record)
        
        assert "eyJhbGciOiJIUzI1NiIsInR5cCI6IkpXVCJ9" not in record.msg
        assert "***REDACTED***" in record.msg
    
    def test_filter_password(self):
        """Test that passwords are masked."""
        filter_obj = SensitiveDataFilter()
        
        record = logging.LogRecord(
            name="test",
            level=logging.INFO,
            pathname="",
            lineno=0,
            msg='Login attempt with password="secret123"',
            args=(),
            exc_info=None
        )
        
        filter_obj.filter(record)
        
        assert "secret123" not in record.msg
        assert "***REDACTED***" in record.msg
    
    def test_filter_authorization_header(self):
        """Test that authorization headers are masked."""
        filter_obj = SensitiveDataFilter()
        
        record = logging.LogRecord(
            name="test",
            level=logging.INFO,
            pathname="",
            lineno=0,
            msg="Headers: authorization: Basic_dXNlcjpwYXNz",
            args=(),
            exc_info=None
        )
        
        filter_obj.filter(record)
        
        assert "Basic_dXNlcjpwYXNz" not in record.msg
        assert "***REDACTED***" in record.msg
    
    def test_filter_preserves_normal_text(self):
        """Test that normal text is not affected by filtering."""
        filter_obj = SensitiveDataFilter()
        
        record = logging.LogRecord(
            name="test",
            level=logging.INFO,
            pathname="",
            lineno=0,
            msg="Processing request for user authentication",
            args=(),
            exc_info=None
        )
        
        original_msg = record.msg
        filter_obj.filter(record)
        
        assert record.msg == original_msg
    
    def test_filter_with_args_dict(self):
        """Test filtering with dictionary arguments."""
        filter_obj = SensitiveDataFilter()
        
        # Create record with dict args
        record = logging.LogRecord(
            name="test",
            level=logging.INFO,
            pathname="",
            lineno=0,
            msg="Request data",
            args=(),
            exc_info=None
        )
        # Manually set args after creation
        record.args = {"data": "api_key=secret123456"}
        
        filter_obj.filter(record)
        
        assert "secret123456" not in record.args["data"]
        assert "***REDACTED***" in record.args["data"]
    
    def test_filter_with_args_tuple(self):
        """Test filtering with tuple arguments."""
        filter_obj = SensitiveDataFilter()
        
        record = logging.LogRecord(
            name="test",
            level=logging.INFO,
            pathname="",
            lineno=0,
            msg="Config: %s",
            args=("api_key=secret123456",),
            exc_info=None
        )
        
        filter_obj.filter(record)
        
        assert "secret123456" not in record.args[0]
        assert "***REDACTED***" in record.args[0]


class TestSetupLogging:
    """Test logging setup and configuration."""
    
    def test_setup_logging_console_only(self):
        """Test setting up logging with console output only."""
        setup_logging(log_level="INFO", log_file=None)
        
        root_logger = logging.getLogger()
        
        # Should have at least one handler (console)
        assert len(root_logger.handlers) >= 1
        
        # Check log level
        assert root_logger.level == logging.INFO
    
    def test_setup_logging_with_file(self, tmp_path):
        """Test setting up logging with file output."""
        log_file = tmp_path / "test.log"
        
        setup_logging(log_level="DEBUG", log_file=log_file)
        
        root_logger = logging.getLogger()
        
        # Should have at least two handlers (console + file)
        assert len(root_logger.handlers) >= 2
        
        # Check log level
        assert root_logger.level == logging.DEBUG
        
        # Test logging to file
        test_logger = logging.getLogger("test")
        test_logger.info("Test message")
        
        # File should exist and contain the message
        assert log_file.exists()
        content = log_file.read_text()
        assert "Test message" in content
    
    def test_setup_logging_custom_format(self, tmp_path):
        """Test setting up logging with custom format."""
        log_file = tmp_path / "test.log"
        custom_format = "%(levelname)s - %(message)s"
        
        setup_logging(
            log_level="INFO",
            log_file=log_file,
            log_format=custom_format
        )
        
        test_logger = logging.getLogger("test_custom")
        test_logger.info("Custom format test")
        
        content = log_file.read_text()
        assert "INFO - Custom format test" in content
    
    def test_setup_logging_applies_sensitive_filter(self, tmp_path):
        """Test that sensitive data filter is applied to all handlers.
        
        Requirement 10.5: Sensitive information should be filtered from logs.
        """
        log_file = tmp_path / "test.log"
        
        setup_logging(log_level="INFO", log_file=log_file)
        
        test_logger = logging.getLogger("test_sensitive")
        test_logger.info("API request with api_key=secret123456789")
        
        # Read log file
        content = log_file.read_text()
        
        # API key should be redacted
        assert "secret123456789" not in content
        assert "***REDACTED***" in content
    
    def test_get_logger(self):
        """Test getting a logger instance."""
        logger = get_logger("test_module")
        
        assert logger is not None
        assert logger.name == "test_module"
        assert isinstance(logger, logging.Logger)


class TestLoggingIntegration:
    """Integration tests for logging system.
    
    Requirement 9.5: System should log all errors with timestamp and stack trace.
    """
    
    def test_error_logging_with_traceback(self, tmp_path):
        """Test that errors are logged with full traceback."""
        log_file = tmp_path / "error.log"
        
        setup_logging(log_level="ERROR", log_file=log_file)
        
        logger = get_logger("test_error")
        
        try:
            # Cause an error
            raise ValueError("Test error for logging")
        except ValueError:
            logger.error("An error occurred", exc_info=True)
        
        # Read log file
        content = log_file.read_text()
        
        # Should contain error message and traceback
        assert "An error occurred" in content
        assert "ValueError: Test error for logging" in content
        assert "Traceback" in content
    
    def test_logging_includes_timestamp(self, tmp_path):
        """Test that log entries include timestamps."""
        log_file = tmp_path / "timestamp.log"
        
        setup_logging(log_level="INFO", log_file=log_file)
        
        logger = get_logger("test_timestamp")
        logger.info("Timestamp test message")
        
        content = log_file.read_text()
        
        # Should contain timestamp in format [YYYY-MM-DD HH:MM:SS]
        import re
        timestamp_pattern = r'\[\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}\]'
        assert re.search(timestamp_pattern, content)
    
    def test_logging_includes_level_and_module(self, tmp_path):
        """Test that log entries include level and module name."""
        log_file = tmp_path / "format.log"
        
        setup_logging(log_level="INFO", log_file=log_file)
        
        logger = get_logger("test_module")
        logger.warning("Warning message")
        
        content = log_file.read_text()
        
        # Should contain level and module name
        assert "[WARNING]" in content
        assert "[test_module]" in content
        assert "Warning message" in content
    
    def test_logging_includes_request_id(self, tmp_path):
        """Test that log entries include request_id when set.
        
        Requirement 9.5: Logs should include request_id for request tracing.
        """
        log_file = tmp_path / "request_id.log"
        
        setup_logging(log_level="INFO", log_file=log_file)
        
        # Set request_id
        set_request_id("req-12345")
        
        logger = get_logger("test_request")
        logger.info("Request message")
        
        content = log_file.read_text()
        
        # Should contain request_id
        assert "[req-12345]" in content
        assert "Request message" in content
        
        # Clean up
        clear_request_id()
    
    def test_logging_without_request_id(self, tmp_path):
        """Test that log entries use '-' when no request_id is set."""
        log_file = tmp_path / "no_request_id.log"
        
        setup_logging(log_level="INFO", log_file=log_file)
        
        # Ensure no request_id is set
        clear_request_id()
        
        logger = get_logger("test_no_request")
        logger.info("Message without request_id")
        
        content = log_file.read_text()
        
        # Should contain '-' for request_id
        assert "[-]" in content
        assert "Message without request_id" in content