search

mwkirk / javapns

Test import of svn javapns repo from Google Code
3 stars 0 forks source link

Reading response hangs, sometimes causing timeouts in 2.2, but not in 2.0-beta4 #114

Closed mwkirk closed 11 years ago

mwkirk commented 11 years ago

Original author: dustin.b...@gmail.com (April 10, 2012 23:38:14)

Just upgraded to use 2.2 (from 2.0-beta4) and are getting long delays.

What steps will reproduce the problem?

  1. Using version 2.0_Beta4, no delay on reading response from APNS, almost instant response from APNS.

2012-04-10 17:27:25 PushNotificationService [INFO] Pushing with Payload: {"aps":{"sound":"default","alert":"this is a test","badge":1},"data.type":"testmsg"} 2012-04-10 17:27:25 ConnectionToAppleServer [DEBUG] Creating SSLSocketFactory 2012-04-10 17:27:25 ConnectionToAppleServer [DEBUG] Creating SSLSocket to gateway.sandbox.push.apple.com:2195 2012-04-10 17:27:25 PushNotificationManager [DEBUG] Initialized Connection to Host: [gateway.sandbox.push.apple.com] Port: [2195]: 4f549ceb[SSL_NULL_WITH_NULL_NULL: Socket[addr=gateway.sandbox.push.apple.com/17.172.233.66,port=2195,localport=65214]] 2012-04-10 17:27:25 PushNotificationManager [DEBUG] Building Raw message from deviceToken and payload 2012-04-10 17:27:25 PushNotificationManager [DEBUG] Attempting to send notification: {"aps":{"sound":"default","alert":"this is a test","badge":1},"data.type":"testmsg"} 2012-04-10 17:27:25 PushNotificationManager [DEBUG] to device: <abc123> 2012-04-10 17:27:25 PushNotificationManager [DEBUG] Flushing 2012-04-10 17:27:25 PushNotificationManager [DEBUG] Notification sent on first attempt 2012-04-10 17:27:25 PushNotificationManager [DEBUG] Closing connection 2012-04-10 17:27:25 PushNotificationService [DEBUG] Devices Size of Push: 1 2012-04-10 17:27:25 DispatcherServlet [DEBUG] Null ModelAndView returned to DispatcherServlet with name 'dispatcher': assuming HandlerAdapter completed request handling 2012-04-10 17:27:25 DispatcherServlet [DEBUG] Successfully completed request

  1. Using version 2.2, sometimes it takes up to 10+ seconds to finish reading the response. Here's log output from running on my local Mac (see same when running on deployed linux server, too):

