package openai import ( "context" "testing" "time" "iop/packages/go/streamgate" "go.uber.org/zap" "go.uber.org/zap/zaptest/observer" ) func emitLogSafetyObservation(t *testing.T, logger *zap.Logger) { t.Helper() target, err := streamgate.NewObservationAttemptTarget("client-model", "served/model", "provider-a", "provider_tunnel") if err != nil { t.Fatalf("NewObservationAttemptTarget: %v", err) } recovery, err := streamgate.NewObservationRecoveryInfo("plan-1", streamgate.RecoveryStrategyExactReplay, streamgate.RecoveryResumeModeReplaceAttempt, "") if err != nil { t.Fatalf("NewObservationRecoveryInfo: %v", err) } preparer, err := streamgate.NewObservationPreparerInfo("preparer-1", streamgate.RecoveryPreparationPrepared, streamgate.ObservationDeadlineOutcomeCompleted) if err != nil { t.Fatalf("NewObservationPreparerInfo: %v", err) } _, err = streamgate.NewObservationSequencer(newZapFilterObservationSink(logger), nil).Emit(context.Background(), streamgate.FilterObservationInput{ Kind: streamgate.ObservationKindRecoveryPrepared, StableCorrelation: "req-1", ConfigGeneration: "gen-1", AttemptID: "attempt-1", AttemptTarget: target, CommitState: streamgate.CommitStateTransportUncommitted, Recovery: &recovery, Preparer: &preparer, OccurredAt: time.Now(), }) if err != nil { t.Fatalf("emit observation: %v", err) } } func TestLogNoPreviewFields(t *testing.T) { // Build a zap logger that captures all emitted fields. core, observed := observer.New(zap.DebugLevel) logger := zap.New(core) emitLogSafetyObservation(t, logger) // ---- 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() if entry.Message == filterObservationLogMessage { allowed := map[string]struct{}{ "sequence": {}, "observation_kind": {}, "correlation_id": {}, "config_generation": {}, "attempt_id": {}, "model_group": {}, "actual_model": {}, "actual_provider": {}, "execution_path": {}, "epoch_id": {}, "commit_state": {}, "plan_id": {}, "recovery_strategy": {}, "resume_mode": {}, "preparer_id": {}, "preparer_status": {}, "preparer_deadline_outcome": {}, } for key := range fieldMap { if _, ok := allowed[key]; !ok { t.Errorf("observation log contains non-allowlisted field %q", key) } } for key, want := range map[string]any{"model_group": "client-model", "actual_model": "served/model", "actual_provider": "provider-a", "execution_path": "provider_tunnel"} { if fieldMap[key] != want { t.Errorf("observation field %s=%v, want %v", key, fieldMap[key], want) } } } for _, name := range []string{ "prompt_preview", "content_preview", "reasoning_preview", "source_preview", "delta_preview", "raw_body", "provider_body", "body", "raw_chunk", "prompt", "output", "tool_args", "tool_result", "authorization", "preparer_input", "preparer_output", "error_text", } { if _, ok := fieldMap[name]; ok { t.Errorf("log line %q unexpectedly contains forbidden field %q", entry.Message, name) } } } } func TestLogRetainsNonContentMetadata(t *testing.T) { core, observed := observer.New(zap.DebugLevel) logger := zap.New(core) emitLogSafetyObservation(t, logger) // 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 "model_group", // observation attempt target "actual_model", // observation attempt target "actual_provider", // observation attempt target "execution_path", // observation attempt target } // 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", "raw_body", "provider_body", "body", "raw_chunk", "prompt", "output", "tool_args", "tool_result", "authorization", "preparer_input", "preparer_output", "error_text", } { if _, ok := fieldMap[name]; ok { t.Errorf("observed forbidden field %q in line %q", name, entry.Message) } } } } // The authoritative guard against new `_preview` zap fields in production code // is the `rg --sort path` source check pinned in the plan's verification // commands (run outside the test binary); the behavioral log tests above assert // the runtime never emits preview/raw fields. There is deliberately no empty // compile-time placeholder test claiming to run that grep. // 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") } } }