AttachProgressReporter allows users to provide arbitrary information when a ProgressReport is requested

Author: onsi

core_dsl.go

@@ -771,3 +771,22 @@ func DeferCleanup(args ...interface{}) {
 	}
 	pushNode(internal.NewCleanupNode(deprecationTracker, fail, args...))
 }
+
+/*
+AttachProgressReporter allows you to register a function that will be called whenever Ginkgo generates a Progress Report.  The contents returned by the function will be included in the report.
+
+Progress Reports are generated:
+- whenever the user explicitly requests one (via `SIGINFO` or `SIGUSR1`)
+- on nodes decorated  with PollProgressAfter
+- on suites run with --poll-progress-after
+- whenever a test times out
+
+Ginkgo uses Progress Reports to convey the current state of the test suite, including any running goroutines.  By attaching a progress reporter you are able to supplement these reports with additional information.
+
+# AttachProgressReporter returns a function that can be called to detach the progress reporter
+
+You can learn more about AttachProgressReporter here: https://onsi.github.io/ginkgo/#attaching-additional-information-to-progress-reports
+*/
+func AttachProgressReporter(reporter func() string) func() {
+	return global.Suite.AttachProgressReporter(reporter)
+}

docs/index.md

@@ -2669,18 +2669,46 @@ Stepping back - it bears repeating: you should use `FlakeAttempts` judiciously.
 ### 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.
 
-Ginkgo can provide a **Progress Report** of what is currently running in response to the `SIGINFO` and `SIGUSR1` signals.  The Progress Report includes information about which node is currently running and the exact line of code that it is currently executing, along with any relevant goroutines that were launched by the spec.  The report also includes the 10 most recent lines written to the `GinkgoWriter`.  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; if you're on linux you'll need to send `SIGUSR1` to the actual test process spanwed by `ginkgo` - not the `ginkgo` cli process itself).
+Ginkgo can provide a **Progress Report** of what is currently running in response to the `SIGINFO` and `SIGUSR1` signals.  The Progress Report includes information about which node is currently running and the exact line of code that it is currently executing, along with any relevant goroutines that were launched by the spec.  The report also includes the 10 most recent lines written to the `GinkgoWriter`.  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; if you're on linux you'll need to send `SIGUSR1` to the actual test process spawned by `ginkgo` - not the `ginkgo` cli process itself).
 
 These Progress Reports can also show you a preview of the running source code, but only if Ginkgo can find your source files.  If need be you can tell Ginkgo where to look for source files by specifying `--source-root`.
 
-Finally - you can instruct Ginkgo to provide these Progress Reports automatically 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.  
+Finally - you can instruct Ginkgo to provide  Progress Reports automatically 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 override 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.
 
 All Progress Reports generated by Ginkgo - whether interactively via `SIGINFO/SIGUSR1` or automatically via the `PollProgressAfter` configuration - also appear in Ginkgo's [machine-readable reports](#generating-machine-readable-reports).
 
 In addition to these formal Progress Reports, Ginkgo tracks whenever a node begins and ends.  These node `> Enter` and `< Exit` events are usually only logged in the spec's timeline when running with `-vv`, however you can turn them on for other verbosity modes using the `--show-node-events` flag.
 
+#### Attaching Additional Information to Progress Reports
+
+Ginkgo also allows you to attach Progress Report providers to provide additional information when a progress report is generated.  For example, these could query the system under test for diagnostic information about its internal state and report back.  You attach these providers via `AttachProgressReporter`.  For example:
+
+```go
+AttachProgressReporter(func() string {
+  libraryState := library.GetStatusReport()
+  return fmt.Sprintf("%s: %s", library.ClientID, libraryState.Summary)
+})
+```
+
+`AttachProgressReporter` returns a `cancel` func that you can call to unregister the progress reporter.  This allow you to do things like:
+
+```go
+BeforeEach(func() {
+  library = libraryClient.ConnectAs("Jean ValJean")
+  
+  //we attach a progress reporter and can trust that it will be cleaned up after the spec runs
+  DeferCleanup(AttachProgressReporter(func() string {
+    libraryState := library.GetStatusReport()
+    return fmt.Sprintf("%s: %s", library.ClientID, libraryState.Summary)
+  }))
+})
+```
+
+Note that the functions called by `AttachProgressReporter` must not block.  Ginkgo currently has a hard-coded 5 second limit.  If all attached progress reporters take longer than 5 seconds to report back, Ginkgo will move on so as to prevent the suite from blocking.
+
+
 ### Spec Timeouts and Interruptible Nodes
 
 Sometimes specs get stuck.  Perhaps a network call is running slowly; or a newly introduced bug has caused an asynchronous process the test is relying on to hang.  It's important, in such cases, to be able to set a deadline for a given spec or node and require the spec/node to complete before the deadline has elapsed.

