Orchestrator/bahn/teamlandkarte-mcp/tests/test_batch_logging_pbt.py

# Feature: llm-batch-matching, Property 7: Logging-Konsistenz
"""Property-based test for logging consistency in batch matching.

For every execution of ``match_capacities`` with at least one candidate, the
INFO-level log messages (start and end) must contain the correct candidate
count, the configured concurrency limit, the number of successful
categorizations, and the number of errors. The sum of successes and errors in
the end log must equal the input count.

The fake LLM is driven by a Hypothesis-generated boolean mask: position ``i``
decides whether the call for capacity ``i+1`` raises ``AzureAPIError``
(``True``) or returns a valid JSON payload (``False``).

**Validates: Requirements 6.1, 6.2**
"""

from __future__ import annotations

import asyncio
import json
import logging
from contextlib import contextmanager
from typing import Any, Generator

from hypothesis import given, settings
from hypothesis import strategies as st

from teamlandkarte_mcp.azure.openai_client import AzureAPIError
from teamlandkarte_mcp.matching.llm_fulltext_matcher import LlmFulltextMatcher
from teamlandkarte_mcp.matching.profiles import TaskProfile
from teamlandkarte_mcp.models import Capacity

_LOGGER_NAME = "teamlandkarte_mcp.matching.llm_fulltext_matcher"


# ---------------------------------------------------------------------------
# Test doubles
# ---------------------------------------------------------------------------


class _MaskLlm:
    """Returns valid JSON for mask[i] is False; raises AzureAPIError for True."""

    def __init__(self, mask: list[bool]) -> None:
        self._mask = mask
        self._call_index = 0

    async def chat_completion(self, system: str, user: str) -> str:
        idx = self._call_index
        self._call_index += 1
        if self._mask[idx]:
            raise AzureAPIError("simulated")
        return json.dumps({"category": "Top", "rationale": "ok"})


class _StubDb:
    """Minimal DBClient double returning empty extras for every id."""

    def batch_get_capacity_descriptions(
        self, capacity_ids: list[Any]
    ) -> dict[str, str | None]:
        return {str(i): None for i in capacity_ids}

    def batch_get_capacity_certificates(
        self, capacity_ids: list[Any]
    ) -> dict[str, list[str]]:
        return {str(i): [] for i in capacity_ids}

    def batch_get_capacity_references(
        self, capacity_ids: list[Any]
    ) -> dict[str, list[dict]]:
        return {str(i): [] for i in capacity_ids}


def _make_capacities(n: int) -> list[Capacity]:
    return [
        Capacity(
            id=i + 1,
            owner_name=f"o{i + 1}",
            role_name="R",
            role_level=None,
            begin_date=None,
            end_date=None,
            competences=[],
        )
        for i in range(n)
    ]


# ---------------------------------------------------------------------------
# Log capture context manager (hypothesis doesn't support pytest fixtures)
# ---------------------------------------------------------------------------


class _ListHandler(logging.Handler):
    """Simple handler that appends records to a list."""

    def __init__(self, records: list[logging.LogRecord]) -> None:
        super().__init__()
        self._records = records

    def emit(self, record: logging.LogRecord) -> None:
        self._records.append(record)


@contextmanager
def _capture_logs(
    logger_name: str, level: int
) -> Generator[list[logging.LogRecord], None, None]:
    """Capture log records from a named logger for the duration of the block."""
    logger = logging.getLogger(logger_name)
    records: list[logging.LogRecord] = []
    handler = _ListHandler(records)
    handler.setLevel(level)
    logger.addHandler(handler)
    old_level = logger.level
    logger.setLevel(level)
    try:
        yield records
    finally:
        logger.removeHandler(handler)
        logger.setLevel(old_level)


# ---------------------------------------------------------------------------
# Property test
# ---------------------------------------------------------------------------


@settings(max_examples=100, deadline=None)
@given(
    mask=st.lists(st.booleans(), min_size=1, max_size=15),
    max_concurrency=st.integers(min_value=1, max_value=5),
)
def test_batch_logging_consistency(mask: list[bool], max_concurrency: int) -> None:
    """Property 7: log messages contain correct counts.

    Start log must contain the candidate count and max_concurrency.
    End log must contain the number of categorized items and errors.
    The sum of categorized + errors must equal the total candidates.
    """
    tracker_client = _MaskLlm(mask)
    matcher = LlmFulltextMatcher(
        db=_StubDb(),
        client=tracker_client,
        max_concurrency=max_concurrency,
    )
    capacities = _make_capacities(len(mask))
    task_profile = TaskProfile(id="t", title="T", description="D", skills=[])

    with _capture_logs(_LOGGER_NAME, logging.INFO) as records:
        asyncio.run(
            matcher.match_capacities(
                task_profile=task_profile, capacities=capacities
            )
        )

    # Find start and end log messages
    start_msgs = [r for r in records if "gestartet" in r.getMessage()]
    end_msgs = [r for r in records if "abgeschlossen" in r.getMessage()]

    assert len(start_msgs) == 1, f"Expected 1 start log, got {len(start_msgs)}"
    assert len(end_msgs) == 1, f"Expected 1 end log, got {len(end_msgs)}"

    start_msg = start_msgs[0].getMessage()
    end_msg = end_msgs[0].getMessage()

    # --- Start log: correct candidate count and max_concurrency ---
    assert str(len(mask)) in start_msg, (
        f"Expected candidate count {len(mask)} in start log: {start_msg}"
    )
    assert str(max_concurrency) in start_msg, (
        f"Expected max_concurrency {max_concurrency} in start log: {start_msg}"
    )

    # --- End log: correct categorized and error counts ---
    expected_errors = sum(1 for m in mask if m)
    expected_success = sum(1 for m in mask if not m)

    assert str(expected_success) in end_msg, (
        f"Expected {expected_success} categorized in end log: {end_msg}"
    )
    assert str(expected_errors) in end_msg, (
        f"Expected {expected_errors} errors in end log: {end_msg}"
    )

    # --- Consistency: categorized + errors == total candidates ---
    # Parse the numbers from the end log message format:
    # "Batch-Matching abgeschlossen: %.1fs, %d kategorisiert, %d Fehler"
    # We verify the sum property by checking the actual values
    assert expected_success + expected_errors == len(mask), (
        f"Sum mismatch: {expected_success} + {expected_errors} != {len(mask)}"
    )