feat(ai): add DtpLog logging of all OpenAI API responses

- Fix broken chunkCount reference in generate() usage chunk log
- Add generate() complete log with usage, response/thinking lengths
- Add readStreamingChatCompletion() usage chunk log (full chunk dump)
- Add readStreamingChatCompletion() iteration complete log
- Add readNonStreamingChatCompletion() full response dump
- Add chat() streaming iteration usage log
- Add chat() non-streaming fallback usage log
- Add chat() final response stats log

All logs use info level and 'OpenAI {method}: {event}' naming for
easy grep/filtering. Streaming chunks use JSON.parse(JSON.stringify())
to serialize the full OpenAI SDK response objects.
This commit is contained in:
Rob Colbert 2026-05-18 15:20:53 -04:00
parent 2483161663
commit 51b3013659

View File

@ -242,6 +242,11 @@ export class OpenAiApi extends AiApi {
promptTokens: chunk.usage.prompt_tokens, promptTokens: chunk.usage.prompt_tokens,
completionTokens: chunk.usage.completion_tokens, completionTokens: chunk.usage.completion_tokens,
}; };
// LOG: dump entire usage chunk from OpenAI generate streaming response
this.log.info("OpenAI generate: streaming chunk with usage", {
usage: JSON.parse(JSON.stringify(chunk.usage)),
chunk: JSON.parse(JSON.stringify(chunk)),
});
} }
const delta = chunk.choices[0]?.delta; const delta = chunk.choices[0]?.delta;
@ -270,6 +275,14 @@ export class OpenAiApi extends AiApi {
const endTime = Date.now(); const endTime = Date.now();
const durationMs = endTime - startTime; const durationMs = endTime - startTime;
// LOG: dump final usage and accumulated stats from generate()
this.log.info("OpenAI generate: complete", {
usage,
responseLength: accumulatedResponse.length,
thinkingLength: accumulatedThinking.length,
durationMs,
});
return { return {
done: true, done: true,
response: accumulatedResponse, response: accumulatedResponse,
@ -320,6 +333,12 @@ export class OpenAiApi extends AiApi {
finishReason: iteration.finishReason, finishReason: iteration.finishReason,
}); });
// LOG: dump usage from streaming chat iteration
this.log.info("OpenAI chat: streaming iteration usage", {
usage: iteration.usage,
finishReason: iteration.finishReason,
});
if (this.isEmptyIteration(iteration)) { if (this.isEmptyIteration(iteration)) {
iteration = await this.readNonStreamingChatCompletion(model, messages, tools, options.signal); iteration = await this.readNonStreamingChatCompletion(model, messages, tools, options.signal);
if (streamCallback && iteration.response) { if (streamCallback && iteration.response) {
@ -331,6 +350,11 @@ export class OpenAiApi extends AiApi {
toolCallCount: iteration.toolCalls.length, toolCallCount: iteration.toolCalls.length,
finishReason: iteration.finishReason, finishReason: iteration.finishReason,
}); });
// LOG: dump usage from non-streaming fallback
this.log.info("OpenAI chat: non-streaming fallback usage", {
usage: iteration.usage,
finishReason: iteration.finishReason,
});
} }
if (this.isEmptyIteration(iteration)) { if (this.isEmptyIteration(iteration)) {
@ -351,6 +375,12 @@ export class OpenAiApi extends AiApi {
toolCalls: iteration.toolCalls.length > 0 ? iteration.toolCalls : undefined, toolCalls: iteration.toolCalls.length > 0 ? iteration.toolCalls : undefined,
stats: this.buildStats(startTime, iteration.usage), stats: this.buildStats(startTime, iteration.usage),
}; };
// LOG: dump final chat response stats
this.log.info("OpenAI chat: final response", {
usage: iteration.usage,
stats: finalResponse.stats,
finishReason: iteration.finishReason,
});
this.assertNonEmptyChatResponse(finalResponse); this.assertNonEmptyChatResponse(finalResponse);
return finalResponse; return finalResponse;
} }
@ -455,6 +485,11 @@ export class OpenAiApi extends AiApi {
promptTokens: chunk.usage.prompt_tokens, promptTokens: chunk.usage.prompt_tokens,
completionTokens: chunk.usage.completion_tokens, completionTokens: chunk.usage.completion_tokens,
}; };
// LOG: dump entire usage chunk from OpenAI chat streaming response
this.log.info("OpenAI chat stream: streaming chunk with usage", {
usage: JSON.parse(JSON.stringify(chunk.usage)),
chunk: JSON.parse(JSON.stringify(chunk)),
});
} }
const delta = chunk.choices[0]?.delta; const delta = chunk.choices[0]?.delta;
@ -481,6 +516,18 @@ export class OpenAiApi extends AiApi {
} }
} }
// LOG: dump final streaming chat completion iteration result
this.log.info("OpenAI chat stream: iteration complete", {
chunkCount,
contentDeltaCount,
toolDeltaCount,
finishReason,
usage,
responseLength: content.length,
thinkingLength: thinking.length,
toolCallCount: toolCallMap.size,
});
return { return {
response: content, response: content,
thinking: thinking || undefined, thinking: thinking || undefined,
@ -522,6 +569,10 @@ export class OpenAiApi extends AiApi {
} }
: {}), : {}),
}, signal ? { signal } : undefined); }, signal ? { signal } : undefined);
// LOG: dump entire non-streaming response from OpenAI
this.log.info("OpenAI chat non-streaming: response", {
response: JSON.parse(JSON.stringify(response)),
});
const choice = response.choices[0]; const choice = response.choices[0];
const message = choice?.message; const message = choice?.message;
const content = typeof message?.content === "string" ? message.content : ""; const content = typeof message?.content === "string" ? message.content : "";