feat: 新增客户端请求响应日志记录、优化错误处理及日志源标识

src/api/routes.py

@@ -1,13 +1,15 @@
 """API routes - OpenAI compatible endpoints"""
-from fastapi import APIRouter, Depends, HTTPException
+from fastapi import APIRouter, Depends, HTTPException, Request
 from fastapi.responses import StreamingResponse, JSONResponse
 from datetime import datetime
 from typing import List
 import json
 import re
+import time
 from ..core.auth import verify_api_key_header
 from ..core.models import ChatCompletionRequest
 from ..services.generation_handler import GenerationHandler, MODEL_CONFIG
+from ..core.logger import debug_logger
 
 router = APIRouter()
 
@@ -71,10 +73,22 @@ async def list_models(api_key: str = Depends(verify_api_key_header)):
 @router.post("/v1/chat/completions")
 async def create_chat_completion(
     request: ChatCompletionRequest,
-    api_key: str = Depends(verify_api_key_header)
+    api_key: str = Depends(verify_api_key_header),
+    http_request: Request = None
 ):
     """Create chat completion (unified endpoint for image and video generation)"""
+    start_time = time.time()
+
     try:
+        # Log client request
+        debug_logger.log_request(
+            method="POST",
+            url="/v1/chat/completions",
+            headers=dict(http_request.headers) if http_request else {},
+            body=request.dict(),
+            source="Client"
+        )
+
         # Extract prompt from messages
         if not request.messages:
             raise HTTPException(status_code=400, detail="Messages cannot be empty")
@@ -153,18 +167,36 @@ async def create_chat_completion(
                     result = chunk
 
                 if result:
-                    return JSONResponse(content=json.loads(result))
+                    duration_ms = (time.time() - start_time) * 1000
+                    response_data = json.loads(result)
+                    debug_logger.log_response(
+                        status_code=200,
+                        headers={"Content-Type": "application/json"},
+                        body=response_data,
+                        duration_ms=duration_ms,
+                        source="Client"
+                    )
+                    return JSONResponse(content=response_data)
                 else:
+                    duration_ms = (time.time() - start_time) * 1000
+                    error_response = {
+                        "error": {
+                            "message": "Availability check failed",
+                            "type": "server_error",
+                            "param": None,
+                            "code": None
+                        }
+                    }
+                    debug_logger.log_response(
+                        status_code=500,
+                        headers={"Content-Type": "application/json"},
+                        body=error_response,
+                        duration_ms=duration_ms,
+                        source="Client"
+                    )
                     return JSONResponse(
                         status_code=500,
-                        content={
+                        content=error_response
-                            "error": {
-                                "message": "Availability check failed",
-                                "type": "server_error",
-                                "param": None,
-                                "code": None
-                            }
-                        }
                     )
 
         # Handle streaming
@@ -229,31 +261,64 @@ async def create_chat_completion(
                 result = chunk
 
             if result:
-                return JSONResponse(content=json.loads(result))
+                duration_ms = (time.time() - start_time) * 1000
+                response_data = json.loads(result)
+                debug_logger.log_response(
+                    status_code=200,
+                    headers={"Content-Type": "application/json"},
+                    body=response_data,
+                    duration_ms=duration_ms,
+                    source="Client"
+                )
+                return JSONResponse(content=response_data)
             else:
                 # Return OpenAI-compatible error format
+                duration_ms = (time.time() - start_time) * 1000
+                error_response = {
+                    "error": {
+                        "message": "Availability check failed",
+                        "type": "server_error",
+                        "param": None,
+                        "code": None
+                    }
+                }
+                debug_logger.log_response(
+                    status_code=500,
+                    headers={"Content-Type": "application/json"},
+                    body=error_response,
+                    duration_ms=duration_ms,
+                    source="Client"
+                )
                 return JSONResponse(
                     status_code=500,
-                    content={
+                    content=error_response
-                        "error": {
-                            "message": "Availability check failed",
-                            "type": "server_error",
-                            "param": None,
-                            "code": None
-                        }
-                    }
                 )
 
     except Exception as e:
         # Return OpenAI-compatible error format
+        duration_ms = (time.time() - start_time) * 1000
+        error_response = {
+            "error": {
+                "message": str(e),
+                "type": "server_error",
+                "param": None,
+                "code": None
+            }
+        }
+        debug_logger.log_error(
+            error_message=str(e),
+            status_code=500,
+            response_text=str(e),
+            source="Client"
+        )
+        debug_logger.log_response(
+            status_code=500,
+            headers={"Content-Type": "application/json"},
+            body=error_response,
+            duration_ms=duration_ms,
+            source="Client"
+        )
         return JSONResponse(
             status_code=500,
-            content={
+            content=error_response
-                "error": {
-                    "message": str(e),
-                    "type": "server_error",
-                    "param": None,
-                    "code": None
-                }
-            }
         )

src/core/logger.py

@@ -68,9 +68,20 @@ class DebugLogger:
         headers: Dict[str, str],
         body: Optional[Any] = None,
         files: Optional[Dict] = None,
-        proxy: Optional[str] = None
+        proxy: Optional[str] = None,
+        source: str = "Server"
     ):
-        """Log API request details to log.txt"""
+        """Log API request details to log.txt
+
+        Args:
+            method: HTTP method
+            url: Request URL
+            headers: Request headers
+            body: Request body
+            files: Files to upload
+            proxy: Proxy URL
+            source: Request source - "Client" for user->sora2api, "Server" for sora2api->Sora
+        """
 
         # Check if debug mode is enabled
         if not config.debug_enabled:
@@ -78,7 +89,7 @@ class DebugLogger:
 
         try:
             self._write_separator()
-            self.logger.info(f"🔵 [REQUEST] {self._format_timestamp()}")
+            self.logger.info(f"🔵 [REQUEST][{source}] {self._format_timestamp()}")
             self._write_separator("-")
 
             # Basic info
@@ -136,9 +147,18 @@ class DebugLogger:
         status_code: int,
         headers: Dict[str, str],
         body: Any,
-        duration_ms: Optional[float] = None
+        duration_ms: Optional[float] = None,
+        source: str = "Server"
     ):
