UnityWebRequests on iOS sometimes get stuck indefinitely even with timeout set

Hello,

Using the latest Unity 2020.1.14f1 and iOS 14.2 unitywebrequests sometimes seem to get 'stuck' indefinitely, even with the timeout set to a low number (stuck meaning the 'isDone' property never returns true).

Here's a test case, this will sometimes keep printing "Awaiting request" indefinitely, eventhough the timeout is set to 5:

Code (CSharp):

1. internal IEnumerator AwaitRequest(UnityWebRequest request, Action<bool> result, Action<UnityWebRequest, ulong> percentage)
2.         {
3.             request.timeout = 5;
4.             request.SendWebRequest();
5.  
6.             while (!request.isDone)
7.             {
8.                 Debug.LogFormat("Awaiting request {0} with timeout {1}", request.uri, request.timeout);
9.                 yield return new WaitForSeconds(1f);
10.             }
11.  
12.             if (!request.isNetworkError && !request.isHttpError)
13.             {
14.                 PlayerPrefs.SetString(request.url, request.downloadHandler.text);
15.                 result?.Invoke(true);
16.             }
17.             else
18.             {
19.                 if (request.responseCode == 400)
20.                 {
21.                     PlayerPrefs.SetString(request.url, "{}");
22.                     result?.Invoke(true);
23.                 }
24.                 else
25.                     result?.Invoke(false);
26.             }
27.         }

 

Nothing in xcode logs, no connectivity issues. This is a signed request to an AWS endpoint.

The webrequest is constructed like this:

Code (CSharp):

1. UnityWebRequest getRequest = UnityWebRequest.Get(uri);

Since it fetches data from a private AWS endpoint, we then set some custom headers:

X-Amz-Content-SHA256
X-Amz-Date
Authorization

Confirmed on iPhone SE (gen1), iPhone 12 Pro, iPhone XR, iOS 14.2 and 14.2.1

 

I meet this issue too. Unity 2019.4.2f, IOS14.2.
I can't get the response from this request forever.
It will happend occasionally.

Here is my code.

Code (CSharp):

1.  
2. _unityWebRequest = new UnityWebRequest(requestUrl, UnityWebRequest.kHttpVerbPOST);
3. _unityWebRequest.timeout = RequestTimeout;
4.             _unityWebRequest.downloadHandler = new DownloadHandlerBuffer();
5. _unityWebRequest.SendWebRequest().completed += (AsyncOperation) => {
6.     Debug.Log("Receive");
7. };

 

@Aurimas-Cernius sorry to ping you directly about this, but we are getting reports about this by a lot of iOS testers

I'm not 100% confident, but this may only occur when fetching from the same endoint twice in the same app session

 

found some juicy infos in the log

Code (CSharp):

1. 2020-11-27 13:16:44.804684+0100 holomeet[8635:1095603] Connection 16: received failure notification
2. 2020-11-27 13:16:44.804960+0100 holomeet[8635:1095603] Connection 16: failed to connect 3:-9816, reason -1
3. 2020-11-27 13:16:44.805951+0100 holomeet[8635:1095603] Connection 16: encountered error(3:-9816)
4. 2020-11-27 13:16:44.893798+0100 holomeet[8635:1095603] Task <11E02759-EA2E-4457-988B-B3CD0711BA5A>.<28> HTTP load failed, 0/0 bytes (error code: -1200 [3:-9816])

 

I can consistently reproducte this across devices and recent ios versions

I would be most interested to know why a request that has a timeout x doesn't auto-abort if a response hasn't been received by then.

The way I see it there are 2 separate issues (from a usability standpoint), correct me if i'm wrong:

- A subsequent request to an endpoint doesn't always return a response
- Setting a timeout doesn't guarantee the request is aborted when the timeout is reached

in UnityWebRequest.mm the timeOutinterval is set:

Code (CSharp):

1.  
2. UnityURLRequest* request = ([B]__bridge[/B] UnityURLRequest*)connection;
3. request.timeoutInterval = timeoutSec;
4.  

