diff --git a/internal/tools/edit_file.go b/internal/tools/edit_file.go index dc70b01da..1c8d54839 100644 --- a/internal/tools/edit_file.go +++ b/internal/tools/edit_file.go @@ -160,7 +160,8 @@ func (tool editFileTool) RunWithOptions(ctx context.Context, args map[string]any // Optional format-on-write (ZERO_FORMAT_ON_WRITE). Must run BEFORE the // FileTracker re-baseline: recording pre-format content would make the very // next edit look like an external modification and trip the conflict guard. - updated = maybeFormatWrittenFile(ctx, absolutePath, updated) + formatting := maybeFormatWrittenFile(ctx, absolutePath, updated) + updated = formatting.Content // Re-baseline to the content we just wrote so subsequent edits in this session // compare against the current on-disk state, not the pre-edit version. newInfo, _ := os.Stat(absolutePath) @@ -193,6 +194,7 @@ func (tool editFileTool) RunWithOptions(ctx context.Context, args map[string]any suffix = "s" } summary := fmt.Sprintf("Successfully edited %s (replaced %d occurrence%s).", relativePath, replacedCount, suffix) + summary += formatting.notice(relativePath) summary += inlineDiagnostics(ctx, options, absolutePath, relativePath) result := okResult(summary) result.ChangedFiles = []string{relativePath} diff --git a/internal/tools/format_on_write.go b/internal/tools/format_on_write.go index cb5bc6159..33bbba952 100644 --- a/internal/tools/format_on_write.go +++ b/internal/tools/format_on_write.go @@ -2,6 +2,7 @@ package tools import ( "context" + "errors" "os" "os/exec" "path/filepath" @@ -22,8 +23,59 @@ import ( // the conflict guard. // formatOnWriteTimeout bounds one formatter run; a wedged formatter must never -// hang a tool call. On timeout the unformatted write stands. -const formatOnWriteTimeout = 10 * time.Second +// hang a tool call. On timeout the unformatted write stands, and the caller +// says so: see formatOnWriteResult. +// +// A var rather than a const so a test can shorten it. Nothing outside a test +// assigns to it, and the deadline path was previously unreachable in a test at +// any speed, which is part of why it went unnoticed that it reported nothing. +var formatOnWriteTimeout = 10 * time.Second + +// formatOnWriteResult is the content after formatting, plus whether the +// formatting that was supposed to happen actually did. +// +// A TIMEOUT IS NOT THE SAME KIND OF MISS AS THE OTHERS. Every other way this +// falls back is a standing fact about the environment: the toggle is off, the +// extension has no formatter, the binary is not installed. Those are silent on +// purpose, because nothing is wrong and saying so on every write would be +// noise. A deadline firing is different: formatting was configured, available +// and expected, and the file was written unformatted anyway, on a machine that +// was merely slow. Left silent, the caller believes it wrote canonical style +// and finds out from a CI format check it cannot see, which is the thing this +// feature exists to prevent. +type formatOnWriteResult struct { + Content string + // Formatter is the binary that was run, named in the notice so the user can + // tell a slow gofmt from a slow prettier. + Formatter string + TimedOut bool + // RestoreFailed means the file on disk is not known to hold Content. + // + // These formatters edit in place, so one that is killed or fails partway + // can leave the target truncated or half-rewritten: what a dead + // `prettier --write` leaves behind is not the input and not the output. + // Returning the written bytes while disk holds something else would put the + // tracker baseline, the diff preview and the file itself into three + // different states, so the failure paths write the bytes back. When even + // that fails the user has to hear about it: it is their file. + RestoreFailed bool +} + +// notice is the line appended to the tool summary when formatting was expected +// and did not happen, and empty in every other case. +func (result formatOnWriteResult) notice(relativePath string) string { + if result.RestoreFailed { + return "\n\nWARNING: " + relativePath + " may not hold what was written. " + + result.Formatter + " was interrupted while rewriting it in place and the " + + "content could not be written back. Re-read the file before trusting it." + } + if !result.TimedOut { + return "" + } + return "\n\nNote: " + relativePath + " was written but not formatted: " + + result.Formatter + " did not finish within " + formatOnWriteTimeout.String() + + ". The file holds exactly what was written, so a project format check may still flag it." +} // formatterCommands maps a file extension to the formatter argv; the file path // is appended as the final argument. Only in-place, config-respecting, @@ -69,18 +121,20 @@ func formatOnWriteEnabled() bool { // enabled and on PATH) and returns the file's content afterwards. Best-effort // throughout: any failure — no formatter, formatter error, timeout, unreadable // result — returns writtenContent so the caller's state matches the last write -// it performed itself. -func maybeFormatWrittenFile(ctx context.Context, absolutePath string, writtenContent string) string { +// it performed itself. Only the timeout is reported back, for the reason on +// formatOnWriteResult. +func maybeFormatWrittenFile(ctx context.Context, absolutePath string, writtenContent string) formatOnWriteResult { + unformatted := formatOnWriteResult{Content: writtenContent} if !formatOnWriteEnabled() { - return writtenContent + return unformatted } command, ok := formatterCommands[strings.ToLower(filepath.Ext(absolutePath))] if !ok { - return writtenContent + return unformatted } binaryPath, err := exec.LookPath(command[0]) if err != nil { - return writtenContent + return unformatted } formatCtx, cancel := context.WithTimeout(ctx, formatOnWriteTimeout) defer cancel() @@ -89,11 +143,35 @@ func maybeFormatWrittenFile(ctx context.Context, absolutePath string, writtenCon formatter.Dir = filepath.Dir(absolutePath) formatter.Stdin = strings.NewReader("") if err := formatter.Run(); err != nil { - return writtenContent + unformatted.Formatter = command[0] + // THE FORMATTER EDITS IN PLACE, SO A FAILED RUN CAN LEAVE THE FILE + // NEITHER FORMATTED NOR AS WRITTEN. Killed by the deadline or by the + // caller, or exiting partway through its own rewrite, the target can hold + // a truncation. Returning the written bytes on top of that would leave the + // tracker baseline and the diff preview describing a file that is not on + // disk, which is a worse failure than the missing formatting: the next + // edit compares against content the file does not have. + // + // Written back unconditionally on this path rather than only when the + // bytes differ. Comparing first means reading the file to find out, and a + // read that fails leaves the same ambiguity this exists to remove. + if restoreErr := os.WriteFile(absolutePath, []byte(writtenContent), 0o644); restoreErr != nil { + unformatted.RestoreFailed = true + } + // OUR deadline, not the caller's cancellation and not the formatter's own + // exit status. A cancelled tool call is already being reported as + // cancelled, and a formatter that ran and refused the file usually means + // content it could not parse, which the write itself does not promise to + // fix. Neither is this notice's business; the restore above is, for all + // three. + if errors.Is(formatCtx.Err(), context.DeadlineExceeded) && ctx.Err() == nil { + unformatted.TimedOut = true + } + return unformatted } formatted, err := os.ReadFile(absolutePath) if err != nil { - return writtenContent + return unformatted } - return string(formatted) + return formatOnWriteResult{Content: string(formatted), Formatter: command[0]} } diff --git a/internal/tools/format_on_write_test.go b/internal/tools/format_on_write_test.go index acca3e868..871de87de 100644 --- a/internal/tools/format_on_write_test.go +++ b/internal/tools/format_on_write_test.go @@ -97,9 +97,12 @@ func TestFormatOnWriteFormatsAndKeepsTrackerConsistent(t *testing.T) { func TestFormatOnWriteSkipsUnknownExtensions(t *testing.T) { t.Setenv("ZERO_FORMAT_ON_WRITE", "1") - content := maybeFormatWrittenFile(context.Background(), filepath.Join(t.TempDir(), "notes.xyz"), "raw text") - if content != "raw text" { - t.Fatalf("unknown extension must pass through: %q", content) + formatting := maybeFormatWrittenFile(context.Background(), filepath.Join(t.TempDir(), "notes.xyz"), "raw text") + if formatting.Content != "raw text" { + t.Fatalf("unknown extension must pass through: %q", formatting.Content) + } + if notice := formatting.notice("notes.xyz"); notice != "" { + t.Fatalf("an extension with no formatter is not a miss worth reporting, got %q", notice) } } @@ -111,8 +114,11 @@ func TestFormatOnWriteFormatterLookupFailure(t *testing.T) { if err := os.WriteFile(targetPath, []byte(uglyContent), 0o644); err != nil { t.Fatal(err) } - content := maybeFormatWrittenFile(context.Background(), targetPath, uglyContent) - if content != uglyContent { - t.Fatalf("missing formatter must return written content, got %q", content) + formatting := maybeFormatWrittenFile(context.Background(), targetPath, uglyContent) + if formatting.Content != uglyContent { + t.Fatalf("missing formatter must return written content, got %q", formatting.Content) + } + if notice := formatting.notice("a.go"); notice != "" { + t.Fatalf("an uninstalled formatter is a standing fact, not a miss worth reporting, got %q", notice) } } diff --git a/internal/tools/format_on_write_timeout_test.go b/internal/tools/format_on_write_timeout_test.go new file mode 100644 index 000000000..b66fbba70 --- /dev/null +++ b/internal/tools/format_on_write_timeout_test.go @@ -0,0 +1,280 @@ +package tools + +import ( + "context" + "os" + "os/exec" + "path/filepath" + "runtime" + "strings" + "testing" + "time" +) + +// A FORMATTER THAT RUNS OUT OF TIME MUST NOT LOOK LIKE ONE THAT SUCCEEDED. +// +// Every other way format-on-write falls back is a standing fact about the +// environment: the toggle is off, the extension has no formatter, the binary is +// not installed. Those are silent because nothing is wrong. A deadline firing is +// different: formatting was configured, available and expected, and the file was +// written unformatted anyway because the machine was slow. Silent, the caller +// believes it wrote canonical style and learns otherwise from a CI format check +// it cannot see, which is the failure this feature exists to prevent. +// +// THE DEADLINE IS SHRUNK RATHER THAN THE FORMATTER SLOWED. A formatter that +// really sleeps has to be killed, and on Windows the batch file that hosts the +// sleep leaves the sleeping grandchild holding the working directory, so the +// test then fails in TempDir cleanup rather than on anything it asserts. An +// expired budget against an ordinary fast formatter reaches the same branch by +// the same route, deterministically and in microseconds. +func TestFormatOnWriteReportsATimeout(t *testing.T) { + formatter := installFakeFormatter(t, ".fastfmt", "fastfmt", succeedingFormatterScript()) + shortenFormatOnWriteTimeout(t, time.Nanosecond) + t.Setenv("ZERO_FORMAT_ON_WRITE", "1") + + target := filepath.Join(t.TempDir(), "subject.fastfmt") + const written = "written but not formatted\n" + if err := os.WriteFile(target, []byte(written), 0o644); err != nil { + t.Fatal(err) + } + + formatting := maybeFormatWrittenFile(context.Background(), target, written) + + if formatting.Content != written { + t.Fatalf("content = %q, want the bytes that were written", formatting.Content) + } + if !formatting.TimedOut { + t.Fatal("a formatter cut off by the deadline was reported as an ordinary miss, so the write claims a formatting that never happened") + } + notice := formatting.notice("subject.fastfmt") + for _, want := range []string{"subject.fastfmt", "not formatted", formatter} { + if !strings.Contains(notice, want) { + t.Errorf("notice %q does not mention %q", notice, want) + } + } +} + +// And the same formatter inside its budget says nothing at all, or the notice +// above would be reporting the deadline rather than the miss. +func TestFormatOnWriteStaysQuietWhenTheFormatterFinishes(t *testing.T) { + installFakeFormatter(t, ".fastfmt", "fastfmt", succeedingFormatterScript()) + t.Setenv("ZERO_FORMAT_ON_WRITE", "1") + + target := filepath.Join(t.TempDir(), "subject.fastfmt") + const written = "written\n" + if err := os.WriteFile(target, []byte(written), 0o644); err != nil { + t.Fatal(err) + } + + formatting := maybeFormatWrittenFile(context.Background(), target, written) + if formatting.TimedOut { + t.Error("a formatter that finished was reported as timed out") + } + if notice := formatting.notice("subject.fastfmt"); notice != "" { + t.Errorf("a successful format produced a notice: %q", notice) + } +} + +// The caller cancelling is not this notice's business: that run is already +// being reported as cancelled, and saying the formatter was too slow on top of +// it would be wrong about why. +func TestFormatOnWriteStaysQuietWhenTheCallerCancels(t *testing.T) { + installFakeFormatter(t, ".fastfmt", "fastfmt", succeedingFormatterScript()) + t.Setenv("ZERO_FORMAT_ON_WRITE", "1") + + target := filepath.Join(t.TempDir(), "subject.fastfmt") + const written = "written\n" + if err := os.WriteFile(target, []byte(written), 0o644); err != nil { + t.Fatal(err) + } + + ctx, cancel := context.WithCancel(context.Background()) + cancel() + formatting := maybeFormatWrittenFile(ctx, target, written) + + if formatting.Content != written { + t.Fatalf("content = %q, want the bytes that were written", formatting.Content) + } + if formatting.TimedOut { + t.Error("a cancelled run was reported as a formatter timeout") + } + if notice := formatting.notice("subject.fastfmt"); notice != "" { + t.Errorf("a cancelled run produced a notice: %q", notice) + } +} + +// A formatter that runs and refuses the file is also not a timeout. It usually +// means content it could not parse, which the write does not promise to fix, +// and reporting it as a slow machine would be wrong about the cause. +func TestFormatOnWriteStaysQuietWhenTheFormatterFails(t *testing.T) { + installFakeFormatter(t, ".failfmt", "failfmt", failingFormatterScript()) + t.Setenv("ZERO_FORMAT_ON_WRITE", "1") + + target := filepath.Join(t.TempDir(), "subject.failfmt") + const written = "unparseable\n" + if err := os.WriteFile(target, []byte(written), 0o644); err != nil { + t.Fatal(err) + } + + formatting := maybeFormatWrittenFile(context.Background(), target, written) + if formatting.TimedOut { + t.Error("a formatter that exited non-zero was reported as a timeout") + } + if notice := formatting.notice("subject.failfmt"); notice != "" { + t.Errorf("a failing formatter produced a timeout notice: %q", notice) + } +} + +// installFakeFormatter puts a formatter on PATH and registers it in the command +// table for the test's duration, returning the binary name the notice carries. +func installFakeFormatter(t *testing.T, extension, name, script string) string { + t.Helper() + binaryName := name + formatterScriptExtension() + directory := t.TempDir() + if err := os.WriteFile(filepath.Join(directory, binaryName), []byte(script), 0o755); err != nil { + t.Fatal(err) + } + t.Setenv("PATH", directory+string(os.PathListSeparator)+os.Getenv("PATH")) + + previous, existed := formatterCommands[extension] + formatterCommands[extension] = []string{binaryName} + t.Cleanup(func() { + if existed { + formatterCommands[extension] = previous + return + } + delete(formatterCommands, extension) + }) + return binaryName +} + +func formatterScriptExtension() string { + if runtime.GOOS == "windows" { + return ".bat" + } + return "" +} + +func succeedingFormatterScript() string { + if runtime.GOOS == "windows" { + return "@echo off\r\nexit /b 0\r\n" + } + return "#!/bin/sh\nexit 0\n" +} + +func failingFormatterScript() string { + if runtime.GOOS == "windows" { + return "@echo off\r\nexit /b 3\r\n" + } + return "#!/bin/sh\nexit 3\n" +} + +// shortenFormatOnWriteTimeout narrows the production deadline for one test. +func shortenFormatOnWriteTimeout(t *testing.T, timeout time.Duration) { + t.Helper() + previous := formatOnWriteTimeout + formatOnWriteTimeout = timeout + t.Cleanup(func() { formatOnWriteTimeout = previous }) +} + +// A FAILED FORMATTER MUST NOT LEAVE THE FILE HALF-REWRITTEN. +// +// These commands edit in place, so one killed by the deadline, killed by the +// caller, or exiting partway through its own rewrite can leave the target +// truncated: neither the input nor the output. Returning the written bytes on +// top of that would leave the tracker baseline and the diff preview describing +// a file that is not on disk, and the next edit would compare against content +// the file does not have. +func TestFormatOnWriteRestoresTheFileWhenTheFormatterFails(t *testing.T) { + installFakeFormatter(t, ".clobberfmt", "clobberfmt", clobberingFormatterScript()) + t.Setenv("ZERO_FORMAT_ON_WRITE", "1") + + target := filepath.Join(t.TempDir(), "subject.clobberfmt") + const written = "the bytes the caller wrote\n" + if err := os.WriteFile(target, []byte(written), 0o644); err != nil { + t.Fatal(err) + } + requireFormatterClobbers(t, written) + + formatting := maybeFormatWrittenFile(context.Background(), target, written) + + onDisk, err := os.ReadFile(target) + if err != nil { + t.Fatal(err) + } + if string(onDisk) != written { + t.Errorf("file on disk = %q, want the bytes that were written back", onDisk) + } + if formatting.Content != written { + t.Errorf("content = %q, want the bytes that were written", formatting.Content) + } + if formatting.RestoreFailed { + t.Error("restoration was reported as failed on a writable file") + } +} + +// And the same for a run cut off by the deadline, which is the case the notice +// already covers: the disclosure and the file have to agree. +func TestFormatOnWriteRestoresTheFileOnTimeout(t *testing.T) { + installFakeFormatter(t, ".clobberfmt", "clobberfmt", clobberingFormatterScript()) + shortenFormatOnWriteTimeout(t, time.Nanosecond) + t.Setenv("ZERO_FORMAT_ON_WRITE", "1") + + target := filepath.Join(t.TempDir(), "subject.clobberfmt") + const written = "the bytes the caller wrote\n" + if err := os.WriteFile(target, []byte(written), 0o644); err != nil { + t.Fatal(err) + } + requireFormatterClobbers(t, written) + + formatting := maybeFormatWrittenFile(context.Background(), target, written) + + onDisk, err := os.ReadFile(target) + if err != nil { + t.Fatal(err) + } + if string(onDisk) != written { + t.Errorf("file on disk = %q, want the bytes that were written back", onDisk) + } + if !formatting.TimedOut { + t.Error("the deadline path stopped being reported once restoration was added") + } + if notice := formatting.notice("subject.clobberfmt"); !strings.Contains(notice, "not formatted") { + t.Errorf("notice = %q, want the timeout note", notice) + } +} + +// clobberingFormatterScript truncates the file it is handed and then fails, the +// way an interrupted in-place formatter leaves a partial rewrite. +func clobberingFormatterScript() string { + if runtime.GOOS == "windows" { + return "@echo off\r\necho CLOBBERED> %1\r\nexit /b 3\r\n" + } + return "#!/bin/sh\necho CLOBBERED > \"$1\"\nexit 3\n" +} + +// requireFormatterClobbers proves the fixture really does damage the file it is +// handed, on a throwaway copy. +// +// It cannot be checked on the real target: restoration is the behaviour under +// test, so when it works the evidence is gone, and asserting on the target +// afterwards would either pass vacuously or report the opposite of what it saw. +func requireFormatterClobbers(t *testing.T, written string) { + t.Helper() + probe := filepath.Join(t.TempDir(), "probe.clobberfmt") + if err := os.WriteFile(probe, []byte(written), 0o644); err != nil { + t.Fatal(err) + } + binary, err := exec.LookPath("clobberfmt" + formatterScriptExtension()) + if err != nil { + t.Fatalf("SETUP INVALID: the fake formatter is not on PATH: %v", err) + } + _ = exec.Command(binary, probe).Run() + after, err := os.ReadFile(probe) + if err != nil { + t.Fatal(err) + } + if !strings.Contains(string(after), "CLOBBERED") { + t.Fatalf("SETUP INVALID: the fake formatter left %q, so it does not damage the file and restoration is not under test", after) + } +} diff --git a/internal/tools/write_file.go b/internal/tools/write_file.go index 76f5f1baa..ab303eb68 100644 --- a/internal/tools/write_file.go +++ b/internal/tools/write_file.go @@ -114,7 +114,8 @@ func (tool writeFileTool) RunWithOptions(ctx context.Context, args map[string]an // Optional format-on-write (ZERO_FORMAT_ON_WRITE). Must run BEFORE the // FileTracker baseline: recording pre-format content would make the very // next edit look like an external modification and trip the conflict guard. - content = maybeFormatWrittenFile(ctx, absolutePath, content) + formatting := maybeFormatWrittenFile(ctx, absolutePath, content) + content = formatting.Content // Baseline the freshly written content so a later edit/overwrite in this // session compares against what is now on disk. newInfo, _ := os.Stat(absolutePath) @@ -137,6 +138,7 @@ func (tool writeFileTool) RunWithOptions(ctx context.Context, args map[string]an lines++ } summary := fmt.Sprintf("%s %s (%d lines).", verb, relativePath, lines) + summary += formatting.notice(relativePath) summary += inlineDiagnostics(ctx, options, absolutePath, relativePath) result := okResult(summary) result.ChangedFiles = []string{relativePath}