iOS 11 Beta renders chunk of application inoperable

A portion of our application transmits and receives data via InputStream and OutputStream. This is done to facilitate high speed data transmission (think prices from a stock exchange). The application gets an URLSessionStreamTask from an URLSession, resumes that task (“streamTask.resume()”), secures the connection (“streamTask.startSecureConnection()”), then captures the streams (“streamTask.captureStreams()”).


We use the captured InputStream and OutputStream objects to communicate using a proprietary protocol. This has worked well for many years - prior to URLSessionStreamTask, we used other mechanisms to set up the streams.


With the advent of iOS 11, this no longer works. The scenario is this:


When bytes become available on the InputStream, we read a predefined, small number of bytes (4) that indicates the size of the payload. Once we know the payload size, we read off the InputStream until we’ve received the entire payload.


In iOS 10 and below, this works well. In iOS 11, the reader thread appears to deadlock in CFNetwork code when reading the payload. If we modify the application to read all available bytes (using some arbitrarily large buffer), we receive both the bytes describing the payload size and the payload itself. However, we don’t want to read this arbitrarily large buffer.


LLDB indicates that the reader thread is blocked waiting for availability of a spin lock.


I filed Radar 33741310 on August 5 with a small sample application that replicates the issue. However, as best I can tell, the Radar hasn’t been looked at. This is a critical issue for us as it renders a portion of our application inoperable.


The slightly sanitized stack trace from the blocked thread is as follows:


Thread 8 Queue : Anonymous

#0 0x0000000111ee231e in __ulock_wait ()

#1 0x0000000111f07aff in _os_ulock_wait ()

#2 0x0000000111f077d0 in _os_nospin_lock_lock_slow ()

#3 0x000000010d6ecf49 in __NSCFTCPIOReadStream::_streamImpl_CanRead(__CFReadStream*) ()

#4 0x000000010dd4dbcd in CFReadStreamHasBytesAvailable ()

#5 0x000000010dd86179 in -[__NSCFInputStream hasBytesAvailable] ()

#6 0x000000010c6d2070 in FourByteHeaderMessageProcessor.readBytesWith4ByteHeader(timeoutTimeInterval:maxMessageLength:) at /...Sanitized.../FourByteHeaderMessageProcessor.swift:80

#7 0x000000010c6ca3aa in closure #1 in static URLSessionStreamTaskManager.testGetSessionIDResponseFromStream() at /...Sanitized.../URLSessionStreamTaskManager.swift:31

#8 0x000000010c6cd835 in URLSessionStreamTaskManager.urlSession(_:streamTask:didBecome:outputStream:) at /...Sanitized.../URLSessionStreamTaskManager.swift:160

#9 0x000000010c6cde9b in @objc URLSessionStreamTaskManager.urlSession(_:streamTask:didBecome:outputStream:) ()

#10 0x000000010d77797e in __88-[NSURLSession delegate_streamTask:didBecomeInputStream:outputStream:completionHandler:]_block_invoke ()

#11 0x000000010ca119b7 in __NSBLOCKOPERATION_IS_CALLING_OUT_TO_A_BLOCK__ ()

#12 0x000000010ca1181a in -[NSBlockOperation main] ()

#13 0x000000010ca0fcd6 in -[__NSOperationInternal _start:] ()

#14 0x0000000111a5843c in _dispatch_client_callout ()

#15 0x0000000111a5daf4 in _dispatch_block_invoke_direct ()

#16 0x0000000111a5843c in _dispatch_client_callout ()

#17 0x0000000111a5daf4 in _dispatch_block_invoke_direct ()

#18 0x0000000111a5d884 in dispatch_block_perform ()

#19 0x000000010ca0bce4 in __NSOQSchedule_f ()

#20 0x0000000111a5843c in _dispatch_client_callout ()

#21 0x0000000111a5e856 in _dispatch_continuation_pop ()

#22 0x0000000111a5cc86 in _dispatch_async_redirect_invoke ()

