From ebcbe1fe35bd84fcd84dcf294351c75639afdc84 Mon Sep 17 00:00:00 2001 From: locnguyen1986 Date: Fri, 19 Dec 2025 14:57:49 +0700 Subject: [PATCH] fix handling invalid format --- .../domain/prompt/deep_research_module.go | 20 ++- .../inference/inference_provider.go | 19 +++ .../handlers/chathandler/chat_handler.go | 82 +++++++++++ .../httpserver/requests/chat/chat.go | 13 +- .../routes/v1/chat/completion_route.go | 29 ++++ .../chat/chat_completion_client.go | 136 ++++++++++++++++++ 6 files changed, 296 insertions(+), 3 deletions(-) diff --git a/services/llm-api/internal/domain/prompt/deep_research_module.go b/services/llm-api/internal/domain/prompt/deep_research_module.go index af61f399..4a69d4c9 100644 --- a/services/llm-api/internal/domain/prompt/deep_research_module.go +++ b/services/llm-api/internal/domain/prompt/deep_research_module.go @@ -2,6 +2,7 @@ package prompt import ( "context" + "fmt" "strings" "github.com/rs/zerolog/log" @@ -37,30 +38,47 @@ func (m *DeepResearchModule) Name() string { // 2. Module is not disabled func (m *DeepResearchModule) ShouldApply(ctx context.Context, promptCtx *Context, messages []openai.ChatCompletionMessage) bool { if ctx == nil || ctx.Err() != nil { + log.Debug().Msg("[DEBUG] DeepResearchModule.ShouldApply: context is nil or cancelled") return false } if promptCtx == nil || promptCtx.Preferences == nil { + log.Debug().Msg("[DEBUG] DeepResearchModule.ShouldApply: promptCtx or Preferences is nil") return false } // Check if module is disabled if isModuleDisabled(promptCtx.Preferences, m.Name()) { + log.Debug().Msg("[DEBUG] DeepResearchModule.ShouldApply: module is disabled via preferences") return false } // Check if deep_research is enabled in preferences deepResearch, ok := promptCtx.Preferences["deep_research"] if !ok { + log.Debug(). + Interface("preferences", promptCtx.Preferences). + Msg("[DEBUG] DeepResearchModule.ShouldApply: deep_research not found in preferences") return false } + log.Debug(). + Interface("deep_research_value", deepResearch). + Str("deep_research_type", fmt.Sprintf("%T", deepResearch)). + Msg("[DEBUG] DeepResearchModule.ShouldApply: found deep_research in preferences") + // Handle different types switch v := deepResearch.(type) { case bool: + log.Debug().Bool("result", v).Msg("[DEBUG] DeepResearchModule.ShouldApply: returning bool value") return v case string: - return strings.ToLower(v) == "true" + result := strings.ToLower(v) == "true" + log.Debug().Bool("result", result).Msg("[DEBUG] DeepResearchModule.ShouldApply: returning parsed string value") + return result default: + log.Debug(). + Str("type", fmt.Sprintf("%T", deepResearch)). + Msg("[DEBUG] DeepResearchModule.ShouldApply: unsupported type, returning false") return false } } diff --git a/services/llm-api/internal/infrastructure/inference/inference_provider.go b/services/llm-api/internal/infrastructure/inference/inference_provider.go index 5180281a..091856ce 100644 --- a/services/llm-api/internal/infrastructure/inference/inference_provider.go +++ b/services/llm-api/internal/infrastructure/inference/inference_provider.go @@ -5,6 +5,8 @@ import ( "fmt" "strings" + "github.com/rs/zerolog/log" + "jan-server/services/llm-api/internal/config" domainmodel "jan-server/services/llm-api/internal/domain/model" "jan-server/services/llm-api/internal/utils/crypto" @@ -22,12 +24,29 @@ func NewInferenceProvider() *InferenceProvider { } func (ip *InferenceProvider) GetChatCompletionClient(ctx context.Context, provider *domainmodel.Provider) (*chatclient.ChatCompletionClient, error) { + log.Debug(). + Str("provider_id", provider.PublicID). + Str("provider_name", provider.DisplayName). + Str("base_url", provider.BaseURL). + Str("provider_kind", string(provider.Kind)). + Msg("[DEBUG] GetChatCompletionClient: creating client for provider") + client, err := ip.createRestyClient(ctx, provider) if err != nil { + log.Error(). + Err(err). + Str("provider_id", provider.PublicID). + Str("provider_name", provider.DisplayName). + Msg("[DEBUG] GetChatCompletionClient: failed to create resty client") return nil, err } clientName := provider.DisplayName + log.Debug(). + Str("provider_name", clientName). + Str("base_url", provider.BaseURL). + Msg("[DEBUG] GetChatCompletionClient: client created successfully") + return chatclient.NewChatCompletionClient(client, clientName, provider.BaseURL), nil } diff --git a/services/llm-api/internal/interfaces/httpserver/handlers/chathandler/chat_handler.go b/services/llm-api/internal/interfaces/httpserver/handlers/chathandler/chat_handler.go index cbc44188..cae8b5c2 100644 --- a/services/llm-api/internal/interfaces/httpserver/handlers/chathandler/chat_handler.go +++ b/services/llm-api/internal/interfaces/httpserver/handlers/chathandler/chat_handler.go @@ -255,6 +255,24 @@ func (h *ChatHandler) CreateChatCompletion( if request.DeepResearch != nil && *request.DeepResearch { preferences["deep_research"] = true observability.AddSpanAttributes(ctx, attribute.Bool("chat.deep_research", true)) + // Debug logging for deep research + debugLog := logger.GetLogger() + debugLog.Debug(). + Bool("deep_research", true). + Str("conversation_id", conversationID). + Str("model", request.Model). + Msg("[DEBUG] deep_research flag enabled, adding to preferences") + } else { + // Debug logging when deep research is NOT enabled + debugLog := logger.GetLogger() + deepResearchValue := "nil" + if request.DeepResearch != nil { + deepResearchValue = fmt.Sprintf("%v", *request.DeepResearch) + } + debugLog.Debug(). + Str("deep_research_value", deepResearchValue). + Str("conversation_id", conversationID). + Msg("[DEBUG] deep_research flag not enabled") } var profileSettings *usersettings.ProfileSettings @@ -412,20 +430,53 @@ func (h *ChatHandler) CreateChatCompletion( observability.AddSpanEvent(ctx, "calling_llm") + // Debug logging before LLM call + log := logger.GetLogger() + log.Debug(). + Str("model", request.Model). + Str("conversation_id", conversationID). + Bool("stream", request.Stream). + Int("message_count", len(llmRequest.Messages)). + Msg("[DEBUG] calling LLM provider") + llmStartTime := time.Now() if request.Stream { + log.Debug(). + Str("model", request.Model). + Str("conversation_id", conversationID). + Msg("[DEBUG] starting streaming completion") response, err = h.streamCompletion(ctx, reqCtx, chatClient, conv, llmRequest) } else { + log.Debug(). + Str("model", request.Model). + Str("conversation_id", conversationID). + Msg("[DEBUG] starting non-streaming completion") response, err = h.callCompletion(ctx, chatClient, llmRequest) } llmDuration := time.Since(llmStartTime) if err != nil { + // Enhanced error logging for debugging + log.Error(). + Err(err). + Str("model", request.Model). + Str("conversation_id", conversationID). + Bool("stream", request.Stream). + Dur("duration", llmDuration). + Str("error_type", fmt.Sprintf("%T", err)). + Msg("[DEBUG] LLM completion failed - returning fallback response") + observability.AddSpanEvent(ctx, "completion_fallback", attribute.String("error", err.Error()), ) response = h.BuildFallbackResponse(request.Model) err = nil + } else { + log.Debug(). + Str("model", request.Model). + Str("conversation_id", conversationID). + Dur("duration", llmDuration). + Msg("[DEBUG] LLM completion succeeded") } // Add LLM response metrics @@ -518,11 +569,27 @@ func (h *ChatHandler) callCompletion( chatClient *chat.ChatCompletionClient, request chat.CompletionRequest, ) (*openai.ChatCompletionResponse, error) { + log := logger.GetLogger() + log.Debug(). + Str("model", request.Model). + Int("message_count", len(request.Messages)). + Msg("[DEBUG] callCompletion: calling CreateChatCompletion") + chatCompletion, err := chatClient.CreateChatCompletion(ctx, "", request) if err != nil { + log.Error(). + Err(err). + Str("model", request.Model). + Str("error_type", fmt.Sprintf("%T", err)). + Msg("[DEBUG] callCompletion: CreateChatCompletion failed") return nil, platformerrors.AsError(ctx, platformerrors.LayerHandler, err, "chat completion failed") } + log.Debug(). + Str("model", request.Model). + Int("total_tokens", chatCompletion.Usage.TotalTokens). + Msg("[DEBUG] callCompletion: completed successfully") + return chatCompletion, nil } @@ -567,11 +634,26 @@ func (h *ChatHandler) streamCompletion( } // Stream completion response to context with callback + log := logger.GetLogger() + log.Debug(). + Str("model", request.Model). + Int("message_count", len(request.Messages)). + Msg("[DEBUG] streamCompletion: calling StreamChatCompletionToContextWithCallback") + resp, err := chatClient.StreamChatCompletionToContextWithCallback(reqCtx, "", request, beforeDoneCallback) if err != nil { + log.Error(). + Err(err). + Str("model", request.Model). + Str("error_type", fmt.Sprintf("%T", err)). + Msg("[DEBUG] streamCompletion: streaming failed") return nil, platformerrors.AsError(ctx, platformerrors.LayerHandler, err, "streaming completion failed") } + log.Debug(). + Str("model", request.Model). + Msg("[DEBUG] streamCompletion: completed successfully") + return resp, nil } diff --git a/services/llm-api/internal/interfaces/httpserver/requests/chat/chat.go b/services/llm-api/internal/interfaces/httpserver/requests/chat/chat.go index dd1ee130..9494b702 100644 --- a/services/llm-api/internal/interfaces/httpserver/requests/chat/chat.go +++ b/services/llm-api/internal/interfaces/httpserver/requests/chat/chat.go @@ -62,9 +62,12 @@ func (p *FlexibleContentPart) ToOpenAIChatMessagePart() openai.ChatMessagePart { Text: p.Text, } } + // Return empty part - will be filtered out by caller + // Note: We can't return nil, so we return an empty image part which will be filtered + // because empty text parts with omitempty cause {"type": "text"} without text field + // which fails validation on some LLM providers return openai.ChatMessagePart{ - Type: openai.ChatMessagePartTypeText, - Text: "", + Type: openai.ChatMessagePartTypeImageURL, // Will be filtered out by caller } } } @@ -85,6 +88,12 @@ func parseFlexibleContentParts(jsonContent string) ([]openai.ChatMessagePart, er log.Warn().Str("original_type", fp.Type).Msg("Skipping empty image part with no URL/data") continue } + // Filter out empty text parts (empty Text field would cause validation errors + // because go-openai uses omitempty, resulting in {"type": "text"} without text field) + if part.Type == openai.ChatMessagePartTypeText && part.Text == "" { + log.Warn().Str("original_type", fp.Type).Msg("Skipping empty text part with no content") + continue + } result = append(result, part) } diff --git a/services/llm-api/internal/interfaces/httpserver/routes/v1/chat/completion_route.go b/services/llm-api/internal/interfaces/httpserver/routes/v1/chat/completion_route.go index 054b17c2..46a0efde 100644 --- a/services/llm-api/internal/interfaces/httpserver/routes/v1/chat/completion_route.go +++ b/services/llm-api/internal/interfaces/httpserver/routes/v1/chat/completion_route.go @@ -1,6 +1,7 @@ package chat import ( + "fmt" "net/http" "github.com/gin-gonic/gin" @@ -103,15 +104,43 @@ func (chatCompletionRoute *ChatCompletionRoute) PostCompletion(reqCtx *gin.Conte Msg("chat completion request received") // Delegate to chat handler + log.Debug(). + Str("route", "/v1/chat/completions"). + Str("model", request.Model). + Str("conversation_id", conversationID). + Bool("stream", request.Stream). + Msg("[DEBUG] delegating to chat handler") + result, err := chatCompletionRoute.chatHandler.CreateChatCompletion(reqCtx.Request.Context(), reqCtx, user.ID, request) if err != nil { + // Log the full error for debugging + log.Error(). + Err(err). + Str("route", "/v1/chat/completions"). + Str("model", request.Model). + Str("conversation_id", conversationID). + Bool("stream", request.Stream). + Str("error_type", fmt.Sprintf("%T", err)). + Msg("[DEBUG] chat completion failed with error") + // Check if it's a validation error (user input too large) if platformerrors.IsValidationError(err) { + log.Debug(). + Err(err). + Str("route", "/v1/chat/completions"). + Msg("[DEBUG] returning validation error response") responses.HandleError(reqCtx, err, err.Error()) return } // For other errors, return fallback response + log.Warn(). + Err(err). + Str("route", "/v1/chat/completions"). + Str("model", request.Model). + Str("conversation_id", conversationID). + Msg("[DEBUG] returning fallback response due to error") + fallback := chatCompletionRoute.chatHandler.BuildFallbackResponse(request.Model) chatResponse := chatresponses.NewChatCompletionResponse(fallback, "", nil, false) reqCtx.JSON(http.StatusOK, chatResponse) diff --git a/services/llm-api/internal/utils/httpclients/chat/chat_completion_client.go b/services/llm-api/internal/utils/httpclients/chat/chat_completion_client.go index 1fa86308..1d69ae8c 100644 --- a/services/llm-api/internal/utils/httpclients/chat/chat_completion_client.go +++ b/services/llm-api/internal/utils/httpclients/chat/chat_completion_client.go @@ -13,6 +13,7 @@ import ( "jan-server/services/llm-api/internal/utils/platformerrors" "github.com/gin-gonic/gin" + "github.com/rs/zerolog/log" "github.com/sashabaranov/go-openai" "go.opentelemetry.io/otel" "go.opentelemetry.io/otel/attribute" @@ -110,6 +111,9 @@ func NewChatCompletionClient(client *resty.Client, name, baseURL string) *ChatCo } func (c *ChatCompletionClient) CreateChatCompletion(ctx context.Context, apiKey string, request CompletionRequest) (*openai.ChatCompletionResponse, error) { + // Sanitize messages to remove invalid parts that cause provider validation errors + request.Messages = SanitizeMessages(request.Messages) + // Start OpenTelemetry span for tracking ctx, span := otel.Tracer("chat-completion-client").Start(ctx, "CreateChatCompletion", trace.WithSpanKind(trace.SpanKindClient), @@ -141,6 +145,13 @@ func (c *ChatCompletionClient) CreateChatCompletion(ctx context.Context, apiKey start := time.Now() + log.Debug(). + Str("provider", c.name). + Str("base_url", c.baseURL). + Str("model", request.Model). + Int("message_count", len(request.Messages)). + Msg("[DEBUG] CreateChatCompletion: sending request to provider") + var respBody openai.ChatCompletionResponse resp, err := c.prepareRequest(ctx, apiKey). SetBody(request). @@ -150,12 +161,40 @@ func (c *ChatCompletionClient) CreateChatCompletion(ctx context.Context, apiKey duration := time.Since(start) if err != nil { + log.Error(). + Err(err). + Str("provider", c.name). + Str("base_url", c.baseURL). + Str("model", request.Model). + Dur("duration", duration). + Str("error_type", fmt.Sprintf("%T", err)). + Msg("[DEBUG] CreateChatCompletion: HTTP request failed") span.RecordError(err) span.SetStatus(codes.Error, err.Error()) span.SetAttributes(attribute.Int64("llm.duration_ms", duration.Milliseconds())) return nil, err } if resp.IsError() { + // Try to get response body for more error details + respBodyStr := "" + if resp.RawResponse != nil && resp.RawResponse.Body != nil { + bodyBytes, _ := io.ReadAll(resp.RawResponse.Body) + respBodyStr = string(bodyBytes) + } + // Also try String() method + if respBodyStr == "" { + respBodyStr = resp.String() + } + + log.Error(). + Str("provider", c.name). + Str("base_url", c.baseURL). + Str("model", request.Model). + Int("status_code", resp.StatusCode()). + Str("response_body", respBodyStr). + Dur("duration", duration). + Msg("[DEBUG] CreateChatCompletion: provider returned error response") + reqErr := c.errorFromResponse(ctx, resp, "request failed") span.RecordError(reqErr) span.SetStatus(codes.Error, reqErr.Error()) @@ -166,6 +205,14 @@ func (c *ChatCompletionClient) CreateChatCompletion(ctx context.Context, apiKey return nil, reqErr } + log.Debug(). + Str("provider", c.name). + Str("model", request.Model). + Int("status_code", resp.StatusCode()). + Int("total_tokens", respBody.Usage.TotalTokens). + Dur("duration", duration). + Msg("[DEBUG] CreateChatCompletion: request successful") + // Record token usage and timing in span span.SetAttributes( attribute.Int("llm.usage.prompt_tokens", respBody.Usage.PromptTokens), @@ -486,6 +533,16 @@ func (c *ChatCompletionClient) errorFromResponse(ctx context.Context, resp *rest } func (c *ChatCompletionClient) doStreamingRequest(ctx context.Context, apiKey string, request CompletionRequest, opts ...StreamOption) (*resty.Response, error) { + // Sanitize messages to remove invalid parts that cause provider validation errors + request.Messages = SanitizeMessages(request.Messages) + + log.Debug(). + Str("provider", c.name). + Str("base_url", c.baseURL). + Str("model", request.Model). + Int("message_count", len(request.Messages)). + Msg("[DEBUG] doStreamingRequest: starting streaming request") + req := c.prepareRequest(ctx, apiKey). SetBody(request). SetDoNotParseResponse(true) @@ -503,16 +560,50 @@ func (c *ChatCompletionClient) doStreamingRequest(ctx context.Context, apiKey st resp, err := req.Post(c.endpoint("/chat/completions")) if err != nil { + log.Error(). + Err(err). + Str("provider", c.name). + Str("base_url", c.baseURL). + Str("model", request.Model). + Str("error_type", fmt.Sprintf("%T", err)). + Msg("[DEBUG] doStreamingRequest: HTTP request failed") return nil, err } if resp.IsError() { + // Try to read response body for error details + respBodyStr := "" + if resp.RawResponse != nil && resp.RawResponse.Body != nil { + bodyBytes, _ := io.ReadAll(resp.RawResponse.Body) + respBodyStr = string(bodyBytes) + } + if respBodyStr == "" { + respBodyStr = resp.String() + } + + log.Error(). + Str("provider", c.name). + Str("base_url", c.baseURL). + Str("model", request.Model). + Int("status_code", resp.StatusCode()). + Str("response_body", respBodyStr). + Msg("[DEBUG] doStreamingRequest: provider returned error response") return nil, c.errorFromResponse(ctx, resp, "streaming request failed") } if resp.RawResponse == nil || resp.RawResponse.Body == nil { + log.Error(). + Str("provider", c.name). + Str("model", request.Model). + Msg("[DEBUG] doStreamingRequest: empty response body") return nil, platformerrors.NewError(ctx, platformerrors.LayerDomain, platformerrors.ErrorTypeExternal, "streaming request failed: empty response body", nil, "1b3ab461-dbf9-4034-8abb-dfc6ea8486c5") } + log.Debug(). + Str("provider", c.name). + Str("model", request.Model). + Int("status_code", resp.StatusCode()). + Msg("[DEBUG] doStreamingRequest: streaming started successfully") + return resp, nil } @@ -787,3 +878,48 @@ func min(a, b int) int { } return b } + +// SanitizeMessages removes invalid message parts that would cause validation errors +// with LLM providers. This includes: +// - Empty text parts (type: "text" without text field due to omitempty) +// - Empty image parts (type: "image_url" without URL) +func SanitizeMessages(messages []openai.ChatCompletionMessage) []openai.ChatCompletionMessage { + result := make([]openai.ChatCompletionMessage, 0, len(messages)) + + for _, msg := range messages { + sanitizedMsg := msg + + // Sanitize MultiContent array if present + if len(msg.MultiContent) > 0 { + sanitizedParts := make([]openai.ChatMessagePart, 0, len(msg.MultiContent)) + for _, part := range msg.MultiContent { + // Skip empty text parts (would serialize as {"type": "text"} without text field) + if part.Type == openai.ChatMessagePartTypeText && part.Text == "" { + log.Debug(). + Str("role", string(msg.Role)). + Msg("[DEBUG] SanitizeMessages: skipping empty text part") + continue + } + // Skip empty image parts (no URL) + if part.Type == openai.ChatMessagePartTypeImageURL && (part.ImageURL == nil || part.ImageURL.URL == "") { + log.Debug(). + Str("role", string(msg.Role)). + Msg("[DEBUG] SanitizeMessages: skipping empty image part") + continue + } + sanitizedParts = append(sanitizedParts, part) + } + + // If all parts were filtered out, convert to a simple text message + if len(sanitizedParts) == 0 && msg.Content != "" { + sanitizedMsg.MultiContent = nil + } else { + sanitizedMsg.MultiContent = sanitizedParts + } + } + + result = append(result, sanitizedMsg) + } + + return result +}