diff --git a/controller/relay.go b/controller/relay.go index 4fba947f74cc..9818911126a0 100644 --- a/controller/relay.go +++ b/controller/relay.go @@ -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()) @@ -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") @@ -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() + } other["error_type"] = err.GetErrorType() other["error_code"] = err.GetErrorCode() other["status_code"] = err.StatusCode @@ -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 @@ -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 { @@ -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 { diff --git a/relay/channel/api_request.go b/relay/channel/api_request.go index 1ff1e2392c5b..9480d5e4a6b2 100644 --- a/relay/channel/api_request.go +++ b/relay/channel/api_request.go @@ -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 { @@ -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 } @@ -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 } @@ -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 } @@ -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 } diff --git a/relay/helper/model_mapped.go b/relay/helper/model_mapped.go index 821158faedf4..e3d51001a4d1 100644 --- a/relay/helper/model_mapped.go +++ b/relay/helper/model_mapped.go @@ -4,8 +4,11 @@ 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" ) @@ -13,6 +16,8 @@ import ( 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) @@ -20,6 +25,8 @@ func ModelMappedHelper(c *gin.Context, info *common.RelayInfo, request dto.Reque return fmt.Errorf("unmarshal_model_mapping_failed") } + logger.LogDebug(c, "模型映射解析: 原模型=%q, 映射表=%s", info.OriginModelName, basecommon.GetJsonString(modelMap)) + // 支持链式模型重定向,最终使用链尾的模型 currentModel := info.OriginModelName visitedModels := map[string]bool{ @@ -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 @@ -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) }