#23 0x0000000111a641f9 in _dispatch_root_queue_drain ()

#24 0x0000000111a63e97 in _dispatch_worker_thread3 ()

#25 0x0000000111f165a2 in _pthread_wqthread ()

#26 0x0000000111f1607d in start_wqthread ()


The only other threads LLDB shows are as follows:


Thread 1 Queue : com.apple.main-thread (serial)

#0 0x0000000111eda34a in mach_msg_trap ()

#1 0x0000000111ed9797 in mach_msg ()

#2 0x000000010dcfde85 in __CFRunLoopServiceMachPort ()

#3 0x000000010dcfd3c2 in __CFRunLoopRun ()

#4 0x000000010dcfca89 in CFRunLoopRunSpecific ()

#5 0x00000001130969c6 in GSEventRunModal ()

#6 0x000000010ecd97d0 in UIApplicationMain ()

#7 0x000000010c6c8cf7 in main at /...Sanitized.../AppDelegate.swift:11

#8 0x0000000111ad4d81 in start ()


Thread 4

#0 0x0000000111ee244e in __workq_kernreturn ()

#1 0x0000000111f1648e in _pthread_wqthread ()

#2 0x0000000111f1607d in start_wqthread ()


com.apple.uikit.eventfetch-thread (5)

#0 0x0000000111eda34a in mach_msg_trap ()

#1 0x0000000111ed9797 in mach_msg ()

#2 0x000000010dcfde85 in __CFRunLoopServiceMachPort ()

#3 0x000000010dcfd3c2 in __CFRunLoopRun ()

#4 0x000000010dcfca89 in CFRunLoopRunSpecific ()

#5 0x000000010c9f6e5e in -[NSRunLoop(NSRunLoop) runMode:beforeDate:] ()

#6 0x000000010ca749b7 in -[NSRunLoop(NSRunLoop) runUntilDate:] ()

#7 0x000000010f8f81bd in -[UIEventFetcher threadMain] ()

#8 0x000000010ca048ac in __NSThread__start__ ()

#9 0x0000000111f1693b in _pthread_body ()

#10 0x0000000111f16887 in _pthread_start ()

#11 0x0000000111f1608d in thread_start ()

I filed Radar 33741310 …

Thanks for that.

Looking at the analysis of the bug so far it seems that:

  • The bug is a real regression and is being treated as such

  • The bug doesn’t seem to have a widespread impact; there’s something about your app that’s triggering it

  • That “something” is likely to be your use of polled I/O

Most folks using NS/CFStream use it in one of two modes:

  • Async mode, where they set up a delegate and wait for events to be delivered via that delegate

  • Sync mode, where they just call

    read(_:maxLength:)
    and block waiting for data

Note Neither of these options every require you to call the

hasBytesAvailable
property, and I generally recommend that you avoid that property at all times. Likewise for
hasSpaceAvailable
.

In contrast, your test app is using the stream synchronously but trying to avoid blocking by polling for data (using

hasBytesAvailable
). This is what’s triggering the bug you’ve encountered.

Before going deeper into this I have a quick test for you to run. It seems like your ultimate goal is to do I/O using the

Stream
API. If that’s the case, why are you using
URLSession
to create your streams? You can open streams directly using
getStreamsToHost(withName:port:inputStream:outputStream:)
. This is a lot more direct, both from your perspective and from the perspective of CFNetwork.

Note That API is a little tricky to call from Swift. At the end of this response you’ll find the standard wrapper that I use.

Please switch to creating your streams with

getStreamsToHost(…)
and then repeat your test to see if that changes things.

Share and Enjoy

Quinn “The Eskimo!”
Apple Developer Relations, Developer Technical Support, Core OS/Hardware

let myEmail = "eskimo" + "1" + "@apple.com"
import UIKit

extension Stream {
    static func streamsToHost(name hostname: String, port: Int) -> (inputStream: InputStream, outputStream: OutputStream) {
        var inStream: InputStream? = nil
        var outStream: OutputStream? = nil
        Stream.getStreamsToHost(withName: hostname, port: port, inputStream: &inStream, outputStream: &outStream)
        return (inStream!, outStream!)
    }
}

