Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Push notifications silently fail until a new PushManager is created #109

Closed
steve-taylor opened this issue Jul 28, 2014 · 6 comments
Closed

Push notifications silently fail until a new PushManager is created #109

steve-taylor opened this issue Jul 28, 2014 · 6 comments
Milestone
v0.4

Comments

@steve-taylor
Copy link

I'm creating a PushManager inside a singleton EJB:

@Singleton
public class ApnsService {

    public void push(int sendingUserId, String deviceToken, PushNotification pushNotification) {
        ApnsPayloadBuilder payloadBuilder = new ApnsPayloadBuilder();
        payloadBuilder.setAlertBody(pushNotification.getMessage());
        payloadBuilder.setSoundFileName(pushNotification.getSound() != null ? pushNotification.getSound() : ApnsPayloadBuilder.DEFAULT_SOUND_FILENAME);
        payloadBuilder.setBadgeNumber(pushNotification.getBadgeNumber());
        for (String propertyName : pushNotification.propertyNames()) {
            payloadBuilder.addCustomProperty(propertyName, pushNotification.propertyValue(propertyName));
        }
        payloadBuilder.addCustomProperty("OwnerId", sendingUserId);
        String payload = payloadBuilder.buildWithDefaultMaximumLength();
        byte[] token = TokenUtil.tokenStringToByteArray(deviceToken);
        try {
            pushManager.getQueue().put(new SimpleApnsPushNotification(token, payload));
        } catch (InterruptedException exc) {
            throw new RuntimeException(exc);
        }
    }

    @PostConstruct
    protected void activate() {
        try {
            String path = getClass().getClassLoader().getResource("/MyAPNS.p12").getPath();

            pushManager
                    = new PushManagerFactory<SimpleApnsPushNotification>(ApnsEnvironment.getSandboxEnvironment(),
                                                                         PushManagerFactory.createDefaultSSLContext(path, "hello"))
                    .buildPushManager();
            pushManager.start();

            pushManager.registerRejectedNotificationListener(new RejectedNotificationListener<SimpleApnsPushNotification>() {
                @Override
                public void handleRejectedNotification(PushManager<? extends SimpleApnsPushNotification> pushManager,
                                                       SimpleApnsPushNotification notification,
                                                       RejectedNotificationReason rejectionReason) {
                    System.out.println(String.format("%s was rejected with reason %s", notification, rejectionReason));
                }
            });

            pushManager.registerFailedConnectionListener(new FailedConnectionListener<SimpleApnsPushNotification>() {
                @Override
                public void handleFailedConnection(PushManager<? extends SimpleApnsPushNotification> pushManager, Throwable cause) {
                    System.out.println(String.format("APNS connection failure: %s (%s)", cause.getMessage(), cause.getClass().getName()));
                }
            });
        } catch (Exception exc) {
            throw new RuntimeException(exc);
        }
    }

    @PreDestroy
    protected void deactivate() {
        try {
            pushManager.shutdown();
        } catch (InterruptedException exc) {
            throw new RuntimeException(exc);
        }
    }

    private PushManager<SimpleApnsPushNotification> pushManager;
}

After a while, push notifications just stop working. There is not feedback and no exceptions being logged. After I reboot the server, push notifications start being processed again. Am I doing something wrong in the above code?
@jchambers
Copy link
Owner

@steve-taylor How long is "a while?" Could you please set our logging level to TRACE and show what happens for (a) a push notification that does get sent and (b) one that does not?

Thanks!

@steve-taylor
Copy link
Author

@jchambers How do I set the logging level in pushy?

@steve-taylor
Copy link
Author

Since I am running on GlassFish 4 and SLF4J and GlassFish 4 don't work together without manually copying jars and hacking XML files, I simply cannot enable pushy logging. It is completely pointless to abstract away choice of logging framework when you could simply just choose one and it will work.

@dbliefernicht
Copy link

