diff --git a/core_dsl.go b/core_dsl.go index 0b13b0d22..8b7b6685c 100644 --- a/core_dsl.go +++ b/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) +} diff --git a/docs/index.md b/docs/index.md index 57bd58367..1a94a249c 100644 --- a/docs/index.md +++ b/docs/index.md @@ -2669,11 +2669,11 @@ 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. @@ -2681,6 +2681,34 @@ All Progress Reports generated by Ginkgo - whether interactively via `SIGINFO/SI 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. diff --git a/dsl/core/core_dsl.go b/dsl/core/core_dsl.go index 8314d7d82..927e312cf 100644 --- a/dsl/core/core_dsl.go +++ b/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 diff --git a/integration/_fixtures/progress_report_fixture/progress_report_test.go b/integration/_fixtures/progress_report_fixture/progress_report_test.go index 9669ba0ce..3e0ee4560 100644 --- a/integration/_fixtures/progress_report_fixture/progress_report_test.go +++ b/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") diff --git a/integration/progress_test.go b/integration/progress_test.go index 94c9e54d2..c4b290e82 100644 --- a/integration/progress_test.go +++ 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`)) }) diff --git a/internal/internal_integration/progress_report_test.go b/internal/internal_integration/progress_report_test.go index 60df37cd3..21ffa6500 100644 --- a/internal/internal_integration/progress_report_test.go +++ b/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"})) + }) + }) }) diff --git a/internal/progress_reporter_manager.go b/internal/progress_reporter_manager.go new file mode 100644 index 000000000..bea4771d1 --- /dev/null +++ b/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 +} diff --git a/internal/progress_reporter_manager_test.go b/internal/progress_reporter_manager_test.go new file mode 100644 index 000000000..e635ac2c2 --- /dev/null +++ b/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)) + }) +}) diff --git a/internal/spec_context.go b/internal/spec_context.go index 8f569dd35..2515b84a1 100644 --- a/internal/spec_context.go +++ b/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 -} diff --git a/internal/spec_context_test.go b/internal/spec_context_test.go index aa32954dd..9dddb4fb1 100644 --- a/internal/spec_context_test.go +++ b/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()) }) }) diff --git a/internal/suite.go b/internal/suite.go index 5ddf10072..8f0283ca8 100644 --- a/internal/suite.go +++ b/internal/suite.go @@ -9,6 +9,7 @@ import ( "github.com/onsi/ginkgo/v2/internal/parallel_support" "github.com/onsi/ginkgo/v2/reporters" "github.com/onsi/ginkgo/v2/types" + "golang.org/x/net/context" ) type Phase uint @@ -19,10 +20,14 @@ const ( PhaseRun ) +var PROGRESS_REPORTER_DEADLING = 5 * time.Second + type Suite struct { tree *TreeNode topLevelContainers Nodes + *ProgressReporterManager + phase Phase suiteNodes Nodes @@ -64,8 +69,9 @@ type Suite struct { func NewSuite() *Suite { return &Suite{ - tree: &TreeNode{}, - phase: PhaseBuildTopLevel, + tree: &TreeNode{}, + phase: PhaseBuildTopLevel, + ProgressReporterManager: NewProgressReporterManager(), selectiveLock: &sync.Mutex{}, } @@ -338,10 +344,13 @@ func (suite *Suite) generateProgressReport(fullReport bool) types.ProgressReport suite.selectiveLock.Lock() defer suite.selectiveLock.Unlock() + deadline, cancel := context.WithTimeout(context.Background(), PROGRESS_REPORTER_DEADLING) + defer cancel() var additionalReports []string if suite.currentSpecContext != nil { - additionalReports = suite.currentSpecContext.QueryProgressReporters() + additionalReports = append(additionalReports, suite.currentSpecContext.QueryProgressReporters(deadline)...) } + additionalReports = append(additionalReports, suite.QueryProgressReporters(deadline)...) gwOutput := suite.currentSpecReport.CapturedGinkgoWriterOutput + string(suite.writer.Bytes()) pr, err := NewProgressReport(suite.isRunningInParallel(), suite.currentSpecReport, suite.currentNode, suite.currentNodeStartTime, suite.currentByStep, gwOutput, timelineLocation, additionalReports, suite.config.SourceRoots, fullReport)