Skip to content

Commit aabdbf2

Browse files
committed
feat: 添加调试日志记录功能,增强工具调用和响应的匹配逻辑,更新相关文档和测试用例
1 parent dd919cb commit aabdbf2

6 files changed

Lines changed: 552 additions & 13 deletions

File tree

.gitignore

Lines changed: 8 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -38,3 +38,11 @@ tmp/litellm-gemini-study/translation-mechanisms.md
3838
tmp/google-ai-streamGenerateContent-docs.md
3939
tmp/review_v2.md
4040
gemini-plan.md
41+
debug-logs/debug-gemini-2025-09-24T16-05-00-806Z-750wa1-compressed.log
42+
debug-logs/debug-gemini-2025-09-24T16-05-00-806Z-750wa1.log
43+
debug-logs/debug-gemini-2025-09-24T16-05-16-625Z-w596rn-compressed.log
44+
debug-logs/debug-gemini-2025-09-24T16-05-16-625Z-w596rn.log
45+
debug-logs/debug-gemini-2025-09-24T16-05-20-120Z-m6ebiq-compressed.log
46+
debug-logs/debug-gemini-2025-09-24T16-05-20-120Z-m6ebiq.log
47+
debug-logs/debug-gemini-2025-09-24T16-05-24-000Z-nuggbx-compressed.log
48+
debug-logs/debug-gemini-2025-09-24T16-05-24-000Z-nuggbx.log

CLAUDE.md

Lines changed: 15 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -75,6 +75,10 @@ Gemini integration
7575
- 逐块处理:`processAndWriteChunk/handleStreamingResponse`: `handler.ts:194-238, 241-282`
7676
- 工具调用的增量参数:不完整 JSON `arguments` 跳过当次块,等待后续完整块
7777
- `processToolCalls`: `translation.ts:537-577`
78+
- **工具响应处理**:确保 tool call 与 response 1:1 映射
79+
- `ensureToolCallResponseMatch`: `translation.ts` 对 tool responses 按 `tool_call_id` 去重
80+
- 问题:OpenAI 可能返回重复的 tool responses,导致 Gemini 1:1 映射要求失败
81+
- 解决:简单去重逻辑,保留每个 `tool_call_id` 的第一个响应
7882
- 终止原因映射
7983
- OpenAI → Gemini: `mapOpenAIFinishReasonToGemini` in `src/routes/generate-content/utils.ts:3-23`
8084
- Gemini → OpenAI: `mapGeminiFinishReasonToOpenAI` in `utils.ts:26-50`
@@ -105,11 +109,22 @@ Error handling
105109

106110
- 常见 Gemini 问题
107111
- `invalid_tool_call_format`:工具声明缺失或参数为空;确保 `tools``tool_choice` 按需出现,并有非空 `parameters`
112+
- **Tool call/response 1:1 映射错误**:"Please ensure that the number of function response parts is equal to the number of function call parts" - 通常由重复的 `tool_call_id` 响应引起,需要去重而不是拆分
108113
- 嵌套 `functionResponse`:Gemini CLI 会发送嵌套数组,需用 `processFunctionResponseArray` 处理
109114
- `tool_call_id` 关联:用函数名暂存并在用户回应时取回,保持一致性
110115
- 取消的 tool call:清理掉未完成的 `assistant+tool_calls` 信息
111116
- `HTTPError`:多半是 OpenAI 侧 payload 校验失败
112117

118+
- Debug 日志分析方法
119+
- 使用 `DebugLogger` 自动生成 debug-logs/ 文件夹中的请求日志
120+
- 压缩大日志文件便于分析:用 `compress-logs.js` 脚本删除重复内容
121+
- 分析时用 PowerShell/脚本统计 function calls vs responses 数量:检查 `functionCall``functionResponse` 计数,以及翻译后的 `tool_calls` 与 tool responses 计数
122+
- **调试方法论**
123+
- **数据先行**:从实际 debug logs 出发,不要基于理论假设
124+
- **验证而非猜测**:每次修改后必须通过新 debug logs 验证效果
125+
- **简单解决方案优先**:去重 > 拆分,避免过度复杂化
126+
- **承认错误**:当证据显示修复制造了新问题时,快速重新思考
127+
113128
- 快速自检
114129
- `bun run lint && bun run typecheck && bun run build`
115130
- `curl http://localhost:4142/v1/models` 查看真实支持的模型集合

