diff --git a/cmd/src/actions_exec.go b/cmd/src/actions_exec.go index 20f1ae4467..ba09c7d729 100644 --- a/cmd/src/actions_exec.go +++ b/cmd/src/actions_exec.go @@ -237,7 +237,8 @@ Format of the action JSON files: } logger.Infof("Use 'src actions scope-query' for help with scoping.\n") - logger.Start() + totalSteps := len(repos) * len(action.Steps) + logger.Start(totalSteps) executor := newActionExecutor(action, *parallelismFlag, logger, opts) for _, repo := range repos { diff --git a/cmd/src/actions_exec_backend_runner.go b/cmd/src/actions_exec_backend_runner.go index 7b8ed33266..38dc036c4b 100644 --- a/cmd/src/actions_exec_backend_runner.go +++ b/cmd/src/actions_exec_backend_runner.go @@ -46,7 +46,7 @@ func (x *actionExecutor) do(ctx context.Context, repo ActionRepo) (err error) { } else if ok { status := ActionRepoStatus{Cached: true, Patch: result} x.updateRepoStatus(repo, status) - x.logger.RepoCacheHit(repo, status.Patch != PatchInput{}) + x.logger.RepoCacheHit(repo, len(x.action.Steps), status.Patch != PatchInput{}) return nil } } diff --git a/cmd/src/actions_exec_logger.go b/cmd/src/actions_exec_logger.go index c7ca544cce..f402a57820 100644 --- a/cmd/src/actions_exec_logger.go +++ b/cmd/src/actions_exec_logger.go @@ -1,12 +1,14 @@ package main import ( + "bytes" "fmt" "io" "io/ioutil" "os" "strings" "sync" + "sync/atomic" "time" "github.com/fatih/color" @@ -31,9 +33,12 @@ type actionLogger struct { highlight func(a ...interface{}) string + progress *progress + out io.Writer + + mu sync.Mutex logFiles map[string]*os.File logWriters map[string]io.Writer - mu sync.Mutex } func newActionLogger(verbose, keepLogs bool) *actionLogger { @@ -41,25 +46,36 @@ func newActionLogger(verbose, keepLogs bool) *actionLogger { if useColor { color.NoColor = false } + + progress := new(progress) + return &actionLogger{ - verbose: verbose, - keepLogs: keepLogs, - highlight: color.New(color.Bold, color.FgGreen).SprintFunc(), + verbose: verbose, + keepLogs: keepLogs, + highlight: color.New(color.Bold, color.FgGreen).SprintFunc(), + progress: progress, + out: &progressWriter{ + p: progress, + w: os.Stderr, + }, logFiles: map[string]*os.File{}, logWriters: map[string]io.Writer{}, } } -func (a *actionLogger) Start() { +func (a *actionLogger) Start(totalSteps int) { if a.verbose { + a.progress.SetTotalSteps(int64(totalSteps)) fmt.Fprintln(os.Stderr) } } +func (a *actionLogger) Infof(format string, args ...interface{}) { + a.log("", grey, format, args...) +} + func (a *actionLogger) Warnf(format string, args ...interface{}) { - if a.verbose { - yellow.Fprintf(os.Stderr, "WARNING: "+format, args...) - } + a.log("", yellow, "WARNING: "+format, args...) } func (a *actionLogger) ActionFailed(err error, patches []PatchInput) { @@ -89,31 +105,25 @@ func (a *actionLogger) ActionFailed(err error, patches []PatchInput) { } func (a *actionLogger) ActionSuccess(patches []PatchInput, newLines bool) { - if a.verbose { - fmt.Fprintln(os.Stderr) - format := "✔ Action produced %d patches." - if newLines { - format = format + "\n\n" - } - hiGreen.Fprintf(os.Stderr, format, len(patches)) + if !a.verbose { + return } -} - -func (a *actionLogger) Infof(format string, args ...interface{}) { - if a.verbose { - grey.Fprintf(os.Stderr, format, args...) + fmt.Fprintln(os.Stderr) + format := "✔ Action produced %d patches." + if newLines { + format = format + "\n\n" } + hiGreen.Fprintf(os.Stderr, format, len(patches)) } -func (a *actionLogger) RepoCacheHit(repo ActionRepo, patchProduced bool) { - if a.verbose { - if patchProduced { - fmt.Fprintf(os.Stderr, "%s -> Cached result found: using cached diff.\n", boldGreen.Sprint(repo.Name)) - return - } - - fmt.Fprintf(os.Stderr, "%s -> Cached result found: no diff produced for this repository.\n", grey.Sprint(repo.Name)) +func (a *actionLogger) RepoCacheHit(repo ActionRepo, stepCount int, patchProduced bool) { + a.progress.IncStepsComplete(int64(stepCount)) + if patchProduced { + a.progress.IncPatchCount() + a.log(repo.Name, boldGreen, "Cached result found: using cached diff.\n") + return } + a.log(repo.Name, grey, "Cached result found: no diff produced for this repository.\n") } func (a *actionLogger) AddRepo(repo ActionRepo) (string, error) { @@ -151,25 +161,14 @@ func (a *actionLogger) RepoStdoutStderr(repoName string) (io.Writer, io.Writer, } stderrPrefix := fmt.Sprintf("%s -> [STDERR]: ", yellow.Sprint(repoName)) - stderr := textio.NewPrefixWriter(os.Stderr, stderrPrefix) + stderr := textio.NewPrefixWriter(a.out, stderrPrefix) stdoutPrefix := fmt.Sprintf("%s -> [STDOUT]: ", yellow.Sprint(repoName)) - stdout := textio.NewPrefixWriter(os.Stderr, stdoutPrefix) + stdout := textio.NewPrefixWriter(a.out, stdoutPrefix) return io.MultiWriter(stdout, w), io.MultiWriter(stderr, w), ok } -func (a *actionLogger) write(repoName string, c *color.Color, format string, args ...interface{}) { - if w, ok := a.RepoWriter(repoName); ok { - fmt.Fprintf(w, format, args...) - } - - if a.verbose { - format = fmt.Sprintf("%s -> %s", c.Sprint(repoName), format) - fmt.Fprintf(os.Stderr, format, args...) - } -} - func (a *actionLogger) RepoFinished(repoName string, patchProduced bool, actionErr error) error { a.mu.Lock() f, ok := a.logFiles[repoName] @@ -186,6 +185,7 @@ func (a *actionLogger) RepoFinished(repoName string, patchProduced bool, actionE a.write(repoName, boldRed, "Action failed: %q\n", actionErr) } } else if patchProduced { + a.progress.IncPatchCount() a.write(repoName, boldGreen, "Finished. Patch produced.\n") } else { a.write(repoName, grey, "Finished. No patch produced.\n") @@ -215,10 +215,13 @@ func (a *actionLogger) CommandStepStarted(repoName string, step int, args []stri } func (a *actionLogger) CommandStepErrored(repoName string, step int, err error) { + a.progress.IncStepsComplete(1) + a.progress.IncStepsFailed() a.write(repoName, boldRed, "%s %s.\n", boldBlack.Sprintf("[Step %d]", step), err) } func (a *actionLogger) CommandStepDone(repoName string, step int) { + a.progress.IncStepsComplete(1) a.write(repoName, yellow, "%s Done.\n", boldBlack.Sprintf("[Step %d]", step)) } @@ -227,9 +230,126 @@ func (a *actionLogger) DockerStepStarted(repoName string, step int, image string } func (a *actionLogger) DockerStepErrored(repoName string, step int, err error, elapsed time.Duration) { + a.progress.IncStepsComplete(1) + a.progress.IncStepsFailed() a.write(repoName, boldRed, "%s %s. (%s)\n", boldBlack.Sprintf("[Step %d]", step), err, elapsed) } func (a *actionLogger) DockerStepDone(repoName string, step int, elapsed time.Duration) { + a.progress.IncStepsComplete(1) a.write(repoName, yellow, "%s Done. (%s)\n", boldBlack.Sprintf("[Step %d]", step), elapsed) } + +// write writes to the RepoWriter associated with the given repoName and logs the message using the log method. +func (a *actionLogger) write(repoName string, c *color.Color, format string, args ...interface{}) { + if w, ok := a.RepoWriter(repoName); ok { + fmt.Fprintf(w, format, args...) + } + a.log(repoName, c, format, args...) +} + +// log logs only to stderr, it does not log to our repoWriters. When not in verbose mode, it's a noop. +func (a *actionLogger) log(repoName string, c *color.Color, format string, args ...interface{}) { + if !a.verbose { + return + } + if len(repoName) > 0 { + format = fmt.Sprintf("%s -> %s", c.Sprint(repoName), format) + } + fmt.Fprintf(a.out, format, args...) +} + +type progress struct { + patchCount int64 + + totalSteps int64 + stepsComplete int64 + stepsFailed int64 +} + +func (p *progress) SetTotalSteps(n int64) { + atomic.StoreInt64(&p.totalSteps, n) +} + +func (p *progress) TotalSteps() int64 { + return atomic.LoadInt64(&p.totalSteps) +} + +func (p *progress) StepsComplete() int64 { + return atomic.LoadInt64(&p.stepsComplete) +} + +func (p *progress) IncStepsComplete(delta int64) { + atomic.AddInt64(&p.stepsComplete, delta) +} + +func (p *progress) TotalStepsFailed() int64 { + return atomic.LoadInt64(&p.stepsFailed) +} + +func (p *progress) IncStepsFailed() { + atomic.AddInt64(&p.stepsFailed, 1) +} + +func (p *progress) PatchCount() int64 { + return atomic.LoadInt64(&p.patchCount) +} + +func (p *progress) IncPatchCount() { + atomic.AddInt64(&p.patchCount, 1) +} + +type progressWriter struct { + p *progress + + mu sync.Mutex + w io.Writer + shouldClear bool + progressLogLength int +} + +func (w *progressWriter) Write(data []byte) (int, error) { + w.mu.Lock() + defer w.mu.Unlock() + + if w.shouldClear { + // Clear current progress + fmt.Fprintf(w.w, "\r") + fmt.Fprintf(w.w, strings.Repeat(" ", w.progressLogLength)) + fmt.Fprintf(w.w, "\r") + } + + if w.p.TotalSteps() == 0 { + // Don't display bar until we know number of steps + w.shouldClear = false + return w.w.Write(data) + } + + if !bytes.HasSuffix(data, []byte("\n")) { + w.shouldClear = false + return w.w.Write(data) + } + + n, err := w.w.Write(data) + if err != nil { + return n, err + } + total := w.p.TotalSteps() + done := w.p.StepsComplete() + var pctDone float64 + if total > 0 { + pctDone = float64(done) / float64(total) + } + + maxLength := 50 + bar := strings.Repeat("=", int(float64(maxLength)*pctDone)) + if len(bar) < maxLength { + bar += ">" + } + bar += strings.Repeat(" ", maxLength-len(bar)) + progessText := fmt.Sprintf("[%s] Steps: %d/%d (%s, %s)", bar, w.p.StepsComplete(), w.p.TotalSteps(), boldRed.Sprintf("%d failed", w.p.TotalStepsFailed()), hiGreen.Sprintf("%d patches", w.p.PatchCount())) + fmt.Fprintf(w.w, progessText) + w.shouldClear = true + w.progressLogLength = len(progessText) + return n, err +}