Merge pull request #325 from christianlouis/copilot/increase-test-coverage-logging-azure
Increase test coverage for logging and Azure API modules to 100%
This commit is contained in:
Christian Krakau-Louis
@@ -371,6 +371,225 @@ class TestAzureTestConnectionIntegration:
|
||||
data = response.json()
|
||||
assert "status" in data
|
||||
|
||||
@patch("app.api.azure.settings")
|
||||
@patch("app.api.azure.logger")
|
||||
@pytest.mark.asyncio
|
||||
async def test_azure_connection_logs_warning_for_missing_config(self, mock_logger, mock_settings):
|
||||
"""Test that warning is logged when configuration is incomplete."""
|
||||
from app.api.azure import test_azure_connection
|
||||
|
||||
mock_settings.azure_endpoint = None
|
||||
mock_settings.azure_ai_key = "test-key"
|
||||
|
||||
mock_request = Mock()
|
||||
result = await test_azure_connection(mock_request)
|
||||
|
||||
# Verify warning was logged
|
||||
mock_logger.warning.assert_called_once()
|
||||
assert "configuration is incomplete" in mock_logger.warning.call_args[0][0].lower()
|
||||
|
||||
assert result["status"] == "error"
|
||||
|
||||
@patch("app.api.azure.DocumentIntelligenceAdministrationClient")
|
||||
@patch("app.api.azure.AzureKeyCredential")
|
||||
@patch("app.api.azure.settings")
|
||||
@patch("app.api.azure.logger")
|
||||
@pytest.mark.asyncio
|
||||
async def test_azure_connection_logs_success(
|
||||
self, mock_logger, mock_settings, mock_credential, mock_admin_client_class
|
||||
):
|
||||
"""Test that success is logged when connection is successful."""
|
||||
from app.api.azure import test_azure_connection
|
||||
|
||||
mock_settings.azure_endpoint = "https://test.cognitiveservices.azure.com/"
|
||||
mock_settings.azure_ai_key = "test-key"
|
||||
|
||||
mock_client = MagicMock()
|
||||
mock_client.list_operations.return_value = iter([])
|
||||
mock_admin_client_class.return_value = mock_client
|
||||
|
||||
mock_request = Mock()
|
||||
await test_azure_connection(mock_request)
|
||||
|
||||
# Verify info log for success
|
||||
info_calls = [call[0][0] for call in mock_logger.info.call_args_list]
|
||||
assert any("successfully tested" in str(call).lower() for call in info_calls)
|
||||
|
||||
@patch("app.api.azure.DocumentIntelligenceAdministrationClient")
|
||||
@patch("app.api.azure.AzureKeyCredential")
|
||||
@patch("app.api.azure.settings")
|
||||
@patch("app.api.azure.logger")
|
||||
@pytest.mark.asyncio
|
||||
async def test_azure_connection_logs_authentication_error(
|
||||
self, mock_logger, mock_settings, mock_credential, mock_admin_client_class
|
||||
):
|
||||
"""Test that authentication errors are logged."""
|
||||
from app.api.azure import test_azure_connection
|
||||
|
||||
mock_settings.azure_endpoint = "https://test.cognitiveservices.azure.com/"
|
||||
mock_settings.azure_ai_key = "invalid-key"
|
||||
|
||||
mock_admin_client_class.side_effect = azure.core.exceptions.ClientAuthenticationError("Auth failed")
|
||||
|
||||
mock_request = Mock()
|
||||
await test_azure_connection(mock_request)
|
||||
|
||||
# Verify error was logged
|
||||
mock_logger.error.assert_called()
|
||||
error_message = mock_logger.error.call_args[0][0]
|
||||
assert "authentication error" in error_message.lower()
|
||||
|
||||
@patch("app.api.azure.DocumentIntelligenceAdministrationClient")
|
||||
@patch("app.api.azure.AzureKeyCredential")
|
||||
@patch("app.api.azure.settings")
|
||||
@patch("app.api.azure.logger")
|
||||
@pytest.mark.asyncio
|
||||
async def test_azure_connection_logs_service_request_error(
|
||||
self, mock_logger, mock_settings, mock_credential, mock_admin_client_class
|
||||
):
|
||||
"""Test that service request errors are logged."""
|
||||
from app.api.azure import test_azure_connection
|
||||
|
||||
mock_settings.azure_endpoint = "https://test.cognitiveservices.azure.com/"
|
||||
mock_settings.azure_ai_key = "test-key"
|
||||
|
||||
mock_admin_client_class.side_effect = azure.core.exceptions.ServiceRequestError("Network error")
|
||||
|
||||
mock_request = Mock()
|
||||
await test_azure_connection(mock_request)
|
||||
|
||||
# Verify error was logged
|
||||
mock_logger.error.assert_called()
|
||||
error_message = mock_logger.error.call_args[0][0]
|
||||
assert "service request error" in error_message.lower()
|
||||
|
||||
@patch("app.api.azure.DocumentIntelligenceAdministrationClient")
|
||||
@patch("app.api.azure.AzureKeyCredential")
|
||||
@patch("app.api.azure.settings")
|
||||
@patch("app.api.azure.logger")
|
||||
@pytest.mark.asyncio
|
||||
async def test_azure_connection_logs_value_error(
|
||||
self, mock_logger, mock_settings, mock_credential, mock_admin_client_class
|
||||
):
|
||||
"""Test that value errors are logged."""
|
||||
from app.api.azure import test_azure_connection
|
||||
|
||||
mock_settings.azure_endpoint = "invalid"
|
||||
mock_settings.azure_ai_key = "test-key"
|
||||
|
||||
mock_admin_client_class.side_effect = ValueError("Invalid config")
|
||||
|
||||
mock_request = Mock()
|
||||
await test_azure_connection(mock_request)
|
||||
|
||||
# Verify error was logged
|
||||
mock_logger.error.assert_called()
|
||||
error_message = mock_logger.error.call_args[0][0]
|
||||
assert "value error" in error_message.lower()
|
||||
|
||||
@patch("app.api.azure.DocumentIntelligenceAdministrationClient")
|
||||
@patch("app.api.azure.AzureKeyCredential")
|
||||
@patch("app.api.azure.settings")
|
||||
@patch("app.api.azure.logger")
|
||||
@pytest.mark.asyncio
|
||||
async def test_azure_connection_logs_unexpected_inner_error(
|
||||
self, mock_logger, mock_settings, mock_credential, mock_admin_client_class
|
||||
):
|
||||
"""Test that unexpected errors in inner try block are logged."""
|
||||
from app.api.azure import test_azure_connection
|
||||
|
||||
mock_settings.azure_endpoint = "https://test.cognitiveservices.azure.com/"
|
||||
mock_settings.azure_ai_key = "test-key"
|
||||
|
||||
mock_admin_client_class.side_effect = RuntimeError("Something went wrong")
|
||||
|
||||
mock_request = Mock()
|
||||
await test_azure_connection(mock_request)
|
||||
|
||||
# Verify error was logged
|
||||
mock_logger.error.assert_called()
|
||||
error_message = mock_logger.error.call_args[0][0]
|
||||
assert "unexpected error" in error_message.lower()
|
||||
|
||||
@patch("app.api.azure.settings")
|
||||
@patch("app.api.azure.logger")
|
||||
@pytest.mark.asyncio
|
||||
async def test_azure_connection_logs_outer_exception(self, mock_logger, mock_settings):
|
||||
"""Test that exceptions in outer try block are logged with exception()."""
|
||||
from unittest.mock import PropertyMock
|
||||
|
||||
from app.api.azure import test_azure_connection
|
||||
|
||||
# Trigger an exception in the outer try block
|
||||
# Use PropertyMock to raise exception when azure_endpoint is accessed
|
||||
type(mock_settings).azure_endpoint = PropertyMock(side_effect=RuntimeError("Outer error"))
|
||||
type(mock_settings).azure_ai_key = PropertyMock(return_value="test-key")
|
||||
|
||||
mock_request = Mock()
|
||||
result = await test_azure_connection(mock_request)
|
||||
|
||||
# Should catch the exception and return error
|
||||
assert result["status"] == "error"
|
||||
assert "unexpected error" in result["message"].lower()
|
||||
|
||||
# Verify exception was logged with logger.exception
|
||||
mock_logger.exception.assert_called_once()
|
||||
|
||||
@patch("app.api.azure.DocumentIntelligenceAdministrationClient")
|
||||
@patch("app.api.azure.AzureKeyCredential")
|
||||
@patch("app.api.azure.settings")
|
||||
@patch("app.api.azure.logger")
|
||||
@pytest.mark.asyncio
|
||||
async def test_azure_connection_logs_operations_parsing_warning(
|
||||
self, mock_logger, mock_settings, mock_credential, mock_admin_client_class
|
||||
):
|
||||
"""Test that warning is logged when operations parsing fails."""
|
||||
from unittest.mock import PropertyMock
|
||||
|
||||
from app.api.azure import test_azure_connection
|
||||
|
||||
mock_settings.azure_endpoint = "https://test.cognitiveservices.azure.com/"
|
||||
mock_settings.azure_ai_key = "test-key"
|
||||
|
||||
mock_client = MagicMock()
|
||||
# Create an operation that will raise exception during attribute access
|
||||
mock_op = MagicMock()
|
||||
mock_op.operation_id = "valid-id"
|
||||
# Make status property raise an exception using PropertyMock
|
||||
type(mock_op).status = PropertyMock(side_effect=RuntimeError("Status error"))
|
||||
mock_client.list_operations.return_value = iter([mock_op])
|
||||
mock_admin_client_class.return_value = mock_client
|
||||
|
||||
mock_request = Mock()
|
||||
result = await test_azure_connection(mock_request)
|
||||
|
||||
# Should still succeed with warning
|
||||
assert result["status"] == "success"
|
||||
assert "couldn't retrieve operations details" in result["message"]
|
||||
# Warning should be logged
|
||||
mock_logger.warning.assert_called()
|
||||
warning_message = str(mock_logger.warning.call_args[0][0])
|
||||
assert "parse" in warning_message.lower() or "operations" in warning_message.lower()
|
||||
|
||||
@patch("app.api.azure.settings")
|
||||
@pytest.mark.asyncio
|
||||
async def test_azure_connection_outer_exception_handler(self, mock_settings):
|
||||
"""Test the outer exception handler catches unexpected errors."""
|
||||
from unittest.mock import PropertyMock
|
||||
|
||||
from app.api.azure import test_azure_connection
|
||||
|
||||
# Create a mock that raises exception when azure_endpoint is accessed using PropertyMock
|
||||
type(mock_settings).azure_endpoint = PropertyMock(side_effect=RuntimeError("Outer error"))
|
||||
type(mock_settings).azure_ai_key = PropertyMock(return_value="test-key")
|
||||
|
||||
mock_request = Mock()
|
||||
result = await test_azure_connection(mock_request)
|
||||
|
||||
# Should catch the exception and return error
|
||||
assert result["status"] == "error"
|
||||
assert "unexpected error" in result["message"].lower()
|
||||
|
||||
|
||||
@pytest.mark.unit
|
||||
class TestAzureModuleStructure:
|
||||
|
||||
@@ -273,3 +273,315 @@ class TestTaskLogCollector:
|
||||
assert collector.drain("no closing bracket") == ""
|
||||
|
||||
logger.removeHandler(collector)
|
||||
|
||||
def test_collector_handles_exception_in_emit(self):
|
||||
"""Test that the collector handles exceptions gracefully during emit."""
|
||||
from app.utils.logging import TaskLogCollector
|
||||
|
||||
collector = TaskLogCollector()
|
||||
# Don't set a formatter to trigger an edge case
|
||||
|
||||
logger = logging.getLogger("test_exception")
|
||||
logger.addHandler(collector)
|
||||
logger.setLevel(logging.DEBUG)
|
||||
|
||||
# This should not raise even if format() fails
|
||||
try:
|
||||
# Try to trigger an exception by causing issues with bracket parsing
|
||||
logger.info("][ backwards brackets")
|
||||
# Should handle gracefully
|
||||
except Exception:
|
||||
pytest.fail("Collector should handle exceptions gracefully")
|
||||
|
||||
logger.removeHandler(collector)
|
||||
|
||||
|
||||
@pytest.mark.unit
|
||||
class TestLogTaskProgressWithFileProcessingStep:
|
||||
"""Test log_task_progress with FileProcessingStep interactions."""
|
||||
|
||||
@patch("app.utils.logging.SessionLocal")
|
||||
@patch("app.utils.logging.ProcessingLog")
|
||||
@patch("app.utils.logging.FileProcessingStep")
|
||||
@patch("app.utils.logging.datetime")
|
||||
def test_creates_new_file_processing_step_with_in_progress_status(
|
||||
self, mock_datetime, mock_file_step, mock_processing_log, mock_session_local
|
||||
):
|
||||
"""Test creating a new FileProcessingStep with in_progress status."""
|
||||
from app.utils.logging import log_task_progress
|
||||
|
||||
# Setup mocks
|
||||
mock_db = MagicMock()
|
||||
mock_session_local.return_value.__enter__.return_value = mock_db
|
||||
|
||||
# No existing step record
|
||||
mock_db.query.return_value.filter.return_value.first.return_value = None
|
||||
|
||||
# Mock datetime
|
||||
from datetime import datetime as dt
|
||||
from datetime import timezone
|
||||
|
||||
mock_now = dt(2024, 1, 1, 12, 0, 0, tzinfo=timezone.utc)
|
||||
mock_datetime.now.return_value = mock_now
|
||||
mock_datetime.timezone = timezone
|
||||
|
||||
# Mock FileProcessingStep creation
|
||||
mock_step = Mock()
|
||||
mock_file_step.return_value = mock_step
|
||||
|
||||
log_task_progress(
|
||||
task_id="task-123",
|
||||
step_name="processing",
|
||||
status="in_progress",
|
||||
message="Starting processing",
|
||||
file_id=1,
|
||||
)
|
||||
|
||||
# Verify FileProcessingStep was created with started_at
|
||||
mock_file_step.assert_called_once()
|
||||
call_kwargs = mock_file_step.call_args[1]
|
||||
assert call_kwargs["file_id"] == 1
|
||||
assert call_kwargs["step_name"] == "processing"
|
||||
assert call_kwargs["status"] == "in_progress"
|
||||
assert call_kwargs["started_at"] == mock_now
|
||||
assert call_kwargs["completed_at"] is None
|
||||
|
||||
@patch("app.utils.logging.SessionLocal")
|
||||
@patch("app.utils.logging.ProcessingLog")
|
||||
@patch("app.utils.logging.FileProcessingStep")
|
||||
@patch("app.utils.logging.datetime")
|
||||
def test_creates_new_file_processing_step_with_success_status(
|
||||
self, mock_datetime, mock_file_step, mock_processing_log, mock_session_local
|
||||
):
|
||||
"""Test creating a new FileProcessingStep with success status."""
|
||||
from app.utils.logging import log_task_progress
|
||||
|
||||
mock_db = MagicMock()
|
||||
mock_session_local.return_value.__enter__.return_value = mock_db
|
||||
|
||||
mock_db.query.return_value.filter.return_value.first.return_value = None
|
||||
|
||||
from datetime import datetime as dt
|
||||
from datetime import timezone
|
||||
|
||||
mock_now = dt(2024, 1, 1, 12, 0, 0, tzinfo=timezone.utc)
|
||||
mock_datetime.now.return_value = mock_now
|
||||
mock_datetime.timezone = timezone
|
||||
|
||||
mock_step = Mock()
|
||||
mock_file_step.return_value = mock_step
|
||||
|
||||
log_task_progress(
|
||||
task_id="task-456",
|
||||
step_name="upload",
|
||||
status="success",
|
||||
message="Upload complete",
|
||||
file_id=2,
|
||||
)
|
||||
|
||||
call_kwargs = mock_file_step.call_args[1]
|
||||
assert call_kwargs["status"] == "success"
|
||||
assert call_kwargs["started_at"] is None # Not in_progress
|
||||
assert call_kwargs["completed_at"] == mock_now # success sets completed_at
|
||||
assert call_kwargs["error_message"] is None
|
||||
|
||||
@patch("app.utils.logging.SessionLocal")
|
||||
@patch("app.utils.logging.ProcessingLog")
|
||||
@patch("app.utils.logging.FileProcessingStep")
|
||||
@patch("app.utils.logging.datetime")
|
||||
def test_creates_new_file_processing_step_with_failure_status(
|
||||
self, mock_datetime, mock_file_step, mock_processing_log, mock_session_local
|
||||
):
|
||||
"""Test creating a new FileProcessingStep with failure status."""
|
||||
from app.utils.logging import log_task_progress
|
||||
|
||||
mock_db = MagicMock()
|
||||
mock_session_local.return_value.__enter__.return_value = mock_db
|
||||
|
||||
mock_db.query.return_value.filter.return_value.first.return_value = None
|
||||
|
||||
from datetime import datetime as dt
|
||||
from datetime import timezone
|
||||
|
||||
mock_now = dt(2024, 1, 1, 12, 0, 0, tzinfo=timezone.utc)
|
||||
mock_datetime.now.return_value = mock_now
|
||||
mock_datetime.timezone = timezone
|
||||
|
||||
mock_step = Mock()
|
||||
mock_file_step.return_value = mock_step
|
||||
|
||||
log_task_progress(
|
||||
task_id="task-789",
|
||||
step_name="convert",
|
||||
status="failure",
|
||||
message="Conversion failed",
|
||||
file_id=3,
|
||||
)
|
||||
|
||||
call_kwargs = mock_file_step.call_args[1]
|
||||
assert call_kwargs["status"] == "failure"
|
||||
assert call_kwargs["completed_at"] == mock_now
|
||||
assert call_kwargs["error_message"] == "Conversion failed"
|
||||
|
||||
@patch("app.utils.logging.SessionLocal")
|
||||
@patch("app.utils.logging.ProcessingLog")
|
||||
@patch("app.utils.logging.datetime")
|
||||
def test_updates_existing_file_processing_step_in_progress_without_started_at(
|
||||
self, mock_datetime, mock_processing_log, mock_session_local
|
||||
):
|
||||
"""Test updating existing FileProcessingStep to in_progress when started_at is not set."""
|
||||
from app.utils.logging import log_task_progress
|
||||
|
||||
mock_db = MagicMock()
|
||||
mock_session_local.return_value.__enter__.return_value = mock_db
|
||||
|
||||
# Existing step without started_at
|
||||
mock_existing_step = Mock()
|
||||
mock_existing_step.started_at = None
|
||||
mock_db.query.return_value.filter.return_value.first.return_value = mock_existing_step
|
||||
|
||||
from datetime import datetime as dt
|
||||
from datetime import timezone
|
||||
|
||||
mock_now = dt(2024, 1, 1, 12, 0, 0, tzinfo=timezone.utc)
|
||||
mock_datetime.now.return_value = mock_now
|
||||
mock_datetime.timezone = timezone
|
||||
|
||||
log_task_progress(
|
||||
task_id="task-update",
|
||||
step_name="ocr",
|
||||
status="in_progress",
|
||||
message="OCR starting",
|
||||
file_id=4,
|
||||
)
|
||||
|
||||
# Verify started_at was set
|
||||
assert mock_existing_step.started_at == mock_now
|
||||
assert mock_existing_step.status == "in_progress"
|
||||
|
||||
@patch("app.utils.logging.SessionLocal")
|
||||
@patch("app.utils.logging.ProcessingLog")
|
||||
@patch("app.utils.logging.datetime")
|
||||
def test_updates_existing_file_processing_step_to_failure_with_detail(
|
||||
self, mock_datetime, mock_processing_log, mock_session_local
|
||||
):
|
||||
"""Test updating existing FileProcessingStep to failure with detail."""
|
||||
from app.utils.logging import log_task_progress
|
||||
|
||||
mock_db = MagicMock()
|
||||
mock_session_local.return_value.__enter__.return_value = mock_db
|
||||
|
||||
mock_existing_step = Mock()
|
||||
mock_existing_step.started_at = None
|
||||
mock_db.query.return_value.filter.return_value.first.return_value = mock_existing_step
|
||||
|
||||
from datetime import datetime as dt
|
||||
from datetime import timezone
|
||||
|
||||
mock_now = dt(2024, 1, 1, 12, 0, 0, tzinfo=timezone.utc)
|
||||
mock_datetime.now.return_value = mock_now
|
||||
mock_datetime.timezone = timezone
|
||||
|
||||
log_task_progress(
|
||||
task_id="task-fail",
|
||||
step_name="metadata",
|
||||
status="failure",
|
||||
message=None, # No message
|
||||
file_id=5,
|
||||
detail="Detailed error information",
|
||||
)
|
||||
|
||||
# Verify error_message uses detail when message is None
|
||||
assert mock_existing_step.error_message == "Detailed error information"
|
||||
assert mock_existing_step.status == "failure"
|
||||
|
||||
@patch("app.utils.logging.SessionLocal")
|
||||
@patch("app.utils.logging.ProcessingLog")
|
||||
@patch("app.utils.logging._collector")
|
||||
@patch("app.utils.logging._ensure_collector_installed")
|
||||
def test_log_task_progress_collects_buffered_logs(
|
||||
self, mock_ensure, mock_collector, mock_processing_log, mock_session_local
|
||||
):
|
||||
"""Test that log_task_progress collects buffered logs when detail is not provided."""
|
||||
from app.utils.logging import log_task_progress
|
||||
|
||||
mock_db = MagicMock()
|
||||
mock_session_local.return_value.__enter__.return_value = mock_db
|
||||
|
||||
# Mock collector to return buffered logs
|
||||
mock_collector.drain.return_value = "Buffered log line 1\nBuffered log line 2"
|
||||
|
||||
log_task_progress(
|
||||
task_id="task-with-logs",
|
||||
step_name="test",
|
||||
status="success",
|
||||
message="Task complete",
|
||||
)
|
||||
|
||||
# Verify collector was used
|
||||
mock_ensure.assert_called_once()
|
||||
mock_collector.drain.assert_called_once_with("task-with-logs")
|
||||
|
||||
# Verify detail was set from collected logs
|
||||
call_kwargs = mock_processing_log.call_args[1]
|
||||
assert call_kwargs["detail"] == "Buffered log line 1\nBuffered log line 2"
|
||||
|
||||
@patch("app.utils.logging.SessionLocal")
|
||||
@patch("app.utils.logging.ProcessingLog")
|
||||
@patch("app.utils.logging._collector")
|
||||
@patch("app.utils.logging._ensure_collector_installed")
|
||||
def test_log_task_progress_skips_collection_when_no_task_id(
|
||||
self, mock_ensure, mock_collector, mock_processing_log, mock_session_local
|
||||
):
|
||||
"""Test that log_task_progress skips collection when task_id is None."""
|
||||
from app.utils.logging import log_task_progress
|
||||
|
||||
mock_db = MagicMock()
|
||||
mock_session_local.return_value.__enter__.return_value = mock_db
|
||||
|
||||
log_task_progress(
|
||||
task_id=None,
|
||||
step_name="test",
|
||||
status="success",
|
||||
message="No task",
|
||||
)
|
||||
|
||||
# Verify collector was NOT used
|
||||
mock_ensure.assert_not_called()
|
||||
mock_collector.drain.assert_not_called()
|
||||
|
||||
|
||||
@pytest.mark.unit
|
||||
class TestEnsureCollectorInstalled:
|
||||
"""Test the _ensure_collector_installed function."""
|
||||
|
||||
@patch("app.utils.logging._collector_installed", False)
|
||||
@patch("app.utils.logging.logging.getLogger")
|
||||
def test_ensure_collector_installed_adds_handler(self, mock_get_logger):
|
||||
"""Test that _ensure_collector_installed adds handler when not installed."""
|
||||
from app.utils.logging import _collector, _ensure_collector_installed
|
||||
|
||||
mock_root = Mock()
|
||||
mock_root.handlers = []
|
||||
mock_get_logger.return_value = mock_root
|
||||
|
||||
_ensure_collector_installed()
|
||||
|
||||
# Verify handler was added
|
||||
mock_root.addHandler.assert_called_once_with(_collector)
|
||||
|
||||
@patch("app.utils.logging._collector_installed", False)
|
||||
@patch("app.utils.logging.logging.getLogger")
|
||||
def test_ensure_collector_installed_skips_if_already_in_handlers(self, mock_get_logger):
|
||||
"""Test that _ensure_collector_installed doesn't add duplicate handler."""
|
||||
from app.utils.logging import _collector, _ensure_collector_installed
|
||||
|
||||
mock_root = Mock()
|
||||
# Collector already in handlers
|
||||
mock_root.handlers = [_collector]
|
||||
mock_get_logger.return_value = mock_root
|
||||
|
||||
_ensure_collector_installed()
|
||||
|
||||
# Verify handler was NOT added again
|
||||
mock_root.addHandler.assert_not_called()
|
||||
|
||||
Reference in New Issue
Block a user