diff --git a/internal/logging/tool_call.go b/internal/logging/tool_call.go index d396736..17d4155 100644 --- a/internal/logging/tool_call.go +++ b/internal/logging/tool_call.go @@ -1,12 +1,12 @@ package logging import ( - "log/slog" "context" "crypto/rand" "encoding/hex" "encoding/json" "fmt" + "log/slog" "os" "path/filepath" "regexp" @@ -41,6 +41,7 @@ func shortHexID(n int) (string, error) { type toolCallLogger struct { file *os.File + base *slog.Logger toolName string startedAt time.Time resultRaw json.RawMessage @@ -54,6 +55,12 @@ func (t *toolCallLogger) WithResult(result any) { func (t *toolCallLogger) WithError(err error) { t.err = err + if t.base != nil && err != nil { + t.base.Error("tool.call.error", + "tool", t.toolName, + "err", err.Error(), + ) + } } func (t *toolCallLogger) End() { @@ -82,6 +89,14 @@ func (t *toolCallLogger) End() { } _, _ = t.file.Write(b) _, _ = t.file.WriteString("\n") + + if t.base != nil { + t.base.Info("tool.call.end", + "tool", t.toolName, + "duration_ms", durationMs, + "error", errStr, + ) + } }) } @@ -145,6 +160,7 @@ func StartToolCall(ctx context.Context, base *slog.Logger, toolName string, para return &toolCallLogger{ file: f, + base: base, toolName: toolName, startedAt: startedAt, }, nil diff --git a/internal/logging/tool_call_test.go b/internal/logging/tool_call_test.go new file mode 100644 index 0000000..1453434 --- /dev/null +++ b/internal/logging/tool_call_test.go @@ -0,0 +1,195 @@ +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