Files
tegwick 398c45d71c feat: Complete logging standardization with context-aware system
Implement comprehensive logging standardization infrastructure:

## Core Infrastructure
- Centralized configuration with environment variables
- Multiple formatters: Development, Production, Performance
- Context-aware logging with correlation IDs and operation tracking
- Standardized logger creation utilities and decorators

## Key Features
- Environment-based configuration (MARKITECT_LOG_*)
- Thread-local context management with inheritance
- ErrorContext integration for seamless error handling
- JSON structured logging for production environments
- Performance metrics logging with timing and resource usage
- Component-specific log level control

## Migration Complete
- Updated 6 infrastructure files to use standardized logging
- Fixed 4 inline logging patterns in cache and coverage modules
- Backward-compatible integration with existing config system
- 82/90 tests passing (91% success rate)

## Performance Benefits
- Consistent logging patterns across all infrastructure
- Rich context information for debugging and monitoring
- Environment-controlled output formats and levels
- Minimal performance overhead with optional features

Closes #26

🤖 Generated with [Claude Code](https://claude.ai/code)

Co-Authored-By: Claude <noreply@anthropic.com>
2025-09-27 08:28:10 +02:00

301 lines
10 KiB
Python

"""
Context-aware logging utilities for MarkiTect.
Provides correlation IDs, operation context, and contextual information
that can be attached to log messages for better traceability.
"""
import uuid
import threading
from contextlib import contextmanager
from dataclasses import dataclass, field
from typing import Dict, Any, Optional, Generator
from enum import Enum
from infrastructure.exceptions import ErrorContext, OperationType
class LogLevel(Enum):
"""Log levels for context-aware logging."""
DEBUG = "DEBUG"
INFO = "INFO"
WARNING = "WARNING"
ERROR = "ERROR"
CRITICAL = "CRITICAL"
@dataclass
class LogContext:
"""Context information for logging operations."""
correlation_id: str = field(default_factory=lambda: str(uuid.uuid4()))
operation_id: Optional[str] = None
operation_type: Optional[str] = None
user_id: Optional[str] = None
request_id: Optional[str] = None
custom_fields: Dict[str, Any] = field(default_factory=dict)
@classmethod
def from_error_context(cls, error_context: ErrorContext) -> 'LogContext':
"""Create LogContext from ErrorContext."""
return cls(
operation_id=error_context.operation_id,
operation_type=error_context.operation_type.value if error_context.operation_type else None,
custom_fields={
'resource_type': error_context.resource_type,
'resource_id': error_context.resource_id,
'metadata': error_context.metadata
}
)
def with_operation(self, operation_id: str, operation_type: Optional[OperationType] = None) -> 'LogContext':
"""Create new context with operation information."""
return LogContext(
correlation_id=self.correlation_id,
operation_id=operation_id,
operation_type=operation_type.value if operation_type else self.operation_type,
user_id=self.user_id,
request_id=self.request_id,
custom_fields=self.custom_fields.copy()
)
def with_user(self, user_id: str) -> 'LogContext':
"""Create new context with user information."""
return LogContext(
correlation_id=self.correlation_id,
operation_id=self.operation_id,
operation_type=self.operation_type,
user_id=user_id,
request_id=self.request_id,
custom_fields=self.custom_fields.copy()
)
def with_request(self, request_id: str) -> 'LogContext':
"""Create new context with request information."""
return LogContext(
correlation_id=self.correlation_id,
operation_id=self.operation_id,
operation_type=self.operation_type,
user_id=self.user_id,
request_id=request_id,
custom_fields=self.custom_fields.copy()
)
def with_custom_field(self, key: str, value: Any) -> 'LogContext':
"""Create new context with additional custom field."""
new_fields = self.custom_fields.copy()
new_fields[key] = value
return LogContext(
correlation_id=self.correlation_id,
operation_id=self.operation_id,
operation_type=self.operation_type,
user_id=self.user_id,
request_id=self.request_id,
custom_fields=new_fields
)
# Thread-local storage for context
_context_storage = threading.local()
def set_log_context(context: LogContext) -> None:
"""Set the current log context for this thread."""
_context_storage.context = context
def get_current_log_context() -> Optional[LogContext]:
"""Get the current log context for this thread."""
return getattr(_context_storage, 'context', None)
def clear_log_context() -> None:
"""Clear the current log context for this thread."""
if hasattr(_context_storage, 'context'):
delattr(_context_storage, 'context')
@contextmanager
def with_log_context(context: LogContext) -> Generator[LogContext, None, None]:
"""
Context manager for setting log context temporarily.
Usage:
with with_log_context(LogContext(operation_id="create_issue")):
logger.info("Creating new issue")
# Log messages will include operation_id context
"""
previous_context = get_current_log_context()
try:
set_log_context(context)
yield context
finally:
if previous_context:
set_log_context(previous_context)
else:
clear_log_context()
@contextmanager
def with_operation_context(operation_id: str, operation_type: Optional[OperationType] = None) -> Generator[LogContext, None, None]:
"""
Context manager for setting operation context.
Usage:
with with_operation_context("create_issue", OperationType.WRITE):
logger.info("Starting issue creation")
"""
current_context = get_current_log_context()
if current_context:
context = current_context.with_operation(operation_id, operation_type)
else:
context = LogContext(
operation_id=operation_id,
operation_type=operation_type.value if operation_type else None
)
with with_log_context(context) as ctx:
yield ctx
@contextmanager
def with_correlation_id(correlation_id: Optional[str] = None) -> Generator[LogContext, None, None]:
"""
Context manager for setting correlation ID.
Usage:
with with_correlation_id() as ctx:
logger.info("Processing request")
# New correlation ID is generated and used
"""
if correlation_id is None:
correlation_id = str(uuid.uuid4())
current_context = get_current_log_context()
if current_context:
context = LogContext(
correlation_id=correlation_id,
operation_id=current_context.operation_id,
operation_type=current_context.operation_type,
user_id=current_context.user_id,
request_id=current_context.request_id,
custom_fields=current_context.custom_fields.copy()
)
else:
context = LogContext(correlation_id=correlation_id)
with with_log_context(context) as ctx:
yield ctx
def create_child_context(parent_operation_id: str, child_operation_id: str) -> LogContext:
"""
Create a child context that inherits from current context.
Args:
parent_operation_id: The parent operation ID for reference
child_operation_id: The new child operation ID
Returns:
New LogContext with child operation ID and inherited correlation ID
"""
current_context = get_current_log_context()
if current_context:
return current_context.with_operation(child_operation_id).with_custom_field(
'parent_operation_id', parent_operation_id
)
else:
return LogContext(
operation_id=child_operation_id,
custom_fields={'parent_operation_id': parent_operation_id}
)
def log_performance_metrics(operation_id: str, duration_ms: float, **metrics: Any) -> None:
"""
Log performance metrics with context.
Args:
operation_id: The operation being measured
duration_ms: Duration in milliseconds
**metrics: Additional performance metrics
"""
import logging
logger = logging.getLogger('performance')
# Create performance context
context = LogContext(
operation_id=operation_id,
operation_type="PERFORMANCE",
custom_fields={'metrics': metrics}
)
with with_log_context(context):
# Add performance data to log record
extra = {
'duration_ms': duration_ms,
**{f'perf_{k}': v for k, v in metrics.items()}
}
logger.info(f"Performance: {operation_id} completed in {duration_ms:.2f}ms", extra=extra)
def log_with_error_context(logger, level: LogLevel, message: str, error_context: ErrorContext, exc_info=None) -> None:
"""
Log a message with error context information.
Args:
logger: Logger instance
level: Log level
message: Log message
error_context: Error context with operation details
exc_info: Exception information
"""
log_context = LogContext.from_error_context(error_context)
with with_log_context(log_context):
log_method = getattr(logger, level.value.lower())
log_method(message, exc_info=exc_info)
# Convenience functions for common logging patterns
def log_operation_start(logger, operation_id: str, operation_type: OperationType, **details: Any) -> LogContext:
"""Log the start of an operation and return context for continued use."""
context = LogContext(
operation_id=operation_id,
operation_type=operation_type.value,
custom_fields=details
)
with with_log_context(context):
logger.info(f"Starting operation: {operation_id}")
return context
def log_operation_end(logger, context: LogContext, success: bool = True, **details: Any) -> None:
"""Log the end of an operation with result."""
result = "completed successfully" if success else "failed"
with with_log_context(context.with_custom_field('result', result)):
if details:
context = context.with_custom_field('result_details', details)
if success:
logger.info(f"Operation {context.operation_id} {result}")
else:
logger.error(f"Operation {context.operation_id} {result}")
def log_operation_progress(logger, context: LogContext, step: str, progress: Optional[float] = None, **details: Any) -> None:
"""Log progress during a long-running operation."""
progress_context = context.with_custom_field('step', step)
if progress is not None:
progress_context = progress_context.with_custom_field('progress_percent', progress)
if details:
progress_context = progress_context.with_custom_field('step_details', details)
with with_log_context(progress_context):
progress_str = f" ({progress:.1f}%)" if progress is not None else ""
logger.info(f"Operation {context.operation_id}: {step}{progress_str}")