src/lib/debug-logger.ts

Lines changed: 80 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,80 @@
1+
import { existsSync, mkdirSync } from "node:fs"
2+
import { writeFile } from "node:fs/promises"
3+
import { join } from "node:path"
4+
5+
import type { GeminiRequest } from "~/routes/generate-content/types"
6+
import type { ChatCompletionsPayload } from "~/services/copilot/create-chat-completions"
7+
8+
interface DebugLogData {
9+
timestamp: string
10+
requestId: string
11+
originalGeminiPayload: GeminiRequest
12+
translatedOpenAIPayload: ChatCompletionsPayload | null
13+
error?: string
14+
processingTime?: number
15+
}
16+
17+
export class DebugLogger {
18+
private static instance: DebugLogger | undefined
19+
private logDir: string
20+
21+
private constructor() {
22+
this.logDir = process.env.DEBUG_LOG_DIR || join(process.cwd(), "debug-logs")
23+
this.ensureLogDir()
24+
}
25+
26+
static getInstance(): DebugLogger {
27+
if (!DebugLogger.instance) {
28+
DebugLogger.instance = new DebugLogger()
29+
}
30+
return DebugLogger.instance
31+
}
32+
33+
private ensureLogDir(): void {
34+
if (!existsSync(this.logDir)) {
35+
mkdirSync(this.logDir, { recursive: true })
36+
}
37+
}
38+
39+
private generateLogFileName(requestId: string): string {
40+
const timestamp = new Date().toISOString().replaceAll(/[:.]/g, "-")
41+
return join(this.logDir, `debug-gemini-${timestamp}-${requestId}.log`)
42+
}
43+
44+
async logRequest(data: {
45+
requestId: string
46+
geminiPayload: GeminiRequest
47+
openAIPayload?: ChatCompletionsPayload | null
48+
error?: string
49+
processingTime?: number
50+
}): Promise<void> {
51+
const logData: DebugLogData = {
52+
timestamp: new Date().toISOString(),
53+
requestId: data.requestId,
54+
originalGeminiPayload: data.geminiPayload,
55+
translatedOpenAIPayload: data.openAIPayload ?? null,
56+
error: data.error,
57+
processingTime: data.processingTime,
58+
}
59+
60+
const logPath = this.generateLogFileName(data.requestId)
61+
62+
try {
63+
await writeFile(logPath, JSON.stringify(logData, null, 2), "utf8")
64+
console.log(`[DEBUG] Logged request data to: ${logPath}`)
65+
} catch (writeError) {
66+
console.error(`[DEBUG] Failed to write log file ${logPath}:`, writeError)
67+
}
68+
}
69+
70+
// For backward compatibility during development
71+
static async logGeminiRequest(
72+
geminiPayload: GeminiRequest,
73+
openAIPayload?: ChatCompletionsPayload,
74+
error?: string,
75+
): Promise<void> {
76+
const logger = DebugLogger.getInstance()
77+
const requestId = Math.random().toString(36).slice(2, 8)
78+
await logger.logRequest({ requestId, geminiPayload, openAIPayload, error })
79+
}
80+
}

src/routes/generate-content/handler.ts

Lines changed: 9 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -4,6 +4,7 @@ import type { SSEStreamingApi } from "hono/streaming"
44
import { streamSSE } from "hono/streaming"
55

