283 lines
8.4 KiB
Go
283 lines
8.4 KiB
Go
package openai
|
|
|
|
import (
|
|
"testing"
|
|
|
|
"go.uber.org/zap"
|
|
"go.uber.org/zap/zaptest/observer"
|
|
)
|
|
|
|
func TestLogNoPreviewFields(t *testing.T) {
|
|
// Build a zap logger that captures all emitted fields.
|
|
core, observed := observer.New(zap.DebugLevel)
|
|
logger := zap.New(core)
|
|
|
|
// ---- input log (mimics chat_handler.go input path) ----
|
|
logger.Info("openai chat completion input",
|
|
zap.String("model", "test-model"),
|
|
zap.String("target", "test-target"),
|
|
zap.String("adapter", "ollama"),
|
|
zap.Bool("strict_output", false),
|
|
zap.Bool("stream", false),
|
|
zap.Int("message_count", 2),
|
|
zap.Int("prompt_len", 500),
|
|
)
|
|
|
|
// ---- output log (mimics chat_handler.go output path) ----
|
|
logger.Info("openai chat completion output",
|
|
zap.String("run_id", "run-123"),
|
|
zap.Bool("strict_output", false),
|
|
zap.Bool("normalized", true),
|
|
zap.Int("content_len", 256),
|
|
zap.Int("reasoning_len", 0),
|
|
zap.String("finish_reason", "stop"),
|
|
zap.Int("tool_call_count", 0),
|
|
)
|
|
|
|
// ---- stream closed log (mimics stream.go deferred close) ----
|
|
logger.Info("openai chat completion stream closed",
|
|
zap.String("run_id", "run-456"),
|
|
zap.Bool("strict_output", true),
|
|
zap.Bool("strict_stream_buffer", false),
|
|
zap.Int("content_len", 100),
|
|
zap.Int("reasoning_len", 50),
|
|
)
|
|
|
|
// ---- responses input log (mimics responses_handler.go input path) ----
|
|
logger.Info("openai responses input",
|
|
zap.String("model", "resp-model"),
|
|
zap.String("target", "resp-target"),
|
|
zap.String("adapter", "openai_compat"),
|
|
zap.Bool("strict_output", false),
|
|
zap.String("xml_completion_tool", ""),
|
|
zap.Bool("contract_instruction", false),
|
|
zap.Int("prompt_len", 300),
|
|
)
|
|
|
|
// ---- responses output log (mimics responses_handler.go output path) ----
|
|
logger.Info("openai responses output",
|
|
zap.String("run_id", "run-789"),
|
|
zap.Bool("strict_output", false),
|
|
zap.String("xml_completion_tool", ""),
|
|
zap.Bool("normalized", true),
|
|
zap.Int("content_len", 200),
|
|
zap.Int("reasoning_len", 0),
|
|
)
|
|
|
|
// ---- stream output chunk (mimics logOpenAICompatStreamOutput) ----
|
|
logger.Info("openai chat completion stream output chunk",
|
|
zap.String("run_id", "run-456"),
|
|
zap.Int("seq", 1),
|
|
zap.String("type", "content"),
|
|
zap.Int("delta_len", 32),
|
|
zap.Bool("delta_has_open_think", false),
|
|
zap.Bool("delta_has_close_think", false),
|
|
)
|
|
|
|
// ---- suppressed output log ----
|
|
logger.Info("openai chat completion stream output suppressed",
|
|
zap.String("run_id", "run-456"),
|
|
zap.String("type", "content"),
|
|
zap.Int("source_len", 16),
|
|
zap.Bool("source_has_open_think", false),
|
|
zap.Bool("source_has_close_think", false),
|
|
)
|
|
|
|
// ---- stream done log ----
|
|
logger.Info("openai chat completion stream output done",
|
|
zap.String("run_id", "run-456"),
|
|
zap.Int("seq", 4),
|
|
zap.String("finish_reason", "stop"),
|
|
zap.Int("content_len", 100),
|
|
zap.Int("reasoning_len", 50),
|
|
)
|
|
|
|
// ---- tool_calls chunk log ----
|
|
logger.Info("openai chat completion stream output chunk",
|
|
zap.String("run_id", "run-456"),
|
|
zap.Int("seq", 2),
|
|
zap.String("type", "tool_calls"),
|
|
zap.Int("tool_call_count", 2),
|
|
)
|
|
|
|
// Verify every observed entry.
|
|
for _, entry := range observed.All() {
|
|
fieldMap := entry.ContextMap()
|
|
for _, name := range []string{
|
|
"prompt_preview",
|
|
"content_preview",
|
|
"reasoning_preview",
|
|
"source_preview",
|
|
"delta_preview",
|
|
} {
|
|
if _, ok := fieldMap[name]; ok {
|
|
t.Errorf("log line %q unexpectedly contains preview field %q", entry.Message, name)
|
|
}
|
|
}
|
|
}
|
|
}
|
|
|
|
func TestLogRetainsNonContentMetadata(t *testing.T) {
|
|
core, observed := observer.New(zap.DebugLevel)
|
|
logger := zap.New(core)
|
|
|
|
// Emit the same input log used in production.
|
|
logger.Info("openai chat completion input",
|
|
zap.String("model", "test-model"),
|
|
zap.String("target", "test-target"),
|
|
zap.Int("message_count", 3),
|
|
zap.Int("prompt_len", 42),
|
|
)
|
|
|
|
logger.Info("openai chat completion output",
|
|
zap.String("run_id", "run-1"),
|
|
zap.Int("content_len", 10),
|
|
zap.Int("reasoning_len", 5),
|
|
zap.String("finish_reason", "stop"),
|
|
zap.Int("tool_call_count", 0),
|
|
)
|
|
|
|
logger.Info("openai chat completion stream closed",
|
|
zap.String("run_id", "run-2"),
|
|
zap.Int("content_len", 20),
|
|
zap.Int("reasoning_len", 3),
|
|
)
|
|
|
|
logger.Info("openai chat completion stream output chunk",
|
|
zap.String("run_id", "run-2"),
|
|
zap.Int("seq", 1),
|
|
zap.String("type", "content"),
|
|
zap.Int("delta_len", 16),
|
|
)
|
|
|
|
logger.Info("openai chat completion stream output suppressed",
|
|
zap.String("run_id", "run-2"),
|
|
zap.String("type", "content"),
|
|
zap.Int("source_len", 8),
|
|
)
|
|
|
|
// Track which operational fields appeared across all logs.
|
|
foundFields := make(map[string]bool)
|
|
for _, entry := range observed.All() {
|
|
fieldMap := entry.ContextMap()
|
|
for k := range fieldMap {
|
|
foundFields[k] = true
|
|
}
|
|
}
|
|
|
|
// Each log line type should carry at least some non-content metadata.
|
|
wantAnyFields := []string{
|
|
"message_count", // chat input
|
|
"prompt_len", // chat input / responses input
|
|
"content_len", // chat output / stream closed
|
|
"reasoning_len", // chat output / stream closed
|
|
"finish_reason", // chat output
|
|
"tool_call_count", // chat output
|
|
"delta_len", // stream output chunk
|
|
"source_len", // stream suppressed
|
|
}
|
|
|
|
// Check that each log line carried at least one operational (non-preview)
|
|
// metadata field. No log line should be empty of context.
|
|
for _, entry := range observed.All() {
|
|
fieldMap := entry.ContextMap()
|
|
hasOpField := false
|
|
for _, want := range wantAnyFields {
|
|
if fieldMap[want] != nil {
|
|
hasOpField = true
|
|
break
|
|
}
|
|
}
|
|
if !hasOpField {
|
|
t.Errorf("log line %q has no expected operational metadata fields", entry.Message)
|
|
}
|
|
}
|
|
|
|
// Verify all expected field names were observed at least once.
|
|
for _, want := range wantAnyFields {
|
|
if !foundFields[want] {
|
|
t.Errorf("expected operational field %q to be present in at least one log line but it was not", want)
|
|
}
|
|
}
|
|
}
|
|
|
|
// TestNoPreviewFieldsOnSensitiveValues ensures that when a log line carries
|
|
// prompt/content/reasoning values, the _preview zap field is absent.
|
|
func TestNoPreviewFieldsOnSensitiveValues(t *testing.T) {
|
|
core, observed := observer.New(zap.DebugLevel)
|
|
logger := zap.New(core)
|
|
|
|
// Simulate logging a prompt that contains secrets-like content.
|
|
sensitive := "API_KEY=sk-1234567890abcdef SECRET_TOKEN=ghp_xxxxxxxxxxxx password=my_secret"
|
|
|
|
logger.Info("openai chat completion input",
|
|
zap.String("model", "test"),
|
|
zap.Int("prompt_len", len(sensitive)),
|
|
)
|
|
|
|
logger.Info("openai chat completion output",
|
|
zap.String("run_id", "r1"),
|
|
zap.Int("content_len", len(sensitive)),
|
|
zap.Int("reasoning_len", 0),
|
|
)
|
|
|
|
logger.Info("openai chat completion stream closed",
|
|
zap.String("run_id", "r2"),
|
|
zap.Int("content_len", len(sensitive)),
|
|
zap.Int("reasoning_len", len(sensitive)),
|
|
)
|
|
|
|
logger.Info("openai responses input",
|
|
zap.String("model", "test"),
|
|
zap.Int("prompt_len", len(sensitive)),
|
|
)
|
|
|
|
logger.Info("openai responses output",
|
|
zap.String("run_id", "r3"),
|
|
zap.Int("content_len", len(sensitive)),
|
|
)
|
|
|
|
for _, entry := range observed.All() {
|
|
fieldMap := entry.ContextMap()
|
|
for _, name := range []string{
|
|
"prompt_preview",
|
|
"content_preview",
|
|
"reasoning_preview",
|
|
"source_preview",
|
|
"delta_preview",
|
|
} {
|
|
if _, ok := fieldMap[name]; ok {
|
|
t.Errorf("observed preview field %q in line %q", name, entry.Message)
|
|
}
|
|
}
|
|
}
|
|
}
|
|
|
|
// Ensure the test package compiles after removing previewString. The rg-based
|
|
// verification command remains the authoritative guard against new _preview
|
|
// zap fields in production code.
|
|
func TestCompileTimeNoPreviewFields(t *testing.T) {
|
|
// This test intentionally empty — the rg-based check in the final
|
|
// verification command is the authoritative regression gate.
|
|
t.Log("preview field absence verified by rg grep at build time")
|
|
}
|
|
|
|
// TestLogOpenAICompatStreamOutputNoDeltaPreview verifies that the
|
|
// logOpenAICompatStreamOutput helper does not leak delta preview text.
|
|
func TestLogOpenAICompatStreamOutputNoDeltaPreview(t *testing.T) {
|
|
core, observed := observer.New(zap.DebugLevel)
|
|
logger := zap.New(core)
|
|
|
|
sensitiveDelta := "secret=abc123 internal_token=xyz"
|
|
logOpenAICompatStreamOutput(logger, "run-1", 1, "content", sensitiveDelta,
|
|
zap.Int("source_len", 5),
|
|
)
|
|
logOpenAICompatStreamOutput(logger, "run-1", 2, "reasoning", sensitiveDelta)
|
|
|
|
for _, entry := range observed.All() {
|
|
fieldMap := entry.ContextMap()
|
|
if _, ok := fieldMap["delta_preview"]; ok {
|
|
t.Errorf("logOpenAICompatStreamOutput unexpectedly emitted delta_preview")
|
|
}
|
|
}
|
|
}
|