Skip to content

Commit

Permalink
Progress Report timings are now stable
Browse files Browse the repository at this point in the history
  • Loading branch information
@onsi
onsi committed Sep 16, 2022
1 parent 9999f0a commit dd27a20
Show file tree
Hide file tree
Showing 4 changed files with 49 additions and 65 deletions.
2 changes: 2 additions & 0 deletions internal/progress_report.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -53,6 +53,8 @@ func NewProgressReport(isRunningInParallel bool, report types.SpecReport, curren
ParallelProcess: report.ParallelProcess,
RunningInParallel: isRunningInParallel,

Time: time.Now(),

ContainerHierarchyTexts: report.ContainerHierarchyTexts,
LeafNodeText: report.LeafNodeText,
LeafNodeLocation: report.LeafNodeLocation,
Expand Down
7 changes: 3 additions & 4 deletions reporters/default_reporter.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -329,13 +329,12 @@ func (r *DefaultReporter) EmitProgressReport(report types.ProgressReport) {
}

func (r *DefaultReporter) emitProgressReport(indent uint, emitGinkgoWriterOutput bool, report types.ProgressReport) {
now := time.Now()
if report.LeafNodeText != "" {
if len(report.ContainerHierarchyTexts) > 0 {
r.emit(r.fi(indent, r.cycleJoin(report.ContainerHierarchyTexts, " ")))
r.emit(" ")
}
r.emit(r.f("{{bold}}{{orange}}%s{{/}} (Spec Runtime: %s)\n", report.LeafNodeText, now.Sub(report.SpecStartTime).Round(time.Millisecond)))
r.emit(r.f("{{bold}}{{orange}}%s{{/}} (Spec Runtime: %s)\n", report.LeafNodeText, report.Time.Sub(report.SpecStartTime).Round(time.Millisecond)))
r.emit(r.fi(indent+1, "{{gray}}%s{{/}}\n", report.LeafNodeLocation))
indent += 1
}
Expand All @@ -345,12 +344,12 @@ func (r *DefaultReporter) emitProgressReport(indent uint, emitGinkgoWriterOutput
r.emit(r.f(" {{bold}}{{orange}}%s{{/}}", report.CurrentNodeText))
}

r.emit(r.f(" (Node Runtime: %s)\n", now.Sub(report.CurrentNodeStartTime).Round(time.Millisecond)))
r.emit(r.f(" (Node Runtime: %s)\n", report.Time.Sub(report.CurrentNodeStartTime).Round(time.Millisecond)))
r.emit(r.fi(indent+1, "{{gray}}%s{{/}}\n", report.CurrentNodeLocation))
indent += 1
}
if report.CurrentStepText != "" {
r.emit(r.fi(indent, "At {{bold}}{{orange}}[By Step] %s{{/}} (Step Runtime: %s)\n", report.CurrentStepText, now.Sub(report.CurrentStepStartTime).Round(time.Millisecond)))
r.emit(r.fi(indent, "At {{bold}}{{orange}}[By Step] %s{{/}} (Step Runtime: %s)\n", report.CurrentStepText, report.Time.Sub(report.CurrentStepStartTime).Round(time.Millisecond)))
r.emit(r.fi(indent+1, "{{gray}}%s{{/}}\n", report.CurrentStepLocation))
indent += 1
}
Expand Down
103 changes: 42 additions & 61 deletions reporters/default_reporter_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -157,13 +157,15 @@ type CurrentNodeText string
type CurrentStepText string

func PR(options ...interface{}) types.ProgressReport {
now := time.Now()
report := types.ProgressReport{
ParallelProcess: 1,
RunningInParallel: false,
Time: now,

SpecStartTime: time.Now().Add(-5 * time.Second),
CurrentNodeStartTime: time.Now().Add(-3 * time.Second),
CurrentStepStartTime: time.Now().Add(-1 * time.Second),
SpecStartTime: now.Add(-5 * time.Second),
CurrentNodeStartTime: now.Add(-3 * time.Second),
CurrentStepStartTime: now.Add(-1 * time.Second),

LeafNodeLocation: cl0,
CurrentNodeLocation: cl1,
Expand Down Expand Up @@ -241,8 +243,6 @@ func G(options ...interface{}) types.Goroutine {

const SlowSpecThreshold = 3 * time.Second

type REGEX string

var _ = Describe("DefaultReporter", func() {
var DENOTER = "•"
var RETRY_DENOTER = "↺"
Expand All @@ -260,25 +260,6 @@ var _ = Describe("DefaultReporter", func() {
}
}

verifyRegExOutput := func(expected []interface{}) {
if len(expected) == 0 {
ExpectWithOffset(1, buf.Contents()).Should(BeEmpty())
return
}

summary := test_helpers.MultilineTextHelper(string(buf.Contents()))
lines := strings.Split(string(buf.Contents()), "\n")
Expect(len(expected)).Should(BeNumerically("<=", len(lines)), summary)
for idx, expected := range expected {
switch v := expected.(type) {
case REGEX:
ExpectWithOffset(1, lines[idx]).Should(MatchRegexp(string(v)), summary)
default:
ExpectWithOffset(1, lines[idx]).Should(Equal(v), summary)
}
}
}

BeforeEach(func() {
buf = gbytes.NewBuffer()
format.CharactersAroundMismatchToInclude = 100
Expand Down Expand Up @@ -434,10 +415,10 @@ var _ = Describe("DefaultReporter", func() {
)

DescribeTable("DidRun",
func(conf types.ReporterConfig, report types.SpecReport, output ...interface{}) {
func(conf types.ReporterConfig, report types.SpecReport, output ...string) {
reporter := reporters.NewDefaultReporterUnderTest(conf, buf)
reporter.DidRun(report)
verifyRegExOutput(output)
verifyExpectedOutput(output)
},
// Passing Tests
Entry("a passing test",
Expand Down Expand Up @@ -1133,7 +1114,7 @@ var _ = Describe("DefaultReporter", func() {
" WITH DETAILS{{/}}",
" {{orange}}In {{bold}}[JustBeforeEach]{{/}}{{orange}} at: {{bold}}"+cl4.String()+"{{/}}",
"",
REGEX(` In {{bold}}{{orange}}\[BeforeSuite\]{{/}} \(Node Runtime: 3[\.\d]*s\)`),
" In {{bold}}{{orange}}[BeforeSuite]{{/}} (Node Runtime: 3s)",
" {{gray}}cl1.go:37{{/}}",
DELIMITER,
"",
Expand Down Expand Up @@ -1376,75 +1357,75 @@ var _ = Describe("DefaultReporter", func() {
)

DescribeTable("EmitProgressReport",
func(conf types.ReporterConfig, report types.ProgressReport, expected ...interface{}) {
func(conf types.ReporterConfig, report types.ProgressReport, expected ...string) {
reporter := reporters.NewDefaultReporterUnderTest(conf, buf)
reporter.EmitProgressReport(report)
verifyRegExOutput(expected)
verifyExpectedOutput(expected)
},
//just headers to start
Entry("With a suite node",
C(),
PR(types.NodeTypeBeforeSuite),
DELIMITER,
REGEX(`In {{bold}}{{orange}}\[BeforeSuite\]{{/}} \(Node Runtime: 3[\d\.]*s\)`),
"In {{bold}}{{orange}}[BeforeSuite]{{/}} (Node Runtime: 3s)",
" {{gray}}"+cl1.String()+"{{/}}",
DELIMITER,
""),
Entry("With a top-level spec",
C(),
PR(types.NodeTypeIt, CurrentNodeText("A Top-Level It"), "A Top-Level It"),
DELIMITER,
REGEX(`{{bold}}{{orange}}A Top-Level It{{/}} \(Spec Runtime: 5[\d\.]*s\)`),
"{{bold}}{{orange}}A Top-Level It{{/}} (Spec Runtime: 5s)",
" {{gray}}"+cl0.String()+"{{/}}",
REGEX(` In {{bold}}{{orange}}\[It\]{{/}} \(Node Runtime: 3[\d\.]*s\)`),
" In {{bold}}{{orange}}[It]{{/}} (Node Runtime: 3s)",
" {{gray}}"+cl1.String()+"{{/}}",
DELIMITER,
""),
Entry("With a spec in containers",
C(),
PR(types.NodeTypeIt, CurrentNodeText("My Spec"), "My Spec", []string{"Container A", "Container B", "Container C"}),
DELIMITER,
REGEX(`{{/}}Container A {{gray}}Container B {{/}}Container C{{/}} {{bold}}{{orange}}My Spec{{/}} \(Spec Runtime: 5[\d\.]*s\)`),
"{{/}}Container A {{gray}}Container B {{/}}Container C{{/}} {{bold}}{{orange}}My Spec{{/}} (Spec Runtime: 5s)",
" {{gray}}"+cl0.String()+"{{/}}",
REGEX(` In {{bold}}{{orange}}\[It\]{{/}} \(Node Runtime: 3[\d\.]*s\)`),
" In {{bold}}{{orange}}[It]{{/}} (Node Runtime: 3s)",
" {{gray}}"+cl1.String()+"{{/}}",
DELIMITER,
""),
Entry("With no current node",
C(),
PR("My Spec", []string{"Container A", "Container B", "Container C"}),
DELIMITER,
REGEX(`{{/}}Container A {{gray}}Container B {{/}}Container C{{/}} {{bold}}{{orange}}My Spec{{/}} \(Spec Runtime: 5[\d\.]*s\)`),
"{{/}}Container A {{gray}}Container B {{/}}Container C{{/}} {{bold}}{{orange}}My Spec{{/}} (Spec Runtime: 5s)",
" {{gray}}"+cl0.String()+"{{/}}",
DELIMITER,
""),
Entry("With a current node that is not an It",
C(),
PR("My Spec", []string{"Container A", "Container B", "Container C"}, types.NodeTypeBeforeEach),
DELIMITER,
REGEX(`{{/}}Container A {{gray}}Container B {{/}}Container C{{/}} {{bold}}{{orange}}My Spec{{/}} \(Spec Runtime: 5[\d\.]*s\)`),
"{{/}}Container A {{gray}}Container B {{/}}Container C{{/}} {{bold}}{{orange}}My Spec{{/}} (Spec Runtime: 5s)",
" {{gray}}"+cl0.String()+"{{/}}",
REGEX(` In {{bold}}{{orange}}\[BeforeEach\]{{/}} \(Node Runtime: 3[\d\.]*s\)`),
" In {{bold}}{{orange}}[BeforeEach]{{/}} (Node Runtime: 3s)",
" {{gray}}"+cl1.String()+"{{/}}",
DELIMITER,
""),
Entry("With a current node that is not an It, but has text",
C(),
PR(types.NodeTypeReportAfterSuite, CurrentNodeText("My Report")),
DELIMITER,
REGEX(`In {{bold}}{{orange}}\[ReportAfterSuite\]{{/}} {{bold}}{{orange}}My Report{{/}} \(Node Runtime: 3[\d\.]*s\)`),
"In {{bold}}{{orange}}[ReportAfterSuite]{{/}} {{bold}}{{orange}}My Report{{/}} (Node Runtime: 3s)",
" {{gray}}"+cl1.String()+"{{/}}",
DELIMITER,
""),
Entry("With a current step",
C(),
PR(types.NodeTypeIt, CurrentNodeText("My Spec"), "My Spec", []string{"Container A", "Container B", "Container C"}, CurrentStepText("Reticulating Splines")),
DELIMITER,
REGEX(`{{/}}Container A {{gray}}Container B {{/}}Container C{{/}} {{bold}}{{orange}}My Spec{{/}} \(Spec Runtime: 5[\d\.]*s\)`),
"{{/}}Container A {{gray}}Container B {{/}}Container C{{/}} {{bold}}{{orange}}My Spec{{/}} (Spec Runtime: 5s)",
" {{gray}}"+cl0.String()+"{{/}}",
REGEX(` In {{bold}}{{orange}}\[It\]{{/}} \(Node Runtime: 3[\d\.]*s\)`),
" In {{bold}}{{orange}}[It]{{/}} (Node Runtime: 3s)",
" {{gray}}"+cl1.String()+"{{/}}",
REGEX(` At {{bold}}{{orange}}\[By Step\] Reticulating Splines{{/}} \(Step Runtime: 1[\d\.]*s\)`),
" At {{bold}}{{orange}}[By Step] Reticulating Splines{{/}} (Step Runtime: 1s)",
" {{gray}}"+cl2.String()+"{{/}}",
DELIMITER,
""),
Expand All @@ -1457,9 +1438,9 @@ var _ = Describe("DefaultReporter", func() {
GW("gw-1\ngw-2\ngw-3\ngw-4\ngw-5\ngw-6\ngw-7\ngw-8\ngw-9\ngw-10\ngw-11\ngw-12\n"),
),
DELIMITER,
REGEX(`{{bold}}{{orange}}My Spec{{/}} \(Spec Runtime: 5[\d\.]*s\)`),
"{{bold}}{{orange}}My Spec{{/}} (Spec Runtime: 5s)",
" {{gray}}"+cl0.String()+"{{/}}",
REGEX(` In {{bold}}{{orange}}\[It\]{{/}} \(Node Runtime: 3[\d\.]*s\)`),
" In {{bold}}{{orange}}[It]{{/}} (Node Runtime: 3s)",
" {{gray}}"+cl1.String()+"{{/}}",
"",
" {{gray}}Begin Captured GinkgoWriter Output >>{{/}}",
Expand All @@ -1485,9 +1466,9 @@ var _ = Describe("DefaultReporter", func() {
GW("gw-1\ngw-2\ngw-3\ngw-4\ngw-5\ngw-6\ngw-7\ngw-8\ngw-9\n"),
),
DELIMITER,
REGEX(`{{bold}}{{orange}}My Spec{{/}} \(Spec Runtime: 5[\d\.]*s\)`),
"{{bold}}{{orange}}My Spec{{/}} (Spec Runtime: 5s)",
" {{gray}}"+cl0.String()+"{{/}}",
REGEX(` In {{bold}}{{orange}}\[It\]{{/}} \(Node Runtime: 3[\d\.]*s\)`),
" In {{bold}}{{orange}}[It]{{/}} (Node Runtime: 3s)",
" {{gray}}"+cl1.String()+"{{/}}",
"",
" {{gray}}Begin Captured GinkgoWriter Output >>{{/}}",
Expand All @@ -1511,9 +1492,9 @@ var _ = Describe("DefaultReporter", func() {
GW("gw-1\n"),
),
DELIMITER,
REGEX(`{{bold}}{{orange}}My Spec{{/}} \(Spec Runtime: 5[\d\.]*s\)`),
"{{bold}}{{orange}}My Spec{{/}} (Spec Runtime: 5s)",
" {{gray}}"+cl0.String()+"{{/}}",
REGEX(` In {{bold}}{{orange}}\[It\]{{/}} \(Node Runtime: 3[\d\.]*s\)`),
" In {{bold}}{{orange}}[It]{{/}} (Node Runtime: 3s)",
" {{gray}}"+cl1.String()+"{{/}}",
DELIMITER,
""),
Expand All @@ -1526,9 +1507,9 @@ var _ = Describe("DefaultReporter", func() {
),
DELIMITER,
"{{coral}}Progress Report for Ginkgo Process #{{bold}}1{{/}}",
REGEX(`{{bold}}{{orange}}My Spec{{/}} \(Spec Runtime: 5[\d\.]*s\)`),
"{{bold}}{{orange}}My Spec{{/}} (Spec Runtime: 5s)",
" {{gray}}"+cl0.String()+"{{/}}",
REGEX(` In {{bold}}{{orange}}\[It\]{{/}} \(Node Runtime: 3[\d\.]*s\)`),
" In {{bold}}{{orange}}[It]{{/}} (Node Runtime: 3s)",
" {{gray}}"+cl1.String()+"{{/}}",
"",
" {{gray}}Begin Captured GinkgoWriter Output >>{{/}}",
Expand All @@ -1549,9 +1530,9 @@ var _ = Describe("DefaultReporter", func() {
),

DELIMITER,
REGEX(`{{bold}}{{orange}}My Spec{{/}} \(Spec Runtime: 5[\d\.]*s\)`),
"{{bold}}{{orange}}My Spec{{/}} (Spec Runtime: 5s)",
" {{gray}}"+cl0.String()+"{{/}}",
REGEX(` In {{bold}}{{orange}}\[It\]{{/}} \(Node Runtime: 3[\d\.]*s\)`),
" In {{bold}}{{orange}}[It]{{/}} (Node Runtime: 3s)",
" {{gray}}"+cl1.String()+"{{/}}",
"",
" {{bold}}{{underline}}Spec Goroutine{{/}}",
Expand All @@ -1577,9 +1558,9 @@ var _ = Describe("DefaultReporter", func() {
),

DELIMITER,
REGEX(`{{bold}}{{orange}}My Spec{{/}} \(Spec Runtime: 5[\d\.]*s\)`),
"{{bold}}{{orange}}My Spec{{/}} (Spec Runtime: 5s)",
" {{gray}}"+cl0.String()+"{{/}}",
REGEX(` In {{bold}}{{orange}}\[It\]{{/}} \(Node Runtime: 3[\d\.]*s\)`),
" In {{bold}}{{orange}}[It]{{/}} (Node Runtime: 3s)",
" {{gray}}"+cl1.String()+"{{/}}",
"",
" {{bold}}{{underline}}Goroutines of Interest{{/}}",
Expand All @@ -1605,9 +1586,9 @@ var _ = Describe("DefaultReporter", func() {
),

DELIMITER,
REGEX(`{{bold}}{{orange}}My Spec{{/}} \(Spec Runtime: 5[\d\.]*s\)`),
"{{bold}}{{orange}}My Spec{{/}} (Spec Runtime: 5s)",
" {{gray}}"+cl0.String()+"{{/}}",
REGEX(` In {{bold}}{{orange}}\[It\]{{/}} \(Node Runtime: 3[\d\.]*s\)`),
" In {{bold}}{{orange}}[It]{{/}} (Node Runtime: 3s)",
" {{gray}}"+cl1.String()+"{{/}}",
"",
" {{gray}}{{bold}}{{underline}}Other Goroutines{{/}}",
Expand Down Expand Up @@ -1641,9 +1622,9 @@ var _ = Describe("DefaultReporter", func() {
),

DELIMITER,
REGEX(`{{bold}}{{orange}}My Spec{{/}} \(Spec Runtime: 5[\d\.]*s\)`),
"{{bold}}{{orange}}My Spec{{/}} (Spec Runtime: 5s)",
" {{gray}}"+cl0.String()+"{{/}}",
REGEX(` In {{bold}}{{orange}}\[It\]{{/}} \(Node Runtime: 3[\d\.]*s\)`),
" In {{bold}}{{orange}}[It]{{/}} (Node Runtime: 3s)",
" {{gray}}"+cl1.String()+"{{/}}",
"",
" {{bold}}{{underline}}Spec Goroutine{{/}}",
Expand Down Expand Up @@ -1681,9 +1662,9 @@ var _ = Describe("DefaultReporter", func() {
),

DELIMITER,
REGEX(`{{bold}}{{orange}}My Spec{{/}} \(Spec Runtime: 5[\d\.]*s\)`),
"{{bold}}{{orange}}My Spec{{/}} (Spec Runtime: 5s)",
" {{gray}}"+cl0.String()+"{{/}}",
REGEX(` In {{bold}}{{orange}}\[It\]{{/}} \(Node Runtime: 3[\d\.]*s\)`),
" In {{bold}}{{orange}}[It]{{/}} (Node Runtime: 3s)",
" {{gray}}"+cl1.String()+"{{/}}",
"",
" {{bold}}{{underline}}Spec Goroutine{{/}}",
Expand Down Expand Up @@ -1711,9 +1692,9 @@ var _ = Describe("DefaultReporter", func() {

DELIMITER,
"{{coral}}Progress Report for Ginkgo Process #{{bold}}3{{/}}",
REGEX(`{{bold}}{{orange}}My Spec{{/}} \(Spec Runtime: 5[\d\.]*s\)`),
"{{bold}}{{orange}}My Spec{{/}} (Spec Runtime: 5s)",
" {{gray}}"+cl0.String()+"{{/}}",
REGEX(` In {{bold}}{{orange}}\[It\]{{/}} \(Node Runtime: 3[\d\.]*s\)`),
" In {{bold}}{{orange}}[It]{{/}} (Node Runtime: 3s)",
" {{gray}}"+cl1.String()+"{{/}}",
DELIMITER,
""),
Expand Down
2 changes: 2 additions & 0 deletions types/types.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -484,6 +484,8 @@ type ProgressReport struct {
ParallelProcess int
RunningInParallel bool

Time time.Time

ContainerHierarchyTexts []string
LeafNodeText string
LeafNodeLocation CodeLocation
Expand Down

0 comments on commit dd27a20

Please sign in to comment.