66
import { awaitApproval } from "~/lib/approval"
7+
import { DebugLogger } from "~/lib/debug-logger"
78
import { checkRateLimit } from "~/lib/rate-limit"
89
import { state } from "~/lib/state"
910
import { getTokenCount } from "~/lib/tokenizer"
@@ -295,6 +296,14 @@ export async function handleGeminiStreamGeneration(c: Context) {
295296

296297
const openAIPayload = translateGeminiToOpenAIStream(geminiPayload, model)
297298

299+
// Log request for debugging (async, non-blocking) - only if debug logging is enabled
300+
if (process.env.DEBUG_GEMINI_REQUESTS === "true") {
301+
DebugLogger.logGeminiRequest(geminiPayload, openAIPayload).catch(
302+
(error: unknown) => {
303+
console.error("[DEBUG] Failed to log request:", error)
304+
},
305+
)
306+
}
298307
if (state.manualApprove) {
299308
await awaitApproval()
300309
}

src/routes/generate-content/translation.ts

Lines changed: 83 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -111,14 +111,24 @@ function processFunctionResponseArray(
111111
for (const responseItem of responseArray) {
112112
if ("functionResponse" in responseItem) {
113113
const functionName = responseItem.functionResponse.name
114-
const toolCallId = pendingToolCalls.get(functionName)
115-
if (toolCallId) {
114+
// Find tool call ID by searching through the map
115+
let matchedToolCallId: string | undefined
116+
for (const [
117+
toolCallId,
118+
mappedFunctionName,
119+
] of pendingToolCalls.entries()) {
120+
if (mappedFunctionName === functionName) {
121+
matchedToolCallId = toolCallId
122+
break
123+
}
124+
}
125+
if (matchedToolCallId) {
116126
messages.push({
117127
role: "tool",
118-
tool_call_id: toolCallId,
128+
tool_call_id: matchedToolCallId,
119129
content: JSON.stringify(responseItem.functionResponse.response),
120130
})
121-
pendingToolCalls.delete(functionName)
131+
pendingToolCalls.delete(matchedToolCallId)
122132
}
123133
}
124134
}
@@ -150,14 +160,21 @@ function processFunctionResponses(
150160
): void {
151161
for (const funcResponse of functionResponses) {
152162
const functionName = funcResponse.functionResponse.name
153-
const toolCallId = pendingToolCalls.get(functionName)
154-
if (toolCallId) {
163+
// Find tool call ID by searching through the map
164+
let matchedToolCallId: string | undefined
165+
for (const [toolCallId, mappedFunctionName] of pendingToolCalls.entries()) {
166+
if (mappedFunctionName === functionName) {
167+
matchedToolCallId = toolCallId
168+
break
169+
}
170+
}
171+
if (matchedToolCallId) {
155172
messages.push({
156173
role: "tool",
157-
tool_call_id: toolCallId,
174+
tool_call_id: matchedToolCallId,
158175
content: JSON.stringify(funcResponse.functionResponse.response),
159176
})
160-
pendingToolCalls.delete(functionName)
177+
pendingToolCalls.delete(matchedToolCallId)
161178
}
162179
}
163180
}
@@ -175,7 +192,8 @@ function processFunctionCalls(options: {
175192
const toolCalls = functionCalls.map((call) => {
176193
const toolCallId = generateToolCallId(call.functionCall.name)
177194
// Remember this tool call for later matching with responses
178-
pendingToolCalls.set(call.functionCall.name, toolCallId)
195+
// Use tool_call_id as key to avoid duplicate function name overwrites
196+
pendingToolCalls.set(toolCallId, call.functionCall.name)
179197

180198
return {
181199
id: toolCallId,
@@ -207,6 +225,8 @@ function mergeConsecutiveSameRoleMessages(
207225
&& lastMessage.role === message.role
208226
&& !lastMessage.tool_calls
209227
&& !message.tool_calls
228+
&& !(lastMessage as { tool_call_id?: string }).tool_call_id // Don't merge tool responses
229+
&& !(message as { tool_call_id?: string }).tool_call_id // Don't merge tool responses
210230
) {
211231
// Merge with previous message of same role
212232
if (
@@ -247,7 +267,7 @@ function removeIncompleteAssistantMessages(messages: Array<Message>): void {
247267
}
248268
}
249269

250-
function translateGeminiContentsToOpenAI(
270+
export function translateGeminiContentsToOpenAI(
251271
contents: Array<
252272
| GeminiContent
253273
| Array<{
@@ -257,7 +277,7 @@ function translateGeminiContentsToOpenAI(
257277
systemInstruction?: GeminiContent,
258278
): Array<Message> {
259279
const messages: Array<Message> = []
260-
const pendingToolCalls = new Map<string, string>() // function name -> tool_call_id
280+
const pendingToolCalls = new Map<string, string>() // tool_call_id -> function_name
261281

262282
// Add system instruction first if present
263283
if (systemInstruction) {
@@ -309,8 +329,11 @@ function translateGeminiContentsToOpenAI(
309329
// Post-process: Remove incomplete assistant messages from cancelled tool calls
310330
removeIncompleteAssistantMessages(messages)
311331

332+
// Post-process: Deduplicate tool responses (remove duplicate tool_call_ids)
333+
const matchedMessages = ensureToolCallResponseMatch(messages)
334+
312335
// Post-process: Merge consecutive messages with same role (based on LiteLLM research)
313-
return mergeConsecutiveSameRoleMessages(messages)
336+
return mergeConsecutiveSameRoleMessages(matchedMessages)
314337
}
315338

316339
function synthesizeToolsFromContents(
@@ -466,6 +489,32 @@ function translateGeminiToolConfigToOpenAI(
466489

467490
// Response translation: OpenAI -> Gemini
468491

492+
// Helper function to deduplicate tool responses - remove duplicate tool_call_ids
493+
// The problem was our logic was CREATING duplicates instead of preventing them
494+
495+
function ensureToolCallResponseMatch(messages: Array<Message>): Array<Message> {
496+
const result: Array<Message> = []
497+
const seenToolCallIds = new Set<string>() // Track processed tool_call_ids to avoid duplicates
498+
499+
for (const message of messages) {
500+
if (message.role === "tool" && message.tool_call_id) {
501+
const toolCallId = message.tool_call_id
502+
503+
// Only keep the FIRST response for each tool_call_id (deduplicate)
504+
if (!seenToolCallIds.has(toolCallId)) {
505+
seenToolCallIds.add(toolCallId)
506+
result.push(message)
507+
}
508+
// Skip any duplicate responses for the same tool_call_id
509+
} else {
510+
// Keep all non-tool messages as-is
511+
result.push(message)
512+
}
513+
}
514+
515+
return result
516+
}
517+
469518
export function translateOpenAIToGemini(
470519
response: ChatCompletionResponse,
471520
): GeminiResponse {
@@ -561,7 +610,12 @@ function processToolCalls(
561610
const parts: Array<GeminiPart> = []
562611

563612
for (const toolCall of toolCalls) {
564-
if (!toolCall.function?.name) {
613+
// Enhanced validation: check for empty/whitespace-only names
614+
if (
615+
!toolCall.function?.name
616+
|| typeof toolCall.function.name !== "string"
617+
|| toolCall.function.name.trim() === ""
618+
) {
565619
continue
566620
}
567621

@@ -723,6 +777,22 @@ export function translateOpenAIChunkToGemini(chunk: ChatCompletionChunk): {
723777
return null
724778
}
725779

780+
// Additional validation - if we only have function call parts with empty names,
781+
// skip this chunk entirely to prevent invalid tool call responses
782+
const hasOnlyEmptyToolCalls =
783+
parts.length > 0
784+
&& parts.every((part) => {
785+
if ("functionCall" in part) {
786+
return !part.functionCall.name || part.functionCall.name.trim() === ""
787+
}
788+
return false
789+
})
790+
&& parts.some((part) => "functionCall" in part)
791+
792+
if (hasOnlyEmptyToolCalls && !choice.finish_reason) {
793+
return null
794+
}
795+
726796
const shouldInclude = shouldIncludeFinishReason(choice)
727797
const mappedFinishReason =
728798
shouldInclude ?

0 commit comments

Comments
 (0)