I might actually have encountered at least a similar issue while debugging sometimes missed push notifications. We're using pushy 0.3 at the moment. Logging at trace level shows the following behaviour:

Everything is running smoothly and when encountering an invalid token, the connection is dropped, re-established and restarted:

2014-08-04 14:52:39,622 Server[2181] TRACE com.relayrides.pushy.apns.ApnsConnection  - ApnsConnection-0 sending SendableApnsPushNotification [sequenceNumber=234, token=<omitted>, payload=<omitted>, deliveryInvalidation=2014-08-07 04:09:35 Etc/GMT]
2014-08-04 14:52:39,623 Server[2181] TRACE com.relayrides.pushy.apns.ApnsConnection  - ApnsConnection-0 successfully wrote notification 234
2014-08-04 14:52:39,977 Server[2181] DEBUG com.relayrides.pushy.apns.ApnsConnection  - APNs gateway rejected notification with sequence number 231 from ApnsConnection-0 (INVALID_TOKEN).
2014-08-04 14:52:39,978 Server[2181] TRACE com.relayrides.pushy.apns.PushManager  - ApnsConnection [name=ApnsConnection-0] rejected SimpleApnsPushNotification [token=<omitted>, payload=<omitted> expiration=2014-08-07 04:09:35 Etc/GMT]: INVALID_TOKEN
2014-08-04 14:52:39,978 Server[2181] TRACE com.relayrides.pushy.apns.PushManager  - ApnsConnection [name=ApnsConnection-0] returned 3 unprocessed notifications
2014-08-04 14:52:39,979 Server[2181] TRACE com.relayrides.pushy.apns.ApnsConnection  - ApnsConnection-0 sending SendableApnsPushNotification [sequenceNumber=235, token=<omitted>, payload=<omitted>, deliveryInvalidation=2014-08-07 04:09:35 Etc/GMT]
2014-08-04 14:52:39,980 Server[2181] TRACE com.relayrides.pushy.apns.ApnsConnection  - ApnsConnection-0 failed to write notification SendableApnsPushNotification [sequenceNumber=235, token=<omitted>, payload=<omitted>, deliveryInvalidation=2014-08-07 04:09:35 Etc/GMT]
2014-08-04 14:52:39,980 Server[2181] TRACE com.relayrides.pushy.apns.ApnsConnection  - ApnsConnection-0 sending SendableApnsPushNotification [sequenceNumber=236, token=<omitted>, payload=<omitted>, deliveryInvalidation=2014-08-07 04:09:35 Etc/GMT]
2014-08-04 14:52:39,981 Server[2181] TRACE com.relayrides.pushy.apns.ApnsConnection  - ApnsConnection-0 failed to write notification SendableApnsPushNotification [sequenceNumber=236, token=<omitted>, payload=<omitted>, deliveryInvalidation=2014-08-07 04:09:35 Etc/GMT]
2014-08-04 14:52:39,981 Server[2181] TRACE com.relayrides.pushy.apns.ApnsConnection  - ApnsConnection-0 sending SendableApnsPushNotification [sequenceNumber=237, token=<omitted>, payload=<omitted>, deliveryInvalidation=2014-08-07 04:09:35 Etc/GMT]
2014-08-04 14:52:39,982 Server[2181] TRACE com.relayrides.pushy.apns.ApnsConnection  - ApnsConnection-0 failed to write notification SendableApnsPushNotification [sequenceNumber=237, token=<omitted>, payload=<omitted>, deliveryInvalidation=2014-08-07 04:09:35 Etc/GMT]
2014-08-04 14:52:39,982 Server[2181] TRACE com.relayrides.pushy.apns.PushManager  - Connection closed: ApnsConnection [name=ApnsConnection-0]
2014-08-04 14:52:39,984 Server[2181] TRACE com.relayrides.pushy.apns.ApnsConnection  - ApnsConnection-0 sending SendableApnsPushNotification [sequenceNumber=238, token=<omitted>, payload=<omitted>, deliveryInvalidation=2014-08-07 04:09:35 Etc/GMT]
2014-08-04 14:52:39,985 Server[2181] DEBUG com.relayrides.pushy.apns.ApnsConnection  - ApnsConnection-1 beginning connection process.
2014-08-04 14:52:39,985 Server[2181] TRACE com.relayrides.pushy.apns.ApnsConnection  - ApnsConnection-0 failed to write notification SendableApnsPushNotification [sequenceNumber=238, token=<omitted>, payload=<omitted>, deliveryInvalidation=2014-08-07 04:09:35 Etc/GMT]
2014-08-04 14:52:39,986 Server[2181] TRACE com.relayrides.pushy.apns.ApnsConnection  - ApnsConnection-0 sending SendableApnsPushNotification [sequenceNumber=239, token=<omitted>, payload=<omitted>, deliveryInvalidation=2014-08-07 04:09:35 Etc/GMT]
2014-08-04 14:52:39,987 Server[2181] TRACE com.relayrides.pushy.apns.ApnsConnection  - ApnsConnection-0 failed to write notification SendableApnsPushNotification [sequenceNumber=239, token=<omitted>, payload=<omitted>, deliveryInvalidation=2014-08-07 04:09:35 Etc/GMT]
2014-08-04 14:52:39,987 Server[2181] TRACE com.relayrides.pushy.apns.ApnsConnection  - ApnsConnection-0 sending SendableApnsPushNotification [sequenceNumber=240, token=<omitted>, payload=<omitted>, deliveryInvalidation=2014-08-07 04:09:35 Etc/GMT]
2014-08-04 14:52:39,987 Server[2181] TRACE com.relayrides.pushy.apns.ApnsConnection  - ApnsConnection-0 failed to write notification SendableApnsPushNotification [sequenceNumber=240, token=<omitted>, payload=<omitted>, deliveryInvalidation=2014-08-07 04:09:35 Etc/GMT]
2014-08-04 14:52:40,181 Server[2181] DEBUG com.relayrides.pushy.apns.ApnsConnection  - ApnsConnection-1 connected; waiting for TLS handshake.
2014-08-04 14:52:40,608 Server[2181] DEBUG com.relayrides.pushy.apns.ApnsConnection  - ApnsConnection-1 successfully completed TLS handshake.
2014-08-04 14:52:40,608 Server[2181] TRACE com.relayrides.pushy.apns.PushManager  - Connection succeeded: ApnsConnection [name=ApnsConnection-1]
2014-08-04 14:52:40,609 Server[2181] TRACE com.relayrides.pushy.apns.ApnsConnection  - ApnsConnection-1 sending SendableApnsPushNotification [sequenceNumber=0, token=<omitted>, payload=<omitted>, deliveryInvalidation=2014-08-07 04:09:35 Etc/GMT]
2014-08-04 14:52:40,610 Server[2181] TRACE com.relayrides.pushy.apns.ApnsConnection  - ApnsConnection-1 successfully wrote notification 0

