Ginkgo output now includes a timeline-view of the spec

This commit changers Ginkgo default output.  Spec details are now
presented as a **timeline** that includes events that occur during the spec
lifecycle interleaved with any GinkgoWriter content.  This makes is much easier
to understand the flow of a spec and where a given failure occurs.

The --progress, --slow-spec-threshold, --always-emit-ginkgo-writer flags
and the SuppressProgressReporting decorator have all been deprecated.  Instead
the existing -v and -vv flags better capture the level of verbosity to display.  However,
a new --show-node-events flag is added to include node > Enter and < Exit events
in the spec timeline.

JUnit reports now include the timeline (rendered with -vv) and custom JUnit
reports can be configured and generated using
GenerateJUnitReportWithConfig(report types.Report, dst string, config JunitReportConfig)`

Author: onsi

core_dsl.go

@@ -21,7 +21,6 @@ import (
 	"os"
 	"path/filepath"
 	"strings"
-	"time"
 
 	"github.com/go-logr/logr"
 	"github.com/onsi/ginkgo/v2/formatter"
@@ -276,7 +275,7 @@ func RunSpecs(t GinkgoTestingT, description string, args ...interface{}) bool {
 	}
 
 	writer := GinkgoWriter.(*internal.Writer)
-	if reporterConfig.Verbose && suiteConfig.ParallelTotal == 1 {
+	if reporterConfig.Verbosity().GTE(types.VerbosityLevelVerbose) && suiteConfig.ParallelTotal == 1 {
 		writer.SetMode(internal.WriterModeStreamAndBuffer)
 	} else {
 		writer.SetMode(internal.WriterModeBufferOnly)
@@ -513,31 +512,7 @@ Note that By does not generate a new Ginkgo node - rather it is simply synctacti
 You can learn more about By here: https://onsi.github.io/ginkgo/#documenting-complex-specs-by
 */
 func By(text string, callback ...func()) {
-	if !global.Suite.InRunPhase() {
-		exitIfErr(types.GinkgoErrors.ByNotDuringRunPhase(types.NewCodeLocation(1)))
-	}
-	value := struct {
-		Text     string
-		Duration time.Duration
-	}{
-		Text: text,
-	}
-	t := time.Now()
-	global.Suite.SetProgressStepCursor(internal.ProgressStepCursor{
-		Text:         text,
-		CodeLocation: types.NewCodeLocation(1),
-		StartTime:    t,
-	})
-	AddReportEntry("By Step", ReportEntryVisibilityNever, Offset(1), &value, t)
-	formatter := formatter.NewWithNoColorBool(reporterConfig.NoColor)
-	GinkgoWriter.Println(formatter.F("{{bold}}STEP:{{/}} %s {{gray}}%s{{/}}", text, t.Format(types.GINKGO_TIME_FORMAT)))
-	if len(callback) == 1 {
-		callback[0]()
-		value.Duration = time.Since(t)
-	}
-	if len(callback) > 1 {
-		panic("just one callback per By, please")
-	}
+	exitIfErr(global.Suite.By(text, callback...))
 }
 
 /*

docs/index.md

@@ -2,6 +2,7 @@ package performance_test
 
 import (
 	"fmt"
+	"os"
 
 	. "github.com/onsi/ginkgo/v2"
 	. "github.com/onsi/gomega"
@@ -12,6 +13,10 @@ var _ = Describe("Compiling and Running a single test package", func() {
 	var cache gmeasure.ExperimentCache
 
 	BeforeEach(func() {
+		if os.Getenv("PERF") == "" {
+			Skip("PERF environment not set, skipping")
+		}
+
 		var err error
 		cache, err = gmeasure.NewExperimentCache("./compiling-and-running-single-cache")
 		Ω(err).ShouldNot(HaveOccurred())
@@ -50,6 +55,10 @@ var _ = Describe("Compiling and Running multiple tests", func() {
 	var cache gmeasure.ExperimentCache
 
 	BeforeEach(func() {
+		if os.Getenv("PERF") == "" {
+			Skip("PERF environment not set, skipping")
+		}
+
 		var err error
 		cache, err = gmeasure.NewExperimentCache("./compiling-and-running-multiple-cache")
 		Ω(err).ShouldNot(HaveOccurred())

ginkgo/performance/compiling_and_running_test.go

@@ -2,6 +2,7 @@ package performance_test
 
 import (
 	"fmt"
+	"os"
 
 	. "github.com/onsi/ginkgo/v2"
 	. "github.com/onsi/gomega"
@@ -12,6 +13,10 @@ var _ = Describe("Fetching Dependencies", func() {
 	var cache gmeasure.ExperimentCache
 
 	BeforeEach(func() {
+		if os.Getenv("PERF") == "" {
+			Skip("PERF environment not set, skipping")
+		}
+
 		var err error
 		cache, err = gmeasure.NewExperimentCache("./fetching-dependencies-cache")
 		Ω(err).ShouldNot(HaveOccurred())

ginkgo/performance/fetching_dependencies_test.go

@@ -6,7 +6,7 @@ require (
 	github.com/go-logr/logr v1.2.3
 	github.com/go-task/slim-sprig v0.0.0-20210107165309-348f09dbbbc0
 	github.com/google/pprof v0.0.0-20210407192527-94a9f03dee38
-	github.com/onsi/gomega v1.23.0
+	github.com/onsi/gomega v1.24.0
 	golang.org/x/sys v0.1.0
 	golang.org/x/tools v0.2.0
 )

go.mod

@@ -17,8 +17,8 @@ github.com/google/go-cmp v0.5.9/go.mod h1:17dUlkBOakJ0+DkrSSNjCkIjxS6bF9zb3elmeN
 github.com/google/pprof v0.0.0-20210407192527-94a9f03dee38 h1:yAJXTCF9TqKcTiHJAE8dj7HMvPfh66eeA2JYW7eFpSE=
 github.com/google/pprof v0.0.0-20210407192527-94a9f03dee38/go.mod h1:kpwsk12EmLew5upagYY7GY0pfYCcupk39gWOCRROcvE=
 github.com/ianlancetaylor/demangle v0.0.0-20200824232613-28f6c0f3b639/go.mod h1:aSSvb/t6k1mPoxDqO4vJh6VOCGPwU4O0C2/Eqndh1Sc=
-github.com/onsi/gomega v1.23.0 h1:/oxKu9c2HVap+F3PfKort2Hw5DEU+HGlW8n+tguWsys=
-github.com/onsi/gomega v1.23.0/go.mod h1:Z/NWtiqwBrwUt4/2loMmHL63EDLnYHmVbuBpDr2vQAg=
+github.com/onsi/gomega v1.24.0 h1:+0glovB9Jd6z3VR+ScSwQqXVTIfJcGA9UBM8yzQxhqg=
+github.com/onsi/gomega v1.24.0/go.mod h1:Z/NWtiqwBrwUt4/2loMmHL63EDLnYHmVbuBpDr2vQAg=
 github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM=
 github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4=
 github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME=

go.sum

@@ -5,7 +5,6 @@ import (
 	"fmt"
 	remapped "math"
 	_ "math/cmplx"
-	"time"
 
 	. "github.com/onsi/ginkgo/v2"
 	. "github.com/onsi/ginkgo/v2/integration/_fixtures/flags_fixture"
@@ -64,10 +63,6 @@ var _ = Describe("Testing various flags", func() {
 			println("RANDOM_C")
 		})
 
-		It("should honor -slow-spec-threshold", func() {
-			time.Sleep(100 * time.Millisecond)
-		})
-
 		It("should pass in additional arguments after '--' directly to the test process", func() {
 			fmt.Printf("CUSTOM_FLAG: %s", customFlag)
 		})

integration/_fixtures/flags_fixture/flags_test.go

@@ -52,7 +52,7 @@ var _ = Describe("top-level container", func() {
 	})
 
 	It("has By entries", func() {
-		By("registers a hidden AddReportEntry")
+		By("registers a By event")
 		By("includes durations", func() {
 			time.Sleep(time.Millisecond * 100)
 		})

integration/_fixtures/progress_fixture/progress_fixture_suite_test.go

@@ -0,0 +1,67 @@
+package timeline_fixture_test
+
+import (
+	"testing"
+	"time"
+
+	. "github.com/onsi/ginkgo/v2"
+	"github.com/onsi/ginkgo/v2/types"
+	. "github.com/onsi/gomega"
+)
+
+func TestTimelineFixture(t *testing.T) {
+	RegisterFailHandler(Fail)
+	RunSpecs(t, "TimelineFixture Suite")
+}
+
+var _ = Describe("a full timeline", Serial, func() {
+	Describe("a flaky test", func() {
+		BeforeEach(func() {
+			By("logging some events")
+			GinkgoWriter.Println("hello!")
+			AddReportEntry("a report!", "Of {{bold}}great{{/}} value")
+			DeferCleanup(func() {
+				By("cleaning up a bit", func() {
+					time.Sleep(time.Millisecond * 50)
+					GinkgoWriter.Println("all done!")
+				})
+			})
+		})
+
+		i := 0
+
+		It("retries a few times", func() {
+			i += 1
+			GinkgoWriter.Println("let's try...")
+			if i < 3 {
+				Fail("bam!")
+			}
+			GinkgoWriter.Println("hooray!")
+		}, FlakeAttempts(3))
+
+		AfterEach(func() {
+			if i == 3 {
+				GinkgoWriter.Println("feeling sleepy...")
+				time.Sleep(time.Millisecond * 200)
+			}
+		}, PollProgressAfter(time.Millisecond*100))
+	})
+
+	Describe("a test with multiple failures", func() {
+		It("times out", func(ctx SpecContext) {
+			By("waiting...")
+			<-ctx.Done()
+			GinkgoWriter.Println("then failing!")
+			Fail("welp")
+		}, NodeTimeout(time.Millisecond*100))
+
+		AfterEach(func() {
+			panic("aaah!")
+		})
+	})
+
+	It("passes happily", func() {
+		AddReportEntry("a verbose-only report", types.ReportEntryVisibilityFailureOrVerbose)
+		AddReportEntry("a hidden report", types.ReportEntryVisibilityNever)
+	})
+})

integration/_fixtures/progress_fixture/progress_fixture_test.go

@@ -32,11 +32,11 @@ some decorated specs
 		session := startGinkgo(fm.PathTo("decorations", "flaky_repeated"), "-vv", "--no-color")
 		Eventually(session).Should(gexec.Exit(1))
 
-		Ω(session).Should(gbytes.Say("Ginkgo: Attempt #1 Failed.  Retrying..."))
-		Ω(session).Should(gbytes.Say("Ginkgo: Attempt #2 Failed.  Retrying..."))
+		Ω(session).Should(gbytes.Say("Attempt #1 Failed.  Retrying"))
+		Ω(session).Should(gbytes.Say("Attempt #2 Failed.  Retrying"))
 
-		Ω(session).Should(gbytes.Say("Ginkgo: Attempt #1 Passed.  Repeating..."))
-		Ω(session).Should(gbytes.Say("Ginkgo: Attempt #2 Passed.  Repeating..."))
+		Ω(session).Should(gbytes.Say("Attempt #1 Passed.  Repeating"))
+		Ω(session).Should(gbytes.Say("Attempt #2 Passed.  Repeating"))
 		Ω(session).Should(gbytes.Say("failed on attempt #3"))
 	})
 

integration/_fixtures/report_entries_fixture/report_entries_fixture_suite_test.go

@@ -35,9 +35,7 @@ var _ = Describe("Failing Specs", func() {
 			Ω(output).Should(MatchRegexp(`goroutine \d+ \[chan receive\]`), "from the progress report emitted by the timeout")
 			Ω(output).Should(MatchRegexp(`>\s*\<\-c\.Done\(\)`), "from the progress report emitted by the timeout")
 
-			Ω(output).Should(MatchRegexp(`a top level DescribeTable\n.*fail_fixture_test\.go:41`),
-				"the output of a failing DescribeTable should include its file path and line number")
-			Ω(output).Should(MatchRegexp(`\[It\] a TableEntry constructed by Entry\n.*fail_fixture_test\.go:45`),
+			Ω(output).Should(MatchRegexp(`a top level DescribeTable \[It\] a TableEntry constructed by Entry\n.*fail_fixture_test\.go:45`),
 				"the output of a failing Entry should include its file path and line number")
 
 			Ω(output).Should(ContainSubstring("0 Passed | 7 Failed"))

integration/_fixtures/timeline_fixture/timeline_fixture_suite_test.go

@@ -23,7 +23,7 @@ var _ = Describe("Flags Specs", func() {
 		Eventually(session).Should(gexec.Exit(types.GINKGO_FOCUS_EXIT_CODE))
 		output := string(session.Out.Contents())
 
-		Ω(output).Should(ContainSubstring("10 Passed"))
+		Ω(output).Should(ContainSubstring("9 Passed"))
 		Ω(output).Should(ContainSubstring("0 Failed"))
 		Ω(output).Should(ContainSubstring("1 Pending"))
 		Ω(output).Should(ContainSubstring("3 Skipped"))
@@ -60,23 +60,14 @@ var _ = Describe("Flags Specs", func() {
 	})
 
 	It("should randomize tests when told to", func() {
-		session := startGinkgo(fm.PathTo("flags"), "--no-color", "--randomize-all", "--seed=1")
+		session := startGinkgo(fm.PathTo("flags"), "--no-color", "--randomize-all", "--seed=40")
 		Eventually(session).Should(gexec.Exit(types.GINKGO_FOCUS_EXIT_CODE))
 		output := string(session.Out.Contents())
 
 		orders := getRandomOrders(output)
 		Ω(orders[0]).ShouldNot(BeNumerically("<", orders[1]))
 	})
 
-	It("should watch for slow specs", func() {
-		session := startGinkgo(fm.PathTo("flags"), "--slow-spec-threshold=50ms")
-		Eventually(session).Should(gexec.Exit(types.GINKGO_FOCUS_EXIT_CODE))
-		output := string(session.Out.Contents())
-
-		Ω(output).Should(ContainSubstring("SLOW TEST"))
-		Ω(output).Should(ContainSubstring("should honor -slow-spec-threshold"))
-	})
-
 	It("should pass additional arguments in", func() {
 		session := startGinkgo(fm.PathTo("flags"), "--", "--customFlag=madagascar")
 		Eventually(session).Should(gexec.Exit(types.GINKGO_FOCUS_EXIT_CODE))
@@ -154,4 +145,26 @@ var _ = Describe("Flags Specs", func() {
 		Ω(output).Should(ContainSubstring("1 Skipped"))
 		Ω(output).Should(ContainSubstring("1 Passed"))
 	})
+
+	It("should emit node start/end events when running with --show-node-events", func() {
+		session := startGinkgo(fm.PathTo("flags"), "--no-color", "-v", "--show-node-events")
+		Eventually(session).Should(gexec.Exit(types.GINKGO_FOCUS_EXIT_CODE))
+		output := string(session.Out.Contents())
+
+		Eventually(output).Should(ContainSubstring("> Enter [It] should honor -cover"))
+		Eventually(output).Should(ContainSubstring("< Exit [It] should honor -cover"))
+
+		fm.MountFixture("fail")
+		session = startGinkgo(fm.PathTo("fail"), "--no-color", "--show-node-events")
+		Eventually(session).Should(gexec.Exit(1))
+		output = string(session.Out.Contents())
+		Ω(output).Should(ContainSubstring("> Enter [It] a top level specify"))
+		Ω(output).Should(ContainSubstring("< Exit [It] a top level specify"))
+
+		session = startGinkgo(fm.PathTo("fail"), "--no-color")
+		Eventually(session).Should(gexec.Exit(1))
+		output = string(session.Out.Contents())
+		Ω(output).ShouldNot(ContainSubstring("> Enter [It] a top level specify"))
+		Ω(output).ShouldNot(ContainSubstring("< Exit [It] a top level specify"))
+	})
 })

integration/decorations_test.go

@@ -38,8 +38,8 @@ var _ = Describe("OutputInterceptor", func() {
 			Eventually(sess).Should(gexec.Exit(0))
 
 			output := string(sess.Out.Contents())
-			Ω(output).Should(ContainSubstring("    CAPTURED OUTPUT A\n"))
-			Ω(output).Should(ContainSubstring("    CAPTURED OUTPUT B\n"))
+			Ω(output).Should(ContainSubstring("CAPTURED OUTPUT A\n"))
+			Ω(output).Should(ContainSubstring("CAPTURED OUTPUT B\n"))
 
 			Ω(output).ShouldNot(ContainSubstring("OUTPUT TO CONSOLE"))