Skip to content

Commit

Permalink
Ginkgo output now includes a timeline-view of the spec
Browse files Browse the repository at this point in the history
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)`
  • Loading branch information
onsi committed Nov 7, 2022
1 parent c70867a commit db83f33
Show file tree
Hide file tree
Showing 60 changed files with 4,916 additions and 2,341 deletions.
29 changes: 2 additions & 27 deletions core_dsl.go
Original file line number Diff line number Diff line change
Expand Up @@ -21,7 +21,6 @@ import (
"os"
"path/filepath"
"strings"
"time"

"github.com/go-logr/logr"
"github.com/onsi/ginkgo/v2/formatter"
Expand Down Expand Up @@ -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)
Expand Down Expand Up @@ -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...))
}

/*
Expand Down
266 changes: 167 additions & 99 deletions docs/index.md

Large diffs are not rendered by default.

9 changes: 9 additions & 0 deletions ginkgo/performance/compiling_and_running_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -2,6 +2,7 @@ package performance_test

import (
"fmt"
"os"

. "github.com/onsi/ginkgo/v2"
. "github.com/onsi/gomega"
Expand All @@ -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())
Expand Down Expand Up @@ -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())
Expand Down
5 changes: 5 additions & 0 deletions ginkgo/performance/fetching_dependencies_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -2,6 +2,7 @@ package performance_test

import (
"fmt"
"os"

. "github.com/onsi/ginkgo/v2"
. "github.com/onsi/gomega"
Expand All @@ -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())
Expand Down
2 changes: 1 addition & 1 deletion go.mod
Original file line number Diff line number Diff line change
Expand Up @@ -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
)
Expand Down
4 changes: 2 additions & 2 deletions go.sum
Original file line number Diff line number Diff line change
Expand Up @@ -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=
Expand Down
5 changes: 0 additions & 5 deletions integration/_fixtures/flags_fixture/flags_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -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"
Expand Down Expand Up @@ -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)
})
Expand Down

This file was deleted.

49 changes: 0 additions & 49 deletions integration/_fixtures/progress_fixture/progress_fixture_test.go

This file was deleted.

Original file line number Diff line number Diff line change
Expand Up @@ -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)
})
Expand Down
Original file line number Diff line number Diff line change
@@ -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)
})
})
8 changes: 4 additions & 4 deletions integration/decorations_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -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"))
})

Expand Down
4 changes: 1 addition & 3 deletions integration/fail_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -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"))
Expand Down
35 changes: 24 additions & 11 deletions integration/flags_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -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"))
Expand Down Expand Up @@ -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))
Expand Down Expand Up @@ -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"))
})
})
4 changes: 2 additions & 2 deletions integration/output_interceptor_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -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"))

Expand Down
Loading

0 comments on commit db83f33

Please sign in to comment.