diff --git a/packages/core/src/client/telemetry.ts b/packages/core/src/client/telemetry.ts index fbdc521..7fdaeef 100644 --- a/packages/core/src/client/telemetry.ts +++ b/packages/core/src/client/telemetry.ts @@ -2,9 +2,11 @@ import type { Attributes, Span } from '@opentelemetry/api'; import { GEN_AI, GEN_AI_OPERATION } from '../observability/attributes.js'; import { recordChatMetrics } from '../observability/metrics.js'; import { + addMessageEvents, finishChatSpan, inActiveSpan, recordSpanError, + responseFinishReason, setMessageContent, setSystemInstructions, spanName, @@ -110,6 +112,11 @@ export function withChatTelemetry( startedAt = performance.now(); setMessageContent(chatSpan, GEN_AI.inputMessages, messages); setSystemInstructions(chatSpan, options?.instructions); + addMessageEvents(chatSpan, { + providerName: client.metadata.providerName, + messages, + ...(options?.instructions === undefined ? {} : { instructions: options.instructions }), + }); try { // Inside the `try`: a client that rejects the call synchronously — a bad model name, a // missing key — would otherwise leave this span open and unrecorded, because the failure @@ -152,6 +159,13 @@ export function withChatTelemetry( } if (failure === undefined && span !== undefined) { finishChatSpan(span, response); + const finishReason = responseFinishReason(response); + addMessageEvents(span, { + providerName: client.metadata.providerName, + messages: response.messages, + output: true, + ...(finishReason === undefined ? {} : { finishReason }), + }); } endSpan(); }, diff --git a/packages/core/src/observability/attributes.ts b/packages/core/src/observability/attributes.ts index c0c2058..be5a028 100644 --- a/packages/core/src/observability/attributes.ts +++ b/packages/core/src/observability/attributes.ts @@ -57,6 +57,12 @@ export const GEN_AI = { /** Names the per-message event, alongside the role-specific event names below. */ eventName: 'event.name', + /** + * The provider name as the v1.36.0 message events carry it. The events predate + * `gen_ai.provider.name` and kept the older key, so all four implementations stamp them with + * this one. + */ + system: 'gen_ai.system', } as const; /** diff --git a/packages/core/src/observability/metrics.test.ts b/packages/core/src/observability/metrics.test.ts index 4bba4b4..f0b08e7 100644 --- a/packages/core/src/observability/metrics.test.ts +++ b/packages/core/src/observability/metrics.test.ts @@ -181,25 +181,25 @@ describe('nested usage aggregation', () => { }); describe('message events', () => { - it('emits one role-named event per message when content capture is on', async () => { + it('emits role-named events on the chat span when content capture is on', async () => { configureObservability({ captureMessageContent: true }); await new Agent({ client: usingClient(), name: 'bot' }).run('hello'); - const invoke = spanExporter.getFinishedSpans().find((span) => span.name === 'invoke_agent bot'); - const names = invoke?.events.map((event) => event.name); + const chat = spanExporter.getFinishedSpans().find((span) => span.name.startsWith('chat')); + const names = chat?.events.map((event) => event.name); expect(names).toEqual(['gen_ai.user.message', 'gen_ai.choice']); - const first = invoke?.events[0]; + const first = chat?.events[0]; expect(first?.attributes?.['event.name']).toBe('gen_ai.user.message'); - expect(first?.attributes?.role).toBe('user'); - expect(String(first?.attributes?.content)).toContain('hello'); + expect(JSON.parse(String(first?.attributes?.body))).toEqual({ content: 'hello' }); }); it('emits nothing without the opt-in, since the events carry message text', async () => { await new Agent({ client: usingClient(), name: 'bot' }).run('hello'); - const invoke = spanExporter.getFinishedSpans().find((span) => span.name === 'invoke_agent bot'); - expect(invoke?.events).toEqual([]); + for (const span of spanExporter.getFinishedSpans()) { + expect(span.events).toEqual([]); + } }); }); diff --git a/packages/core/src/observability/tracing.test.ts b/packages/core/src/observability/tracing.test.ts index 043de63..3d493c0 100644 --- a/packages/core/src/observability/tracing.test.ts +++ b/packages/core/src/observability/tracing.test.ts @@ -16,7 +16,7 @@ import { message } from '../types/message.js'; import { agentResponse } from '../types/response.js'; import { GEN_AI } from './attributes.js'; import { configureObservability, getTracer } from './settings.js'; -import { startAgentRunSpan } from './tracing.js'; +import { addMessageEvents, responseFinishReason, startAgentRunSpan } from './tracing.js'; const exporter = new InMemorySpanExporter(); /** Names of spans that were *started*, whether or not they were ended. */ @@ -439,6 +439,176 @@ describe('startAgentRunSpan', () => { }); }); +describe('v1.36.0 message events', () => { + /** A tool round followed by a text answer, so every event kind appears somewhere. */ + const toolTurns = [ + { + contents: [ + { + type: 'function_call' as const, + callId: 'c1', + name: 'get_weather', + arguments: '{"city":"Tokyo"}', + }, + ], + finishReason: 'tool_calls', + }, + { contents: [textContent('It is sunny.')], finishReason: 'stop' }, + ]; + + /** The JSON-decoded `body` attribute of each event on `span`, keyed by event name. */ + function eventBodies(span: ReadableSpan): Array<{ name: string; body: unknown }> { + return span.events.map((event) => ({ + name: event.name, + body: JSON.parse(String(event.attributes?.body)), + })); + } + + it('keeps message events off the invoke_agent span', async () => { + configureObservability({ captureMessageContent: true }); + await new Agent({ client: new MockChatClient(toolTurns), name: 'bot', tools: [getWeather] }).run( + 'weather?', + ); + + const invoke = must(byName('invoke_agent bot')); + // The reference implementations emit message events only for the model invocation; the agent + // span reports content as span attributes alone. + expect(invoke.events).toEqual([]); + expect(invoke.attributes[GEN_AI.inputMessages]).toBeDefined(); + expect(invoke.attributes[GEN_AI.outputMessages]).toBeDefined(); + }); + + it('emits v1.36.0-shaped events on each chat span', async () => { + configureObservability({ captureMessageContent: true }); + await new Agent({ + client: new MockChatClient(toolTurns), + name: 'bot', + tools: [getWeather], + instructions: 'Be terse.', + }).run('weather?'); + + const chats = spans().filter((span) => span.name === 'chat mock-model'); + expect(chats).toHaveLength(2); + + // First round: instructions, the user turn, then the model's tool-calling choice. + expect(eventBodies(must(chats[0]))).toEqual([ + { name: 'gen_ai.system.message', body: { content: 'Be terse.' } }, + { name: 'gen_ai.user.message', body: { content: 'weather?' } }, + { + name: 'gen_ai.choice', + body: { + index: 0, + finish_reason: 'tool_calls', + message: { + tool_calls: [ + { + id: 'c1', + type: 'function', + function: { name: 'get_weather', arguments: '{"city":"Tokyo"}' }, + }, + ], + }, + }, + }, + ]); + + // Second round replays the whole exchange: the assistant's call, the tool result, the answer. + expect(eventBodies(must(chats[1]))).toEqual([ + { name: 'gen_ai.system.message', body: { content: 'Be terse.' } }, + { name: 'gen_ai.user.message', body: { content: 'weather?' } }, + { + name: 'gen_ai.assistant.message', + body: { + tool_calls: [ + { + id: 'c1', + type: 'function', + function: { name: 'get_weather', arguments: '{"city":"Tokyo"}' }, + }, + ], + }, + }, + { name: 'gen_ai.tool.message', body: { id: 'c1', content: 'sunny' } }, + { + name: 'gen_ai.choice', + body: { index: 0, finish_reason: 'stop', message: { content: 'It is sunny.' } }, + }, + ]); + }); + + it('stamps the provider on every event and steps the timestamps', async () => { + configureObservability({ captureMessageContent: true }); + await new Agent({ client: new MockChatClient(toolTurns), name: 'bot', tools: [getWeather] }).run( + 'weather?', + ); + + const chat = must(spans().find((span) => span.name === 'chat mock-model')); + expect(chat.events.length).toBeGreaterThan(1); + for (const event of chat.events) { + expect(event.attributes?.['gen_ai.system']).toBe('mock'); + expect(event.attributes?.['event.name']).toBe(event.name); + } + // Compared as [seconds, nanos] tuples: collapsing an epoch hrtime into one number exceeds + // float64 integer precision and would erase the 1μs steps this asserts. + for (let i = 1; i < chat.events.length; i++) { + const [prevSec, prevNs] = must(chat.events[i - 1]).time; + const [sec, ns] = must(chat.events[i]).time; + expect(sec > prevSec || (sec === prevSec && ns > prevNs)).toBe(true); + } + }); + + it('degrades only the values JSON cannot encode, not the whole body', () => { + configureObservability({ captureMessageContent: true }); + const cyclic: Record = {}; + cyclic.self = cyclic; + const span = getTracer().startSpan('chat test'); + addMessageEvents(span, { + providerName: 'mock', + messages: [ + { + role: 'assistant', + contents: [ + textContent('calling'), + { type: 'function_call', callId: 'c1', name: 'f', arguments: { big: 1n, loop: cyclic } }, + ], + }, + ], + }); + span.end(); + + // A bigint or a cycle inside caller-built arguments must not cost the event its text and + // call name; only the offending values degrade. + const body = JSON.parse(String(must(byName('chat test')).events[0]?.attributes?.body)); + expect(body.content).toBe('calling'); + expect(body.tool_calls[0].id).toBe('c1'); + expect(body.tool_calls[0].function.name).toBe('f'); + expect(body.tool_calls[0].function.arguments.big).toBe('1'); + expect(body.tool_calls[0].function.arguments.loop).toEqual({ self: '[circular]' }); + }); + + it('falls back to the raw representation for the finish reason', () => { + const base = agentResponse({ messages: [] }); + expect(responseFinishReason(base)).toBeUndefined(); + // A provider that only reports the reason on the wire object still gets choice events. + expect(responseFinishReason({ ...base, rawRepresentation: { finish_reason: 'stop' } })).toBe('stop'); + // The normalized field wins over the raw one. + expect( + responseFinishReason({ ...base, finishReason: 'length', rawRepresentation: { finish_reason: 'stop' } }), + ).toBe('length'); + // A non-string raw value is not a finish reason. + expect(responseFinishReason({ ...base, rawRepresentation: { finish_reason: 42 } })).toBeUndefined(); + }); + + it('emits no choice event when the response reports no finish reason', async () => { + configureObservability({ captureMessageContent: true }); + const mock = new MockChatClient([{ contents: [textContent('hi')] }]); + await new Agent({ client: mock, name: 'bot' }).run('hello'); + + const chat = must(spans().find((span) => span.name === 'chat mock-model')); + expect(chat.events.map((event) => event.name)).toEqual(['gen_ai.user.message']); + }); +}); + describe('no-op behaviour without an SDK', () => { it('runs unchanged when no tracer provider is registered', async () => { trace.disable(); diff --git a/packages/core/src/observability/tracing.ts b/packages/core/src/observability/tracing.ts index ce99201..a879fb0 100644 --- a/packages/core/src/observability/tracing.ts +++ b/packages/core/src/observability/tracing.ts @@ -1,7 +1,7 @@ import type { Attributes, AttributeValue, Span } from '@opentelemetry/api'; import { context, SpanKind, SpanStatusCode, trace } from '@opentelemetry/api'; import type { Content } from '../types/content.js'; -import { textContent } from '../types/content.js'; +import { textContent, textOfContents } from '../types/content.js'; import type { Message } from '../types/message.js'; import type { ChatResponse, ResponseBase } from '../types/response.js'; import type { UsageDetails } from '../types/usage.js'; @@ -72,24 +72,18 @@ export function capturesContent(span: Span): boolean { } /** - * Records prompts and completions, but only when the caller opted in. + * Records prompts and completions as span attributes, but only when the caller opted in. * - * Two forms, as the conventions ask for: the whole list as one attribute, and one event per - * message so a backend can render the exchange in order. Both are gated on the same opt-in, - * because both carry message text. + * Attributes only: the per-message events are a separate concern ({@link addMessageEvents}) + * emitted solely on the `chat` span, while this attribute form goes on both the `invoke_agent` + * and `chat` spans — the split the reference implementations settled on for their message + * telemetry. */ export function setMessageContent(span: Span, key: string, messages: readonly Message[]): void { if (messages.length === 0 || !capturesContent(span)) { return; } - // Each message is serialized once; the aggregate attribute and the per-message events share the - // same strings, so a long transcript pays one serialization pass instead of two. - const serialized = messages.map(serializeMessageForSpan); - span.setAttribute(key, `[${serialized.join(',')}]`); - const output = key === GEN_AI.outputMessages; - messages.forEach((msg, index) => { - addMessageEvent(span, msg, output, serialized[index]); - }); + span.setAttribute(key, serializeMessagesForSpan(messages)); } /** @@ -106,22 +100,203 @@ export function setSystemInstructions(span: Span, instructions: string | undefin } /** - * Adds the per-message event for one message. + * How far apart consecutive message events are stamped, in milliseconds (1 microsecond). * - * Python logs these through the logging module, which its OpenTelemetry handler turns into log - * records; here they are span events, since the logs API is a separate package and the core - * depends only on `@opentelemetry/api`. The event name and the serialized payload match, so the - * two implementations produce the same shape. + * All events of one invocation share a single wall-clock read plus this fixed step, so their + * order survives backends that truncate or collapse timestamps for tightly-emitted events — the + * same spacing Python applies. */ -export function addMessageEvent(span: Span, message: Message, output: boolean, serialized?: string): void { - const name = output - ? GEN_AI_MESSAGE_EVENT.choice - : (GEN_AI_MESSAGE_EVENT[message.role as keyof typeof GEN_AI_MESSAGE_EVENT] ?? GEN_AI_MESSAGE_EVENT.user); - span.addEvent(name, { - [GEN_AI.eventName]: name, - ...(message.role === undefined ? {} : { role: message.role }), - content: `[${serialized ?? serializeMessageForSpan(message)}]`, - }); +const MESSAGE_EVENT_TIMESTAMP_STEP_MS = 0.001; + +/** + * The event body as the JSON string a span event can carry. + * + * A tool result or call arguments can hold values JSON cannot encode (circular references, + * bigints); one telemetry event is not worth failing the run for, and one bad value is not worth + * losing the rest of the body for, so only the offending values degrade — the granularity the + * Python emitter gets from its exporter stringifying unencodable values one at a time. + */ +function eventBodyJson(body: Record): string { + try { + return JSON.stringify(body); + } catch { + try { + const seen = new WeakSet(); + return JSON.stringify(body, (_key, value: unknown) => { + if (typeof value === 'bigint') { + return value.toString(); + } + if (typeof value === 'object' && value !== null) { + if (seen.has(value)) { + return '[circular]'; + } + seen.add(value); + } + return value; + }); + } catch { + return '"[unserializable]"'; + } + } +} + +/** The v1.36.0 `tool_calls` structures of a message's function calls. */ +function toolCallsOf(message: Message): Record[] { + const calls: Record[] = []; + for (const content of message.contents) { + if (content.type === 'function_call' && content.callId !== '' && content.name !== '') { + calls.push({ + id: content.callId, + type: 'function', + function: { name: content.name, arguments: content.arguments }, + }); + } + } + return calls; +} + +/** + * The v1.36.0 events for one input message. + * + * A tool message becomes one event per function result; other mapped roles become a single event + * whose body carries the text and, for the assistant, its tool calls. A role outside the map + * produces nothing, as in the reference implementations. + */ +function inputEventsOf(message: Message): Array<{ name: string; body: Record }> { + if (message.role === 'tool') { + const events: Array<{ name: string; body: Record }> = []; + for (const content of message.contents) { + if (content.type === 'function_result' && content.callId !== '') { + events.push({ + name: GEN_AI_MESSAGE_EVENT.tool, + body: { id: content.callId, content: content.result ?? '' }, + }); + } + } + return events; + } + const name = + message.role === 'system' + ? GEN_AI_MESSAGE_EVENT.system + : message.role === 'user' + ? GEN_AI_MESSAGE_EVENT.user + : message.role === 'assistant' + ? GEN_AI_MESSAGE_EVENT.assistant + : undefined; + if (name === undefined) { + return []; + } + const body: Record = {}; + const text = textOfContents(message.contents); + if (text !== '') { + body.content = text; + } + if (message.role === 'assistant') { + const toolCalls = toolCallsOf(message); + if (toolCalls.length > 0) { + body.tool_calls = toolCalls; + } + } + return [{ name, body }]; +} + +/** The v1.36.0 `gen_ai.choice` body for one response message. */ +function choiceBody(message: Message, index: number, finishReason: string): Record { + const choiceMessage: Record = {}; + const text = textOfContents(message.contents); + if (text !== '') { + choiceMessage.content = text; + } + if (message.role !== 'assistant') { + choiceMessage.role = message.role; + } + const toolCalls = toolCallsOf(message); + if (toolCalls.length > 0) { + choiceMessage.tool_calls = toolCalls; + } + return { index, finish_reason: finishReason, message: choiceMessage }; +} + +/** What {@link addMessageEvents} emits. */ +export interface MessageEventsInit { + /** Stamped on every event as `gen_ai.system`, the key the v1.36.0 events carry it under. */ + providerName: string; + messages: readonly Message[]; + /** Emitted ahead of the input messages as a `gen_ai.system.message` event. Input side only. */ + instructions?: string; + /** Marks the response side: each message becomes a `gen_ai.choice` event. */ + output?: boolean; + /** Why the response stopped. Without it the output side emits nothing — a choice event's body requires it. */ + finishReason?: string; +} + +/** + * Emits the per-message GenAI events (v1.36.0 shapes) for one model invocation. + * + * These belong on the `chat` span only: the reference implementations emit message events for the + * model invocation and leave the `invoke_agent` span with attribute-form content, so emitting here + * too would double-report every exchange. + * + * Python emits these through the OpenTelemetry logs API with a structured body; here they are + * span events, since the logs API is a separate package and the core depends only on + * `@opentelemetry/api`. A span event cannot carry a structured body, so the body rides the `body` + * attribute as JSON — same shape, one parse away — and `event.name` is kept for backends that + * lift span events into log records. + */ +export function addMessageEvents(span: Span, init: MessageEventsInit): void { + if (!capturesContent(span)) { + return; + } + // A sub-millisecond wall-clock read: `Date.now()` has millisecond resolution, so the input + // events and the choice events of one fast invocation would collide on the same base and the + // choice events would stamp *earlier* than the stepped input events. + let timestamp = performance.timeOrigin + performance.now(); + const emit = (name: string, body: Record): void => { + span.addEvent( + name, + { [GEN_AI.eventName]: name, [GEN_AI.system]: init.providerName, body: eventBodyJson(body) }, + timestamp, + ); + timestamp += MESSAGE_EVENT_TIMESTAMP_STEP_MS; + }; + if (init.output === true) { + const finishReason = init.finishReason; + if (finishReason === undefined || finishReason === '') { + return; + } + init.messages.forEach((message, index) => { + emit(GEN_AI_MESSAGE_EVENT.choice, choiceBody(message, index, finishReason)); + }); + return; + } + if (init.instructions !== undefined && init.instructions !== '') { + emit(GEN_AI_MESSAGE_EVENT.system, { content: init.instructions }); + } + for (const message of init.messages) { + for (const event of inputEventsOf(message)) { + emit(event.name, event.body); + } + } +} + +/** + * The finish reason a response reports, falling back to its raw representation. + * + * Some providers only populate `finish_reason` on the wire object rather than the normalized + * response field; the fallback keeps their responses from silently losing choice events. + */ +export function responseFinishReason(response: ResponseBase): string | undefined { + if (response.finishReason !== undefined) { + return response.finishReason; + } + const raw: unknown = response.rawRepresentation; + if (typeof raw === 'object' && raw !== null) { + const fallback = (raw as { finish_reason?: unknown }).finish_reason; + if (typeof fallback === 'string') { + return fallback; + } + } + return undefined; } /** Marks a span failed and records the error type, matching the GenAI conventions. */