AfterSuiteDidRun is not invoked when ginkgo run with -p

[ferozjilla]

Hello,

We are using Ginkgo Version 1.4.0.

We have a custom reporter for our tests for which we are failing to generate the AfterSuite report when ginkgo is run with the -p flag. Without the flag, the reporter works fine.

We have made a simpler test suite to highlight our problem. It can be cloned from: https://github.com/ferozjilla/ginkgo-demo

Without the -p flag, the output is:

ginkgo  .
Running Suite: Dummy Smoke Tests
================================
Random Seed: 1500908397
Will run 0 of 0 specs

DUMMY SpecSuiteWillBegin
DUMMY BeforeSuiteDidRun
DUMMY AfterSuiteDidRun SUCCESS!

Ran 0 of 0 Specs in 0.000 seconds
SUCCESS! -- 0 Passed | 0 Failed | 0 Pending | 0 Skipped DUMMY SpecSuiteDidEnd
PASS

Ginkgo ran 1 suite in 441.679738ms
Test Suite Passed

With the -p flag, the output is:

ginkgo -p .
Running Suite: Dummy Smoke Tests
================================
Random Seed: 1500908402
Will run 0 specs

Running in parallel across 7 nodes

DUMMY SpecSuiteWillBegin


DUMMY SpecSuiteWillBegin


DUMMY SpecSuiteWillBegin


DUMMY SpecSuiteWillBegin


DUMMY BeforeSuiteDidRun


DUMMY BeforeSuiteDidRun


DUMMY BeforeSuiteDidRun


DUMMY SpecSuiteWillBegin


DUMMY BeforeSuiteDidRun


DUMMY SpecSuiteWillBegin


DUMMY SpecSuiteWillBegin


DUMMY BeforeSuiteDidRun


DUMMY BeforeSuiteDidRun


DUMMY BeforeSuiteDidRun


Ran 0 of 0 Specs in 0.110 seconds
SUCCESS! -- 0 Passed | 0 Failed | 0 Pending | 0 Skipped

Ginkgo ran 1 suite in 525.599759ms
Test Suite Passed

As can be seen, the AfterSuiteDidRun method is not called in the case when the -p flag is included. This results in the loss of the after suite reports for the tests.

Upon further investigation, we discovered the following:

• The SynchronizedAfterSuite method from ginkgo_dsl.go is not invoked https://github.com/onsi/ginkgo/blob/master/ginkgo_dsl.go#L523:L531. This causes the afterSuiteNodes to not be initialized which becomes an issue in this part of the code:
  https://github.com/onsi/ginkgo/blob/master/internal/specrunner/spec_runner.go#L129:L142
  because https://github.com/onsi/ginkgo/blob/master/internal/specrunner/spec_runner.go#L140 method is not invoked.

• When run with the -stream flag, we see that each individual nodes does invoke the AfterSuiteDidRun.

