life-echo/api/app/core/agent_logging.py

"""
Agent / LLM 诊断日志：耗时、输入输出规模、截断预览。

- **详情**（完整 prompt 预览等）：仅在 ``LOG_LEVEL`` 为 ``TRACE`` / ``DEBUG`` 时通过 ``logger.debug`` 输出。
- **摘要**（单行：耗时、字符数、operation 名）：当 ``LOG_AGENT_VERBOSE=1`` 时通过 ``logger.info`` 输出，
  便于生产环境在不把全局日志调到 DEBUG 的情况下排查 Agent 性能与路径。

敏感内容：DEBUG 下会记录用户相关文本截断预览，生产环境请勿长期开启 DEBUG。

配置（节选）：``AGENT_LOG_OMIT_SYSTEM_MESSAGE_BODY``（默认 true）省略聊天 System 正文，仅打 len+sha12；
``AGENT_LOG_JSON_PROMPT_PREFIX_CHARS`` + ``AGENT_LOG_JSON_PROMPT_PREFIX_ONLY_IF_LEN_GT`` 在 DEBUG 下跳过
超长单段 prompt 的前缀再预览。
"""

from __future__ import annotations

import time
from contextlib import contextmanager
from typing import Any, Iterator

from app.core.config import settings


def agent_verbose_enabled() -> bool:
    """是否输出含完整 prompt 预览等 DEBUG 级详情。"""
    raw = (settings.log_level or "INFO").strip().upper()
    return raw in ("TRACE", "DEBUG")


def agent_summary_enabled() -> bool:
    """是否输出单行 INFO 摘要（耗时、规模等），不依赖全局 DEBUG。"""
    if agent_verbose_enabled():
        return True
    return bool(settings.log_agent_verbose)


def truncate_for_log(text: str | None, *, max_chars: int | None = None) -> str:
    """截断过长文本，避免日志爆量。"""
    if text is None:
        return ""
    max_c = max_chars if max_chars is not None else settings.agent_log_max_chars
    s = str(text)
    if len(s) <= max_c:
        return s
    return s[:max_c] + f"... [truncated total_len={len(s)}]"


def log_agent_detail(
    logger: Any,
    message: str,
    *args: Any,
) -> None:
    """DEBUG 级详情（含预览时先判断 ``agent_verbose_enabled()``）。"""
    if agent_verbose_enabled():
        logger.debug(message, *args)


def log_agent_summary(
    logger: Any,
    message: str,
    *args: Any,
) -> None:
    """INFO 级单行摘要（``LOG_AGENT_VERBOSE`` 或 DEBUG 全局时启用）。"""
    if agent_summary_enabled():
        logger.info(message, *args)


@contextmanager
def agent_span(
    logger: Any,
    operation: str,
    **context: Any,
) -> Iterator[None]:
    """
    记录一段 Agent/LLM 调用的起止与耗时。
    - DEBUG：输出 context 与起止。
    - INFO（仅 ``LOG_AGENT_VERBOSE``）：仅输出结束行含 duration_ms。
    """
    t0 = time.perf_counter()
    ctx = " ".join(f"{k}={v!r}" for k, v in context.items())
    if agent_verbose_enabled():
        logger.debug("agent_span_start {} {}", operation, ctx)
    try:
        yield
    finally:
        ms = (time.perf_counter() - t0) * 1000
        if agent_verbose_enabled():
            logger.debug("agent_span_end {} duration_ms={:.2f} {}", operation, ms, ctx)
        elif settings.log_agent_verbose:
            logger.info("agent_span {} duration_ms={:.2f} {}", operation, ms, ctx)


def log_agent_payload(
    logger: Any,
    label: str,
    text: str | None,
    *,
    max_chars: int | None = None,
) -> None:
    """在 DEBUG 下记录文本长度与截断预览。"""
    if not agent_verbose_enabled():
        return
    raw = text or ""
    total_len = len(raw)
    preview_source = raw
    extra_note = ""
    if (
        label.endswith(".prompt")
        and settings.agent_log_json_prompt_prefix_chars > 0
        and total_len > settings.agent_log_json_prompt_prefix_only_if_len_gt
    ):
        skip = settings.agent_log_json_prompt_prefix_chars
        preview_source = raw[skip:]
        extra_note = f" skipped_prefix_chars={skip}"
    preview = truncate_for_log(preview_source, max_chars=max_chars)
    logger.debug(
        "agent_payload {} total_len={}{} preview={}",
        label,
        total_len,
        extra_note,
        preview,
    )