Why are the before- and afterEach blocks called multiple times in unit-testing with Quick?

Question

I wrote a test case with some example groups including beforeEach and afterEach. And I expected that each beforeEach and afterEach would be called once for each it.

Alas, for a single it the beforeEach and afterEach got called multiple times.

I've looked at some documentation (i.e. Quick's own documentation and http://jasmine.github.io/2.1/introduction.html), but those don't help my cause.

Here is a small snippet that demonstrates this:

class CheckerTests: QuickSpec {

override func spec() {

    describe("something") {
        beforeEach {
            tLog.info("describe before")
        }
        afterEach {
            tLog.info("describe after")
        }

        context("of something") {
            beforeEach {
                tLog.info("context before")
            }
            afterEach {
                tLog.info("context after")
            }

            it("should behave like something") {
                tLog.info("in the `IT`")
                expect(true).to(beTrue())
            }
        }
    }

}

}

---

My console logs:

The above logs raise two questions:

• I'm not sure when beforeEach and afterEach are called now; nor do I know why I see multiple logs calling them. How come they are called multiple times?

- The above logs show that the context's after block is called before the example passes...shouldn't that happen after the example?

From my code snippet I would've expect the logs to return:

Could someone explain what happens here? And is this the correct behaviour?

---

EDIT:

As suggested by a comment; I also added a log inside the it example (see the revised code snippet above). Which gives me the following logs:

Test Suite 'CheckerTests' started at 2017-05-18 13:35:29.025
Test Case '-[CheckerTests something__of_something__should_behave_like_something]' started.
13:35:29.046 💙 INFO CheckerTests.spec():21 - describe before
13:35:29.046 💙 INFO CheckerTests.spec():21 - describe before
13:35:29.048 💙 INFO CheckerTests.spec():29 - context before
13:35:29.048 💙 INFO CheckerTests.spec():29 - context before
13:35:29.048 💙 INFO CheckerTests.spec():36 - in the `IT`
13:35:29.048 💙 INFO CheckerTests.spec():36 - in the `IT`
13:35:29.049 💙 INFO CheckerTests.spec():32 - context after
1Test Case '-[CheckerTests something__of_something__should_behave_like_something]' passed (0.024 seconds).
3:35:29.049 💙 INFO CheckerTests.spec():32 - context after
13:35:29.050 💙 INFOTest Suite 'CheckerTests' passed at 2017-05-18 13:35:29.050.
     Executed 1 test, with 0 failures (0 unexpected) in 0.024 (0.025) seconds
 CheckerTests.spec():24 - describe after
13:35:29.050 \360\237\222Test Suite 'CheckerTests.xctest' passed at 2017-05-18 13:35:29.051.
     Executed 1 test, with 0 failures (0 unexpected) in 0.024 (0.026) seconds
\231 INFO CheckerTests.spec():24 - describe after
Test Suite 'Selected tests' passed at 2017-05-18 13:35:29.051.
     Executed 1 test, with 0 failures (0 unexpected) in 0.024 (0.029) seconds

The above logs show me that the example is running twice, which confuses me even more.

---

EDIT:
One of the questions is answered:

- The above logs show that the context's after block is called before the example passes...shouldn't that happen after the example?

It seems the tests follow up in the correct order, so that answers the above question.

---

EDIT:

For reference; this is what my Podfile looks like:

def pods_for_testing
    pod 'Quick'
    pod 'Nimble'
    pod 'KIF'
end

target 'Checker' do
  project 'Checker.xcodeproj', 'dev' => :debug, 'ntrl' => :debug, 'acpt' => :release, 'prod' => :release, 'prod appstore' => :release

  pod 'SQLCipher'
  pod 'UrbanAirship-iOS-SDK'
  pod 'TBXML', :inhibit_warnings => true
  pod 'SSZipArchive'
  pod 'Google/Analytics'
  pod 'Moya', '>= 8.0'
  pod 'Unbox'
  pod 'ProcedureKit'
  pod 'ProcedureKit/Mobile'
  pod 'SwiftyBeaver'
  pod 'OHHTTPStubs'
  pod 'OHHTTPStubs/Swift'

  target 'CheckerTests' do
      inherit! :search_paths
      pods_for_testing
  end

  target 'CheckerUITests' do
      inherit! :search_paths
      pods_for_testing
  end

end

Next to this I'm not sure what other settings could be affecting the tests.

Answer 1

I tried to reproduce the issue. But in my case, each of the testcase was being executed exactly one.