ginkgo -p -stream .
[4] Running Suite: Dummy Smoke Tests
[4] ================================
[4] Random Seed: 1500909202
[4] Parallel test node 4/7.
[4]
[4] DUMMY SpecSuiteWillBegin
[2] Running Suite: Dummy Smoke Tests
[2] ================================
[2] Random Seed: 1500909202
[2] Parallel test node 2/7.
[2]
[2] DUMMY SpecSuiteWillBegin
[7] Running Suite: Dummy Smoke Tests
[7] ================================
[7] Random Seed: 1500909202
[7] Parallel test node 7/7.
[7]
[7] DUMMY SpecSuiteWillBegin
[1] Running Suite: Dummy Smoke Tests
[1] ================================
[1] Random Seed: 1500909202
[1] Parallel test node 1/7.
[1]
[1] DUMMY SpecSuiteWillBegin
[1] DUMMY BeforeSuiteDidRun
[3] Running Suite: Dummy Smoke Tests
[3] ================================
[3] Random Seed: 1500909202
[3] Parallel test node 3/7.
[3]
[3] DUMMY SpecSuiteWillBegin
[3] DUMMY BeforeSuiteDidRun
[3] DUMMY AfterSuiteDidRun SUCCESS!
[3]
[3] Ran 0 of 0 Specs in 0.000 seconds
[3] SUCCESS! -- 0 Passed | 0 Failed | 0 Pending | 0 Skipped DUMMY SpecSuiteDidEnd
[3] PASS
[5] Running Suite: Dummy Smoke Tests
[5] ================================
[5] Random Seed: 1500909202
[5] Parallel test node 5/7.
[5]
[5] DUMMY SpecSuiteWillBegin
[5] DUMMY BeforeSuiteDidRun
[5] DUMMY AfterSuiteDidRun SUCCESS!
[5]
[5] Ran 0 of 0 Specs in 0.000 seconds
[5] SUCCESS! -- 0 Passed | 0 Failed | 0 Pending | 0 Skipped DUMMY SpecSuiteDidEnd
[5] PASS
[6] Running Suite: Dummy Smoke Tests
[6] ================================
[6] Random Seed: 1500909202
[6] Parallel test node 6/7.
[6]
[6] DUMMY SpecSuiteWillBegin
[6] DUMMY BeforeSuiteDidRun
[6] DUMMY AfterSuiteDidRun SUCCESS!
[6]
[6] Ran 0 of 0 Specs in 0.000 seconds
[6] SUCCESS! -- 0 Passed | 0 Failed | 0 Pending | 0 Skipped DUMMY SpecSuiteDidEnd
[6] PASS
[7] DUMMY BeforeSuiteDidRun
[4] DUMMY BeforeSuiteDidRun
[2] DUMMY BeforeSuiteDidRun
[7] DUMMY AfterSuiteDidRun SUCCESS!
[7]
[7] Ran 0 of 0 Specs in 0.054 seconds
[4] DUMMY AfterSuiteDidRun SUCCESS!
[4]
[4] Ran 0 of 0 Specs in 0.055 seconds
[7] SUCCESS! -- 0 Passed | 0 Failed | 0 Pending | 0 Skipped DUMMY SpecSuiteDidEnd
[7] PASS
[4] SUCCESS! -- 0 Passed | 0 Failed | 0 Pending | 0 Skipped DUMMY SpecSuiteDidEnd
[4] PASS
[2] DUMMY AfterSuiteDidRun SUCCESS!
[2]
[2] Ran 0 of 0 Specs in 0.055 seconds
[2] SUCCESS! -- 0 Passed | 0 Failed | 0 Pending | 0 Skipped DUMMY SpecSuiteDidEnd
[2] PASS
[1] DUMMY AfterSuiteDidRun SUCCESS!
[1]
[1] Ran 0 of 0 Specs in 0.108 seconds
[1] SUCCESS! -- 0 Passed | 0 Failed | 0 Pending | 0 Skipped DUMMY SpecSuiteDidEnd
[1] PASS

Ginkgo ran 1 suite in 827.293659ms
Test Suite Passed

cc: @alamages , @jamesjoshuahill, @BooleanCat

Are we missing something or have we found an issue? Thanks

[onsi]

Hey @ferozjilla can you point me at the actual code? The ginkgo-demo you generated - while helpful in providing an isolated example - is misleading.

Ginkgo is running the SynchronizedAfterSuite and it is calling your reporter's AfterSuiteDidRun - it's just not capturing any output generated by your AfterSuiteDidRun method.

You can prove this to yourself like so:

func (report *DummyReport) AfterSuiteDidRun(summary *types.SetupSummary) {
	fmt.Println("DUMMY AfterSuiteDidRun SUCCESS!")
	ioutil.WriteFile(fmt.Sprintf("aftersuite%d.out", ginkgo.GinkgoParallelNode()), []byte("I ran..."), 0777)
}

Run ginkgo -p after this and you'll see a bunch of aftersuiteN.out files - one for each parallel node.

---

The reason Ginkgo doesn't emit the output of your reporter is because it runs custom reporters after it runs the default reporter and it is the default reporter that captures output and emits it. This happens here:

ginkgo/ginkgo_dsl.go

Line 205 in 228e3a8

specReporters = append([]Reporter{buildDefaultReporter()}, specReporters...)

Problem is... I don't remember why I wrote it this way. This is, sadly, a great example of Connascence of Position where I haven't clearly documented if/whether or not the order is significant.

I've switched the order around and seen all the Ginkgo tests go green, though. So folks debugging similar things in the future won't have quite as baffling an experience.

[ferozjilla]

Hey @onsi, thanks for the prompt reply, it has fixed our issue :)

The actual code is here: https://github.com/pivotal-cf/cf-redis-smoke-tests. The bin/test script is invoked to start our ginkgo tests. The following summary from our reporter was missed in the output before the fix: https://github.com/pivotal-cf/cf-redis-smoke-tests/blob/master/service/reporter/smoke_test_report.go#L122-L134

Thanks again for the quick fix!

[onsi]

Great! btw @ferozjilla I think a lot of what you are trying to do with the customer reporter and could be accomplished with Ginkgo's By function. Have you given it a look? I'd be curious to understand what Step is giving you and whether or not it's pointing to a missing feature in Ginkgo.