SupplyAgent/supply_agent/logging/logger.py

from __future__ import annotations

import json
import logging
import re
import uuid
from datetime import datetime, timezone
from pathlib import Path
from typing import Any

from supply_agent.types import AgentResult, Message, ToolDefinition


def _serialize(obj: Any) -> str:
    """Serialize any object to a complete, non-truncated JSON string."""

    def default(o: Any) -> Any:
        if hasattr(o, "model_dump"):
            return o.model_dump()
        if hasattr(o, "to_api_dict"):
            return o.to_api_dict()
        return str(o)

    return json.dumps(obj, ensure_ascii=False, indent=2, default=default)


def _try_parse_json(text: str) -> Any:
    """Best-effort JSON parse; return original string on failure."""
    try:
        return json.loads(text)
    except (json.JSONDecodeError, TypeError):
        return text


def _extract_usage(raw_response: Any) -> dict[str, Any] | None:
    if raw_response is None:
        return None
    usage = getattr(raw_response, "usage", None)
    if usage is None and isinstance(raw_response, dict):
        usage = raw_response.get("usage")
    if usage is None:
        return None
    if hasattr(usage, "model_dump"):
        return usage.model_dump()
    if isinstance(usage, dict):
        return usage
    return {"raw": str(usage)}


def _extract_skill_name(skill_name_or_args: str) -> str:
    parsed = _try_parse_json(skill_name_or_args)
    if isinstance(parsed, dict):
        return str(parsed.get("name") or skill_name_or_args)
    return skill_name_or_args


def slugify_agent_name(name: str | None) -> str | None:
    """Make agent name safe for use in log filenames / OSS paths."""
    if not name:
        return None
    slug = re.sub(r"[^\w\-]+", "_", name.strip(), flags=re.UNICODE)
    slug = re.sub(r"_+", "_", slug).strip("_.")
    return slug[:64] or None


# Backwards-compatible alias
_slugify_agent_name = slugify_agent_name


class _FullContentFormatter(logging.Formatter):
    """Formatter that never truncates message content."""

    def format(self, record: logging.LogRecord) -> str:
        record.message = record.getMessage()
        return f"[{self.formatTime(record, '%Y-%m-%d %H:%M:%S')}] {record.message}"


