#!/usr/bin/env python3 """ Structured Logging Test Script Tests the comprehensive logging infrastructure with structured logging, request tracking, and proper log formatting. """ import os import sys import asyncio import json import time import tempfile from pathlib import Path # Add session-manager to path for imports sys.path.insert(0, str(Path(__file__).parent)) from logging_config import ( setup_logging, get_logger, RequestContext, log_performance, log_request, log_session_operation, log_security_event, StructuredFormatter, HumanReadableFormatter, ) # Set up logging logger = get_logger(__name__) async def test_log_formatters(): """Test JSON and human-readable formatters.""" print("๐Ÿงช Testing Log Formatters") print("=" * 50) # Test JSON formatter json_formatter = StructuredFormatter() log_record = logging.LogRecord( name="test.logger", level=logging.INFO, pathname="test.py", lineno=42, msg="Test message", args=(), exc_info=None, ) log_record.request_id = "req-123" log_record.session_id = "ses-456" json_output = json_formatter.format(log_record) parsed = json.loads(json_output) # Verify JSON structure assert "timestamp" in parsed assert parsed["level"] == "INFO" assert parsed["message"] == "Test message" assert parsed["request_id"] == "req-123" assert parsed["session_id"] == "ses-456" print("โœ… JSON formatter produces valid structured logs") # Test human-readable formatter human_formatter = HumanReadableFormatter() human_output = human_formatter.format(log_record) assert "Test message" in human_output assert "req-123" in human_output # Request ID included print("โœ… Human-readable formatter includes request context") return True async def test_request_context(): """Test request ID tracking and context management.""" print("\n๐Ÿ†” Testing Request Context") print("=" * 50) # Test context management with RequestContext("test-request-123") as ctx: assert RequestContext.get_current_request_id() == "test-request-123" print("โœ… Request context properly set") # Nested context should override with RequestContext("nested-request-456"): assert RequestContext.get_current_request_id() == "nested-request-456" print("โœ… Nested context overrides parent") # Should revert to parent assert RequestContext.get_current_request_id() == "test-request-123" print("โœ… Context properly restored after nested context") # Should be cleared after context exit assert RequestContext.get_current_request_id() is None print("โœ… Context properly cleared after exit") return True async def test_log_levels_and_filtering(): """Test different log levels and filtering.""" print("\n๐Ÿ“Š Testing Log Levels and Filtering") print("=" * 50) # Create a temporary log file with tempfile.NamedTemporaryFile(mode="w+", suffix=".log", delete=False) as f: log_file = f.name try: # Set up logging with file output test_logger = setup_logging( level="DEBUG", format_type="json", log_file=log_file, enable_console=False, enable_file=True, ) # Log messages at different levels test_logger.debug("Debug message", extra={"test": "debug"}) test_logger.info("Info message", extra={"test": "info"}) test_logger.warning("Warning message", extra={"test": "warning"}) test_logger.error("Error message", extra={"test": "error"}) # Flush logs for handler in logging.getLogger().handlers: handler.flush() # Read and verify log file with open(log_file, "r") as f: lines = f.readlines() # Should have 4 log entries assert len(lines) == 4 # Parse JSON and verify levels for line in lines: entry = json.loads(line) assert "level" in entry assert "message" in entry assert "timestamp" in entry # Verify specific messages messages = [json.loads(line)["message"] for line in lines] assert "Debug message" in messages assert "Info message" in messages assert "Warning message" in messages assert "Error message" in messages print("โœ… All log levels captured correctly") print(f"โœ… Log file contains {len(lines)} entries") finally: # Clean up if os.path.exists(log_file): os.unlink(log_file) return True async def test_structured_logging_features(): """Test structured logging features and extra fields.""" print("\n๐Ÿ”ง Testing Structured Logging Features") print("=" * 50) # Test with temporary file with tempfile.NamedTemporaryFile(mode="w+", suffix=".log", delete=False) as f: log_file = f.name try: # Set up structured logging test_logger = setup_logging( level="INFO", format_type="json", log_file=log_file, enable_console=False, enable_file=True, ) with RequestContext("req-abc-123"): # Test performance logging log_performance("test_operation", 150.5, user_id="user123", success=True) # Test request logging log_request("POST", "/api/test", 200, 45.2, user_agent="test-client") # Test session operation logging log_session_operation("session-xyz", "created", container_id="cont-123") # Test security event logging log_security_event( "authentication_success", "info", user_id="user123", ip="192.168.1.1" ) # Flush logs for handler in logging.getLogger().handlers: handler.flush() # Read and analyze logs with open(log_file, "r") as f: lines = f.readlines() # Should have multiple entries assert len(lines) >= 4 # Parse and verify structured data for line in lines: entry = json.loads(line) # All entries should have request_id assert "request_id" in entry assert entry["request_id"] == "req-abc-123" # Check for operation-specific fields if "operation" in entry: if entry["operation"] == "test_operation": assert "duration_ms" in entry assert entry["duration_ms"] == 150.5 assert entry["user_id"] == "user123" elif entry["operation"] == "http_request": assert "method" in entry assert "path" in entry assert "status_code" in entry elif entry["operation"] == "authentication_success": assert "security_event" in entry assert "severity" in entry print("โœ… All structured logging features working correctly") print(f"โœ… Generated {len(lines)} structured log entries") finally: if os.path.exists(log_file): os.unlink(log_file) return True async def test_environment_configuration(): """Test logging configuration from environment variables.""" print("\n๐ŸŒ Testing Environment Configuration") print("=" * 50) # Save original environment original_env = {} test_vars = [ ("LOG_LEVEL", "DEBUG"), ("LOG_FORMAT", "human"), ("LOG_FILE", "/tmp/test-env-log.log"), ("LOG_MAX_SIZE_MB", "5"), ("LOG_BACKUP_COUNT", "2"), ("LOG_CONSOLE", "false"), ("LOG_FILE_ENABLED", "true"), ] for var, _ in test_vars: original_env[var] = os.environ.get(var) try: # Set test environment for var, value in test_vars: os.environ[var] = value # Re-initialize logging from logging_config import init_logging init_logging() # Verify configuration applied root_logger = logging.getLogger() # Check level (DEBUG = 10) assert root_logger.level == 10 # Check handlers file_handlers = [ h for h in root_logger.handlers if isinstance(h, logging.handlers.RotatingFileHandler) ] console_handlers = [ h for h in root_logger.handlers if isinstance(h, logging.StreamHandler) ] assert len(file_handlers) == 1, "Should have one file handler" assert len(console_handlers) == 0, "Should have no console handlers (disabled)" # Check file handler configuration file_handler = file_handlers[0] assert file_handler.baseFilename == "/tmp/test-env-log.log" print("โœ… Environment-based logging configuration working") print("โœ… Log level set to DEBUG") print("โœ… File logging enabled, console disabled") print("โœ… Log rotation configured correctly") finally: # Clean up test log file if os.path.exists("/tmp/test-env-log.log"): os.unlink("/tmp/test-env-log.log") # Restore original environment for var, original_value in original_env.items(): if original_value is not None: os.environ[var] = original_value elif var in os.environ: del os.environ[var] async def run_all_logging_tests(): """Run all structured logging tests.""" print("๐Ÿ“ Structured Logging Test Suite") print("=" * 70) tests = [ ("Log Formatters", test_log_formatters), ("Request Context", test_request_context), ("Log Levels and Filtering", test_log_levels_and_filtering), ("Structured Logging Features", test_structured_logging_features), ("Environment Configuration", test_environment_configuration), ] results = [] for test_name, test_func in tests: print(f"\n{'=' * 25} {test_name} {'=' * 25}") try: result = await test_func() results.append(result) status = "โœ… PASSED" if result else "โŒ FAILED" print(f"\n{status}: {test_name}") except Exception as e: print(f"\nโŒ ERROR in {test_name}: {e}") results.append(False) # Summary print(f"\n{'=' * 70}") passed = sum(results) total = len(results) print(f"๐Ÿ“Š Test Results: {passed}/{total} tests passed") if passed == total: print("๐ŸŽ‰ All structured logging tests completed successfully!") print("๐Ÿ” Logging infrastructure provides comprehensive observability.") else: print("โš ๏ธ Some tests failed. Check the output above for details.") print("๐Ÿ’ก Ensure proper file permissions for log file creation.") return passed == total if __name__ == "__main__": asyncio.run(run_all_logging_tests())