Quinn,

Thanks so much for responding and confirming that this is a regression.


We switched over to using NSURLSession in 2015 after viewing the latter segment of WWDC 2015's “Networking with NSURLSession” (Session 711). We did so for several reasons:

  1. Dealing with SSL and proxies was a historical pain point. SSL for us (getting it configured properly) and proxies for our users (as users encountered new proxies, we’d get support calls regarding connectivity). NSURLSession promised to take care of that for us and has done so since we began using it.
  2. We could use NSURLSession to obtain streams as we had historically done without major disruption to our existing algorithm.
  3. We send a standard HTTP GET request when we initially open the connection to inform an F5 which server resource we’re contacting. NSURLSession makes this quite easy.


Using “Stream.getStreamsToHost(…)” does work, but we lose the benefits of the items above.


I altered the sample application provided with the radar to avoid using “hasBytesAvailable”. I’ll attach the updated sample application to the radar. The thread still blocks. The crux of the issue is this:

  1. the stream has 59 bytes available
  2. we call “inputStream.read(&buffer, maxLength: 4)”
  3. we receive 4 bytes and interpret those bytes as a 32bit Int (whose value is 55).
  4. we call “inputStream.read(&buffer, maxLength: 55)”
  5. the thread blocks


It appears to us as if reading less than the available bytes, followed by reading the remaining available bytes will cause the thread to block. Is that expected?


This is the stack trace when the thread blocks at step 5:

Thread 5 Queue : Anonymous

#0 0x0000000113e3a31e in __ulock_wait ()

#1 0x0000000113e5faff in _os_ulock_wait ()

#2 0x0000000113e5f7d0 in _os_nospin_lock_lock_slow ()

#3 0x000000010f643bef in __NSCFTCPIOReadStream::_streamImpl_Read(__CFReadStream*, unsigned char*, long, CFStreamError*, unsigned char*) ()

#4 0x000000010fc4b54c in CFReadStreamRead ()

#5 0x000000010e628ee9 in static FourByteHeaderMessageProcessor.readFromInputStream(_:atMost:) at /...Sanitized.../StreamFailure/ClientCommon/FourByteHeaderMessageProcessor.swift:43

#6 0x000000010e629d23 in FourByteHeaderMessageProcessor.readBytesWith4ByteHeader(timeoutTimeInterval:maxMessageLength:) at /...Sanitized.../StreamFailure/ClientCommon/FourByteHeaderMessageProcessor.swift:88

#7 0x000000010e621b3a in closure #1 in static URLSessionStreamTaskManager._urlSessionRead() at /...Sanitized.../StreamFailure/ClientCommon/URLSessionStreamTaskManager.swift:74

#8 0x000000010e625075 in URLSessionStreamTaskManager.urlSession(_:streamTask:didBecome:outputStream:) at /...Sanitized.../StreamFailure/ClientCommon/URLSessionStreamTaskManager.swift:208

#9 0x000000010e6256db in @objc URLSessionStreamTaskManager.urlSession(_:streamTask:didBecome:outputStream:) ()

#10 0x000000010f6ce97e in __88-[NSURLSession delegate_streamTask:didBecomeInputStream:outputStream:completionHandler:]_block_invoke ()

#11 0x000000010e9689b7 in __NSBLOCKOPERATION_IS_CALLING_OUT_TO_A_BLOCK__ ()

#12 0x000000010e96881a in -[NSBlockOperation main] ()

#13 0x000000010e966cd6 in -[__NSOperationInternal _start:] ()

#14 0x00000001139ab43c in _dispatch_client_callout ()

#15 0x00000001139b0af4 in _dispatch_block_invoke_direct ()

#16 0x00000001139ab43c in _dispatch_client_callout ()

#17 0x00000001139b0af4 in _dispatch_block_invoke_direct ()

