diff --git a/modules/bonfire/live.go b/modules/bonfire/live.go index d220e80c..f69bfe65 100644 --- a/modules/bonfire/live.go +++ b/modules/bonfire/live.go @@ -46,10 +46,18 @@ type ( } // finishMsg ends a live view; err is the result of the work. finishMsg struct{ err error } - // printAboveMsg is a line to print above the view. - printAboveMsg string ) +// printLine is the message that prints s, one or more lines, above the +// running view. It is bubbletea's own Println message, sent straight to +// the program's queue: the event loop prints it itself, in the order the +// messages arrive. Returning tea.Println as a command instead would run +// it on a goroutine of its own, so lines would race each other and a line +// still in flight when the view quits would be lost. +func printLine(s string) tea.Msg { + return tea.Println(s)() +} + // itemState is the display state of one item in the process view. type itemState int @@ -306,24 +314,6 @@ func (m processModel) View() tea.View { return tea.NewView(b.String()) } -// liveModel wraps a view so lines from PrintAbove print above it. -type liveModel struct { - inner tea.Model -} - -func (m liveModel) Init() tea.Cmd { return m.inner.Init() } - -func (m liveModel) Update(msg tea.Msg) (tea.Model, tea.Cmd) { - if line, ok := msg.(printAboveMsg); ok { - return m, tea.Println(string(line)) - } - inner, cmd := m.inner.Update(msg) - m.inner = inner - return m, cmd -} - -func (m liveModel) View() tea.View { return m.inner.View() } - // The running live program, for PrintAbove. Only one live view runs at a // time; widgets started while one runs print plain lines. var ( @@ -341,12 +331,13 @@ func liveActive() bool { // runLive runs model as a bubbletea program on out while work runs on the // calling goroutine. work gets a send function for progress messages. When // work returns, the program is unregistered (so PrintAbove stops sending to -// it), told to finish and waited for; it never receives lines after that. +// it), told to finish and waited for, all under liveMu; it never receives +// lines after that. func runLive(ctx context.Context, out io.Writer, c *console, model tea.Model, work func(send func(tea.Msg)) error) error { if ctx == nil { ctx = context.Background() } - prog := tea.NewProgram(liveModel{inner: model}, + prog := tea.NewProgram(model, tea.WithInput(nil), tea.WithOutput(out), tea.WithoutSignalHandler(), @@ -364,11 +355,14 @@ func runLive(ctx context.Context, out io.Writer, c *console, model tea.Model, wo err := work(prog.Send) + // Unregister, finish and wait as one step: a printer that arrives + // meanwhile waits for the lock and then writes after the final frame, + // so no line reaches a stopped program or races the last frame. liveMu.Lock() activeProg = nil - liveMu.Unlock() prog.Send(finishMsg{err: err}) <-finished + liveMu.Unlock() return err } @@ -380,8 +374,8 @@ func printAboveLines(s string) bool { if activeProg == nil { return false } - for _, line := range strings.Split(strings.TrimSuffix(s, "\n"), "\n") { - activeProg.Send(printAboveMsg(line)) - } + // One message for the whole block, sent while holding liveMu: blocks + // from different goroutines keep the order of their calls. + activeProg.Send(printLine(strings.TrimSuffix(s, "\n"))) return true } diff --git a/modules/bonfire/live_test.go b/modules/bonfire/live_test.go index 5281a1f1..8ede2c09 100644 --- a/modules/bonfire/live_test.go +++ b/modules/bonfire/live_test.go @@ -2,9 +2,13 @@ package bonfire import ( "bytes" + "context" "errors" "fmt" + "io" + "regexp" "strings" + "sync" "testing" "time" @@ -206,21 +210,20 @@ func TestLiveModels(t *testing.T) { }) t.Run("print above", func(t *testing.T) { - var m tea.Model = liveModel{inner: newSpinnerModel(p, "x")} - before := frame(m) - m, cmd := m.Update(printAboveMsg("a log line")) - if cmd == nil || frame(m) != before { - t.Error("printAboveMsg did not become a Println command or reached the inner model") + // A printed block is one message for the program's queue, not a + // command bubbletea would run on a goroutine of its own. + msg := printLine("first\nsecond") + if msg == nil { + t.Fatal("printLine returned no message") } - m, _ = m.Update(itemMsg{done: 1, total: 2}) - if !strings.Contains(frame(m), "1/2") { - t.Errorf("other messages do not reach the inner model: %q", frame(m)) + if _, isCmd := msg.(tea.Cmd); isCmd { + t.Error("printLine returned a command") } }) t.Run("program end to end", func(t *testing.T) { var buf bytes.Buffer - prog := tea.NewProgram(liveModel{inner: newSpinnerModel(p, "Importing posts")}, + prog := tea.NewProgram(newSpinnerModel(p, "Importing posts"), tea.WithInput(nil), tea.WithOutput(&buf), tea.WithoutSignalHandler(), @@ -233,7 +236,7 @@ func TestLiveModels(t *testing.T) { done <- err }() prog.Send(itemMsg{done: 1, total: 2, item: "first"}) - prog.Send(printAboveMsg("imported first")) + prog.Send(printLine("imported first")) prog.Send(itemMsg{done: 2, total: 2, item: "second"}) prog.Send(finishMsg{}) select { @@ -253,3 +256,174 @@ func TestLiveModels(t *testing.T) { } }) } + +// lockedBuffer is a bytes.Buffer safe for a live program and other +// goroutines writing at the same time. +type lockedBuffer struct { + mu sync.Mutex + buf bytes.Buffer +} + +func (b *lockedBuffer) Write(p []byte) (int, error) { + b.mu.Lock() + defer b.mu.Unlock() + return b.buf.Write(p) +} + +func (b *lockedBuffer) String() string { + b.mu.Lock() + defer b.mu.Unlock() + return b.buf.String() +} + +var numberedLine = regexp.MustCompile(`(line|bg)-\d{3}`) + +// numbered returns the numbered lines of the ANSI-stripped output in the +// order they appear. +func numbered(out string) []string { + return numberedLine.FindAllString(ansi.Strip(out), -1) +} + +// printNumbered prints line- .. line- through the console's +// print paths in turn: Println, Printf, Info and bonfire.PrintAbove. +func printNumbered(c *console, from, to int) { + for i := from; i < to; i++ { + line := fmt.Sprintf("line-%03d", i) + switch i % 4 { + case 0: + c.Println(line) + case 1: + c.Printf("%s\n", line) + case 2: + c.Info(line) + case 3: + if !PrintAbove(line) { + c.Println(line) + } + } + } +} + +// checkNumbered fails unless out holds line-000 .. line- exactly once +// and in order. +func checkNumbered(t *testing.T, run int, out string, n int) { + t.Helper() + got := numbered(out) + for i := 0; i < n; i++ { + want := fmt.Sprintf("line-%03d", i) + if i >= len(got) { + t.Fatalf("run %d: %d of %d lines printed, %s missing:\n%s", run, len(got), n, want, ansi.Strip(out)) + } + if got[i] != want { + t.Fatalf("run %d: line %d is %s, want %s (lines: %v)", run, i, got[i], want, got) + } + } + if len(got) != n { + t.Fatalf("run %d: %d lines printed, want %d: %v", run, len(got), n, got) + } +} + +// TestPrintAboveOrderedNoLoss (CR-01): every line printed while a spinner, +// progress or process view runs appears once and in order; a line printed +// from another goroutine while the view finishes is not lost. +func TestPrintAboveOrderedNoLoss(t *testing.T) { + const runs, lines = 20, 100 + newTTY := func(out io.Writer) *console { + return newConsole(strings.NewReader(""), out, io.Discard, noEnv, boolPtr(true), boolPtr(true)) + } + + t.Run("spinner", func(t *testing.T) { + for run := range runs { + out := &lockedBuffer{} + c := newTTY(out) + if err := c.Spinner("working", func() error { + printNumbered(c, 0, lines) + return nil + }); err != nil { + t.Fatal(err) + } + checkNumbered(t, run, out.String(), lines) + } + }) + + t.Run("progress", func(t *testing.T) { + for run := range runs { + out := &lockedBuffer{} + c := newTTY(out) + if err := c.Progress(lines, func(p Progress) error { + printNumbered(c, 0, 40) + Failed(p, "item-a", errors.New("first failure")) + printNumbered(c, 40, 80) + Failed(p, "item-b", errors.New("second failure")) + printNumbered(c, 80, lines) + return nil + }); err != nil { + t.Fatal(err) + } + got := out.String() + checkNumbered(t, run, got, lines) + for _, want := range []string{"item-a: first failure", "item-b: second failure"} { + if !strings.Contains(ansi.Strip(got), want) { + t.Fatalf("run %d: failure line %q missing:\n%s", run, want, ansi.Strip(got)) + } + } + } + }) + + t.Run("process", func(t *testing.T) { + items := []string{"a", "b", "c", "d"} + for run := range runs { + out := &lockedBuffer{} + c := newTTY(out) + next := 0 + err := Process(context.Background(), c, "Pushing", items, func(context.Context, string) error { + printNumbered(c, next, next+lines/len(items)) + next += lines / len(items) + return nil + }) + if err != nil { + t.Fatal(err) + } + checkNumbered(t, run, out.String(), lines) + } + }) + + t.Run("concurrent_finish", func(t *testing.T) { + const bg = 200 + for run := range runs { + out := &lockedBuffer{} + c := newTTY(out) + started := make(chan struct{}) + done := make(chan struct{}) + if err := c.Spinner("working", func() error { + go func() { + defer close(done) + for i := range bg { + line := fmt.Sprintf("bg-%03d", i) + if !PrintAbove(line) { + _, _ = io.WriteString(out, line+"\n") + } + if i == 5 { + close(started) + } + } + }() + <-started + return nil + }); err != nil { + t.Fatal(err) + } + <-done + count := map[string]int{} + for _, l := range numbered(out.String()) { + count[l]++ + } + for i := range bg { + l := fmt.Sprintf("bg-%03d", i) + if count[l] != 1 { + t.Fatalf("run %d: %s printed %d times:\n%s", run, l, count[l], ansi.Strip(out.String())) + } + } + } + }) +} diff --git a/modules/bonfire/widgets.go b/modules/bonfire/widgets.go index 3ff0c574..54455e9c 100644 --- a/modules/bonfire/widgets.go +++ b/modules/bonfire/widgets.go @@ -129,7 +129,7 @@ func (p *liveProgress) Current(item string) { func (p *liveProgress) Fail(item string, err error) { p.send(itemMsg{done: p.current, total: p.total, item: item, err: err}) - p.send(printAboveMsg(failureLine(item, err))) + p.send(printLine(failureLine(item, err))) } func failureLine(item string, err error) string {