2012-04-10 17:31:44 PushController [DEBUG] Push message request received for token: <abc123>, message=this is a test, payload=data.type=testmsg 2012-04-10 17:31:44 PushController [DEBUG] * building extras from payload:data.type=testmsg 2012-04-10 17:31:44 PushController [DEBUG] * adding extra:data.type===testmsg 2012-04-10 17:31:44 PushNotificationService [DEBUG] * Pushing alert/badge/sound message 2012-04-10 17:31:44 Payload [DEBUG] Adding alert [this is a test] 2012-04-10 17:31:44 Payload [DEBUG] Adding badge [1] 2012-04-10 17:31:44 Payload [DEBUG] Adding sound [default] 2012-04-10 17:31:44 PushNotificationService [DEBUG] * Adding extra : data.type=testmsg 2012-04-10 17:31:44 Payload [DEBUG] Adding custom Dictionary [data.type] = [testmsg] 2012-04-10 17:31:44 PushNotificationService [INFO] Pushing with Payload: {"aps":{"sound":"default","alert":"this is a test","badge":1},"data.type":"testmsg"} 2012-04-10 17:31:44 ConnectionToAppleServer [DEBUG] Creating SSLSocketFactory 2012-04-10 17:31:44 ConnectionToAppleServer [DEBUG] Creating SSLSocket to gateway.sandbox.push.apple.com:2195 2012-04-10 17:31:44 PushNotificationManager [DEBUG] Initialized Connection to Host: [gateway.sandbox.push.apple.com] Port: [2195]: 1633c3e6[SSL_NULL_WITH_NULL_NULL: Socket[addr=gateway.sandbox.push.apple.com/17.149.34.65,port=2195,localport=65252]] 2012-04-10 17:31:44 PushNotificationManager [DEBUG] Building Raw message from deviceToken and payload 2012-04-10 17:31:44 PushNotificationManager [DEBUG] Built raw message ID 1 of total length 129 2012-04-10 17:31:44 PushNotificationManager [DEBUG] Attempting to send notification: {"aps":{"sound":"default","alert":"this is a test","badge":1},"data.type":"testmsg"} 2012-04-10 17:31:44 PushNotificationManager [DEBUG] to device: <abc123> 2012-04-10 17:31:44 PushNotificationManager [DEBUG] Flushing 2012-04-10 17:31:44 PushNotificationManager [DEBUG] At this point, the entire 129-bytes message has been streamed out successfully through the SSL connection 2012-04-10 17:31:44 PushNotificationManager [DEBUG] Notification sent on first attempt 2012-04-10 17:31:44 PushNotificationManager [DEBUG] Reading responses // 5 seconds in this case 2012-04-10 17:31:49 PushNotificationManager [DEBUG] Closing connection 2012-04-10 17:31:49 PushNotificationService [DEBUG] Devices Size of Push: 1 2012-04-10 17:31:49 DispatcherServlet [DEBUG] Null ModelAndView returned to DispatcherServlet with name 'dispatcher': assuming HandlerAdapter completed request handling 2012-04-10 17:31:49 DispatcherServlet [DEBUG] Successfully completed request

Stack dump while it was paused for 5 minutes shows this thread waiting on read operation to complete: "http-8080-2" daemon prio=5 tid=7fe8ccbb2000 nid=0x10fc3c000 runnable [10fc39000] java.lang.Thread.State: RUNNABLE at java.net.SocketInputStream.socketRead0(Native Method) at java.net.SocketInputStream.read(SocketInputStream.java:129) at com.sun.net.ssl.internal.ssl.InputRecord.readFully(InputRecord.java:293) at com.sun.net.ssl.internal.ssl.InputRecord.read(InputRecord.java:331) at com.sun.net.ssl.internal.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:830)

What is the expected output? What do you see instead?

What version of the product are you using? On what operating system?

Please provide any additional information below. My code: public boolean pushNewMessage(String token, String message, HashMap<String, String> extras) { ... PushNotificationPayload payload = PushNotificationPayload.complex(); ... payload.addAlert(message); payload.addBadge(1); payload.addSound(sound); ... // now push the payload LOG.info("Pushing with Payload: " + payload.toString()); List<PushedNotification> devices = Push.payload(payload, certPath, certPassword, productionEnabled, new String[] { token });

... }

Let me know what other info you need, or what I can try/doing wrong, etc!

Many thanks!

Original issue: http://code.google.com/p/javapns/issues/detail?id=114

mwkirk commented 11 years ago

