search

woolfel / javapns

Automatically exported from code.google.com/p/javapns
0 stars 0 forks source link

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

Closed GoogleCodeExporter closed 9 years ago

GoogleCodeExporter commented 9 years ago 
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=652
14]]
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

2. 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=6525
2]]
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)
    - locked <7f4065260> (a java.lang.Object)
    at com.sun.net.ssl.internal.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:787)
    at com.sun.net.ssl.internal.ssl.AppInputStream.read(AppInputStream.java:75)
    - locked <7f4065358> (a com.sun.net.ssl.internal.ssl.AppInputStream)
    at com.sun.net.ssl.internal.ssl.AppInputStream.read(AppInputStream.java:50)
    - locked <7f4065358> (a com.sun.net.ssl.internal.ssl.AppInputStream)
    at javapns.notification.ResponsePacketReader.readResponsePacketData(ResponsePacketReader.java:81)
    at javapns.notification.ResponsePacketReader.readResponses(ResponsePacketReader.java:53)
    at javapns.notification.ResponsePacketReader.processResponses(ResponsePacketReader.java:26)
    at javapns.notification.PushNotificationManager.processedFailedNotifications(PushNotificationManager.java:223)
    at javapns.notification.PushNotificationManager.stopConnection(PushNotificationManager.java:198)
    at javapns.Push.sendPayload(Push.java:185)
    at javapns.Push.payload(Push.java:149)

What is the expected output? What do you see instead?
- really liked 2.0_beta4 speed!  ;)

What version of the product are you using? On what operating system?
- Running tests on Mac OSX 10.7 as well as Linux.

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 reported on code.google.com by dustin.b...@gmail.com on 10 Apr 2012 at 11:38

GoogleCodeExporter commented 9 years ago 
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).

Original comment by sype...@gmail.com on 11 Apr 2012 at 1:15

GoogleCodeExporter commented 9 years ago 
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=5045
3]]
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

Original comment by dustin.b...@gmail.com on 11 Apr 2012 at 2:00

GoogleCodeExporter commented 9 years ago 
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...

Original comment by sype...@gmail.com on 11 Apr 2012 at 3:01

GoogleCodeExporter commented 9 years ago 
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.

Original comment by sype...@gmail.com on 21 Apr 2012 at 5:08