class AgentLogger:
    """
    Encapsulated logger for agent runs.

    Each run writes:
    - ``logs/run_<id>.log``   — human-readable full dump
    - ``logs/run_<id>.jsonl`` — structured event stream for visualization
    """

    def __init__(self, logs_dir: Path | str = "logs", *, enabled: bool = True) -> None:
        self.logs_dir = Path(logs_dir)
        self.enabled = enabled
        self._run_id: str | None = None
        self._log_file: Path | None = None
        self._jsonl_file: Path | None = None
        self._logger: logging.Logger | None = None
        self._seq: int = 0
        self._jsonl_fh: Any | None = None
        self._agent_name: str | None = None
        self._last_model: str | None = None

    @property
    def run_id(self) -> str | None:
        return self._run_id

    @property
    def agent_name(self) -> str | None:
        return self._agent_name

    @property
    def last_model(self) -> str | None:
        return self._last_model

    @property
    def log_file(self) -> Path | None:
        return self._log_file

    @property
    def jsonl_file(self) -> Path | None:
        return self._jsonl_file

    def start_run(
        self,
        user_input: str,
        *,
        model: str,
        agent_name: str | None = None,
    ) -> str:
        """Start a new run log file. Returns the run id."""
        if not self.enabled:
            return ""

        self.logs_dir.mkdir(parents=True, exist_ok=True)
        timestamp = datetime.now().strftime("%Y%m%d_%H%M%S")
        short_id = uuid.uuid4().hex[:8]
        slug = _slugify_agent_name(agent_name)
        self._agent_name = agent_name
        self._last_model = model
        if slug:
            self._run_id = f"{slug}_{timestamp}_{short_id}"
        else:
            self._run_id = f"{timestamp}_{short_id}"
        self._log_file = self.logs_dir / f"run_{self._run_id}.log"
        self._jsonl_file = self.logs_dir / f"run_{self._run_id}.jsonl"
        self._seq = 0

        self._logger = logging.getLogger(f"supply_agent.run.{self._run_id}")
        self._logger.setLevel(logging.DEBUG)
        self._logger.handlers.clear()
        self._logger.propagate = False

        formatter = _FullContentFormatter()

        file_handler = logging.FileHandler(self._log_file, encoding="utf-8")
        file_handler.setFormatter(formatter)
        self._logger.addHandler(file_handler)

        console_handler = logging.StreamHandler()
        console_handler.setFormatter(formatter)
        self._logger.addHandler(console_handler)

        self._jsonl_fh = open(self._jsonl_file, "w", encoding="utf-8")

        self._emit(
            "run_start",
            {
                "run_id": self._run_id,
                "agent_name": agent_name,
                "model": model,
                "user_input": user_input,
                "log_file": str(self._log_file),
                "jsonl_file": str(self._jsonl_file),
            },
            title="RUN START",
        )
        return self._run_id

    def log_llm_input(
        self,
        iteration: int,
        model: str,
        messages: list[Message],
        tools: list[ToolDefinition] | None,
        temperature: float,
    ) -> None:
        """Log the complete LLM request payload."""
        if not self.enabled or not self._logger:
            return

        self._last_model = model
        payload = {
            "iteration": iteration,
            "model": model,
            "temperature": temperature,
            "messages": [m.to_api_dict() for m in messages],
            "tools": [t.to_api_dict() for t in tools] if tools else None,
            "message_count": len(messages),
            "tool_count": len(tools) if tools else 0,
        }
        self._emit(
            "llm_input",
            payload,
            iteration=iteration,
            title=f"LLM INPUT | step={self._seq + 1} | iteration={iteration}",
        )

    def log_llm_output(
        self,
        iteration: int,
        response: Message,
        raw_response: Any | None = None,
        *,
        model: str | None = None,
        provider: str = "openrouter",
    ) -> None:
        """Log the complete LLM response, highlighting reasoning and tool calls."""
        if not self.enabled or not self._logger:
            return

        parsed = response.model_dump()
        tool_calls = parsed.get("tool_calls") or []
        usage = _extract_usage(raw_response)
        resolved_model = model or self._extract_model(raw_response) or self._last_model
        if resolved_model:
            self._last_model = resolved_model

        payload: dict[str, Any] = {
            "iteration": iteration,
            "model": resolved_model,
            "content": parsed.get("content"),
            "reasoning": parsed.get("reasoning"),
            "tool_calls": tool_calls,
            "has_reasoning": bool(parsed.get("reasoning")),
            "tool_call_count": len(tool_calls),
            "usage": usage,
            "parsed": parsed,
        }
        if raw_response is not None:
            if hasattr(raw_response, "model_dump"):
                payload["raw"] = raw_response.model_dump()
            else:
                payload["raw"] = raw_response

        self._emit(
            "llm_output",
            payload,
            iteration=iteration,
            title=f"LLM OUTPUT | step={self._seq + 1} | iteration={iteration}",
        )
        self._record_usage(
            iteration=iteration,
            model=resolved_model,
            usage=usage,
            provider=provider,
        )

    def log_tool_call(
        self,
        iteration: int,
        name: str,
        arguments: str,
        result: str,
        is_error: bool = False,
        *,
        tool_call_id: str | None = None,
    ) -> None:
        """Log a tool execution with full arguments and result."""
        if not self.enabled or not self._logger:
            return

        args_parsed = _try_parse_json(arguments)
        result_parsed = _try_parse_json(result)

        payload = {
            "iteration": iteration,
            "tool": name,
            "tool_call_id": tool_call_id,
            "arguments": arguments,
            "arguments_parsed": args_parsed,
            "result": result,
            "result_parsed": result_parsed,
            "is_error": is_error,
        }
        status = "ERROR" if is_error else "OK"
        self._emit(
            "tool_call",
            payload,
            iteration=iteration,
            title=f"TOOL CALL | step={self._seq + 1} | iteration={iteration} | {name} [{status}]",
        )

    def log_skill_loaded(self, iteration: int, skill_name: str) -> None:
        """Log when a skill is loaded."""
        if not self.enabled or not self._logger:
            return

        name = _extract_skill_name(skill_name)
        self._emit(
            "skill_loaded",
            {"iteration": iteration, "skill": name},
            iteration=iteration,
            title=f"SKILL LOADED | step={self._seq + 1} | iteration={iteration} | {name}",
        )

    def end_run(self, result: AgentResult) -> None:
        """Log run summary and close the run log."""
        if not self.enabled or not self._logger:
            return

        self._emit(
            "run_end",
            {
                "run_id": self._run_id,
                "agent_name": self._agent_name,
                "iterations": result.iterations,
                "tool_calls_made": result.tool_calls_made,
                "skills_used": result.skills_used,
                "final_content": result.content,
            },
            title="RUN END",
        )

        for handler in self._logger.handlers:
            handler.close()
        self._logger.handlers.clear()

        if self._jsonl_fh is not None:
            self._jsonl_fh.close()
            self._jsonl_fh = None

    def _extract_model(self, raw_response: Any) -> str | None:
        if raw_response is None:
            return None
        model = getattr(raw_response, "model", None)
        if model is None and isinstance(raw_response, dict):
            model = raw_response.get("model")
        return str(model) if model else None

    def _record_usage(
        self,
        *,
        iteration: int,
        model: str | None,
        usage: dict[str, Any] | None,
        provider: str,
    ) -> None:
        if not usage:
            return
        from supply_agent.logging.usage import record_llm_usage

        record_llm_usage(
            {
                "run_id": self._run_id,
                "agent_name": self._agent_name,
                "model": model,
                "provider": provider,
                "iteration": iteration,
                "usage": usage,
            }
        )

    def _emit(
        self,
        event: str,
        data: dict[str, Any],
        *,
        title: str,
        iteration: int | None = None,
    ) -> None:
        assert self._logger is not None
        self._seq += 1
        ts = datetime.now(timezone.utc).astimezone().isoformat(timespec="seconds")

        record: dict[str, Any] = {
            "event": event,
            "ts": ts,
            "seq": self._seq,
            "run_id": self._run_id,
            "data": data,
        }
        if iteration is not None:
            record["iteration"] = iteration

        if self._jsonl_fh is not None:
            self._jsonl_fh.write(json.dumps(record, ensure_ascii=False, default=str) + "\n")
            self._jsonl_fh.flush()

        separator = "=" * 80
        body = _serialize(data)
        self._logger.info("%s\n%s\n%s\n%s", separator, title, separator, body)


# Module-level default logger instance
_default_logger: AgentLogger | None = None


def get_agent_logger(
    logs_dir: Path | str = "logs",
    *,
    enabled: bool = True,
) -> AgentLogger:
    """Get or create the default AgentLogger instance."""
    global _default_logger
    if _default_logger is None:
        _default_logger = AgentLogger(logs_dir, enabled=enabled)
    return _default_logger