feat: compile-check writes what each run did to the CLI VibeLog

cli/dispatcher/internal/dispatcher/compile_check.go

@@ -138,9 +138,11 @@ func runCompileCheck(
 			stderr, err, clierrors.ErrorContext{Command: clicore.CompileCheckCommandName})
 		return 1
 	}
+	logRun := startCompileCheckVibeLog(projectRoot, options)
 
 	editorPath, err := resolveCompileCheckEditorPath(projectRoot, options)
 	if err != nil {
+		logRun.failed(err)
 		clierrors.WriteClassifiedError(stderr, err, clierrors.ErrorContext{
 			Command: clicore.CompileCheckCommandName, ProjectRoot: projectRoot,
 		})
@@ -149,6 +151,7 @@ func runCompileCheck(
 
 	result, err := compilecheck.Run(ctx, newCompileCheckRunOptions(options, projectRoot, editorPath))
 	if err != nil {
+		logRun.failed(err)
 		clierrors.WriteClassifiedError(stderr, err, clierrors.ErrorContext{
 			Command: clicore.CompileCheckCommandName, ProjectRoot: projectRoot,
 		})
@@ -158,11 +161,13 @@ func runCompileCheck(
 	response := buildCompileCheckResponse(result, projectRoot)
 	encoded, err := json.Marshal(response)
 	if err != nil {
+		logRun.failed(err)
 		clierrors.WriteClassifiedError(stderr, err, clierrors.ErrorContext{
 			Command: clicore.CompileCheckCommandName, ProjectRoot: projectRoot,
 		})
 		return 1
 	}
+	logRun.completed(response, result)
 	clicore.WriteJSON(stdout, encoded)
 
 	if response.ErrorCount > 0 {

cli/dispatcher/internal/dispatcher/compile_check_vibe_log.go

@@ -0,0 +1,155 @@
+package dispatcher
+
+import (
+	"time"
+
+	"github.com/hatayama/unity-cli-loop/common/clicore"
+	clierrors "github.com/hatayama/unity-cli-loop/common/errors"
+	"github.com/hatayama/unity-cli-loop/common/vibelog"
+	"github.com/hatayama/unity-cli-loop/dispatcher/internal/compilecheck"
+)
+
+const (
+	compileCheckVibeStartOperation    = "cli_compile_check_start"
+	compileCheckVibeCompleteOperation = "cli_compile_check_complete"
+)
+
+// compileCheckVibeLog writes what one compile-check run did to the CLI VibeLog: a start entry, and a
+// complete entry under the same correlation id on every way out of the run.
+// Why compile-check needs its own entries: it never talks to the Editor, so nothing on the Editor
+// side records which runs compiled, which were checked on their changed files, and why.
+type compileCheckVibeLog struct {
+	enabled       bool
+	projectRoot   string
+	correlationID string
+	startedAt     time.Time
+}
+
+// startCompileCheckVibeLog writes the start entry of a run and returns what writes its complete
+// entry. With ULOOP_DEBUG unset it writes nothing and builds no context.
+func startCompileCheckVibeLog(projectRoot string, options compileCheckOptions) compileCheckVibeLog {
+	if !vibelog.IsCLIVibeLogEnabled() {
+		return compileCheckVibeLog{}
+	}
+
+	logRun := compileCheckVibeLog{
+		enabled:       true,
+		projectRoot:   projectRoot,
+		correlationID: vibelog.NewCLIVibeCorrelationID(),
+		startedAt:     time.Now(),
+	}
+	logRun.write("INFO", compileCheckVibeStartOperation, "Starting compile-check.", map[string]any{
+		"command":          clicore.CompileCheckCommandName,
+		"all":              options.all,
+		"full":             options.full,
+		"jobs":             options.jobs,
+		"project_identity": vibelog.ProjectIdentity(projectRoot),
+	})
+
+	return logRun
+}
+
+// failed writes the complete entry of a run that stopped before it had a response to print.
+func (logRun compileCheckVibeLog) failed(err error) {
+	if !logRun.enabled {
+		return
+	}
+
+	context := logRun.completeContext("failed")
+	context["error"] = clicore.ErrorMessage(err)
+	context["error_code"] = clierrors.ClassifyError(err, clierrors.ErrorContext{
+		Command: clicore.CompileCheckCommandName, ProjectRoot: logRun.projectRoot,
+	}).ErrorCode
+	logRun.write("ERROR", compileCheckVibeCompleteOperation, "compile-check failed.", context)
+}
+
+// completed writes the complete entry of a run that produced a response, with the response's own
+// lists so the log and the printed JSON can be read side by side.
+func (logRun compileCheckVibeLog) completed(response compileCheckResponse, result compilecheck.Result) {
+	if !logRun.enabled {
+		return
+	}
+
+	level, outcome := "INFO", "succeeded"
+	if response.ErrorCount > 0 {
+		level, outcome = "WARNING", "errors"
+	}
+	context := logRun.completeContext(outcome)
+	context["error_count"] = response.ErrorCount
+	context["warning_count"] = response.WarningCount
+	context["compiled"] = response.CompiledAssemblies
+	context["reused"] = response.ReusedAssemblies
+	context["fast_checked"] = response.FastCheckedAssemblies
+	context["blocked"] = response.BlockedAssemblies
+	context["skipped_count"] = response.SkippedAssemblies
+	context["fast_checks"] = compileCheckVibeFastChecks(response.FastChecks)
+	context["fallbacks"] = compileCheckVibeReasons(response.FastPathFallbacks)
+	context["baseline_notes"] = compileCheckVibeReasons(response.FastPathBaselineNotes)
+	context["units"] = compileCheckVibeUnits(result.Units)
+	logRun.write(level, compileCheckVibeCompleteOperation, "compile-check finished.", context)
+}
+
+// completeContext holds the fields every complete entry carries.
+func (logRun compileCheckVibeLog) completeContext(outcome string) map[string]any {
+	return map[string]any{
+		"command":     clicore.CompileCheckCommandName,
+		"outcome":     outcome,
+		"duration_ms": time.Since(logRun.startedAt).Milliseconds(),
+	}
+}
+
+// write appends one entry of this run.
+// Why a failed write is ignored: the log is a diagnostic aid, and a run must not fail for it.
+func (logRun compileCheckVibeLog) write(level string, operation string, message string, context map[string]any) {
+	_ = vibelog.WriteCLIVibeLog(logRun.projectRoot, vibelog.CLIVibeLogEntry{
+		Level:         level,
+		Operation:     operation,
+		Message:       message,
+		Context:       context,
+		CorrelationID: logRun.correlationID,
+	})
+}
+
+// compileCheckVibeFastChecks lists each fast check by assembly, whether it was replayed, and how
+// many files it covered.
+func compileCheckVibeFastChecks(checks []compileCheckFastCheck) []map[string]any {
+	entries := make([]map[string]any, 0, len(checks))
+	for _, check := range checks {
+		entries = append(entries, map[string]any{
+			"assembly":           check.Assembly,
+			"reused":             check.Reused,
+			"changed_file_count": len(check.ChangedFiles),
+		})
+	}
+
+	return entries
+}
+
+// compileCheckVibeReasons lists one reason per assembly.
+func compileCheckVibeReasons(reasons []compileCheckFastPathFallback) []map[string]any {
+	entries := make([]map[string]any, 0, len(reasons))
+	for _, reason := range reasons {
+		entries = append(entries, map[string]any{"assembly": reason.Assembly, "reason": reason.Reason})
+	}
+
+	return entries
+}
+
+// compileCheckVibeUnits lists how long each unit this run compiled or checked took.
+// Why replayed units are left out: they took no work, and their durations would only hide which
+// units the run spent its time on.
+func compileCheckVibeUnits(units []compilecheck.UnitResult) []map[string]any {
+	entries := make([]map[string]any, 0, len(units))
+	for _, unit := range units {
+		if unit.Reused || unit.FastCheckReused {
+			continue
+		}
+		entries = append(entries, map[string]any{
+			"assembly":    unit.Assembly,
+			"duration_ms": unit.Duration.Milliseconds(),
+			"succeeded":   unit.Succeeded,
+		})
+	}
+
+	return entries
+}

cli/dispatcher/internal/dispatcher/compile_check_vibe_log_test.go

@@ -0,0 +1,196 @@
+package dispatcher
+
+import (
+	"bufio"
+	"bytes"
+	"context"
+	"encoding/json"
+	"errors"
+	"os"
+	"path/filepath"
+	"testing"
+	"time"
+
+	clierrors "github.com/hatayama/unity-cli-loop/common/errors"
+	"github.com/hatayama/unity-cli-loop/common/vibelog"
+	"github.com/hatayama/unity-cli-loop/dispatcher/internal/compilecheck"
+)
+
+// readCompileCheckVibeLog reads every entry today's CLI VibeLog of the project holds, in order.
+func readCompileCheckVibeLog(t *testing.T, projectRoot string) []vibelog.CLIVibeLogEntry {
+	t.Helper()
+	path := filepath.Join(projectRoot, vibelog.CLIVibeLogDirectory,
+		vibelog.CLIVibeLogPrefix+"_"+time.Now().UTC().Format("20060102")+".json")
+	content, err := os.ReadFile(path)
+	if err != nil {
+		t.Fatalf("failed to read the CLI VibeLog: %v", err)
+	}
+
+	entries := []vibelog.CLIVibeLogEntry{}
+	scanner := bufio.NewScanner(bytes.NewReader(content))
+	scanner.Buffer(make([]byte, 0, 64*1024), 1024*1024)
+	for scanner.Scan() {
+		var entry vibelog.CLIVibeLogEntry
+		if err := json.Unmarshal(scanner.Bytes(), &entry); err != nil {
+			t.Fatalf("failed to parse a CLI VibeLog line %q: %v", scanner.Text(), err)
+		}
+		entries = append(entries, entry)
+	}
+
+	return entries
+}
+
+// assertCompileCheckVibeRun checks the log holds exactly one start and one complete of the same run,
+// and returns the complete entry.
+func assertCompileCheckVibeRun(t *testing.T, entries []vibelog.CLIVibeLogEntry) vibelog.CLIVibeLogEntry {
+	t.Helper()
+	if len(entries) != 2 {
+		t.Fatalf("expected a start and a complete entry, got %+v", entries)
+	}
+	start, complete := entries[0], entries[1]
+	if start.Operation != "cli_compile_check_start" || complete.Operation != "cli_compile_check_complete" {
+		t.Fatalf("operations = %q, %q", start.Operation, complete.Operation)
+	}
+	if start.CorrelationID == "" || start.CorrelationID != complete.CorrelationID {
+		t.Errorf("correlation ids = %q, %q, want one shared id", start.CorrelationID, complete.CorrelationID)
+	}
+
+	return complete
+}
+
+// assertVibeContextJSON checks one context field serializes to the given JSON.
+func assertVibeContextJSON(t *testing.T, entry vibelog.CLIVibeLogEntry, key string, want string) {
+	t.Helper()
+	encoded, err := json.Marshal(entry.Context[key])
+	if err != nil {
+		t.Fatalf("failed to encode %s: %v", key, err)
+	}
+	if string(encoded) != want {
+		t.Errorf("%s = %s, want %s", key, encoded, want)
+	}
+}
+
+// loggedCompileCheckResult is a run that compiled, fast-checked, replayed a fast check of, reused,
+// and blocked one assembly each, so a field the log drops or mixes up shows.
+func loggedCompileCheckResult() compilecheck.Result {
+	return compilecheck.Result{
+		DagDir:  "Library/Bee/artifacts/1300b0aE.dag",
+		Skipped: 3,
+		Blocked: []string{"Delta"},
+		Units: []compilecheck.UnitResult{
+			{
+				Assembly: "Alpha", Succeeded: true, Duration: 1500 * time.Millisecond,
+				FastPathFallbackReason: "no baseline: no full compile of this assembly is on record",
+				FastPathNote:           "baseline not recorded: source changed during the compile: Assets/A.cs",
+			},
+			{
+				Assembly: "Beta", Succeeded: true, Duration: 250 * time.Millisecond, FastChecked: true,
+				FastCheckChangedFiles: []string{"Assets/B1.cs", "Assets/B2.cs"},
+			},
+			{
+				Assembly: "Epsilon", Succeeded: true, FastChecked: true, FastCheckReused: true,
+				FastCheckChangedFiles: []string{"Assets/E.cs"},
+			},
+			{Assembly: "Gamma", Succeeded: true, Reused: true},
+		},
+	}
+}
+
+// Verifies a run writes a start and a complete entry with one correlation id, and the complete
+// entry carries what the response reported and how long each compiled or checked unit took.
+func TestCompileCheckVibeLogRecordsASucceededRun(t *testing.T) {
+	t.Setenv(vibelog.CLIVibeLogEnvName, "1")
+	projectRoot := t.TempDir()
+	result := loggedCompileCheckResult()
+
+	logRun := startCompileCheckVibeLog(projectRoot, compileCheckOptions{all: true, jobs: 4})
+	logRun.completed(buildCompileCheckResponse(result, projectRoot), result)
+
+	entries := readCompileCheckVibeLog(t, projectRoot)
+	complete := assertCompileCheckVibeRun(t, entries)
+	assertVibeContextJSON(t, entries[0], "all", "true")
+	assertVibeContextJSON(t, entries[0], "full", "false")
+	assertVibeContextJSON(t, entries[0], "jobs", "4")
+	assertVibeContextJSON(t, entries[0], "project_identity", `"`+vibelog.ProjectIdentity(projectRoot)+`"`)
+	if complete.Level != "INFO" {
+		t.Errorf("level = %q, want INFO", complete.Level)
+	}
+	assertVibeContextJSON(t, complete, "outcome", `"succeeded"`)
+	assertVibeContextJSON(t, complete, "error_count", "0")
+	assertVibeContextJSON(t, complete, "compiled", `["Alpha"]`)
+	assertVibeContextJSON(t, complete, "fast_checked", `["Beta","Epsilon"]`)
+	assertVibeContextJSON(t, complete, "reused", `["Gamma"]`)
+	assertVibeContextJSON(t, complete, "blocked", `["Delta"]`)
+	assertVibeContextJSON(t, complete, "skipped_count", "3")
+	assertVibeContextJSON(t, complete, "fast_checks", `[{"assembly":"Beta","changed_file_count":2,"reused":false},`+
+		`{"assembly":"Epsilon","changed_file_count":1,"reused":true}]`)
+	assertVibeContextJSON(t, complete, "fallbacks",
+		`[{"assembly":"Alpha","reason":"no baseline: no full compile of this assembly is on record"}]`)
+	assertVibeContextJSON(t, complete, "baseline_notes",
+		`[{"assembly":"Alpha","reason":"baseline not recorded: source changed during the compile: Assets/A.cs"}]`)
+	assertVibeContextJSON(t, complete, "units",
+		`[{"assembly":"Alpha","duration_ms":1500,"succeeded":true},{"assembly":"Beta","duration_ms":250,"succeeded":true}]`)
+	if _, found := complete.Context["duration_ms"]; !found {
+		t.Error("expected the run's duration to be logged")
+	}
+}
+
+// Verifies a run that found compile errors is logged as a warning with the errors counted.
+func TestCompileCheckVibeLogRecordsARunWithErrors(t *testing.T) {
+	t.Setenv(vibelog.CLIVibeLogEnvName, "1")
+	projectRoot := t.TempDir()
+	result := compilecheck.Result{Units: []compilecheck.UnitResult{{
+		Assembly: "Alpha", Diagnostics: []compilecheck.Diagnostic{
+			{Severity: "error", Code: "CS0103", Message: "missing", File: "Assets/A.cs", Line: 1, Column: 1},
+			{Severity: "error", Code: "CS0029", Message: "cannot convert", File: "Assets/A.cs", Line: 2, Column: 1},
+		},
+	}}}
+
+	logRun := startCompileCheckVibeLog(projectRoot, compileCheckOptions{})
+	logRun.completed(buildCompileCheckResponse(result, projectRoot), result)
+
+	complete := assertCompileCheckVibeRun(t, readCompileCheckVibeLog(t, projectRoot))
+	if complete.Level != "WARNING" {
+		t.Errorf("level = %q, want WARNING", complete.Level)
+	}
+	assertVibeContextJSON(t, complete, "outcome", `"errors"`)
+	assertVibeContextJSON(t, complete, "error_count", "2")
+}
+
+// Verifies a run that could not finish is logged as an error with what stopped it.
+func TestCompileCheckVibeLogRecordsAFailedRun(t *testing.T) {
+	t.Setenv(vibelog.CLIVibeLogEnvName, "1")
+	projectRoot := t.TempDir()
+
+	logRun := startCompileCheckVibeLog(projectRoot, compileCheckOptions{})
+	logRun.failed(errors.New("no Bee build found"))
+
+	complete := assertCompileCheckVibeRun(t, readCompileCheckVibeLog(t, projectRoot))
+	if complete.Level != "ERROR" {
+		t.Errorf("level = %q, want ERROR", complete.Level)
+	}
+	assertVibeContextJSON(t, complete, "outcome", `"failed"`)
+	assertVibeContextJSON(t, complete, "error", `"no Bee build found"`)
+	wantCode := clierrors.ClassifyError(errors.New("no Bee build found"), clierrors.ErrorContext{}).ErrorCode
+	assertVibeContextJSON(t, complete, "error_code", `"`+wantCode+`"`)
+}
+
+// Verifies runCompileCheck logs the run that stopped because the project's Editor is not
+// installed, as a start and a failed complete of the same run.
+func TestCompileCheckVibeLogRecordsAnEditorResolutionFailure(t *testing.T) {
+	t.Setenv(vibelog.CLIVibeLogEnvName, "1")
+	isolateCompileCheckEditorLookup(t)
+	projectRoot := createDispatcherUnityProject(t)
+	writeDispatcherTestFile(t, filepath.Join(projectRoot, projectVersionFilePath),
+		"m_EditorVersion: "+bogusCompileCheckEditorVersion+"\n")
+	var stdout bytes.Buffer
+	var stderr bytes.Buffer
+
+	code := runCompileCheck(context.Background(), compileCheckOptions{projectPath: projectRoot}, projectRoot, &stdout, &stderr)
+
+	if code != 1 {
+		t.Fatalf("code = %d, want 1", code)
+	}
+	complete := assertCompileCheckVibeRun(t, readCompileCheckVibeLog(t, projectRoot))
+	assertVibeContextJSON(t, complete, "outcome", `"failed"`)
+}

docs/compile-check.md

@@ -260,6 +260,11 @@ gives the `Assembly` and `Reason` of each successful full compile that left no b
 process exits 1 when
 `ErrorCount` is greater than zero.
 
+With the `ULOOP_DEBUG` environment variable set, each run also writes two entries to the CLI
+VibeLog of the project, `cli_compile_check_start` and `cli_compile_check_complete`, with which
+assemblies it compiled, reused, checked on their changed files, or blocked, why each fallback
+happened, and how long each assembly took. `docs/vibe-logs.md` lists their fields.
+
 ## Limitations
 
 - **It replays the last Unity build, and only some staleness is detectable.** Four `.asmdef`