This goes on for a while, until one of the restarts seem to encounter an issue and does not properly restart anymore:

2014-08-04 14:52:41,671 Server[2181] TRACE com.relayrides.pushy.apns.ApnsConnection  - ApnsConnection-2 successfully wrote notification 76
2014-08-04 14:52:41,671 Server[2181] TRACE com.relayrides.pushy.apns.ApnsConnection  - ApnsConnection-2 successfully wrote notification 77
2014-08-04 14:52:41,671 Server[2181] TRACE com.relayrides.pushy.apns.ApnsConnection  - ApnsConnection-2 successfully wrote notification 78
2014-08-04 14:52:41,819 Server[2181] TRACE com.relayrides.pushy.apns.ApnsConnection  - ApnsConnection-2 sending SendableApnsPushNotification [sequenceNumber=79, token=<omitted>, payload=<omitted>, deliveryInvalidation=292278994-08-17 07:12:55 Etc/GMT]
2014-08-04 14:52:41,820 Server[2181] TRACE com.relayrides.pushy.apns.ApnsConnection  - ApnsConnection-2 successfully wrote notification 79
2014-08-04 14:52:41,857 Server[2181] DEBUG com.relayrides.pushy.apns.ApnsConnection  - APNs gateway rejected notification with sequence number 77 from ApnsConnection-2 (INVALID_TOKEN).
2014-08-04 14:52:41,858 Server[2181] TRACE com.relayrides.pushy.apns.PushManager  - ApnsConnection [name=ApnsConnection-2] rejected SimpleApnsPushNotification [token=<omitted>, payload=<omitted>, expiration=292278994-08-17 07:12:55 Etc/GMT]: INVALID_TOKEN
2014-08-04 14:52:41,858 Server[2181] TRACE com.relayrides.pushy.apns.PushManager  - ApnsConnection [name=ApnsConnection-2] returned 2 unprocessed notifications
2014-08-04 14:52:41,858 Server[2181] TRACE com.relayrides.pushy.apns.ApnsConnection  - ApnsConnection-2 sending SendableApnsPushNotification [sequenceNumber=80, token=<omitted>, payload=<omitted>, deliveryInvalidation=292278994-08-17 07:12:55 Etc/GMT]
2014-08-04 14:52:41,859 Server[2181] TRACE com.relayrides.pushy.apns.ApnsConnection  - ApnsConnection-2 successfully wrote notification 80
2014-08-04 14:52:41,859 Server[2181] TRACE com.relayrides.pushy.apns.PushManager  - ApnsConnection [name=ApnsConnection-2] returned 1 unprocessed notifications
2014-08-04 14:52:41,859 Server[2181] TRACE com.relayrides.pushy.apns.ApnsConnection  - ApnsConnection-2 sending SendableApnsPushNotification [sequenceNumber=81, token=<omitted>, payload=<omitted>, deliveryInvalidation=292278994-08-17 07:12:55 Etc/GMT]
2014-08-04 14:52:41,860 Server[2181] TRACE com.relayrides.pushy.apns.ApnsConnection  - ApnsConnection-2 successfully wrote notification 81

