NSOperation's completionBlock is called twice.

[difujia]

Try the following test.

func testCompletionBlock() {
    let queue = OperationQueue()
    let blockOp = BlockOperation()
    let exp = expectationWithDescription("Block finished")
    blockOp.addCompletionBlock {
        exp.fulfill()
    }
    queue.addOperation(blockOp)
    waitForExpectationsWithTimeout(5, handler: nil)
}

Then the test runner will log:

Terminating app due to uncaught exception 'NSInternalInconsistencyException', reason: 'API violation - multiple calls made to -[XCTestExpectation fulfill] for Block finished.'

The same error appear even if I set the completionBlock directly, which I think make no difference when only one completionBlock exists.

Discussion Xcode would not always stop the test as the error pops up, I think this is due to a race condition that the second call of fulfill() may happen either before or after waitForExpectationsWithTimeout has seen the effect of the first call (in case of after, the test has finished running and succeeded). Anyway, this is probably irrelevant of the issue. Isn't the completionBlock guaranteed to execute only once by Foundation framework?

[danthorpe]

Hi @difujia, thanks for the feedback. This is a great spot, and may explain some of the flaky unit tests in #119. Will look into it today.

[danthorpe]

Looking into this more closely. Have re-produces your exception. Hmm, I think you're right about a race condition with regard to fulfill - which explains why some of the tests are inconsistent (I need to refactor them).

But, also, there is this test: https://github.com/danthorpe/Operations/blob/development/Tests/Core/OperationTests.swift#L142 which admittedly doesn't test against multiple invocation of the completion block, but according to this bug, should be failing.

Also, I'll just add, that most of the tests fulfill their expectation using a BlockObserver (https://github.com/danthorpe/Operations/blob/development/Tests/Core/OperationTests.swift#L100) instead of a completion handler. This is because it's a little ill-defined exactly when that completion handler will be run by NSOperation. It happens after the operation's finished is true, (which is after the observers are notified), but, it's not very clear in what threading context the block is run.

Anyway, I will continue to investigate...

[danthorpe]

Okay, so more info. This bug doesn't have anything to do with chaining completion blocks (as @difujia said). Changing the test case a little bit to see what's happening into this:

func test__block_operation_with_default_block_runs_completion_block_once() {
    let _queue = OperationQueue()
    let expectation = expectationWithDescription("Test: \(__FUNCTION__)")
    let operation = BlockOperation()
    operation.log.severity = .Verbose

    operation.completionBlock = {
        print("*** I'm in a completion block on \(String.fromCString(dispatch_queue_get_label(DISPATCH_CURRENT_QUEUE_LABEL)))")
    }

    operation.addObserver(BlockObserver { op, errors in
        expectation.fulfill()
    })

    _queue.addOperation(operation)
    waitForExpectationsWithTimeout(3, handler: nil)
}

Will output the following in the test runner logs:

Test Case '-[iOS_OperationsTests.BlockOperationTests test__block_operation_with_default_block_runs_completion_block_once]' started.
Unnamed Block Operation: Initialized -> Pending
Unnamed Block Operation: Pending -> EvaluatingConditions
Unnamed Block Operation: EvaluatingConditions -> Ready
Unnamed Block Operation: Ready -> Executing
Unnamed Block Operation: did start
Unnamed Block Operation: Executing -> Finishing
Unnamed Block Operation: did Test Case '-[iOS_OperationsTests.BlockOperationTests test__block_operation_with_default_block_runs_completion_block_once]' passed (0.001 seconds).
finish with no errors.
*** I'm in a completion block on Optional("com.apple.root.utility-qos")
*** I'm in a completion block on Optional("com.apple.root.utility-qos")
Unnamed Block Operation: Finishing -> Finished

Notice that as the operation transitions Finishing -> Finished is when the Test Case passes and the completion block is executed - and yes, it's executed twice (on the same queue). This is all essentially happening at the same time but on different queues, but of course the console displays lines (intrinsically serial) so we read these events ordered thanks to race conditions between the queues. This is not a problem, just helps to understand what is going on.

[danthorpe]

Okay, think I'm getting to the bottom of it. I've added a KV observer to the isFinished property. When this is asserted the completion block is executed. So I have this in my observer (the test case):

override func observeValueForKeyPath(keyPath: String?, ofObject object: AnyObject?, change: [String : AnyObject]?, context: UnsafeMutablePointer<Void>) {
    if context != &completionBlockObservationContext {
       super.observeValueForKeyPath(keyPath, ofObject: object, change: change, context: context)
    }

    guard let
        oldIsFinished = change?[NSKeyValueChangeOldKey] as? Bool,
        newIsFinished = change?[NSKeyValueChangeNewKey] as? Bool
        else { return }

    switch (oldIsFinished, newIsFinished) {
    case (false, true):
        print("Asserting isFinished for the first time.")
    case (_, true):
        print("Asserting isFinished again.")
    default:
        break
    }
}

And if you put a break point on the 2nd assertion that isFinished is true, it's from the start method of Operation where we call super.start(). FYI - this is exactly what the docs say not to do:

IMPORTANT

At no time in your start method should you ever call super. When you define a concurrent operation, you take it upon yourself to provide the same behavior that the default start method provides, which includes starting the task and generating the appropriate KVO notifications. Your start method should also check to see if the operation itself was cancelled before actually starting the task. For more information about cancellation semantics, see Responding to the Cancel Command.

Which is from: https://developer.apple.com/library/mac/documentation/Cocoa/Reference/NSOperation_class/

