Generate real-time Progress Reports

Progress Reports point the user at the current running line of code, including a preview of the actual source code. They include a best guess at any relevant goroutines.

A Progress Report can be generated at any time by sending Ginkgo a SIGINFO (^T on MacOS) or SIGUSR1.

In addition, the user can specify --poll-progress-after and --poll-progress-interval to have Ginkgo start periodically emitting progress reports if a given node takes too long.
These can be overriden/set on a per-node basis with the PollProgressAfter and PollProgressInterval decorators.

Ginkgo also uses this progress reporting infrastructure under the hood when handling timeouts and interrupts.  This yields much more focused, useful, and informative stack traces than previously.

core_dsl.go

@@ -277,7 +277,7 @@ func RunSpecs(t GinkgoTestingT, description string, args ...interface{}) bool {
 	suitePath, err = filepath.Abs(suitePath)
 	exitIfErr(err)
 
-	passed, hasFocusedTests := global.Suite.Run(description, suiteLabels, suitePath, global.Failer, reporter, writer, outputInterceptor, interrupt_handler.NewInterruptHandler(suiteConfig.Timeout, client), client, suiteConfig)
+	passed, hasFocusedTests := global.Suite.Run(description, suiteLabels, suitePath, global.Failer, reporter, writer, outputInterceptor, interrupt_handler.NewInterruptHandler(suiteConfig.Timeout, client), client, internal.RegisterForProgressSignal, suiteConfig)
 	outputInterceptor.Shutdown()
 
 	flagSet.ValidateDeprecations(deprecationTracker)
@@ -504,6 +504,11 @@ func By(text string, callback ...func()) {
 		Text: text,
 	}
 	t := time.Now()
+	global.Suite.SetProgressStepCursor(internal.ProgressStepCursor{
+		Name:         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)))
@@ -525,8 +530,10 @@ You may only register *one* BeforeSuite handler per test suite.  You typically d
 You cannot nest any other Ginkgo nodes within a BeforeSuite node's closure.
 You can learn more here: https://onsi.github.io/ginkgo/#suite-setup-and-cleanup-beforesuite-and-aftersuite
 */