Thus, the issue doesn't seem to be reproducible in a normal setting. Probably you have some special setting that causes the issue you described above.

Note:
I'm not sure what other libraries you have to get the 'tLog.info', but I couldn't find one. I assume that doesn't matter for this purpose. I substitute with print(_:) statement instead.

Here is my 'TryQuickTest.swift' looks like:

import XCTest
import Quick
import Nimble 

class TryQuickTest: QuickSpec {

    override func spec() {

        describe("blah") {
            beforeEach {
                print("describe before")
            }
            afterEach {
                print("describe after")
            }

            context("of blah2") {
                beforeEach {
                    print("context before")
                }
                afterEach {
                    print("context after")
                }

                it("first it should be like this") {
                    print("in the first `IT`")
                    XCTFail("Hey fail in first it")
                }

                it("second it should be like this") {
                    print("in the second `IT`")
                    XCTFail("Hey fail in second it")
                }
            }
        }   
    }    
}

And my console for the run of this test file:

Test Suite 'Selected tests' started at 2017-05-28 07:35:32.345
Test Suite 'PlayQuickTests.xctest' started at 2017-05-28 07:35:32.347
Test Suite 'TryQuickTest' started at 2017-05-28 07:35:32.348
Test Case '-[PlayQuickTests.TryQuickTest blah__of_blah2__first_it_should_be_like_this]' started.
describe before
context before
in the first `IT`
/Users/shisui/Developer/General/iOS_Swift/PlayQuick/PlayQuickTests/TryQuickTest.swift:35: error: -[PlayQuickTests.TryQuickTest blah__of_blah2__first_it_should_be_like_this] : failed - Hey fail in first it
context after
describe after
Test Case '-[PlayQuickTests.TryQuickTest blah__of_blah2__first_it_should_be_like_this]' failed (0.004 seconds).
Test Case '-[PlayQuickTests.TryQuickTest blah__of_blah2__second_it_should_be_like_this]' started.
describe before
context before
in the second `IT`
/Users/shisui/Developer/General/iOS_Swift/PlayQuick/PlayQuickTests/TryQuickTest.swift:40: error: -[PlayQuickTests.TryQuickTest blah__of_blah2__second_it_should_be_like_this] : failed - Hey fail in second it
context after
describe after
Test Case '-[PlayQuickTests.TryQuickTest blah__of_blah2__second_it_should_be_like_this]' failed (0.003 seconds).
Test Suite 'TryQuickTest' failed at 2017-05-28 07:35:32.359.
    Executed 2 tests, with 2 failures (0 unexpected) in 0.007 (0.010) seconds
Test Suite 'PlayQuickTests.xctest' failed at 2017-05-28 07:35:32.359.
    Executed 2 tests, with 2 failures (0 unexpected) in 0.007 (0.012) seconds
Test Suite 'Selected tests' failed at 2017-05-28 07:35:32.374.
    Executed 2 tests, with 2 failures (0 unexpected) in 0.007 (0.029) seconds

From the output above. The each testcase was executed only once.

And if I remove the second 'it' part. The console output would look like this:

Test Suite 'Selected tests' started at 2017-05-28 07:56:09.214
Test Suite 'PlayQuickTests.xctest' started at 2017-05-28 07:56:09.215
Test Suite 'TryQuickTest' started at 2017-05-28 07:56:09.215
Test Case '-[PlayQuickTests.TryQuickTest blah__of_blah2__first_it_should_be_like_this]' started.
describe before
context before
in the first `IT`
/Users/shisui/Developer/General/iOS_Swift/PlayQuick/PlayQuickTests/TryQuickTest.swift:35: error: -[PlayQuickTests.TryQuickTest blah__of_blah2__first_it_should_be_like_this] : failed - Hey fail in first it
context after
describe after
Test Case '-[PlayQuickTests.TryQuickTest blah__of_blah2__first_it_should_be_like_this]' failed (0.006 seconds).
Test Suite 'TryQuickTest' failed at 2017-05-28 07:56:09.222.
    Executed 1 test, with 1 failure (0 unexpected) in 0.006 (0.007) seconds
Test Suite 'PlayQuickTests.xctest' failed at 2017-05-28 07:56:09.224.
    Executed 1 test, with 1 failure (0 unexpected) in 0.006 (0.009) seconds
Test Suite 'Selected tests' failed at 2017-05-28 07:56:09.224.
    Executed 1 test, with 1 failure (0 unexpected) in 0.006 (0.011) seconds