diff --git a/internal/build/pipeline_state.go b/internal/build/pipeline_state.go index 4f8a0138be..a00d964a53 100644 --- a/internal/build/pipeline_state.go +++ b/internal/build/pipeline_state.go @@ -10,15 +10,19 @@ import ( ) type PipelineState struct { - curPipelineStep int - curBuildStep int totalPipelineStepCount int - pipelineStepDurations []time.Duration + curBuildStep int curPipelineStart time.Time - curPipelineStepStart time.Time + pipelineSteps []PipelineStep c Clock } +type PipelineStep struct { + Name string // for logging + StartTime time.Time + Duration time.Duration // not populated until end of the step +} + type Clock interface { Now() time.Time } @@ -35,8 +39,8 @@ const buildStepOutputPrefix = " " func NewPipelineState(ctx context.Context, totalStepCount int, c Clock) *PipelineState { return &PipelineState{ - curPipelineStep: 1, totalPipelineStepCount: totalStepCount, + pipelineSteps: []PipelineStep{}, curPipelineStart: c.Now(), c: c, } @@ -48,7 +52,6 @@ func NewPipelineState(ctx context.Context, totalStepCount int, c Clock) *Pipelin // and NOT: // defer ps.End(ctx, err) func (ps *PipelineState) End(ctx context.Context, err error) { - ps.curPipelineStep = 0 ps.curBuildStep = 0 if err != nil { @@ -59,27 +62,42 @@ func (ps *PipelineState) End(ctx context.Context, err error) { elapsed := ps.c.Now().Sub(ps.curPipelineStart) - for i, duration := range ps.pipelineStepDurations { - l.Infof("%sStep %d - %.2fs", buildStepOutputPrefix, i+1, duration.Seconds()) + for i, step := range ps.pipelineSteps { + l.Infof("%sStep %d - %.2fs (%s)", buildStepOutputPrefix, i+1, step.Duration.Seconds(), step.Name) } t := logger.Blue(l).Sprintf("%.2fs", elapsed.Seconds()) l.Infof("%sDONE IN: %s \n", buildStepOutputPrefix, t) } +func (ps *PipelineState) curPipelineIndex() int { + // human-readable i.e. 1-indexed + return len(ps.pipelineSteps) +} + +func (ps *PipelineState) curPipelineStep() PipelineStep { + if len(ps.pipelineSteps) == 0 { + return PipelineStep{} + } + return ps.pipelineSteps[len(ps.pipelineSteps)-1] +} + func (ps *PipelineState) StartPipelineStep(ctx context.Context, format string, a ...interface{}) { l := logger.Get(ctx) - line := logger.Blue(l).Sprintf("STEP %d/%d", ps.curPipelineStep, ps.totalPipelineStepCount) - l.Infof("%s — %s", line, fmt.Sprintf(format, a...)) - ps.curPipelineStep++ + stepName := fmt.Sprintf(format, a...) + ps.pipelineSteps = append(ps.pipelineSteps, PipelineStep{ + Name: stepName, + StartTime: ps.c.Now(), + }) + line := logger.Blue(l).Sprintf("STEP %d/%d", ps.curPipelineIndex(), ps.totalPipelineStepCount) + l.Infof("%s — %s", line, stepName) ps.curBuildStep = 1 - ps.curPipelineStepStart = ps.c.Now() } func (ps *PipelineState) EndPipelineStep(ctx context.Context) { - elapsed := ps.c.Now().Sub(ps.curPipelineStepStart) + elapsed := ps.c.Now().Sub(ps.curPipelineStep().StartTime) logger.Get(ctx).Infof("") - ps.pipelineStepDurations = append(ps.pipelineStepDurations, elapsed) + ps.pipelineSteps[len(ps.pipelineSteps)-1].Duration = elapsed } func (ps *PipelineState) StartBuildStep(ctx context.Context, format string, a ...interface{}) { diff --git a/internal/build/pipeline_state_test.go b/internal/build/pipeline_state_test.go index f08ac2cd93..1e56c294c7 100644 --- a/internal/build/pipeline_state_test.go +++ b/internal/build/pipeline_state_test.go @@ -56,6 +56,26 @@ func TestPipelineMultilinePrint(t *testing.T) { assertSnapshot(t, out.String()) } +func TestPipelineMultistep(t *testing.T) { + var err error + out := &bytes.Buffer{} + ctx := logger.WithLogger(context.Background(), logger.NewLogger(logger.InfoLvl, out)) + ps := NewPipelineState(ctx, 3, fakeClock{}) + ps.StartPipelineStep(ctx, "%s %s", "hello", "world") + ps.Printf(ctx, "in ur step") + ps.EndPipelineStep(ctx) + ps.StartPipelineStep(ctx, "doing stuff") + ps.Printf(ctx, "here is some stuff!") + ps.EndPipelineStep(ctx) + ps.StartPipelineStep(ctx, "different stuff") + ps.Printf(ctx, "even more stuff") + ps.Printf(ctx, "i can't believe it's not stuff") + ps.EndPipelineStep(ctx) + ps.End(ctx, err) + + assertSnapshot(t, out.String()) +} + func assertSnapshot(t *testing.T, output string) { d1 := []byte(output) gmPath := fmt.Sprintf("testdata/%s_master", t.Name()) diff --git a/internal/build/testdata/TestPipelineMultilinePrint_master b/internal/build/testdata/TestPipelineMultilinePrint_master index 8517dfc228..6f01a1925b 100644 --- a/internal/build/testdata/TestPipelineMultilinePrint_master +++ b/internal/build/testdata/TestPipelineMultilinePrint_master @@ -3,6 +3,6 @@ STEP 1/1 — hello world line 2 - Step 1 - 0.00s + Step 1 - 0.00s (hello world) DONE IN: 0.00s diff --git a/internal/build/testdata/TestPipelineMultistep_master b/internal/build/testdata/TestPipelineMultistep_master new file mode 100644 index 0000000000..aaa188b42c --- /dev/null +++ b/internal/build/testdata/TestPipelineMultistep_master @@ -0,0 +1,15 @@ +STEP 1/3 — hello world + in ur step + +STEP 2/3 — doing stuff + here is some stuff! + +STEP 3/3 — different stuff + even more stuff + i can't believe it's not stuff + + Step 1 - 0.00s (hello world) + Step 2 - 0.00s (doing stuff) + Step 3 - 0.00s (different stuff) + DONE IN: 0.00s + diff --git a/internal/build/testdata/TestPipeline_master b/internal/build/testdata/TestPipeline_master index 751fda8310..8e42aa7a66 100644 --- a/internal/build/testdata/TestPipeline_master +++ b/internal/build/testdata/TestPipeline_master @@ -1,6 +1,6 @@ STEP 1/1 — hello world in ur step - Step 1 - 0.00s + Step 1 - 0.00s (hello world) DONE IN: 0.00s