Why did writing with URLSessionStreamTask time out?

Question

I'm practicing making a URLProtocol subclass. I'm using URLSessionStreamTask to do the reading & writing. When trying out the subclass, I got a time-out. I thought I messed up my reading routine, but adding logging showed I didn't get past the initial write!

Here's a shortened version of my subclass:

import Foundation
import LoggerAPI

class GopherUrlProtocol: URLProtocol {

    enum Constants {
        static let schemeName = "gopher"
        static let defaultPort = 70
    }

    var innerSession: URLSession?
    var innerTask: URLSessionStreamTask?

    override class func canInit(with request: URLRequest) -> Bool { /*...*/ }
    override class func canonicalRequest(for request: URLRequest) -> URLRequest { /*...*/ }

    override func startLoading() {
        Log.entry("Starting up a download")
        defer { Log.exit("Started a download") }

        precondition(innerSession == nil)
        precondition(innerTask == nil)

        innerSession = URLSession(configuration: .ephemeral, delegate: self, delegateQueue: .current)
        innerTask = innerSession?.streamTask(withHostName: (request.url?.host)!, port: request.url?.port ?? Constants.defaultPort)
        innerTask!.resume()
        downloadGopher()
    }

    override func stopLoading() {
        Log.entry("Stopping a download")
        defer { Log.exit("Stopped a download") }

        innerTask?.cancel()
        innerTask = nil
        innerSession = nil
    }

}

extension GopherUrlProtocol {

    func downloadGopher() {
        Log.entry("Doing a gopher download")
        defer { Log.exit("Did a gopher download") }

        guard let task = innerTask, let url = request.url, let path = URLComponents(url: url, resolvingAgainstBaseURL: false)?.path else { return }

        let downloadAsText = determineTextDownload(path)
        task.write(determineRetrievalKey(path).data(using: .isoLatin1)!, timeout: innerSession?.configuration.timeoutIntervalForRequest ?? 60) {
            Log.entry("Responding to a write with error '\(String(describing: $0))'")
            defer { Log.exit("Responded to a write") }
            Log.info("Hi")

            if let error = $0 {
                self.client?.urlProtocol(self, didFailWithError: error)
                return
            }

            var hasSentClientData = false
            var endReadLoop = false
            let aMinute: TimeInterval = 60
            let bufferSize = 1024
            let noData = Data()
            var result = noData
            while !endReadLoop {
                task.readData(ofMinLength: 1, maxLength: bufferSize, timeout: self.innerSession?.configuration.timeoutIntervalForRequest ?? aMinute) { data, atEOF, error in
                    Log.entry("Responding to a read with data '\(String(describing: data))', at-EOF '\(atEOF)', and error '\(String(describing: error))'")
                    defer { Log.exit("Responded to a read") }
                    Log.info("Hello")

                    if let error = error {
                        self.client?.urlProtocol(self, didFailWithError: error)
                        endReadLoop = true
                        return
                    }
                    endReadLoop = atEOF
                    result.append(data ?? noData)
                    hasSentClientData = hasSentClientData || data != nil
                }
            }
            if hasSentClientData {
                self.client?.urlProtocol(self, didReceive: URLResponse(url: url, mimeType: downloadAsText ? "text/plain" : "application/octet-stream", expectedContentLength: result.count, textEncodingName: nil), cacheStoragePolicy: .notAllowed)  // To-do: Update cache policy
                self.client?.urlProtocol(self, didLoad: result)
            }
        }
    }

}

extension GopherUrlProtocol: URLSessionStreamDelegate {}

And the log:

[2017-08-28T00:52:33.861-04:00] [ENTRY] [GopherUrlProtocol.swift:39 canInit(with:)] GopherUrlProtocol checks if it can 'init' gopher://gopher.floodgap.com/
[2017-08-28T00:52:33.863-04:00] [EXIT] [GopherUrlProtocol.swift:41 canInit(with:)] Returning true
[2017-08-28T00:52:33.863-04:00] [ENTRY] [GopherUrlProtocol.swift:39 canInit(with:)] GopherUrlProtocol checks if it can 'init' gopher://gopher.floodgap.com/
[2017-08-28T00:52:33.863-04:00] [EXIT] [GopherUrlProtocol.swift:41 canInit(with:)] Returning true
[2017-08-28T00:52:33.864-04:00] [ENTRY] [GopherUrlProtocol.swift:54 canonicalRequest(for:)] GopherUrlProtocol canonizes gopher://gopher.floodgap.com/
[2017-08-28T00:52:33.864-04:00] [EXIT] [GopherUrlProtocol.swift:56 canonicalRequest(for:)] Returning gopher://gopher.floodgap.com
[2017-08-28T00:52:33.867-04:00] [ENTRY] [GopherUrlProtocol.swift:82 startLoading()] Starting up a download
[2017-08-28T00:52:33.868-04:00] [ENTRY] [GopherUrlProtocol.swift:112 downloadGopher()] Doing a gopher download
[2017-08-28T00:52:33.868-04:00] [EXIT] [GopherUrlProtocol.swift:113 downloadGopher()] Did a gopher download
[2017-08-28T00:52:33.868-04:00] [EXIT] [GopherUrlProtocol.swift:83 startLoading()] Started a download
[2017-08-28T00:53:33.871-04:00] [ENTRY] [GopherUrlProtocol.swift:132 downloadGopher()] Responding to a write with error 'Optional(Error Domain=NSPOSIXErrorDomain Code=60 "Operation timed out" UserInfo={_kCFStreamErrorCodeKey=60, _kCFStreamErrorDomainKey=1})'
[2017-08-28T00:53:33.871-04:00] [INFO] [GopherUrlProtocol.swift:134 downloadGopher()] Hi
[2017-08-28T00:53:33.872-04:00] [EXIT] [GopherUrlProtocol.swift:133 downloadGopher()] Responded to a write
[2017-08-28T00:53:33.876-04:00] [ENTRY] [GopherUrlProtocol.swift:95 stopLoading()] Stopping a download
[2017-08-28T00:53:33.876-04:00] [ERROR] [main.swift:42 cget] Retrieval Error: Error Domain=NSURLErrorDomain Code=-1001 "The request timed out." UserInfo={NSUnderlyingError=0x100e01470 {Error Domain=kCFErrorDomainCFNetwork Code=-1001 "(null)" UserInfo={_kCFStreamErrorCodeKey=-2102, _kCFStreamErrorDomainKey=4}}, NSErrorFailingURLStringKey=gopher://gopher.floodgap.com, NSErrorFailingURLKey=gopher://gopher.floodgap.com, _kCFStreamErrorDomainKey=4, _kCFStreamErrorCodeKey=-2102, NSLocalizedDescription=The request timed out.}
[2017-08-28T00:53:33.876-04:00] [EXIT] [GopherUrlProtocol.swift:96 stopLoading()] Stopped a download
Program ended with exit code: 11

Strangely, the logging for the writing closure appears only sometimes. Maybe it's some kind of threading/timing issue. (Here, I ran the program twice.)

Am I using URLSessionStreamTask wrong? Or URLProtocol wrong? Or, although it's not HTTP, am I triggering ATS?

Answer 1

It looks like you're queueing up an insane number of read callbacks in a while loop and blocking the thread where the callback will actually run by never returning from the while loop.

That read call is asynchronous, which means that the callback inside will run later—probably much later. Thus, your "while not EOF" thing will block the calling thread, ensuring that it never returns to the top of the run loop to allow the callback to run, thus ensuring that the callback will never be able to set the eof flag to terminate the while loop. Essentially, you deadlocked the thread.

You should almost never call asynchronous methods in any sort of loop. Instead:

• create a method whose sole purpose is to return that block/closure (perhaps getReadHandlerBlock).
• Call the read method, passing the block returned from a call to getReadHandlerBlock.

Then, the bottom of the read handler block:

• Check to see if you need to read more.
• If so, call getReadHandlerBlock on a weak reference to self to obtain a reference to a read handler block.
• Call the read method.

Hope that helps. (Note that I'm not saying that this is the only problem with the code; I haven't looked at it in too much detail. It was just the first thing that I noticed.)

Answer 2

I was about to ask this query on a different forum. In my steps, I mentioned that I send out the request line...

Line? With... endings?

[Look up RFC 1436, Section 2]

Oh, I calculate and send the retrieval string from the URL, but I forgot to cap off the request with a CR-LF. That gets the request through.

But now I'm getting a time-out on the read-back....