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?
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:
getReadHandlerBlock).getReadHandlerBlock.Then, the bottom of the read handler block:
getReadHandlerBlock on a weak reference to self to obtain a reference to a read handler block.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.)