diff --git a/cli/dispatcher/internal/dispatcher/compile_check.go b/cli/dispatcher/internal/dispatcher/compile_check.go index 9b9b791da..ee88cd659 100644 --- a/cli/dispatcher/internal/dispatcher/compile_check.go +++ b/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 { diff --git a/cli/dispatcher/internal/dispatcher/compile_check_vibe_log.go b/cli/dispatcher/internal/dispatcher/compile_check_vibe_log.go new file mode 100644 index 000000000..df2eb49ee --- /dev/null +++ b/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 +} diff --git a/cli/dispatcher/internal/dispatcher/compile_check_vibe_log_test.go b/cli/dispatcher/internal/dispatcher/compile_check_vibe_log_test.go new file mode 100644 index 000000000..7c96caeb8 --- /dev/null +++ b/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"`) +} diff --git a/docs/compile-check.md b/docs/compile-check.md index 31e77675e..49bcc733d 100644 --- a/docs/compile-check.md +++ b/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` diff --git a/docs/vibe-logs.md b/docs/vibe-logs.md index 2cd813563..6f34ec177 100644 --- a/docs/vibe-logs.md +++ b/docs/vibe-logs.md @@ -222,8 +222,9 @@ command ran against: - A missing line is evidence only when the define was set and the code path logs at all. Coverage is per call site, not per command: for example, `execute-dynamic-code`, `simulate-keyboard`, `screenshot`, compile, domain reload, server binding, and hot reload log - start and completion, while the CLI side logs compile requests, window focus, and the tool - requests described under "CLI entries for tool commands" below. + start and completion, while the CLI side logs compile requests, window focus, the tool + requests described under "CLI entries for tool commands" below, and `compile-check` runs + ("CLI entries for compile-check"). Check that the operation you expect is logged somewhere (`git grep` the operation name) before reading its absence as "it never ran". @@ -270,6 +271,21 @@ or `control-play-mode` that waits for a domain reload or a Play Mode change, and - The `cli_tool_*` entries of one command share one `correlation_id`, and the two `cli_hot_reload_*` entries share another. Pair the two groups by time. +## CLI entries for compile-check + +`compile-check` never talks to the Editor, so these two entries are the only record of what a run +did. Both carry the same `correlation_id`. A run that cannot find its project writes neither, +because there is no project to write into. + +| `operation` | Written | `context` | +|---|---|---| +| `cli_compile_check_start` | once the project is found | `command`, `all`, `full`, `jobs`, `project_identity` | +| `cli_compile_check_complete` (`INFO`; `WARNING` when the run found compile errors; `ERROR` when it could not finish) | on every way out of a run that wrote the start entry | `command`, `outcome` (`succeeded`, `errors`, or `failed`), `duration_ms`; for `failed`, `error` and `error_code`; otherwise `error_count`, `warning_count`, `compiled`, `reused`, `fast_checked`, `blocked` (assembly names, as in the response), `skipped_count`, `fast_checks` (`assembly`, `reused`, `changed_file_count`), `fallbacks` and `baseline_notes` (`assembly`, `reason`), and `units` (`assembly`, `duration_ms`, `succeeded` of each assembly the run compiled or checked; replayed ones are left out) | + +- Unlike the tool-command entries, the complete entry holds the run's error message and fallback + reasons: they can name assemblies and files of the project, which the command's own output prints + as well. + ## How to use them in an investigation 1. Find the time window from the report or the command output, then open the matching