10 most recent GinkgoWriter lines are now emitted in the progress report

docs/index.md

@@ -2629,9 +2629,9 @@ Ginkgo is often used to build large, complex, integration suites and it is a com
 
 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; 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).
+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.  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).
 
-These Progress Reports can also show you a preview of the running source code, but only if Ginkgo can find your source files.  If you are running a precompiled test suite you can tell Ginkgo where to look for source files by specifying `--source-root`.
+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 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.  
 

integration/_fixtures/progress_report_fixture/progress_report_fixture_suite_test.go

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

integration/_fixtures/progress_reporter_fixture/progress_reporter_test.go → integration/_fixtures/progress_report_fixture/progress_report_test.go

@@ -1,4 +1,4 @@
-package progress_reporter_fixture_test
+package progress_report_fixture_test
 
 import (
 	"fmt"
@@ -8,10 +8,13 @@ import (
 	. "github.com/onsi/ginkgo/v2"
 )
 
-var _ = Describe("ProgressReporter", func() {
+var _ = Describe("ProgressReport", func() {
 	It("can track on demand", func() {
 		By("Step A")
 		By("Step B")
+		for i := 1; i <= 12; i++ {
+			GinkgoWriter.Printf("ginkgo-writer-output-%d\n", i)
+		}
 		fmt.Printf("READY %d\n", os.Getpid())
 		time.Sleep(time.Second)
 	})

integration/progress_test.go

@@ -1,6 +1,7 @@
 package integration_test
 
 import (
+	"fmt"
 	"os"
 	"path/filepath"
 	"regexp"
@@ -16,11 +17,11 @@ import (
 var _ = Describe("Emitting progress", func() {
 	Describe("progress reports", func() {
 		BeforeEach(func() {
-			fm.MountFixture("progress_reporter")
+			fm.MountFixture("progress_report")
 		})
 
 		It("emits progress when a singal is sent and when tests take too long", func() {
-			session := startGinkgo(fm.PathTo("progress_reporter"), "--poll-progress-after=1500ms", "--poll-progress-interval=200ms", "--no-color")
+			session := startGinkgo(fm.PathTo("progress_report"), "--poll-progress-after=1500ms", "--poll-progress-interval=200ms", "--no-color")
 			Eventually(session).Should(gbytes.Say(`READY `))
 			buf := make([]byte, 128)
 			_, err := session.Out.Read(buf)
@@ -32,6 +33,13 @@ var _ = Describe("Emitting progress", func() {
 			Eventually(session).Should(gbytes.Say(`can track on demand \(Spec Runtime:`))
 			Eventually(session).Should(gbytes.Say(`In \[It\] \(Node Runtime:`))
 			Eventually(session).Should(gbytes.Say(`\[By Step\] Step B \(Step Runtime:`))
+
+			Eventually(session).Should(gbytes.Say(`Begin Captured GinkgoWriter Output`))
+			Eventually(session).Should(gbytes.Say(`\.\.\.`))
+			for i := 3; i <= 12; i++ {
+				Eventually(session).Should(gbytes.Say(fmt.Sprintf("ginkgo-writer-output-%d", i)))
+			}
+
 			Eventually(session).Should(gbytes.Say(`|\s*fmt\.Println\("READY"\)`))
 			Eventually(session).Should(gbytes.Say(`>\s*time\.Sleep\(time\.Second\)`))
 
@@ -53,29 +61,29 @@ var _ = Describe("Emitting progress", func() {
 		It("allows the user to specify a source-root to find source code files", func() {
 			// first we build the test with -gcflags=all=-trimpath=<PATH TO SPEC> to ensure
 			// that stack traces do not contain absolute paths
-			path, err := filepath.Abs(fm.PathTo("progress_reporter"))
+			path, err := filepath.Abs(fm.PathTo("progress_report"))
 			Ω(err).ShouldNot(HaveOccurred())
-			session := startGinkgo(fm.PathTo("progress_reporter"), "build", `-gcflags=-trimpath=`+path+``)
+			session := startGinkgo(fm.PathTo("progress_report"), "build", `-gcflags=-trimpath=`+path+``)
 			Eventually(session).Should(gexec.Exit(0))
 
 			// now we move the compiled test binary to a separate directory
-			fm.MkEmpty("progress_reporter/suite")
-			os.Rename(fm.PathTo("progress_reporter", "progress_reporter.test"), fm.PathTo("progress_reporter", "suite", "progress_reporter.test"))
+			fm.MkEmpty("progress_report/suite")
+			os.Rename(fm.PathTo("progress_report", "progress_report.test"), fm.PathTo("progress_report", "suite", "progress_report.test"))
 
 			//and we run and confirm that we don't see the expected source code
-			session = startGinkgo(fm.PathTo("progress_reporter", "suite"), "--poll-progress-after=1500ms", "--poll-progress-interval=200ms", "--no-color", "-label-filter=one-second", "./progress_reporter.test")
+			session = startGinkgo(fm.PathTo("progress_report", "suite"), "--poll-progress-after=1500ms", "--poll-progress-interval=200ms", "--no-color", "-label-filter=one-second", "./progress_report.test")
 			Eventually(session).Should(gexec.Exit(0))
 			Ω(session).ShouldNot(gbytes.Say(`>\s*time.Sleep\(1 \* time\.Second\)`))
 
 			// now we run, but configured with source-root and see that we have the file
 			// note that multipel source-roots can be passed in
-			session = startGinkgo(fm.PathTo("progress_reporter", "suite"), "--poll-progress-after=1500ms", "--poll-progress-interval=200ms", "--no-color", "-label-filter=one-second", "--source-root=/tmp", "--source-root="+path, "./progress_reporter.test")
+			session = startGinkgo(fm.PathTo("progress_report", "suite"), "--poll-progress-after=1500ms", "--poll-progress-interval=200ms", "--no-color", "-label-filter=one-second", "--source-root=/tmp", "--source-root="+path, "./progress_report.test")
 			Eventually(session).Should(gbytes.Say(`>\s*time\.Sleep\(1 \* time\.Second\)`))
 			Eventually(session).Should(gexec.Exit(0))
 		})
 
 		It("emits progress immediately and includes process information when running in parallel", func() {
-			session := startGinkgo(fm.PathTo("progress_reporter"), "--poll-progress-after=1500ms", "--poll-progress-interval=200ms", "--no-color", "-procs=2", "-label-filter=parallel")
+			session := startGinkgo(fm.PathTo("progress_report"), "--poll-progress-after=1500ms", "--poll-progress-interval=200ms", "--no-color", "-procs=2", "-label-filter=parallel")
 			Eventually(session).Should(gexec.Exit(0))
 
 			Eventually(session.Out.Contents()).Should(ContainSubstring(`Progress Report for Ginkgo Process #1`))

internal/internal_integration/progress_report_test.go

@@ -43,6 +43,7 @@ var _ = Describe("Progress Reporting", func() {
 			success, _ := RunFixture("emitting spec progress in a BeforeSuite", func() {
 				BeforeSuite(func() {
 					cl = types.NewCodeLocation(0)
+					writer.Print("ginkgo-writer-content")
 					triggerProgressSignal()
 				})
 				It("runs", func() {})
@@ -56,8 +57,9 @@ var _ = Describe("Progress Reporting", func() {
 			Ω(pr.CurrentNodeType).Should(Equal(types.NodeTypeBeforeSuite))
 			Ω(pr.LeafNodeLocation).Should(Equal(clLine(-1)))
 			Ω(pr.CurrentStepText).Should(Equal(""))
+			Ω(pr.CapturedGinkgoWriterOutput).Should(Equal("ginkgo-writer-content"))
 			Ω(pr.SpecGoroutine().State).Should(Equal("running"))
-			Ω(pr.SpecGoroutine().Stack).Should(HaveHighlightedStackLine(clLine(1)))
+			Ω(pr.SpecGoroutine().Stack).Should(HaveHighlightedStackLine(clLine(2)))
 		})
 	})
 

internal/progress_report.go

@@ -46,7 +46,7 @@ type ProgressStepCursor struct {
 	StartTime    time.Time
 }
 
-func NewProgressReport(isRunningInParallel bool, report types.SpecReport, currentNode Node, currentNodeStartTime time.Time, currentStep ProgressStepCursor, includeAll bool) (types.ProgressReport, error) {
+func NewProgressReport(isRunningInParallel bool, report types.SpecReport, currentNode Node, currentNodeStartTime time.Time, currentStep ProgressStepCursor, gwOutput string, includeAll bool) (types.ProgressReport, error) {
 	pr := types.ProgressReport{
 		ParallelProcess:   report.ParallelProcess,
 		RunningInParallel: isRunningInParallel,
@@ -64,6 +64,8 @@ func NewProgressReport(isRunningInParallel bool, report types.SpecReport, curren
 		CurrentStepText:      currentStep.Text,
 		CurrentStepLocation:  currentStep.CodeLocation,
 		CurrentStepStartTime: currentStep.StartTime,
+
+		CapturedGinkgoWriterOutput: gwOutput,
 	}
 
 	goroutines, err := extractRunningGoroutines()
@@ -115,9 +117,15 @@ OUTER:
 	//Now, we find the first non-Ginkgo function call
 	if specGoRoutineIdx > -1 {
 		for runNodeFunctionCallIdx >= 0 {
-			if strings.Contains(goroutines[specGoRoutineIdx].Stack[runNodeFunctionCallIdx].Function, "ginkgo/v2/internal") {
+			fn := goroutines[specGoRoutineIdx].Stack[runNodeFunctionCallIdx].Function
+			file := goroutines[specGoRoutineIdx].Stack[runNodeFunctionCallIdx].Filename
+			// these are all things that could potentially happen from within ginkgo
+			if strings.Contains(fn, "ginkgo/v2/internal") || strings.Contains(fn, "reflect.Value") || strings.Contains(file, "ginkgo/table_dsl") || strings.Contains(file, "ginkgo/core_dsl") {
 				runNodeFunctionCallIdx--
 				continue
+			}
+			if strings.Contains(goroutines[specGoRoutineIdx].Stack[runNodeFunctionCallIdx].Function, "ginkgo/table_dsl") {
+
 			}
 			//found it!  lets add its package of interest
 			addPackageFor(goroutines[specGoRoutineIdx].Stack[runNodeFunctionCallIdx].Filename)

internal/progress_report_test.go

@@ -19,7 +19,7 @@ var _ = Describe("ProgressReport", func() {
 
 	Context("when includeAll is false", func() {
 		It("does not include any other goroutines", func() {
-			pr, err := internal.NewProgressReport(false, types.SpecReport{}, Node{}, time.Now(), internal.ProgressStepCursor{}, false)
+			pr, err := internal.NewProgressReport(false, types.SpecReport{}, Node{}, time.Now(), internal.ProgressStepCursor{}, "", false)
 			Ω(err).ShouldNot(HaveOccurred())
 
 			Ω(pr.OtherGoroutines()).Should(HaveLen(0))
@@ -28,7 +28,7 @@ var _ = Describe("ProgressReport", func() {
 
 	Context("when includeAll is true", func() {
 		It("includes all other goroutines", func() {
-			pr, err := internal.NewProgressReport(false, types.SpecReport{}, Node{}, time.Now(), internal.ProgressStepCursor{}, true)
+			pr, err := internal.NewProgressReport(false, types.SpecReport{}, Node{}, time.Now(), internal.ProgressStepCursor{}, "", true)
 			Ω(err).ShouldNot(HaveOccurred())
 
 			Ω(pr.OtherGoroutines()).ShouldNot(HaveLen(0))

internal/suite.go

@@ -272,7 +272,7 @@ func (suite *Suite) generateProgressReport(fullReport bool) types.ProgressReport
 
 	stepCursor := suite.progressStepCursor
 
-	pr, err := NewProgressReport(suite.isRunningInParallel(), suite.currentSpecReport, suite.currentNode, suite.currentNodeStartTime, stepCursor, fullReport)
+	pr, err := NewProgressReport(suite.isRunningInParallel(), suite.currentSpecReport, suite.currentNode, suite.currentNodeStartTime, stepCursor, string(suite.writer.Bytes()), fullReport)
 	if err != nil {
 		fmt.Printf("{{red}}Failed to generate progress report:{{/}}\n%s\n", err.Error())
 	}

reporters/default_reporter.go

@@ -214,9 +214,7 @@ func (r *DefaultReporter) DidRun(report types.SpecReport) {
 	//Emit Captured GinkgoWriter Output
 	if emitGinkgoWriterOutput && hasGW {
 		r.emitBlock("\n")
-		r.emitBlock(r.fi(1, "{{gray}}Begin Captured GinkgoWriter Output >>{{/}}"))
-		r.emitBlock(r.fi(2, "%s", report.CapturedGinkgoWriterOutput))
-		r.emitBlock(r.fi(1, "{{gray}}<< End Captured GinkgoWriter Output{{/}}"))
+		r.emitGinkgoWriterOutput(1, report.CapturedGinkgoWriterOutput, 0)
 	}
 
 	if hasEmittableReports {
@@ -253,7 +251,7 @@ func (r *DefaultReporter) DidRun(report types.SpecReport) {
 
 		if !report.Failure.ProgressReport.IsZero() {
 			r.emitBlock("\n")
-			r.emitProgressReport(1, report.Failure.ProgressReport)
+			r.emitProgressReport(1, false, report.Failure.ProgressReport)
 		}
 	}
 
@@ -331,11 +329,11 @@ func (r *DefaultReporter) EmitProgressReport(report types.ProgressReport) {
 	if report.RunningInParallel {
 		r.emit(r.f("{{coral}}Progress Report for Ginkgo Process #{{bold}}%d{{/}}\n", report.ParallelProcess))
 	}
-	r.emitProgressReport(0, report)
+	r.emitProgressReport(0, true, report)
 	r.emitDelimiter()
 }
 
-func (r *DefaultReporter) emitProgressReport(indent uint, report types.ProgressReport) {
+func (r *DefaultReporter) emitProgressReport(indent uint, emitGinkgoWriterOutput bool, report types.ProgressReport) {
 	now := time.Now()
 	if report.LeafNodeText != "" {
 		if len(report.ContainerHierarchyTexts) > 0 {
@@ -366,6 +364,11 @@ func (r *DefaultReporter) emitProgressReport(indent uint, report types.ProgressR
 		indent -= 1
 	}
 
+	if emitGinkgoWriterOutput && report.CapturedGinkgoWriterOutput != "" && (report.RunningInParallel || r.conf.Verbosity().LT(types.VerbosityLevelVerbose)) {
+		r.emit("\n")
+		r.emitGinkgoWriterOutput(indent, report.CapturedGinkgoWriterOutput, 10)
+	}
+
 	if !report.SpecGoroutine().IsZero() {
 		r.emit("\n")
 		r.emit(r.fi(indent, "{{bold}}{{underline}}Spec Goroutine{{/}}\n"))
@@ -387,6 +390,24 @@ func (r *DefaultReporter) emitProgressReport(indent uint, report types.ProgressR
 	}
 }
 
+func (r *DefaultReporter) emitGinkgoWriterOutput(indent uint, output string, limit int) {
+	r.emitBlock(r.fi(indent, "{{gray}}Begin Captured GinkgoWriter Output >>{{/}}"))
+	if limit == 0 {
+		r.emitBlock(r.fi(indent+1, "%s", output))
+	} else {
+		lines := strings.Split(output, "\n")
+		if len(lines) <= limit {
+			r.emitBlock(r.fi(indent+1, "%s", output))
+		} else {
+			r.emitBlock(r.fi(indent+1, "{{gray}}...{{/}}"))
+			for _, line := range lines[len(lines)-limit-1:] {
+				r.emitBlock(r.fi(indent+1, "%s", line))
+			}
+		}
+	}
+	r.emitBlock(r.fi(indent, "{{gray}}<< End Captured GinkgoWriter Output{{/}}"))
+}
+
 func (r *DefaultReporter) emitGoroutines(indent uint, goroutines ...types.Goroutine) {
 	for idx, g := range goroutines {
 		color := "{{gray}}"