dsl/core/core_dsl.go

@@ -61,3 +61,4 @@ var BeforeAll = ginkgo.BeforeAll
 var AfterAll = ginkgo.AfterAll
 var DeferCleanup = ginkgo.DeferCleanup
 var GinkgoT = ginkgo.GinkgoT
+var AttachProgressReporter = ginkgo.AttachProgressReporter

integration/_fixtures/progress_report_fixture/progress_report_test.go

@@ -9,6 +9,11 @@ import (
 )
 
 var _ = Describe("ProgressReport", func() {
+	BeforeEach(func() {
+		DeferCleanup(AttachProgressReporter(func() string {
+			return fmt.Sprintf("Some global information: %d", GinkgoParallelProcess())
+		}))
+	})
 	It("can track on demand", func() {
 		By("Step A")
 		By("Step B")

integration/progress_test.go

@@ -46,6 +46,9 @@ var _ = Describe("Emitting progress", func() {
 			//first poll
 			Eventually(session).Should(gbytes.Say(`--poll-progress-after tracks things that take too long \(Spec Runtime: 1\.5\d*s\)`))
 			Eventually(session).Should(gbytes.Say(`>\s*time.Sleep\(2 \* time\.Second\)`))
+			Eventually(session).Should(gbytes.Say(`Begin Additional Progress Reports >>`))
+			Eventually(session).Should(gbytes.Say(`Some global information: 1`))
+			Eventually(session).Should(gbytes.Say(`<< End Additional Progress Reports`))
 
 			//second poll
 			Eventually(session).Should(gbytes.Say(`--poll-progress-after tracks things that take too long \(Spec Runtime: 1\.7\d*s\)`))
@@ -88,6 +91,8 @@ var _ = Describe("Emitting progress", func() {
 
 			Eventually(session.Out.Contents()).Should(ContainSubstring(`Progress Report for Ginkgo Process #1`))
 			Eventually(session.Out.Contents()).Should(ContainSubstring(`Progress Report for Ginkgo Process #2`))
+			Eventually(session.Out.Contents()).Should(ContainSubstring(`Some global information: 1`))
+			Eventually(session.Out.Contents()).Should(ContainSubstring(`Some global information: 2`))
 
 		})
 

internal/internal_integration/progress_report_test.go

@@ -305,7 +305,7 @@ var _ = Describe("Progress Reporting", func() {
 		})
 	})
 
-	Context("when a test takes longer then the overriden PollProgressAfter", func() {
+	Context("when a test takes longer then the overridden PollProgressAfter", func() {
 		BeforeEach(func() {
 			success, _ := RunFixture("emitting spec progress", func() {
 				Describe("a container", func() {
@@ -439,4 +439,43 @@ var _ = Describe("Progress Reporting", func() {
 			Ω(pr.AdditionalReports).Should(BeEmpty())
 		})
 	})
+
+	Context("when a global progress report provider has been registered", func() {
+		BeforeEach(func() {
+			success, _ := RunFixture("emitting spec progress", func() {
+				Describe("a container", func() {
+					It("A", func(ctx SpecContext) {
+						cancelGlobal := AttachProgressReporter(func() string { return "Some Global Information" })
+						AttachProgressReporter(func() string { return "Some More (Never Cancelled) Global Information" })
+						ctx.AttachProgressReporter(func() string { return "Some Additional Information" })
+						cl = types.NewCodeLocation(0)
+						triggerProgressSignal()
+						cancelGlobal()
+						triggerProgressSignal()
+					})
+
+					It("B", func() {
+						triggerProgressSignal()
+					})
+				})
+			})
+			Ω(success).Should(BeTrue())
+		})
+
+		It("includes information from that progress report provider", func() {
+			Ω(reporter.ProgressReports).Should(HaveLen(3))
+			pr := reporter.ProgressReports[0]
+
+			Ω(pr.LeafNodeText).Should(Equal("A"))
+			Ω(pr.AdditionalReports).Should(Equal([]string{"Some Additional Information", "Some Global Information", "Some More (Never Cancelled) Global Information"}))
+
+			pr = reporter.ProgressReports[1]
+			Ω(pr.LeafNodeText).Should(Equal("A"))
+			Ω(pr.AdditionalReports).Should(Equal([]string{"Some Additional Information", "Some More (Never Cancelled) Global Information"}))
+
+			pr = reporter.ProgressReports[2]
+			Ω(pr.LeafNodeText).Should(Equal("B"))
+			Ω(pr.AdditionalReports).Should(Equal([]string{"Some More (Never Cancelled) Global Information"}))
+		})
+	})
 })

internal/progress_reporter_manager.go

@@ -0,0 +1,67 @@
+package internal
+
+import (
+	"context"
+	"sort"
+	"sync"
+)
+
+type ProgressReporterManager struct {
+	lock              *sync.Mutex
+	progressReporters map[int]func() string
+	prCounter         int
+}
+
+func NewProgressReporterManager() *ProgressReporterManager {
+	return &ProgressReporterManager{
+		progressReporters: map[int]func() string{},
+		lock:              &sync.Mutex{},
+	}
+}
+
+func (prm *ProgressReporterManager) AttachProgressReporter(reporter func() string) func() {
+	prm.lock.Lock()
+	defer prm.lock.Unlock()
+	prm.prCounter += 1
+	prCounter := prm.prCounter
+	prm.progressReporters[prCounter] = reporter
+
+	return func() {
+		prm.lock.Lock()
+		defer prm.lock.Unlock()
+		delete(prm.progressReporters, prCounter)
+	}
+}
+
+func (prm *ProgressReporterManager) QueryProgressReporters(ctx context.Context) []string {
+	prm.lock.Lock()
+	keys := []int{}
+	for key := range prm.progressReporters {
+		keys = append(keys, key)
+	}
+	sort.Ints(keys)
+	reporters := []func() string{}
+	for _, key := range keys {
+		reporters = append(reporters, prm.progressReporters[key])
+	}
+	prm.lock.Unlock()
+
+	if len(reporters) == 0 {
+		return nil
+	}
+	out := []string{}
+	for _, reporter := range reporters {
+		reportC := make(chan string, 1)
+		go func() {
+			reportC <- reporter()
+		}()
+		var report string
+		select {
+		case report = <-reportC:
+		case <-ctx.Done():
+			return out
+		}
+		out = append(out, report)
+	}
+	return out
+}

internal/progress_reporter_manager_test.go

@@ -0,0 +1,55 @@
+package internal_test
+
+import (
+	"context"
+	"time"
+
+	. "github.com/onsi/ginkgo/v2"
+	. "github.com/onsi/gomega"
+	"github.com/onsi/gomega/gleak"
+
+	"github.com/onsi/ginkgo/v2/internal"
+)
+
+var _ = Describe("ProgressReporterManager", func() {
+	var manager *internal.ProgressReporterManager
+
+	BeforeEach(func() {
+		manager = internal.NewProgressReporterManager()
+	})
+
+	It("can attach and detach progress reporters", func() {
+		Ω(manager.QueryProgressReporters(context.Background())).Should(BeEmpty())
+		cancelA := manager.AttachProgressReporter(func() string { return "A" })
+		Ω(manager.QueryProgressReporters(context.Background())).Should(Equal([]string{"A"}))
+		cancelB := manager.AttachProgressReporter(func() string { return "B" })
+		Ω(manager.QueryProgressReporters(context.Background())).Should(Equal([]string{"A", "B"}))
+		cancelC := manager.AttachProgressReporter(func() string { return "C" })
+		Ω(manager.QueryProgressReporters(context.Background())).Should(Equal([]string{"A", "B", "C"}))
+		cancelB()
+		Ω(manager.QueryProgressReporters(context.Background())).Should(Equal([]string{"A", "C"}))
+		cancelA()
+		Ω(manager.QueryProgressReporters(context.Background())).Should(Equal([]string{"C"}))
+		cancelC()
+		Ω(manager.QueryProgressReporters(context.Background())).Should(BeEmpty())
+	})
+
+	It("bails if a progress reporter takes longer than the passed-in context's deadline", func() {
+		startingGoroutines := gleak.Goroutines()
+		c := make(chan struct{})
+		manager.AttachProgressReporter(func() string { return "A" })
+		manager.AttachProgressReporter(func() string { return "B" })
+		manager.AttachProgressReporter(func() string {
+			<-c
+			return "C"
+		})
+		manager.AttachProgressReporter(func() string { return "D" })
+		context, cancel := context.WithTimeout(context.Background(), time.Millisecond*100)
+		result := manager.QueryProgressReporters(context)
+		Ω(result).Should(Equal([]string{"A", "B"}))
+		cancel()
+		close(c)
+
+		Eventually(gleak.Goroutines).ShouldNot(gleak.HaveLeaked(startingGoroutines))
+	})
+})

internal/spec_context.go

@@ -2,8 +2,6 @@ package internal
 
 import (
 	"context"
-	"sort"
-	"sync"
 
 	"github.com/onsi/ginkgo/v2/types"
 )
@@ -17,11 +15,9 @@ type SpecContext interface {
 
 type specContext struct {
 	context.Context
+	*ProgressReporterManager
 
-	cancel            context.CancelFunc
-	lock              *sync.Mutex
-	progressReporters map[int]func() string
-	prCounter         int
+	cancel context.CancelFunc
 
 	suite *Suite
 }
@@ -36,11 +32,9 @@ This is because Ginkgo needs finer control over when the context is canceled.  S
 func NewSpecContext(suite *Suite) *specContext {
 	ctx, cancel := context.WithCancel(context.Background())
 	sc := &specContext{
-		cancel:            cancel,
-		suite:             suite,
-		lock:              &sync.Mutex{},
-		prCounter:         0,
-		progressReporters: map[int]func() string{},
+		cancel:                  cancel,
+		suite:                   suite,
+		ProgressReporterManager: NewProgressReporterManager(),
 	}
 	ctx = context.WithValue(ctx, "GINKGO_SPEC_CONTEXT", sc) //yes, yes, the go docs say don't use a string for a key... but we'd rather avoid a circular dependency between Gomega and Ginkgo
 	sc.Context = ctx                                        //thank goodness for garbage collectors that can handle circular dependencies
@@ -51,40 +45,3 @@ func NewSpecContext(suite *Suite) *specContext {
 func (sc *specContext) SpecReport() types.SpecReport {
 	return sc.suite.CurrentSpecReport()
 }
-
-func (sc *specContext) AttachProgressReporter(reporter func() string) func() {
-	sc.lock.Lock()
-	defer sc.lock.Unlock()
-	sc.prCounter += 1
-	prCounter := sc.prCounter
-	sc.progressReporters[prCounter] = reporter
-
-	return func() {
-		sc.lock.Lock()
-		defer sc.lock.Unlock()
-		delete(sc.progressReporters, prCounter)
-	}
-}
-
-func (sc *specContext) QueryProgressReporters() []string {
-	sc.lock.Lock()
-	keys := []int{}
-	for key := range sc.progressReporters {
-		keys = append(keys, key)
-	}
-	sort.Ints(keys)
-	reporters := []func() string{}
-	for _, key := range keys {
-		reporters = append(reporters, sc.progressReporters[key])
-	}
-	sc.lock.Unlock()
-
-	if len(reporters) == 0 {
-		return nil
-	}
-	out := []string{}
-	for _, reporter := range reporters {
-		out = append(out, reporter())
-	}
-	return out
-}

internal/spec_context_test.go

@@ -25,25 +25,25 @@ var _ = Describe("SpecContext", func() {
 	It("can attach and detach progress reporters", func(c SpecContext) {
 		type CompleteSpecContext interface {
 			AttachProgressReporter(func() string) func()
-			QueryProgressReporters() []string
+			QueryProgressReporters(ctx context.Context) []string
 		}
 
 		wrappedC := context.WithValue(c, "foo", "bar")
 		ctx := wrappedC.Value("GINKGO_SPEC_CONTEXT").(CompleteSpecContext)
 
-		Ω(ctx.QueryProgressReporters()).Should(BeEmpty())
+		Ω(ctx.QueryProgressReporters(context.Background())).Should(BeEmpty())
 
 		cancelA := ctx.AttachProgressReporter(func() string { return "A" })
-		Ω(ctx.QueryProgressReporters()).Should(Equal([]string{"A"}))
+		Ω(ctx.QueryProgressReporters(context.Background())).Should(Equal([]string{"A"}))
 		cancelB := ctx.AttachProgressReporter(func() string { return "B" })
-		Ω(ctx.QueryProgressReporters()).Should(Equal([]string{"A", "B"}))
+		Ω(ctx.QueryProgressReporters(context.Background())).Should(Equal([]string{"A", "B"}))
 		cancelC := ctx.AttachProgressReporter(func() string { return "C" })
-		Ω(ctx.QueryProgressReporters()).Should(Equal([]string{"A", "B", "C"}))
+		Ω(ctx.QueryProgressReporters(context.Background())).Should(Equal([]string{"A", "B", "C"}))
 		cancelB()
-		Ω(ctx.QueryProgressReporters()).Should(Equal([]string{"A", "C"}))
+		Ω(ctx.QueryProgressReporters(context.Background())).Should(Equal([]string{"A", "C"}))
 		cancelA()
-		Ω(ctx.QueryProgressReporters()).Should(Equal([]string{"C"}))
+		Ω(ctx.QueryProgressReporters(context.Background())).Should(Equal([]string{"C"}))
 		cancelC()
-		Ω(ctx.QueryProgressReporters()).Should(BeEmpty())
+		Ω(ctx.QueryProgressReporters(context.Background())).Should(BeEmpty())
 	})
 })