package logging import ( "bytes" "context" "encoding/json" "log/slog" "os" "path/filepath" "strings" "testing" "time" ) // newCapturingLogger returns a slog.Logger that writes JSON to buf and a // pointer to buf so tests can assert on what was emitted. func newCapturingLogger() (*slog.Logger, *bytes.Buffer) { buf := &bytes.Buffer{} return slog.New(slog.NewJSONHandler(buf, &slog.HandlerOptions{Level: slog.LevelDebug})), buf } // initLogDir sets the package-level logDir for StartToolCall to discover. // Tests run in a temp directory; tear down via t.Cleanup. func initLogDir(t *testing.T) string { t.Helper() dir := t.TempDir() logDirMu.Lock() prev := logDir logDir = dir logDirMu.Unlock() t.Cleanup(func() { logDirMu.Lock() logDir = prev logDirMu.Unlock() }) return dir } // TestStartToolCall_EmitsErrorAndEnd verifies that WithError and End each // emit a structured event through the main base logger, in addition to // writing the per-tool file. This is what makes "tail -f spark-mcp.log" // useful for debugging tool-call failures. func TestStartToolCall_EmitsErrorAndEnd(t *testing.T) { dir := initLogDir(t) base, buf := newCapturingLogger() cl, err := StartToolCall(context.Background(), base, "list_applications", map[string]any{"cluster_id": "x"}) if err != nil { t.Fatalf("StartToolCall: %v", err) } if cl == nil { t.Fatal("nil logger") } cl.WithError(os.ErrNotExist) cl.End() // Per-tool file is still written (regression check). entries, err := os.ReadDir(filepath.Join(dir, "tools")) if err != nil { t.Fatalf("read tools dir: %v", err) } if len(entries) == 0 { t.Fatalf("no per-tool log file written") } // Decode each JSON line in the captured buffer. var sawError, sawEnd bool for line := range strings.SplitSeq(strings.TrimSpace(buf.String()), "\n") { if line == "" { continue } var rec map[string]any if err := json.Unmarshal([]byte(line), &rec); err != nil { t.Fatalf("invalid JSON in log: %q (err=%v)", line, err) } switch rec["msg"] { case "tool.call.error": sawError = true if rec["level"] != "ERROR" { t.Errorf("tool.call.error level=%v, want ERROR", rec["level"]) } if rec["tool"] != "list_applications" { t.Errorf("tool.call.error tool=%v, want list_applications", rec["tool"]) } if !strings.Contains(rec["err"].(string), "file does not exist") { t.Errorf("tool.call.error err=%v, missing underlying err text", rec["err"]) } case "tool.call.end": sawEnd = true if rec["level"] != "INFO" { t.Errorf("tool.call.end level=%v, want INFO", rec["level"]) } if rec["tool"] != "list_applications" { t.Errorf("tool.call.end tool=%v, want list_applications", rec["tool"]) } if _, ok := rec["duration_ms"].(float64); !ok { t.Errorf("tool.call.end missing numeric duration_ms: %v", rec) } if rec["error"] != "file does not exist" { t.Errorf("tool.call.end error=%v, want file does not exist", rec["error"]) } } } if !sawError { t.Errorf("expected tool.call.error in main logger; got: %s", buf.String()) } if !sawEnd { t.Errorf("expected tool.call.end in main logger; got: %s", buf.String()) } } // TestStartToolCall_NilBaseSafe verifies the noop-friendly path: if base is // nil (e.g. tests where deps.Logger is unset), WithError and End must not // panic and the per-tool file must still be written. func TestStartToolCall_NilBaseSafe(t *testing.T) { dir := initLogDir(t) cl, err := StartToolCall(context.Background(), nil, "noop_tool", map[string]any{"k": "v"}) if err != nil { t.Fatalf("StartToolCall: %v", err) } // Should not panic. cl.WithError(os.ErrPermission) cl.End() // Per-tool file still written. entries, err := os.ReadDir(filepath.Join(dir, "tools")) if err != nil { t.Fatalf("read tools dir: %v", err) } if len(entries) == 0 { t.Errorf("expected per-tool file even with nil base") } } // TestStartToolCall_SuccessfulCall_EmitsEndOnly verifies that a happy-path // call emits exactly one end event (no error event), with an empty error // string and a non-negative duration. func TestStartToolCall_SuccessfulCall_EmitsEndOnly(t *testing.T) { _ = initLogDir(t) base, buf := newCapturingLogger() cl, err := StartToolCall(context.Background(), base, "list_clusters", nil) if err != nil { t.Fatalf("StartToolCall: %v", err) } cl.End() lines := strings.SplitSeq(strings.TrimSpace(buf.String()), "\n") // Exactly one event: tool.call.start (from StartToolCall itself). // No tool.call.error, and one tool.call.end. var endCount, errorCount int for line := range lines { if line == "" { continue } var rec map[string]any if err := json.Unmarshal([]byte(line), &rec); err != nil { t.Fatalf("invalid JSON: %q", line) } switch rec["msg"] { case "tool.call.end": endCount++ if rec["error"] != "" { t.Errorf("successful end should have empty error; got %v", rec["error"]) } case "tool.call.error": errorCount++ } } if errorCount != 0 { t.Errorf("expected 0 tool.call.error, got %d; buf=%s", errorCount, buf.String()) } if endCount != 1 { t.Errorf("expected exactly 1 tool.call.end, got %d; buf=%s", endCount, buf.String()) } // Sanity: duration_ms is non-negative. for line := range lines { var rec map[string]any if err := json.Unmarshal([]byte(line), &rec); err == nil { if msg, _ := rec["msg"].(string); msg == "tool.call.end" { if d, ok := rec["duration_ms"].(float64); !ok || d < 0 { t.Errorf("duration_ms invalid: %v", rec["duration_ms"]) } } } } } // ensure time is referenced even if no test uses it directly (avoids unused // import churn when tests are edited). var _ = time.Now