bug(core): Add workaround + logging for orphaned function calls.

This commit is contained in:
Your Name
2026-01-21 23:03:12 +00:00
parent 1033550f78
commit 1dbd3e8ce1
5 changed files with 451 additions and 105 deletions

View File

@@ -12,7 +12,6 @@ import {
GeminiChat,
InvalidStreamError,
StreamEventType,
SYNTHETIC_THOUGHT_SIGNATURE,
type StreamEvent,
} from './geminiChat.js';
import type { Config } from '../config/config.js';
@@ -1951,96 +1950,6 @@ describe('GeminiChat', () => {
});
});
describe('ensureActiveLoopHasThoughtSignatures', () => {
it('should add thoughtSignature to the first functionCall in each model turn of the active loop', () => {
const chat = new GeminiChat(mockConfig, '', [], []);
const history: Content[] = [
{ role: 'user', parts: [{ text: 'Old message' }] },
{
role: 'model',
parts: [{ functionCall: { name: 'old_tool', args: {} } }],
},
{ role: 'user', parts: [{ text: 'Find a restaurant' }] }, // active loop starts here
{
role: 'model',
parts: [
{ functionCall: { name: 'find_restaurant', args: {} } }, // This one gets a signature
{ functionCall: { name: 'find_restaurant_2', args: {} } }, // This one does NOT
],
},
{
role: 'user',
parts: [
{ functionResponse: { name: 'find_restaurant', response: {} } },
],
},
{
role: 'model',
parts: [
{
functionCall: { name: 'tool_with_sig', args: {} },
thoughtSignature: 'existing-sig',
},
{ functionCall: { name: 'another_tool', args: {} } }, // This one does NOT get a signature
],
},
];
const newContents = chat.ensureActiveLoopHasThoughtSignatures(history);
// Outside active loop - unchanged
expect(newContents[1]?.parts?.[0]).not.toHaveProperty('thoughtSignature');
// Inside active loop, first model turn
// First function call gets a signature
expect(newContents[3]?.parts?.[0]?.thoughtSignature).toBe(
SYNTHETIC_THOUGHT_SIGNATURE,
);
// Second function call does NOT
expect(newContents[3]?.parts?.[1]).not.toHaveProperty('thoughtSignature');
// User functionResponse part - unchanged (this is not a model turn)
expect(newContents[4]?.parts?.[0]).not.toHaveProperty('thoughtSignature');
// Inside active loop, second model turn
// First function call already has a signature, so nothing changes
expect(newContents[5]?.parts?.[0]?.thoughtSignature).toBe('existing-sig');
// Second function call does NOT get a signature
expect(newContents[5]?.parts?.[1]).not.toHaveProperty('thoughtSignature');
});
it('should not modify contents if there is no user text message', () => {
const chat = new GeminiChat(mockConfig, '', [], []);
const history: Content[] = [
{
role: 'user',
parts: [{ functionResponse: { name: 'tool1', response: {} } }],
},
{
role: 'model',
parts: [{ functionCall: { name: 'tool2', args: {} } }],
},
];
const newContents = chat.ensureActiveLoopHasThoughtSignatures(history);
expect(newContents).toEqual(history);
expect(newContents[1]?.parts?.[0]).not.toHaveProperty('thoughtSignature');
});
it('should handle an empty history', () => {
const chat = new GeminiChat(mockConfig, '', []);
const history: Content[] = [];
const newContents = chat.ensureActiveLoopHasThoughtSignatures(history);
expect(newContents).toEqual([]);
});
it('should handle history with only a user message', () => {
const chat = new GeminiChat(mockConfig, '', []);
const history: Content[] = [{ role: 'user', parts: [{ text: 'Hello' }] }];
const newContents = chat.ensureActiveLoopHasThoughtSignatures(history);
expect(newContents).toEqual(history);
});
});
describe('Availability Service Integration', () => {
let mockAvailabilityService: ModelAvailabilityService;

View File

@@ -32,6 +32,7 @@ import type { CompletedToolCall } from './coreToolScheduler.js';
import {
logContentRetry,
logContentRetryFailure,
logOrphanedFunctionCallFixed,
} from '../telemetry/loggers.js';
import {
ChatRecordingService,
@@ -40,6 +41,7 @@ import {
import {
ContentRetryEvent,
ContentRetryFailureEvent,
OrphanedFunctionCallFixedEvent,
} from '../telemetry/types.js';
import { handleFallback } from '../fallback/handler.js';
import { isFunctionResponse } from '../utils/messageInspectors.js';
@@ -441,9 +443,6 @@ export class GeminiChat {
prompt_id: string,
abortSignal: AbortSignal,
): Promise<AsyncGenerator<GenerateContentResponse>> {
const contentsForPreviewModel =
this.ensureActiveLoopHasThoughtSignatures(requestContents);
// Track final request parameters for AfterModel hooks
const {
model: availabilityFinalModel,
@@ -451,6 +450,15 @@ export class GeminiChat {
maxAttempts: availabilityMaxAttempts,
} = applyModelSelection(this.config, modelConfigKey);
// Ensure all function calls in the history have responses.
requestContents = this.ensureActiveLoopHasFunctionResponses(
requestContents,
availabilityFinalModel,
);
const contentsForPreviewModel =
this.ensureActiveLoopHasThoughtSignatures(requestContents);
let lastModelToUse = availabilityFinalModel;
let currentGenerateContentConfig: GenerateContentConfig =
newAvailabilityConfig;
@@ -698,20 +706,105 @@ export class GeminiChat {
});
}
private findActiveLoopStartIndex(contents: Content[]): number {
for (let i = contents.length - 1; i >= 0; i--) {
const content = contents[i];
if (content.role === 'user' && content.parts?.some((part) => part.text)) {
return i;
}
}
return -1;
}
// To ensure our requests validate, every function call in the history
// must have a valid function response. If we do not do this, we will get
// back 400 errors from the API.
ensureActiveLoopHasFunctionResponses(
requestContents: Content[],
model: string,
): Content[] {
// Iterate through every message in the history, ensuring that every
// function call in each model message has a corresponding function
// response in the next user message.
const newContents = requestContents.slice(); // Shallow copy the array
for (let i = 0; i < newContents.length; i++) {
const content = newContents[i];
if (content.role === 'model' && content.parts) {
const functionCalls = content.parts.filter((part) => part.functionCall);
if (functionCalls.length > 0) {
const nextIndex = i + 1;
const nextContent =
nextIndex < newContents.length ? newContents[nextIndex] : undefined;
const missingResponses: Part[] = [];
for (const callPart of functionCalls) {
const call = callPart.functionCall!;
const callId = (call as { id: string })['id'];
// Check if the next turn is a user turn and has a response for this call.
const hasResponse =
nextContent?.role === 'user' &&
nextContent.parts?.some((part) => {
if (!part.functionResponse) {
return false;
}
if (callId && part.functionResponse.id) {
return part.functionResponse.id === callId;
}
return part.functionResponse.name === call.name;
});
if (!hasResponse) {
logOrphanedFunctionCallFixed(
this.config,
new OrphanedFunctionCallFixedEvent(
model,
call.name ?? 'unknown',
),
);
missingResponses.push({
functionResponse: {
name: call.name,
id: callId,
response: {
status: 'unknown',
message:
'The status of this function call is unknown. Please validate the state of the world before continuing.',
},
},
});
}
}
if (missingResponses.length > 0) {
if (nextContent?.role === 'user') {
// Add missing responses to the existing user turn.
const updatedNextContent = {
...nextContent,
parts: [...missingResponses, ...(nextContent.parts || [])],
};
newContents[nextIndex] = updatedNextContent;
} else {
// Insert a new user turn with the missing responses.
const newUserContent: Content = {
role: 'user',
parts: missingResponses,
};
newContents.splice(nextIndex, 0, newUserContent);
}
}
}
}
}
return newContents;
}
// To ensure our requests validate, the first function call in every model
// turn within the active loop must have a `thoughtSignature` property.
// If we do not do this, we will get back 400 errors from the API.
ensureActiveLoopHasThoughtSignatures(requestContents: Content[]): Content[] {
// First, find the start of the active loop by finding the last user turn
// with a text message, i.e. that is not a function response.
let activeLoopStartIndex = -1;
for (let i = requestContents.length - 1; i >= 0; i--) {
const content = requestContents[i];
if (content.role === 'user' && content.parts?.some((part) => part.text)) {
activeLoopStartIndex = i;
break;
}
}
const activeLoopStartIndex = this.findActiveLoopStartIndex(requestContents);
if (activeLoopStartIndex === -1) {
return requestContents;

View File

@@ -0,0 +1,298 @@
/**
* @license
* Copyright 2025 Google LLC
* SPDX-License-Identifier: Apache-2.0
*/
import { describe, it, expect, vi, beforeEach } from 'vitest';
import type { Content } from '@google/genai';
import { GeminiChat, SYNTHETIC_THOUGHT_SIGNATURE } from './geminiChat.js';
import type { Config } from '../config/config.js';
import { DEFAULT_THINKING_MODE } from '../config/models.js';
import { createMockMessageBus } from '../test-utils/mock-message-bus.js';
import { createAvailabilityServiceMock } from '../availability/testUtils.js';
vi.mock('node:fs', () => ({
default: {
mkdirSync: vi.fn(),
writeFileSync: vi.fn(),
readFileSync: vi.fn(() => {
const error = new Error('ENOENT');
(error as NodeJS.ErrnoException).code = 'ENOENT';
throw error;
}),
existsSync: vi.fn(() => false),
},
}));
const { mockLogOrphanedFunctionCallFixed } = vi.hoisted(() => ({
mockLogOrphanedFunctionCallFixed: vi.fn(),
}));
vi.mock('../telemetry/loggers.js', async (importOriginal) => {
const actual =
await importOriginal<typeof import('../telemetry/loggers.js')>();
return {
...actual,
logOrphanedFunctionCallFixed: mockLogOrphanedFunctionCallFixed,
};
});
describe('GeminiChat History Repair', () => {
let chat: GeminiChat;
let mockConfig: Config;
beforeEach(() => {
vi.clearAllMocks();
mockConfig = {
getSessionId: () => 'test-session-id',
getTelemetryLogPromptsEnabled: () => true,
getUsageStatisticsEnabled: () => true,
getDebugMode: () => false,
getPreviewFeatures: () => false,
getContentGeneratorConfig: vi.fn().mockImplementation(() => ({
authType: 'oauth-personal',
model: 'gemini-pro',
})),
getModel: vi.fn().mockReturnValue('gemini-pro'),
getProjectRoot: vi.fn().mockReturnValue('/test/project/root'),
storage: {
getProjectTempDir: vi.fn().mockReturnValue('/test/temp'),
},
getToolRegistry: vi.fn().mockReturnValue({
getTool: vi.fn(),
}),
modelConfigService: {
getResolvedConfig: vi.fn().mockImplementation((modelConfigKey) => {
const model = modelConfigKey.model ?? 'gemini-pro';
return {
model,
generateContentConfig: {
temperature: 0,
thinkingConfig: {
thinkingBudget: DEFAULT_THINKING_MODE,
},
},
};
}),
},
getActiveModel: vi.fn().mockReturnValue('gemini-pro'),
getModelAvailabilityService: vi
.fn()
.mockReturnValue(createAvailabilityServiceMock()),
getMessageBus: vi.fn().mockReturnValue(createMockMessageBus()),
} as unknown as Config;
chat = new GeminiChat(mockConfig);
});
describe('ensureActiveLoopHasFunctionResponses', () => {
it('should add synthetic function responses for missing responses in the history', () => {
const history: Content[] = [
{ role: 'user', parts: [{ text: 'Start' }] },
{
role: 'model',
parts: [
{ functionCall: { name: 'tool1', args: {} } },
{ functionCall: { name: 'tool2', args: {} } },
],
},
];
const newContents = chat.ensureActiveLoopHasFunctionResponses(
history,
'test-model',
);
expect(newContents.length).toBe(3);
expect(newContents[2].role).toBe('user');
expect(newContents[2].parts?.length).toBe(2);
expect(newContents[2].parts![0].functionResponse?.name).toBe('tool1');
expect(newContents[2].parts![1].functionResponse?.name).toBe('tool2');
expect(newContents[2].parts![0].functionResponse?.response).toEqual({
status: 'unknown',
message: expect.stringContaining('unknown'),
});
expect(mockLogOrphanedFunctionCallFixed).toHaveBeenCalledTimes(2);
});
it('should add missing responses to existing user turn', () => {
const history: Content[] = [
{ role: 'user', parts: [{ text: 'Start' }] },
{
role: 'model',
parts: [{ functionCall: { name: 'tool1', args: {} } }],
},
{
role: 'user',
parts: [{ text: 'Some other user message' }],
},
];
const newContents = chat.ensureActiveLoopHasFunctionResponses(
history,
'test-model',
);
expect(newContents.length).toBe(3);
expect(newContents[2].role).toBe('user');
expect(newContents[2].parts?.length).toBe(2);
expect(newContents[2].parts![0].functionResponse?.name).toBe('tool1');
expect(newContents[2].parts![1].text).toBe('Some other user message');
expect(mockLogOrphanedFunctionCallFixed).toHaveBeenCalled();
});
it('should match responses by ID if provided', () => {
const history: Content[] = [
{ role: 'user', parts: [{ text: 'Start' }] },
{
role: 'model',
parts: [{ functionCall: { name: 'tool1', args: {}, id: 'call-1' } }],
},
{
role: 'user',
parts: [
{
functionResponse: {
name: 'tool1',
id: 'call-1',
response: { result: 'ok' },
},
},
],
},
];
const newContents = chat.ensureActiveLoopHasFunctionResponses(
history,
'test-model',
);
expect(newContents).toEqual(history);
expect(mockLogOrphanedFunctionCallFixed).not.toHaveBeenCalled();
});
it('should add synthetic response if ID does not match', () => {
const history: Content[] = [
{ role: 'user', parts: [{ text: 'Start' }] },
{
role: 'model',
parts: [{ functionCall: { name: 'tool1', args: {}, id: 'call-1' } }],
},
{
role: 'user',
parts: [
{
functionResponse: {
name: 'tool1',
id: 'call-wrong',
response: { result: 'ok' },
},
},
],
},
];
const newContents = chat.ensureActiveLoopHasFunctionResponses(
history,
'test-model',
);
expect(newContents[2].parts?.length).toBe(2);
expect(newContents[2].parts![0].functionResponse?.id).toBe('call-1');
expect(newContents[2].parts![1].functionResponse?.id).toBe('call-wrong');
expect(mockLogOrphanedFunctionCallFixed).toHaveBeenCalled();
});
it('should repair history regardless of "active loop" interruptions', () => {
const history: Content[] = [
{
role: 'model',
parts: [{ functionCall: { name: 'old_tool', args: {} } }],
},
{ role: 'user', parts: [{ text: 'Start' }] },
{
role: 'model',
parts: [{ functionCall: { name: 'new_tool', args: {} } }],
},
];
const newContents = chat.ensureActiveLoopHasFunctionResponses(
history,
'test-model',
);
expect(newContents.length).toBe(4);
expect(newContents[1].parts![0].functionResponse?.name).toBe('old_tool');
expect(newContents[3].parts![0].functionResponse?.name).toBe('new_tool');
expect(mockLogOrphanedFunctionCallFixed).toHaveBeenCalledTimes(2);
});
});
describe('ensureActiveLoopHasThoughtSignatures', () => {
it('should add thoughtSignature to the first functionCall in each model turn of the active loop', () => {
const history: Content[] = [
{ role: 'user', parts: [{ text: 'Old message' }] },
{
role: 'model',
parts: [{ functionCall: { name: 'old_tool', args: {} } }],
},
{ role: 'user', parts: [{ text: 'Find a restaurant' }] }, // active loop starts here
{
role: 'model',
parts: [
{ functionCall: { name: 'find_restaurant', args: {} } },
{ functionCall: { name: 'find_restaurant_2', args: {} } },
],
},
{
role: 'user',
parts: [
{ functionResponse: { name: 'find_restaurant', response: {} } },
],
},
{
role: 'model',
parts: [
{
functionCall: { name: 'tool_with_sig', args: {} },
thoughtSignature: 'existing-sig',
},
{ functionCall: { name: 'another_tool', args: {} } },
],
},
];
const newContents = chat.ensureActiveLoopHasThoughtSignatures(history);
// Outside active loop - unchanged
expect(newContents[1]?.parts?.[0]).not.toHaveProperty('thoughtSignature');
// Inside active loop, first model turn
expect(newContents[3]?.parts?.[0]?.thoughtSignature).toBe(
SYNTHETIC_THOUGHT_SIGNATURE,
);
expect(newContents[3]?.parts?.[1]).not.toHaveProperty('thoughtSignature');
// Inside active loop, second model turn (already has sig)
expect(newContents[5]?.parts?.[0]?.thoughtSignature).toBe('existing-sig');
expect(newContents[5]?.parts?.[1]).not.toHaveProperty('thoughtSignature');
});
it('should not modify contents if there is no user text message', () => {
const history: Content[] = [
{
role: 'user',
parts: [{ functionResponse: { name: 'tool1', response: {} } }],
},
{
role: 'model',
parts: [{ functionCall: { name: 'tool2', args: {} } }],
},
];
const newContents = chat.ensureActiveLoopHasThoughtSignatures(history);
expect(newContents).toEqual(history);
});
});
});

View File

@@ -53,6 +53,7 @@ import type {
HookCallEvent,
StartupStatsEvent,
LlmLoopCheckEvent,
OrphanedFunctionCallFixedEvent,
} from './types.js';
import {
recordApiErrorMetrics,
@@ -719,6 +720,20 @@ export function logHookCall(config: Config, event: HookCallEvent): void {
});
}
export function logOrphanedFunctionCallFixed(
config: Config,
event: OrphanedFunctionCallFixedEvent,
): void {
bufferTelemetryEvent(() => {
const logger = logs.getLogger(SERVICE_NAME);
const logRecord: LogRecord = {
body: event.toLogBody(),
attributes: event.toOpenTelemetryAttributes(config),
};
logger.emit(logRecord);
});
}
export function logStartupStats(
config: Config,
event: StartupStatsEvent,

View File

@@ -1522,6 +1522,36 @@ export class LlmLoopCheckEvent implements BaseTelemetryEvent {
}
}
export const EVENT_ORPHANED_FUNCTION_CALL_FIXED =
'gemini_cli.chat.orphaned_function_call_fixed';
export class OrphanedFunctionCallFixedEvent implements BaseTelemetryEvent {
'event.name': 'orphaned_function_call_fixed';
'event.timestamp': string;
model: string;
function_name: string;
constructor(model: string, function_name: string) {
this['event.name'] = 'orphaned_function_call_fixed';
this['event.timestamp'] = new Date().toISOString();
this.model = model;
this.function_name = function_name;
}
toOpenTelemetryAttributes(config: Config): LogAttributes {
return {
...getCommonAttributes(config),
'event.name': EVENT_ORPHANED_FUNCTION_CALL_FIXED,
'event.timestamp': this['event.timestamp'],
model: this.model,
function_name: this.function_name,
};
}
toLogBody(): string {
return `Orphaned function call fixed for ${this.function_name}.`;
}
}
export type TelemetryEvent =
| StartSessionEvent
| EndSessionEvent
@@ -1555,7 +1585,8 @@ export type TelemetryEvent =
| StartupStatsEvent
| WebFetchFallbackAttemptEvent
| EditStrategyEvent
| EditCorrectionEvent;
| EditCorrectionEvent
| OrphanedFunctionCallFixedEvent;
export const EVENT_EXTENSION_DISABLE = 'gemini_cli.extension_disable';
export class ExtensionDisableEvent implements BaseTelemetryEvent {