package agentruntime import ( "bytes" "encoding/json" "errors" "os" "path/filepath" "strings" "testing" "time" ) func TestCodexAppServerStartupTraceRecordsStructuredSpanClose(t *testing.T) { var observations []CodexAppServerSpanObservation trace := &codexAppServerStartupTrace{ startedAt: time.Now(), session: Session{Provider: ProviderCodex, RoomID: "room-1", AgentSessionID: "session-1"}, path: filepath.Join(t.TempDir(), "trace.jsonl"), spanObserver: func(observation CodexAppServerSpanObservation) { observations = append(observations, observation) }, openSpans: make(map[string][]codexAppServerOpenSpan), } firstChunk := []byte(`{"timestamp":"2026-08-20T02:00:00.000Z","level":"INFO","target":"codex_core","fields":{"message":"new"},"span":{"name":"session_init"}`) secondChunk := []byte(`} {"timestamp":"2026-08-20T02:00:00.125Z","level":"INFO","target":"codex_core","fields":{"message":"close","time.busy":"120ms","time.idle":"5ms"},"span":{"name":"session_init"}} {"timestamp":"2026-08-20T02:00:00.200Z","level":"INFO","target":"codex_core","fields":{"message":"close"},"span":{"name":"unrelated_span"}} `) trace.LogStderr(firstChunk) trace.LogStderr(secondChunk) if got, want := trace.stderrChunks.Load(), int64(2); got != want { t.Fatalf("stderr chunks = %d, want %d", got, want) } if got, want := trace.stderrBytes.Load(), int64(len(firstChunk)+len(secondChunk)); got != want { t.Fatalf("stderr bytes = %d, want %d", got, want) } data, err := os.ReadFile(trace.path) if err != nil { t.Fatalf("read trace: %v", err) } var records []map[string]any for _, line := range splitJSONLines(data) { var record map[string]any if err := json.Unmarshal(line, &record); err != nil { t.Fatalf("decode trace line %q: %v", line, err) } records = append(records, record) } var closeRecord map[string]any spanRecords := 0 for _, record := range records { if record["event"] != "app_server.span" { continue } spanRecords++ if record["span_phase"] == "close" { closeRecord = record } } if spanRecords != 2 { t.Fatalf("span records = %d, want new and close only", spanRecords) } if closeRecord == nil { t.Fatal("missing session_init close span record") } if closeRecord["span_name"] != "session_init" { t.Fatalf("span_name = %#v, want session_init", closeRecord["span_name"]) } if closeRecord["duration_ms"] != float64(125) { t.Fatalf("duration_ms = %#v, want 125", closeRecord["duration_ms"]) } if closeRecord["span_busy"] != "120ms" || closeRecord["span_idle"] != "5ms" { t.Fatalf("span timing = %#v, want busy/idle values", closeRecord) } if len(observations) != 2 { t.Fatalf("span observations = %d, want new and close", len(observations)) } newObservation := observations[0] closeObservation := observations[1] if newObservation.Provider != ProviderCodex || newObservation.RoomID != "room-1" || newObservation.AgentSessionID != "session-1" { t.Fatalf("new observation scope = %#v, want Codex room/session scope", newObservation) } if newObservation.SpanName != "session_init" || newObservation.SpanPhase != "new" || newObservation.DurationMS != 0 { t.Fatalf("new observation span = %#v, want session_init new at 0ms", newObservation) } if newObservation.SpanInstanceID == "" || newObservation.SpanInstanceID != closeObservation.SpanInstanceID { t.Fatalf("span instance IDs = %q and %q, want the same non-empty ID", newObservation.SpanInstanceID, closeObservation.SpanInstanceID) } if closeObservation.SpanName != "session_init" || closeObservation.SpanPhase != "close" || closeObservation.DurationMS != 125 { t.Fatalf("close observation span = %#v, want session_init close at 125ms", closeObservation) } if closeObservation.SpanBusy != "120ms" || closeObservation.SpanIdle != "5ms" { t.Fatalf("close observation timing = %#v, want busy/idle values", closeObservation) } } func TestCodexAppServerStartupTraceBoundsStderrDiagnostics(t *testing.T) { trace := &codexAppServerStartupTrace{ startedAt: time.Now(), session: Session{Provider: ProviderCodex, RoomID: "room-1", AgentSessionID: "session-1"}, path: filepath.Join(t.TempDir(), "trace.jsonl"), openSpans: make(map[string][]codexAppServerOpenSpan), } firstChunk := bytes.Repeat([]byte("x"), codexAppServerStderrTailLimit+100) secondChunk := []byte("\nstartup timeout details") trace.LogStderr(firstChunk) trace.LogStderr(secondChunk) trace.Finish(errors.New("startup timeout")) data, err := os.ReadFile(trace.path) if err != nil { t.Fatalf("read trace: %v", err) } var failedRecord map[string]any for _, line := range splitJSONLines(data) { var record map[string]any if err := json.Unmarshal(line, &record); err != nil { t.Fatalf("decode trace line %q: %v", line, err) } if record["event"] == "process.stderr" { t.Fatal("trace contains per-chunk process.stderr record") } if record["event"] == "start.failed" { failedRecord = record } } if failedRecord == nil { t.Fatal("missing start.failed record") } if failedRecord["stderr_chunks"] != float64(2) { t.Fatalf("stderr_chunks = %#v, want 2", failedRecord["stderr_chunks"]) } if failedRecord["stderr_bytes"] != float64(len(firstChunk)+len(secondChunk)) { t.Fatalf("stderr_bytes = %#v, want %d", failedRecord["stderr_bytes"], len(firstChunk)+len(secondChunk)) } tail, ok := failedRecord["stderr_tail"].(string) if !ok || !strings.Contains(tail, "startup timeout details") { t.Fatalf("stderr_tail = %#v, want bounded failure tail", failedRecord["stderr_tail"]) } if len(tail) > codexAppServerStderrTailLimit { t.Fatalf("stderr_tail length = %d, want <= %d", len(tail), codexAppServerStderrTailLimit) } } func TestCodexAppServerStartupTraceReportsOpenSpanBeforeClose(t *testing.T) { var observations []CodexAppServerSpanObservation trace := &codexAppServerStartupTrace{ startedAt: time.Now(), session: Session{Provider: ProviderCodex, RoomID: "room-1", AgentSessionID: "session-1"}, path: filepath.Join(t.TempDir(), "trace.jsonl"), spanObserver: func(observation CodexAppServerSpanObservation) { observations = append(observations, observation) }, openSpans: make(map[string][]codexAppServerOpenSpan), } trace.LogStderr([]byte(`{"timestamp":"2026-08-20T02:00:00.000Z","target":"codex_core","fields":{"message":"new"},"span":{"name":"app_server.thread_start.send_response"}} `)) if len(observations) != 1 { t.Fatalf("span observations = %d, want one open span", len(observations)) } if observations[0].SpanPhase != "new" || observations[0].SpanName != "app_server.thread_start.send_response" { t.Fatalf("open observation = %#v, want send_response new", observations[0]) } if observations[0].SpanInstanceID == "" { t.Fatal("open observation has empty span instance ID") } } func TestCodexAppServerStartupTraceAssociatesNestedSameNameSpans(t *testing.T) { var observations []CodexAppServerSpanObservation trace := &codexAppServerStartupTrace{ startedAt: time.Now(), session: Session{Provider: ProviderCodex, RoomID: "room-1", AgentSessionID: "session-1"}, path: filepath.Join(t.TempDir(), "trace.jsonl"), spanObserver: func(observation CodexAppServerSpanObservation) { observations = append(observations, observation) }, openSpans: make(map[string][]codexAppServerOpenSpan), } trace.LogStderr([]byte(`{"timestamp":"2026-08-20T02:00:00.000Z","fields":{"message":"new"},"span":{"name":"session_init"}} {"timestamp":"2026-08-20T02:00:00.001Z","fields":{"message":"new"},"span":{"name":"session_init"}} {"timestamp":"2026-08-20T02:00:00.003Z","fields":{"message":"close"},"span":{"name":"session_init"}} {"timestamp":"2026-08-20T02:00:00.005Z","fields":{"message":"close"},"span":{"name":"session_init"}} `)) if len(observations) != 4 { t.Fatalf("span observations = %d, want two new and two close", len(observations)) } if observations[0].SpanInstanceID == observations[1].SpanInstanceID { t.Fatal("nested spans have the same instance ID") } if observations[2].SpanInstanceID != observations[1].SpanInstanceID || observations[3].SpanInstanceID != observations[0].SpanInstanceID { t.Fatalf("close instance IDs = %q, %q; want LIFO association", observations[2].SpanInstanceID, observations[3].SpanInstanceID) } if observations[2].DurationMS != 2 || observations[3].DurationMS != 5 { t.Fatalf("close durations = %d, %d; want 2ms and 5ms", observations[2].DurationMS, observations[3].DurationMS) } } func TestCodexAppServerStartupTraceReportsBoundedSummary(t *testing.T) { var observations []CodexAppServerStartupObservation trace := &codexAppServerStartupTrace{ startedAt: time.Now().Add(-125 * time.Millisecond), session: Session{ Provider: ProviderCodex, RoomID: "room-1", AgentSessionID: "session-1", MCPServers: []MCPServerBinding{ {Name: "one"}, {Name: "two"}, }, }, path: filepath.Join(t.TempDir(), "trace.jsonl"), startupObserver: func(observation CodexAppServerStartupObservation) { observations = append(observations, observation) }, openSpans: make(map[string][]codexAppServerOpenSpan), } trace.LogStderr([]byte(`{"timestamp":"2026-08-20T02:00:00.000Z","fields":{"message":"new"},"span":{"name":"session_init"}} {"timestamp":"2026-08-20T02:00:00.125Z","fields":{"message":"close"},"span":{"name":"session_init"}} `)) trace.Finish(nil) if len(observations) != 1 { t.Fatalf("startup observations = %d, want one", len(observations)) } observation := observations[0] if observation.Provider != ProviderCodex || observation.RoomID != "room-1" || observation.AgentSessionID != "session-1" { t.Fatalf("observation scope = %#v, want Codex room/session scope", observation) } if observation.Outcome != "succeeded" { t.Fatalf("outcome = %q, want succeeded", observation.Outcome) } if observation.MCPServerCount != 2 || observation.CompletedSpanCount != 1 { t.Fatalf("resource summary = %#v, want two MCP servers and one span", observation) } if observation.DurationMS < 100 { t.Fatalf("duration_ms = %d, want at least 100ms", observation.DurationMS) } } func TestCodexAppServerStartupTraceStartupObserverPanicDoesNotEscape(t *testing.T) { trace := &codexAppServerStartupTrace{ startedAt: time.Now(), session: Session{Provider: ProviderCodex, AgentSessionID: "session-1"}, path: filepath.Join(t.TempDir(), "trace.jsonl"), startupObserver: func(CodexAppServerStartupObservation) { panic("analytics observer failure") }, openSpans: make(map[string][]codexAppServerOpenSpan), } trace.Finish(nil) } func TestCodexAppServerStartupTraceObserverPanicDoesNotEscape(t *testing.T) { trace := &codexAppServerStartupTrace{ startedAt: time.Now(), session: Session{Provider: ProviderCodex, AgentSessionID: "session-1"}, path: filepath.Join(t.TempDir(), "trace.jsonl"), spanObserver: func(CodexAppServerSpanObservation) { panic("analytics observer failure") }, openSpans: make(map[string][]codexAppServerOpenSpan), } trace.LogStderr([]byte(`{"timestamp":"2026-08-20T02:00:00.000Z","fields":{"message":"new"},"span":{"name":"session_init"}} {"timestamp":"2026-08-20T02:00:00.125Z","fields":{"message":"close"},"span":{"name":"session_init"}} `)) } func TestCodexAppServerStartupTraceBoundsTheSharedFile(t *testing.T) { path := filepath.Join(t.TempDir(), "trace.jsonl") if err := appendCodexAppServerStartupTrace(path, []byte("first"), 10); err != nil { t.Fatalf("write first trace record: %v", err) } if err := appendCodexAppServerStartupTrace(path, []byte("second"), 10); err != nil { t.Fatalf("write second trace record: %v", err) } data, err := os.ReadFile(path) if err != nil { t.Fatalf("read bounded trace: %v", err) } if string(data) != "second\n" { t.Fatalf("bounded trace = %q, want only the newest record", data) } } func TestWithCodexAppServerLoggingReplacesInheritedLogSettings(t *testing.T) { env := withCodexAppServerLogging([]string{ "log_format=pretty", "rust_log=off", "SESSION_ENV=1", }) if !containsString(env, "SESSION_ENV=1") { t.Fatalf("env = %#v, lost session env", env) } if !containsString(env, codexAppServerLogFormatEnv) || !containsString(env, codexAppServerRustLogEnv) { t.Fatalf("env = %#v, missing managed Codex log settings", env) } if countEnvironmentKeyFold(env, "LOG_FORMAT") != 1 || countEnvironmentKeyFold(env, "RUST_LOG") != 1 { t.Fatalf("env = %#v, expected one managed value per log key", env) } } func splitJSONLines(data []byte) [][]byte { lines := make([][]byte, 0) for len(data) > 0 { index := 0 for index < len(data) && data[index] != '\n' { index++ } line := data[:index] if len(line) > 0 { lines = append(lines, line) } if index == len(data) { break } data = data[index+1:] } return lines } func countEnvironmentKeyFold(env []string, key string) int { count := 0 for _, entry := range env { candidateKey, _, ok := strings.Cut(entry, "=") if ok && strings.EqualFold(candidateKey, key) { count++ } } return count }