lotr-sut/sut/backend/services/negotiation_logger.py

"""Logging service for bargaining negotiations (anonymized)."""
import json
import logging
from datetime import datetime, timedelta
from typing import Any, Dict, List, Optional
import hashlib
import uuid

logger = logging.getLogger(__name__)


class NegotiationLogger:
    """
    Log negotiation outcomes and user behaviors for analytics/debugging.
    
    All logs are anonymized - no user identifiers are stored.
    Each negotiation gets a unique session ID for tracking.
    """

    # In-memory store for simplicity. In production, use a database or CloudWatch Logs.
    _negotiation_logs: List[Dict[str, Any]] = []

    @classmethod
    def log_negotiation_start(
        cls,
        character: str,
        item_id: int,
        item_name: str,
        original_price: int,
    ) -> str:
        """
        Log the start of a negotiation.
        
        Returns:
            session_id: Unique identifier for this negotiation session
        """
        session_id = str(uuid.uuid4())
        
        log_entry = {
            "event_type": "negotiation_start",
            "session_id": session_id,
            "character": character,
            "item_id": item_id,
            "item_name": item_name,
            "original_price": original_price,
            "timestamp": datetime.utcnow().isoformat(),
        }
        
        cls._negotiation_logs.append(log_entry)
        logger.debug(f"Negotiation started: {session_id} for {character} - {item_name}")
        
        return session_id

    @classmethod
    def log_offer_made(
        cls,
        session_id: str,
        round_num: int,
        user_offer: int,
        current_ask: int,
        is_flattered: bool = False,
    ) -> None:
        """Log when the user makes an offer."""
        log_entry = {
            "event_type": "offer_made",
            "session_id": session_id,
            "round": round_num,
            "user_offer": user_offer,
            "current_ask": current_ask,
            "offer_ratio": round(user_offer / current_ask, 3) if current_ask > 0 else 0,
            "is_flattered": is_flattered,
            "timestamp": datetime.utcnow().isoformat(),
        }
        
        cls._negotiation_logs.append(log_entry)
        logger.debug(f"Offer made in {session_id}: {user_offer} (ask was {current_ask})")

    @classmethod
    def log_algorithm_result(
        cls,
        session_id: str,
        result_type: str,
        context: Dict[str, Any],
    ) -> None:
        """Log the algorithm's decision."""
        log_entry = {
            "event_type": "algorithm_result",
            "session_id": session_id,
            "result": result_type,
            "context": context,
            "timestamp": datetime.utcnow().isoformat(),
        }
        
        cls._negotiation_logs.append(log_entry)
        logger.debug(f"Algorithm result for {session_id}: {result_type}")

    @classmethod
    def log_negotiation_end(
        cls,
        session_id: str,
        final_status: str,  # "accepted", "rejected", "bored", "stopped"
        final_price: Optional[int] = None,
        rounds_taken: int = 0,
    ) -> None:
        """Log the end of a negotiation."""
        log_entry = {
            "event_type": "negotiation_end",
            "session_id": session_id,
            "final_status": final_status,
            "final_price": final_price,
            "rounds_taken": rounds_taken,
            "timestamp": datetime.utcnow().isoformat(),
        }
        
        cls._negotiation_logs.append(log_entry)
        logger.debug(f"Negotiation ended: {session_id} - {final_status} after {rounds_taken} rounds")

    @classmethod
    def log_behavior_detected(
        cls,
        session_id: str,
        behavior_type: str,  # "flattery", "persistence", "politeness", etc.
    ) -> None:
        """Log when a user behavior is detected."""
        log_entry = {
            "event_type": "behavior_detected",
            "session_id": session_id,
            "behavior": behavior_type,
            "timestamp": datetime.utcnow().isoformat(),
        }
        
        cls._negotiation_logs.append(log_entry)
        logger.debug(f"Behavior detected in {session_id}: {behavior_type}")

    @classmethod
    def log_llm_interaction(
        cls,
        session_id: str,
        llm_input_summary: Dict[str, Any],
        llm_output: str,
    ) -> None:
        """Log LLM interaction for debugging."""
        log_entry = {
            "event_type": "llm_interaction",
            "session_id": session_id,
            "llm_prompt_fields": list(llm_input_summary.keys()),
            "llm_output_length": len(llm_output),
            "timestamp": datetime.utcnow().isoformat(),
        }
        
        cls._negotiation_logs.append(log_entry)
        logger.debug(f"LLM interaction in {session_id}: generated {len(llm_output)} char response")

    @classmethod
    def purge_old_logs(cls, days_to_keep: int = 30) -> int:
        """
        Remove logs older than specified days.
        
        Returns:
            Number of logs removed
        """
        cutoff_date = (datetime.utcnow() - timedelta(days=days_to_keep)).isoformat()
        initial_count = len(cls._negotiation_logs)
        
        cls._negotiation_logs = [
            log for log in cls._negotiation_logs
            if log.get("timestamp", "") > cutoff_date
        ]
        
        removed_count = initial_count - len(cls._negotiation_logs)
        if removed_count > 0:
            logger.info(f"Purged {removed_count} negotiation logs older than {days_to_keep} days")
        
        return removed_count

    @classmethod
    def get_stats(cls) -> Dict[str, Any]:
        """Get aggregated statistics from logs (for monitoring)."""
        if not cls._negotiation_logs:
            return {
                "total_logs": 0,
                "negotiation_sessions": 0,
            }
        
        # Count unique sessions
        sessions = set()
        accepted_count = 0
        rejected_count = 0
        flattery_count = 0
        
        for log in cls._negotiation_logs:
            if log.get("session_id"):
                sessions.add(log["session_id"])
            if log.get("event_type") == "negotiation_end":
                if log.get("final_status") == "accepted":
                    accepted_count += 1
                elif log.get("final_status") == "rejected":
                    rejected_count += 1
            if log.get("is_flattered"):
                flattery_count += 1
        
        return {
            "total_logs": len(cls._negotiation_logs),
            "unique_sessions": len(sessions),
            "successful_negotiations": accepted_count,
            "failed_negotiations": rejected_count,
            "flattery_attempts": flattery_count,
        }

    @classmethod
    def clear_logs(cls) -> None:
        """Clear all logs (for testing)."""
        cls._negotiation_logs = []