Skip to content

Commit

Permalink
AttachProgressReporter allows users to provide arbitrary information …
Browse files Browse the repository at this point in the history
…when a ProgressReport is requested
  • Loading branch information
onsi committed Mar 2, 2023
1 parent da91bbf commit 28801fe
Show file tree
Hide file tree
Showing 11 changed files with 247 additions and 62 deletions.
19 changes: 19 additions & 0 deletions core_dsl.go
Original file line number Diff line number Diff line change
Expand Up @@ -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)
}
32 changes: 30 additions & 2 deletions docs/index.md
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down
1 change: 1 addition & 0 deletions dsl/core/core_dsl.go
Original file line number Diff line number Diff line change
Expand Up @@ -61,3 +61,4 @@ var BeforeAll = ginkgo.BeforeAll
var AfterAll = ginkgo.AfterAll
var DeferCleanup = ginkgo.DeferCleanup
var GinkgoT = ginkgo.GinkgoT
var AttachProgressReporter = ginkgo.AttachProgressReporter
Original file line number Diff line number Diff line change
Expand Up @@ -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")
Expand Down
5 changes: 5 additions & 0 deletions integration/progress_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -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\)`))
Expand Down Expand Up @@ -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`))

})

Expand Down
41 changes: 40 additions & 1 deletion internal/internal_integration/progress_report_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -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() {
Expand Down Expand Up @@ -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"}))
})
})
})
67 changes: 67 additions & 0 deletions internal/progress_reporter_manager.go
Original file line number Diff line number Diff line change
@@ -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
}
55 changes: 55 additions & 0 deletions internal/progress_reporter_manager_test.go
Original file line number Diff line number Diff line change
@@ -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))
})
})
53 changes: 5 additions & 48 deletions internal/spec_context.go
Original file line number Diff line number Diff line change
Expand Up @@ -2,8 +2,6 @@ package internal

import (
"context"
"sort"
"sync"

"github.com/onsi/ginkgo/v2/types"
)
Expand All @@ -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
}
Expand All @@ -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
Expand All @@ -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
}
16 changes: 8 additions & 8 deletions internal/spec_context_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -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())
})
})
Loading

0 comments on commit 28801fe

Please sign in to comment.