UnityURLRequest is an implementation of NSMutableURLRequest, so I'm guessing it uses that underlying logic to handle timeouts on the basis of the value set in c#.

So, reading into the the timeoutInterval property of the URLRequest it says this:

Code (CSharp):

1. The "idle
2.    interval" is defined as the period of time that has passed since the
3.     last instance of load activity occurred for a request that is in the
4.     process of loading. Hence, when an instance of load activity occurs
5.     (e.g. bytes are received from the network for a request), the idle
6.     interval for a request is reset to 0.

This indicates the timeout resets when any kind of activity occurs.

your own documentation says something else

https://docs.unity3d.com/ScriptReference/Networking.UnityWebRequest-timeout.html

this indicates the request aborts if a time interval is reached, even if there's been activity in the meantime

Can I somehow subscribe to the timeout event (if there is one) on the native side, to see if it fires?

 

Seems like we're facing the same problem

 

We havent yet found the cause, nor have we been able to make a 100 percent reliable reproduction case

 

same, it's kinda random, sometimes it works, sometimes it takes forever to return with timeout, even though we explicitly set the timeout to 10 seconds

 

Same here... we're having the EXACT same issue (only on 14.2, hard to reproduce, no timeout, no isDone status). We get it more often on the iPhoneX.

We've created our own time-out process so that, when we don't have a UnityWebRequest.isDone we try to resend the UnityWebRequest. But once it's broken... it's broken for good.

 

We're experiencing the same issue with UnityWebRequest calls in our app, on iOS 14. Similar errors in our log as others have reported. Also tried to implement on own timeout if we see that the connection stalls, but re-trying the request produces the same failure.

Code (CSharp):

1. 2020-12-08 11:41:11.164205-0500 coreApp[3077:182352] [tcp] tcp_output [C14.1:3] flags=[R.] seq=1572399593, ack=1585269364, win=8191 state=CLOSED rcv_nxt=1585269364, snd_una=1572399593
2. 2020-12-08 11:41:11.165343-0500 coreApp[3077:182352] Connection 14: received failure notification
3. 2020-12-08 11:41:11.165432-0500 coreApp[3077:182352] Connection 14: failed to connect 3:-9816, reason -1
4. 2020-12-08 11:41:11.165460-0500 coreApp[3077:182352] Connection 14: encountered error(3:-9816)
5. 2020-12-08 11:41:11.167284-0500 coreApp[3077:182352] Task <49BD9E09-6C4E-4BAE-BABB-63904A290614>.<16> HTTP load failed, 0/0 bytes (error code: -1200 [3:-9816])
6. 2020-12-08 11:41:11.315431-0500 coreApp[3077:182354] [tcp] tcp_output [C15.1:3] flags=[R.] seq=1360238599, ack=1453406931, win=8191 state=CLOSED rcv_nxt=1453406931, snd_una=1360238599
7. 2020-12-08 11:41:11.316850-0500 coreApp[3077:182354] Connection 15: received failure notification
8. 2020-12-08 11:41:11.317008-0500 coreApp[3077:182354] Connection 15: failed to connect 3:-9816, reason -1
9. 2020-12-08 11:41:11.317047-0500 coreApp[3077:182354] Connection 15: encountered error(3:-9816)
10. 2020-12-08 11:41:11.317828-0500 coreApp[3077:182354] Task <9A4C7C55-5F06-420A-9AB0-3B3183ABC88C>.<17> HTTP load failed, 0/0 bytes (error code: -1200 [3:-9816])

 

Same issue here is some additional logs...

Code (CSharp):

