Gingko now records additional failures that occur during cleanup of a…

… failed spec

integration/_fixtures/reporting_fixture/reporting_fixture_test.go

@@ -38,7 +38,9 @@ var _ = Describe("reporting test", func() {
 		Skip("skip")
 	})
 
-	It("times out", func(ctx SpecContext) {
+	It("times out and fails during cleanup", func(ctx SpecContext) {
 		<-ctx.Done()
+		DeferCleanup(func() { Fail("double-whammy") })
+		Fail("failure-after-timeout")
 	}, NodeTimeout(time.Millisecond*100))
 })

integration/fail_test.go

@@ -31,7 +31,7 @@ var _ = Describe("Failing Specs", func() {
 			Ω(output).ShouldNot(ContainSubstring("ginkgo_dsl.go"))
 			Ω(output).Should(ContainSubstring("fail_fixture_test.go:38"))
 
-			Ω(output).Should(ContainSubstring("[TIMEOUT]"))
+			Ω(output).Should(ContainSubstring("[TIMEDOUT]"))
 			Ω(output).Should(MatchRegexp(`goroutine \d+ \[chan receive\]`), "from the progress report emitted by the timeout")
 			Ω(output).Should(MatchRegexp(`>\s*\<\-c\.Done\(\)`), "from the progress report emitted by the timeout")
 

integration/interrupt_test.go

@@ -79,7 +79,7 @@ var _ = Describe("Interrupt and Timeout", func() {
 			Ω(session).Should(gbytes.Say("Cleaning up twice..."))
 			Ω(session).Should(gbytes.Say("Cleaning up thrice..."), "we manage to get here even though the second after-each gets stuck.  that's thanks to the GracePeriod configuration.")
 
-			Ω(session).Should(gbytes.Say(`\[TIMEOUT\]`))
+			Ω(session).Should(gbytes.Say(`\[TIMEDOUT\]`))
 			Ω(session).Should(gbytes.Say(`Spec Goroutine`))
 			Ω(session).Should(gbytes.Say(`goroutine \d+ \[select\]`))
 			Ω(session).Should(gbytes.Say(`>\s*select {`), "The actual source code gets emitted now")

integration/reporting_test.go

@@ -35,7 +35,7 @@ var _ = Describe("Reporting", func() {
 				"has a progress report - INVALID SPEC STATE",
 				"is pending - pending",
 				"is skipped - INVALID SPEC STATE",
-				"times out - INVALID SPEC STATE",
+				"times out and fails during cleanup - INVALID SPEC STATE",
 				"",
 			))
 		})
@@ -55,7 +55,7 @@ var _ = Describe("Reporting", func() {
 				"has a progress report - passed",
 				"is pending - pending",
 				"is skipped - skipped",
-				"times out - timeout",
+				"times out and fails during cleanup - timedout",
 				"",
 			))
 		})
