feat: Enhanced logging with session tracking and usage patterns

- Track sessions with unique IDs
- Log call sequence (call#1, call#2, prev=...)
- Log response size in bytes
- Track indicators and geographic levels queried
- Detect patterns (list→details→query)
- Prepare for MCP optimization analysis

Co-authored-by: Cursor <cursoragent@cursor.com>

src/tools.py

@@ -3,9 +3,12 @@
 import json
 import logging
 import time
+import hashlib
+from collections import defaultdict
+from dataclasses import dataclass, field
 from datetime import datetime, timezone
 from functools import wraps
-from typing import Any, Callable
+from typing import Any, Callable, Optional
 
 from .api_client import get_client, CubeJsClient, CubeJsClientError
 
@@ -18,43 +21,189 @@ logging.basicConfig(
 logger = logging.getLogger("mcp_tools")
 
 
+# =============================================================================
+# Session Tracker - Track usage patterns across calls
+# =============================================================================
+@dataclass
+class SessionData:
+    """Track data for a single session."""
+    session_id: str
+    start_time: float = field(default_factory=time.time)
+    calls: list = field(default_factory=list)
+    last_call_time: float = 0
+    indicators_queried: set = field(default_factory=set)
+    levels_queried: set = field(default_factory=set)
+    
+    def add_call(self, tool: str, params: dict, duration_ms: int, 
+                 result_count: int, response_size: int, status: str):
+        """Record a tool call."""
+        now = time.time()
+        time_since_last = int((now - self.last_call_time) * 1000) if self.last_call_time else 0
+        
+        self.calls.append({
+            "tool": tool,
+            "params": params,
+            "duration_ms": duration_ms,
+            "result_count": result_count,
+            "response_size": response_size,
+            "status": status,
+            "time_since_last_ms": time_since_last,
+        })
+        self.last_call_time = now
+        
+        # Track what's being queried
+        if "indicator_id" in params:
+            self.indicators_queried.add(params["indicator_id"])
+        if "geographic_level" in params:
+            self.levels_queried.add(params["geographic_level"])
+    
+    def get_sequence(self) -> str:
+        """Get the sequence of tools called."""
+        return "→".join(c["tool"].replace("_indicators", "").replace("_indicator", "") 
+                       for c in self.calls)
+    
+    def get_total_duration_ms(self) -> int:
+        """Total time spent in API calls."""
+        return sum(c["duration_ms"] for c in self.calls)
+
+
+class UsageTracker:
+    """Track MCP usage patterns across sessions."""
+    
+    # Session timeout in seconds (new session if no call for 5 minutes)
+    SESSION_TIMEOUT = 300
+    
+    def __init__(self):
+        self.sessions: dict[str, SessionData] = {}
+        self.patterns: defaultdict[str, int] = defaultdict(int)  # sequence -> count
+        self.tool_stats: defaultdict[str, dict] = defaultdict(
+            lambda: {"calls": 0, "total_ms": 0, "errors": 0}
+        )
+    
+    def get_or_create_session(self, session_hint: str = "default") -> SessionData:
+        """Get existing session or create new one."""
+        # Simple session management based on hint (could be IP, user-agent hash, etc.)
+        session_id = hashlib.md5(session_hint.encode()).hexdigest()[:8]
+        
+        now = time.time()
+        
+        # Check if session exists and is not expired
+        if session_id in self.sessions:
+            session = self.sessions[session_id]
+            if session.last_call_time and (now - session.last_call_time) > self.SESSION_TIMEOUT:
+                # Session expired, log pattern and create new
+                self._finalize_session(session)
+                session = SessionData(session_id=session_id)
+                self.sessions[session_id] = session
+                logger.info(f"[SESSION] id={session_id} | new_session (previous expired)")
+        else:
+            session = SessionData(session_id=session_id)
+            self.sessions[session_id] = session
+            logger.info(f"[SESSION] id={session_id} | new_session")
+        
+        return session
+    
+    def _finalize_session(self, session: SessionData):
+        """Log session summary when it ends."""
+        if len(session.calls) > 1:
+            sequence = session.get_sequence()
+            self.patterns[sequence] += 1
+            
+            logger.info(
+                f"[PATTERN] id={session.session_id} | "
+                f"sequence={sequence} | "
+                f"calls={len(session.calls)} | "
+                f"total_ms={session.get_total_duration_ms()} | "
+                f"indicators={list(session.indicators_queried)} | "
+                f"levels={list(session.levels_queried)}"
+            )
+    
+    def log_stats_summary(self):
+        """Log accumulated statistics."""
+        if self.patterns:
+            top_patterns = sorted(self.patterns.items(), key=lambda x: -x[1])[:5]
+            logger.info(f"[STATS] top_patterns={top_patterns}")
+
+
+# Global tracker instance
+_tracker = UsageTracker()
+
+
 def log_tool_call(func: Callable) -> Callable:
-    """Decorator to log MCP tool calls with timing and parameters."""
+    """Decorator to log MCP tool calls with rich metrics."""
     @wraps(func)
     async def wrapper(*args, **kwargs):
         tool_name = func.__name__
         start_time = time.time()
         
-        # Log the call
-        params = {k: v for k, v in kwargs.items() if v}  # Only non-empty params
-        logger.info(f"[CALL] {tool_name} | params={params}")
+        # Get or create session
+        session = _tracker.get_or_create_session()
+        
+        # Extract params (only non-empty)
+        params = {k: v for k, v in kwargs.items() if v}
+        
+        # Build context info
+        call_num = len(session.calls) + 1
+        prev_tool = session.calls[-1]["tool"] if session.calls else None
+        
+        # Log the call with context
+        context = f"call#{call_num}"
+        if prev_tool:
+            context += f" | prev={prev_tool}"
+        logger.info(f"[CALL] {tool_name} | {context} | params={params}")
         
         try:
             result = await func(*args, **kwargs)
             elapsed_ms = int((time.time() - start_time) * 1000)
+            response_size = len(result.encode('utf-8'))
             
-            # Parse result to get summary
+            # Parse result to get metrics
+            status = "ok"
+            result_count = 0
             try:
                 result_data = json.loads(result)
                 if "error" in result_data:
-                    logger.warning(f"[ERROR] {tool_name} | {elapsed_ms}ms | error={result_data['error']}")
-                elif "count" in result_data:
-                    logger.info(f"[OK] {tool_name} | {elapsed_ms}ms | count={result_data['count']}")
-                elif "total_count" in result_data:
-                    logger.info(f"[OK] {tool_name} | {elapsed_ms}ms | count={result_data['total_count']}")
-                elif "metadata" in result_data:
-                    ind_id = result_data.get("metadata", {}).get("id", "?")
-                    logger.info(f"[OK] {tool_name} | {elapsed_ms}ms | indicator_id={ind_id}")
+                    status = "error"
+                    logger.warning(
+                        f"[ERROR] {tool_name} | {elapsed_ms}ms | "
+                        f"error={result_data['error'][:100]}"
+                    )
                 else:
-                    logger.info(f"[OK] {tool_name} | {elapsed_ms}ms")
+                    result_count = (
+                        result_data.get("count") or 
+                        result_data.get("total_count") or 
+                        len(result_data.get("data", [])) or
+                        (1 if "metadata" in result_data else 0)
+                    )
+                    logger.info(
+                        f"[OK] {tool_name} | {elapsed_ms}ms | "
+                        f"count={result_count} | size={response_size}B"
+                    )
             except json.JSONDecodeError:
-                logger.info(f"[OK] {tool_name} | {elapsed_ms}ms | raw_response")
+                logger.info(f"[OK] {tool_name} | {elapsed_ms}ms | size={response_size}B")
+            
+            # Record in session
+            session.add_call(
+                tool=tool_name,
+                params=params,
+                duration_ms=elapsed_ms,
+                result_count=result_count,
+                response_size=response_size,
+                status=status,
+            )
+            
+            # Update global stats
+            _tracker.tool_stats[tool_name]["calls"] += 1
+            _tracker.tool_stats[tool_name]["total_ms"] += elapsed_ms
+            if status == "error":
+                _tracker.tool_stats[tool_name]["errors"] += 1
             
             return result
             
         except Exception as e:
             elapsed_ms = int((time.time() - start_time) * 1000)
             logger.error(f"[EXCEPTION] {tool_name} | {elapsed_ms}ms | {type(e).__name__}: {e}")
+            _tracker.tool_stats[tool_name]["errors"] += 1
             raise
     
     return wrapper