07979bfb09
Replace CreateRecTask polling with recording-file flash API, add TENCENT_APP_ID, remove server-side pydub slicing, and log ASR recognition text at INFO in development. Co-authored-by: Cursor <cursoragent@cursor.com>
226 lines
7.3 KiB
Python
226 lines
7.3 KiB
Python
"""
|
||
Agent / LLM 诊断日志：耗时、输入输出规模、截断预览。
|
||
|
||
- **详情**（prompt 预览 / hash / 响应预览）：仅在 ``LOG_LEVEL`` 为 ``TRACE`` / ``DEBUG`` 时通过 ``logger.debug`` 输出。
|
||
- **摘要**（单行：耗时、字符数、operation 名）：当 ``LOG_AGENT_VERBOSE=1`` 时通过 ``logger.info`` 输出，
|
||
便于生产环境在不把全局日志调到 DEBUG 的情况下排查 Agent 性能与路径。
|
||
|
||
生产/预发建议 ``LOG_LEVEL=INFO``；需看 Agent 耗时与规模时可设 ``LOG_AGENT_VERBOSE=1``，无需长期 DEBUG。
|
||
|
||
敏感内容：DEBUG 下会记录用户相关文本；``AGENT_LOG_MAX_CHARS=0`` 时预览不截断（完整输出，慎用）。
|
||
|
||
配置（节选）：``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`` 的前缀再预览；
|
||
``AGENT_LOG_PROMPT_MODE=hash_only`` 时 ``*.prompt`` 仅输出 sha12 + 长度，无正文；
|
||
``AGENT_LOG_PROMPT_DEDUP=1`` 时同一 label 连续相同全文则跳过重复行。
|
||
"""
|
||
|
||
from __future__ import annotations
|
||
|
||
import hashlib
|
||
import threading
|
||
import time
|
||
from contextlib import contextmanager
|
||
from typing import Any, Iterator
|
||
|
||
from opentelemetry import trace
|
||
from opentelemetry.trace import Status, StatusCode
|
||
|
||
from app.core.config import settings
|
||
from app.core.telemetry import get_tracer
|
||
from app.core.runtime_constants import agent_log_defaults
|
||
|
||
_dedup_lock = threading.Lock()
|
||
_last_prompt_sha256_by_label: dict[str, str] = {}
|
||
|
||
|
||
def _payload_sha256_hex(text: str) -> str:
|
||
return hashlib.sha256(text.encode("utf-8", errors="replace")).hexdigest()
|
||
|
||
|
||
def _payload_sha12(text: str) -> str:
|
||
return _payload_sha256_hex(text)[:12]
|
||
|
||
|
||
def agent_verbose_enabled() -> bool:
|
||
"""是否输出含 prompt/response 等 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(agent_log_defaults.agent_verbose)
|
||
|
||
|
||
def truncate_for_log(text: str | None, *, max_chars: int | None = None) -> str:
|
||
"""截断过长文本，避免日志爆量。max_chars / AGENT_LOG_MAX_CHARS 为 0 表示不截断。"""
|
||
if text is None:
|
||
return ""
|
||
max_c = max_chars if max_chars is not None else agent_log_defaults.max_chars
|
||
s = str(text)
|
||
if max_c <= 0 or 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)
|
||
|
||
|
||
def asr_transcript_log_enabled() -> bool:
|
||
"""development 环境或全局 DEBUG/TRACE 时以 INFO 输出 ASR 识别全文。"""
|
||
env = (settings.app_environment or "").strip().lower()
|
||
if env == "development":
|
||
return True
|
||
return agent_verbose_enabled()
|
||
|
||
|
||
def log_asr_transcript_result(
|
||
logger: Any,
|
||
*,
|
||
text: str,
|
||
**context: Any,
|
||
) -> None:
|
||
"""在 ``asr_transcript_log_enabled()`` 时记录识别结果（过长文本会截断）。"""
|
||
if not asr_transcript_log_enabled():
|
||
return
|
||
parts = [f"{k}={v}" for k, v in context.items() if v is not None and v != ""]
|
||
ctx = " ".join(parts)
|
||
body = truncate_for_log(text)
|
||
if ctx:
|
||
logger.info("ASR 识别结果 {} text={}", ctx, body)
|
||
else:
|
||
logger.info("ASR 识别结果 text={}", body)
|
||
|
||
|
||
@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)
|
||
|
||
def _log_end(ms: float) -> None:
|
||
if agent_verbose_enabled():
|
||
logger.debug("agent_span_end {} duration_ms={:.2f} {}", operation, ms, ctx)
|
||
elif agent_log_defaults.agent_verbose:
|
||
logger.info("agent_span {} duration_ms={:.2f} {}", operation, ms, ctx)
|
||
|
||
if settings.otel_enabled:
|
||
tracer = get_tracer("app.agent")
|
||
with tracer.start_as_current_span(
|
||
"agent.operation",
|
||
attributes={"agent.operation": operation},
|
||
) as span:
|
||
failed = False
|
||
try:
|
||
yield
|
||
except Exception:
|
||
failed = True
|
||
if span.is_recording():
|
||
span.set_status(Status(StatusCode.ERROR))
|
||
raise
|
||
finally:
|
||
ms = (time.perf_counter() - t0) * 1000
|
||
if span.is_recording():
|
||
span.set_attribute("agent.duration_ms", round(ms, 2))
|
||
if not failed:
|
||
span.set_status(Status(StatusCode.OK))
|
||
_log_end(ms)
|
||
return
|
||
|
||
try:
|
||
yield
|
||
finally:
|
||
_log_end((time.perf_counter() - t0) * 1000)
|
||
|
||
|
||
def log_agent_payload(
|
||
logger: Any,
|
||
label: str,
|
||
text: str | None,
|
||
*,
|
||
max_chars: int | None = None,
|
||
) -> None:
|
||
"""在 DEBUG 下记录文本长度与截断预览（*.prompt 可 hash_only / 去重）。"""
|
||
if not agent_verbose_enabled():
|
||
return
|
||
raw = text or ""
|
||
total_len = len(raw)
|
||
digest = _payload_sha256_hex(raw)
|
||
sha12 = digest[:12]
|
||
|
||
is_prompt = label.endswith(".prompt")
|
||
if is_prompt and agent_log_defaults.prompt_dedup:
|
||
with _dedup_lock:
|
||
if _last_prompt_sha256_by_label.get(label) == digest:
|
||
logger.debug(
|
||
"agent_payload_skipped label={} reason=same_as_previous sha12={} total_len={}",
|
||
label,
|
||
sha12,
|
||
total_len,
|
||
)
|
||
return
|
||
_last_prompt_sha256_by_label[label] = digest
|
||
|
||
preview_source = raw
|
||
extra_note = ""
|
||
if (
|
||
is_prompt
|
||
and agent_log_defaults.json_prompt_prefix_chars > 0
|
||
and total_len > agent_log_defaults.json_prompt_prefix_only_if_len_gt
|
||
):
|
||
skip = agent_log_defaults.json_prompt_prefix_chars
|
||
preview_source = raw[skip:]
|
||
extra_note = f" skipped_prefix_chars={skip}"
|
||
|
||
mode = (agent_log_defaults.prompt_mode or "preview").strip().lower()
|
||
if is_prompt and mode == "hash_only":
|
||
logger.debug(
|
||
"agent_payload label={} total_len={} sha12={} mode=hash_only{}",
|
||
label,
|
||
total_len,
|
||
sha12,
|
||
extra_note,
|
||
)
|
||
return
|
||
|
||
preview = truncate_for_log(preview_source, max_chars=max_chars)
|
||
logger.debug(
|
||
"agent_payload {} total_len={}{} sha12={} preview={}",
|
||
label,
|
||
total_len,
|
||
extra_note,
|
||
sha12,
|
||
preview,
|
||
)
|