From a87ec827fd11f8e52f1a9e91d7247a22440b6a91 Mon Sep 17 00:00:00 2001 From: Onsi Fakhouri Date: Mon, 10 Oct 2022 10:03:29 -0600 Subject: [PATCH] Gingko now records additional failures that occur during cleanup of a failed spec --- .../reporting_fixture_test.go | 4 +- integration/fail_test.go | 2 +- integration/interrupt_test.go | 2 +- integration/reporting_test.go | 21 ++- internal/group.go | 2 + internal/internal_integration/fail_test.go | 24 ++- internal/suite.go | 8 +- internal/test_helpers/fake_reporter.go | 2 +- reporters/default_reporter.go | 107 ++++++++++--- reporters/default_reporter_test.go | 149 +++++++++++++++++- reporters/junit_report.go | 34 ++-- reporters/teamcity_report.go | 14 +- types/types.go | 29 +++- 13 files changed, 326 insertions(+), 72 deletions(-) diff --git a/integration/_fixtures/reporting_fixture/reporting_fixture_test.go b/integration/_fixtures/reporting_fixture/reporting_fixture_test.go index 6b3efeac1..aa36e5b69 100644 --- a/integration/_fixtures/reporting_fixture/reporting_fixture_test.go +++ b/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)) }) diff --git a/integration/fail_test.go b/integration/fail_test.go index 334316e8b..02fe5b60b 100644 --- a/integration/fail_test.go +++ b/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") diff --git a/integration/interrupt_test.go b/integration/interrupt_test.go index 8a2c65898..eb0237aa1 100644 --- a/integration/interrupt_test.go +++ b/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") diff --git a/integration/reporting_test.go b/integration/reporting_test.go index f963b0c94..93f946082 100644 --- a/integration/reporting_test.go +++ b/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'"))) diff --git a/internal/group.go b/internal/group.go index 1cd339220..82d929aa5 100644 --- a/internal/group.go +++ b/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 diff --git a/internal/internal_integration/fail_test.go b/internal/internal_integration/fail_test.go index 706eb1b3d..deaada777 100644 --- a/internal/internal_integration/fail_test.go +++ b/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)) }) }) }) diff --git a/internal/suite.go b/internal/suite.go index efb1ac4d1..8210dfff9 100644 --- a/internal/suite.go +++ b/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,7 +792,7 @@ 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) @@ -800,7 +800,7 @@ func (suite *Suite) runNode(node Node, specDeadline time.Time, text string) (typ 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:{{/}}" diff --git a/internal/test_helpers/fake_reporter.go b/internal/test_helpers/fake_reporter.go index b899926bb..4adc51906 100644 --- a/internal/test_helpers/fake_reporter.go +++ b/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 { diff --git a/reporters/default_reporter.go b/reporters/default_reporter.go index 4a439592a..2ee51286e 100644 --- a/reporters/default_reporter.go +++ b/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,7 +160,6 @@ 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 @@ -166,22 +167,21 @@ func (r *DefaultReporter) DidRun(report types.SpecReport) { 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]" } diff --git a/reporters/default_reporter_test.go b/reporters/default_reporter_test.go index b809181ce..5b5337009 100644 --- a/reporters/default_reporter_test.go +++ b/reporters/default_reporter_test.go @@ -62,6 +62,13 @@ func F(options ...interface{}) types.Failure { return failure } +func AF(state types.SpecState, options ...interface{}) types.AdditionalFailure { + return types.AdditionalFailure{ + State: state, + Failure: F(options...), + } +} + type STD string type GW string @@ -98,6 +105,8 @@ func S(options ...interface{}) types.SpecReport { report.RunTime = option.(time.Duration) case reflect.TypeOf(types.Failure{}): report.Failure = option.(types.Failure) + case reflect.TypeOf(types.AdditionalFailure{}): + report.AdditionalFailures = append(report.AdditionalFailures, option.(types.AdditionalFailure)) case reflect.TypeOf(0): report.NumAttempts = option.(int) case reflect.TypeOf(STD("")): @@ -1129,12 +1138,12 @@ var _ = Describe("DefaultReporter", func() { Entry("when a test times out", C(), S(CTS("Describe A", "Context B"), "The Test", CLS(cl0, cl1), cl2, - types.SpecStateTimeout, 2, + types.SpecStateTimedout, 2, GW("GW-OUTPUT\nIS EMITTED"), STD("STD-OUTPUT\nIS EMITTED"), F("FAILURE MESSAGE\nWITH DETAILS", types.FailureNodeInContainer, FailureNodeLocation(cl3), types.NodeTypeJustBeforeEach, 1, cl4, PR(types.NodeTypeBeforeSuite, GW("GW-OUTPUT\nIS EMITTED"))), ), DELIMITER, - "{{orange}}"+DENOTER+" [TIMEOUT] [1.000 seconds]{{/}}", + "{{orange}}"+DENOTER+" [TIMEDOUT] [1.000 seconds]{{/}}", "Describe A", "{{gray}}"+cl0.String()+"{{/}}", " {{orange}}{{bold}}Context B [JustBeforeEach]{{/}}", @@ -1192,7 +1201,137 @@ var _ = Describe("DefaultReporter", func() { " {{coral}}In {{bold}}[JustBeforeEach]{{/}}{{coral}} at: {{bold}}"+cl4.String()+"{{/}}", DELIMITER, "", - )) + ), + + // with additional failures + Entry("with additional failures, and not in verbose mode", + C(), + S(CTS("Describe A", "Context B"), "The Test", CLS(cl0, cl1), cl2, + types.SpecStateFailed, 2, + GW("GW-OUTPUT\nIS EMITTED"), STD("STD-OUTPUT\nIS EMITTED"), + F("FAILURE MESSAGE\nWITH DETAILS", types.FailureNodeIsLeafNode, types.NodeTypeIt, FailureNodeLocation(cl2), cl3), + AF(types.SpecStateFailed, "Additional Failure 1", types.NodeTypeAfterEach, cl3), + AF(types.SpecStateTimedout, "Additional Failure 2", types.NodeTypeCleanupAfterEach, cl4), + AF(types.SpecStatePanicked, "Additional Failure 3", types.NodeTypeAfterAll, cl2), + ), + DELIMITER, + "{{red}}• [FAILED] [1.000 seconds]{{/}}", + "Describe A", + "{{gray}}cl0.go:12{{/}}", + " Context B", + " {{gray}}cl1.go:37{{/}}", + " {{red}}{{bold}}[It] The Test{{/}}", + " {{gray}}cl2.go:80{{/}}", + "", + " {{gray}}Begin Captured StdOut/StdErr Output >>{{/}}", + " STD-OUTPUT", + " IS EMITTED", + " {{gray}}<< End Captured StdOut/StdErr Output{{/}}", + "", + " {{gray}}Begin Captured GinkgoWriter Output >>{{/}}", + " GW-OUTPUT", + " IS EMITTED", + " {{gray}}<< End Captured GinkgoWriter Output{{/}}", + "", + " {{red}}FAILURE MESSAGE", + " WITH DETAILS{{/}}", + " {{red}}In {{bold}}[It]{{/}}{{red}} at: {{bold}}cl3.go:103{{/}}", + "", + " {{bold}}There were additional failures detected after the initial failure. Here's a summary - for full details run Ginkgo in verbose mode:{{/}}", + " {{red}}[FAILED]{{/}} in [AfterEach] at cl3.go:103", + " {{orange}}[TIMEDOUT]{{/}} in [DeferCleanup (Each)] at cl4.go:144", + " {{magenta}}[PANICKED]{{/}} in [AfterAll] at cl2.go:80", + DELIMITER, + "", + ), + + Entry("with one additional failure, in verbose mode", + C(Verbose), + S(CTS("Describe A", "Context B"), "The Test", CLS(cl0, cl1), cl2, + types.SpecStateFailed, 2, + GW("GW-OUTPUT\nIS EMITTED"), STD("STD-OUTPUT\nIS EMITTED"), + F("FAILURE MESSAGE\nWITH DETAILS", types.FailureNodeIsLeafNode, types.NodeTypeIt, FailureNodeLocation(cl2), cl3), + AF(types.SpecStateFailed, "Additional Failure", types.NodeTypeAfterEach, cl3), + ), + DELIMITER, + "{{red}}• [FAILED] [1.000 seconds]{{/}}", + "Describe A", + "{{gray}}cl0.go:12{{/}}", + " Context B", + " {{gray}}cl1.go:37{{/}}", + " {{red}}{{bold}}[It] The Test{{/}}", + " {{gray}}cl2.go:80{{/}}", + "", + " {{gray}}Begin Captured StdOut/StdErr Output >>{{/}}", + " STD-OUTPUT", + " IS EMITTED", + " {{gray}}<< End Captured StdOut/StdErr Output{{/}}", + "", + " {{gray}}Begin Captured GinkgoWriter Output >>{{/}}", + " GW-OUTPUT", + " IS EMITTED", + " {{gray}}<< End Captured GinkgoWriter Output{{/}}", + "", + " {{red}}FAILURE MESSAGE", + " WITH DETAILS{{/}}", + " {{red}}In {{bold}}[It]{{/}}{{red}} at: {{bold}}cl3.go:103{{/}}", + "", + " {{bold}}There were additional failures detected after the initial failure:{{/}}", + " {{red}}[FAILED]{{/}}", + " {{red}}Additional Failure{{/}}", + " {{red}}In {{bold}}[AfterEach]{{/}}{{red}} at: {{bold}}cl3.go:103{{/}}", + DELIMITER, + "", + ), + + Entry("with multiple additional failure, in verbose mode", + C(Verbose), + S(CTS("Describe A", "Context B"), "The Test", CLS(cl0, cl1), cl2, + types.SpecStateFailed, 2, + GW("GW-OUTPUT\nIS EMITTED"), STD("STD-OUTPUT\nIS EMITTED"), + F("FAILURE MESSAGE\nWITH DETAILS", types.FailureNodeIsLeafNode, types.NodeTypeIt, FailureNodeLocation(cl2), cl3), + AF(types.SpecStateFailed, "Additional Failure 1", types.NodeTypeAfterEach, cl3), + AF(types.SpecStateTimedout, "Additional Failure 2", types.NodeTypeCleanupAfterEach, cl4), + AF(types.SpecStatePanicked, "Additional Failure 3", types.NodeTypeAfterAll, cl2), + ), + DELIMITER, + "{{red}}• [FAILED] [1.000 seconds]{{/}}", + "Describe A", + "{{gray}}cl0.go:12{{/}}", + " Context B", + " {{gray}}cl1.go:37{{/}}", + " {{red}}{{bold}}[It] The Test{{/}}", + " {{gray}}cl2.go:80{{/}}", + "", + " {{gray}}Begin Captured StdOut/StdErr Output >>{{/}}", + " STD-OUTPUT", + " IS EMITTED", + " {{gray}}<< End Captured StdOut/StdErr Output{{/}}", + "", + " {{gray}}Begin Captured GinkgoWriter Output >>{{/}}", + " GW-OUTPUT", + " IS EMITTED", + " {{gray}}<< End Captured GinkgoWriter Output{{/}}", + "", + " {{red}}FAILURE MESSAGE", + " WITH DETAILS{{/}}", + " {{red}}In {{bold}}[It]{{/}}{{red}} at: {{bold}}cl3.go:103{{/}}", + "", + " {{bold}}There were additional failures detected after the initial failure:{{/}}", + " {{red}}[FAILED]{{/}}", + " {{red}}Additional Failure 1{{/}}", + " {{red}}In {{bold}}[AfterEach]{{/}}{{red}} at: {{bold}}cl3.go:103{{/}}", + " {{gray}}----------{{/}}", + " {{orange}}[TIMEDOUT]{{/}}", + " {{orange}}Additional Failure 2{{/}}", + " {{orange}}In {{bold}}[DeferCleanup (Each)]{{/}}{{orange}} at: {{bold}}cl4.go:144{{/}}", + " {{gray}}----------{{/}}", + " {{magenta}}[PANICKED]{{/}}", + " {{magenta}}Additional Failure 3{{/}}", + " {{magenta}}In {{bold}}[AfterAll]{{/}}{{magenta}} at: {{bold}}cl2.go:80{{/}}", DELIMITER, + "", + ), + ) DescribeTable("Rendering SuiteDidEnd", func(conf types.ReporterConfig, report types.Report, expected ...string) { @@ -1307,7 +1446,7 @@ var _ = Describe("DefaultReporter", func() { F("FAILURE MESSAGE\nWITH DETAILS", types.FailureNodeIsLeafNode, FailureNodeLocation(cl0), types.NodeTypeIt, cl1), ), S("The Test", cl0, - types.SpecStateTimeout, 2, + types.SpecStateTimedout, 2, F("FAILURE MESSAGE\nWITH DETAILS", types.FailureNodeIsLeafNode, FailureNodeLocation(cl0), types.NodeTypeIt, cl1), ), S(types.NodeTypeAfterSuite), @@ -1324,7 +1463,7 @@ var _ = Describe("DefaultReporter", func() { " {{gray}}"+cl1.String()+"{{/}}", " {{coral}}[ABORTED]{{/}} {{/}}{{coral}}{{bold}}[It] The Test{{/}}{{/}}", " {{gray}}"+cl1.String()+"{{/}}", - " {{orange}}[TIMEOUT]{{/}} {{/}}{{orange}}{{bold}}[It] The Test{{/}}{{/}}", + " {{orange}}[TIMEDOUT]{{/}} {{/}}{{orange}}{{bold}}[It] The Test{{/}}{{/}}", " {{gray}}"+cl1.String()+"{{/}}", "", "{{red}}{{bold}}Ran 10 of 14 Specs in 60.000 seconds{{/}}", diff --git a/reporters/junit_report.go b/reporters/junit_report.go index dcdc75c81..fcea6ab17 100644 --- a/reporters/junit_report.go +++ b/reporters/junit_report.go @@ -191,35 +191,35 @@ func GenerateJUnitReport(report types.Report, dst string) error { test.Failure = &JUnitFailure{ Message: spec.Failure.Message, Type: "failed", - Description: fmt.Sprintf("%s\n%s", spec.Failure.Location.String(), spec.Failure.Location.FullStackTrace), + Description: failureDescriptionForUnstructuredReporters(spec), } suite.Failures += 1 - case types.SpecStateTimeout: + case types.SpecStateTimedout: test.Failure = &JUnitFailure{ Message: spec.Failure.Message, - Type: "timeout", - Description: interruptDescriptionForUnstructuredReporters(spec.Failure), + Type: "timedout", + Description: failureDescriptionForUnstructuredReporters(spec), } suite.Failures += 1 case types.SpecStateInterrupted: test.Error = &JUnitError{ Message: spec.Failure.Message, Type: "interrupted", - Description: interruptDescriptionForUnstructuredReporters(spec.Failure), + Description: failureDescriptionForUnstructuredReporters(spec), } suite.Errors += 1 case types.SpecStateAborted: test.Failure = &JUnitFailure{ Message: spec.Failure.Message, Type: "aborted", - Description: fmt.Sprintf("%s\n%s", spec.Failure.Location.String(), spec.Failure.Location.FullStackTrace), + Description: failureDescriptionForUnstructuredReporters(spec), } suite.Errors += 1 case types.SpecStatePanicked: test.Error = &JUnitError{ Message: spec.Failure.ForwardedPanic, Type: "panicked", - Description: fmt.Sprintf("%s\n%s", spec.Failure.Location.String(), spec.Failure.Location.FullStackTrace), + Description: failureDescriptionForUnstructuredReporters(spec), } suite.Errors += 1 } @@ -285,11 +285,23 @@ func MergeAndCleanupJUnitReports(sources []string, dst string) ([]string, error) return messages, f.Close() } -func interruptDescriptionForUnstructuredReporters(failure types.Failure) string { +func failureDescriptionForUnstructuredReporters(spec types.SpecReport) string { out := &strings.Builder{} - out.WriteString(failure.Location.String() + "\n") - out.WriteString(failure.Message + "\n") - NewDefaultReporter(types.ReporterConfig{NoColor: true}, out).EmitProgressReport(failure.ProgressReport) + out.WriteString(spec.Failure.Location.String() + "\n") + out.WriteString(spec.Failure.Location.FullStackTrace) + if !spec.Failure.ProgressReport.IsZero() { + out.WriteString("\n") + NewDefaultReporter(types.ReporterConfig{NoColor: true}, out).EmitProgressReport(spec.Failure.ProgressReport) + } + if len(spec.AdditionalFailures) > 0 { + out.WriteString("\nThere were additional failures detected after the initial failure:\n") + for i, additionalFailure := range spec.AdditionalFailures { + NewDefaultReporter(types.ReporterConfig{NoColor: true}, out).EmitFailure(0, additionalFailure.State, additionalFailure.Failure, true) + if i < len(spec.AdditionalFailures)-1 { + out.WriteString("----------\n") + } + } + } return out.String() } diff --git a/reporters/teamcity_report.go b/reporters/teamcity_report.go index a6a68f136..c1863496d 100644 --- a/reporters/teamcity_report.go +++ b/reporters/teamcity_report.go @@ -60,17 +60,19 @@ func GenerateTeamcityReport(report types.Report, dst string) error { } fmt.Fprintf(f, "##teamcity[testIgnored name='%s' message='%s']\n", name, tcEscape(message)) case types.SpecStateFailed: - details := fmt.Sprintf("%s\n%s", spec.Failure.Location.String(), spec.Failure.Location.FullStackTrace) + details := failureDescriptionForUnstructuredReporters(spec) fmt.Fprintf(f, "##teamcity[testFailed name='%s' message='failed - %s' details='%s']\n", name, tcEscape(spec.Failure.Message), tcEscape(details)) case types.SpecStatePanicked: - details := fmt.Sprintf("%s\n%s", spec.Failure.Location.String(), spec.Failure.Location.FullStackTrace) + details := failureDescriptionForUnstructuredReporters(spec) fmt.Fprintf(f, "##teamcity[testFailed name='%s' message='panicked - %s' details='%s']\n", name, tcEscape(spec.Failure.ForwardedPanic), tcEscape(details)) - case types.SpecStateTimeout: - fmt.Fprintf(f, "##teamcity[testFailed name='%s' message='timeout' details='%s']\n", name, tcEscape(interruptDescriptionForUnstructuredReporters(spec.Failure))) + case types.SpecStateTimedout: + details := failureDescriptionForUnstructuredReporters(spec) + fmt.Fprintf(f, "##teamcity[testFailed name='%s' message='timedout - %s' details='%s']\n", name, tcEscape(spec.Failure.Message), tcEscape(details)) case types.SpecStateInterrupted: - fmt.Fprintf(f, "##teamcity[testFailed name='%s' message='interrupted' details='%s']\n", name, tcEscape(interruptDescriptionForUnstructuredReporters(spec.Failure))) + details := failureDescriptionForUnstructuredReporters(spec) + fmt.Fprintf(f, "##teamcity[testFailed name='%s' message='interrupted - %s' details='%s']\n", name, tcEscape(spec.Failure.Message), tcEscape(details)) case types.SpecStateAborted: - details := fmt.Sprintf("%s\n%s", spec.Failure.Location.String(), spec.Failure.Location.FullStackTrace) + details := failureDescriptionForUnstructuredReporters(spec) fmt.Fprintf(f, "##teamcity[testFailed name='%s' message='aborted - %s' details='%s']\n", name, tcEscape(spec.Failure.Message), tcEscape(details)) } diff --git a/types/types.go b/types/types.go index f69e1fa07..a752c46d3 100644 --- a/types/types.go +++ b/types/types.go @@ -168,6 +168,9 @@ type SpecReport struct { // ProgressReports contains any progress reports generated during this spec. These can either be manually triggered, or automatically generated by Ginkgo via the PollProgressAfter() decorator ProgressReports []ProgressReport + + // AdditionalFailures contains any failures that occurred after the initial spec failure. These typically occur in cleanup nodes after the initial failure and are only emitted when running in verbose mode. + AdditionalFailures []AdditionalFailure } func (report SpecReport) MarshalJSON() ([]byte, error) { @@ -187,10 +190,11 @@ func (report SpecReport) MarshalJSON() ([]byte, error) { ParallelProcess int Failure *Failure `json:",omitempty"` NumAttempts int - CapturedGinkgoWriterOutput string `json:",omitempty"` - CapturedStdOutErr string `json:",omitempty"` - ReportEntries ReportEntries `json:",omitempty"` - ProgressReports []ProgressReport `json:",omitempty"` + CapturedGinkgoWriterOutput string `json:",omitempty"` + CapturedStdOutErr string `json:",omitempty"` + ReportEntries ReportEntries `json:",omitempty"` + ProgressReports []ProgressReport `json:",omitempty"` + AdditionalFailures []AdditionalFailure `json:",omitempty"` }{ ContainerHierarchyTexts: report.ContainerHierarchyTexts, ContainerHierarchyLocations: report.ContainerHierarchyLocations, @@ -220,6 +224,9 @@ func (report SpecReport) MarshalJSON() ([]byte, error) { if len(report.ProgressReports) > 0 { out.ProgressReports = report.ProgressReports } + if len(report.AdditionalFailures) > 0 { + out.AdditionalFailures = report.AdditionalFailures + } return json.Marshal(out) } @@ -434,6 +441,14 @@ func (fnc FailureNodeContext) MarshalJSON() ([]byte, error) { return fncEnumSupport.MarshJSON(uint(fnc)) } +// AdditionalFailure capturs any additional failures that occur after the initial failure of a psec +// these typically occur in clean up nodes after the spec has failed. +// We can't simply use Failure as we want to track the SpecState to know what kind of failure this is +type AdditionalFailure struct { + State SpecState + Failure Failure +} + // SpecState captures the state of a spec // To determine if a given `state` represents a failure state, use `state.Is(SpecStateFailureStates)` type SpecState uint @@ -448,7 +463,7 @@ const ( SpecStateAborted SpecStatePanicked SpecStateInterrupted - SpecStateTimeout + SpecStateTimedout ) var ssEnumSupport = NewEnumSupport(map[uint]string{ @@ -460,7 +475,7 @@ var ssEnumSupport = NewEnumSupport(map[uint]string{ uint(SpecStateAborted): "aborted", uint(SpecStatePanicked): "panicked", uint(SpecStateInterrupted): "interrupted", - uint(SpecStateTimeout): "timeout", + uint(SpecStateTimedout): "timedout", }) func (ss SpecState) String() string { @@ -475,7 +490,7 @@ func (ss SpecState) MarshalJSON() ([]byte, error) { return ssEnumSupport.MarshJSON(uint(ss)) } -var SpecStateFailureStates = SpecStateFailed | SpecStateTimeout | SpecStateAborted | SpecStatePanicked | SpecStateInterrupted +var SpecStateFailureStates = SpecStateFailed | SpecStateTimedout | SpecStateAborted | SpecStatePanicked | SpecStateInterrupted func (ss SpecState) Is(states SpecState) bool { return ss&states != 0