diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 584df3e..2687b62 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -21,7 +21,33 @@ jobs: env: GITHUB_TOKEN: ${{ secrets.GITHUB_TOKEN }} + format: + if: (github.event_name == 'push' && github.ref == 'refs/heads/main') || (github.event_name == 'pull_request' && github.event.action != 'closed') + runs-on: ubuntu-latest + steps: + - uses: actions/checkout@v4 + + - name: Install uv + uses: astral-sh/setup-uv@v3 + with: + enable-cache: true + cache-dependency-glob: | + pyproject.toml + *.py + + - name: Set up Python + run: uv python install 3.12 + + - name: Install dependencies + run: | + uv venv --python 3.12 + make sync + + - name: Format code + run: make format + lint: + needs: format if: (github.event_name == 'push' && github.ref == 'refs/heads/main') || (github.event_name == 'pull_request' && github.event.action != 'closed') runs-on: ubuntu-latest steps: @@ -125,7 +151,7 @@ jobs: run: make test-unit release: - needs: [lint, type-check, test] + needs: [format, lint, type-check, test] if: (github.event_name == 'push' && github.ref == 'refs/heads/main') || (github.event.action == 'closed' && github.event.pull_request.merged == true) runs-on: ubuntu-latest permissions: diff --git a/.pre-commit-config.yaml b/.pre-commit-config.yaml index 125b430..615a65b 100644 --- a/.pre-commit-config.yaml +++ b/.pre-commit-config.yaml @@ -1,6 +1,13 @@ repos: - repo: local hooks: + - id: format-check + name: Format code with ruff + entry: make format + language: system + stages: [pre-commit] + verbose: true + pass_filenames: false - id: lint-check name: Run ruff linter entry: make lint diff --git a/Makefile b/Makefile index b8b884c..4e88469 100644 --- a/Makefile +++ b/Makefile @@ -116,8 +116,9 @@ test-all: ## Run all tests including integration tests # Branch Validation # ---------------------------- -validate-branch: ## Run linting, type checks, and tests +validate-branch: ## Run formatting, linting, type checks, and tests @echo "🔍 Running branch validation..." + $(MAKE) format $(MAKE) lint $(MAKE) type-check $(MAKE) test diff --git a/README.md b/README.md index 23229b9..d392093 100644 --- a/README.md +++ b/README.md @@ -15,9 +15,10 @@ A **modern Python foundation** designed for AI systems that need to work reliably in production: - **Modern Python Tooling** - Python 3.12+, FastAPI, Pydantic, type hints throughout +- **Production Logging** - Structured JSON logging with correlation tracking and dual-mode rendering - **Development Automation** - Pre-configured linting, formatting, testing, and validation - **Production-Ready Structure** - Organized for maintainability and scaling -- **Comprehensive Testing** - Unit, functional, and integration test patterns +- **Comprehensive Testing** - Unit, functional, and integration test patterns (21+ logging tests included) - **CI/CD Ready** - GitHub Actions, pre-commit hooks, semantic versioning - **Documentation Standards** - Clear guides for development and deployment @@ -93,9 +94,11 @@ make test-all # Complete test suite ai-base-template/ ├── ai_base_template/ # Your service code goes here │ ├── __init__.py -│ └── main.py # Simple starting point +│ ├── main.py # Simple starting point with logging integration +│ └── logging.py # Production structured logging system ├── tests/ # Comprehensive test suite -│ └── test_main.py # Example test patterns +│ ├── test_main.py # Example test patterns +│ └── test_logging.py # 21+ logging system tests ├── research/ # Notebooks and experiments │ └── EDA.ipynb # Exploratory work stays here ├── Makefile # All automation commands @@ -114,6 +117,67 @@ Stop reinventing infrastructure. Focus on your models while using battle-tested ### Technical Leaders Give your team a consistent, production-ready starting point that embodies engineering best practices from day one. +## 📊 Production Logging System + +This template includes a **production-grade structured logging system** built with structlog that handles the observability requirements of real-world AI systems. + +### Dual-Mode Logging + +**Development Mode** - Human-readable format for debugging: +```bash +22:45:00 [INFO] main: Processing request [HTTP 200, 150ms, user_id=user-123] [id:req-abc12] +``` + +**Production Mode** - Structured JSON for monitoring systems: +```json +{ + "timestamp": "2025-08-31T22:45:00.123Z", + "level": "info", + "logger": "main", + "message": "Processing request", + "context": "default", + "extra": { + "status_code": 200, + "duration_ms": 150, + "user_id": "user-123", + "correlation_id": "req-abc-123" + } +} +``` + +### Built-in Features + +- **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 + +### 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 + ## 📚 Learn More ### Core Methodology @@ -126,6 +190,7 @@ Give your team a consistent, production-ready starting point that embodies engin ### Technologies Used - [FastAPI](https://fastapi.tiangolo.com/) - Modern Python web framework - [Pydantic](https://docs.pydantic.dev/) - Data validation using type annotations +- [structlog](https://www.structlog.org/) - Structured logging for production systems - [uv](https://docs.astral.sh/uv/) - Modern Python package management ## 🤝 Contributing diff --git a/ai_base_template/__init__.py b/ai_base_template/__init__.py index f3e3836..9dd3cb2 100644 --- a/ai_base_template/__init__.py +++ b/ai_base_template/__init__.py @@ -1,3 +1,3 @@ """AI Flora Mind - Python AI Package""" -__version__ = "1.0.6" \ No newline at end of file +__version__ = "1.0.6" diff --git a/ai_base_template/logging.py b/ai_base_template/logging.py new file mode 100644 index 0000000..5cecd31 --- /dev/null +++ b/ai_base_template/logging.py @@ -0,0 +1,179 @@ +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/ai_base_template/main.py b/ai_base_template/main.py index 8b20ed1..a9c19e7 100644 --- a/ai_base_template/main.py +++ b/ai_base_template/main.py @@ -1,12 +1,22 @@ """Main module for AI Base Template service.""" +from .logging import configure_structlog, get_logger + +# Configure logging +configure_structlog(testing=True) +logger = get_logger(__name__) + def hello_world() -> str: - """Simple function to test the package.""" - return "Hello from AI Base Template!" + logger.info("hello_world function called") + result = "Hello from AI Base Template!" + logger.info("hello_world function returning result", result=result) + return result def get_version() -> str: - """Get the package version.""" + logger.info("get_version function called") from . import __version__ - return __version__ \ No newline at end of file + + logger.info("Version retrieved", version=__version__) + return __version__ diff --git a/pyproject.toml b/pyproject.toml index 58b6c48..0155900 100644 --- a/pyproject.toml +++ b/pyproject.toml @@ -24,6 +24,7 @@ dependencies = [ # Core dependencies "pydantic>=2.11.5", "pydantic-settings>=2.9.1", + "structlog>=25.4.0", ] [project.optional-dependencies] diff --git a/tests/test_logging.py b/tests/test_logging.py new file mode 100644 index 0000000..7571c0c --- /dev/null +++ b/tests/test_logging.py @@ -0,0 +1,424 @@ +"""Functional tests for the logger module.""" + +import json + +import pytest +from pytest import LogCaptureFixture, MonkeyPatch + +from ai_base_template.logging import ( + bind_contextvars, + clear_context_fields, + configure_structlog, + get_correlation_id, + get_logger, +) + + +@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 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 + + +# 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"] + + +# Log Level Filtering Tests + + +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") + configure_structlog() + + 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 + + +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() + + logger = get_logger("test") + + # Should still work with INFO level + logger.debug("Should not appear") + logger.info("Should appear") + + messages = [json.loads(record.message)["message"] for record in caplog.records] + assert "Should not appear" not in messages + assert "Should appear" in messages + + +# Context Isolation Tests + + +def test_context_clears_between_requests(caplog: LogCaptureFixture) -> None: + """Verify context clearing prevents data leakage between requests.""" + logger = get_logger("request_handler") + + # First request + bind_contextvars(correlation_id="request-1", user_id="user-1") + logger.info("Processing first request") + + # Clear context as would happen at request end + 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") + + # Parse both logs + first_log = json.loads(caplog.records[0].message) + second_log = json.loads(caplog.records[1].message) + + # First log should have both fields + assert first_log["extra"]["correlation_id"] == "request-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 "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) + + # Simulate multiple log points in request processing + logger1 = get_logger("auth") + logger1.info("Authenticating user") + + logger2 = get_logger("database") + logger2.info("Querying database") + + logger3 = get_logger("response") + logger3.info("Sending response") + + # 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 + + +# Critical Safety Tests for New Logging Features + + +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) + + # 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) + + # Should get human-readable format, not JSON + log_output = 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) + + # 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 + + +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.""" + configure_structlog(testing=True) + + # 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") + + log_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 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) + + +def test_human_readable_renderer_handles_empty_fields(caplog: LogCaptureFixture) -> None: + """Renderer should handle missing/empty fields gracefully.""" + configure_structlog(testing=True) + + # Log without correlation ID or extra fields + logger = get_logger("simple.logger") + logger.error("Simple error message") + + log_output = caplog.records[0].message + + # 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 + + # Should not have extra brackets or correlation ID + assert "[id:" not in log_output + assert "[]" not in log_output + + +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" + + # Test single component (should use last part) + assert _abbreviate_logger_name("ai_base_template.main") == "main" + + # 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" + + +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 + + # 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) + + # Should start with brackets + assert result.startswith(" [") + assert result.endswith("]") + + # Important fields should appear first in specific format + content = result[2:-1] # Remove " [" and "]" + fields = [f.strip() for f in content.split(",")] + + # 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") + + # 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 + + # Regular fields should have key=value format + assert any("user_id=user-123" in field for field in fields) + + +def test_correlation_id_works_in_human_readable_mode(caplog: LogCaptureFixture) -> None: + """Correlation IDs should work in human-readable format.""" + configure_structlog(testing=True) + + # 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") + + log_output = caplog.records[0].message + + # Should appear as truncated correlation ID + assert "[id:very-lon]" in log_output # First 8 characters + + # Should not contain the full correlation ID + assert long_correlation_id not in log_output + + # Test with shorter correlation ID + clear_context_fields() + bind_contextvars(correlation_id="short") + logger.info("Test short correlation ID") + + log_output = caplog.records[1].message + assert "[id:short]" in log_output + + +def test_configure_structlog_chooses_correct_renderer() -> None: + """configure_structlog should choose renderer based on testing flag.""" + import structlog + + # Test production mode - should use JSONRenderer + 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 + + # Test testing mode - should use HumanReadableRenderer + configure_structlog(testing=True) + config = structlog.get_config() + + renderer_types = [type(processor).__name__ for processor in config["processors"]] + assert "HumanReadableRenderer" in renderer_types + assert "JSONRenderer" not in renderer_types diff --git a/tests/test_main.py b/tests/test_main.py index c8164a9..790924f 100644 --- a/tests/test_main.py +++ b/tests/test_main.py @@ -2,18 +2,17 @@ import pytest +from ai_base_template import __version__ from ai_base_template.main import get_version, hello_world def test_hello_world(): - """Test the hello_world function.""" result = hello_world() assert result == "Hello from AI Base Template!" assert isinstance(result, str) def test_get_version(): - """Test the get_version function.""" version = get_version() assert version == "1.0.6" assert isinstance(version, str) @@ -21,7 +20,6 @@ def test_get_version(): @pytest.mark.unit def test_hello_world_unit(): - """Unit test for hello_world function.""" assert hello_world() == "Hello from AI Base Template!" @@ -29,9 +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 - from ai_base_template import __version__ assert __version__ == "1.0.6" - + # Test main functions work assert hello_world() == "Hello from AI Base Template!" - assert get_version() == "1.0.6" \ No newline at end of file + assert get_version() == "1.0.6"