diff --git a/cli/cliui/provisionerjob.go b/cli/cliui/provisionerjob.go index aeaea7a34c..f9ecbf3d8a 100644 --- a/cli/cliui/provisionerjob.go +++ b/cli/cliui/provisionerjob.go @@ -54,6 +54,11 @@ func (err *ProvisionerJobError) Error() string { return err.Message } +const ( + ProvisioningStateQueued = "Queued" + ProvisioningStateRunning = "Running" +) + // ProvisionerJob renders a provisioner job with interactive cancellation. func ProvisionerJob(ctx context.Context, wr io.Writer, opts ProvisionerJobOptions) error { if opts.FetchInterval == 0 { @@ -63,8 +68,9 @@ func ProvisionerJob(ctx context.Context, wr io.Writer, opts ProvisionerJobOption defer cancelFunc() var ( - currentStage = "Queued" + currentStage = ProvisioningStateQueued currentStageStartedAt = time.Now().UTC() + currentQueuePos = -1 errChan = make(chan error, 1) job codersdk.ProvisionerJob @@ -74,7 +80,20 @@ func ProvisionerJob(ctx context.Context, wr io.Writer, opts ProvisionerJobOption sw := &stageWriter{w: wr, verbose: opts.Verbose, silentLogs: opts.Silent} printStage := func() { - sw.Start(currentStage) + out := currentStage + + if currentStage == ProvisioningStateQueued && currentQueuePos > 0 { + var queuePos string + if currentQueuePos == 1 { + queuePos = "next" + } else { + queuePos = fmt.Sprintf("position: %d", currentQueuePos) + } + + out = pretty.Sprintf(DefaultStyles.Warn, "%s (%s)", currentStage, queuePos) + } + + sw.Start(out) } updateStage := func(stage string, startedAt time.Time) { @@ -103,15 +122,26 @@ func ProvisionerJob(ctx context.Context, wr io.Writer, opts ProvisionerJobOption errChan <- xerrors.Errorf("fetch: %w", err) return } + if job.QueuePosition != currentQueuePos { + initialState := currentQueuePos == -1 + + currentQueuePos = job.QueuePosition + // Print an update when the queue position changes, but: + // - not initially, because the stage is printed at startup + // - not when we're first in the queue, because it's redundant + if !initialState && currentQueuePos != 0 { + printStage() + } + } if job.StartedAt == nil { return } - if currentStage != "Queued" { + if currentStage != ProvisioningStateQueued { // If another stage is already running, there's no need // for us to notify the user we're running! return } - updateStage("Running", *job.StartedAt) + updateStage(ProvisioningStateRunning, *job.StartedAt) } if opts.Cancel != nil { @@ -143,8 +173,8 @@ func ProvisionerJob(ctx context.Context, wr io.Writer, opts ProvisionerJobOption } // The initial stage needs to print after the signal handler has been registered. - printStage() updateJob() + printStage() logs, closer, err := opts.Logs() if err != nil { diff --git a/cli/cliui/provisionerjob_test.go b/cli/cliui/provisionerjob_test.go index 19241fc9b1..f3661ca8d1 100644 --- a/cli/cliui/provisionerjob_test.go +++ b/cli/cliui/provisionerjob_test.go @@ -2,13 +2,16 @@ package cliui_test import ( "context" + "fmt" "io" "os" + "regexp" "runtime" "sync" "testing" "time" + "github.com/coder/coder/v2/testutil" "github.com/stretchr/testify/assert" "github.com/coder/coder/v2/cli/cliui" @@ -25,7 +28,11 @@ func TestProvisionerJob(t *testing.T) { t.Parallel() test := newProvisionerJob(t) - go func() { + + ctx, cancel := context.WithTimeout(context.Background(), testutil.WaitShort) + defer cancel() + + testutil.Go(t, func() { <-test.Next test.JobMutex.Lock() test.Job.Status = codersdk.ProvisionerJobRunning @@ -39,20 +46,26 @@ func TestProvisionerJob(t *testing.T) { test.Job.CompletedAt = &now close(test.Logs) test.JobMutex.Unlock() - }() - test.PTY.ExpectMatch("Queued") - test.Next <- struct{}{} - test.PTY.ExpectMatch("Queued") - test.PTY.ExpectMatch("Running") - test.Next <- struct{}{} - test.PTY.ExpectMatch("Running") + }) + testutil.Eventually(ctx, t, func(ctx context.Context) (done bool) { + test.PTY.ExpectMatch(cliui.ProvisioningStateQueued) + test.Next <- struct{}{} + test.PTY.ExpectMatch(cliui.ProvisioningStateQueued) + test.PTY.ExpectMatch(cliui.ProvisioningStateRunning) + test.Next <- struct{}{} + test.PTY.ExpectMatch(cliui.ProvisioningStateRunning) + return true + }, testutil.IntervalFast) }) t.Run("Stages", func(t *testing.T) { t.Parallel() test := newProvisionerJob(t) - go func() { + ctx, cancel := context.WithTimeout(context.Background(), testutil.WaitShort) + defer cancel() + + testutil.Go(t, func() { <-test.Next test.JobMutex.Lock() test.Job.Status = codersdk.ProvisionerJobRunning @@ -70,13 +83,86 @@ func TestProvisionerJob(t *testing.T) { test.Job.CompletedAt = &now close(test.Logs) test.JobMutex.Unlock() - }() - test.PTY.ExpectMatch("Queued") - test.Next <- struct{}{} - test.PTY.ExpectMatch("Queued") - test.PTY.ExpectMatch("Something") - test.Next <- struct{}{} - test.PTY.ExpectMatch("Something") + }) + testutil.Eventually(ctx, t, func(ctx context.Context) (done bool) { + test.PTY.ExpectMatch(cliui.ProvisioningStateQueued) + test.Next <- struct{}{} + test.PTY.ExpectMatch(cliui.ProvisioningStateQueued) + test.PTY.ExpectMatch("Something") + test.Next <- struct{}{} + test.PTY.ExpectMatch("Something") + return true + }, testutil.IntervalFast) + }) + + t.Run("Queue Position", func(t *testing.T) { + t.Parallel() + + stage := cliui.ProvisioningStateQueued + + tests := []struct { + name string + queuePos int + expected string + }{ + { + name: "first", + queuePos: 0, + expected: fmt.Sprintf("%s$", stage), + }, + { + name: "next", + queuePos: 1, + expected: fmt.Sprintf(`%s %s$`, stage, regexp.QuoteMeta("(next)")), + }, + { + name: "other", + queuePos: 4, + expected: fmt.Sprintf(`%s %s$`, stage, regexp.QuoteMeta("(position: 4)")), + }, + } + + for _, tc := range tests { + tc := tc + + t.Run(tc.name, func(t *testing.T) { + t.Parallel() + + test := newProvisionerJob(t) + test.JobMutex.Lock() + test.Job.QueuePosition = tc.queuePos + test.Job.QueueSize = tc.queuePos + test.JobMutex.Unlock() + + ctx, cancel := context.WithTimeout(context.Background(), testutil.WaitShort) + defer cancel() + + testutil.Go(t, func() { + <-test.Next + test.JobMutex.Lock() + test.Job.Status = codersdk.ProvisionerJobRunning + now := dbtime.Now() + test.Job.StartedAt = &now + test.JobMutex.Unlock() + <-test.Next + test.JobMutex.Lock() + test.Job.Status = codersdk.ProvisionerJobSucceeded + now = dbtime.Now() + test.Job.CompletedAt = &now + close(test.Logs) + test.JobMutex.Unlock() + }) + testutil.Eventually(ctx, t, func(ctx context.Context) (done bool) { + test.PTY.ExpectRegexMatch(tc.expected) + test.Next <- struct{}{} + test.PTY.ExpectMatch(cliui.ProvisioningStateQueued) // step completed + test.PTY.ExpectMatch(cliui.ProvisioningStateRunning) + test.Next <- struct{}{} + test.PTY.ExpectMatch(cliui.ProvisioningStateRunning) + return true + }, testutil.IntervalFast) + }) + } }) // This cannot be ran in parallel because it uses a signal. @@ -90,7 +176,11 @@ func TestProvisionerJob(t *testing.T) { } test := newProvisionerJob(t) - go func() { + + ctx, cancel := context.WithTimeout(context.Background(), testutil.WaitShort) + defer cancel() + + testutil.Go(t, func() { <-test.Next currentProcess, err := os.FindProcess(os.Getpid()) assert.NoError(t, err) @@ -103,12 +193,15 @@ func TestProvisionerJob(t *testing.T) { test.Job.CompletedAt = &now close(test.Logs) test.JobMutex.Unlock() - }() - test.PTY.ExpectMatch("Queued") - test.Next <- struct{}{} - test.PTY.ExpectMatch("Gracefully canceling") - test.Next <- struct{}{} - test.PTY.ExpectMatch("Queued") + }) + testutil.Eventually(ctx, t, func(ctx context.Context) (done bool) { + test.PTY.ExpectMatch(cliui.ProvisioningStateQueued) + test.Next <- struct{}{} + test.PTY.ExpectMatch("Gracefully canceling") + test.Next <- struct{}{} + test.PTY.ExpectMatch(cliui.ProvisioningStateQueued) + return true + }, testutil.IntervalFast) }) } diff --git a/pty/ptytest/ptytest.go b/pty/ptytest/ptytest.go index d522c7dee7..451f3602a3 100644 --- a/pty/ptytest/ptytest.go +++ b/pty/ptytest/ptytest.go @@ -6,6 +6,7 @@ import ( "context" "fmt" "io" + "regexp" "runtime" "strings" "sync" @@ -145,16 +146,36 @@ type outExpecter struct { } func (e *outExpecter) ExpectMatch(str string) string { + return e.expectMatchContextFunc(str, e.ExpectMatchContext) +} + +func (e *outExpecter) ExpectRegexMatch(str string) string { + return e.expectMatchContextFunc(str, e.ExpectRegexMatchContext) +} + +func (e *outExpecter) expectMatchContextFunc(str string, fn func(ctx context.Context, str string) string) string { e.t.Helper() timeout, cancel := context.WithTimeout(context.Background(), testutil.WaitMedium) defer cancel() - return e.ExpectMatchContext(timeout, str) + return fn(timeout, str) } // TODO(mafredri): Rename this to ExpectMatch when refactoring. func (e *outExpecter) ExpectMatchContext(ctx context.Context, str string) string { + return e.expectMatcherFunc(ctx, str, func(src, pattern string) bool { + return strings.Contains(src, pattern) + }) +} + +func (e *outExpecter) ExpectRegexMatchContext(ctx context.Context, str string) string { + return e.expectMatcherFunc(ctx, str, func(src, pattern string) bool { + return regexp.MustCompile(pattern).MatchString(src) + }) +} + +func (e *outExpecter) expectMatcherFunc(ctx context.Context, str string, fn func(src, pattern string) bool) string { e.t.Helper() var buffer bytes.Buffer @@ -168,7 +189,7 @@ func (e *outExpecter) ExpectMatchContext(ctx context.Context, str string) string if err != nil { return err } - if strings.Contains(buffer.String(), str) { + if fn(buffer.String(), str) { return nil } }