logging: tool.call.error/end 接入主 logger (双写终端 + spark-mcp.log)

之前所有 tool 调用的 error 和 end 事件只写进 per-tool 文件 (data/logs/tools/<ts>_<tool>_<id>.log), 主日志文件 spark-mcp.log 完全看不到。tail -f spark-mcp.log 排查问题时形同虚设, 必须去找具体的 per-tool 文件才能看到错误。修复: toolCallLogger struct 加 base *slog.Logger 字段, StartToolCall 把传入的 base 写进 struct. WithError 在记录错误的同时调 base.Error ("tool.call.error", tool, name, err), End 在写完 per-tool 文件后调 base.Info("tool.call.end", tool, name, duration_ms, error). base 走的是 main logger (multiHandler 包装), 自动同时写终端 (遵循 LOG_FORMAT, 默认 text) 和主日志文件 (永远 JSON). LOG_LEVEL 过滤对这两条事件仍生效, 行为统一. 新增 3 个单元测试 (internal/logging/tool_call_test.go): - TestStartToolCall_EmitsErrorAndEnd: 验证错误路径两条事件都进主 logger (用 bytes.Buffer 捕获 slog 输出, 解码 JSON 校验字段) - TestStartToolCall_NilBaseSafe: 验证 base=nil (测试场景) 不 panic 且 per-tool 文件仍写入 - TestStartToolCall_SuccessfulCall_EmitsEndOnly: 验证成功路径只发 end 不发 error, duration_ms >= 0 附带: gofmt 重排 internal/logging/tool_call.go import 块 (按字母序) 未提交: spark-mcp-linux-amd64 (本地 build 产物, .gitignore 未拦, 需另决定); .env (gitignored 内容) Co-Authored-By: Claude <noreply@anthropic.com>
2026-07-13 15:27:28 +08:00
parent 2537976722
commit 9bcfe558cf
2 changed files with 212 additions and 1 deletions
@@ -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