However, during the development of this framework, there was quite a bit of back and forth with @davedelong and (via him) a Foundation engineer who wrote/maintains NSOperation, about what start() in NSOperation does. If you take a look at the sample code from WWDC: https://developer.apple.com/sample-code/wwdc/2015/?q=NSOperations it is exactly the same. I'm going to go through my emails to remember what the discussion was about.

Anyway, regardless, I suspect that there is some KVC happening on the state property, which is triggering start to be called after it's already finished - so... narrowing down the bug to the state transition...

UPDATE:

Okay, whoops my bad - the observer is called twice because I had [.Old, .New] options set.

[danthorpe]

Okay, so, the override of start is not relevant. In fact, I think this code is actually redundant, as the equivalent cancellation logic exists inside main(). So the start override can be removed. All the tests still pass, except the one with the completion block being run twice.

[danthorpe]

Hi @difujia - pretty sure I've fixed this now. The bug was not as wide reaching as I initially thought it might be, as I could only re-produce it using BlockOperation and in particular the style of block which is used for the default block implementation.

If you're able to install Operations from the development branch and re-check, that would be great. I'll leave this issue here until it's verified fixed.

Again, thanks for the feedback!

[kevinbrewster]

I am able to re-produce this problem on both the development and release branches with an Operation class (as opposed to just BlockOperation). It's strange though - sometimes the code will run correctly for a few goes but if you Clean and Re-build it will have problems.

I did a bunch of testing on this tonight and I figured some stuff out. You were definitely right about the start method on the NSOperation superclass triggering a willChangeValueForKeyPath("isFinalized") which causes the completionBlock to run. Then when the state changes, an additional willChangeValueForKeyPath("isFinalized") triggers which causes the completionBlock to run again. This seems to be the crux of the issue.

Based on my testing, it looks like you have to override the start method but you can't call super.start(). For example, this is what the start method should look like:

public override final func start() {
    if cancelled {
        finish()
    } else {
        main()
    }
}

This seems to be the approach recommended by apple in the past for subclassing NSOperation (see https://gist.github.com/LoganWright/eb844fdec0873182abd8). It's very odd that the "Advanced NSOperations" Sample Code makes a point of calling super.start()

If you are curious, here is a really simple way to re-produce the double-completion block calling:

class DoubleCompletionOp : NSOperation {
    var _finished = false
    override var finished: Bool {
        return _finished
    }
    override final func main() {
        willChangeValueForKey("isFinished")
        _finished = true
        didChangeValueForKey("isFinished")
    }
}

And as soon as you override start it works fine:

class SingleCompletionOp : NSOperation {
    var _finished = false
    override var finished: Bool {
        return _finished
    }
    override final func start() {
        main()
    }
    override final func main() {
        willChangeValueForKey("isFinished")
        _finished = true
        didChangeValueForKey("isFinished")
    }
}

The tests seem to all run correctly with this new start method.

[difujia]

Thank you guys for investigating this issue.
I agree that the call on super in override of start() method is the key. The problem can still be reproduced like this:

func testCompletionBlock() {
        measureBlock {
            let queue = OperationQueue()
            let op = DummyOperation()
            let expectation = self.expectationWithDescription("Test: \(__FUNCTION__)")
            op.addCompletionBlock {
                expectation.fulfill()
            }
            queue.addOperation(op)
            self.waitForExpectationsWithTimeout(10, handler: nil)
        }
}
class DummyOperation: Operation {

}

Here measureBlock is just used to let the test run multiple times in each run.

The sample code from Apple has actually been changed a couple of times. I have a very early version of the sample (June 10, 2015) in my computer. The override of start() in that version was:

override final func start() {
    assert(state == .Ready, "This operation must be performed on an operation queue.")

    state = .Executing

    for observer in observers {
        observer.operationDidStart(self)
    }

    execute()   // No override of main in this version.
}

I don't have time to go deeper into this issue right now. Hope this snippet could help.

[danthorpe]

@kevinbrewster @difujia okay, great stuff. I've left the start() code commented out at the moment. I knew this was the issue, didn't have any concrete info from @davedelong about why we ended up calling super.start(). Will refactor this now.

Also - great idea on using measureBlock.

[danthorpe]

@difujia @kevinbrewster proposed fix: 689c29e has been merged into development. Will leave this issue open until either of you can confirm that the completion block is no longer called twice. My test for this passes.

[danthorpe]

Thanks for testing @OperationKit - will leave the issue open for @difujia and @kevinbrewster as they found/diagnosed the bug.

[kevinbrewster]

(sorry i was logged in under the wrong account earlier. changing to avoid confusion).

@danthorpe - I can confirm that the completion block is no longer called twice with the latest development code.

[danthorpe]

@kevinbrewster are you the mysterious @OperationKit? ;)

[danthorpe]

Okay, closing this issue now as fix has been verified. Thanks @kevinbrewster & @difujia!

[kevinbrewster]

haha - my secret identity has been revealed!!

I had actually been working on my own framework for Operations before I discovered this one only a few days ago.

[danthorpe]

Ha! Cool. I know there are a couple of other projects. If you have any more feature requests or suggestions - feel free to create an issue - I'm eager to develop this more to increase its utility and fix annoyances people are having.

I've not got time to look at your other issue now, but I will do tomorrow.

[difujia]

Thanks @danthorpe. I too believe this issue has been addressed. For other improvements, I think a generic way of piping operation results could be great. I will create an issue for discussion.