#18 0x00000001139b0884 in dispatch_block_perform ()

#19 0x000000010e962ce4 in __NSOQSchedule_f ()

#20 0x00000001139ab43c in _dispatch_client_callout ()

#21 0x00000001139b1856 in _dispatch_continuation_pop ()

#22 0x00000001139afc86 in _dispatch_async_redirect_invoke ()

#23 0x00000001139b71f9 in _dispatch_root_queue_drain ()

#24 0x00000001139b6e97 in _dispatch_worker_thread3 ()

#25 0x0000000113e6e5a2 in _pthread_wqthread ()

#26 0x0000000113e6e07d in start_wqthread ()

It appears to us as if reading less than the available bytes, followed by reading the remaining available bytes will cause the thread to block. Is that expected?

No. If your using the stream in blocking mode it should behave like a socket (in the BSD Sockets sense), that is:

  • If there’s any data on the stream you should get what’s there, which might be less than you’d asked for

  • It only blocks if there’s no data at all on the stream

Using

Stream.getStreamsToHost(…)
does work, but we lose the benefits of the items above.

Fair enough. But does it help with this specific problem? The reason I ask is that CFNetwork is in the process of transitioning to the newer stream infrastructure, which is likely to be the source of this bug, and I’m curious whether

getStreamsToHost(…)
also puts you on the failing path.

Share and Enjoy

Quinn “The Eskimo!”
Apple Developer Relations, Developer Technical Support, Core OS/Hardware

let myEmail = "eskimo" + "1" + "@apple.com"

"Stream.getStreamsToHost()" does prevent us from getting blocked. The updated sample application associated with the Radar is set up to demonstrate that.


That said, we've tested eliminating the call to "URLSessionStreamTask.captureStreams()" by using its "readData(:Int,:Int,:TimeInterval:(Data?,Bool,Error?)->Void)" and "writeData(:Data,:TimeInterval,:(Error?)->Void)" methods directly. Our code is significantly simplified. Unit tests however, have broken in an unfortunate way - it's harder to mock URLSessionStreamTask than it was to mock a Stream.


At this point, we're going to continue to plow forward using "URLSessionStreamTask.readData(...)" and "URLSessionStreamTask.writeData(...)" for future releases of our app. They eliminate the need to call URLSessionStreamTask.captureStreams() and prevent us from touching the underlying Stream objects altogether. Given the typical cadence of iOS releases, we anticipate having enough time to get a new build through our QA and onto the store by the time iOS 11 is released. Knowing our customer base though, I would anticipate that our help desk will get a number of calls from folks that have upgraded to iOS 11, but not upgraded our app. Thus, if the CFNetwork team can fix the regression prior to the official release of iOS 11, it would be appreciated. We'd be happy to test any fixes in a very timely manner.

Stream.getStreamsToHost()
does prevent us from getting blocked.

Well, that is interesting.

The updated sample application associated with the Radar is set up to demonstrate that.

Thanks.

That said, we've tested eliminating the call to

URLSessionStreamTask.captureStreams()
by using its
readData(:Int,:Int,:TimeInterval:(Data?,Bool,Error?)->Void)
and
writeData(:Data,:TimeInterval,:(Error?)->Void)
methods directly. Our code is significantly simplified.

Cool.

Unit tests however, have broken in an unfortunate way - it's harder to mock

URLSessionStreamTask
than it was to mock a
Stream
.

Indeed. I’ve been struggling with this issue myself recently (with regards

NWTCPConnection
, but it’s API is very similar to
URLSessionTask
).

At this point, we're going to continue to plow forward using

URLSessionStreamTask.readData(…)
and
URLSessionStreamTask.writeData(…)
for future releases of our app.

Best of luck with that.

Share and Enjoy

Quinn “The Eskimo!”
Apple Developer Relations, Developer Technical Support, Core OS/Hardware

let myEmail = "eskimo" + "1" + "@apple.com"
iOS 11 Beta renders chunk of application inoperable
 
 
Q