Michael Hu
add more logs
fdc056d
"""Tests for structured logger functionality."""
import pytest
import json
import logging
from unittest.mock import Mock, patch
from src.application.error_handling.structured_logger import (
StructuredLogger, LogContext, JsonFormatter, ContextFormatter,
get_structured_logger, set_correlation_id, get_correlation_id,
generate_correlation_id
)
class TestLogContext:
"""Test cases for LogContext."""
def test_log_context_creation(self):
"""Test creating log context."""
context = LogContext(
correlation_id="test-123",
operation="test_operation",
component="test_component"
)
assert context.correlation_id == "test-123"
assert context.operation == "test_operation"
assert context.component == "test_component"
def test_log_context_to_dict(self):
"""Test converting log context to dictionary."""
context = LogContext(
correlation_id="test-123",
operation="test_operation",
metadata={"key": "value"}
)
context_dict = context.to_dict()
assert context_dict["correlation_id"] == "test-123"
assert context_dict["operation"] == "test_operation"
assert context_dict["metadata"] == {"key": "value"}
assert "user_id" not in context_dict # None values should be excluded
class TestStructuredLogger:
"""Test cases for StructuredLogger."""
def setup_method(self):
"""Set up test fixtures."""
self.logger = StructuredLogger("test_logger", enable_json_logging=False)
def test_logger_creation(self):
"""Test creating structured logger."""
assert self.logger.logger.name == "test_logger"
assert not self.logger.enable_json_logging
def test_debug_logging(self):
"""Test debug logging."""
context = LogContext(correlation_id="test-123", operation="test_op")
with patch.object(self.logger.logger, 'debug') as mock_debug:
self.logger.info("Test debug message", context=context)
mock_debug.assert_called_once()
args, kwargs = mock_debug.call_args
assert "Test debug message" in args[0]
assert "extra" in kwargs
def test_info_logging(self):
"""Test info logging."""
context = LogContext(correlation_id="test-123")
extra = {"key": "value"}
with patch.object(self.logger.logger, 'info') as mock_info:
self.logger.info("Test info message", context=context, extra=extra)
mock_info.assert_called_once()
args, kwargs = mock_info.call_args
assert "Test info message" in args[0]
assert kwargs["extra"]["extra"] == extra
def test_error_logging_with_exception(self):
"""Test error logging with exception."""
context = LogContext(correlation_id="test-123")
exception = ValueError("Test error")
with patch.object(self.logger.logger, 'error') as mock_error:
self.logger.error("Test error message", context=context, exception=exception)
mock_error.assert_called_once()
args, kwargs = mock_error.call_args
assert "Test error message" in args[0]
assert kwargs["extra"]["exception"]["type"] == "ValueError"
assert kwargs["extra"]["exception"]["message"] == "Test error"
def test_log_operation_start(self):
"""Test logging operation start."""
extra = {"param": "value"}
with patch.object(self.logger.logger, 'info') as mock_info:
correlation_id = self.logger.log_operation_start("test_operation", extra=extra)
assert correlation_id is not None
mock_info.assert_called_once()
args, kwargs = mock_info.call_args
assert "Operation started: test_operation" in args[0]
def test_log_operation_end_success(self):
"""Test logging successful operation end."""
correlation_id = "test-123"
with patch.object(self.logger.logger, 'info') as mock_info:
self.logger.log_operation_end(
"test_operation",
correlation_id,
success=True,
duration=1.5
)
mock_info.assert_called_once()
args, kwargs = mock_info.call_args
assert "completed successfully" in args[0]
assert kwargs["extra"]["extra"]["success"] is True
assert kwargs["extra"]["extra"]["duration_seconds"] == 1.5
def test_log_operation_end_failure(self):
"""Test logging failed operation end."""
correlation_id = "test-123"
with patch.object(self.logger.logger, 'error') as mock_error:
self.logger.log_operation_end(
"test_operation",
correlation_id,
success=False
)
mock_error.assert_called_once()
args, kwargs = mock_error.call_args
assert "failed" in args[0]
assert kwargs["extra"]["extra"]["success"] is False
def test_log_performance_metric(self):
"""Test logging performance metric."""
context = LogContext(correlation_id="test-123")
with patch.object(self.logger.logger, 'info') as mock_info:
self.logger.log_performance_metric(
"response_time",
150.5,
"ms",
context=context
)
mock_info.assert_called_once()
args, kwargs = mock_info.call_args
assert "Performance metric: response_time=150.5 ms" in args[0]
assert kwargs["extra"]["extra"]["metric"]["name"] == "response_time"
assert kwargs["extra"]["extra"]["metric"]["value"] == 150.5
assert kwargs["extra"]["extra"]["metric"]["unit"] == "ms"
class TestJsonFormatter:
"""Test cases for JsonFormatter."""
def setup_method(self):
"""Set up test fixtures."""
self.formatter = JsonFormatter()
def test_format_log_record(self):
"""Test formatting log record as JSON."""
record = logging.LogRecord(
name="test_logger",
level=logging.INFO,
pathname="test.py",
lineno=10,
msg="Test message",
args=(),
exc_info=None
)
# Add extra data
record.extra = {
"correlation_id": "test-123",
"operation": "test_op"
}
formatted = self.formatter.format(record)
# Should be valid JSON
log_data = json.loads(formatted)
assert log_data["message"] == "Test message"
assert log_data["level"] == "INFO"
assert log_data["correlation_id"] == "test-123"
assert log_data["operation"] == "test_op"
def test_format_error_handling(self):
"""Test formatter error handling."""
record = logging.LogRecord(
name="test_logger",
level=logging.INFO,
pathname="test.py",
lineno=10,
msg="Test message",
args=(),
exc_info=None
)
# Add problematic extra data that can't be JSON serialized
record.extra = {
"correlation_id": "test-123",
"problematic_data": object() # Can't be JSON serialized
}
formatted = self.formatter.format(record)
# Should still work and include error message
assert "Test message" in formatted
class TestContextFormatter:
"""Test cases for ContextFormatter."""
def setup_method(self):
"""Set up test fixtures."""
self.formatter = ContextFormatter()
def test_format_with_correlation_id(self):
"""Test formatting with correlation ID."""
record = logging.LogRecord(
name="test_logger",
level=logging.INFO,
pathname="test.py",
lineno=10,
msg="Test message",
args=(),
exc_info=None
)
record.extra = {"correlation_id": "test-123"}
formatted = self.formatter.format(record)
assert "[test-123]" in formatted
assert "Test message" in formatted
def test_format_with_operation(self):
"""Test formatting with operation context."""
record = logging.LogRecord(
name="test_logger",
level=logging.INFO,
pathname="test.py",
lineno=10,
msg="Test message",
args=(),
exc_info=None
)
record.extra = {
"correlation_id": "test-123",
"operation": "test_operation"
}
formatted = self.formatter.format(record)
assert "[test_operation]" in formatted
assert "Test message" in formatted
class TestUtilityFunctions:
"""Test cases for utility functions."""
def test_get_structured_logger(self):
"""Test getting structured logger."""
logger = get_structured_logger("test_logger")
assert isinstance(logger, StructuredLogger)
assert logger.logger.name == "test_logger"
def test_correlation_id_context(self):
"""Test correlation ID context management."""
# Initially should be None
assert get_correlation_id() is None
# Set correlation ID
set_correlation_id("test-123")
assert get_correlation_id() == "test-123"
def test_generate_correlation_id(self):
"""Test generating correlation ID."""
correlation_id = generate_correlation_id()
assert correlation_id is not None
assert len(correlation_id) > 0
# Should generate different IDs
another_id = generate_correlation_id()
assert correlation_id != another_id