Specs that timeout now include information about any failures that oc…

…cur after the spec is timed out

docs/index.md

@@ -2823,7 +2823,9 @@ DescribeTable("contrived context-value example",
 
 #### SpecContext and Progress Reports
 
-_Coming Soon_
+`SpecContext` provides an extension point that enables consumers to attach additional information to Progress Reports that Ginkgo generates.  This is accomplished by calling `ctx.AttachProgressReporter(f)` where `f` has the signature `func() string`.  Once attached, the function will be called whenever a Progress Report needs to be generated (e.g. due to a user request via `SIGINFO`/`SIGUSR1` or via an interrupt or timeout).  `ctx.AttachProgressReporter` returns a detach function with signature `func()` that can be called to detach the attached progress reporter.  Becuase these progress reporters are attached to the passed-in `SpecContext` they only remain attached for the lifecycle of the context: i.e. the current node.
+
+While users of Ginkgo can provide their own custom progress reporters the intent behind this extension point is to allow deeper integration between Ginkgo and third-party libraries, specifically Gomega.  Whenever Gomega's `Eventually` is passed a `SpecContext` it automatically registers a progress reporter.  This reporter will provide the latest state of the `Eventually` matcher - enabling users to get insight into where and why an `Eventually` might be stuck simply by asking for a Progress Report.
 
 ### Interrupting, Aborting, and Timing Out Suites
 

internal/internal_integration/interrupt_and_timeout_test.go

@@ -60,6 +60,7 @@ var _ = Describe("Interrupts and Timeouts", func() {
 			summary := reporter.Did.FindByLeafNodeType(types.NodeTypeBeforeSuite)
 			Ω(summary.State).Should(Equal(types.SpecStateInterrupted))
 			Ω(summary.Failure.Message).Should(ContainSubstring("Interrupted by User"))
+			Ω(summary.Failure.ProgressReport.Message).Should(Equal("{{bold}}This is the Progress Report generated when the interrupt was received:{{/}}"))
 			Ω(summary.Failure.ProgressReport.CurrentNodeType).Should(Equal(types.NodeTypeBeforeSuite))
 		})
 
@@ -624,6 +625,7 @@ var _ = Describe("Interrupts and Timeouts", func() {
 						It("A", rt.TSC("A", func(c SpecContext) {
 							<-c.Done()
 							rt.Run("A-cancelled")
+							Fail("subsequent failure message")
 						}), NodeTimeout(time.Millisecond*100))
 					})
 
@@ -659,7 +661,7 @@ var _ = Describe("Interrupts and Timeouts", func() {
 				"bef", "E", "aft",
 			))
 
-			Ω(reporter.Did.Find("A")).Should(HaveTimedOut())
+			Ω(reporter.Did.Find("A")).Should(HaveTimedOut("This spec timed out and reported the following failure after the timeout:\n\nsubsequent failure message"))
 			Ω(reporter.Did.Find("B")).Should(HaveTimedOut())
 			Ω(reporter.Did.Find("C")).Should(HaveTimedOut())
 			Ω(reporter.Did.Find("D")).Should(HavePassed())
@@ -677,6 +679,7 @@ var _ = Describe("Interrupts and Timeouts", func() {
 
 		It("attaches progress reports to the timout failures", func() {
 			Ω(reporter.Did.Find("A").Failure.ProgressReport.LeafNodeText).Should(Equal("A"))
+			Ω(reporter.Did.Find("A").Failure.ProgressReport.Message).Should(Equal("{{bold}}This is the Progress Report generated when the timeout occurred:{{/}}"))
 			Ω(reporter.Did.Find("B").Failure.ProgressReport.LeafNodeText).Should(Equal("B"))
 			Ω(reporter.Did.Find("C").Failure.ProgressReport.LeafNodeText).Should(Equal("C"))
 			Ω(reporter.Did.Find("D").Failure.ProgressReport).Should(BeZero())
@@ -879,9 +882,8 @@ var _ = Describe("Interrupts and Timeouts", func() {
 			success, _ := RunFixture(CurrentSpecReport().LeafNodeText, func() {
 				Context("container", func() {
 					It("A", rt.TSC("A", func(c SpecContext) {
-						Eventually(func() string {
-							return "foo"
-						}).WithTimeout(time.Hour).WithContext(c).Should(Equal("bar"))
+						cl = types.NewCodeLocation(0)
+						Eventually(func() string { return "foo" }).WithTimeout(time.Hour).WithContext(c).Should(Equal("bar"))
 						rt.Run("A-dont-see") //never see this because Eventually fails which panics and ends execution
 					}), SpecTimeout(time.Millisecond*200))
 				})
@@ -891,7 +893,9 @@ var _ = Describe("Interrupts and Timeouts", func() {
 
 		It("doesn't get stuck because Eventually will exit and it includes the additional report provided by eventually", func() {
 			Ω(rt).Should(HaveTracked("A"))
-			Ω(reporter.Did.Find("A")).Should(HaveTimedOut())
+			Ω(reporter.Did.Find("A")).Should(HaveTimedOut(clLine(1)))
+			Ω(reporter.Did.Find("A").Failure.Message).Should(MatchRegexp(`This spec timed out and reported the following failure after the timeout:\n\nContext was cancelled after .*\nExpected\n    <string>: foo\nto equal\n    <string>: bar`))
+			Ω(reporter.Did.Find("A").Failure.ProgressReport.Message).Should(Equal("{{bold}}This is the Progress Report generated when the timeout occurred:{{/}}"))
 			Ω(reporter.Did.Find("A").Failure.ProgressReport.AdditionalReports).Should(ConsistOf("Expected\n    <string>: foo\nto equal\n    <string>: bar"))
 		})
 	})

internal/internal_integration/progress_report_test.go

@@ -34,6 +34,7 @@ var _ = Describe("Progress Reporting", func() {
 		It("emits progress when asked and includes source code", func() {
 			Ω(reporter.ProgressReports).Should(HaveLen(1))
 			pr := reporter.ProgressReports[0]
+			Ω(pr.Message).Should(Equal("{{bold}}You've requested a progress report:{{/}}"))
 			Ω(pr.CurrentNodeType).Should(Equal(types.NodeTypeBeforeSuite))
 			Ω(pr.LeafNodeLocation).Should(Equal(clLine(-1)))
 			Ω(pr.CurrentStepText).Should(Equal(""))
@@ -293,6 +294,7 @@ var _ = Describe("Progress Reporting", func() {
 			Ω(len(reporter.ProgressReports)).Should(BeNumerically(">", 1))
 
 			for _, pr := range reporter.ProgressReports {
+				Ω(pr.Message).Should(Equal("{{bold}}Automatically polling progress:{{/}}"))
 				Ω(pr.ContainerHierarchyTexts).Should(ConsistOf("a container"))
 				Ω(pr.LeafNodeLocation).Should(Equal(clLine(-1)))
 				Ω(pr.LeafNodeText).Should(Equal("A"))

internal/suite.go

@@ -293,7 +293,7 @@ func (suite *Suite) generateProgressReport(fullReport bool) types.ProgressReport
 
 func (suite *Suite) handleProgressSignal() {
 	report := suite.generateProgressReport(false)
-	report.Message = "You've requested a progress report:"
+	report.Message = "{{bold}}You've requested a progress report:{{/}}"
 	suite.emitProgressReport(report)
 }
 
@@ -772,10 +772,18 @@ func (suite *Suite) runNode(node Node, specDeadline time.Time, text string) (typ
 		select {
 		case outcomeFromRun := <-outcomeC:
 			failureFromRun := <-failureC
-			if outcome != types.SpecStateInvalid {
-				// we've already timed out or been interrupted.  we just managed to actually exit
+			if outcome == types.SpecStateInterrupted {
+				// we've already been interrupted.  we just managed to actually exit
 				// before the grace period elapsed
 				return outcome, failure
+			} else if outcome == types.SpecStateTimeout {
+				// we've already timed out.  we just managed to actually exit
+				// before the grace period elapsed.  if we have a failure message we should include it
+				if outcomeFromRun != types.SpecStatePassed {
+					failure.Location, failure.ForwardedPanic = failureFromRun.Location, failureFromRun.ForwardedPanic
+					failure.Message = "This spec timed out and reported the following failure after the timeout:\n\n" + failureFromRun.Message
+				}
+				return outcome, failure
 			}
 			if outcomeFromRun.Is(types.SpecStatePassed) {
 				return outcomeFromRun, types.Failure{}
@@ -795,6 +803,7 @@ func (suite *Suite) runNode(node Node, specDeadline time.Time, text string) (typ
 			outcome = types.SpecStateTimeout
 			failure.Message, failure.Location = "Timeout", node.CodeLocation
 			failure.ProgressReport = suite.generateProgressReport(false).WithoutCapturedGinkgoWriterOutput()
+			failure.ProgressReport.Message = "{{bold}}This is the Progress Report generated when the timeout occurred:{{/}}"
 			deadlineChannel = nil
 			// tell the spec to stop.  it's important we generate the progress report first to make sure we capture where
 			// the spec is actually stuck
@@ -810,6 +819,7 @@ func (suite *Suite) runNode(node Node, specDeadline time.Time, text string) (typ
 				failure.Message, failure.Location = interruptStatus.Message(), node.CodeLocation
 				if interruptStatus.ShouldIncludeProgressReport() {
 					failure.ProgressReport = suite.generateProgressReport(true).WithoutCapturedGinkgoWriterOutput()
+					failure.ProgressReport.Message = "{{bold}}This is the Progress Report generated when the interrupt was received:{{/}}"
 				}
 			}
 
@@ -844,7 +854,9 @@ func (suite *Suite) runNode(node Node, specDeadline time.Time, text string) (typ
 				return outcome, failure
 			}
 		case <-emitProgressNow:
-			suite.emitProgressReport(suite.generateProgressReport(false))
+			report := suite.generateProgressReport(false)
+			report.Message = "{{bold}}Automatically polling progress:{{/}}"
+			suite.emitProgressReport(report)
 			if pollProgressInterval > 0 {
 				progressPoller.Reset(pollProgressInterval)
 			}

reporters/default_reporter.go

@@ -248,7 +248,6 @@ func (r *DefaultReporter) DidRun(report types.SpecReport) {
 
 		if !report.Failure.ProgressReport.IsZero() {
 			r.emitBlock("\n")
-			r.emitBlock(r.fi(1, highlightColor+"Progress Report{{/}}"))
 			r.emitProgressReport(1, false, report.Failure.ProgressReport)
 		}
 	}
@@ -382,14 +381,14 @@ func (r *DefaultReporter) emitProgressReport(indent uint, emitGinkgoWriterOutput
 
 	if len(report.AdditionalReports) > 0 {
 		r.emit("\n")
-		r.emitBlock(r.fi(indent, "{{gray}}Begin Additional Progress Reporst >>{{/}}"))
+		r.emitBlock(r.fi(indent, "{{gray}}Begin Additional Progress Reports >>{{/}}"))
 		for i, additionalReport := range report.AdditionalReports {
 			r.emit(r.fi(indent+1, additionalReport))
 			if i < len(report.AdditionalReports)-1 {
 				r.emitBlock(r.fi(indent+1, "{{gray}}%s{{/}}", strings.Repeat("-", 10)))
 			}
 		}
-		r.emitBlock(r.fi(indent, "{{gray}}<< End Additional Progress Report{{/}}"))
+		r.emitBlock(r.fi(indent, "{{gray}}<< End Additional Progress Reports{{/}}"))
 	}
 
 	highlightedGoroutines := report.HighlightedGoroutines()

reporters/default_reporter_test.go

@@ -1120,7 +1120,6 @@ var _ = Describe("DefaultReporter", func() {
 			"  WITH DETAILS{{/}}",
 			"  {{orange}}In {{bold}}[JustBeforeEach]{{/}}{{orange}} at: {{bold}}"+cl4.String()+"{{/}}",
 			"",
-			"  {{orange}}Progress Report{{/}}",
 			"  In {{bold}}{{orange}}[BeforeSuite]{{/}} (Node Runtime: 3s)",
 			"    {{gray}}cl1.go:37{{/}}",
 			DELIMITER,
@@ -1157,7 +1156,6 @@ var _ = Describe("DefaultReporter", func() {
 			"  WITH DETAILS{{/}}",
 			"  {{orange}}In {{bold}}[JustBeforeEach]{{/}}{{orange}} at: {{bold}}"+cl4.String()+"{{/}}",
 			"",
-			"  {{orange}}Progress Report{{/}}",
 			"  In {{bold}}{{orange}}[BeforeSuite]{{/}} (Node Runtime: 3s)",
 			"    {{gray}}cl1.go:37{{/}}",
 			DELIMITER,
@@ -1769,9 +1767,9 @@ var _ = Describe("DefaultReporter", func() {
 			"    {{gray}}F3(){{/}}",
 			"      {{gray}}fileC:9{{/}}",
 			"",
-			"  {{gray}}Begin Additional Progress Reporst >>{{/}}",
+			"  {{gray}}Begin Additional Progress Reports >>{{/}}",
 			"    {{blue}}Report 1{{/}}",
-			"  {{gray}}<< End Additional Progress Report{{/}}",
+			"  {{gray}}<< End Additional Progress Reports{{/}}",
 			"",
 			"  {{bold}}{{underline}}Goroutines of Interest{{/}}",
 			"  {{orange}}goroutine 17 [sleeping]{{/}}",
@@ -1816,11 +1814,11 @@ var _ = Describe("DefaultReporter", func() {
 			"    {{gray}}F3(){{/}}",
 			"      {{gray}}fileC:9{{/}}",
 			"",
-			"  {{gray}}Begin Additional Progress Reporst >>{{/}}",
+			"  {{gray}}Begin Additional Progress Reports >>{{/}}",
 			"    {{blue}}Report 1{{/}}",
 			"    {{gray}}----------{{/}}",
 			"    {{green}}Report 2{{/}}",
-			"  {{gray}}<< End Additional Progress Report{{/}}",
+			"  {{gray}}<< End Additional Progress Reports{{/}}",
 			"",
 			"  {{bold}}{{underline}}Goroutines of Interest{{/}}",
 			"  {{orange}}goroutine 17 [sleeping]{{/}}",