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

1

6

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:

Console logs before

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:

Console logs after

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.

Restorative answered 18/5, 2017 at 9:52 Comment(7)
If you add a print("test print") in the it, when does it print? The fact that the test library prints information about test pass after cleanup seems fine to me. – Airliah
If I adjust the test with a print inside the it, the print just gets printed twice as well. It just seems as if the it gets called twice or something. – Restorative
So from this test and form your edit, we know that the methods get executed in the right order - the fact that the information that the test passed is printed after context after is irrelevant. Now, only problem that remains is the fact that the methods are executed twice. – Airliah
I've updated the question; the fact remains that the example is executed multiple times... – Restorative
Are you sure the method is executed twice and it's not just that a single log entry gets printed twice? Maybe add a variable counting the calls to a method? – Barnaul
@Barnaul I'm quite sure the method runs by the log twice; added breakpoints too – Restorative
It must have to do with how we add the Quick Framework to project. This detail steps might be useful. https://mcmap.net/q/1915204/-how-to-reliably-install-and-setup-quick-test-framework-on-xcode-8 – Kwangchow
K
3

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
Kwangchow answered 28/5, 2017 at 12:54 Comment(6)
I would suggest to create a new project from scratch and add the Quick framework again. Maybe it has to do with some special settings. – Kwangchow
Created a new project and tried again; the first time had the same problem, the second time I got the correct output. I really don't know why though. I'm not sure what special settings I could have in my Tests (in the original project), I used the same pods and configuration. – Restorative
Oh and for reference; the tLog is just my 'test-logger', an instance of SwiftyBeaver – Restorative
Ah, just read the notice. Well truth to be told, I've still got no clue why it happens. However letting the bounty 'go to waste' is also...a waste :) – Restorative
Thanks for being thoughtful. Probably next time you could provide more context on how the issue occurred. It also took me several frustrating attempts to make have a working project with the Quick test framework. Not a trivial task. So many things could go wrong. I wish there's a standard / automatic way to set it up. Nonesuch could we found today. – Kwangchow
FYI. I bounce a new question in SO about how to reliably set up quick test framework on Xcode. https://mcmap.net/q/1915204/-how-to-reliably-install-and-setup-quick-test-framework-on-xcode-8/3549695 – Kwangchow

© 2022 - 2024 β€” McMap. All rights reserved.