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.

Gerald Eersteling
  • 1,244
  • 14
  • 28
  • 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. – Losiowaty May 18 '17 at 10:14
  • 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. – Gerald Eersteling May 18 '17 at 11:33
  • 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. – Losiowaty May 18 '17 at 18:04
  • I've updated the question; the fact remains that the example is executed multiple times... – Gerald Eersteling May 19 '17 at 07:00
  • 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? – qwerty May 29 '17 at 01:40
  • @qwerty I'm quite sure the method runs by the log twice; added breakpoints too – Gerald Eersteling May 29 '17 at 07:10
  • It must have to do with how we add the Quick Framework to project. This `detail steps` might be useful. https://stackoverflow.com/a/44263733/3549695 – Wismin May 30 '17 at 13:45

1 Answers1

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
Wismin
  • 1,135
  • 7
  • 21
  • 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. – Wismin May 28 '17 at 13:00
  • 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. – Gerald Eersteling May 29 '17 at 07:07
  • Oh and for reference; the `tLog` is just my 'test-logger', an instance of `SwiftyBeaver` – Gerald Eersteling May 29 '17 at 07:11
  • 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 :) – Gerald Eersteling May 29 '17 at 12:41
  • 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. – Wismin May 29 '17 at 13:18
  • 1
    FYI. I bounce a new question in SO about how to reliably set up quick test framework on Xcode. https://stackoverflow.com/q/44244912/3549695 – Wismin May 29 '17 at 14:34