-func BeforeSuite(body func()) bool {
-	return pushNode(internal.NewNode(deprecationTracker, types.NodeTypeBeforeSuite, "", body))
+func BeforeSuite(body func(), args ...interface{}) bool {
+	combinedArgs := []interface{}{body}
+	combinedArgs = append(combinedArgs, args...)
+	return pushNode(internal.NewNode(deprecationTracker, types.NodeTypeBeforeSuite, "", combinedArgs...))
 }
 
 /*
@@ -540,8 +547,10 @@ You may only register *one* AfterSuite handler per test suite.  You typically do
 You cannot nest any other Ginkgo nodes within an AfterSuite node's closure.
 You can learn more here: https://onsi.github.io/ginkgo/#suite-setup-and-cleanup-beforesuite-and-aftersuite
 */
-func AfterSuite(body func()) bool {
-	return pushNode(internal.NewNode(deprecationTracker, types.NodeTypeAfterSuite, "", body))
+func AfterSuite(body func(), args ...interface{}) bool {
+	combinedArgs := []interface{}{body}
+	combinedArgs = append(combinedArgs, args...)
+	return pushNode(internal.NewNode(deprecationTracker, types.NodeTypeAfterSuite, "", combinedArgs...))
 }
 
 /*
@@ -563,8 +572,11 @@ The byte array returned by the first function is then passed to the second funct
 You cannot nest any other Ginkgo nodes within an SynchronizedBeforeSuite node's closure.
 You can learn more, and see some examples, here: https://onsi.github.io/ginkgo/#parallel-suite-setup-and-cleanup-synchronizedbeforesuite-and-synchronizedaftersuite
 */
-func SynchronizedBeforeSuite(process1Body func() []byte, allProcessBody func([]byte)) bool {
-	return pushNode(internal.NewSynchronizedBeforeSuiteNode(process1Body, allProcessBody, types.NewCodeLocation(1)))
+func SynchronizedBeforeSuite(process1Body func() []byte, allProcessBody func([]byte), args ...interface{}) bool {
+	combinedArgs := []interface{}{process1Body, allProcessBody}
+	combinedArgs = append(combinedArgs, args...)
+
+	return pushNode(internal.NewNode(deprecationTracker, types.NodeTypeSynchronizedBeforeSuite, "", combinedArgs...))
 }
 
 /*
@@ -580,8 +592,11 @@ Note that you can also use DeferCleanup() in SynchronizedBeforeSuite to accompli
 You cannot nest any other Ginkgo nodes within an SynchronizedAfterSuite node's closure.
 You can learn more, and see some examples, here: https://onsi.github.io/ginkgo/#parallel-suite-setup-and-cleanup-synchronizedbeforesuite-and-synchronizedaftersuite
 */
-func SynchronizedAfterSuite(allProcessBody func(), process1Body func()) bool {
-	return pushNode(internal.NewSynchronizedAfterSuiteNode(allProcessBody, process1Body, types.NewCodeLocation(1)))
+func SynchronizedAfterSuite(allProcessBody func(), process1Body func(), args ...interface{}) bool {
+	combinedArgs := []interface{}{allProcessBody, process1Body}
+	combinedArgs = append(combinedArgs, args...)
+
+	return pushNode(internal.NewNode(deprecationTracker, types.NodeTypeSynchronizedAfterSuite, "", combinedArgs...))
 }
 
 /*

decorator_dsl.go

@@ -81,6 +81,20 @@ You can learn more here: https://onsi.github.io/ginkgo/#spec-labels
 */
 type Labels = internal.Labels
 
+/*
+PollProgressAfter allows you to override the configured value for --poll-progress-after for a particular node.
+
+Ginkgo will start emitting node progress if the node is still running after a duration of PollProgressAfter.  This allows you to get quicker feedback about the state of a long-running spec.
+*/
+type PollProgressAfter = internal.PollProgressAfter
+
+/*
+PollProgressInterval allows you to override the configured value for --poll-progress-interval for a particular node.
+
+Once a node has been running for longer than PollProgressAfter Ginkgo will emit node progress periodically at an interval of PollProgresInterval.
+*/
+type PollProgressInterval = internal.PollProgressInterval
+
 /*
 SuppressProgressReporting is a decorator that allows you to disable progress reporting of a particular node.  This is useful if `ginkgo -v -progress` is generating too much noise; particularly
 if you have a `ReportAfterEach` node that is running for every skipped spec and is generating lots of progress reports.

docs/index.md

@@ -2540,6 +2540,8 @@ All three mechanisms have same effects.  They:
 
 In short, Ginkgo does its best to cleanup and emit as much information as possible about the suite before shutting down.  If, during cleanup, any cleanup node closures get stuck Ginkgo allows you to interrupt them via subsequent interrupt signals.  In the case of a timeout, Ginkgo sends these repeat interrupt signals itself to make sure the suite shuts down eventually.
 
+If you want to get information about what is currently running in a suite _without_ interrupting it, check out the [Getting Visibility Into Long-Running Specs](#getting-visibility-into-long-running-specs) section below.
+
 ### Running Multiple Suites
 
 So far we've covered writing and running specs in individual suites.  Of course, the `ginkgo` CLI also supports running multiple suites with a single invocation on the command line.  We'll close out this chapter on running specs by covering how Ginkgo runs multiple suites.
@@ -2611,11 +2613,7 @@ The two verbose settings are most helpful when debugging spec suites.  They make
 
 When you [filter specs](#filtering-specs) using Ginkgo's various filtering mechanism Ginkgo usually emits a single cyan `S` for each skipped spec (the only exception is specs skipped with `Skip(<message>)` - Ginkgo emits the message for those specs.  You can circumvent this with `Skip("")`).  If you run with the very-verbose setting, however, Ginkgo will emit the description and location information of every skipped spec.  This can be useful if you need to debug your filter queries and can be paired with `--dry-run`.
 
-There are a couple more flags that are verbosity-related but can be controlled independently from the verbosity mode:
-
-First, you can tell Ginkgo to always emit the `GinkgoWriter` output of every spec with `--always-emit-ginkgo-writer`.  This will emit `GinkgoWriter` output for both failed _and_ passing specs, regardless of verbosity setting.
-
-Second, you can tell Ginkgo to emit progress of a spec as Ginkgo runs each of its node closures.  You do this with `ginkgo --progress -v` (or `-vv`).  `--progress` will emit a message to the `GinkgoWriter` just before a node starts running.  By running with `-v` or `-vv` you can then stream the output to the `GinkgoWriter` immediately.  `--progress` was initially introduced to help debug specs that are stuck/hanging but is no longer strictly necessary as Ginkgo's behavior during an interrupt has matured and now generally has enough information to help you identify where a spec is stuck.  If you, nonetheless, want to run with `--progress` but want to suppress output of individual nodes (e.g. a top-level `ReportAfterEach` that always runs even if a spec is skipped) you can pass the `SuppressProgressOuput` decorator to the node in question.
+Finally, you can tell Ginkgo to always emit the `GinkgoWriter` output of every spec with `--always-emit-ginkgo-writer`.  This will emit `GinkgoWriter` output for both failed _and_ passing specs, regardless of verbosity setting.
 
 #### Other Settings
 Here are a grab bag of other settings:
@@ -2626,6 +2624,17 @@ By default, Ginkgo calls out specs that are running slowly if they exceed a cert
 
 By default, Ginkgo only emits full stack traces when a spec panics.  When a normal assertion failure occurs, Ginkgo simply emits the line at which the failure occurred.  You can, instead, have Ginkgo always emit the full stack trace by running `ginkgo --trace`.
 
+### Getting Visibility Into Long-Running Specs
+Ginkgo is often used to build large, complex, integration suites and it is a common - if painful - experience for these suites to run slowly.  Ginkgo provides numerous mechanisms that enable developers to get visibility into what part of a suite is running and where, precisely, a spec may be lagging or hanging.
+
+First, you can tell Ginkgo to emit progress of a spec as Ginkgo runs each of its nodes.  You do this with `ginkgo --progress -v`.  `--progress` will emit a message to the `GinkgoWriter` just before a node starts running.  By running with `-v` or `-vv` you can then stream the output to the `GinkgoWriter` immediately - this can help developers debugging a suite understand exactly which node is running in real-time.  If you want to run with `--progress` but want to suppress output of individual nodes (e.g. a top-level `ReportAfterEach` that always runs even if a spec is skipped) you can pass the `SuppressProgressOuput` decorator to the node in question.
+
+Second, Ginkgo can provide a **Progress Report** of what is currently running in response to the `SIGINFO` and `SIGUSR1` signals.  This improves on the behavior of `--progress` by telling you not just which node is running but exactly which line of spec code is currently running along with any relevant goroutines that were launched by the spec.  A developer waiting for a stuck spec can get this information immediately by sending either the `SIGINFO` or `SIGUSR1` signal (on MacOS/BSD systems, `SIGINFO` can be sent via `^T` - making it especially convenient).
+
+Finally - you can instruct Ginkgo to provide these Progress Reports whenever a node takes too long to complete.  You do this by passing the `--poll-progress-after=INTERVAL` flag to specify how long Ginkgo should wait before emitting a progress report.  Once this interval is passed Ginkgo can periodically emit Progress Reports - the interval between these reports is controlled via the `--poll-progress-interval=INTERVAL` flag.  By default `--poll-progress-after` is set to `0` and so Ginkgo does not emit Progress Reports.  
+
+You can ovveride the global setting of `poll-progess-after` and `poll-progress-interval` on a per-node basis by using the `PollProgressAfter(INTERVAL)` and `PollProgressInterval(INTERVAL)` decorators.  A value of `0` will explicitly turn off Progress Reports for a given node regardless of the global setting.
+
 ### Reporting Infrastructure
 Ginkgo's console output is great when running specs on the console or quickly grokking a CI run.  Of course, there are several contexts where generating a machine-readable report is crucial.  Ginkgo provides first-class CLI support for generating and aggregating reports in a number of machine-readable formats _and_ an extensible reporting infrastructure to enable additional formats and custom reporting.  We'll dig into these topics in the next few sections.
 
@@ -4279,7 +4288,7 @@ The `Label` decorator applies to container nodes and subject nodes only.  It is
 
 Labels can be used to control which subset of tests to run.  This is done by providing the `--label-filter` flag to the `ginkgo` CLI.  More details can be found at [Spec Labels](#spec-labels).
 
-#### The Focus and Pending Decorator
+#### The Focus and Pending Decorators
 The `Focus` and `Pending` decorators apply to container nodes and subject nodes only.  It is an error to try to `Focus` or `Pending` a setup node.
 
 Using these decorators is identical to using the `FX` or `PX` form of the node constructor.  For example:
@@ -4382,6 +4391,12 @@ ReportAfterEach(func(report SpecReport) {
 }, SuppressProgressReporting)
 ```
 
+#### The PollProgressAfter and PollProgressInterval Decorators
+
+As described in the [Getting Visibility Into Long-Running Specs](#getting-visibility-into-long-running-specs) section, the globally specified values for `--poll-progress-after` and `--poll-progress-interval` can be overridden on a particular node using the `PollProgressAfter(INTERVAL)` and `PollProgressInterval(INTERVAL)` decorators.  Here, `INTERVAL` is a `time.Duration` and when specified Ginkgo will start emitting Progress Reports for the node after a duration of `PollProgressAfter` and will repeatedly emit a Progress Report at an interval of `PollProgressInterval`.  To turn off progress reporting for a given node, set `PollProgressAfter` to `0`.
+
+Both of these decorators can only be used on subject and setup nodes, not container nodes.
+
 ## Ginkgo CLI Overview
 
 This chapter provides a quick overview and tour of the Ginkgo CLI.  For comprehensive details about all of the Ginkgo CLI's flags, run `ginkgo help`.  To get information about Ginkgo's implicit `run` command (i.e. what you get when you just run `ginkgo`) run `ginkgo help run`.

dsl/decorators/decorators_dsl.go

@@ -19,6 +19,8 @@ import (
 type Offset = ginkgo.Offset
 type FlakeAttempts = ginkgo.FlakeAttempts
 type Labels = ginkgo.Labels
+type PollProgressAfter = ginkgo.PollProgressAfter
+type PollProgressInterval = ginkgo.PollProgressInterval
 
 const Focus = ginkgo.Focus
 const Pending = ginkgo.Pending

integration/_fixtures/progress_reporter_fixture/progress_reporter_fixture_suite_test.go

@@ -0,0 +1,13 @@
+package progress_reporter_fixture_test
+
+import (
+	"testing"
+
+	. "github.com/onsi/ginkgo/v2"
+	. "github.com/onsi/gomega"
+)
+
+func TestProgressReporterFixture(t *testing.T) {
+	RegisterFailHandler(Fail)
+	RunSpecs(t, "ProgressReporterFixture Suite")
+}

integration/_fixtures/progress_reporter_fixture/progress_reporter_test.go

@@ -0,0 +1,26 @@
+package progress_reporter_fixture_test
+
+import (
+	"fmt"
+	"os"
+	"time"
+
+	. "github.com/onsi/ginkgo/v2"
+)
+
+var _ = Describe("ProgressReporter", func() {
+	It("can track on demand", func() {
+		By("Step A")
+		By("Step B")
+		fmt.Printf("READY %d\n", os.Getpid())
+		time.Sleep(time.Second)
+	})
+
+	It("--poll-progress-after tracks things that take too long", Label("parallel"), func() {
+		time.Sleep(2 * time.Second)
+	})
+
+	It("decorator tracks things that take too long", Label("parallel"), func() {
+		time.Sleep(1 * time.Second)
+	}, PollProgressAfter(500*time.Millisecond))
+})

integration/interrupt_test.go

@@ -44,8 +44,12 @@ var _ = Describe("Interrupt and Timeout", func() {
 		It("should report where the suite was interrupted", func() {
 			Ω(session).Should(gbytes.Say(`\[INTERRUPTED\]`))
 			Ω(session).Should(gbytes.Say(`Interrupted by User`))
-			Ω(session).Should(gbytes.Say(`Here's a stack trace of all running goroutines:`))
-			Ω(session).Should(gbytes.Say(`\[It\] .*hanging_test.go:24`))
+			Ω(session).Should(gbytes.Say(`Here is the current progress of this Ginkgo process, and the stack of running goroutines:`))
+			Ω(session).Should(gbytes.Say(`Spec Goroutine`))
+			Ω(session).Should(gbytes.Say(`goroutine \d+ \[sleep\]`))
+			Ω(session).Should(gbytes.Say(`>\s*time\.Sleep\(time\.Hour\)`), "The actual source code gets emitted now")
+			Ω(session).Should(gbytes.Say(`Other Goroutines`))
+			Ω(session).Should(gbytes.Say(`main\.main\(\)`))
 		})
 
 		It("should run the AfterEach and the AfterSuite", func() {
@@ -71,8 +75,12 @@ var _ = Describe("Interrupt and Timeout", func() {
 		It("should report where and why the suite was interrupted", func() {
 			Ω(session).Should(gbytes.Say(`\[INTERRUPTED\]`))
 			Ω(session).Should(gbytes.Say(`Interrupted by Timeout`))
-			Ω(session).Should(gbytes.Say(`Here's a stack trace of all running goroutines:`))
-			Ω(session).Should(gbytes.Say(`\[It\] .*hanging_test.go:24`))
+			Ω(session).Should(gbytes.Say(`Here is the current progress of this Ginkgo process, and the stack of running goroutines:`))
+			Ω(session).Should(gbytes.Say(`Spec Goroutine`))
+			Ω(session).Should(gbytes.Say(`goroutine \d+ \[sleep\]`))
+			Ω(session).Should(gbytes.Say(`>\s*time\.Sleep\(time\.Hour\)`), "The actual source code gets emitted now")
+			Ω(session).Should(gbytes.Say(`Other Goroutines`))
+			Ω(session).Should(gbytes.Say(`main\.main\(\)`))
 		})
 
 		It("should run the AfterEach and the AfterSuite", func() {