From 0f2fa2787054cf7b1f7c32ac3f4548b9e6033864 Mon Sep 17 00:00:00 2001 From: Onsi Fakhouri Date: Thu, 27 Oct 2022 08:27:28 -0600 Subject: [PATCH] Provide details about which timeout expired --- integration/reporting_test.go | 4 ++-- internal/internal_integration/fail_test.go | 2 +- .../internal_integration_suite_test.go | 2 ++ .../interrupt_and_timeout_test.go | 16 ++++++++-------- internal/suite.go | 13 +++++++++---- 5 files changed, 22 insertions(+), 15 deletions(-) diff --git a/integration/reporting_test.go b/integration/reporting_test.go index 93f946082..f2b6198fc 100644 --- a/integration/reporting_test.go +++ b/integration/reporting_test.go @@ -140,7 +140,7 @@ 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 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")).Should(HaveTimedOut("A node timeout occurred and the following failure was recorded 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)) @@ -230,7 +230,7 @@ var _ = Describe("Reporting", func() { Ω(getTestCase("[It] reporting test is skipped", suite.TestCases).Skipped.Message).Should(Equal("skipped - skip")) Ω(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.Message).Should(Equal("A node timeout occurred and the following failure was recorded 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:")) diff --git a/internal/internal_integration/fail_test.go b/internal/internal_integration/fail_test.go index deaada777..1f4750a98 100644 --- a/internal/internal_integration/fail_test.go +++ b/internal/internal_integration/fail_test.go @@ -340,7 +340,7 @@ var _ = Describe("handling test failures", func() { Ω(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.Message).Should(Equal("A node timeout occurred and the following failure was recorded after the timeout:\n\nfail-DC")) Ω(specReport.AdditionalFailures[1].Failure.FailureNodeType).Should(Equal(types.NodeTypeCleanupAfterEach)) }) }) diff --git a/internal/internal_integration/internal_integration_suite_test.go b/internal/internal_integration/internal_integration_suite_test.go index 4a70645e4..2a44ffe15 100644 --- a/internal/internal_integration/internal_integration_suite_test.go +++ b/internal/internal_integration/internal_integration_suite_test.go @@ -14,9 +14,11 @@ import ( . "github.com/onsi/ginkgo/v2/internal/test_helpers" "github.com/onsi/ginkgo/v2/types" . "github.com/onsi/gomega" + "github.com/onsi/gomega/format" ) func TestSuiteTests(t *testing.T) { + format.TruncatedDiff = false RegisterFailHandler(Fail) suiteConfig, _ := GinkgoConfiguration() suiteConfig.GracePeriod = time.Second diff --git a/internal/internal_integration/interrupt_and_timeout_test.go b/internal/internal_integration/interrupt_and_timeout_test.go index b436a2b35..bc23c886b 100644 --- a/internal/internal_integration/interrupt_and_timeout_test.go +++ b/internal/internal_integration/interrupt_and_timeout_test.go @@ -663,7 +663,7 @@ var _ = Describe("Interrupts and Timeouts", func() { "bef", "E", "aft", )) - Ω(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("A")).Should(HaveTimedOut("A node timeout occurred and the following failure was recorded 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()) @@ -681,7 +681,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("A").Failure.ProgressReport.Message).Should(Equal("{{bold}}This is the Progress Report generated when the node 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()) @@ -807,7 +807,7 @@ var _ = Describe("Interrupts and Timeouts", func() { Ω(times.Get("aft-3-out")).Should(BeNumerically("~", times.Get("aft-3-cancel")+50*time.Millisecond, dt)) Ω(times.Get("aft-4-out")).Should(BeNumerically("~", times.Get("aft-3-out")+gracePeriod, dt)) - Ω(reporter.Did.Find("A")).Should(HaveTimedOut()) + Ω(reporter.Did.Find("A")).Should(HaveTimedOut("A suite timeout occurred")) Ω(reporter.Did.Find("A").Failure.ProgressReport.LeafNodeText).Should(Equal("A")) Ω(reporter.ProgressReports).Should(HaveLen(3)) @@ -867,9 +867,9 @@ var _ = Describe("Interrupts and Timeouts", func() { It("should always favor the shorter timeout", func() { Ω(rt).Should(HaveTracked("bef-A", "bef-B", "bef-C")) - Ω(reporter.Did.Find("A")).Should(HaveTimedOut()) - Ω(reporter.Did.Find("B")).Should(HaveTimedOut()) - Ω(reporter.Did.Find("C")).Should(HaveTimedOut()) + Ω(reporter.Did.Find("A")).Should(HaveTimedOut("A node timeout occurred")) + Ω(reporter.Did.Find("B")).Should(HaveTimedOut("A spec timeout occurred")) + Ω(reporter.Did.Find("C")).Should(HaveTimedOut("A suite timeout occurred")) Ω(times.Get("bef-A")).Should(BeNumerically("~", time.Millisecond*100, 50*time.Millisecond)) Ω(times.Get("bef-B")).Should(BeNumerically("~", time.Millisecond*150, 50*time.Millisecond)) @@ -896,8 +896,8 @@ 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(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 : foo\nto equal\n : 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.Message).Should(MatchRegexp(`A spec timeout occurred and the following failure was recorded after the timeout:\n\nContext was cancelled after .*\nExpected\n : foo\nto equal\n : bar`)) + Ω(reporter.Did.Find("A").Failure.ProgressReport.Message).Should(Equal("{{bold}}This is the Progress Report generated when the spec timeout occurred:{{/}}")) Ω(reporter.Did.Find("A").Failure.ProgressReport.AdditionalReports).Should(ConsistOf("Expected\n : foo\nto equal\n : bar")) }) }) diff --git a/internal/suite.go b/internal/suite.go index 432bd217b..006cfa224 100644 --- a/internal/suite.go +++ b/internal/suite.go @@ -248,7 +248,7 @@ func (suite *Suite) SetProgressStepCursor(cursor ProgressStepCursor) { } /* - Spec Running methods - used during PhaseRun +Spec Running methods - used during PhaseRun */ func (suite *Suite) CurrentSpecReport() types.SpecReport { suite.selectiveLock.Lock() @@ -697,18 +697,23 @@ func (suite *Suite) runNode(node Node, specDeadline time.Time, text string) (typ now := time.Now() deadline := suite.deadline + timeoutInPlay := "suite" if deadline.IsZero() || (!specDeadline.IsZero() && specDeadline.Before(deadline)) { deadline = specDeadline + timeoutInPlay = "spec" } if node.NodeTimeout > 0 && (deadline.IsZero() || deadline.Sub(now) > node.NodeTimeout) { deadline = now.Add(node.NodeTimeout) + timeoutInPlay = "node" } if (!deadline.IsZero() && deadline.Before(now)) || interruptStatus.Interrupted() { //we're out of time already. let's wait for a NodeTimeout if we have it, or GracePeriod if we don't if node.NodeTimeout > 0 { deadline = now.Add(node.NodeTimeout) + timeoutInPlay = "node" } else { deadline = now.Add(gracePeriod) + timeoutInPlay = "grace period" } } @@ -781,7 +786,7 @@ func (suite *Suite) runNode(node Node, specDeadline time.Time, text string) (typ // 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 + failure.Message = fmt.Sprintf("A %s timeout occurred and the following failure was recorded after the timeout:\n\n%s", timeoutInPlay, failureFromRun.Message) } return outcome, failure } @@ -801,9 +806,9 @@ func (suite *Suite) runNode(node Node, specDeadline time.Time, text string) (typ case <-deadlineChannel: // we're out of time - the outcome is a timeout and we capture the failure and progress report outcome = types.SpecStateTimedout - failure.Message, failure.Location = "Timedout", node.CodeLocation + failure.Message, failure.Location = fmt.Sprintf("A %s timeout occurred", timeoutInPlay), node.CodeLocation failure.ProgressReport = suite.generateProgressReport(false).WithoutCapturedGinkgoWriterOutput() - failure.ProgressReport.Message = "{{bold}}This is the Progress Report generated when the timeout occurred:{{/}}" + failure.ProgressReport.Message = fmt.Sprintf("{{bold}}This is the Progress Report generated when the %s timeout occurred:{{/}}", timeoutInPlay) 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