@@ -77,7 +77,7 @@ var _ = Describe("Reporting", func() {
 				"has a progress report - passed",
 				"is pending - pending",
 				"is skipped - skipped",
-				"times out - timeout",
+				"times out and fails during cleanup - timedout",
 				"1: [DeferCleanup (Suite)] - passed",
 				"1: [DeferCleanup (Suite)] - passed",
 				"",
@@ -103,7 +103,7 @@ var _ = Describe("Reporting", func() {
 					"has a progress report - passed",
 					"is pending - pending",
 					"is skipped - skipped",
-					"times out - timeout",
+					"times out and fails during cleanup - timedout",
 					"1: [DeferCleanup (Suite)] - passed",
 					"1: [DeferCleanup (Suite)] - passed",
 					"2: [DeferCleanup (Suite)] - passed",
@@ -140,7 +140,10 @@ var _ = Describe("Reporting", func() {
 			Ω(specReports.Find("panics")).Should(HavePanicked("boom"))
 			Ω(specReports.Find("is pending")).Should(BePending())
 			Ω(specReports.Find("is skipped").State).Should(Equal(types.SpecStateSkipped))
-			Ω(specReports.Find("times out")).Should(HaveTimedOut())
+			Ω(specReports.Find("times out and fails during cleanup")).Should(HaveTimedOut("This spec timed out and reported the following failure after the timeout:\n\nfailure-after-timeout"))
+
+			Ω(specReports.Find("times out and fails during cleanup").AdditionalFailures[0].Failure.Message).Should(Equal("double-whammy"))
+			Ω(specReports.Find("times out and fails during cleanup").AdditionalFailures[0].Failure.FailureNodeType).Should(Equal(types.NodeTypeCleanupAfterEach))
 			Ω(specReports.Find("my report")).Should(HaveFailed("fail!", types.FailureNodeIsLeafNode, types.NodeTypeReportAfterSuite))
 			Ω(specReports.FindByLeafNodeType(types.NodeTypeBeforeSuite)).Should(HavePassed())
 			Ω(specReports.FindByLeafNodeType(types.NodeTypeCleanupAfterSuite)).Should(HavePassed())
@@ -226,8 +229,10 @@ var _ = Describe("Reporting", func() {
 			Ω(getTestCase("[It] reporting test is skipped", suite.TestCases).Status).Should(Equal("skipped"))
 			Ω(getTestCase("[It] reporting test is skipped", suite.TestCases).Skipped.Message).Should(Equal("skipped - skip"))
 
-			Ω(getTestCase("[It] reporting test times out", suite.TestCases).Status).Should(Equal("timeout"))
-			Ω(getTestCase("[It] reporting test times out", suite.TestCases).Failure.Description).Should(ContainSubstring("<-ctx.Done()"))
+			Ω(getTestCase("[It] reporting test times out and fails during cleanup", suite.TestCases).Status).Should(Equal("timedout"))
+			Ω(getTestCase("[It] reporting test times out and fails during cleanup", suite.TestCases).Failure.Message).Should(Equal("This spec timed out and reported the following failure after the timeout:\n\nfailure-after-timeout"))
+			Ω(getTestCase("[It] reporting test times out and fails during cleanup", suite.TestCases).Failure.Description).Should(ContainSubstring("<-ctx.Done()"))
+			Ω(getTestCase("[It] reporting test times out and fails during cleanup", suite.TestCases).Failure.Description).Should(ContainSubstring("There were additional failures detected after the initial failure:\n[FAILED]\ndouble-whammy\nIn [DeferCleanup (Each)] at:"))
 
 			buf := gbytes.NewBuffer()
 			fmt.Fprintf(buf, getTestCase("[It] reporting test has a progress report", suite.TestCases).SystemErr)
@@ -291,7 +296,7 @@ var _ = Describe("Reporting", func() {
 
 			Ω(lines).Should(ContainElement("##teamcity[testStarted name='|[It|] reporting test is skipped']"))
 			Ω(lines).Should(ContainElement("##teamcity[testIgnored name='|[It|] reporting test is skipped' message='skipped - skip']"))
-			Ω(lines).Should(ContainElement(HavePrefix("##teamcity[testFailed name='|[It|] reporting test times out' message='timeout")))
+			Ω(lines).Should(ContainElement(HavePrefix("##teamcity[testFailed name='|[It|] reporting test times out and fails during cleanup' message='timedout")))
 
 			Ω(lines).Should(ContainElement(HavePrefix("##teamcity[testFinished name='|[It|] reporting test is skipped'")))
 

internal/group.go

@@ -271,6 +271,8 @@ func (g *group) attemptSpec(isFinalAttempt bool, spec Spec) {
 			if g.suite.currentSpecReport.State == types.SpecStatePassed || state == types.SpecStateAborted {
 				g.suite.currentSpecReport.State = state
 				g.suite.currentSpecReport.Failure = failure
+			} else if state.Is(types.SpecStateFailureStates) {
+				g.suite.currentSpecReport.AdditionalFailures = append(g.suite.currentSpecReport.AdditionalFailures, types.AdditionalFailure{State: state, Failure: failure})
 			}
 		}
 		includeDeferCleanups = true

internal/internal_integration/fail_test.go

@@ -1,6 +1,8 @@
 package internal_integration_test
 
 import (
+	"time"
+
 	. "github.com/onsi/ginkgo/v2"
 	. "github.com/onsi/gomega"
 
@@ -307,6 +309,11 @@ var _ = Describe("handling test failures", func() {
 				success, _ := RunFixture("failed after each", func() {
 					BeforeEach(rt.T("bef-1", func() {
 						writer.Write([]byte("run A"))
+						DeferCleanup(rt.TSC("dc-1", func(ctx SpecContext) {
+							writer.Write([]byte("run DC"))
+							<-ctx.Done()
+							F("fail-DC")
+						}), NodeTimeout(time.Millisecond*50))
 						F("fail-A", clA)
 					}))
 					It("the test", rt.T("it"))
@@ -318,12 +325,23 @@ var _ = Describe("handling test failures", func() {
 				Ω(success).Should(BeFalse())
 			})
 
-			It("reports a suite failure and a spec failure and only tracks the first failure", func() {
+			It("reports a suite failure and a spec failure and tracks the first failure as its primary failure, but also tracks the additional failures", func() {
 				Ω(reporter.End).Should(BeASuiteSummary(false, NSpecs(1), NPassed(0), NFailed(1)))
 				specReport := reporter.Did.Find("the test")
-				Ω(specReport).Should(HaveFailed("fail-A", clA), CapturedGinkgoWriterOutput("run Arun B"))
+				Ω(specReport).Should(HaveFailed("fail-A", clA), CapturedGinkgoWriterOutput("run Arun BrunDC"))
 				Ω(specReport.Failure.FailureNodeType).Should(Equal(types.NodeTypeBeforeEach))
-				Ω(rt).Should(HaveTracked("bef-1", "aft-1"))
+				Ω(rt).Should(HaveTracked("bef-1", "aft-1", "dc-1"))
+
+				Ω(specReport.AdditionalFailures).Should(HaveLen(2))
+
+				Ω(specReport.AdditionalFailures[0].State).Should(Equal(types.SpecStateFailed))
+				Ω(specReport.AdditionalFailures[0].Failure.Message).Should(Equal("fail-B"))
+				Ω(specReport.AdditionalFailures[0].Failure.Location).Should(Equal(clB))
+				Ω(specReport.AdditionalFailures[0].Failure.FailureNodeType).Should(Equal(types.NodeTypeAfterEach))
+
+				Ω(specReport.AdditionalFailures[1].State).Should(Equal(types.SpecStateTimedout))
+				Ω(specReport.AdditionalFailures[1].Failure.Message).Should(Equal("This spec timed out and reported the following failure after the timeout:\n\nfail-DC"))
+				Ω(specReport.AdditionalFailures[1].Failure.FailureNodeType).Should(Equal(types.NodeTypeCleanupAfterEach))
 			})
 		})
 	})

internal/suite.go

@@ -571,7 +571,7 @@ func (suite *Suite) runSuiteNode(node Node) {
 			switch proc1State {
 			case types.SpecStatePassed:
 				runAllProcs = true
-			case types.SpecStateFailed, types.SpecStatePanicked, types.SpecStateTimeout:
+			case types.SpecStateFailed, types.SpecStatePanicked, types.SpecStateTimedout:
 				err = types.GinkgoErrors.SynchronizedBeforeSuiteFailedOnProc1()
 			case types.SpecStateInterrupted, types.SpecStateAborted, types.SpecStateSkipped:
 				suite.currentSpecReport.State = proc1State
@@ -776,7 +776,7 @@ func (suite *Suite) runNode(node Node, specDeadline time.Time, text string) (typ
 				// we've already been interrupted.  we just managed to actually exit
 				// before the grace period elapsed
 				return outcome, failure
-			} else if outcome == types.SpecStateTimeout {
+			} else if outcome == types.SpecStateTimedout {
 				// 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 {
@@ -792,15 +792,15 @@ func (suite *Suite) runNode(node Node, specDeadline time.Time, text string) (typ
 				return outcomeFromRun, failure
 			}
 		case <-gracePeriodChannel:
-			if node.HasContext && outcome.Is(types.SpecStateTimeout) {
+			if node.HasContext && outcome.Is(types.SpecStateTimedout) {
 				report := suite.generateProgressReport(false)
 				report.Message = "{{bold}}{{orange}}A running node failed to exit in time{{/}}\nGinkgo is moving on but a node has timed out and failed to exit before its grace period elapsed.  The node has now leaked and is running in the background.\nHere's a current progress report:"
 				suite.emitProgressReport(report)
 			}
 			return outcome, failure
 		case <-deadlineChannel:
 			// we're out of time - the outcome is a timeout and we capture the failure and progress report
-			outcome = types.SpecStateTimeout
+			outcome = types.SpecStateTimedout
 			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:{{/}}"

internal/test_helpers/fake_reporter.go

@@ -275,7 +275,7 @@ func HaveFailed(options ...interface{}) OmegaMatcher {
 }
 
 func HaveTimedOut(options ...interface{}) OmegaMatcher {
-	return failureMatcherForState(types.SpecStateTimeout, "Failure.Message", options...)
+	return failureMatcherForState(types.SpecStateTimedout, "Failure.Message", options...)
 }
 
 func HaveAborted(options ...interface{}) OmegaMatcher {

reporters/default_reporter.go

@@ -135,9 +135,11 @@ func (r *DefaultReporter) DidRun(report types.SpecReport) {
 		denoter = fmt.Sprintf("[%s]", report.LeafNodeType)
 	}
 
+	highlightColor = r.highlightColorForState(report.State)
+
 	switch report.State {
 	case types.SpecStatePassed:
-		highlightColor, succinctLocationBlock = "{{green}}", v.LT(types.VerbosityLevelVerbose)
+		succinctLocationBlock = v.LT(types.VerbosityLevelVerbose)
 		emitGinkgoWriterOutput = (r.conf.AlwaysEmitGinkgoWriter || v.GTE(types.VerbosityLevelVerbose)) && hasGW
 		if report.LeafNodeType.Is(types.NodeTypesForSuiteLevelNodes) {
 			if v.GTE(types.VerbosityLevelVerbose) || hasStd || hasEmittableReports {
@@ -158,30 +160,28 @@ func (r *DefaultReporter) DidRun(report types.SpecReport) {
 			stream = false
 		}
 	case types.SpecStatePending:
-		highlightColor = "{{yellow}}"
 		includeRuntime, emitGinkgoWriterOutput = false, false
 		if v.Is(types.VerbosityLevelSuccinct) {
 			header, stream = "P", true
 		} else {
 			header, succinctLocationBlock = "P [PENDING]", v.LT(types.VerbosityLevelVeryVerbose)
 		}
 	case types.SpecStateSkipped:
-		highlightColor = "{{cyan}}"
 		if report.Failure.Message != "" || v.Is(types.VerbosityLevelVeryVerbose) {
 			header = "S [SKIPPED]"
 		} else {
 			header, stream = "S", true
 		}
 	case types.SpecStateFailed:
-		highlightColor, header = "{{red}}", fmt.Sprintf("%s [FAILED]", denoter)
-	case types.SpecStateTimeout:
-		highlightColor, header = "{{orange}}", fmt.Sprintf("%s [TIMEOUT]", denoter)
+		header = fmt.Sprintf("%s [FAILED]", denoter)
+	case types.SpecStateTimedout:
+		header = fmt.Sprintf("%s [TIMEDOUT]", denoter)
 	case types.SpecStatePanicked:
-		highlightColor, header = "{{magenta}}", fmt.Sprintf("%s! [PANICKED]", denoter)
+		header = fmt.Sprintf("%s! [PANICKED]", denoter)
 	case types.SpecStateInterrupted:
-		highlightColor, header = "{{orange}}", fmt.Sprintf("%s! [INTERRUPTED]", denoter)
+		header = fmt.Sprintf("%s! [INTERRUPTED]", denoter)
 	case types.SpecStateAborted:
-		highlightColor, header = "{{coral}}", fmt.Sprintf("%s! [ABORTED]", denoter)
+		header = fmt.Sprintf("%s! [ABORTED]", denoter)
 	}
 
 	// Emit stream and return
@@ -233,28 +233,87 @@ func (r *DefaultReporter) DidRun(report types.SpecReport) {
 	// Emit Failure Message
 	if !report.Failure.IsZero() {
 		r.emitBlock("\n")
-		r.emitBlock(r.fi(1, highlightColor+"%s{{/}}", report.Failure.Message))
-		r.emitBlock(r.fi(1, highlightColor+"In {{bold}}[%s]{{/}}"+highlightColor+" at: {{bold}}%s{{/}}\n", report.Failure.FailureNodeType, report.Failure.Location))
-		if report.Failure.ForwardedPanic != "" {
-			r.emitBlock("\n")
-			r.emitBlock(r.fi(1, highlightColor+"%s{{/}}", report.Failure.ForwardedPanic))
-		}
+		r.EmitFailure(1, report.State, report.Failure, false)
+	}
 
-		if r.conf.FullTrace || report.Failure.ForwardedPanic != "" {
+	if len(report.AdditionalFailures) > 0 {
+		if v.GTE(types.VerbosityLevelVerbose) {
 			r.emitBlock("\n")
-			r.emitBlock(r.fi(1, highlightColor+"Full Stack Trace{{/}}"))
-			r.emitBlock(r.fi(2, "%s", report.Failure.Location.FullStackTrace))
-		}
-
-		if !report.Failure.ProgressReport.IsZero() {
+			r.emitBlock(r.fi(1, "{{bold}}There were additional failures detected after the initial failure:{{/}}"))
+			for i, additionalFailure := range report.AdditionalFailures {
+				r.EmitFailure(2, additionalFailure.State, additionalFailure.Failure, true)
+				if i < len(report.AdditionalFailures)-1 {
+					r.emitBlock(r.fi(2, "{{gray}}%s{{/}}", strings.Repeat("-", 10)))
+				}
+			}
+		} else {
 			r.emitBlock("\n")
-			r.emitProgressReport(1, false, report.Failure.ProgressReport)
+			r.emitBlock(r.fi(1, "{{bold}}There were additional failures detected after the initial failure.  Here's a summary - for full details run Ginkgo in verbose mode:{{/}}"))
+			for _, additionalFailure := range report.AdditionalFailures {
+				r.emitBlock(r.fi(2, r.highlightColorForState(additionalFailure.State)+"[%s]{{/}} in [%s] at %s",
+					r.humanReadableState(additionalFailure.State),
+					additionalFailure.Failure.FailureNodeType,
+					additionalFailure.Failure.Location,
+				))
+			}
+
 		}
 	}
 
 	r.emitDelimiter()
 }
 
+func (r *DefaultReporter) highlightColorForState(state types.SpecState) string {
+	switch state {
+	case types.SpecStatePassed:
+		return "{{green}}"
+	case types.SpecStatePending:
+		return "{{yellow}}"
+	case types.SpecStateSkipped:
+		return "{{cyan}}"
+	case types.SpecStateFailed:
+		return "{{red}}"
+	case types.SpecStateTimedout:
+		return "{{orange}}"
+	case types.SpecStatePanicked:
+		return "{{magenta}}"
+	case types.SpecStateInterrupted:
+		return "{{orange}}"
+	case types.SpecStateAborted:
+		return "{{coral}}"
+	default:
+		return "{{gray}}"
+	}
+}
+
+func (r *DefaultReporter) humanReadableState(state types.SpecState) string {
+	return strings.ToUpper(state.String())
+}
+
+func (r *DefaultReporter) EmitFailure(indent uint, state types.SpecState, failure types.Failure, includeState bool) {
+	highlightColor := r.highlightColorForState(state)
+	if includeState {
+		r.emitBlock(r.fi(indent, highlightColor+"[%s]{{/}}", r.humanReadableState(state)))
+	}
+	r.emitBlock(r.fi(indent, highlightColor+"%s{{/}}", failure.Message))
+	r.emitBlock(r.fi(indent, highlightColor+"In {{bold}}[%s]{{/}}"+highlightColor+" at: {{bold}}%s{{/}}\n", failure.FailureNodeType, failure.Location))
+	if failure.ForwardedPanic != "" {
+		r.emitBlock("\n")
+		r.emitBlock(r.fi(indent, highlightColor+"%s{{/}}", failure.ForwardedPanic))
+	}
+
+	if r.conf.FullTrace || failure.ForwardedPanic != "" {
+		r.emitBlock("\n")
+		r.emitBlock(r.fi(indent, highlightColor+"Full Stack Trace{{/}}"))
+		r.emitBlock(r.fi(indent+1, "%s", failure.Location.FullStackTrace))
+	}
+
+	if !failure.ProgressReport.IsZero() {
+		r.emitBlock("\n")
+		r.emitProgressReport(indent, false, failure.ProgressReport)
+	}
+}
+
 func (r *DefaultReporter) SuiteDidEnd(report types.Report) {
 	failures := report.SpecReports.WithState(types.SpecStateFailureStates)
 	if len(failures) > 0 {
@@ -271,8 +330,8 @@ func (r *DefaultReporter) SuiteDidEnd(report types.Report) {
 				highlightColor, heading = "{{magenta}}", "[PANICKED!]"
 			case types.SpecStateAborted:
 				highlightColor, heading = "{{coral}}", "[ABORTED]"
-			case types.SpecStateTimeout:
-				highlightColor, heading = "{{orange}}", "[TIMEOUT]"
+			case types.SpecStateTimedout:
+				highlightColor, heading = "{{orange}}", "[TIMEDOUT]"
 			case types.SpecStateInterrupted:
 				highlightColor, heading = "{{orange}}", "[INTERRUPTED]"
 			}