1. 2020-12-08 11:41:11.164205-0500 app[3077:182352] [tcp] tcp_output [C14.1:3] flags=[R.] seq=1572399593, ack=1585269364, win=8191 state=CLOSED rcv_nxt=1585269364, snd_una=1572399593
2. 2020-12-08 11:41:11.165343-0500 app[3077:182352] Connection 14: received failure notification
3. 2020-12-08 11:41:11.165432-0500 app[3077:182352] Connection 14: failed to connect 3:-9816, reason -1
4. 2020-12-08 11:41:11.165460-0500 app[3077:182352] Connection 14: encountered error(3:-9816)
5. 2020-12-08 11:41:11.167284-0500 app[3077:182352] Task <49BD9E09-6C4E-4BAE-BABB-63904A290614>.<16> HTTP load failed, 0/0 bytes (error code: -1200 [3:-9816])
6. 2020-12-08 11:41:11.315431-0500 app[3077:182354] [tcp] tcp_output [C15.1:3] flags=[R.] seq=1360238599, ack=1453406931, win=8191 state=CLOSED rcv_nxt=1453406931, snd_una=1360238599
7. 2020-12-08 11:41:11.316850-0500 app[3077:182354] Connection 15: received failure notification
8. 2020-12-08 11:41:11.317008-0500 app[3077:182354] Connection 15: failed to connect 3:-9816, reason -1
9. 2020-12-08 11:41:11.317047-0500 app[3077:182354] Connection 15: encountered error(3:-9816)
10. 2020-12-08 11:41:11.317828-0500 app[3077:182354] Task <9A4C7C55-5F06-420A-9AB0-3B3183ABC88C>.<17> HTTP load failed, 0/0 bytes (error code: -1200 [3:-9816])

 

Same issue

 

Some news?
Perhaps something related exclusively to the ios version 14.2. The same app works for me in version 14.1.

 

i've tried to make a reproduction project but haven't yet been able to come up with something, it might be related to high memory usage

 

OK OK OK, thats the question: Are you all using AR Foundation!? I've replicated that, seems! Closing ArFoundation and reopening it. Now I have to understand if is my fault(some code error) or not.
May it be the right way?

 

I'm having the same problem: iOS 14.2 + AR foundation = network requests stop working after several requests that performed fine before. So at least in my case, yes! AR Foundation it's in the equation. It's a complex project and I couldn't find time to create a simpler project reproducing it, so thanks!

 

Sure, I'll try it. Although it'll take me some time to check since I don't have the device to reproduce it. But I'll be back to this thread as soon as I can. Thanks!

 

We're also using ARFoundation

 

i've tried:

Code (CSharp):

1. @implementation UnityWebRequestDelegate
2.  
3. - (void)URLSession:(NSURLSession *)session dataTask:(NSURLSessionDataTask *)dataTask didReceiveResponse:(nonnull NSURLResponse *)response completionHandler:(nonnull void (^)(NSURLSessionResponseDisposition))completionHandler
4. {
5.     [self handleResponse: response task: dataTask];
6.     completionHandler(NSURLSessionResponseAllow);
7. }
8.  
9. - (void)URLSession:(NSURLSession *)session didBecomeInvalidWithError:(NSError *)error
10. {
11.     NSLog (@"LOG MY ERROR");
12. }

"didBecomeInvalidWithError" is never called.

I'm not an ios dev. So meaby something is wrong.

But I can reproduce it ever on a clean scene in my project.
I'm creating a clean project which i will share to you if needed.

 

*So maybe something is wrong.

 