although Apple already rejected a notification, pushy seems to continue writing in the (probably broken) connection, this goes on for quite a while:

2014-08-04 14:52:41,967 Server[2181] TRACE com.relayrides.pushy.apns.ApnsConnection  - ApnsConnection-2 sending SendableApnsPushNotification [sequenceNumber=219, token=<omitted>, payload=<omitted>, deliveryInvalidation=292278994-08-17 07:12:55 Etc/GMT]
2014-08-04 14:52:41,968 Server[2181] TRACE com.relayrides.pushy.apns.ApnsConnection  - ApnsConnection-2 successfully wrote notification 219
2014-08-04 14:52:41,968 Server[2181] TRACE com.relayrides.pushy.apns.PushManager  - ApnsConnection [name=ApnsConnection-2] returned 1 unprocessed notifications
2014-08-04 14:52:41,968 Server[2181] TRACE com.relayrides.pushy.apns.ApnsConnection  - ApnsConnection-2 sending SendableApnsPushNotification [sequenceNumber=220, token=<omitted>, payload=<omitted>, deliveryInvalidation=292278994-08-17 07:12:55 Etc/GMT]
2014-08-04 14:52:41,969 Server[2181] TRACE com.relayrides.pushy.apns.ApnsConnection  - ApnsConnection-2 successfully wrote notification 220
2014-08-04 14:52:41,969 Server[2181] TRACE com.relayrides.pushy.apns.PushManager  - ApnsConnection [name=ApnsConnection-2] returned 1 unprocessed notifications
2014-08-04 14:52:41,969 Server[2181] TRACE com.relayrides.pushy.apns.ApnsConnection  - ApnsConnection-2 sending SendableApnsPushNotification [sequenceNumber=221, token=<omitted>, payload=<omitted>, deliveryInvalidation=292278994-08-17 07:12:55 Etc/GMT]
2014-08-04 14:52:41,969 Server[2181] TRACE com.relayrides.pushy.apns.ApnsConnection  - ApnsConnection-2 sending SendableApnsPushNotification [sequenceNumber=222, token=<omitted>, payload=<omitted>, deliveryInvalidation=292278994-08-17 07:12:55 Etc/GMT]
2014-08-04 14:52:42,879 Server[2181] TRACE com.relayrides.pushy.apns.ApnsConnection  - ApnsConnection-2 sending SendableApnsPushNotification [sequenceNumber=223, token=<omitted>, payload=<omitted>, deliveryInvalidation=292278994-08-17 07:12:55 Etc/GMT]

