Skip to content

增加调试日志并记录请求体 #2731

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closed
tanranv5 wants to merge 3 commits into from
Closed

增加调试日志并记录请求体 #2731

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
8759f9a
添加模型映射调试日志
tanranv5 Jan 24, 2026
bb08684
增加请求头覆盖调试日志
tanranv5 Jan 24, 2026
1a0bbba
增加渠道重试调试日志并记录请求体
tanranv5 Jan 24, 2026
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
26 changes: 25 additions & 1 deletion controller/relay.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -180,16 +180,20 @@ func Relay(c *gin.Context, relayFormat types.RelayFormat) {
}

for ; retryParam.GetRetry() <= common.RetryTimes; retryParam.IncreaseRetry() {
logger.LogDebug(c, "渠道请求开始: retry=%d/%d, model=%q, relay_mode=%d, token_group=%q, using_group=%q", retryParam.GetRetry(), common.RetryTimes, relayInfo.OriginModelName, relayInfo.RelayMode, relayInfo.TokenGroup, relayInfo.UsingGroup)
channel, channelErr := getChannel(c, relayInfo, retryParam)
if channelErr != nil {
logger.LogDebug(c, "渠道选择失败: retry=%d, err=%s", retryParam.GetRetry(), channelErr.Error())
logger.LogError(c, channelErr.Error())
newAPIError = channelErr
break
}

logger.LogDebug(c, "渠道选择成功: retry=%d, channel_id=%d, channel_type=%d, channel_name=%q", retryParam.GetRetry(), channel.Id, channel.Type, channel.Name)
addUsedChannel(c, channel.Id)
requestBody, bodyErr := common.GetRequestBody(c)
if bodyErr != nil {
logger.LogDebug(c, "读取请求体失败: retry=%d, err=%s", retryParam.GetRetry(), bodyErr.Error())
// Ensure consistent 413 for oversized bodies even when error occurs later (e.g., retry path)
if common.IsRequestBodyTooLargeError(bodyErr) || errors.Is(bodyErr, common.ErrRequestBodyTooLarge) {
newAPIError = types.NewErrorWithStatusCode(bodyErr, types.ErrorCodeReadRequestBodyFailed, http.StatusRequestEntityTooLarge, types.ErrOptionWithSkipRetry())
Expand All @@ -212,14 +216,19 @@ func Relay(c *gin.Context, relayFormat types.RelayFormat) {
}

if newAPIError == nil {
logger.LogDebug(c, "渠道请求成功: retry=%d, channel_id=%d", retryParam.GetRetry(), channel.Id)
return
}

logger.LogDebug(c, "渠道请求失败: retry=%d, channel_id=%d, status=%d, err=%s", retryParam.GetRetry(), channel.Id, newAPIError.StatusCode, newAPIError.Error())
processChannelError(c, *types.NewChannelError(channel.Id, channel.Type, channel.Name, channel.ChannelInfo.IsMultiKey, common.GetContextKeyString(c, constant.ContextKeyChannelKey), channel.GetAutoBan()), newAPIError)

if !shouldRetry(c, newAPIError, common.RetryTimes-retryParam.GetRetry()) {
remainTimes := common.RetryTimes - retryParam.GetRetry()
if !shouldRetry(c, newAPIError, remainTimes) {
logger.LogDebug(c, "渠道重试结束: retry=%d, remaining=%d, channel_id=%d", retryParam.GetRetry(), remainTimes, channel.Id)
break
}
logger.LogDebug(c, "渠道重试继续: retry=%d, remaining=%d, channel_id=%d", retryParam.GetRetry(), remainTimes, channel.Id)
}

useChannel := c.GetStringSlice("use_channel")
Expand Down Expand Up @@ -349,6 +358,12 @@ func processChannelError(c *gin.Context, channelError types.ChannelError, err *t
if c.Request != nil && c.Request.URL != nil {
other["request_path"] = c.Request.URL.Path
}
requestBody, bodyErr := common.GetRequestBody(c)
if bodyErr == nil {
other["request_body"] = string(requestBody)
} else {
other["request_body_error"] = bodyErr.Error()
}
Comment on lines +361 to +366

@coderabbitai coderabbitai Bot Jan 24, 2026

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

⚠️ Potential issue | 🟠 Major

Avoid persisting raw request bodies to error logs.

Storing full request bodies in error logs risks leaking sensitive data and can bloat storage (especially for large or binary payloads). Consider truncation and/or masking, and optionally gating by content type.

✅ Suggested fix (truncate + flag) 
 requestBody, bodyErr := common.GetRequestBody(c)
 if bodyErr == nil {
-    other["request_body"] = string(requestBody)
+    const maxLogBytes = 2048
+    bodyForLog := requestBody
+    if len(bodyForLog) > maxLogBytes {
+        bodyForLog = bodyForLog[:maxLogBytes]
+        other["request_body_truncated"] = true
+    }
+    other["request_body"] = string(bodyForLog)
 } else {
     other["request_body_error"] = bodyErr.Error()
 }
🤖 Prompt for AI Agents 
In `@controller/relay.go` around lines 361 - 366, The current error logging stores
the full raw request body from common.GetRequestBody into the telemetry map
(other["request_body"]) which may leak sensitive data and bloat logs; update the
relay handler to avoid persisting raw bodies by inspecting the request
Content-Type and, for text types, applying masking or truncation (e.g., limit to
N bytes and replace sensitive fields) before assigning to other["request_body"],
and for non-text or large payloads set a safe placeholder (e.g., "<omitted:
binary/large payload>") or set a flag like other["request_body_omitted"]=true;
still record body read errors to other["request_body_error"] as before.

other["error_type"] = err.GetErrorType()
other["error_code"] = err.GetErrorCode()
other["status_code"] = err.StatusCode
Expand Down Expand Up @@ -454,8 +469,10 @@ func RelayTask(c *gin.Context) {
Retry: common.GetPointer(0),
}
for ; shouldRetryTaskRelay(c, channelId, taskErr, retryTimes) && retryParam.GetRetry() < retryTimes; retryParam.IncreaseRetry() {
logger.LogDebug(c, "任务渠道重试开始: retry=%d/%d, current_channel=%d, model=%q, status=%d", retryParam.GetRetry(), retryTimes, channelId, relayInfo.OriginModelName, taskErr.StatusCode)
channel, newAPIError := getChannel(c, relayInfo, retryParam)
if newAPIError != nil {
logger.LogDebug(c, "任务渠道选择失败: retry=%d, err=%s", retryParam.GetRetry(), newAPIError.Error())
logger.LogError(c, fmt.Sprintf("CacheGetRandomSatisfiedChannel failed: %s", newAPIError.Error()))
taskErr = service.TaskErrorWrapperLocal(newAPIError.Err, "get_channel_failed", http.StatusInternalServerError)
break
Expand All @@ -464,11 +481,13 @@ func RelayTask(c *gin.Context) {
useChannel := c.GetStringSlice("use_channel")
useChannel = append(useChannel, fmt.Sprintf("%d", channelId))
c.Set("use_channel", useChannel)
logger.LogDebug(c, "任务渠道选择成功: retry=%d, channel_id=%d, channel_type=%d, channel_name=%q", retryParam.GetRetry(), channel.Id, channel.Type, channel.Name)
logger.LogInfo(c, fmt.Sprintf("using channel #%d to retry (remain times %d)", channel.Id, retryParam.GetRetry()))
//middleware.SetupContextForSelectedChannel(c, channel, originalModel)

requestBody, err := common.GetRequestBody(c)
if err != nil {
logger.LogDebug(c, "任务读取请求体失败: retry=%d, err=%s", retryParam.GetRetry(), err.Error())
if common.IsRequestBodyTooLargeError(err) || errors.Is(err, common.ErrRequestBodyTooLarge) {
taskErr = service.TaskErrorWrapperLocal(err, "read_request_body_failed", http.StatusRequestEntityTooLarge)
} else {
Expand All @@ -478,6 +497,11 @@ func RelayTask(c *gin.Context) {
}
c.Request.Body = io.NopCloser(bytes.NewBuffer(requestBody))
taskErr = taskRelayHandler(c, relayInfo)
if taskErr == nil {
logger.LogDebug(c, "任务渠道请求成功: retry=%d, channel_id=%d", retryParam.GetRetry(), channelId)
} else {
logger.LogDebug(c, "任务渠道请求失败: retry=%d, channel_id=%d, status=%d, code=%s, message=%s", retryParam.GetRetry(), channelId, taskErr.StatusCode, taskErr.Code, taskErr.Message)
}
}
useChannel := c.GetStringSlice("use_channel")
if len(useChannel) > 1 {
Expand Down
57 changes: 53 additions & 4 deletions relay/channel/api_request.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -38,10 +38,54 @@ func SetupApiRequestHeader(info *common.RelayInfo, c *gin.Context, req *http.Hea
}
}

func maskHeaderOverrideValue(value string, apiKey string) string {
if apiKey == "" || value == "" {
return value
}
return strings.ReplaceAll(value, apiKey, "***")
}

func maskHeaderOverrideForLog(headerOverride map[string]interface{}, apiKey string) map[string]interface{} {
if len(headerOverride) == 0 {
return nil
}
masked := make(map[string]interface{}, len(headerOverride))
for key, value := range headerOverride {
if str, ok := value.(string); ok {
masked[key] = maskHeaderOverrideValue(str, apiKey)
} else {
masked[key] = value
}
}
return masked
}

func maskHeaderOverrideForLogString(headerOverride map[string]string, apiKey string) map[string]string {
if len(headerOverride) == 0 {
return nil
}
masked := make(map[string]string, len(headerOverride))
for key, value := range headerOverride {
masked[key] = maskHeaderOverrideValue(value, apiKey)
}
return masked
}

// processHeaderOverride 处理请求头覆盖，支持变量替换
// 支持的变量：{api_key}
func processHeaderOverride(info *common.RelayInfo) (map[string]string, error) {
func processHeaderOverride(c *gin.Context, info *common.RelayInfo) (map[string]string, error) {
channelId := 0
channelType := 0
if info != nil && info.ChannelMeta != nil {
channelId = info.ChannelId
channelType = info.ChannelType
}
headerOverride := make(map[string]string)
if len(info.HeadersOverride) == 0 {
logger.LogDebug(c, "请求头覆盖配置: channel_id=%d, channel_type=%d, headers=空", channelId, channelType)
} else {
logger.LogDebug(c, "请求头覆盖配置: channel_id=%d, channel_type=%d, headers=%s", channelId, channelType, common2.GetJsonString(maskHeaderOverrideForLog(info.HeadersOverride, info.ApiKey)))
}
for k, v := range info.HeadersOverride {
str, ok := v.(string)
if !ok {
Expand All @@ -55,6 +99,11 @@ func processHeaderOverride(info *common.RelayInfo) (map[string]string, error) {

headerOverride[k] = str
}
if len(headerOverride) == 0 {
logger.LogDebug(c, "请求头覆盖结果: channel_id=%d, channel_type=%d, headers=空", channelId, channelType)
} else {
logger.LogDebug(c, "请求头覆盖结果: channel_id=%d, channel_type=%d, headers=%s", channelId, channelType, common2.GetJsonString(maskHeaderOverrideForLogString(headerOverride, info.ApiKey)))
}
return headerOverride, nil
}

Expand All @@ -71,7 +120,7 @@ func DoApiRequest(a Adaptor, c *gin.Context, info *common.RelayInfo, requestBody
return nil, fmt.Errorf("new request failed: %w", err)
}
headers := req.Header
headerOverride, err := processHeaderOverride(info)
headerOverride, err := processHeaderOverride(c, info)
if err != nil {
return nil, err
}
Expand Down Expand Up @@ -104,7 +153,7 @@ func DoFormRequest(a Adaptor, c *gin.Context, info *common.RelayInfo, requestBod
// set form data
req.Header.Set("Content-Type", c.Request.Header.Get("Content-Type"))
headers := req.Header
headerOverride, err := processHeaderOverride(info)
headerOverride, err := processHeaderOverride(c, info)
if err != nil {
return nil, err
}
Expand All @@ -128,7 +177,7 @@ func DoWssRequest(a Adaptor, c *gin.Context, info *common.RelayInfo, requestBody
return nil, fmt.Errorf("get request url failed: %w", err)
}
targetHeader := http.Header{}
headerOverride, err := processHeaderOverride(info)
headerOverride, err := processHeaderOverride(c, info)
if err != nil {
return nil, err
}
Expand Down
15 changes: 15 additions & 0 deletions relay/helper/model_mapped.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -4,22 +4,29 @@ import (
"encoding/json"
"errors"
"fmt"
"strings"

basecommon "github.com/QuantumNous/new-api/common"
"github.com/QuantumNous/new-api/dto"
"github.com/QuantumNous/new-api/logger"
"github.com/QuantumNous/new-api/relay/common"
"github.com/gin-gonic/gin"
)

func ModelMappedHelper(c *gin.Context, info *common.RelayInfo, request dto.Request) error {
// map model name
modelMapping := c.GetString("model_mapping")
logger.LogDebug(c, "模型映射检查: 原模型=%q, 映射配置=%s", info.OriginModelName, modelMapping)
chain := []string{info.OriginModelName}
if modelMapping != "" && modelMapping != "{}" {
modelMap := make(map[string]string)
err := json.Unmarshal([]byte(modelMapping), &modelMap)
if err != nil {
return fmt.Errorf("unmarshal_model_mapping_failed")
}

logger.LogDebug(c, "模型映射解析: 原模型=%q, 映射表=%s", info.OriginModelName, basecommon.GetJsonString(modelMap))

// 支持链式模型重定向，最终使用链尾的模型
currentModel := info.OriginModelName
visitedModels := map[string]bool{
Expand All @@ -42,6 +49,7 @@ func ModelMappedHelper(c *gin.Context, info *common.RelayInfo, request dto.Reque
}
visitedModels[mappedModel] = true
currentModel = mappedModel
chain = append(chain, currentModel)
info.IsModelMapped = true
} else {
break
Expand All @@ -50,7 +58,14 @@ func ModelMappedHelper(c *gin.Context, info *common.RelayInfo, request dto.Reque
if info.IsModelMapped {
info.UpstreamModelName = currentModel
}
} else {
logger.LogDebug(c, "模型映射跳过: 原模型=%q, 未配置映射表", info.OriginModelName)
}
upstreamModel := info.UpstreamModelName
if upstreamModel == "" {
upstreamModel = info.OriginModelName
}
logger.LogDebug(c, "模型映射结果: 原模型=%q, 映射链路=%s, 上游模型=%q, 已映射=%t", info.OriginModelName, strings.Join(chain, "->"), upstreamModel, info.IsModelMapped)
if request != nil {
request.SetModelName(info.UpstreamModelName)
}
Comment on lines +64 to 71

@coderabbitai coderabbitai Bot Jan 24, 2026

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

⚠️ Potential issue | 🟠 Major

Default upstream model before mutating the request.

upstreamModel is defaulted locally, but request.SetModelName(info.UpstreamModelName) can still receive an empty string when mapping is skipped, causing the request model to be cleared and logs to disagree with runtime behavior. Consider normalizing info.UpstreamModelName before use.

✅ Suggested fix 
-    upstreamModel := info.UpstreamModelName
-    if upstreamModel == "" {
-        upstreamModel = info.OriginModelName
-    }
+    if info.UpstreamModelName == "" {
+        info.UpstreamModelName = info.OriginModelName
+    }
+    upstreamModel := info.UpstreamModelName
     logger.LogDebug(c, "模型映射结果: 原模型=%q, 映射链路=%s, 上游模型=%q, 已映射=%t", info.OriginModelName, strings.Join(chain, "->"), upstreamModel, info.IsModelMapped)
     if request != nil {
         request.SetModelName(info.UpstreamModelName)
     }
📝 Committable suggestion

‼️ IMPORTANT
Carefully review the code before committing. Ensure that it accurately replaces the highlighted code, contains no missing lines, and has no issues with indentation. Thoroughly test & benchmark the code to ensure it meets the requirements.

Suggested change
upstreamModel := info.UpstreamModelName
if upstreamModel == "" {
upstreamModel = info.OriginModelName
}
logger.LogDebug(c, "模型映射结果: 原模型=%q, 映射链路=%s, 上游模型=%q, 已映射=%t", info.OriginModelName, strings.Join(chain, "->"), upstreamModel, info.IsModelMapped)
if request != nil {
request.SetModelName(info.UpstreamModelName)
}
if info.UpstreamModelName == "" {
info.UpstreamModelName = info.OriginModelName
}
upstreamModel := info.UpstreamModelName
logger.LogDebug(c, "模型映射结果: 原模型=%q, 映射链路=%s, 上游模型=%q, 已映射=%t", info.OriginModelName, strings.Join(chain, "->"), upstreamModel, info.IsModelMapped)
if request != nil {
request.SetModelName(info.UpstreamModelName)
}
🤖 Prompt for AI Agents 
In `@relay/helper/model_mapped.go` around lines 64 - 71, The code computes a local
upstreamModel but still calls request.SetModelName(info.UpstreamModelName),
which can pass an empty string and clear the request; change the mutation to use
the normalized upstreamModel (or only call SetModelName when upstreamModel !=
"") so the request and the logger remain consistent—update the block around
upstreamModel, logger.LogDebug, and request.SetModelName to use the
upstreamModel variable (or guard the SetModelName call) instead of
info.UpstreamModelName.

Expand Down