No. :-(
Perhaps the problem is not very clear.
The situation I'm in is that unitywebrequest calls are unanswered. Sometimes they break midway and do not continue and the error is not declared. The theme is that they shouldn't give any errors. So you don't have to understand why they don't return errors but why they don't work at all. I have prepared a clean project where it is possible to reproduce the situation. A loop call every second, Simply sometimes at random, sometimes turning off and on again arfoundation (with a button) while you are moving the device, the web calls stop working. What should I do to share the project?

I hope my analysis is correct and that this is the problem to be solved.

 

We're also experiencing this issue, and are using AR Foundation. I've personally seen the issue on my iOS 14.2.1 device. Other team members have as well, though I'm not sure what iOS versions they're using.

Our first report of the issue was from someone on our team who said he could reproduce the issue reliably by obscuring the camera while AR is active, which forces the AR session to go into a "Tracking lost -> recovering" mode.

 

i did a bug report.That's the right way? how can you know which is it?

 

Yes! Confirm! but not ever!

I never said it here yet but it is an error that also blocks published apps. It is a big deal for us.

 

Yes... ARFoundation is there as well. Since the error was happening whenever we were jumping back from a scene where we activate the ARFoundation we tried to stay in only single scene. But the problem is still there. Thinking the problem was the UnityWebRequest we switched to using HttpClient from System.Net. But, no success... we still have the issue. This is a major problem because, just like @Carlogeno, we can't publish the app on iOS (it's already live on Android). :-(

 

Arfoundation here too

 

Interesting! I've had the opposite experience (I think.) I also switched to HttpClient and I think it has resolved the issue. Our game uses UWR, and several of our dependencies' SDKs also use UWR. I rewrote our code to use HttpClient instead of UWR. Now, when I see the bug, the code in our dependencies that relies on UWR stop working, but my new HttpClient-based code continues working.

I'm am currently tracking down an issue with our HttpClient-using code where connections can stop working after ~1hr, but I think that's a separate issue.

This whole thing is so difficult to be certain about, because we haven't yet isolated a reliable repro. Does anyone have steps for a 100% repro? It would help us confirm that switching to HttpClient has worked around the issue.

Does anyone know if UnityEngine.WWW is affected by the bug?

 

FYI, one of my team members has been trying for several weeks to reproduce this issue on their iOS13 device and has not been able to do so. Today they upgraded to iOS 14.3 and reproduced the bug almost immediately.

It could all be coincidence, but it seems the bug is caused by the overlap of UnityWebRequest, ARFoundation, and newer versions of iOS.

 

Yes, our experience is the same. Uwr, arfoundation and iOS 14.2.x only.

My attempts at minimal repro projects failed, probably because of no Arfoundation.

I have a theory that it might only occur after calling reset on an arsession. Gonna try that tomorrow

 

Interesting thought - anecdotally we have seen this issue more often when doing things that cause the AR Session to reset. However, we haven't been able to find an exact link. We have a debug button in our game that resets the ARSession, and we tried for several hours this afternoon to find a 1:1 connection between resetting the ARSession and this bug, and didn't have any success.

 

Our app never resets the AR session, still experiencing this

 

Sometimes it happens. I have done several tests and it happens very often when the AR restarts after being closed, not at closing. I noticed that the floors are suddenly relocated and the camera acquisition updated. Once, this happened to me just after a new plane was found without resetting. I think there is a moment of reallocation of the camera and the planes. Maybe an update after a Point Cloud recognition, something like that.

My suggestions are not technical because there is no data to understand the techinic problem, but only when it happens.
In my opinion only arfoundation developers can solve it.

Tested, bug still happen.


Here is my very simple code and my super simple scene to reproduce the error:

Code (CSharp):

1.  
2. public class Testbutton : MonoBehaviour
3. {
4.     public string url = "";
5.     public GameObject arall;
6.  
7.     protected void Start()
8.     {
9.         GetComponent<Button>().onClick.AddListener(() => OnClickButton());
10.         StartCoroutine(Test());
11.     }
12.  
13.     protected void OnClickButton()
14.     {
15.         arall.SetActive(!arall.activeSelf);
16.     }
17.  
18.     IEnumerator Test()
19.     {
20.         while(true)
21.         {
22.             yield return new WaitForSeconds(2);
23.  
24.             UnityWebRequest request = new UnityWebRequest();
25.  
26.             request = UnityWebRequest.Get(url);
27.  
28.             Debug.Log(request);
29.  
30.             AsyncOperation asyncOperation = request.SendWebRequest();
31.             yield return asyncOperation;
32.  
33.             if (request.isNetworkError || request.isHttpError || request.error != null)
34.             {
35.                 Debug.Log("UnityWebRequest ERROR : " + request.error);
36.             }
37.             else
38.             {
39.                 Debug.Log("UnityWebRequest ok");
40.             }    
41.             Debug.Log("Loop again");
42.         }
43.     }
44. }
45.  

P.S. I'm Carlogeno

 

Could this in theory be reproducible in a native scenekit/arkit project that fires a NSMutableUrlRequest? (could it be an OS bug)

Made an issue about this here:

https://github.com/Unity-Technologies/arfoundation-samples/issues/694

 

That's exactly the question we're asking ourselves. Has anyone reproduced this issue when only using the ARKit?

 

Same here.
Unity 2019.4.16, ARFoundation 4.0.2, iOS 14.2.x
.net web requesting seems to work fine

 

On our side, 14.0.x was working fine... 14.2.x does not! (don't know about 14.1 or 14.3 released yesterday)

 

Same issue, waiting for some official updates or helpful comments...

 

I can confirm that the event `didBecomeInvalidWithError` is invoked just before the network requests stop working. I printed a log including the errorlocalizedMessage but it was null (this is what I got: NDSession <C0B5C629-3F99-4655-A2E4-24B62B5389F6> Session <private> didBecomeInvalidWithError: (null) [0])

I couldn't test it further yet but I hope this helps you

If you print a NSLog you won't see it in the Unity logs, if you use the application Console from Mac you may see then the `LOG MY ERROR` appearing when the URLSession becomes invalid

 

Great thanks! Let me know if I can do more specific debugs.

I'm experiencing the issue after changing between a scene that has AR, to another one that doesn't have, and going back to the one with AR. But the `didBecomeInvalidWithError` happens during the first scene in AR, although I'm not sure if after stopping the AR session or if it's still running

 

Thanks! I was looking at the xcode console.
But event in Console.app i cant see "LOG MY ERROR". (To be clear, i've modified the UnityWebRequest.mm in xcode project).

But no problem if you're sure you've seen a relationship between the method and the bug.

I can add this now:

Code (CSharp):

1. default    18:20:17.184103+0100    IosArBug    Task <33DDC293-9C69-4388-851D-[COLOR=#ff4d4d]A02369CF1170>.<33> {strength 0, tls 4, ct 0, sub 0, sig 1, ciphers 0, bundle 0, builtin 0}
2.  
3. default    18:20:17.184215+0100    IosArBug    Task <33DDC293-9C69-4388-851D-A02369CF1170>.<33> now using Connection 1
4.  
5. default    18:20:17.184381+0100    IosArBug    Task <33DDC293-9C69-4388-851D-A02369CF1170>.<33> sent request, body N 0
6.  
7. default    18:20:17.292295+0100    IosArBug    Task <33DDC293-9C69-4388-851D-A02369CF1170>.<33> received response, status 200 content K
8.  
9. default    18:20:17.301250+0100    IosArBug    Task <33DDC293-9C69-4388-851D-A02369CF1170>.<33> done using Connection 1
10.  
11. default    2020-12-.30144515 18:20:17+0100    IosArBug    Task <33DDC293-9C69-4388-851D-A02369CF1170>.<33> response ended[/COLOR]
12. default    18:20:17.301686+0100    IosArBug    Task <33DDC293-9C69-4388-851D-A02369CF1170>.<33> summary for task success {transaction_duration_ms=117, response_status=200, connection=1, reused=1, request_start_ms=0, request_duration_ms=0, response_start_ms=108, response_duration_ms=9, request_bytes=23, response_bytes=41219, cache_hit=0}
13. default    18:20:17.301950+0100    IosArBug    Task <33DDC293-9C69-4388-851D-A02369CF1170>.<33> finished successfully
14. default    18:20:19.317202+0100    IosArBug    Task <DE6A9365-85A7-408C-86B9-0882447D3F20>.<34> resuming, timeouts(0.0, 604800.0) QOS(0x0) Voucher (null)
15. default    18:20:19.318056+0100    IosArBug    [Telemetry]: Activity <nw_activity 12:2 [F28FF22B-3041-4426-A57A-3B76FAF1300D] (reporting strategy default)> on Task <DE6A9365-85A7-408C-86B9-0882447D3F20>.<34> was not selected for reporting
16. default    18:20:19.318823+0100    IosArBug    Task <DE6A9365-85A7-408C-86B9-0882447D3F20>.<34> {strength 0, tls 4, ct 0, sub 0, sig 1, ciphers 0, bundle 0, builtin 0}
17. [COLOR=#0080ff]default    18:20:19.319108+0100    IosArBug    Task <DE6A9365-85A7-408C-86B9-0882447D3F20>.<34> now using Connection 1
18.  
19. default    18:20:19.319310+0100    IosArBug    Task <DE6A9365-85A7-408C-86B9-0882447D3F20>.<34> sent request, body N 0
20.  
21. default    18:20:19.437822+0100    IosArBug    Task <DE6A9365-85A7-408C-86B9-0882447D3F20>.<34> received response, status 200 content K
22.  
23. default    18:20:19.449373+0100    IosArBug    Task <DE6A9365-85A7-408C-86B9-0882447D3F20>.<34> done using Connection 1[/COLOR]
24. [COLOR=#ff99ff]default    18:23:09.015618+0100    IosArBug    Connection 1: cleaning up[/COLOR]
25. default    18:23:09.016587+0100    IosArBug    [C1 F6625071-BDD3-4B74-91F4-FC6C59A8B7AD www.google.com:443 tcp, url hash: 38c313ef, tls] cancel
26. default    18:23:09.017142+0100    IosArBug    [C1 F6625071-BDD3-4B74-91F4-FC6C59A8B7AD www.google.com:443 tcp, url hash: 38c313ef, tls] cancelled
27.     [C1.1 FBC75025-3A6B-4A01-B172-3F1C772432B9 192.168.1.6:59058<->216.58.209.36:443]
28.     Connected Path: satisfied (Path is satisfied), viable, interface: en0, ipv4, dns
29.     Duration: 241.142s, DNS @0.002s took 0.164s, TCP @0.295s took 0.030s, TLS 1.3 took 0.050s
30.     bytes in/out: 1430461/3864, packets in/out: 611/815, rtt: 0.100s, retransmitted bytes: 0, out-of-order bytes: 0
31. default    18:23:09.018573+0100    IosArBug    nw_protocol_tcp_log_summary [C1.1:3]
32.     [F8133395-48AB-4FBD-A81D-5FEF6CAECE42 192.168.1.6:59058<->216.58.209.36:443]
33.     Init: 1, Conn_Time: 28.988ms, SYNs: 1, WR_T: 0/0, RD_T: 0/0, TFO: 0/0/0, ECN: 0/0/0, TS: 1
34.     rtt_cache: none, rtt_upd: 376, rtt: 100.750ms, rtt_var: 36.562ms rtt_nc: 100.750ms, rtt_var_nc: 36.562ms
35.     ACKs-compressed: 0, ACKs delayed: 26 delayed ACKs sent: 0
36. default    18:23:09.018779+0100    IosArBug    nw_flow_disconnected [C1.1 216.58.209.36:443 cancelled channel-flow ((null))] Output protocol disconnected
37. default    18:23:09.018974+0100    IosArBug    nw_connection_report_state_with_handler_on_nw_queue [C1] reporting state cancelled
38. default    18:23:09.019243+0100    IosArBug    tcp_output [C1.1:3] flags=[F.] seq=232858359, ack=2343472314, win=2048 state=FIN_WAIT_1 rcv_nxt=2343472314, snd_una=232858296
39. default    18:23:09.019475+0100    IosArBug    Connection 1: done
40. default    18:23:09.045710+0100    IosArBug    tcp_input [C1.1:3] flags=[F.] seq=2343472314, ack=232858359, win=265 state=FIN_WAIT_1 rcv_nxt=2343472314, snd_una=232858359
41. default    18:23:09.046489+0100    IosArBug    tcp_output [C1.1:3] flags=[F.] seq=232858359, ack=2343472315, win=2048 state=CLOSING rcv_nxt=2343472315, snd_una=232858359
42.  

RED : Last good call
BLUE : Last call stoped
We can see than recived an answer 200, seems!! Something go wrong after that.

Pink: After 3 minutes connection cleaning up

I can't understand all other stuff.
I ask to you to test if the same happen to you.