-        """Log API response details to log.txt"""
+        """Log API response details to log.txt
+
+        Args:
+            status_code: HTTP status code
+            headers: Response headers
+            body: Response body
+            duration_ms: Request duration in milliseconds
+            source: Request source - "Client" for user->sora2api, "Server" for sora2api->Sora
+        """
 
         # Check if debug mode is enabled
         if not config.debug_enabled:
@@ -146,7 +166,7 @@ class DebugLogger:
 
         try:
             self._write_separator()
-            self.logger.info(f"🟢 [RESPONSE] {self._format_timestamp()}")
+            self.logger.info(f"🟢 [RESPONSE][{source}] {self._format_timestamp()}")
             self._write_separator("-")
 
             # Status
@@ -192,9 +212,17 @@ class DebugLogger:
         self,
         error_message: str,
         status_code: Optional[int] = None,
-        response_text: Optional[str] = None
+        response_text: Optional[str] = None,
+        source: str = "Server"
     ):
-        """Log API error details to log.txt"""
+        """Log API error details to log.txt
+
+        Args:
+            error_message: Error message
+            status_code: HTTP status code
+            response_text: Response text
+            source: Request source - "Client" for user->sora2api, "Server" for sora2api->Sora
+        """
 
         # Check if debug mode is enabled
         if not config.debug_enabled:
@@ -202,7 +230,7 @@ class DebugLogger:
 
         try:
             self._write_separator()
-            self.logger.info(f"🔴 [ERROR] {self._format_timestamp()}")
+            self.logger.info(f"🔴 [ERROR][{source}] {self._format_timestamp()}")
             self._write_separator("-")
 
             if status_code:

src/services/sora_client.py

@@ -226,7 +226,8 @@ class SoraClient:
             debug_logger.log_error(
                 error_message=f"nf/create request failed: {str(e)}",
                 status_code=0,
-                response_text=str(e)
+                response_text=str(e),
+                source="Server"
             )
             raise
 
@@ -259,7 +260,8 @@ class SoraClient:
             debug_logger.log_error(
                 error_message=f"Sentinel request failed: {str(e)}",
                 status_code=0,
-                response_text=str(e)
+                response_text=str(e),
+                source="Server"
             )
             raise
 
@@ -386,7 +388,8 @@ class SoraClient:
                 headers=headers,
                 body=json_data,
                 files=multipart,
-                proxy=proxy_url
+                proxy=proxy_url,
+                source="Server"
             )
 
             # Record start time
@@ -414,7 +417,8 @@ class SoraClient:
                 status_code=response.status_code,
                 headers=dict(response.headers),
                 body=response_json if response_json else response.text,
-                duration_ms=duration_ms
+                duration_ms=duration_ms,
+                source="Server"
             )
 
             # Check status
@@ -436,7 +440,8 @@ class SoraClient:
                         debug_logger.log_error(
                             error_message=f"Unsupported country: {error_msg}",
                             status_code=response.status_code,
-                            response_text=error_msg
+                            response_text=error_msg,
+                            source="Server"
                         )
                         # Raise exception with structured error data
                         raise Exception(error_msg)
@@ -446,7 +451,8 @@ class SoraClient:
                 debug_logger.log_error(
                     error_message=error_msg,
                     status_code=response.status_code,
-                    response_text=response.text
+                    response_text=response.text,
+                    source="Server"
                 )
                 raise Exception(error_msg)
 
@@ -654,7 +660,8 @@ class SoraClient:
                 status_code=response.status_code,
                 headers=dict(response.headers),
                 body=response.text if response.text else "No content",
-                duration_ms=duration_ms
+                duration_ms=duration_ms,
+                source="Server"
             )
 
             # Check status (DELETE typically returns 204 No Content or 200 OK)
@@ -663,7 +670,8 @@ class SoraClient:
                 debug_logger.log_error(
                     error_message=error_msg,
                     status_code=response.status_code,
-                    response_text=response.text
+                    response_text=response.text,
+                    source="Server"
                 )
                 raise Exception(error_msg)
 
@@ -719,7 +727,8 @@ class SoraClient:
                     status_code=response.status_code,
                     headers=dict(response.headers),
                     body=response.text if response.text else "No content",
-                    duration_ms=duration_ms
+                    duration_ms=duration_ms,
+                    source="Server"
                 )
 
                 # Check status
@@ -728,7 +737,8 @@ class SoraClient:
                     debug_logger.log_error(
                         error_message=error_msg,
                         status_code=response.status_code,
-                        response_text=response.text
+                        response_text=response.text,
+                        source="Server"
                     )
                     raise Exception(error_msg)
 
@@ -741,7 +751,8 @@ class SoraClient:
                     debug_logger.log_error(
                         error_message=error_msg,
                         status_code=401,
-                        response_text=str(result)
+                        response_text=str(result),
+                        source="Server"
                     )
                     raise Exception(error_msg)
 
@@ -757,7 +768,8 @@ class SoraClient:
             debug_logger.log_error(
                 error_message=f"Custom parse request failed: {str(e)}",
                 status_code=500,
-                response_text=str(e)
+                response_text=str(e),
+                source="Server"
             )
             raise