diff --git a/.gitignore b/.gitignore index b1fa5db..e628185 100644 --- a/.gitignore +++ b/.gitignore @@ -266,4 +266,5 @@ htmlcov/ # Custom TODO.md notes.md -scratch/ \ No newline at end of file +scratch/ +.serena/ diff --git a/.serena/.gitignore b/.serena/.gitignore new file mode 100644 index 0000000..14d86ad --- /dev/null +++ b/.serena/.gitignore @@ -0,0 +1 @@ +/cache diff --git a/Makefile b/Makefile index 4e88469..5ec7e06 100644 --- a/Makefile +++ b/Makefile @@ -1,8 +1,8 @@ -.PHONY: default help clean-project init clean-env sync format lint type-check test test-unit test-functional test-integration test-all validate-branch +.PHONY: default help clean-project init clean-env sync format lint type-check test test-unit test-functional test-integration test-all validate-branch run GREEN_LINE=@echo "\033[0;32m--------------------------------------------------\033[0m" -SOURCE_DIR = ai_base_template/ +SOURCE_DIR = src/ TEST_DIR = tests/ PROJECT_VERSION := $(shell awk '/^\[project\]/ {flag=1; next} /^\[/{flag=0} flag && /^version/ {gsub(/"/, "", $$2); print $$2}' pyproject.toml) PYTHON_VERSION := 3.12 @@ -97,7 +97,7 @@ test-integration: ## Run integration tests with pytest test: ## Run standard tests with coverage report (excludes integration) @echo "Running tests with pytest..." uv run python -m pytest -m "not integration" -vv -s $(TEST_DIR) \ - --cov=ai_base_template \ + --cov=src \ --cov-config=pyproject.toml \ --cov-fail-under=80 \ --cov-report=term-missing @@ -106,7 +106,7 @@ test: ## Run standard tests with coverage report (excludes integration) test-all: ## Run all tests including integration tests @echo "Running ALL tests with pytest..." uv run python -m pytest -vv -s $(TEST_DIR) \ - --cov=ai_base_template \ + --cov=src \ --cov-config=pyproject.toml \ --cov-fail-under=80 \ --cov-report=term-missing @@ -125,3 +125,12 @@ validate-branch: ## Run formatting, linting, type checks, and tests @echo "🎉 Branch validation successful - ready for PR!" $(GREEN_LINE) +# ---------------------------- +# Run Application +# ---------------------------- + +run: ## Run the main application module + @echo "🚀 Running main application..." + uv run python -m src.main + $(GREEN_LINE) + diff --git a/README.md b/README.md index d392093..6fb0530 100644 --- a/README.md +++ b/README.md @@ -92,7 +92,7 @@ make test-all # Complete test suite ``` ai-base-template/ -├── ai_base_template/ # Your service code goes here +├── src/ # Your service code goes here │ ├── __init__.py │ ├── main.py # Simple starting point with logging integration │ └── logging.py # Production structured logging system @@ -123,17 +123,17 @@ This template includes a **production-grade structured logging system** built wi ### Dual-Mode Logging -**Development Mode** - Human-readable format for debugging: +**Development Mode** - Human-readable format optimized for local debugging: ```bash -22:45:00 [INFO] main: Processing request [HTTP 200, 150ms, user_id=user-123] [id:req-abc12] +22:45:00 [INFO] api.handlers: Processing request [status_code=200, duration_ms=150, user_id=user-123] [id:req-abc1] ``` -**Production Mode** - Structured JSON for monitoring systems: +**Production Mode** - Structured JSON for monitoring and analytics: ```json { "timestamp": "2025-08-31T22:45:00.123Z", "level": "info", - "logger": "main", + "logger": "src.api.handlers", "message": "Processing request", "context": "default", "extra": { @@ -145,38 +145,17 @@ This template includes a **production-grade structured logging system** built wi } ``` -### Built-in Features +### Key Capabilities -- **Correlation ID Tracking** - Trace requests across your entire system -- **Context Isolation** - Prevent data leakage between concurrent requests -- **Smart Field Organization** - Important fields (status_code, duration_ms) formatted for readability -- **Environment-Driven Configuration** - `LOGGING_LEVEL` and `LITELLM_LOG_LEVEL` support -- **Logger Name Abbreviation** - Clean, readable logger names in development +- **Correlation ID Tracking** - Automatically trace requests across your entire system +- **Context Isolation** - Prevent data leakage between concurrent requests and operations +- **Smart Field Organization** - Separates standard fields from custom data for optimal readability +- **Environment-Driven Configuration** - Dynamic log levels and format switching via environment variables +- **Edge Case Handling** - Graceful handling of long values, special characters, and null data ### Usage Example -```python -from ai_base_template.logging import configure_structlog, get_logger, bind_contextvars - -# Configure for your environment -configure_structlog(testing=False) # Production JSON output -logger = get_logger(__name__) - -# Bind correlation ID at request start -bind_contextvars(correlation_id="req-123", user_id="user-456") - -# All subsequent logs will include context automatically -logger.info("Processing AI request", model="gpt-4", tokens=150) -logger.info("Request completed", status_code=200, duration_ms=1200) -``` - -### Integration with AI Systems - -The logging system is specifically designed for AI/ML production requirements: -- **Cost tracking** with built-in fields for model usage -- **Performance monitoring** with latency and token usage -- **Request tracing** across complex AI pipelines -- **Error categorization** for model vs. infrastructure failures +See `src/main.py` for a complete demonstration of the logging system in action, including context binding, multi-function logging, and both development and production formatting modes. ## 📚 Learn More diff --git a/ai_base_template/logging.py b/ai_base_template/logging.py deleted file mode 100644 index 5cecd31..0000000 --- a/ai_base_template/logging.py +++ /dev/null @@ -1,179 +0,0 @@ -import logging -import os -import sys -from typing import Any - -import structlog -from structlog.types import EventDict, WrappedLogger - -LOG_SPECIFIC_FIELDS = { - "timestamp", - "logger", - "message", - "context", - "level", -} - - -def _process_log_fields(logger: WrappedLogger, log_method: str, event_dict: EventDict) -> EventDict: - # Rename "event" to "message" - event_dict["message"] = event_dict.pop("event", "") - event_dict["context"] = structlog.contextvars.get_contextvars().get("context", "default") - - # Create the "extra" dictionary for unexpected keys - extra_fields = {key: event_dict.pop(key) for key in list(event_dict.keys()) if key not in LOG_SPECIFIC_FIELDS} - - # Add the "extra" dictionary if it contains any fields - if extra_fields: - event_dict["extra"] = extra_fields - - return event_dict - - -def _abbreviate_logger_name(logger_name: str) -> str: - """Abbreviate logger names for readable output.""" - if not logger_name.startswith("ai_base_template"): - return logger_name - - # Remove the ai_base_template prefix and return the meaningful part - parts = logger_name.replace("ai_base_template.", "").split(".") - - # Keep last 2 parts for context (e.g., "core.chat", "services.llm") - if len(parts) >= 2: - return f"{parts[-2]}.{parts[-1]}" - return parts[-1] if parts else logger_name - - -def _format_extra_fields(extra: dict[str, Any]) -> str: - """Format extra fields for human-readable output.""" - if not extra: - return "" - - # Prioritize important fields - important_keys = ["status_code", "duration_ms", "response_size_bytes", "error", "sql_query"] - formatted_parts = [] - - # Add important fields first - for key in important_keys: - if key in extra: - value = extra[key] - if key == "duration_ms": - formatted_parts.append(f"{value}ms") - elif key == "status_code": - formatted_parts.append(f"HTTP {value}") - elif key == "response_size_bytes": - formatted_parts.append(f"{value}B") - else: - formatted_parts.append(f"{key}={value}") - - # Add remaining fields - remaining = {k: v for k, v in extra.items() if k not in important_keys} - for key, value in remaining.items(): - if len(str(value)) > 50: # Truncate long values - formatted_parts.append(f"{key}={str(value)[:47]}...") - else: - formatted_parts.append(f"{key}={value}") - - return f" [{', '.join(formatted_parts)}]" if formatted_parts else "" - - -class HumanReadableRenderer: - """Human-readable log formatter for testing environments.""" - - def __call__(self, logger: WrappedLogger, log_method: str, event_dict: EventDict) -> str: - """Render log entry in human-readable format: HH:MM:SS [LEVEL] logger: message [key_info] [correlation_id]""" - # Extract components - timestamp = event_dict.get("timestamp", "") - level = event_dict.get("level", "").upper() - logger_name = _abbreviate_logger_name(event_dict.get("logger", "")) - message = event_dict.get("message", "") - extra = event_dict.get("extra", {}) - correlation_id = structlog.contextvars.get_contextvars().get("correlation_id", "") - - # Format timestamp to HH:MM:SS - time_part = "" - if timestamp: - try: - # Extract time from ISO timestamp (e.g., "2025-01-27T14:30:45.123456") - if "T" in timestamp: - time_part = timestamp.split("T")[1].split(".")[0] # Get HH:MM:SS part - else: - time_part = timestamp.split(" ")[1].split(".")[0] if " " in timestamp else timestamp - except (IndexError, AttributeError): - time_part = timestamp - - # Build the formatted message - parts = [] - if time_part: - parts.append(time_part) - if level: - parts.append(f"[{level}]") - if logger_name: - parts.append(f"{logger_name}:") - if message: - parts.append(message) - - base_message = " ".join(parts) - - # Add extra fields if present - extra_str = _format_extra_fields(extra) - if extra_str: - base_message += extra_str - - # Add correlation ID if present - if correlation_id: - base_message += f" [id:{correlation_id[:8]}]" - - return base_message - - -def configure_structlog(testing: bool = False) -> None: - """Configure structured logging with JSON or human-readable output format.""" - # Get logging level from environment or default to INFO - log_level = os.environ.get("LOGGING_LEVEL", "INFO").upper() - level = getattr(logging, log_level, logging.INFO) - - logging.basicConfig(format="%(message)s", level=level, stream=sys.stdout) - logging.getLogger().setLevel(level) - - # Silence LiteLLM's verbose logging - let our app control what gets logged - litellm_logger = logging.getLogger("LiteLLM") - litellm_log_level = os.environ.get("LITELLM_LOG_LEVEL", "WARNING").upper() - litellm_level = getattr(logging, litellm_log_level, logging.WARNING) - litellm_logger.setLevel(litellm_level) - - # Common processors - base_processors = [ - structlog.stdlib.add_log_level, - structlog.stdlib.add_logger_name, - structlog.contextvars.merge_contextvars, - _process_log_fields, - structlog.processors.TimeStamper(fmt="iso"), - ] - - # Add renderer based on testing flag - renderer = HumanReadableRenderer() if testing else structlog.processors.JSONRenderer() - processors = base_processors + [renderer] - - structlog.configure( - processors=processors, # type: ignore[arg-type] - logger_factory=structlog.stdlib.LoggerFactory(), - wrapper_class=structlog.make_filtering_bound_logger(level), - cache_logger_on_first_use=True, - ) - - -# Direct assignments for context management -clear_context_fields = structlog.contextvars.clear_contextvars -bind_contextvars = structlog.contextvars.bind_contextvars -get_contextvars = structlog.contextvars.get_contextvars - - -def get_correlation_id() -> str: - """Get correlation ID from context or return default.""" - contextvars = structlog.contextvars.get_contextvars() - return str(contextvars.get("correlation_id", "unknown")) - - -def get_logger(name: str = "") -> structlog.stdlib.BoundLogger: - return structlog.get_logger(name or __name__) # type: ignore diff --git a/pyproject.toml b/pyproject.toml index 836d1f9..7500b4b 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -57,7 +57,7 @@ dev = [ [tool.setuptools.packages.find] where = ["."] include = [ - "ai_base_template*", + "src*", ] [tool.ruff] diff --git a/research/EDA.ipynb b/research/EDA.ipynb index d4296b6..91e9588 100644 --- a/research/EDA.ipynb +++ b/research/EDA.ipynb @@ -14,14 +14,14 @@ "execution_count": null, "metadata": {}, "outputs": [], - "source": "# Import production code\nimport sys\nfrom pathlib import Path\n\nsys.path.append(str(Path().parent.absolute()))\n\nimport ai_base_template\nfrom ai_base_template.main import get_version, hello_world" + "source": "# Import production code\nimport sys\nfrom pathlib import Path\n\nsys.path.append(str(Path().parent.absolute()))\n\nimport src\nfrom src.main import get_version, hello_world" }, { "cell_type": "code", "execution_count": null, "metadata": {}, "outputs": [], - "source": "# Explore the package\nprint(f\"Version: {ai_base_template.__version__}\")\nprint(f\"Hello: {hello_world()}\")\nprint(f\"Get version: {get_version()}\")" + "source": "# Explore the package\nprint(f\"Version: {src.__version__}\")\nprint(f\"Hello: {hello_world()}\")\nprint(f\"Get version: {get_version()}\")" }, { "cell_type": "code", diff --git a/ai_base_template/__init__.py b/src/__init__.py similarity index 65% rename from ai_base_template/__init__.py rename to src/__init__.py index 9dd3cb2..c3647b3 100644 --- a/ai_base_template/__init__.py +++ b/src/__init__.py @@ -1,3 +1,3 @@ """AI Flora Mind - Python AI Package""" -__version__ = "1.0.6" +__version__ = "0.3.0" diff --git a/src/logging.py b/src/logging.py new file mode 100644 index 0000000..e03c517 --- /dev/null +++ b/src/logging.py @@ -0,0 +1,224 @@ +import logging +import os +import sys +from dataclasses import dataclass +from datetime import datetime +from enum import Enum +from typing import Any + +import structlog +from structlog.types import EventDict, WrappedLogger + +# ============================================================================ +# Configuration & Constants +# ============================================================================ + + +class LogKeys(str, Enum): + """Enum for log field keys to prevent typos and improve maintainability.""" + + CORRELATION_ID = "correlation_id" + CONTEXT = "context" + TIMESTAMP = "timestamp" + LOGGER = "logger" + MESSAGE = "message" + LEVEL = "level" + EXTRA = "extra" + + +@dataclass(frozen=True) +class LogDefaults: + """Default values for logging configuration.""" + + context: str = "default" + correlation_id: str = "unknown" + log_level: str = "INFO" + max_value_length: int = 50 + correlation_id_display_length: int = 8 + + +# Immutable defaults instance +DEFAULTS = LogDefaults() + + +# ============================================================================ +# Context Operations +# ============================================================================ + + +def _get_context_value(key: str, default: str) -> str: + """Get a value from context variables with fallback.""" + return str(structlog.contextvars.get_contextvars().get(key, default)) + + +def get_correlation_id() -> str: + """Get current correlation ID from context.""" + return _get_context_value(LogKeys.CORRELATION_ID.value, DEFAULTS.correlation_id) + + +# ============================================================================ +# Log Processing (Universal) +# ============================================================================ + + +def _process_log_fields(_: WrappedLogger, __: str, event_dict: EventDict) -> EventDict: + """Process log fields by restructuring event_dict for consistent formatting.""" + # Rename "event" to "message" for clarity + event_dict[LogKeys.MESSAGE.value] = event_dict.pop("event", "") + + # Add context and correlation data + event_dict[LogKeys.CONTEXT.value] = _get_context_value(LogKeys.CONTEXT.value, DEFAULTS.context) + correlation_id = _get_context_value(LogKeys.CORRELATION_ID.value, DEFAULTS.correlation_id) + + # Extract non-standard fields to 'extra' + standard_fields = ( + LogKeys.TIMESTAMP.value, + LogKeys.LOGGER.value, + LogKeys.MESSAGE.value, + LogKeys.CONTEXT.value, + LogKeys.LEVEL.value, + ) + extra_fields = {key: event_dict.pop(key) for key in list(event_dict.keys()) if key not in standard_fields} + + # Add correlation ID to extra if it's not the default + if correlation_id != DEFAULTS.correlation_id: + extra_fields[LogKeys.CORRELATION_ID.value] = correlation_id + + # Add extra fields if any exist + if extra_fields: + event_dict[LogKeys.EXTRA.value] = extra_fields + + return event_dict + + +# ============================================================================ +# Human-Readable Formatting +# ============================================================================ + + +class HumanReadableFormatter: + """Encapsulates human-readable log formatting logic for structlog processor.""" + + def __init__(self, defaults: LogDefaults = DEFAULTS): + self.defaults = defaults + + def __call__(self, _: WrappedLogger, __: str, event_dict: EventDict) -> str: + """Format EventDict for human-readable output (structlog processor). + + Format: HH:MM:SS [LEVEL] logger: message [key_info] [correlation_id] + """ + # Extract key components with safe defaults + level = event_dict.get(LogKeys.LEVEL.value, "info").upper() + logger_name = self.format_logger_name(event_dict.get(LogKeys.LOGGER.value, "")) + message = event_dict.get(LogKeys.MESSAGE.value, "") + timestamp = event_dict.get(LogKeys.TIMESTAMP.value, "") + extra = event_dict.get(LogKeys.EXTRA.value, {}) + + # Format components + time_str = self.format_timestamp(timestamp) + extra_str = self.format_extra_fields(extra) + correlation_id = extra.get(LogKeys.CORRELATION_ID.value, "") + corr_str = self.format_correlation_id(correlation_id) + + return f"{time_str} [{level}] {logger_name}: {message}{extra_str}{corr_str}" + + def format_field_value(self, value: Any) -> str: + """Format a single field value, truncating if too long.""" + str_value = str(value) + if len(str_value) > self.defaults.max_value_length: + return f"{str_value[: self.defaults.max_value_length - 3]}..." + return str_value + + def format_timestamp(self, timestamp_str: str) -> str: + """Convert ISO timestamp to HH:MM:SS format.""" + if not timestamp_str: + return "" + + try: + # Parse ISO timestamp and format as HH:MM:SS + dt = datetime.fromisoformat(timestamp_str.replace("Z", "+00:00")) + return dt.strftime("%H:%M:%S") + except (ValueError, AttributeError): + # Fallback: try to extract time portion manually + return timestamp_str.split("T")[1][:8] if "T" in timestamp_str else "" + + def format_correlation_id(self, correlation_id: str) -> str: + """Format correlation ID for display, truncating to readable length.""" + if not correlation_id: + return "" + truncated = correlation_id[: self.defaults.correlation_id_display_length] + return f" [id:{truncated}]" + + def format_logger_name(self, logger_name: str) -> str: + if not logger_name.startswith("src"): + return logger_name + + # Remove the src prefix and return the meaningful part + parts = logger_name.replace("src.", "").split(".") + + # Keep last 2 parts for context (e.g., "core.chat", "services.llm") + if len(parts) >= 2: + return f"{parts[-2]}.{parts[-1]}" + return parts[-1] if parts else logger_name + + def format_extra_fields(self, extra: dict[str, Any]) -> str: + if not extra: + return "" + + formatted_parts = [f"{key}={self.format_field_value(value)}" for key, value in extra.items()] + return f" [{', '.join(formatted_parts)}]" + + +# ============================================================================ +# Configuration +# ============================================================================ + + +def configure_structlog(testing: bool = False) -> None: + """Configure structured logging with JSON or human-readable output format.""" + # Get logging level from environment with default + log_level = os.environ.get("LOGGING_LEVEL", DEFAULTS.log_level).upper() + level = getattr(logging, log_level, logging.INFO) + + logging.basicConfig(format="%(message)s", level=level, stream=sys.stdout) + logging.getLogger().setLevel(level) + + # Build processor pipeline + processors = [ + structlog.stdlib.add_log_level, + structlog.stdlib.add_logger_name, + structlog.contextvars.merge_contextvars, + _process_log_fields, + structlog.processors.TimeStamper(fmt="iso"), + HumanReadableFormatter() if testing else structlog.processors.JSONRenderer(), + ] + + structlog.configure( + processors=processors, # type: ignore[arg-type] + logger_factory=structlog.stdlib.LoggerFactory(), + wrapper_class=structlog.make_filtering_bound_logger(level), + cache_logger_on_first_use=True, + ) + + +# ============================================================================ +# Public API +# ============================================================================ + + +def clear_context_fields() -> None: + """Clear all context variables.""" + structlog.contextvars.clear_contextvars() + + +def bind_context_vars(**kwargs: Any) -> None: + """Bind context variables for logging.""" + structlog.contextvars.bind_contextvars(**kwargs) + + +def get_context_vars() -> dict[str, Any]: + return structlog.contextvars.get_contextvars() + + +def get_logger(name: str = "") -> structlog.stdlib.BoundLogger: + return structlog.get_logger(name or __name__) # type: ignore diff --git a/ai_base_template/main.py b/src/main.py similarity index 51% rename from ai_base_template/main.py rename to src/main.py index a9c19e7..933c8a4 100644 --- a/ai_base_template/main.py +++ b/src/main.py @@ -3,6 +3,7 @@ from .logging import configure_structlog, get_logger # Configure logging +# Note: testing=True enables human-readable format, testing=False uses JSON format configure_structlog(testing=True) logger = get_logger(__name__) @@ -20,3 +21,22 @@ def get_version() -> str: logger.info("Version retrieved", version=__version__) return __version__ + + +def main() -> None: + """Main entry point to demonstrate logging functionality.""" + logger.info("Application starting") + + # Test hello_world function + greeting = hello_world() + logger.info("Received greeting", greeting=greeting) + + # Test get_version function + version = get_version() + logger.info("Application version check complete", version=version) + + logger.info("Application finished successfully") + + +if __name__ == "__main__": + main() diff --git a/tests/test_logging.py b/tests/test_logging.py index 7571c0c..4686e30 100644 --- a/tests/test_logging.py +++ b/tests/test_logging.py @@ -1,424 +1,355 @@ """Functional tests for the logger module.""" import json +from typing import Any import pytest from pytest import LogCaptureFixture, MonkeyPatch -from ai_base_template.logging import ( - bind_contextvars, +from src.logging import ( + bind_context_vars, clear_context_fields, configure_structlog, - get_correlation_id, get_logger, ) +# ============================================================================ +# Helpers +# ============================================================================ -@pytest.fixture(autouse=True) -def setup_logger(): - """Configure logger before each test and clean up after.""" - configure_structlog() - yield - clear_context_fields() - - -# Correlation ID Functionality Tests - - -def test_correlation_id_appears_in_logged_json(caplog: LogCaptureFixture) -> None: - """Verify correlation_id is preserved in JSON log output for request tracing.""" - # Bind a correlation ID as would happen at request start - correlation_id = "req-abc-123" - bind_contextvars(correlation_id=correlation_id) - - # Log a message as would happen during request processing - logger = get_logger("api_handler") - logger.info("Processing request") - - # Parse the JSON output - log_output = json.loads(caplog.records[0].message) - - # Verify correlation_id is in the extra fields - assert "extra" in log_output - assert log_output["extra"]["correlation_id"] == correlation_id - - -def test_get_correlation_id_returns_unknown_when_unset() -> None: - """Ensure get_correlation_id provides safe fallback when ID is not bound.""" - # Don't bind any correlation_id - clear_context_fields() - - # Should return "unknown" as default - assert get_correlation_id() == "unknown" +def parse_log_json(caplog: LogCaptureFixture, index: int = 0) -> dict[str, Any]: + try: + return json.loads(caplog.records[index].message) + except (json.JSONDecodeError, IndexError) as e: + records = [r.message for r in caplog.records] + raise AssertionError(f"Failed to parse log {index}: {e}. Records: {records}") -def test_get_correlation_id_retrieves_bound_value() -> None: - """Verify get_correlation_id returns the bound correlation ID.""" - correlation_id = "test-correlation-456" - bind_contextvars(correlation_id=correlation_id) - assert get_correlation_id() == correlation_id +def assert_json_log_structure(log_data: dict[str, Any]) -> None: + required_fields = {"timestamp", "level", "logger", "message", "context"} + missing_fields = required_fields - log_data.keys() + assert not missing_fields, f"Missing required fields: {missing_fields}" -# Log Output Structure Tests - - -def test_logger_outputs_valid_json_structure(caplog: LogCaptureFixture) -> None: - """Ensure log output is valid JSON with required fields for log processors.""" - logger = get_logger("test_logger") - logger.info("Test message", custom_field="custom_value") - - # Should be valid JSON - log_output = json.loads(caplog.records[0].message) - - # Verify required fields exist - assert "timestamp" in log_output - assert "level" in log_output - assert "logger" in log_output - assert "message" in log_output - assert log_output["message"] == "Test message" - assert log_output["logger"] == "test_logger" - assert log_output["level"] == "info" - - -def test_custom_fields_isolated_in_extra_dict(caplog: LogCaptureFixture) -> None: - """Verify custom fields are isolated to prevent field name collisions.""" - logger = get_logger("api") - - # Log with custom fields - logger.info("API call", user_id="user-123", endpoint="/api/v1/chat", method="POST", status_code=200) - - log_output = json.loads(caplog.records[0].message) - - # Standard fields should be at root level - assert "timestamp" in log_output - assert "level" in log_output - assert "message" in log_output - assert "logger" in log_output - assert "context" in log_output - - # Custom fields should be in extra - assert "extra" in log_output - assert log_output["extra"]["user_id"] == "user-123" - assert log_output["extra"]["endpoint"] == "/api/v1/chat" - assert log_output["extra"]["method"] == "POST" - assert log_output["extra"]["status_code"] == 200 - - # Verify standard fields are not in extra - assert "timestamp" not in log_output["extra"] - assert "level" not in log_output["extra"] - assert "message" not in log_output["extra"] - +def assert_human_readable_format(log_message: str) -> None: + with pytest.raises((json.JSONDecodeError, ValueError)): + json.loads(log_message) -# Log Level Filtering Tests + # Should contain basic readable components + assert "[" in log_message and "]" in log_message + assert ":" in log_message -def test_logging_level_filters_messages(monkeypatch: MonkeyPatch, caplog: LogCaptureFixture) -> None: - """Verify log level setting correctly filters messages for production log control.""" - # Set INFO level - monkeypatch.setenv("LOGGING_LEVEL", "INFO") +@pytest.fixture(autouse=True) +def setup_logger(): configure_structlog() + yield + clear_context_fields() - logger = get_logger("test") - - # Log at different levels - logger.debug("Debug message - should not appear") - logger.info("Info message - should appear") - logger.warning("Warning message - should appear") - logger.error("Error message - should appear") - - # Only INFO and above should be logged - messages = [json.loads(record.message)["message"] for record in caplog.records] - assert "Debug message - should not appear" not in messages - assert "Info message - should appear" in messages - assert "Warning message - should appear" in messages - assert "Error message - should appear" in messages +# ============================================================================ +# Core Functionality Tests +# ============================================================================ -def test_invalid_log_level_defaults_to_info(monkeypatch: MonkeyPatch, caplog: LogCaptureFixture) -> None: - """Ensure invalid log level falls back to INFO safely.""" - # Set invalid level - monkeypatch.setenv("LOGGING_LEVEL", "INVALID") - configure_structlog() +@pytest.mark.parametrize( + "correlation_id", + [ + "simple-123", + "very-long-correlation-id-with-lots-of-characters-12345", + "req-abc-123", + ], +) +def test__correlation_id__appears_in_logs(caplog: LogCaptureFixture, correlation_id: str): + bind_context_vars(correlation_id=correlation_id) - logger = get_logger("test") + get_logger("test").info("Test message") - # Should still work with INFO level - logger.debug("Should not appear") - logger.info("Should appear") + log_data = parse_log_json(caplog) + assert log_data["extra"]["correlation_id"] == correlation_id - messages = [json.loads(record.message)["message"] for record in caplog.records] - assert "Should not appear" not in messages - assert "Should appear" in messages +def test__correlation_id__propagates_across_loggers(caplog: LogCaptureFixture): + bind_context_vars(correlation_id="propagate-test") -# Context Isolation Tests + get_logger("auth").info("Auth step") + get_logger("db").info("DB step") + get_logger("api").info("Response step") + for i in range(3): + log_data = parse_log_json(caplog, i) + assert log_data["extra"]["correlation_id"] == "propagate-test" -def test_context_clears_between_requests(caplog: LogCaptureFixture) -> None: - """Verify context clearing prevents data leakage between requests.""" - logger = get_logger("request_handler") +def test__context__isolates_between_requests(caplog: LogCaptureFixture): # First request - bind_contextvars(correlation_id="request-1", user_id="user-1") - logger.info("Processing first request") + bind_context_vars(correlation_id="req-1", user_id="user-1") + get_logger("handler").info("First request") - # Clear context as would happen at request end + # Clear context (simulates end of request) clear_context_fields() - # Second request - should not have first request's context - bind_contextvars(correlation_id="request-2") # Note: no user_id - logger.info("Processing second request") + # Second request + bind_context_vars(correlation_id="req-2") # Note: no user_id + get_logger("handler").info("Second request") - # Parse both logs - first_log = json.loads(caplog.records[0].message) - second_log = json.loads(caplog.records[1].message) + first_log = parse_log_json(caplog, 0) + second_log = parse_log_json(caplog, 1) - # First log should have both fields - assert first_log["extra"]["correlation_id"] == "request-1" + assert first_log["extra"]["correlation_id"] == "req-1" assert first_log["extra"]["user_id"] == "user-1" - # Second log should only have correlation_id, not user_id - assert second_log["extra"]["correlation_id"] == "request-2" + assert second_log["extra"]["correlation_id"] == "req-2" assert "user_id" not in second_log.get("extra", {}) -def test_correlation_id_propagates_through_request_lifecycle(caplog: LogCaptureFixture) -> None: - """Verify correlation_id propagates through entire request without re-binding.""" - # Bind correlation_id once at request start - correlation_id = "request-lifecycle-789" - bind_contextvars(correlation_id=correlation_id) +# ============================================================================ +# Output Format Tests +# ============================================================================ - # Simulate multiple log points in request processing - logger1 = get_logger("auth") - logger1.info("Authenticating user") - logger2 = get_logger("database") - logger2.info("Querying database") +def test__custom_fields__go_to_extra_section(caplog: LogCaptureFixture): + get_logger("api").info("API call", user_id="user-123", endpoint="/api/chat", status_code=200) - logger3 = get_logger("response") - logger3.info("Sending response") + log_data = parse_log_json(caplog) - # All logs should have the same correlation_id - for record in caplog.records: - log_output = json.loads(record.message) - assert log_output["extra"]["correlation_id"] == correlation_id + # Standard fields at root + assert_json_log_structure(log_data) + # Custom fields in extra + extra = log_data["extra"] + assert extra["user_id"] == "user-123" + assert extra["endpoint"] == "/api/chat" + assert extra["status_code"] == 200 -# Critical Safety Tests for New Logging Features + # Standard fields not in extra + standard_fields = {"timestamp", "level", "message", "logger", "context"} + assert not (standard_fields & extra.keys()) -def test_testing_mode_produces_human_readable_output(caplog: LogCaptureFixture) -> None: - """End-to-end test that TESTING=True actually produces human-readable logs.""" - # Configure logger in testing mode - configure_structlog(testing=True) +@pytest.mark.parametrize( + "testing,should_be_json", + [ + (False, True), # Production mode = JSON + (True, False), # Testing mode = Human readable + ], +) +def test__output_format__changes_based_on_testing_flag(caplog: LogCaptureFixture, testing: bool, should_be_json: bool): + configure_structlog(testing=testing) + bind_context_vars(correlation_id="format-test") - # Bind context and log with extra fields - bind_contextvars(correlation_id="test-123-abc") - logger = get_logger("core.chat") - logger.info("Processing user query", query="How many customers?", duration_ms=150, status_code=200) + get_logger("format").info("Format test", field="value") - # Should get human-readable format, not JSON - log_output = caplog.records[0].message + log_message = caplog.records[0].message - # Verify it's NOT JSON (would raise exception if we tried to parse) - with pytest.raises((json.JSONDecodeError, ValueError)): - json.loads(log_output) + if should_be_json: + log_data = parse_log_json(caplog) + assert_json_log_structure(log_data) + assert log_data["extra"]["correlation_id"] == "format-test" + else: + assert_human_readable_format(log_message) + assert "Format test" in log_message + assert "field=value" in log_message + assert "[id:format-t]" in log_message # Truncated correlation ID - # Verify human-readable format components - assert "[INFO]" in log_output - assert "core.chat:" in log_output - assert "Processing user query" in log_output - assert "query=How many customers?" in log_output - assert "150ms" in log_output - assert "HTTP 200" in log_output - assert "[id:test-123]" in log_output # Truncated correlation ID +# Human-Readable Formatter Tests -def test_production_mode_still_produces_json_output(caplog: LogCaptureFixture) -> None: - """Ensure existing JSON logging unaffected by new features.""" - # Configure logger in production mode (default) - configure_structlog(testing=False) - # Bind context and log with extra fields - bind_contextvars(correlation_id="prod-456-def") - logger = get_logger("api.handler") - logger.info("Processing request", user_id="user-123", endpoint="/api/chat") - - # Should be valid JSON - log_output = json.loads(caplog.records[0].message) - - # Verify JSON structure matches existing format - assert "timestamp" in log_output - assert "level" in log_output - assert "logger" in log_output - assert "message" in log_output - assert "context" in log_output - assert "extra" in log_output - - # Verify content - assert log_output["level"] == "info" - assert log_output["logger"] == "api.handler" - assert log_output["message"] == "Processing request" - assert log_output["extra"]["correlation_id"] == "prod-456-def" - assert log_output["extra"]["user_id"] == "user-123" - assert log_output["extra"]["endpoint"] == "/api/chat" - - -def test_human_readable_renderer_formats_complete_log_entry(caplog: LogCaptureFixture) -> None: - """HumanReadableRenderer should format all components correctly.""" +def test__human_readable_formatter__formats_complete_log(caplog: LogCaptureFixture): configure_structlog(testing=True) + bind_context_vars(correlation_id="complete-test-789") - # Bind correlation ID and log with full context - bind_contextvars(correlation_id="complete-test-789") - logger = get_logger("ai_sql_assistant.services.llm.session") - logger.warning("LLM call completed", duration_ms=2500, status_code=200, model="gpt-4o-mini") + get_logger("services.llm").warning("LLM call completed", duration_ms=2500, model="gpt-4o-mini") - log_output = caplog.records[0].message + output = caplog.records[0].message - # Verify format: "HH:MM:SS [LEVEL] logger: message [key_info] [correlation_id]" - assert "[WARNING]" in log_output - assert "llm.session:" in log_output # Should be abbreviated - assert "LLM call completed" in log_output - assert "2500ms" in log_output - assert "HTTP 200" in log_output - assert "model=gpt-4o-mini" in log_output - assert "[id:complete]" in log_output # Truncated to 8 chars + # Verify format components + assert "[WARNING]" in output + assert "services.llm:" in output + assert "LLM call completed" in output + assert "duration_ms=2500" in output + assert "model=gpt-4o-mini" in output + assert "[id:complete]" in output # Truncated to 8 chars # Verify timestamp format (HH:MM:SS at start) import re - timestamp_pattern = r"^\d{2}:\d{2}:\d{2}" - assert re.match(timestamp_pattern, log_output) + assert re.match(r"^\d{2}:\d{2}:\d{2}", output) -def test_human_readable_renderer_handles_empty_fields(caplog: LogCaptureFixture) -> None: - """Renderer should handle missing/empty fields gracefully.""" - configure_structlog(testing=True) +# ============================================================================ +# Configuration Tests +# ============================================================================ - # Log without correlation ID or extra fields - logger = get_logger("simple.logger") - logger.error("Simple error message") - log_output = caplog.records[0].message +def test__log_level__filters_messages(monkeypatch: MonkeyPatch, caplog: LogCaptureFixture): + monkeypatch.setenv("LOGGING_LEVEL", "WARNING") + configure_structlog() - # Should not crash and should format basic components - assert "[ERROR]" in log_output - assert "simple.logger:" in log_output - assert "Simple error message" in log_output + logger = get_logger("test") + logger.debug("Should not appear") + logger.info("Should not appear") + logger.warning("Should appear") + logger.error("Should appear") - # Should not have extra brackets or correlation ID - assert "[id:" not in log_output - assert "[]" not in log_output + messages = [parse_log_json(caplog, i)["message"] for i in range(len(caplog.records))] + assert "Should not appear" not in " ".join(messages) + assert "Should appear" in " ".join(messages) + assert len(caplog.records) == 2 # Only WARNING and ERROR -def test_abbreviate_logger_name_shortens_project_loggers() -> None: - """Project logger names should be abbreviated for readability.""" - from ai_base_template.logging import _abbreviate_logger_name - # Test project logger abbreviation - assert _abbreviate_logger_name("ai_base_template.core.chat") == "core.chat" - assert _abbreviate_logger_name("ai_base_template.services.llm.session") == "llm.session" - assert _abbreviate_logger_name("ai_base_template.middleware.logger") == "middleware.logger" - assert _abbreviate_logger_name("ai_base_template.api.threads") == "api.threads" +def test__invalid_log_level__defaults_to_info(monkeypatch: MonkeyPatch, caplog: LogCaptureFixture): + monkeypatch.setenv("LOGGING_LEVEL", "INVALID") + configure_structlog() - # Test single component (should use last part) - assert _abbreviate_logger_name("ai_base_template.main") == "main" + logger = get_logger("test") + logger.debug("Debug message") + logger.info("Info message") - # Test external loggers (should be unchanged) - assert _abbreviate_logger_name("werkzeug") == "werkzeug" - assert _abbreviate_logger_name("sqlalchemy.engine") == "sqlalchemy.engine" - assert _abbreviate_logger_name("litellm") == "litellm" + # Should default to INFO level, so debug filtered out + assert len(caplog.records) == 1 + log_data = parse_log_json(caplog) + assert log_data["message"] == "Info message" -def test_format_extra_fields_prioritizes_important_fields() -> None: - """Important fields like status_code, duration_ms should appear first.""" - from ai_base_template.logging import _format_extra_fields +# ============================================================================ +# Edge Cases & Integration Tests +# ============================================================================ - # Test with mix of important and regular fields - extra = { - "user_id": "user-123", - "status_code": 200, - "request_type": "chat", - "duration_ms": 1500, - "endpoint": "/api/v1/chat", - "response_size_bytes": 2048, - } - result = _format_extra_fields(extra) +def test__edge_case_values__are_handled_correctly(caplog: LogCaptureFixture): + """Test that various edge case values (long, empty, special chars) are handled properly.""" + configure_structlog(testing=True) - # Should start with brackets - assert result.startswith(" [") - assert result.endswith("]") + # Test long values get truncated in human-readable format + very_long_value = "x" * 100 + get_logger("test").info("Long value test", long_field=very_long_value) + human_output = caplog.records[0].message + assert "long_field=" in human_output + assert "..." in human_output + assert very_long_value not in human_output - # Important fields should appear first in specific format - content = result[2:-1] # Remove " [" and "]" - fields = [f.strip() for f in content.split(",")] + caplog.clear() + configure_structlog(testing=False) # Switch to JSON format - # Check that important fields are formatted specially and appear early - important_fields_found = [] - for field in fields[:4]: # Check first 4 fields - if "HTTP" in field: - important_fields_found.append("status_code") - elif "ms" in field and "=" not in field: # Duration without "=" means special format - important_fields_found.append("duration_ms") - elif "B" in field and "=" not in field: # Bytes without "=" means special format - important_fields_found.append("response_size_bytes") + # Test empty, None, zero, false values are preserved in JSON + get_logger("test").info("Edge case test", empty_string="", none_value=None, zero_value=0, false_value=False) - # At least status_code and duration_ms should be in special format - assert "status_code" in important_fields_found - assert "duration_ms" in important_fields_found + log_data = parse_log_json(caplog) + extra = log_data["extra"] + assert extra["empty_string"] == "" + assert extra["none_value"] is None + assert extra["zero_value"] == 0 + assert extra["false_value"] is False - # Regular fields should have key=value format - assert any("user_id=user-123" in field for field in fields) + caplog.clear() + # Test special characters are preserved + special_chars = 'Test with "quotes", commas, and [brackets]' + get_logger("test").info("Special chars", special_field=special_chars) -def test_correlation_id_works_in_human_readable_mode(caplog: LogCaptureFixture) -> None: - """Correlation IDs should work in human-readable format.""" - configure_structlog(testing=True) + log_data = parse_log_json(caplog) + assert log_data["extra"]["special_field"] == special_chars - # Test with long correlation ID (should be truncated) - long_correlation_id = "very-long-correlation-id-that-should-be-truncated-123456789" - bind_contextvars(correlation_id=long_correlation_id) - logger = get_logger("correlation.test") - logger.info("Test correlation ID display") +def test__end_to_end_logging_workflow__maintains_context_and_formats_correctly(caplog: LogCaptureFixture): + """Test complete logging workflow: set context, log across services, verify output.""" + configure_structlog(testing=False) # JSON format for structured validation - log_output = caplog.records[0].message + # Simulate request start - set context + bind_context_vars(correlation_id="req-123", user_id="user-456", request_path="/api/users") - # Should appear as truncated correlation ID - assert "[id:very-lon]" in log_output # First 8 characters + # Simulate logging across different services in a request + auth_logger = get_logger("src.auth.service") + auth_logger.info("User authentication started", method="jwt") - # Should not contain the full correlation ID - assert long_correlation_id not in log_output + db_logger = get_logger("src.database.users") + db_logger.info("Database query executed", table="users", query_time_ms=45) - # Test with shorter correlation ID - clear_context_fields() - bind_contextvars(correlation_id="short") - logger.info("Test short correlation ID") + api_logger = get_logger("src.api.response") + api_logger.warning("Rate limit approaching", current_requests=950, limit=1000) - log_output = caplog.records[1].message - assert "[id:short]" in log_output + # Verify all logs have correct context and structure + assert len(caplog.records) == 3 + for i, (service, expected_message) in enumerate( + [ + ("auth.service", "User authentication started"), + ("database.users", "Database query executed"), + ("api.response", "Rate limit approaching"), + ] + ): + log_data = parse_log_json(caplog, i) -def test_configure_structlog_chooses_correct_renderer() -> None: - """configure_structlog should choose renderer based on testing flag.""" - import structlog + # Verify required structure + assert log_data["message"] == expected_message + assert log_data["level"] in ["info", "warning"] + assert log_data["context"] == "default" + assert service in log_data["logger"] - # Test production mode - should use JSONRenderer + # Verify context propagation + extra = log_data["extra"] + assert extra["correlation_id"] == "req-123" + assert extra["user_id"] == "user-456" + assert extra["request_path"] == "/api/users" + + # Verify service-specific fields are preserved + auth_log = parse_log_json(caplog, 0) + assert auth_log["extra"]["method"] == "jwt" + + db_log = parse_log_json(caplog, 1) + assert db_log["extra"]["table"] == "users" + assert db_log["extra"]["query_time_ms"] == 45 + + rate_log = parse_log_json(caplog, 2) + assert rate_log["extra"]["current_requests"] == 950 + assert rate_log["extra"]["limit"] == 1000 + + +def test__concurrent_requests__maintain_isolated_contexts(caplog: LogCaptureFixture): + """Test that context isolation works correctly when simulating concurrent requests.""" configure_structlog(testing=False) - config = structlog.get_config() - # Check that JSONRenderer is in processors - renderer_types = [type(processor).__name__ for processor in config["processors"]] - assert "JSONRenderer" in renderer_types - assert "HumanReadableRenderer" not in renderer_types + # Simulate first request context + bind_context_vars(correlation_id="req-001", session_id="sess-abc", feature="checkout") + get_logger("src.checkout").info("Checkout process started") - # Test testing mode - should use HumanReadableRenderer - configure_structlog(testing=True) - config = structlog.get_config() + # Simulate second request context (different context) + clear_context_fields() # Simulate end of first request + bind_context_vars(correlation_id="req-002", session_id="sess-xyz", feature="search") + get_logger("src.search").info("Search query processed") - renderer_types = [type(processor).__name__ for processor in config["processors"]] - assert "HumanReadableRenderer" in renderer_types - assert "JSONRenderer" not in renderer_types + # Simulate third request context + clear_context_fields() + bind_context_vars(correlation_id="req-003", user_type="premium", feature="analytics") + get_logger("src.analytics").info("Analytics event recorded") + + # Verify each log has only its own context + assert len(caplog.records) == 3 + + # First request log + checkout_log = parse_log_json(caplog, 0) + checkout_extra = checkout_log["extra"] + assert checkout_extra["correlation_id"] == "req-001" + assert checkout_extra["session_id"] == "sess-abc" + assert checkout_extra["feature"] == "checkout" + assert "user_type" not in checkout_extra # Should not leak from later request + + # Second request log + search_log = parse_log_json(caplog, 1) + search_extra = search_log["extra"] + assert search_extra["correlation_id"] == "req-002" + assert search_extra["session_id"] == "sess-xyz" + assert search_extra["feature"] == "search" + assert "user_type" not in search_extra # Should not leak from later request + + # Third request log + analytics_log = parse_log_json(caplog, 2) + analytics_extra = analytics_log["extra"] + assert analytics_extra["correlation_id"] == "req-003" + assert analytics_extra["user_type"] == "premium" + assert analytics_extra["feature"] == "analytics" + assert "session_id" not in analytics_extra # Should not leak from previous requests diff --git a/tests/test_main.py b/tests/test_main.py index 790924f..c2b96d0 100644 --- a/tests/test_main.py +++ b/tests/test_main.py @@ -2,8 +2,8 @@ import pytest -from ai_base_template import __version__ -from ai_base_template.main import get_version, hello_world +from src import __version__ +from src.main import get_version, hello_world def test_hello_world(): @@ -14,7 +14,7 @@ def test_hello_world(): def test_get_version(): version = get_version() - assert version == "1.0.6" + assert version == "0.3.0" assert isinstance(version, str) @@ -27,8 +27,8 @@ def test_hello_world_unit(): def test_package_functionality(): """Functional test for basic package functionality.""" # Test that we can import and use the package - assert __version__ == "1.0.6" + assert __version__ == "0.3.0" # Test main functions work assert hello_world() == "Hello from AI Base Template!" - assert get_version() == "1.0.6" + assert get_version() == "0.3.0"