From sype...@gmail.com on April 11, 2012 01:15:49 2.0 Beta 4 did not include any support for reading error-response packets, so it would not have been affected by this more recent read process (but obviously 2.0b4 wouldn't provide accurate error reports because of that missing process). However, the library we have today is supposed to request a short timeout so not to block indefinitely, so a thread stuck on read for 5 minutes is not behaving as expected.

Could you try the latest 2.3 Alpha build from the trunk and let me know if you still experience the issue with it? Some work has been done recently around error-response packets in JavaPNS, so the issue might already be fixed.

Btw, if you don't care about error-response packets, you can disable the enhanced notification format entirely by invoking PushNotificationManager.setEnhancedNotificationFormatEnabled(false); (although this is not recommended because you turn off error management and loose that precious source of error information).

mwkirk commented 11 years ago

From dustin.b...@gmail.com on April 11, 2012 02:00:16 Note: It's 5 SECONDS, not minutes. But, our GAE server that calls over to our push-server times out after 30 seconds, so it's causing issues.

I just tried 2.3-Alpha4 and get the same results:

2012-04-10 19:57:50 Payload [DEBUG] Adding custom Dictionary [data.type] = [testmsg] 2012-04-10 19:57:50 PushNotificationService [INFO] Pushing with Payload: {"aps":{"sound":"default","alert":"testing","badge":1},"data.type":"testmsg"} 2012-04-10 19:57:50 ConnectionToAppleServer [DEBUG] Creating SSLSocketFactory 2012-04-10 19:57:50 ConnectionToAppleServer [DEBUG] Creating SSLSocket to gateway.sandbox.push.apple.com:2195 2012-04-10 19:57:50 PushNotificationManager [DEBUG] Initialized Connection to Host: [gateway.sandbox.push.apple.com] Port: [2195]: 64626fd2[SSL_NULL_WITH_NULL_NULL: Socket[addr=gateway.sandbox.push.apple.com/17.149.34.66,port=2195,localport=50453]] 2012-04-10 19:57:50 PushNotificationManager [DEBUG] Building Raw message from deviceToken and payload 2012-04-10 19:57:50 PushNotificationManager [DEBUG] Built raw message ID 1 of total length 122 2012-04-10 19:57:50 PushNotificationManager [DEBUG] Attempting to send notification: {"aps":{"sound":"default","alert":"testing","badge":1},"data.type":"testmsg"} 2012-04-10 19:57:50 PushNotificationManager [DEBUG] to device: 8a662fa8e2d7c6bd6c309941f1b14c354286cd3aeb26e01e37dbd2af339af044 2012-04-10 19:57:50 PushNotificationManager [DEBUG] Flushing 2012-04-10 19:57:50 PushNotificationManager [DEBUG] At this point, the entire 122-bytes message has been streamed out successfully through the SSL connection 2012-04-10 19:57:50 PushNotificationManager [DEBUG] Notification sent on first attempt 2012-04-10 19:57:50 PushNotificationManager [DEBUG] Reading responses

//// 5 seconds here

2012-04-10 19:57:55 PushNotificationManager [DEBUG] Closing connection 2012-04-10 19:57:55 PushNotificationService [DEBUG] Devices Size of Push: 1 2012-04-10 19:57:55 DispatcherServlet [DEBUG] Null ModelAndView returned to DispatcherServlet with name 'dispatcher': assuming HandlerAdapter completed request handling 2012-04-10 19:57:55 DispatcherServlet [DEBUG] Successfully completed request

mwkirk commented 11 years ago

From sype...@gmail.com on April 11, 2012 03:01:56 Ah, 5 seconds sounds much better than 5 minutes :)

5 seconds is indeed the hardcoded timeout necessary to make sure that no more response packets are coming in. This specific timeout was selected after a lot of field testing, so it is pretty much a fine-tuned value which should not be changed. Since reading is done inline within the same thread, and since Apple servers to not shut down the stream on their end when the socket is closed, read timeout seems to be unavoidable. The timeouts are trapped and ignored, but the delay before a timeout occurs can be perceived, as you did.

If you push a single notification at a time and that you can't do it asynchronously, I agree that the delay might be problematic. For now, the only way to avoid the delay is to turn off the enhanced notification format as per my previous comment. There are plans to eventually move the error-response packet reading mechanism to a separate thread to avoid the delay, but it is not as easy as it sounds because push methods returning immediately would not yet know about the errors coming in asynchronously a few milliseconds or seconds later from the other thread...

mwkirk commented 11 years ago

From sype...@gmail.com on April 21, 2012 17:08:59 Since the 5-seconds delay is necessary to give Apple servers time to return error-response packets, if any, I am closing this issue as WontFix because it is an APNS design issue rather than an issue with JavaPNS.