at this point the successful writes and unprocessed notifications messages stop as well, notifications are further sent though (probably until a buffer is filled):

2014-08-04 14:53:21,960 Server[2181] TRACE com.relayrides.pushy.apns.ApnsConnection  - ApnsConnection-2 sending SendableApnsPushNotification [sequenceNumber=499, token=<omitted>, payload=<omitted>, deliveryInvalidation=292278994-08-17 07:12:55 Etc/GMT]
2014-08-04 14:53:21,960 Server[2181] TRACE com.relayrides.pushy.apns.ApnsConnection  - ApnsConnection-2 sending SendableApnsPushNotification [sequenceNumber=500, token=<omitted>, payload=<omitted>, deliveryInvalidation=292278994-08-17 07:12:55 Etc/GMT]
2014-08-04 14:53:21,961 Server[2181] TRACE com.relayrides.pushy.apns.ApnsConnection  - ApnsConnection-2 sending SendableApnsPushNotification [sequenceNumber=501, token=<omitted>, payload=<omitted>, deliveryInvalidation=292278994-08-17 07:12:55 Etc/GMT]
2014-08-04 14:53:21,961 Server[2181] TRACE com.relayrides.pushy.apns.PushManager  - Writability for ApnsConnection [name=ApnsConnection-2] changed to false

at which point pushy just waits. There is no issue (exception etc.), sending further notifications to the push manager though (from the API side). Another log shows, that this actually has some kind of timeout as well. After 16 minutes and 10 seconds the process seems to advance again, noticing an (unlogged) exception and restarting. Of course notifications are up to 15 minutes too late this way, of course:

