celery 升级优化V2 | 日志调整 | 前端BUG修复

video-gen-api/app/services/llm.py

@@ -1,6 +1,6 @@
 import json
-import os
-from datetime import datetime
+import time
+from types import SimpleNamespace
 
 import httpx
 from sqlalchemy import select
@@ -10,47 +10,13 @@ from app.config import settings
 from app.models.model_config import ModelConfig
 from app.models.token_usage import TokenUsage
 from app.utils.id_gen import generate_id
-from app.services.log_config import is_enabled, LOG_DIR, LOG_DATE_FORMAT, encrypt_data
+from app.services.operation_log_service import build_exception_detail, log_ai_model_event
 
 
-def _sanitize_for_log(data):
-    """Replace base64 data URIs with placeholder for readable logs."""
-    if isinstance(data, str):
-        if data.startswith("data:") and ";base64," in data:
-            return "[base64 image data]"
-        return data
-    if isinstance(data, dict):
-        return {k: _sanitize_for_log(v) for k, v in data.items()}
-    if isinstance(data, list):
-        return [_sanitize_for_log(item) for item in data]
-    return data
 
 
-def _log_ai_request_response(config, request_data: dict, response_data: dict | None, error: str | None = None):
-    """Log AI model request/response to log/AiModel/YYYY-MM-DD.log"""
-    if not is_enabled():
-        return
-    try:
-        os.makedirs(LOG_DIR, exist_ok=True)
-        today = datetime.now().strftime(LOG_DATE_FORMAT)
-        log_file = os.path.join(LOG_DIR, f"{today}.log")
-        request_encrypted = encrypt_data(_sanitize_for_log(request_data), True)
-        response_encrypted = encrypt_data(_sanitize_for_log(response_data), True) if response_data else ""
-        entry = {
-            "timestamp": datetime.now().strftime("%Y-%m-%d %H:%M:%S"),
-            "model_name": config.name,
-            "model_id": config.model_name,
-            "provider": config.provider,
-            "api_base": config.api_base,
-            "request": request_encrypted,
-            "response": response_encrypted,
-            "error": error,
-        }
-        with open(log_file, "a", encoding="utf-8") as f:
-            f.write(json.dumps(entry, ensure_ascii=False) + "\n")
-    except Exception:
-        pass
-
+class LLMProviderCallError(RuntimeError):
+    """Remote model call or response validation failed and may use fallback."""
 
 MOCK_OPTIMIZED_PROMPTS = {
     "直播": "专业直播间场景，45度斜角机位，暖色柔光打光，主播居中构图，背景虚化处理，产品特写切换流畅，镜头推进节奏感强，画面色彩饱和度高，适合电商直播推广视频。",
@@ -92,9 +58,17 @@ async def optimize_prompt(
     duration: int | None = None,
     image_size: str | None = None,
     image_proportion: str | None = None,
-    image_px: str | None | None = None,
+    image_px: str | None = None,
     references: list[dict] | None = None,
     gen_type: str = "video",
+    *,
+    log_module: str = "generation_ai",
+    log_step: str = "prompt_optimize",
+    log_project_id: str | None = None,
+    log_task_id: str | None = None,
+    log_owner_type: str | None = None,
+    log_owner_id: str | None = None,
+    generation_attempt_no: int | None = None,
 ) -> tuple[str, dict]:
     """Optimize user prompt using LLM. Returns (optimized_text, token_usage_dict)."""
 
@@ -103,9 +77,22 @@ async def optimize_prompt(
         .where(ModelConfig.is_active == True, ModelConfig.deleted_at.is_(None))
         .order_by(ModelConfig.priority.desc())
     )
-    configs = list(result.scalars().all())
-    # Release the read transaction before the external LLM request. Callers
-    # must commit their business claim before invoking optimize_prompt.
+    configs = [
+        SimpleNamespace(
+            id=item.id,
+            name=item.name,
+            provider=item.provider,
+            api_base=item.api_base,
+            api_key=item.api_key,
+            model_name=item.model_name,
+            max_tokens=item.max_tokens,
+            temperature=item.temperature,
+        )
+        for item in result.scalars().all()
+    ]
+    # Release the read transaction before the external LLM request. Only
+    # plain scalar snapshots are used afterwards, so expire_on_commit does
+    # not trigger an ORM refresh while the provider request is in flight.
     await db.commit()
 
     if configs:
@@ -122,8 +109,15 @@ async def optimize_prompt(
                         image_size=image_size,
                         image_proportion=image_proportion,
                         image_px=image_px,
+                        log_module=log_module,
+                        log_step=log_step,
+                        log_project_id=log_project_id,
+                        log_task_id=log_task_id,
+                        log_owner_type=log_owner_type,
+                        log_owner_id=log_owner_id,
+                        generation_attempt_no=generation_attempt_no,
                     )
-                except Exception:
+                except LLMProviderCallError:
                     continue
 
         # 所有真实模型都失败，降级到 mock
@@ -156,7 +150,15 @@ async def _call_openai_compatible(
     gen_type: str = "video",
     image_size: str | None = None,
     image_proportion: str | None = None,
-    image_px: str | None | None = None,
+    image_px: str | None = None,
+    *,
+    log_module: str = "generation_ai",
+    log_step: str = "prompt_optimize",
+    log_project_id: str | None = None,
+    log_task_id: str | None = None,
+    log_owner_type: str | None = None,
+    log_owner_id: str | None = None,
+    generation_attempt_no: int | None = None,
 ) -> tuple[str, dict]:
     """Call an OpenAI-compatible API to optimize the prompt. Returns (content, token_usage)."""
     system_prompt = None
@@ -321,14 +323,33 @@ async def _call_openai_compatible(
             "max_tokens": config.max_tokens,
             "temperature": config.temperature,
         }
-        # Build log-friendly request data (image paths instead of base64)
-        if log_user_message:
-            log_request_data = {**request_data, "messages": [
-                {"role": "system", "content": system_prompt},
-                log_user_message,
-            ]}
-        else:
-            log_request_data = request_data
+        call_id = generate_id()
+        started = time.perf_counter()
+        common_log = {
+            "module": log_module,
+            "step_code": log_step,
+            "call_id": call_id,
+            "source": "app.services.llm",
+            "user_id": user_id,
+            "project_id": log_project_id,
+            "task_id": log_task_id,
+            "owner_type": log_owner_type,
+            "owner_id": log_owner_id,
+            "generation_attempt_no": generation_attempt_no,
+            "model_config_id": config.id,
+            "model_config_name": config.name,
+            "model_name": config.model_name,
+            "provider": config.provider,
+            "api_base": config.api_base,
+            "remote_action": "chat_completions",
+        }
+        log_ai_model_event(
+            event_type="REQUEST",
+            event_phase="REQUEST",
+            event_status="started",
+            request=request_data,
+            **common_log,
+        )
         try:
             response = await client.post(
                 f"{config.api_base}/chat/completions",
@@ -338,47 +359,117 @@ async def _call_openai_compatible(
                 },
                 json=request_data,
             )
+            latency_ms = int((time.perf_counter() - started) * 1000)
             if response.status_code >= 400:
                 error_body = response.text
-                _log_ai_request_response(config, log_request_data, None, error=f"HTTP {response.status_code}: {error_body}")
-                raise RuntimeError(f"HTTP {response.status_code}: {error_body}")
+                log_ai_model_event(
+                    event_type="RESPONSE",
+                    event_phase="RESPONSE",
+                    event_status="failed",
+                    http_status=response.status_code,
+                    latency_ms=latency_ms,
+                    response={"body": error_body},
+                    error=f"HTTP {response.status_code}",
+                    **common_log,
+                )
+                error = LLMProviderCallError(f"HTTP {response.status_code}: {error_body}")
+                log_ai_model_event(
+                    event_type="ERROR",
+                    event_phase="ERROR",
+                    event_status="failed",
+                    http_status=response.status_code,
+                    latency_ms=latency_ms,
+                    detail=build_exception_detail(error),
+                    error=str(error),
+                    **common_log,
+                )
+                raise error
             data = response.json()
-        except RuntimeError:
+            log_ai_model_event(
+                event_type="RESPONSE",
+                event_phase="RESPONSE",
+                event_status="success",
+                http_status=response.status_code,
+                latency_ms=latency_ms,
+                response=data,
+                token_usage=data.get("usage") if isinstance(data, dict) else None,
+                **common_log,
+            )
+        except LLMProviderCallError:
             raise
-        except Exception as e:
-            _log_ai_request_response(config, log_request_data, None, error=str(e))
-            raise RuntimeError(f"{type(e).__name__}: {e}")
+        except Exception as exc:
+            latency_ms = int((time.perf_counter() - started) * 1000)
+            log_ai_model_event(
+                event_type="ERROR",
+                event_phase="ERROR",
+                event_status="failed",
+                latency_ms=latency_ms,
+                detail=build_exception_detail(exc),
+                error=str(exc),
+                **common_log,
+            )
+            raise LLMProviderCallError(f"{type(exc).__name__}: {exc}") from exc
 
-        # Log request/response
-        _log_ai_request_response(config, log_request_data, data)
-
-        # Record token usage
-        usage = data.get("usage", {})
-        input_tokens = usage.get("prompt_tokens", 0)
-        output_tokens = usage.get("completion_tokens", 0)
-        total_tokens = usage.get("total_tokens", input_tokens + output_tokens)
+        try:
+            usage = data.get("usage", {})
+            input_tokens = int(usage.get("prompt_tokens", 0) or 0)
+            output_tokens = int(usage.get("completion_tokens", 0) or 0)
+            total_tokens = int(usage.get("total_tokens", input_tokens + output_tokens) or 0)
+            content = data["choices"][0]["message"]["content"].strip()
+            if not content:
+                raise ValueError("模型未返回有效提示词")
+        except Exception as exc:
+            log_ai_model_event(
+                event_type="ERROR",
+                event_phase="ERROR",
+                event_status="failed",
+                latency_ms=int((time.perf_counter() - started) * 1000),
+                detail=build_exception_detail(exc, {"stage": "response_validation"}),
+                error=str(exc),
+                **common_log,
+            )
+            raise LLMProviderCallError(f"模型响应解析失败: {exc}") from exc
 
         token_usage_id = None
         if db is not None:
-            token_usage_id = generate_id()
-            record = TokenUsage(
-                id=token_usage_id,
-                model_config_id=config.id,
-                user_id=user_id,
-                input_tokens=input_tokens,
-                output_tokens=output_tokens,
-                total_tokens=total_tokens,
-            )
-            db.add(record)
-            await db.flush()
+            try:
+                token_usage_id = generate_id()
+                record = TokenUsage(
+                    id=token_usage_id,
+                    model_config_id=config.id,
+                    user_id=user_id,
+                    input_tokens=input_tokens,
+                    output_tokens=output_tokens,
+                    total_tokens=total_tokens,
+                    source_module=log_module,
+                    source_step_code=log_step,
+                    owner_type=log_owner_type,
+                    owner_id=log_owner_id,
+                )
+                db.add(record)
+                await db.flush()
+            except Exception as exc:
+                log_ai_model_event(
+                    event_type="ERROR",
+                    event_phase="ERROR",
+                    event_status="failed",
+                    latency_ms=int((time.perf_counter() - started) * 1000),
+                    detail=build_exception_detail(exc, {"stage": "token_usage_persistence"}),
+                    error=str(exc),
+                    **common_log,
+                )
+                # A local transaction failure must not call a second provider after
+                # the first provider has already returned a valid response.
+                raise
 
-        content = data["choices"][0]["message"]["content"].strip()
         token_usage = {
             "token_usage_id": token_usage_id,
             "model_config_id": config.id,
             "model_config_name": config.name,
             "model_provider": config.provider,
             "model_name": config.model_name,
+            "source_module": log_module,
+            "source_step_code": log_step,
             "input_tokens": input_tokens,
             "output_tokens": output_tokens,
             "total_tokens": total_tokens,