feat: Add Open Telemetric semantic standard compliant log (#11975)

This commit is contained in:
Christie Warwick (Wilson)
2025-10-28 13:02:46 -07:00
committed by GitHub
parent 44bdd3ad11
commit 70996bfdee
11 changed files with 1371 additions and 179 deletions
+212 -37
View File
@@ -20,9 +20,9 @@ import {
} from '../index.js';
import { OutputFormat } from '../output/types.js';
import { logs } from '@opentelemetry/api-logs';
import { SemanticAttributes } from '@opentelemetry/semantic-conventions';
import type { Config } from '../config/config.js';
import {
logApiError,
logApiRequest,
logApiResponse,
logCliConfiguration,
@@ -46,6 +46,7 @@ import {
} from './loggers.js';
import { ToolCallDecision } from './tool-call-decision.js';
import {
EVENT_API_ERROR,
EVENT_API_REQUEST,
EVENT_API_RESPONSE,
EVENT_CLI_CONFIG,
@@ -64,6 +65,7 @@ import {
EVENT_AGENT_START,
EVENT_AGENT_FINISH,
EVENT_WEB_FETCH_FALLBACK_ATTEMPT,
ApiErrorEvent,
ApiRequestEvent,
ApiResponseEvent,
StartSessionEvent,
@@ -87,16 +89,13 @@ import {
EVENT_EXTENSION_UPDATE,
} from './types.js';
import * as metrics from './metrics.js';
import {
FileOperation,
GenAiOperationName,
GenAiProviderName,
} from './metrics.js';
import { FileOperation } from './metrics.js';
import * as sdk from './sdk.js';
import { vi, describe, beforeEach, it, expect, afterEach } from 'vitest';
import type {
CallableTool,
GenerateContentResponseUsageMetadata,
import {
FinishReason,
type CallableTool,
type GenerateContentResponseUsageMetadata,
} from '@google/genai';
import { DiscoveredMCPTool } from '../tools/mcp-tool.js';
import * as uiTelemetry from './uiTelemetry.js';
@@ -316,12 +315,6 @@ describe('loggers', () => {
const mockMetrics = {
recordApiResponseMetrics: vi.fn(),
recordTokenUsageMetrics: vi.fn(),
getConventionAttributes: vi.fn(() => ({
'gen_ai.operation.name': GenAiOperationName.GENERATE_CONTENT,
'gen_ai.provider.name': GenAiProviderName.GCP_VERTEX_AI,
'gen_ai.request.model': 'test-model',
'gen_ai.response.model': 'test-model',
})),
};
beforeEach(() => {
@@ -331,9 +324,6 @@ describe('loggers', () => {
vi.spyOn(metrics, 'recordTokenUsageMetrics').mockImplementation(
mockMetrics.recordTokenUsageMetrics,
);
vi.spyOn(metrics, 'getConventionAttributes').mockImplementation(
mockMetrics.getConventionAttributes,
);
});
it('should log an API response with all fields', () => {
@@ -347,7 +337,47 @@ describe('loggers', () => {
const event = new ApiResponseEvent(
'test-model',
100,
'prompt-id-1',
{
prompt_id: 'prompt-id-1',
contents: [
{
role: 'user',
parts: [{ text: 'Hello' }],
},
],
generate_content_config: {
temperature: 1,
topP: 2,
topK: 3,
responseMimeType: 'text/plain',
candidateCount: 1,
seed: 678,
frequencyPenalty: 10,
maxOutputTokens: 8000,
presencePenalty: 6,
stopSequences: ['stop', 'please stop'],
systemInstruction: {
role: 'model',
parts: [{ text: 'be nice' }],
},
},
server: {
address: 'foo.com',
port: 8080,
},
},
{
response_id: '',
candidates: [
{
content: {
role: 'model',
parts: [{ text: 'candidate 1' }],
},
finishReason: FinishReason.STOP,
},
],
},
AuthType.LOGIN_WITH_GOOGLE,
usageData,
'test-response',
@@ -357,26 +387,40 @@ describe('loggers', () => {
expect(mockLogger.emit).toHaveBeenCalledWith({
body: 'API response from test-model. Status: 200. Duration: 100ms.',
attributes: {
'session.id': 'test-session-id',
'user.email': 'test-user@example.com',
'installation.id': 'test-installation-id',
attributes: expect.objectContaining({
'event.name': EVENT_API_RESPONSE,
'event.timestamp': '2025-01-01T00:00:00.000Z',
[SemanticAttributes.HTTP_STATUS_CODE]: 200,
model: 'test-model',
status_code: 200,
duration_ms: 100,
input_token_count: 17,
output_token_count: 50,
cached_content_token_count: 10,
thoughts_token_count: 5,
tool_token_count: 2,
total_token_count: 0,
response_text: 'test-response',
prompt_id: 'prompt-id-1',
auth_type: 'oauth-personal',
},
}),
});
expect(mockLogger.emit).toHaveBeenCalledWith({
body: 'GenAI operation details from test-model. Status: 200. Duration: 100ms.',
attributes: expect.objectContaining({
'event.name': 'gen_ai.client.inference.operation.details',
'gen_ai.request.model': 'test-model',
'gen_ai.request.temperature': 1,
'gen_ai.request.top_p': 2,
'gen_ai.request.top_k': 3,
'gen_ai.input.messages':
'[{"role":"user","parts":[{"type":"text","content":"Hello"}]}]',
'gen_ai.output.messages':
'[{"finish_reason":"stop","role":"system","parts":[{"type":"text","content":"candidate 1"}]}]',
'gen_ai.response.finish_reasons': ['stop'],
'gen_ai.response.model': 'test-model',
'gen_ai.usage.input_tokens': 17,
'gen_ai.usage.output_tokens': 50,
'gen_ai.operation.name': 'generate_content',
'gen_ai.output.type': 'text',
'gen_ai.request.choice.count': 1,
'gen_ai.request.seed': 678,
'gen_ai.request.frequency_penalty': 10,
'gen_ai.request.presence_penalty': 6,
'gen_ai.request.max_tokens': 8000,
'server.address': 'foo.com',
'server.port': 8080,
'gen_ai.request.stop_sequences': ['stop', 'please stop'],
'gen_ai.system_instructions': '[{"type":"text","content":"be nice"}]',
}),
});
expect(mockMetrics.recordApiResponseMetrics).toHaveBeenCalledWith(
@@ -433,6 +477,137 @@ describe('loggers', () => {
});
});
describe('logApiError', () => {
const mockConfig = {
getSessionId: () => 'test-session-id',
getTargetDir: () => 'target-dir',
getUsageStatisticsEnabled: () => true,
getTelemetryEnabled: () => true,
getTelemetryLogPromptsEnabled: () => true,
} as Config;
const mockMetrics = {
recordApiResponseMetrics: vi.fn(),
recordApiErrorMetrics: vi.fn(),
recordTokenUsageMetrics: vi.fn(),
};
beforeEach(() => {
vi.spyOn(metrics, 'recordApiResponseMetrics').mockImplementation(
mockMetrics.recordApiResponseMetrics,
);
vi.spyOn(metrics, 'recordApiErrorMetrics').mockImplementation(
mockMetrics.recordApiErrorMetrics,
);
});
it('should log an API error with all fields', () => {
const event = new ApiErrorEvent(
'test-model',
'UNAVAILABLE. {"error":{"code":503,"message":"The model is overloaded. Please try again later.","status":"UNAVAILABLE"}}',
100,
{
prompt_id: 'prompt-id-1',
contents: [
{
role: 'user',
parts: [{ text: 'Hello' }],
},
],
generate_content_config: {
temperature: 1,
topP: 2,
topK: 3,
responseMimeType: 'text/plain',
candidateCount: 1,
seed: 678,
frequencyPenalty: 10,
maxOutputTokens: 8000,
presencePenalty: 6,
stopSequences: ['stop', 'please stop'],
systemInstruction: {
role: 'model',
parts: [{ text: 'be nice' }],
},
},
server: {
address: 'foo.com',
port: 8080,
},
},
AuthType.LOGIN_WITH_GOOGLE,
'ApiError',
503,
);
logApiError(mockConfig, event);
expect(mockLogger.emit).toHaveBeenCalledWith({
body: 'API error for test-model. Error: UNAVAILABLE. {"error":{"code":503,"message":"The model is overloaded. Please try again later.","status":"UNAVAILABLE"}}. Duration: 100ms.',
attributes: expect.objectContaining({
'event.name': EVENT_API_ERROR,
prompt_id: 'prompt-id-1',
}),
});
expect(mockLogger.emit).toHaveBeenCalledWith({
body: 'GenAI operation error details from test-model. Error: UNAVAILABLE. {"error":{"code":503,"message":"The model is overloaded. Please try again later.","status":"UNAVAILABLE"}}. Duration: 100ms.',
attributes: expect.objectContaining({
'event.name': 'gen_ai.client.inference.operation.details',
'gen_ai.request.model': 'test-model',
'gen_ai.request.temperature': 1,
'gen_ai.request.top_p': 2,
'gen_ai.request.top_k': 3,
'gen_ai.input.messages':
'[{"role":"user","parts":[{"type":"text","content":"Hello"}]}]',
'gen_ai.operation.name': 'generate_content',
'gen_ai.output.type': 'text',
'gen_ai.request.choice.count': 1,
'gen_ai.request.seed': 678,
'gen_ai.request.frequency_penalty': 10,
'gen_ai.request.presence_penalty': 6,
'gen_ai.request.max_tokens': 8000,
'server.address': 'foo.com',
'server.port': 8080,
'gen_ai.request.stop_sequences': ['stop', 'please stop'],
'gen_ai.system_instructions': '[{"type":"text","content":"be nice"}]',
}),
});
expect(mockMetrics.recordApiErrorMetrics).toHaveBeenCalledWith(
mockConfig,
100,
{
model: 'test-model',
status_code: 503,
error_type: 'ApiError',
},
);
expect(mockMetrics.recordApiResponseMetrics).toHaveBeenCalledWith(
mockConfig,
100,
{
model: 'test-model',
status_code: 503,
genAiAttributes: {
'gen_ai.operation.name': 'generate_content',
'gen_ai.provider.name': 'gcp.vertex_ai',
'gen_ai.request.model': 'test-model',
'gen_ai.response.model': 'test-model',
'error.type': 'ApiError',
},
},
);
expect(mockUiEvent.addEvent).toHaveBeenCalledWith({
...event,
'event.name': EVENT_API_ERROR,
'event.timestamp': '2025-01-01T00:00:00.000Z',
});
});
});
describe('logApiRequest', () => {
const mockConfig = {
getSessionId: () => 'test-session-id',