classLateCallback:XCTestCase{letcallBackDelay:NSTimeInterval=2functestNotWaitingLongEnough(){letpromiseToCallBack=expectationWithDescription("calls back")after(seconds:callBackDelay){()->Voidinprint("I knew you'd call!")promiseToCallBack.fulfill()}waitForExpectationsWithTimeout(callBackDelay/2){errorinprint("Aww, we timed out: \(error)")}}}
Go ahead and run this. Everything works fine – for now:
12345678910111213141516171819
Test Suite 'All tests' started at 2016-03-19 21:56:49.223
Test Suite 'Tests.xctest' started at 2016-03-19 21:56:49.225
Test Suite 'LateCallback' started at 2016-03-19 21:56:49.225
Test Case '-[Tests.LateCallback testNotWaitingLongEnough]' started.
Aww, we timed out: Optional(Error Domain=com.apple.XCTestErrorDomain Code=0 "The operation couldn’t be completed. (com.apple.XCTestErrorDomain error 0.)")
/Users/jeremy/Github/XCTestExpectationGotchas/Tests/LateCallback.swift:26: error: -[Tests.LateCallback testNotWaitingLongEnough] : Asynchronous wait failed: Exceeded timeout of 1 seconds, with unfulfilled expectations: "calls back".
Test Case '-[Tests.LateCallback testNotWaitingLongEnough]' failed (2.247 seconds).
Test Suite 'LateCallback' failed at 2016-03-19 21:56:51.473.
Executed 1 test, with 1 failure (0 unexpected) in 2.247 (2.248) seconds
Test Suite 'Tests.xctest' failed at 2016-03-19 21:56:51.474.
Executed 1 test, with 1 failure (0 unexpected) in 2.247 (2.249) seconds
Test Suite 'All tests' failed at 2016-03-19 21:56:51.474.
Executed 1 test, with 1 failure (0 unexpected) in 2.247 (2.251) seconds
Test session log:
/var/folders/63/np5g0d5j54x1s0z12rf41wxm0000gp/T/com.apple.dt.XCTest-status/Session-2016-03-19_21:56:45-vfvzhb.log
Program ended with exit code: 1
Test suite kicks off, everything runs, the test fails due to a timeout while
waiting for the expectation to be met, and the process exits.
This is how XCTestExpectation is supposed to work.
Kaboom: Missing the Window
We only ran the one test, though.
Let’s say you have more tests to run after this one.
We can fake this out by adding a new test method whose name
sorts alphabetically after our testNotWaitingLongEnough test
that runs the runloop for a bit before exiting.
Conveniently enough, XCTest happens to run tests in alphabetical order,
so the test runner will run our first test,
then run this second one,
then exit.
Here’s our new test method:
123456
functestZzz(){print("Let's just wait a while…")lettillAfterCallBack=callBackDelayspin(forSeconds:tillAfterCallBack)print("Yawn, that was boring.")}
Test Suite 'All tests' started at 2016-03-19 22:19:31.796
Test Suite 'Tests.xctest' started at 2016-03-19 22:19:31.798
Test Suite 'LateCallback' started at 2016-03-19 22:19:31.798
Test Case '-[Tests.LateCallback testNotWaitingLongEnough]' started.
Aww, we timed out: Optional(Error Domain=com.apple.XCTestErrorDomain Code=0 "The operation couldn’t be completed. (com.apple.XCTestErrorDomain error 0.)")
/Users/jeremy/Github/XCTestExpectationGotchas/Tests/LateCallback.swift:16: error: -[Tests.LateCallback testNotWaitingLongEnough] : Asynchronous wait failed: Exceeded timeout of 1 seconds, with unfulfilled expectations: "calls back".
Test Case '-[Tests.LateCallback testNotWaitingLongEnough]' failed (2.202 seconds).
Test Case '-[Tests.LateCallback testZzz]' started.
Let's just wait a while…
2.0: finished waiting
I knew you'd call!
2016-03-19 22:19:34.001 xctest[92369:96447173] *** Assertion failure in -[XCTestExpectation fulfill], /Library/Caches/com.apple.xbs/Sources/XCTest/XCTest-9530/XCTestFramework/Classes/XCTestCase+AsynchronousTesting.m:451
2016-03-19 22:19:34.002 xctest[92369:96447173] *** Terminating app due to uncaught exception 'NSInternalInconsistencyException', reason: 'API violation - called -[XCTestExpectation fulfill] after the wait context has ended for calls back.'
*** First throw call stack:
(
0 CoreFoundation 0x00007fff897ec03c __exceptionPreprocess + 172
1 libobjc.A.dylib 0x00007fff8674276e objc_exception_throw + 43
2 CoreFoundation 0x00007fff897ebe1a +[NSException raise:format:arguments:] + 106
3 Foundation 0x00007fff8b98b99b -[NSAssertionHandler handleFailureInMethod:object:file:lineNumber:description:] + 195
4 XCTest 0x000000010006f149 -[XCTestExpectation fulfill] + 302
5 Tests 0x00000001006858ab _TFFC5Tests12LateCallback24testNotWaitingLongEnoughFS0_FT_T_U_FT_T_ + 203
6 Tests 0x0000000100685c4f _TFF5Tests5afterFT7secondsSd4callFT_T__T_U_FT_T_ + 367
7 Tests 0x0000000100685de7 _TTRXFo__dT__XFdCb__dT__ + 39
8 libdispatch.dylib 0x00007fff8301f700 _dispatch_call_block_and_release + 12
9 libdispatch.dylib 0x00007fff8301be73 _dispatch_client_callout + 8
10 libdispatch.dylib 0x00007fff8302d6a0 _dispatch_after_timer_callback + 77
11 libdispatch.dylib 0x00007fff8301be73 _dispatch_client_callout + 8
12 libdispatch.dylib 0x00007fff830284e6 _dispatch_source_latch_and_call + 721
13 libdispatch.dylib 0x00007fff8302093b _dispatch_source_invoke + 412
14 libdispatch.dylib 0x00007fff8302c5aa _dispatch_main_queue_callback_4CF + 416
15 CoreFoundation 0x00007fff8973f3f9 __CFRUNLOOP_IS_SERVICING_THE_MAIN_DISPATCH_QUEUE__ + 9
16 CoreFoundation 0x00007fff896fa68f __CFRunLoopRun + 2159
17 CoreFoundation 0x00007fff896f9bd8 CFRunLoopRunSpecific + 296
18 Foundation 0x00007fff8b953b29 -[NSRunLoop(NSRunLoop) runMode:beforeDate:] + 278
19 Foundation 0x00007fff8b971d9e -[NSRunLoop(NSRunLoop) runUntilDate:] + 108
20 Tests 0x0000000100685262 _TF5Tests4spinFT10forSecondsSd_T_ + 162
21 Tests 0x000000010068510f _TFC5Tests12LateCallback7testZzzfS0_FT_T_ + 207
22 Tests 0x00000001006852a2 _TToFC5Tests12LateCallback7testZzzfS0_FT_T_ + 34
23 CoreFoundation 0x00007fff896c37bc __invoking___ + 140
24 CoreFoundation 0x00007fff896c3612 -[NSInvocation invoke] + 290
25 XCTest 0x0000000100022598 __24-[XCTestCase invokeTest]_block_invoke_2 + 159
26 XCTest 0x000000010005602e -[XCTestContext performInScope:] + 184
27 XCTest 0x00000001000224e8 -[XCTestCase invokeTest] + 169
28 XCTest 0x0000000100022983 -[XCTestCase performTest:] + 443
29 XCTest 0x0000000100020654 -[XCTestSuite performTest:] + 377
30 XCTest 0x0000000100020654 -[XCTestSuite performTest:] + 377
31 XCTest 0x0000000100020654 -[XCTestSuite performTest:] + 377
32 XCTest 0x000000010000e892 __25-[XCTestDriver _runSuite]_block_invoke + 51
33 XCTest 0x0000000100033a1b -[XCTestObservationCenter _observeTestExecutionForBlock:] + 611
34 XCTest 0x000000010000e7db -[XCTestDriver _runSuite] + 408
35 XCTest 0x000000010000f38a -[XCTestDriver _checkForTestManager] + 696
36 XCTest 0x000000010005729f _XCTestMain + 628
37 xctest 0x0000000100001dca xctest + 7626
38 libdyld.dylib 0x00007fff8b25f5c9 start + 1
)
libc++abi.dylib: terminating with uncaught exception of type NSException
(lldb)
And now we’re sitting at the debugger. Oof, that smarts.
Take a look at what’s going on in that backtrace:
Our Zzz test is hanging out running the runloop.
The after(seconds:call:) finishes waiting and calls its callback.
The callback fulfills an expectation belonging to the
(already finished, already failed) first test
This trips a “you’re holding it wrong” assertion in the test framework:
Terminating app due to uncaught exception
‘NSInternalInconsistencyException’, reason:
‘API violation - called -[XCTestExpectation fulfill]
after the wait context has ended for calls back.’
You might run up against this in practice when writing integration tests
against a live, but not always quick to respond, backend service.
Kaboom: Calling Twice
That’s not the only way things can go wrong.
What happens if our callback has at-least-once rather than exactly-once
behavior, and happens to call back twice?
1234567891011121314
classDoubleCallback:XCTestCase{functestDoubleTheFulfillment(){letpromiseToCallBack=expectationWithDescription("calls back")letcallBackDelay:NSTimeInterval=1twiceAfter(seconds:callBackDelay){print("i hear you calling me")promiseToCallBack.fulfill()}letafterCallBack=2*callBackDelaywaitForExpectationsWithTimeout(afterCallBack,handler:nil)}}
Terminating app due to uncaught exception
‘NSInternalInconsistencyException’, reason:
‘API violation - multiple calls made to
-[XCTestExpectation fulfill] for calls back.’
This probably does indicate an actual error in the code calling the callback
much of the time, but if it doesn’t, you’ll want to know about and be able to
dodge this assertion, too.
What’s Wrong?
This double-callback scenario calls back twice in succession.
But if there were a delay between the first and second call back,
and the test runner happened to exit during that delay,
you’d get a successful test run rather than crashing every time.
With a delay between callbacks,
you’d only trip the assertion
when other tests kept the test runner process running long enough.
This situation parallels that of the too-late callback:
no problems till appear till something else runs out the clock.
This is tricky:
You won’t ever trip them when you’re banging away at whatever
the latest test you’re working on is, because
a test runner running just that async test will exit
as soon as the wait-timer runs out,
before the too-late/second callback can occur.
You might not even trip them when you run your whole test suite
at first, because they might be the last test in the run
or the tests that follow don’t run for long enough.
This is also obnoxious to run into:
When an assertion trips, it bombs the entire test process.
(Unwrapping an implicitly unwrapped optional to find a nil has the same
effect.)
These assertions aren’t test failures that would allow testing to continue;
instead, XCTest treats as programmer error:
Fulfilling a promise after its test has already finished
Filling an already-filled promise
To be fair, these cases are called out
in the documentation for XCTestExpectation.fulfill():
Call -fulfill to mark an expectation as having been met.
It’s an error to call -fulfill on an expectation
that has already been fulfilled
or when the test case that vended the expectation has already completed.
but the documentation isn’t explicit that “it’s an error” translates to
“and it will bomb your whole test process”.
Avoiding These Assertions
In both cases, the problem is that we’re calling fulfill when we shouldn’t.
So let’s not do that.
Let the Expectation Die With the Test
XCTest actually hangs on to the expectations it creates
so it can collect them during the wait call.
Our test method doesn’t need yet another strong reference to the
expectation; if we instead work with a weak reference in our callback closure,
the expectation will die with our test,
rather than lingering for us to trip over after the test has completed,
and we’ll have turned our callback into a no-op.
First, neuter the time-bombed testNotWaitingLongEnough
by prefixing its name with an x so it won’t get picked up
by the test runner any more:
12345678
class LateCallback: XCTestCase {
let callBackDelay: NSTimeInterval = 2
- func testNotWaitingLongEnough() {+ func xtestNotWaitingLongEnough() { let promiseToCallBack = expectationWithDescription("calls back")
after(seconds: callBackDelay) { () -> Void in
Now clone it, but this time, use a weak reference
to the expectation:
Run the LateCallback suite again, and
the logs now look like (or skip to the summary):
1234567891011121314151617181920212223
Test Suite 'Selected tests' started at 2016-03-19 23:19:19.980
Test Suite 'LateCallback' started at 2016-03-19 23:19:19.981
Test Case '-[Tests.LateCallback testPreparedForNotWaitingLongEnough]' started.
Aww, we timed out: Optional(Error Domain=com.apple.XCTestErrorDomain Code=0 "The operation couldn’t be completed. (com.apple.XCTestErrorDomain error 0.)")
/Users/jeremy/Github/XCTestExpectationGotchas/Tests/LateCallback.swift:34: error: -[Tests.LateCallback testPreparedForNotWaitingLongEnough] : Asynchronous wait failed: Exceeded timeout of 1 seconds, with unfulfilled expectations: "calls back".
Test Case '-[Tests.LateCallback testPreparedForNotWaitingLongEnough]' failed (1.945 seconds).
Test Case '-[Tests.LateCallback testZzz]' started.
Let's just wait a while…
2.0: finished waiting
too late, buckaroo
2.0: all done here
Yawn, that was boring.
Test Case '-[Tests.LateCallback testZzz]' passed (2.004 seconds).
Test Suite 'LateCallback' failed at 2016-03-19 23:19:23.932.
Executed 2 tests, with 1 failure (0 unexpected) in 3.950 (3.951) seconds
Test session log:
/var/folders/63/np5g0d5j54x1s0z12rf41wxm0000gp/T/com.apple.dt.XCTest-status/Session-2016-03-19_23:19:16-QZf0lq.log
Test Suite 'Selected tests' failed at 2016-03-19 23:19:23.933.
Executed 2 tests, with 1 failure (0 unexpected) in 3.950 (3.953) seconds
Program ended with exit code: 1
Our testZzz runs to completion and passes,
and the test process exits on its own terms
reporting the one failure.
The late callback still happened,
but by that time, promiseToCallBack had been zeroed,
so we never called fulfill().
Assertion: Dodged!
Kill the Expectation Proactively
What about the double-callback case?
We can use the same trick,
only this time,
we’ll want to proactively annihilate the expectation:
1234567891011121314151617
functestSafelyDoubleTheFulfillment(){weakvarpromiseToCallBack=expectationWithDescription("calls back")letcallBackDelay:NSTimeInterval=1twiceAfter(seconds:callBackDelay){guardletpromise=promiseToCallBackelse{print("once was enough, thanks!")return}promise.fulfill()promiseToCallBack=nil}letafterCallBack=2*callBackDelaywaitForExpectationsWithTimeout(afterCallBack,handler:nil)}
With the unsafe test neutered via the prefix-x trick,
running the test class gives (or skip to the summary):
123456789101112131415161718192021
Test Suite 'Selected tests' started at 2016-03-19 23:22:56.356
Test Suite 'DoubleCallback' started at 2016-03-19 23:22:56.357
Test Case '-[Tests.DoubleCallback testSafelyDoubleTheFulfillment]' started.
1.0: finished waiting
Test session log:
/var/folders/63/np5g0d5j54x1s0z12rf41wxm0000gp/T/com.apple.dt.XCTest-status/Session-2016-03-19_23:22:51-14ywpS.log
now once
i hear you calling me
now twice
once was enough, thanks!
wasn't that nice?
1.0: all done here
Test Case '-[Tests.DoubleCallback testSafelyDoubleTheFulfillment]' passed (1.099 seconds).
Test Suite 'DoubleCallback' passed at 2016-03-19 23:22:57.457.
Executed 1 test, with 0 failures (0 unexpected) in 1.099 (1.100) seconds
Test Suite 'Selected tests' passed at 2016-03-19 23:22:57.458.
Executed 1 test, with 0 failures (0 unexpected) in 1.099 (1.102) seconds
Program ended with exit code: 0
Since we explicitly set the promise to nil,
we only end up fulfilling it once.
No harm, no foul.
Use a Different Promise API
If you’ve got an API written in terms of a promise/future library already,
such as Deferred,
then there’s no need to use XCTest’s promises:
classBringYourOwnPromises:XCTestCase{letanyDelay:NSTimeInterval=1functestGettingAPony(){letfuturePony=giveMeAPony(after:anyDelay)letlongEnough=anyDelay+1guardletpony=futurePony.wait(.Interval(longEnough))else{XCTFail("no pony ;_;")return}print("we got a pony! \(pony)")}functestWhenImpatientNoPonyForYou(){letfuturePony=giveMeAPony(after:anyDelay)guardletpony=futurePony.wait(.Now)else{print("no patience, no pony")return}XCTFail("we got a pony???! \(pony)")}functestZzzDoesNotCrash(){spin(forSeconds:2*anyDelay)}}
Summary
Always assign your expectations to a weak reference,
and then bail in your callback if it’s nil.
In the rare case where you expect your callback to be triggered
more than once, you can avoid fulfilling by annihilating your
weak reference after fulfilling it and then ignoring future calls.
More likely, you know how many times you should be called,
and you’ll want to fulfill the promise only on the
last call. But the workaround is there if you need it.
If you’re already working with a promise-based API,
you can skip XCTestExpectation and use whatever wait-and-see
API is provided by that promise instead of XCTest’s own.
This has the added advantage of linearizing your test code
by eliminating the need to handle the delivered value
in the closure (or manually shuttle it out to assert against
after the XCTest wait has finished).