Fix redirect race condition

[morrowa]

The redirect and response finished callbacks were being executed in two separate blocks, each submitted using dispatch_after. The wait time for each dispatch_after block was equal (and potentially 0 if the user did not configure a request time). As a result, the order the blocks ran in was non-deterministic and unpredictable. This broke the strong ordering of the callbacks. When the response finished callback arrived before the redirect callback, the OHHTTPStubs client would be given the contents of the 3xx response with no opportunity to follow the redirect.

By moving both callbacks into a single block, strong ordering is again guaranteed and redirect callbacks always happen when appropriate.

For more details about the required ordering of NSURLProtocolClient callbacks, see the "Threading Notes" section of the readme of the Apple CustomHTTPProtocol sample code project:

https://developer.apple.com/library/content/samplecode/CustomHTTPProtocol/Listings/Read_Me_About_CustomHTTPProtocol_txt.html

[AliSoftware]

Thanks for the PR! Very good point and good explanation 👍

---

I'm wondering if, when I did write that code (potentially half asleep 😂) maybe my intent was to wait for the delay to call the redirect callback… then wait for the delay again after that callback fire the real response (as a 3xx redirect + the call to the redirected URL could be seen as two requests interest of one = wouldn't we be supposed to fake twice the request time?).

So maybe my intent was to send those one after the other and not in parallel (Obviously if I wanted to implement exactly that I should have nested the executeOnClientRunLoopAfterDelay… closures instead of calling them at the same level, might have been a sleepy day 😂)

What do you think would be the best behavior users would expect?

1. Wait for the delay, then call the redirect callback and the finished callback immediately after (your solution)
2. Wait for the delay, call the redirect callback, wait for the delay again — because that's like a new request being sent — then call the finished callback (probably what I intended to implement in the first place)
3. Wait for half the delay, call the redirect callback, wait for second half of the delay, call the finished callback — making the overall delay as long as what's passed/asked as initial parameter

---

I personally think I prefer solution 2 but that would break the timing compared to current version, so people who already wrote code with some delays for their stubs with redirection will see that overall delay doubled. While your solution fix just the race condition while not changing the overall delay but it seems strange to me timing-wise to have the finish closure called immediately after the redirect, like the redirection took no time… so solution 3 seems like a good mitigation?

[morrowa]

I'm not sure I understand the build failure. Is it a known issue?

I have not tested non-zero response times, and my understanding of NSURLProtocol is limited. (There's not very much documentation.) However, I believe that this implementation is correct for non-zero response times.

The response complete callback that gets called immediately after the redirect callback signals the completion of the 3xx response. startLoading is called a second time with a new request if the user chooses the follow the redirect. I was able to verify this with the debugger. It's also documented in the comments in the CustomHTTPProtocol Apple sample project.

Since the redirect and the final request are separate invocations of startLoading, each will honor the request time configured on its respective stub. That means the behavior as implemented here will match both the API and the current behavior (ignoring the race condition).

For context, the issue was introduced as part of a bug fix for a related issue in May in PR #175 . Before that fix was merged, startLoading would submit either the redirect notification block or the request completion block. That was incorrect - both callbacks must be made in the event of a 3xx response. After that code was merged, the code would correctly call both callbacks, but each was submitted in a separate block, which introduced the race condition solved in this patch.

It would be possible to write a unit test with a long response time for both the initial 3xx and the final response and verify that the response time is honored in each case with these changes. If you can wait a day or two, I'd be happy to write one.

[AliSoftware]

Indeed, makes sense; your implementation seems to be the one making more sense in that context then 👍

---

About the build failure, yes it's an issue I've introduced in a quite recent commit on master while trying to disable timing tests on CI, because timing tests depend highly on the speed and CPU of the machine running them — so they are non-deterministic — and typically VMs on Travis share a common CPU — meaning that timers to will be late. All of which made those timing tests (and Travis builds) fail randomly depending on VM speed and execution conditions.
But since I disabled those tests I got this new error about module not found and can't understand the relationship between the changes I've done and this error… and haven't had time to investigate further yet.

[morrowa]

OK! Meanwhile, I will find time to write a test verifying that the new behavior is correct for non-zero request times.

[morrowa]

While working on unit tests for redirect response times, I found another bug which I addressed in commit a6f5453. The response time was not being honored for requests with zero-length data.

I added some very rough timing to the NSURLSession tests to verify that the amount of time spent waiting for the requests to finish was greater than or equal to the configured request and response delays. Let me know if the tests look okay. I know that using NSDate for timing isn't ideal, but I thought it simplest in this scenario.

[AliSoftware]

I'm not sur I see a better way to test that, so I'm ok with NSDatefor this scenario.

BTW, don't forget to add an entry in th CHANGELOG.md to mention both fixes (race condition + timing for zero-length responses) and credit yourself!

[morrowa]

OK! Should I add that to this PR?

[AliSoftware]

@morrowa yeah, just add a commit with the changes in the CHANGELOG, that way it'll be included automatically when we merge the PR 😃

[AliSoftware]

If I'm being pedantic, I think it would read more clearly with two separate entries/bullet points instead of one 😝

[morrowa]

OK! Sounds good! Only one copy of the links though, right?

[AliSoftware]

Mmmh, good question …

nah I think it would be more logical to put the links on both, because if anyone is interested only in one of the entries they have to have the links to that PR always right next to it (and otherwise a reader would have no clue if the second entry just miss the links because we forgot them or if they're supposed to be the same as the previous entry…)

Damn I have to stop being perfectionist and pedantic, sorry 😂

[morrowa]

No, I appreciate this help! I haven't contributed to an open-source project in a long time and want to be sure that all of my changes fit the project perfectly.

[AliSoftware]

👌

[AliSoftware]

Now I'll probably have to take some time to understand what I did that makes the build fall on travis due to this "cannot import module" error, try and fix that on master so you can rebase on top on it, and hopefully this PR's build will pass at last and be mergeable at last!
(I hope do have some time on Friday or the week-end to do that)

[AliSoftware]

Travis failure fixed on master 🎉