Timeout exception

[IvAlex1986]

Hello.

Sometimes I have Timeout exception when I send APN to apple server.
Below is my exception StackTrace:

System.AggregateException: One or more errors occurred. ---> System.TimeoutException: The operation has timed out.
at HttpTwo.Http2Client.d__19.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at HttpTwo.Http2Client.d__17.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at HttpTwo.Http2Client.d__15.MoveNext()
--- End of inner exception stack trace ---
at System.Threading.Tasks.Task`1.GetResultCore(Boolean waitCompletionNotification)
at PushNotificationAPI.Controllers.AppleController.SendNotification(String jwtToken, String deviceToken, String topic, Object payload, Boolean isProduction)
at PushNotificationAPI.Controllers.AppleController.PushNotification(String kid, String iss, String topic, String authKey, Boolean isProduction, String deviceToken, Object payload)
---> (Inner Exception #0) System.TimeoutException: The operation has timed out.
at HttpTwo.Http2Client.d__19.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at HttpTwo.Http2Client.d__17.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at HttpTwo.Http2Client.d__15.MoveNext()<---

My code here:

private AppleResponseModel SendNotification(string jwtToken, string deviceToken, string topic, object payload, bool isProduction)
        {
            var domain = isProduction ? "https://api.push.apple.com:443" : "https://api.development.push.apple.com:443";
            var uri = new Uri($"{domain}/3/device/{deviceToken}");

            var client = new Http2Client(uri);

            var headers = new NameValueCollection
            {
                {"apns-id", Guid.NewGuid().ToString()},
                {"apns-expiration", "0"},
                {"apns-priority", "10"},
                {"apns-topic", topic},
                {"authorization", $"bearer {jwtToken}"}
            };

            var body = Encoding.ASCII.GetBytes(JsonConvert.SerializeObject(payload));

            var response = client.Post(uri, headers, body).Result;

            var responseBody = Encoding.ASCII.GetString(response.Body);
            var notificationId = response.Headers["apns-id"];

            return new AppleResponseModel(response.Status, responseBody, notificationId);
        }

Could you please help me what going wrong?

[tubsybot]

@IvAlex1986 did you ever find a solution for this? We are having the same exact issue. The timeout only happens sometimes and we have the same stack trace as you.

[tanderbold]

+1

[Citaborg]

Think this is related to issue #12

[tsukasa1989]

We also have this same issue. Anyone found a solution for this?

[Neio]

This happened because it is talking to wrong TCP connection somethings. I have some fixes in my fork.

[tsukasa1989]

Thank you, used your version and seems to work fine.

[Jent05]

@Neio i'm using your version, but still get TimeoutException sometimes
my code is:

    var http2Settings = new Http2ConnectionSettings(apnsServerHost,
          apnsServerPort, true, certificatesCollection);

    var payloadJsonBytes = Encoding.ASCII.GetBytes(payload);
    var uri = new Uri($"https://{apnsServerHost}:{apnsServerPort}/3/device/{deviceToken}");
    var headers = new NameValueCollection
    {
          {"apns-id", Guid.NewGuid().ToString()},
          {"apns-expiration", "0"},
          {"apns-priority", "10"},
          {"content-length", payloadJsonBytes.Length.ToString()}
    };

    try
    {
          var http2Client = new Http2Client(http2Settings);
          return await http2Client.Post(uri, headers, payloadJsonBytes);
    }
    catch (Exception ex)
    {
          throw new Exception(ex.Message, ex);
    }

stack trace is:

at HttpTwo.Http2Client.<Send>d__19.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at HttpTwo.Http2Client.<Send>d__17.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at HttpTwo.Http2Client.<Post>d__15.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
   at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
   at System.Runtime.CompilerServices.TaskAwaiter`1.GetResult()
   at PlayAndMore.Services.Services.AppleService.<SendAsync>d__7.MoveNext()

[Neio]

@Jent05 What is your test Windows OS version? And what are logs before you got this exception?
Typically, we could see something like in the console:

01:08:06.391 AM: <- [Frame: SETTINGS, Id=0, Ack=False, HeaderTableSize=, EnablePush=, MaxConcurrentStreams=, InitialWindowSize=, MaxFrameSize=, MaxHeaderListSize=]
01:08:06.391 AM: -> [Frame: SETTINGS, Id=0, Ack=False, HeaderTableSize=, EnablePush=, MaxConcurrentStreams=, InitialWindowSize=, MaxFrameSize=, MaxHeaderListSize=]
01:08:06.400 AM: -> [Frame: SETTINGS, Id=0, Ack=True, HeaderTableSize=, EnablePush=, MaxConcurrentStreams=, InitialWindowSize=, MaxFrameSize=, MaxHeaderListSize=]
01:08:06.402 AM: -> [Frame: HEADERS, Id=1, EndStream=False, EndHeaders=True, Priority=False, Weight=0, Padded=False, PadLength=0, HeaderBlockFragmentLength=175]
01:08:06.403 AM: -> [Frame: DATA, Id=1, EndStream=True, Padded=False, PadLength=0, PayloadLength=35]
01:08:06.679 AM: <- [Frame: SETTINGS, Id=0, Ack=True, HeaderTableSize=, EnablePush=, MaxConcurrentStreams=, InitialWindowSize=, MaxFrameSize=, MaxHeaderListSize=]
01:08:06.685 AM: <- [Frame: SETTINGS, Id=0, Ack=False, HeaderTableSize=, EnablePush=, MaxConcurrentStreams=, InitialWindowSize=, MaxFrameSize=, MaxHeaderListSize=]
01:08:06.685 AM: -> [Frame: SETTINGS, Id=0, Ack=True, HeaderTableSize=, EnablePush=, MaxConcurrentStreams=, InitialWindowSize=, MaxFrameSize=, MaxHeaderListSize=]
01:08:06.686 AM: <- [Frame: HEADERS, Id=1, EndStream=True, EndHeaders=True, Priority=False, Weight=0, Padded=False, PadLength=0, HeaderBlockFragmentLength=35]

[Jent05]

Of course, currently i tested on Windows 10 x64 Home, v.1703
console log is:

10:08:29.966 : -> [Frame: SETTINGS, Id=0, Ack=False, HeaderTableSize=, EnablePush=, MaxConcurrentStreams=, InitialWindowSize=, MaxFrameSize=, MaxHeaderListSize=]
10:08:29.971 : <- [Frame: SETTINGS, Id=0, Ack=False, HeaderTableSize=, EnablePush=, MaxConcurrentStreams=, InitialWindowSize=, MaxFrameSize=, MaxHeaderListSize=]
10:08:29.985 : <- [Frame: SETTINGS, Id=0, Ack=False, HeaderTableSize=, EnablePush=, MaxConcurrentStreams=, InitialWindowSize=, MaxFrameSize=, MaxHeaderListSize=]
10:08:29.993 : -> [Frame: SETTINGS, Id=0, Ack=True, HeaderTableSize=, EnablePush=, MaxConcurrentStreams=, InitialWindowSize=, MaxFrameSize=, MaxHeaderListSize=]
10:08:29.994 : -> [Frame: SETTINGS, Id=0, Ack=True, HeaderTableSize=, EnablePush=, MaxConcurrentStreams=, InitialWindowSize=, MaxFrameSize=, MaxHeaderListSize=]
10:08:29.998 : -> [Frame: HEADERS, Id=1, EndStream=False, EndHeaders=True, Priority=False, Weight=0, Padded=False, PadLength=0, HeaderBlockFragmentLength=86]
10:08:29.999 : -> [Frame: SETTINGS, Id=0, Ack=False, HeaderTableSize=, EnablePush=, MaxConcurrentStreams=, InitialWindowSize=, MaxFrameSize=, MaxHeaderListSize=]
10:08:29.999 : -> [Frame: HEADERS, Id=1, EndStream=False, EndHeaders=True, Priority=False, Weight=0, Padded=False, PadLength=0, HeaderBlockFragmentLength=86]
10:08:30.000 : -> [Frame: DATA, Id=1, EndStream=True, Padded=False, PadLength=0, PayloadLength=248]
10:08:30.092 : <- [Frame: SETTINGS, Id=0, Ack=True, HeaderTableSize=, EnablePush=, MaxConcurrentStreams=, InitialWindowSize=, MaxFrameSize=, MaxHeaderListSize=]
Executed: 'MessageHandlers.SendPushNotificationAsync' (Succeeded)
10:08:30.928 : -> [Frame: DATA, Id=1, EndStream=True, Padded=False, PadLength=0, PayloadLength=248]
10:08:31.055 : <- [Frame: SETTINGS, Id=0, Ack=False, HeaderTableSize=, EnablePush=, MaxConcurrentStreams=, InitialWindowSize=, MaxFrameSize=, MaxHeaderListSize=]
10:08:31.055 : -> [Frame: SETTINGS, Id=0, Ack=True, HeaderTableSize=, EnablePush=, MaxConcurrentStreams=, InitialWindowSize=, MaxFrameSize=, MaxHeaderListSize=]
10:08:31.056 : <- [Frame: HEADERS, Id=1, EndStream=True, EndHeaders=True, Priority=False, Weight=0, Padded=False, PadLength=0, HeaderBlockFragmentLength=37]
10:08:31.061 : <- [Frame: GOAWAY, Id=0, ErrorCode=1, LastStreamId=0, AdditionalDebugData=First received frame was not SETTINGS. Hex dump for first 5 bytes: 0000000401]

[Neio]

@Jent05 , your log looks quite different from mime. Are you sending two request at the same time or asynchronously?

[Jent05]

Yes, I use asynchronous execution, I have a lot of notifications, and especially architecture allows, why not?

[Neio]

@Jent05 Unfortunately, I doubt that HttpTwo library supports that. When I use it, I use lock to make sure other thread finished using HttpTwo.

[karsuszhang]

@Neio @Jent05 Have you tried this on windows server 2016? I have an ec2 instantce running windows server 2016 basic, turn off the firewall, open all port inbound and outbound in security groups. It works fine on my windows 10, but always timeout on the server, very few times can send succeed. Even when I just send one push.Logs are below, compare to normal log seems shouldn't have a GOAWAY frame:

8/8/2017 8:06:21 AM [Normal]<- [Frame: SETTINGS, Id=0, Ack=False, HeaderTableSize=, EnablePush=, MaxConcurrentStreams=, InitialWindowSize=, MaxFrameSize=, MaxHeaderListSize=]
8/8/2017 8:06:21 AM [Normal]-> [Frame: SETTINGS, Id=0, Ack=True, HeaderTableSize=, EnablePush=, MaxConcurrentStreams=, InitialWindowSize=, MaxFrameSize=, MaxHeaderListSize=]
8/8/2017 8:06:21 AM [Normal]-> [Frame: SETTINGS, Id=0, Ack=False, HeaderTableSize=, EnablePush=, MaxConcurrentStreams=, InitialWindowSize=, MaxFrameSize=, MaxHeaderListSize=]
8/8/2017 8:06:21 AM [Normal]-> [Frame: HEADERS, Id=1, EndStream=False, EndHeaders=True, Priority=False, Weight=0, Padded=False, PadLength=0, HeaderBlockFragmentLength=309]
8/8/2017 8:06:21 AM [Normal]-> [Frame: DATA, Id=1, EndStream=True, Padded=False, PadLength=0, PayloadLength=87]
8/8/2017 8:06:21 AM [Normal]<- [Frame: GOAWAY, Id=0, ErrorCode=1, LastStreamId=0, AdditionalDebugData=First received frame was not SETTINGS. Hex dump for first 5 bytes: 0000000401]