URLSession downloadTask(with:) TimeOut Error NSURLErrorDomain Code=-1001, _kCFStreamErrorCodeKey=-2103

I have been battling this intermittent error for some time. It is generally random and has been difficult to reproduce until yesterday when I stumbled across a way to reproduce it each time. I can cause the code to throw this error:

Task <70E3909F-8C30-4F34-A8B0-4AF3B41DD81B>.<1> finished with error [-1001] Error Domain=NSURLErrorDomain Code=-1001 "The request timed out." UserInfo={_kCFStreamErrorCodeKey=-2103, _NSURLErrorFailingURLSessionTaskErrorKey=BackgroundDownloadTask <70E3909F-8C30-4F34-A8B0-4AF3B41DD81B>.<1>, _NSURLErrorRelatedURLSessionTaskErrorKey=(
    "BackgroundDownloadTask <70E3909F-8C30-4F34-A8B0-4AF3B41DD81B>.<1>",
    "LocalDownloadTask <70E3909F-8C30-4F34-A8B0-4AF3B41DD81B>.<1>"
), NSLocalizedDescription=The request timed out., _kCFStreamErrorDomainKey=4, NSErrorFailingURLStringKey=https://redacted*, NSErrorFailingURLKey=https://redacted*}
*"redacted" is the backend URL, and it is the correct and same path for each

immediately after restarting an actual device. I have been over the following threads with no results:

What is kCFStreamErrorCodeKey=-4 (kCFStreamErrorDomainKey=4)

Request timed out with _kCFStreamErrorCodeKey=60

How to better diagnose -1001 "The request timed out." URLSession errors

Random timed out error on app start

Because I was able to reproduce it, I have been able to get the following logs:

Dec 29 13:53:17 device nsurlsessiond(Network)[119] : [C13] event: client:end_activity @155.620s, activity 
Dec 29 13:53:17 device nsurlsessiond(CFNetwork)[119] : Connection 13: cleaning up
Dec 29 13:53:17 device nsurlsessiond(CFNetwork)[119] : Connection 0: summary for unused connection {protocol="(null)", domain_lookup_duration_ms=0, connect_duration_ms=0, secure_connection_duration_ms=0, private_relay=false, idle_duration_ms=0}
Dec 29 13:53:17 device nsurlsessiond(CFNetwork)[119] : Task <142B32FB-CA2F-48A3-A647-FB343E95DE52>.<1> summary for task failure {transaction_duration_ms=15370, response_status=-1, connection=0, reused=1, reused_after_ms=0, request_start_ms=0, request_duration_ms=0, response_start_ms=0, response_duration_ms=0, request_bytes=0, request_throughput_kbps=0, response_bytes=0, response_throughput_kbps=0, cache_hit=false}
Dec 29 13:53:17 device nsurlsessiond(Network)[119] : [C13 4775CE07-7B21-4C53-B50D-D90D2DF90C5C Hostname#3415e863:443 quic-connection, bundle id: BundleID, url hash: ba14aab5, traffic class: 100, attribution: developer] cancel
Dec 29 13:53:17 device nsurlsessiond(Network)[119] : nw_connection_report_state_with_handler_on_nw_queue [C13] reporting state cancelled
Dec 29 13:53:17 device nsurlsessiond(CFNetwork)[119] : Connection 13: activity(0xac432ad00) will be canceled
Dec 29 13:53:17 device nsurlsessiond(CFNetwork)[119] : Task <142B32FB-CA2F-48A3-A647-FB343E95DE52>.<1> can retry(N) with reason(2) for error [1:89]
Dec 29 13:53:17 device nsurlsessiond(CFNetwork)[119] : Task <142B32FB-CA2F-48A3-A647-FB343E95DE52>.<1> HTTP load canceled, 0/0 bytes (error code: -999 [1:89])
Dec 29 13:53:17 device nsurlsessiond(CFNetwork)[119] : Task <142B32FB-CA2F-48A3-A647-FB343E95DE52>.<1> finished with error [-1001] Error Domain=NSURLErrorDomain Code=-1001 UserInfo={_kCFStreamErrorCodeKey=-2103, _NSURLErrorFailingURLSessionTaskErrorKey=, _NSURLErrorRelatedURLSessionTaskErrorKey=, NSLocalizedDescription=, NSErrorFailingURLStringKey=, NSErrorFailingURLKey=, _kCFStreamErrorDomainKey=4}
Dec 29 13:53:17 device dasd[85] : CANCELED: com.apple.CFNetwork-cc-119-12-Task <142B32FB-CA2F-48A3-A647-FB343E95DE52>.<1>:DE3ADB at priority 10
Dec 29 13:53:17 device dasd[85] : Activity  not tracked as being started, ignoring it
Dec 29 13:53:17 device dasd(Network)[85] : nw_path_evaluator_cancel [4DB7EF71-384D-4FD5-8DF6-D6BEB0CD3C8F] cancel
Dec 29 13:53:17 device nsurlsessiond[119] : NDSession <2383110B-3A38-463C-AB6B-06833619A76F> Task <142B32FB-CA2F-48A3-A647-FB343E95DE52>.<1> completed with error Error Domain=NSURLErrorDomain Code=-1001 UserInfo={_kCFStreamErrorCodeKey=-2103, _NSURLErrorFailingURLSessionTaskErrorKey=, _NSURLErrorRelatedURLSessionTaskErrorKey=, NSLocalizedDescription=, NSErrorFailingURLStringKey=, NSErrorFailingURLKey=, _kCFStreamErrorDomainKey=4} [-1001]. C(U)
Dec 29 13:53:17 device nsurlsessiond[119] : NDSession <2383110B-3A38-463C-AB6B-06833619A76F> Task <142B32FB-CA2F-48A3-A647-FB343E95DE52>.<1> for client  completed with error - code: -1001
Dec 29 13:53:17 device nsurlsessiond[119] : NDSession <2383110B-3A38-463C-AB6B-06833619A76F> has 0 outstanding tasks
Dec 29 13:53:17 device nsurlsessiond[119] : NDSession <2383110B-3A38-463C-AB6B-06833619A76F> client  is active result (Y), XPC(Y) proxy(Y) for 
Dec 29 13:53:17 device nsurlsessiond(CFNetwork)[119] : {"_transactionUUID":"999D5D02-D913-435B-8A5F-2E773CA7F7B9","_taskUUID":"142B32FB-CA2F-48A3-A647-FB343E95DE52","serverIPAddress":"","startedDateTime":"2024-12-29T13:53:02.123-05:00","time":15370,"cache":{},"timings":{"connect":-1,"dns":-1,"send":-1,"wait":-1,"ssl":-1,"blocked":-1,"receive":-1},"_precisionPreservingTimings":{},"_sourceApplicationBundleIdentifier":"BundleID","connection":"0","request":{"method":"POST","bodySize":0,"headersSize":0,"cookies":[],"headers":[{"name":"Cookie","value":"mobile=Fd7Z48VbxqH9Cw1az2PMwYOaH5N9TJx0cNkYfkrhwj8txX%2Fp3YDFFUP9jlrExNDgAUkpaEPTD15nE2FKA8pxlCv6mE7kikaUqkBTQI4VEU%2F%2BC5njebZ%2FIXarSMpb%2BqiJRmRBB4TogP%2BMA25u0bGWTwaLICSFg%2Ff62RNzEQCl%2Fc65vhsEp3M6YoQrkXncM5EJLyx9vSVAcEMgVDqC384l6uvD0RytsoGA940OHMasVdt7AtNgsDPR8cBQMwGdVsfqyOsHLSSE%2FaGVx7i6fMxHPonEVwSVCw4vLcS8L9%2FBgc0%2BDwSQmS4UWwnlxiDanfhtQK7P%2Bc%2FHGHBSi8XwcOMcNJ%2B%2BkXkC%2BaflCkP3te5bOYqIkZarIgBqdwX0o1nVsdFXW7BDdbUzu1Gagg%2BfdvjpIhXBKyrcs5sD7RY5PPLJi%2FtJeGa2pG9zAU9NadvNarlgn6bRoIpaSh4bknG4JYO33Bzvrmo%3D--4CzBTkU2hdmgums2--%2BO8TFmvQ3dGr92tZ4FsWew%3D%3D"},{"name":"X-USER-EMAIL","value":"name@domain.com"},{"name":"Content-Type","value":"application\134/json"},{"name":"X-USER-CLIENT","value":"mobile"},{"name":"Accept","value":"*\134/*"},{"name":"Accept-Language","value":"en-US,en;q=0.9"},{"name":"User-Agent","value":"Redacted\134/1221 CFNetwork\134/3826.400.101 Darwin\134/24.3.0"},{"name":"Accept-Encoding","value":"gzip"}],"queryString":[],"httpVersion":"HTTP\134/1.1","url":"https:\134/\134/backendURL\134/app\134/v2\134/calendars\134/events"},"response":{"status":0,"content":{"size":0,"mimeType":"application\134/octet-stream"},"bodySize":0,"headersSize":0,"cookies":[],"statusText":"","headers":[],"httpVersion":"","redirectURL":""},"_fetchType":"Network Load"}
Dec 29 13:53:17 device AppName(CFNetwork)[517] : Task <142B32FB-CA2F-48A3-A647-FB343E95DE52>.<1> finished with error [-1001] Error Domain=NSURLErrorDomain Code=-1001 "The request timed out." UserInfo={_kCFStreamErrorCodeKey=-2103, _NSURLErrorFailingURLSessionTaskErrorKey=BackgroundDownloadTask <142B32FB-CA2F-48A3-A647-FB343E95DE52>.<1>, _NSURLErrorRelatedURLSessionTaskErrorKey=(    "BackgroundDownloadTask <142B32FB-CA2F-48A3-A647-FB343E95DE52>.<1>",
"LocalDownloadTask <142B32FB-CA2F-48A3-A647-FB343E95DE52>.<1>"
), NSLocalizedDescription=The request timed out., _kCFStreamErrorDomainKey=4, NSErrorFailingURLStringKey=https://backendURL/app/v2/calendars/events, NSErrorFailingURLKey=https://backendURL/app/v2/calendars/events}
Dec 29 13:53:17 device nsurlsessiond[119] : Task <142B32FB-CA2F-48A3-A647-FB343E95DE52>.<1> client acknowledged completion
Dec 29 13:53:17 device nsurlsessiond[119] : NDSession <2383110B-3A38-463C-AB6B-06833619A76F> has 0 outstanding tasks
Dec 29 13:53:17 device AppName(CFNetwork)[517] : Task <88BD8987-0FCE-4554-B7F8-C2BF3B4B00DE>.<151> resuming, timeouts(60.0, 604800.0) qos(0x9) voucher() activity(00000000-0000-0000-0000-000000000000)
Dec 29 13:53:17 device AppName(AppName.debug.dylib)[517] : BackgroundEventsDownloadManager.urlSession_didCompleteWithError_error, a233e1b8e9aa1b80041c751ea149ac3e failed with error: Error Domain=NSURLErrorDomain Code=-1001 "The request timed out." UserInfo={_kCFStreamErrorCodeKey=-2103, _NSURLErrorFailingURLSessionTaskErrorKey=BackgroundDownloadTask <142B32FB-CA2F-48A3-A647-FB343E95DE52>.<1>, _NSURLErrorRelatedURLSessionTaskErrorKey=(    "BackgroundDownloadTask <142B32FB-CA2F-48A3-A647-FB343E95DE52>.<1>",
"LocalDownloadTask <142B32FB-CA2F-48A3-A647-FB343E95DE52>.<1>"
), NSLocalizedDescription=The request timed out., _kCFStreamErrorDomainKey=4, NSErrorFailingURLStringKey=https://backendURL/app/v2/calendars/events, NSErrorFailingURLKey=https://backendURL/app/v2/calendars/events}
Dec 29 13:53:17 device AppName(CFNetwork)[517] : CFNetwork Diagnostics [1:1950] 13:53:17.518 {LoaderWhatToDo: (null)
Request: {string = https://backendURL/app/v1/metrics, encoding = 134217984, base = (null)}
CachePolicy: 1
WhatToDo: originload
CreateToNow: 0.00059s
} [1:1950]
Dec 29 13:53:17 device AppName(CFNetwork)[517] : CFNetwork Diagnostics [1:1951] 13:53:17.520 {AddCookies Continue: request POST https://backendURL/app/v1/metrics HTTP/1.1
HTTPProtocol: Task: 0x1051bec00
} [1:1951]
Dec 29 13:53:17 device AppName(CFNetwork)[517] : CFNetwork Diagnostics [1:1952] 13:53:17.520 {Protocol Enqueue: request POST https://backendURL/app/v1/metrics HTTP/1.1
Request: request POST https://backendURL/app/v1/metrics HTTP/1.1
Message: POST https://backendURL/app/v1/metrics HTTP/1.1
} [1:1952]
Dec 29 13:53:17 device AppName(Network)[517] : [C1] event: client:connection_reused @64.425s
Dec 29 13:53:17 device AppName(CFNetwork)[517] : Task <88BD8987-0FCE-4554-B7F8-C2BF3B4B00DE>.<151> now using Connection 1
Dec 29 13:53:17 device AppName(CFNetwork)[517] : Task <88BD8987-0FCE-4554-B7F8-C2BF3B4B00DE>.<151> sent request, body S 979
Dec 29 13:53:17 device AppName(CFNetwork)[517] : CFNetwork Diagnostics [1:1953] 13:53:17.523 { touchConnection: (null)
Loader: request POST https://backendURL/app/v1/metrics HTTP/1.1
Timeout Interval: 60.000 seconds
} [1:1953]
Dec 29 13:53:17 device WirelessRadioManagerd[49] : 
Dec 29 13:53:17 device kernel()[0] : 000155.678674 wlan0.A[1172] [dk] parsePHYEcounterV3@31194:Version = 3, ChanSpec  40 5g 80MHz u, slice=0 phyWdg=112 noiseReq=76 noiseCrsbit=3 crsminPwrIdx=14 featureflag=0x0247 chanSwitchCnt=94 chipTemp=31 femTemp=36 ofdmDesense=0 bphyDesen
Dec 29 13:53:17 device kernel()[0] : 000155.678749 wlan0.A[1173] [dk] parsePHYEcounterV3@31200:gbdBphySleepCnt=0 gbdOfdmSleepCnt=0 homeChan=0x2a scca_txstall_precondition=0, crsminPwrApplyCnt=67 edThreshold=-76 preemptStatus2=0x003f totalGlitch=19 bphyGlitch=0 badplcp=0 bphyB
Dec 29 13:53:17 device kernel()[0] : 000155.678779 wlan0.A[1174] [dk] parsePHYEcounterV3@31205:ccaDurMS=1000 ccaEdDuration=0 crsminPwr0=-89 noiseLevelInst0=-90 crsminPwr1=-89 noiseLevelInst1=-90
Dec 29 13:53:17 device kernel()[0] : 000155.683404 wlan0.A[1175] [dk] updateChanSeqCommonStats@3603:P2P chan 40: dur 113609, entry 46, crsglitch 432, start 33066, badplcp 705, badfcs 379, f0ov 0, f1ov 0, anyerr 5704, resptout 1013, frmtooln 0, frmtoosh 106
Dec 29 13:53:17 device kernel()[0] : I [dk] @29318: DTIM missed count: p2p(21), iovar(0), scan(3), roam(0), homechan(70), sleep(10), misc(0)
Dec 29 13:53:17 device AppName(CFNetwork)[517] : Task <88BD8987-0FCE-4554-B7F8-C2BF3B4B00DE>.<151> received response, status 200 content U
Dec 29 13:53:17 device AppName(CFNetwork)[517] : Task <88BD8987-0FCE-4554-B7F8-C2BF3B4B00DE>.<151> done using Connection 1
Dec 29 13:53:17 device AppName(Network)[517] : [C1] event: client:connection_idle @64.476s
Dec 29 13:53:17 device AppName(CFNetwork)[517] : CFNetwork Diagnostics [1:1954] 13:53:17.572 {Protocol Received: request POST https://backendURL/app/v1/metrics HTTP/1.1
Response: HTTP/2.0 200
} [1:1954]
Dec 29 13:53:17 device AppName(CFNetwork)[517] : Task <88BD8987-0FCE-4554-B7F8-C2BF3B4B00DE>.<151> response ended
Dec 29 13:53:17 device AppName(CFNetwork)[517] : CFNetwork Diagnostics [1:1955] 13:53:17.573 { touchConnection: (null)
Loader: request POST https://backendURL/app/v1/metrics HTTP/1.1
Timeout Interval: 60.000 seconds
} [1:1955]
Dec 29 13:53:17 device AppName(CFNetwork)[517] : CFNetwork Diagnostics [1:1956] 13:53:17.573 {destroyReadStream: request POST https://backendURL/app/v1/metrics HTTP/1.1
Request: request POST https://backendURL/app/v1/metrics HTTP/1.1
sent: 1031
received: 604
} [1:1956]
Dec 29 13:53:17 device AppName(CFNetwork)[517] : CFNetwork Diagnostics [1:1958] 13:53:17.573 {Response Complete: (null)
Request: request POST https://backendURL/app/v1/metrics HTTP/1.1
} [1:1958]
Dec 29 13:53:17 device AppName(CFNetwork)[517] : CFNetwork Diagnostics [1:1957] 13:53:17.573 { touchConnection: (null)
Loader: request POST https://backendURL/app/v1/metrics HTTP/1.1
Timeout Interval: 60.000 seconds
} [1:1957]
Dec 29 13:53:17 device AppName(CFNetwork)[517] : CFNetwork Diagnostics [1:1959] 13:53:17.574 {         Did Finish: (null)
Loader: request POST https://backendURL/app/v1/metrics HTTP/1.1
init to origin load: 0.001544s
total time: 0.055987s
total bytes: 2
} [1:1959]
Dec 29 13:53:17 device AppName(CFNetwork)[517] : CFNetwork Diagnostics [1:1960] 13:53:17.574 { touchConnection: (null)
Loader: request POST https://backendURL/app/v1/metrics HTTP/1.1
Timeout Interval: 60.000 seconds
} [1:1960]
Dec 29 13:53:17 device AppName(CFNetwork)[517] : CFNetwork Diagnostics [1:1961] 13:53:17.575 {Vary Persistence: (null)
Request: {string = https://backendURL/app/v1/metrics, encoding = 134217984, base = (null)}
VaryHeader: Accept, Accept-Encoding, Origin
VaryState: dict [2] {
Accept-Encoding: gzip
Accept: */*
}
} [1:1961]
Dec 29 13:53:17 device AppName(CFNetwork)[517] : CFNetwork Diagnostics [1:1962] 13:53:17.575 {~HTTPProtocol: request POST https://backendURL/app/v1/metrics HTTP/1.1
Request: request POST https://backendURL/app/v1/metrics HTTP/1.1
sent: 1031
received: 604
} [1:1962]
Dec 29 13:53:17 device AppName(CFNetwork)[517] : Task <88BD8987-0FCE-4554-B7F8-C2BF3B4B00DE>.<151> summary for task success {transaction_duration_ms=57, response_status=200, connection=1, reused=1, reused_after_ms=15348, request_start_ms=4, request_duration_ms=1, response_start_ms=53, response_duration_ms=2, request_bytes=1031, request_throughput_kbps=999, response_bytes=604, response_throughput_kbps=275, cache_hit=false}
Dec 29 13:53:17 device AppName(CFNetwork)[517] : Task <88BD8987-0FCE-4554-B7F8-C2BF3B4B00DE>.<151> finished successfully
Dec 29 13:53:17 device runningboardd(RunningBoard)[33] : Acquiring assertion targeting [app:517] from originator [app:517] with description ,
	
	]>
Dec 29 13:53:17 device runningboardd(RunningBoard)[33] : Assertion 33-517-640 (target:[app:517]) will be created as inactive as start-time-defining assertions exist
Dec 29 13:53:17 device AppName(CFNetwork)[517] : {"_transactionUUID":"C6B49E42-0AB9-41CE-AB46-D636FEBE1F84","_taskUUID":"88BD8987-0FCE-4554-B7F8-C2BF3B4B00DE","serverIPAddress":"104.26.14.159","startedDateTime":"2024-12-29T13:53:17.518-05:00","time":57,"cache":{},"timings":{"connect":-1,"dns":-1,"send":1,"wait":48,"ssl":-1,"blocked":4,"receive":2},"_precisionPreservingTimings":{"send":{"start":0.0042940378189086914,"end":0.0053009986877441406},"receive":{"start":0.053356051445007324,"end":0.055495023727416992}},"_sourceApplicationBundleIdentifier":null,"connection":"1","request":{"method":"POST","bodySize":988,"headersSize":43,"postData":{"text":"{\134"client\134":\134"iOS\134\134ndevice: iPhone14\134\134nconfig: Debug\134",\134"user_token\134":\134"9jivAXwJvmEacEYK\134",\134"version\134":\134"OS18.3, V1.0.199-1221\134",\134"category\134":\134"backgroundSync\134",\134"timestamp\134":\134"2024-12-29T18:53:17Z\134",\134"event_action\134":\134"urlSession_didCompleteWithError_error\134",\134"label\134":\134"time: 12\134\134\134/29\134\134\134/2024, 1:53:17\M-b\M^@\M-/PM EST, id: a233e1b8e9aa1b80041c751ea149ac3e failed with error: Error Domain=NSURLErrorDomain Code=-1001 \134\134\134"The request timed out.\134\134\134" UserInfo={_kCFStreamErrorCodeKey=-2103, _NSURLErrorFailingURLSessionTaskErrorKey=BackgroundDownloadTask <142B32FB-CA2F-48A3-A647-FB343E95DE52>.<1>, _NSURLErrorRelatedURLSessionTaskErrorKey=(\134\134n    \134\134\134"BackgroundDownloadTask <142B32FB-CA2F-48A3-A647-FB343E95DE52>.<1>\134\134\134",\134\134n    \134\134\134"LocalDownloadTask <142B32FB-CA2F-48A3-A647-FB343E95DE52>.<1>\134\134\134"\134\134n), NSLocalizedDescription=The request timed out., _kCFStreamErrorDomainKey=4, NSErrorFailingURLStringKey=https:\134\134\134/\134\134\134/backendURL\134\134\134/app\134\134\134/v2\134\134\134/calendars\134\134\134/events, NSErrorFailingURLKey=https:\134\134\134/\134\134\134/backendURL\134\134\134/app\134\134\134/v2\134\134\134/calendars\134\134\134/events}\134"}","mimeType"
txX%2Fp3YDFFUP9jlrExNDgAUkpaEPTD15nE2FKA8pxlCv6mE7kikaUqkBTQI4VEU%2F%2BC5njebZ%2FIXarSMpb%2BqiJRmRBB4TogP%2BMA25u0bGWTwaLICSFg%2Ff62RNzEQCl%2Fc65vhsEp3M6YoQrkXncM5EJLyx9vSVAcEMgVDqC384l6uvD0RytsoGA940OHMasVdt7AtNgsDPR8cBQMwGdVsfqyOsHLSSE%2FaGVx7i6fMxHPonEVwSVCw4vLcS8L9%2FBgc0%2BDwSQmS4UWwnlxiDanfhtQK7P%2Bc%2FHGHBSi8XwcOMcNJ%2B%2BkXkC%2BaflCkP3te5bOYqIkZarIgBqdwX0o1nVsdFXW7BDdbUzu1Gagg%2BfdvjpIhXBKyrcs5sD7RY5PPLJi%2FtJeGa2pG9zAU9NadvNarlgn6bRoIpaSh4bknG4JYO33Bzvrmo%3D--4CzBTkU2hdmgums2--%2BO8TFmvQ3dGr92tZ4FsWew%3D%3D"}],"queryString":[],"httpVersion":"HTTP\134/2.0","url":"https:\134/\134/backendURL\134/app\134/v1\134/metrics"},"response":{"status":200,"content":{"size":2,"mimeType":"application\134/json","text":"{}"},"bodySize":46,"headersSize":558,"cookies":[],"statusText":"","headers":[{"name":"Content-Encoding","value":"gzip"},{"name":"x-runtime","value":"0.009342"},{"name":"x-content-type-options","value":"nosniff"},{"name":"content-security-policy","value":"default-src 'self' https:; font-src 'self'
https: data:; img-src 'self' https: data:; object-src 'none'; script-src https:; style-src 'self' https: 'unsafe-inline'"},{"name":"Cache-Control","value":"no-cache"},{"name":"Strict-Transport-Security","value":"max-age=15552000"},{"name":"reporting-endpoints","value":"redacted-nel=https:\134/\134/nel.redacted.com\134/reports?ts=1735498397&sid=1b10b0ff-8a76-4548-befa-353fc6c6c045&s=E1XFeBhF5szfgPmz0md8zm3v0bYf7oyudc9IVwtaZYo%3D"},{"name":"Server","value":"cloudflare"},{"name":"x-download-options","value":"noopen"},{"name":"server-timing","value":"cfL4;desc=\134"?proto=TCP&rtt=14408&min_rtt=10175&rtt_var=1379&sent=568&recv=380&lost=0&retrans=1&sent_bytes=204807&recv_bytes=58911&delivery_rate=1771653&cwnd=252&unsent_bytes=0&cid=dc74be6ccdbbd64e&ts=64391&x=0\134""},{"name":"report-to","value":"{\134"group\134":\134"redacted-nel\134",\134"max_age\134":3600,\134"endpoints\134":[{\134"url\134":\134"https:\134/\134/nel.redacted.com\134/reports?ts=1735498397&sid=1b10b0ff-8a76-4548-befa-353fc6c6c045&s=E1XFeBhF5szfgPmz0md8zm3v
0bYf7oyudc9IVwtaZYo%3D\134"}]}"},{"name":"Via","value":"1.1 vegur"},{"name":"x-xss-protection","value":"1; mode=block"},{"name":"Date","value":"Sun, 29 Dec 2024 18:53:17 GMT"},{"name":"Vary","value":"Accept, Accept-Encoding, Origin"},{"name":"x-request-id","value":"c1a79808-3fd1-4aa7-aead-cbef40b1b2d8"},{"name":"nel","value":"{\134"report_to\134":\134"redacted-nel\134",\134"max_age\134":3600,\134"success_fraction\134":0.005,\134"failure_fraction\134":0.05,\134"response_headers\134":[\134"Via\134"]}"},{"name":"x-frame-options","value":"sameorigin"},{"name":"Content-Type","value":"application\134/json; charset=utf-8"},{"name":"cf-ray","value":"8f9bfdf888db4358-EWR"},{"name":"x-permitted-cross-domain-policies","value":"none"},{"name":"cf-cache-status","value":"DYNAMIC"}],"httpVersion":"HTTP\134/2.0","redirectURL":""},"_fetchType":"Network Load"}
Dec 29 13:53:17 device backboardd(ColourSensorFilterPlugin)[71] : [ALS] ts=155.771 lux=86.374 xy=(0.446 0.397) chs=[764 1922 2272 3080 3109] CCT1=3187.789 gain=256x mode= subsamples=24 rawLux=106.058 nits=128 xTalk=[10 38 37 49 51] status=0x9B copyEvent=0
Dec 29 13:53:17 device locationd[79] : os_transaction created: () 
Dec 29 13:53:17 device locationd[79] : os_transaction released: () 
Dec 29 13:53:17 device kernel()[0] : wlan0:com.apple.p2p: isInfraRealtimePacketThresholdAllowed allowed:1 option:32 threshold:50 noRegistrations:1 cachedPeerCount:0 fastDiscoveryInactive:1 fastDiscoveryOnSince:156028
Dec 29 13:53:17 device kernel()[0] : wlan0:com.apple.p2p: currentInfraTrafficType:8976 checking if realtime upgrade required with inputPackets:7 outputPackets:5 packetThreshold:50
Dec 29 13:53:17 device backboardd(ColourSensorFilterPlugin)[71] : [ALS] ts=156.021 lux=86.584 xy=(0.446 0.397) chs=[764 1963 2259 3094 3122] CCT1=3189.286 gain=256x mode= subsamples=24 rawLux=106.268 nits=128 xTalk=[10 38 37 49 51] status=0x9B copyEvent=0
Dec 29 13:53:18 device identityservicesd(IMFoundation)[63] : -[IMDispatchTimer fired] {self: 0x58994e800}
Dec 29 13:53:18 device identityservicesd(IMFoundation)[63] : -[IMDispatchTimer invalidate] {self: 0x58994e800, _timerSource: }
Dec 29 13:53:18 device identityservicesd(IMFoundation)[63] : -[IMDispatchTimer invalidating] {self: 0x58994e800}
Dec 29 13:53:18 device DTServiceHub(DVTInstrumentsFoundation)[382] : Checking a pid of -1, this shouldn't be happening
Dec 29 13:53:18 device AppName(CFNetwork)[517] : Task <BC1A6931-A9E5-45B7-B07B-C6D99CF559E2>.<152> resuming, timeouts(60.0, 604800.0) qos(0x9) voucher() activity(00000000-0000-0000-0000-000000000000)
Dec 29 13:53:18 device AppName(CFNetwork)[517] : CFNetwork Diagnostics [1:1963] 13:53:18.111 {LoaderWhatToDo: (null)
Request: {string = https://backendURL/app/v1/metrics, encoding = 134217984, base = (null)}
CachePolicy: 1
WhatToDo: originload
CreateToNow: 0.00024s
} [1:1963]
Dec 29 13:53:18 device AppName(CFNetwork)[517] : CFNetwork Diagnostics [1:1964] 13:53:18.112 {AddCookies Continue: request POST https://backendURL/app/v1/metrics HTTP/1.1
HTTPProtocol: Task: 0x1051bec00
} [1:1964]
Dec 29 13:53:18 device AppName(CFNetwork)[517] : CFNetwork Diagnostics [1:1965] 13:53:18.113 {Protocol Enqueue: request POST https://backendURL/app/v1/metrics HTTP/1.1
Request: request POST https://backendURL/app/v1/metrics HTTP/1.1
Message: POST https://backendURL/app/v1/metrics HTTP/1.1
} [1:1965]
Dec 29 13:53:18 device AppName(Network)[517] : [C1] event: client:connection_reused @65.017s
Dec 29 13:53:18 device AppName(CFNetwork)[517] : Task <BC1A6931-A9E5-45B7-B07B-C6D99CF559E2>.<152> now using Connection 1
Dec 29 13:53:18 device AppName(UIKitCore)[517] : [0x3028dad10] [keyboardFocus] Recreation of event deferring records requested: removing recreation reason: detachedContext; for reason: _UIEventDeferringManager: 0x3028dad10: recreating keyboardFocus: context attached for window: 0x102958980; contextID: 0x5E1873B3
Dec 29 13:53:18 device AppName(CFNetwork)[517] : Task <BC1A6931-A9E5-45B7-B07B-C6D99CF559E2>.<152> sent request, body S 365
Dec 29 13:53:18 device AppName(CFNetwork)[517] : CFNetwork Diagnostics [1:1966] 13:53:18.115 { touchConnection: (null)
Loader: request POST https://backendURL/app/v1/metrics HTTP/1.1
Timeout Interval: 60.000 seconds
} [1:1966]
Dec 29 13:53:18 device AppName(BackBoardServices)[517] : flushing changes: ; deferringRules: [[517-2];  -> ; reason: UIWindowScene: 0x103aec800: Begin event deferring in keyboardFocus for window: 0x102958980]; keyCommandDispatchingRules: ; keyCommandsRegistrations: ; bufferingPredicates: ; activeUIResponders: >
Dec 29 13:53:18 device backboardd(BackBoardHIDEventFoundation)[71] : new deferring rules for pid:517: [[517-2];  -> ; reason: UIWindowScene: 0x103aec800: Begin event deferring in keyboardFocus for window: 0x102958980]
Dec 29 13:53:18 device backboardd(BackBoardHIDEventFoundation)[71] : cycle detected between [34-C] -> [34-3]
Dec 29 13:53:18 device backboardd(ColourSensorFilterPlugin)[71] : [ALS] ts=156.271 lux=87.256 xy=(0.448 0.399) chs=[750 1949 2286 3121 3136] CCT1=3147.691 gain=256x mode= subsamples=24 rawLux=106.940 nits=128 xTalk=[10 38 37 49 51] status=0x9B copyEvent=0
Dec 29 13:53:18 device AppName(CFNetwork)[517] : Task <BC1A6931-A9E5-45B7-B07B-C6D99CF559E2>.<152> received response, status 200 content U
Dec 29 13:53:18 device AppName(CFNetwork)[517] : Task <BC1A6931-A9E5-45B7-B07B-C6D99CF559E2>.<152> done using Connection 1
Dec 29 13:53:18 device AppName(Network)[517] : [C1] event: client:connection_idle @65.067s
Dec 29 13:53:18 device AppName(CFNetwork)[517] : CFNetwork Diagnostics [1:1967] 13:53:18.163 {Protocol Received: request POST https://backendURL/app/v1/metrics HTTP/1.1
Response: HTTP/2.0 200
} [1:1967]
Dec 29 13:53:18 device AppName(CFNetwork)[517] : CFNetwork Diagnostics [1:1968] 13:53:18.163 { touchConnection: (null)
Loader: request POST https://backendURL/app/v1/metrics HTTP/1.1
Timeout Interval: 60.000 seconds
} [1:1968]
Dec 29 13:53:18 device AppName(CFNetwork)[517] : Task <BC1A6931-A9E5-45B7-B07B-C6D99CF559E2>.<152> response ended
Dec 29 13:53:18 device AppName(CFNetwork)[517] : CFNetwork Diagnostics [1:1969] 13:53:18.163 { touchConnection: (null)
Loader: request POST https://backendURL/app/v1/metrics HTTP/1.1
Timeout Interval: 60.000 seconds
} [1:1969]
Dec 29 13:53:18 device AppName(CFNetwork)[517] : CFNetwork Diagnostics [1:1970] 13:53:18.163 {destroyReadStream: request POST https://backendURL/app/v1/metrics HTTP/1.1
Request: request POST https://backendURL/app/v1/metrics HTTP/1.1
sent: 417
received: 585
} [1:1970]
Dec 29 13:53:18 device AppName(CFNetwork)[517] : CFNetwork Diagnostics [1:1971] 13:53:18.163 {Response Complete: (null)
Request: request POST https://backendURL/app/v1/metrics HTTP/1.1
} [1:1971]
Dec 29 13:53:18 device AppName(CFNetwork)[517] : CFNetwork Diagnostics [1:1972] 13:53:18.163 {         Did Finish: (null)
Loader: request POST https://backendURL/app/v1/metrics HTTP/1.1
init to origin load: 0.000737071s
total time: 0.0522151s
total bytes: 2
} [1:1972]
Dec 29 13:53:18 device AppName(CFNetwork)[517] : CFNetwork Diagnostics [1:1973] 13:53:18.164 { touchConnection: (null)
Loader: request POST https://backendURL/app/v1/metrics HTTP/1.1
Timeout Interval: 60.000 seconds
} [1:1973]
Dec 29 13:53:18 device AppName(CFNetwork)[517] : CFNetwork Diagnostics [1:1974] 13:53:18.164 {Vary Persistence: (null)
Request: {string = https://backendURL/app/v1/metrics, encoding = 134217984, base = (null)}
VaryHeader: Accept, Accept-Encoding, Origin
VaryState: dict [2] {
Accept-Encoding: gzip
Accept: */*
}
} [1:1974]
Dec 29 13:53:18 device AppName(CFNetwork)[517] : Task <BC1A6931-A9E5-45B7-B07B-C6D99CF559E2>.<152> summary for task success {transaction_duration_ms=52, response_status=200, connection=1, reused=1, reused_after_ms=541, request_start_ms=2, request_duration_ms=0, response_start_ms=51, response_duration_ms=0, request_bytes=417, request_throughput_kbps=449, response_bytes=585, response_throughput_kbps=741, cache_hit=false}
Dec 29 13:53:18 device AppName(CFNetwork)[517] : CFNetwork Diagnostics [1:1975] 13:53:18.164 {~HTTPProtocol: request POST https://backendURL/app/v1/metrics HTTP/1.1
Request: request POST https://backendURL/app/v1/metrics HTTP/1.1
sent: 417
received: 585
} [1:1975]
Dec 29 13:53:18 device AppName(CFNetwork)[517] : Task <BC1A6931-A9E5-45B7-B07B-C6D99CF559E2>.<152> finished successfully
nnection","value":"keep-alive"},{"name":"Host","value":"backendURL"},{"name":"Upload-Complete","value":"?1"},{"name":"Cookie","value":"mobile=Fd7Z48VbxqH9Cw1az2PMwYOaH5N9TJx0cNkYfkrhwj8txX%2Fp3YDFFUP9jlrExNDgAUkpaEPTD15nE2FKA8pxlCv6mE7kikaUqkBTQI4VEU%2F%2BC5njebZ%2FIXarSMpb%2BqiJRmRBB4TogP%2BMA25u0bGWTwaLICSFg%2Ff62RNzEQCl%2Fc65vhsEp3M6YoQrkXncM5EJLyx9vSVAcEMgVDqC384l6uvD0RytsoGA940OHMasVdt7AtNgsDPR8cBQMwGdVsfqyOsHLSSE%2FaGVx7i6fMxHPonEVwSVCw4vLcS8L9%2FBgc0%2BDwSQmS4UWwnlxiDanfhtQK7P%2Bc%2FHGHBSi8XwcOMcNJ%2B%2BkXkC%2BaflCkP3te5bOYqIkZarIgBqdwX0o1nVsdFXW7BDdbUzu1Gagg%2BfdvjpIhXBKyrcs5sD7RY5PPLJi%2FtJeGa2pG9zAU9NadvNarlgn6bRoIpaSh4bknG4JYO33Bzvrmo%3D--4CzBTkU2hdmgums2--%2BO8TFmvQ3dGr92tZ4FsWew%3D%3D"}],"queryString":[],"httpVersion":"HTTP\134/2.0","url":"https:\134/\134/backendURL\134/app\134/v1\134/metrics"},"response":{"status":200,"content":{"size":2,"mimeType":"application\134/json","text":"{}"},"bodySize":46,"headersSize":539,"cookies":[],"statusText":"","headers":[{"name":"Content-Encoding","val
ue":"gzip"},{"name":"x-runtime","value":"0.010079"},{"name":"x-content-type-options","value":"nosniff"},{"name":"content-security-policy","value":"default-src 'self' https:; font-src 'self' https: data:; img-src 'self' https: data:; object-src 'none'; script-src https:; style-src 'self' https: 'unsafe-inline'"},{"name":"Cache-Control","value":"no-cache"},{"name":"Strict-Transport-Security","value":"max-age=15552000"},{"name":"reporting-endpoints","value":"redacted-nel=https:\134/\134/nel.redacted.com\134/reports?ts=1735498398&sid=1b10b0ff-8a76-4548-befa-353fc6c6c045&s=YuCNaHxnB1ny2BrQBbKr2%2Fz7u8f55emYOfPDAeD8Oao%3D"},{"name":"Server","value":"cloudflare"},{"name":"x-download-options","value":"noopen"},{"name":"server-timing","value":"cfL4;desc=\134"?proto=TCP&rtt=14153&min_rtt=10175&rtt_var=1400&sent=571&recv=383&lost=0&retrans=1&sent_bytes=205477&recv_bytes=59372&delivery_rate=1771653&cwnd=252&unsent_bytes=0&cid=dc74be6ccdbbd64e&ts=64981&x=0\134""},{"name":"report-to","value":"{\134"group\134":\134"redacted-nel\1
34",\134"max_age\134":3600,\134"endpoints\134":[{\134"url\134":\134"https:\134/\134/nel.redacted.com\134/reports?ts=1735498398&sid=1b10b0ff-8a76-4548-befa-353fc6c6c045&s=YuCNaHxnB1ny2BrQBbKr2%2Fz7u8f55emYOfPDAeD8Oao%3D\134"}]}"},{"name":"Via","value":"1.1 vegur"},{"name":"x-xss-protection","value":"1; mode=block"},{"name":"Date","value":"Sun, 29 Dec 2024 18:53:18 GMT"},{"name":"Vary","value":"Accept, Accept-Encoding, Origin"},{"name":"x-request-id","value":"fb540a81-4e98-47af-8e94-e2b25bf3b574"},{"name":"nel","value":"{\134"report_to\134":\134"redacted-nel\134",\134"max_age\134":3600,\134"success_fraction\134":0.005,\134"failure_fraction\134":0.05,\134"response_headers\134":[\134"Via\134"]}"},{"name":"x-frame-options","value":"sameorigin"},{"name":"Content-Type","value":"application\134/json; charset=utf-8"},{"name":"cf-ray","value":"8f9bfdfc3d704358-EWR"},{"name":"x-permitted-cross-domain-policies","value":"none"},{"name":"cf-cache-status","value":"DYNAMIC"}],"httpVersion":"HTTP\134/2.0","redirectURL":""},"_fetc
hType":"Network Load"}

Last bit of information is that I had Network Instruments running, and when this error occurred, I found that the Connection ID was "No Connection" and it appears the request was never actually sent, though it waited the full time out for a backend response.

Any help would be appreciated. This data request is being used after sending a certain APNs to update necessary data in the background, and has been the source of many user complaints.

Answered by DTS Engineer in 824133022

Thanks for the response. Originally, the timeoutIntervalForResource was set to 60 seconds, and the timeoutIntervalForRequest was default. We were still getting these errors in the wild. The only reason I implemented these times is because I implemented a retry once this specific error came in, and the server has a 15 second timeout. I am not opposed to increasing those times at all, but I am not sure this solves the root issue.

But yes, this data is pretty ephemeral, so "if you can't get me this data in the next <insert time> don't bother trying at all" is exactly what we were going for. We also have an app refresh we call that uses this same code that is called regularly throughout the day. That will also exhibit this error on occasion.

This slipped off my radar for awhile, but my answer here is actually really simple. Based on what you're describing, it sound like you should stop using the background URL session and just use the standard configuration. That is, you try to immediately download it while your app is awake in the background and if you can't download it, then you don't download it. Jumping back to what I said here:

"if you can't get me this data in the next <insert time> don't bother trying at all"

Putting some concrete numbers on that, when "<insert time>" is:

  • "a day or so"-> the background session is a great solution.

  • "12 hours"-> the background session might be worth "trying". That is, sometimes it will work, sometimes it won't, but something is better than nothing.

  • "60 minutes"-> the background session is largely irrelevant. There are times it might work but the results aren't going to be consistent enough to be useful

  • "a few minutes"-> the background session is probably a bad idea. To the extent it "works", that's almost certainly an artifact of your testing environment or some other distortion.

There are odd edge cases and exceptions to this, but the over arching point here is that as download size and resource timeout decrease, the background session makes less and less sense. If you need a 5k file in the next 30 min, then you should just download it directly instead of trying to use the background session.

__
Kevin Elliott
DTS Engineer, CoreOS/Hardware

To add a few more details here:

  1. I don't believe I mentioned this is being called in the background. The basic code I am using is:
let configuration = URLSessionConfiguration.background(withIdentifier: sessionIdentifier)
configuration.timeoutIntervalForRequest = 15 // The backend times out in 15 seconds
configuration.timeoutIntervalForResource = 15
configuration.isDiscretionary = false
let session = URLSession(
          configuration: configuration,
          delegate: self,
          delegateQueue: nil
        )
let task = session.downloadTask(with: request)
task.resume()

In the delegate, I am implementing both urlSession(_:downloadTask:didFinishDownloadingTo:) and urlSession(_:task:didCompleteWithError:)

Using the same server endpoint, I am successfully completing the fetch when the app starts up, albeit using data(for:delegate:).

The issue does not just occur after restart. It will also randomly occur, but I can replicate it reliably after restart.

So, I think the issue here is with your timeoutIntervalForResource. More specifically, breaking down the two timeouts:

  • "timeoutIntervalForRequest"-> The is the network level timeout. When a connection is attempted, the system tries for 15s and then "gives up" if it doesn't complete it gives up. In you particular case, 15s is "short", but not unreasonable.

  • "timeoutIntervalForResource"-> This is the "overall" timeout on the entire request, meaning how long should the system keep the request "around" before discarding the entire request. In concrete terms, "if you can't get me this data in the next <insert time> don't bother trying at all". In that context, 15s is WAY to short, as you're basically saying "if you can't get it now, don't bother at all". Note that the default here is 7 days, which is the kind of time window you should be thinking in terms of.

Covering a few edge cases:

Using the same server endpoint, I am successfully completing the fetch when the app starts up, albeit using data(for:delegate:).

  • The "data(for:delegate:)" delegate changes things, as I believe it will end up doing the transfer in process (not as a true background transfer).

  • Having your app in the foreground also skews results, as it means your "background" transfer is getting much higher priority than it normally would.

The issue does not just occur after restart. It will also randomly occur, but I can replicate it reliably after restart.

If you're launching immediately after restart, then you can easily be in a situation where our radios have not fully initialized and/or the backend support daemon hasn't fully launched. Those delays could easily add 5-15s of delay in starting your transfer, at which point we'll end the entire request based on timeoutIntervalForResource.

__
Kevin Elliott
DTS Engineer, CoreOS/Hardware

Hey Kevin,

Thanks for the response. Originally, the timeoutIntervalForResource was set to 60 seconds, and the timeoutIntervalForRequest was default. We were still getting these errors in the wild. The only reason I implemented these times is because I implemented a retry once this specific error came in, and the server has a 15 second timeout. I am not opposed to increasing those times at all, but I am not sure this solves the root issue.

But yes, this data is pretty ephemeral, so "if you can't get me this data in the next <insert time> don't bother trying at all" is exactly what we were going for. We also have an app refresh we call that uses this same code that is called regularly throughout the day. That will also exhibit this error on occasion.

"If you're launching immediately after restart, then you can easily be in a situation where our radios have not fully initialized and/or the backend support daemon hasn't fully launched. Those delays could easily add 5-15s of delay in starting your transfer, at which point we'll end the entire request based on timeoutIntervalForResource." That is a worry of ours. These were the steps where we could reproduce the error, but they are not the conditions that we would expect with the errors in the wild. And, because this is in the background, getting a Sysdiagnose Log is a non starter, because the user won't know it failed to initiate one.

With regard to the foreground fetches, they are not being done with this code. They are performed with an asynchronous data fetch. The only reason I included that was simply to show that the endpoint was up and radios working before the background fetch was made, to try to eliminate that as a possible issue.

The "backend support daemon hasn't fully launched" is a concern, and it may be the cause of this relocation of the problem, but not for what we see in the wild. The issue occurs when the app has been in the background and/or has been stopped by the system. But only occasionally. The issue we have is being able to get logs and traces on it as a result.

Could there be an issue we are triggering with the backend support daemon that we are inadvertently triggering? If so, how best to avoid it

This is a question that I really can't seem to find an answer on. This part of the system is triggered by a silent APNs. It is my understanding that we get 30 seconds total processing, give or take, ymmmv, to complete the processing. It is also my understanding that this time is suspended once the fetch request(s) are sent, until the delegate is called. Is this correct?

Also, am I correct in my guess that the Network Trace showing "No connection" literally means a connection wasn't attempted by the OS? We are showing no connection errors from the server, but it also has to get through Cloudflare.

Any assistance is greatly appreciated. This is a very difficult issue to debug, and we have been dealing with it for at least 9 months that we know of. I would really like to put this to bed.

Thanks for the response. Originally, the timeoutIntervalForResource was set to 60 seconds, and the timeoutIntervalForRequest was default. We were still getting these errors in the wild. The only reason I implemented these times is because I implemented a retry once this specific error came in, and the server has a 15 second timeout. I am not opposed to increasing those times at all, but I am not sure this solves the root issue.

But yes, this data is pretty ephemeral, so "if you can't get me this data in the next <insert time> don't bother trying at all" is exactly what we were going for. We also have an app refresh we call that uses this same code that is called regularly throughout the day. That will also exhibit this error on occasion.

This slipped off my radar for awhile, but my answer here is actually really simple. Based on what you're describing, it sound like you should stop using the background URL session and just use the standard configuration. That is, you try to immediately download it while your app is awake in the background and if you can't download it, then you don't download it. Jumping back to what I said here:

"if you can't get me this data in the next <insert time> don't bother trying at all"

Putting some concrete numbers on that, when "<insert time>" is:

  • "a day or so"-> the background session is a great solution.

  • "12 hours"-> the background session might be worth "trying". That is, sometimes it will work, sometimes it won't, but something is better than nothing.

  • "60 minutes"-> the background session is largely irrelevant. There are times it might work but the results aren't going to be consistent enough to be useful

  • "a few minutes"-> the background session is probably a bad idea. To the extent it "works", that's almost certainly an artifact of your testing environment or some other distortion.

There are odd edge cases and exceptions to this, but the over arching point here is that as download size and resource timeout decrease, the background session makes less and less sense. If you need a 5k file in the next 30 min, then you should just download it directly instead of trying to use the background session.

__
Kevin Elliott
DTS Engineer, CoreOS/Hardware

This fell off my radar as well.

I just want to confirm, you are saying we CAN use a standard URLSession in the background? That is:

    `let (data, response) = try await URLSession.shared.data(for: request)`

and download the data without all of the overhead of a downloadTask?

I have two points where I would like to do this:

  1. In response to the receipt of an APNs
  2. In a BGAppRefreshTaskRequest

And I would like to confirm that I can rip out a bunch of code in favor of a standard URLSession. You would make my life so much better if this is correct.

URLSession downloadTask(with:) TimeOut Error NSURLErrorDomain Code=-1001, _kCFStreamErrorCodeKey=-2103
 
 
Q