2014-08-04 15:13:10,237 Server[2181] TRACE com.relayrides.pushy.apns.ApnsConnection  - ApnsConnection-12 sending SendableApnsPushNotification [sequenceNumber=1054, token=<omitted>, payload=<omitted>, deliveryInvalidation=292278994-08-17 07:12:55 Etc/GMT]
2014-08-04 15:13:10,237 Server[2181] TRACE com.relayrides.pushy.apns.ApnsConnection  - ApnsConnection-12 sending SendableApnsPushNotification [sequenceNumber=1055, token=<omitted>, payload=<omitted>, deliveryInvalidation=292278994-08-17 07:12:55 Etc/GMT]
2014-08-04 15:29:20,269 Server[2181] DEBUG com.relayrides.pushy.apns.ApnsConnection  - ApnsConnection-12 caught an exception.
2014-08-04 15:29:20,270 Server[2181] TRACE com.relayrides.pushy.apns.ApnsConnection  - ApnsConnection-12 failed to write notification SendableApnsPushNotification [sequenceNumber=769, token=<omitted>, payload=<omitted>, deliveryInvalidation=292278994-08-17 07:12:55 Etc/GMT]
2014-08-04 15:29:20,270 Server[2181] TRACE com.relayrides.pushy.apns.ApnsConnection  - ApnsConnection-12 failed to write notification SendableApnsPushNotification [sequenceNumber=770, token=<omitted>, payload=<omitted>, deliveryInvalidation=292278994-08-17 07:12:55 Etc/GMT]
...
...
...
2014-08-04 15:29:20,313 Server[2181] TRACE com.relayrides.pushy.apns.ApnsConnection  - ApnsConnection-12 failed to write notification SendableApnsPushNotification [sequenceNumber=1054, token=<omitted>, payload=<omitted>, deliveryInvalidation=292278994-08-17 07:12:55 Etc/GMT]
2014-08-04 15:29:20,313 Server[2181] TRACE com.relayrides.pushy.apns.ApnsConnection  - ApnsConnection-12 failed to write notification SendableApnsPushNotification [sequenceNumber=1055, token=<omitted>, payload=<omitted>, deliveryInvalidation=292278994-08-17 07:12:55 Etc/GMT]
2014-08-04 15:29:20,314 Server[2181] TRACE com.relayrides.pushy.apns.PushManager  - Connection closed: ApnsConnection [name=ApnsConnection-12]
2014-08-04 15:29:20,315 Server[2181] DEBUG com.relayrides.pushy.apns.ApnsConnection  - ApnsConnection-13 beginning connection process.
2014-08-04 15:29:20,485 Server[2181] DEBUG com.relayrides.pushy.apns.ApnsConnection  - ApnsConnection-13 connected; waiting for TLS handshake.
2014-08-04 15:29:20,738 Server[2181] DEBUG com.relayrides.pushy.apns.ApnsConnection  - ApnsConnection-13 successfully completed TLS handshake.
2014-08-04 15:29:20,739 Server[2181] TRACE com.relayrides.pushy.apns.PushManager  - Connection succeeded: ApnsConnection [name=ApnsConnection-13]
2014-08-04 15:29:20,739 Server[2181] TRACE com.relayrides.pushy.apns.ApnsConnection  - ApnsConnection-13 sending SendableApnsPushNotification [sequenceNumber=0, token=<omitted>, payload=<omitted>, deliveryInvalidation=292278994-08-17 07:12:55 Etc/GMT]
2014-08-04 15:29:20,740 Server[2181] TRACE com.relayrides.pushy.apns.ApnsConnection  - ApnsConnection-13 successfully wrote notification 0
2014-08-04 15:29:20,740 Server[2181] TRACE com.relayrides.pushy.apns.ApnsConnection  - ApnsConnection-13 sending SendableApnsPushNotification [sequenceNumber=1, token=<omitted>, payload=<omitted>, deliveryInvalidation=292278994-08-17 07:12:55 Etc/GMT]
2014-08-04 15:29:20,740 Server[2181] TRACE com.relayrides.pushy.apns.ApnsConnection  - ApnsConnection-13 successfully wrote notification 1

I'll try if the current master branch is working better, but this issue actually seems to come up quite often after a few thousand messages (current logfile for example after 12 reconnects). Maybe this does help for now. About the environment: this is a linux machine running a WebObjects application combined with Akka Actors and Pushy.

Greetings
Dennis

Edit: on a previous own-code-implementation of push notifications we encountered somewhat similar issues, where connections would hang up to 15 minutes waiting for a timeout. In those cases the TCP send buffer seemed to be full and no timeout mechanism was in use for TCP sending.

Edit^2: While the newest dev version did not help, it seems that I could reduce the impact by introducing a WriteTimeoutHandler into the handler chain (although more of a quickfix right now).

@jchambers
Copy link
Owner

By all appearances, this is another case of having no way of knowing if a connection is alive or not. We have changes in the works (a write timeout being one of them) that will mitigate the situation, but won't actually introduce any new delivery guarantees. I'm afraid this is an inherent design issue with the APNs protocol.

I'll leave this open until we've actually implemented those changes.

@jchambers jchambers added this to the v0.4 milestone Sep 6, 2014
@jchambers
Copy link
Owner

This should be fixed (as much as it can be, at least) by the combination of #116, #117, and #118.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
v0.4
Development

No branches or pull requests
3 participants
@jchambers @steve-taylor @dbliefernicht