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?

score 1 · Accepted Answer · answered Sep 03 '17 at 04:45

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.)

Before I went to bed, I saw a notification for this answer on my smartphone, with the first sentence shown. I woke up a few hours later, suddenly realizing this is probably what you were saying. A run of the `while` loop doesn't finish in the loop, since the call is asynchronous. I had a sample project with the same problem, and changing it to remove the loop and have the reading callback call the next iteration (if required) instead worked. Thanks. — CTMacUser, Sep 04 '17 at 06:07
I've gone from 100% CPU utilization and 100 MB of memory, and both climbing, to 2% and 12 MB. — CTMacUser, Sep 04 '17 at 22:46

score 0 · Answer 2 · answered Aug 28 '17 at 15:23

0

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....

answered Aug 28 '17 at 15:23

CTMacUser

1,996
1
16
27

Soon after I realized that this "solution" doesn't actually solve the initial problem. I don't know why my original send was broken, nor why it now works. See @dgatwood's answer. – CTMacUser Sep 04 '17 at 06:03

Why did writing with URLSessionStreamTask time out?

2 Answers2