search

jchambers / pushy

A Java library for sending APNs (iOS/macOS/Safari) push notifications
https://pushy-apns.org/
MIT License
1.81k stars 451 forks source link

TooManyProviderTokenUpdates issue on v0.15.1 #931

Closed gchen888 closed 2 years ago

gchen888 commented 2 years ago

Currently we use pushy v0.15.1 for our APNS push notification in a enterprise application and receive "TooManyProviderTokenUpdates" sporadically when sent a push notification to apns using .p8 file.

Below is the code to instance the ApnsClient

    private synchronized void activateApnsClient(final ConfigData activeConfigData) throws SSLException {
        if (activeConfigData != loadedConfigData) {
            closeApnsClient();
            loadedConfigData = activeConfigData;
            apnsClient = new ApnsClientBuilder()
                    .setApnsServer(activeConfigData.getApnsHostName(), activeConfigData.getApnsServerport())
                    .setSigningKey(activeConfigData.getApnsSigningKey())
                    .setConnectionTimeout(Duration.ofSeconds(activeConfigData.getApnsConnectionTimeout(), 0))
                    .setTrustedServerCertificateChain(activeConfigData.getTrustedServerCertFile())
                    .build();
        }
    }

where ApnsClientBuilder.PRODUCTION_APNS_HOST and 2197 are used as Hostname and port for ApnsServer. Connection timeout is set to 5sec.

The ApnsClient will be closed and reinstantiated, when the configuration data are changed, what but seldom happens.

In our application the above code and pushy v0.14.2 are used untill 23. nov. 2021without any problem. On 24. nov. 2021 we upgraded pushy to v0.15.1using netty 4.1.69 (see #922 ). Since that time we get the response with "TooManyProviderTokenUpdates" sometimes.

Any reply is appreciated. Thanks very much.

jchambers commented 2 years ago

Could you please turn on debug-level logging for AuthenticationTokenProvider and share what appears in your logs? That will help us understand how and when Pushy is generating new tokens in your case.

In particular, we're looking for output from this line: https://github.com/jchambers/pushy/blob/9ca2560ea2dc6ab393db4f3e9cdadb890ab306d8/pushy/src/main/java/com/eatthepath/pushy/apns/auth/AuthenticationTokenProvider.java#L84

kicktipp commented 2 years ago

I added a log config to get the logging you asked for. Stay tuned for this.

As far as I can tell, the reason might be our clustered configuration. We run 20+ application server, each is sending apns notifications with the same authentication token. The error message on one server might be caused by an authentication token update of another server inside the cluster.

The documentation does not say anything about this, see here "Refresh Your Token Regularly" https://developer.apple.com/documentation/usernotifications/setting_up_a_remote_notification_server/establishing_a_token-based_connection_to_apns

But other people are asking this question, too: https://developer.apple.com/forums/thread/675879

kicktipp commented 2 years ago

It seems to be a wrong configuration on my side. I had two ApnsClients: one for production APNS and one for Sandbox APNS. I had both in production as some external developer needed the sandbox APNS for their development.

Therefor I had the log line always twice in a given second:

2022-01-11 11:31:08.567 DEBUG 2087054 --- [nioEventLoopGroup-2-1] c.e.p.a.a.AuthenticationTokenProvider    : Refreshed authentication token
2022-01-11 11:31:08.666 DEBUG 2087054 --- [nioEventLoopGroup-3-1] c.e.p.a.a.AuthenticationTokenProvider    : Refreshed authentication token
2022-01-11 12:21:08.555 DEBUG 2087054 --- [nioEventLoopGroup-2-1] c.e.p.a.a.AuthenticationTokenProvider    : Refreshed authentication token
2022-01-11 12:21:08.665 DEBUG 2087054 --- [nioEventLoopGroup-3-1] c.e.p.a.a.AuthenticationTokenProvider    : Refreshed authentication token
2022-01-11 13:11:08.594 DEBUG 2087054 --- [nioEventLoopGroup-2-1] c.e.p.a.a.AuthenticationTokenProvider    : Refreshed authentication token
2022-01-11 13:11:08.608 DEBUG 2087054 --- [nioEventLoopGroup-3-1] c.e.p.a.a.AuthenticationTokenProvider    : Refreshed authentication token
2022-01-11 14:01:08.563 DEBUG 2087054 --- [nioEventLoopGroup-2-1] c.e.p.a.a.AuthenticationTokenProvider    : Refreshed authentication token
2022-01-11 14:01:08.679 DEBUG 2087054 --- [nioEventLoopGroup-3-1] c.e.p.a.a.AuthenticationTokenProvider    : Refreshed authentication token

Both ApnsClients are injected into another bean (Spring boot). To me it looks like the production ApnsClient was created first, so usually it was refreshed first, too. But if for some reason the sandbox client was refreshed first and the production client only a few seconds later, the production apns connection failed. Both used the same authorization token (p8)

I removed the sandbox ApnsClient and now everything looks fine. I will report here if it didn't fix the problem.

jchambers commented 2 years ago

Okay; thanks for adding the logging and thanks for following up! We'll look forward to hearing back from you soon.

kicktipp commented 2 years ago

Only one of our servers had problems sending messages tonight:

For me it looks like the refresh process of the token at 03:48:36 failed already. Each message afterwards failed until the 50 minute timeout refreshed the token again.

How can I do some more logging to help you? 

2022-01-18 03:49:02.145 ERROR Notification rejected by the APNs gateway: TooManyProviderTokenUpdates
2022-01-18 04:01:35.969 ERROR Notification rejected by the APNs gateway: TooManyProviderTokenUpdates
2022-01-18 04:01:40.757 ERROR Notification rejected by the APNs gateway: TooManyProviderTokenUpdates
2022-01-18 04:20:18.605 ERROR Notification rejected by the APNs gateway: TooManyProviderTokenUpdates
2022-01-18 04:20:18.758 ERROR Notification rejected by the APNs gateway: TooManyProviderTokenUpdates
2022-01-18 04:20:32.627 ERROR Notification rejected by the APNs gateway: TooManyProviderTokenUpdates
2022-01-18 04:20:32.780 ERROR Notification rejected by the APNs gateway: TooManyProviderTokenUpdates
2022-01-18 04:20:32.933 ERROR Notification rejected by the APNs gateway: TooManyProviderTokenUpdates
2022-01-18 04:32:16.518 ERROR Notification rejected by the APNs gateway: TooManyProviderTokenUpdates
2022-01-18 04:33:01.194 ERROR Notification rejected by the APNs gateway: TooManyProviderTokenUpdates

The token was updated every 50 minutes

2022-01-18 00:28:36.304 DEBUG 383795 --- [nioEventLoopGroup-2-1] c.e.p.a.a.AuthenticationTokenProvider    : Refreshed authentication token
2022-01-18 01:18:36.356 DEBUG 383795 --- [nioEventLoopGroup-2-1] c.e.p.a.a.AuthenticationTokenProvider    : Refreshed authentication token
2022-01-18 02:08:36.309 DEBUG 383795 --- [nioEventLoopGroup-2-1] c.e.p.a.a.AuthenticationTokenProvider    : Refreshed authentication token
2022-01-18 02:58:36.305 DEBUG 383795 --- [nioEventLoopGroup-2-1] c.e.p.a.a.AuthenticationTokenProvider    : Refreshed authentication token
2022-01-18 03:48:36.333 DEBUG 383795 --- [nioEventLoopGroup-2-1] c.e.p.a.a.AuthenticationTokenProvider    : Refreshed authentication token
2022-01-18 04:38:36.333 DEBUG 383795 --- [nioEventLoopGroup-2-1] c.e.p.a.a.AuthenticationTokenProvider    : Refreshed authentication token
2022-01-18 05:28:36.358 DEBUG 383795 --- [nioEventLoopGroup-2-1] c.e.p.a.a.AuthenticationTokenProvider    : Refreshed authentication token
2022-01-18 06:18:36.324 DEBUG 383795 --- [nioEventLoopGroup-2-1] c.e.p.a.a.AuthenticationTokenProvider    : Refreshed authentication token
2022-01-18 07:08:36.300 DEBUG 383795 --- [nioEventLoopGroup-2-1] c.e.p.a.a.AuthenticationTokenProvider    : Refreshed authentication token
2022-01-18 07:58:36.317 DEBUG 383795 --- [nioEventLoopGroup-2-1] c.e.p.a.a.AuthenticationTokenProvider    : Refreshed authentication token
2022-01-18 08:48:36.306 DEBUG 383795 --- [nioEventLoopGroup-2-1] c.e.p.a.a.AuthenticationTokenProvider    : Refreshed authentication token
2022-01-18 09:38:36.299 DEBUG 383795 --- [nioEventLoopGroup-2-1] c.e.p.a.a.AuthenticationTokenProvider    : Refreshed authentication token
2022-01-18 10:28:36.305 DEBUG 383795 --- [nioEventLoopGroup-2-1] c.e.p.a.a.AuthenticationTokenProvider    : Refreshed authentication token
2022-01-18 11:18:36.345 DEBUG 383795 --- [nioEventLoopGroup-2-1] c.e.p.a.a.AuthenticationTokenProvider    : Refreshed authentication token

and here is our log about sending messages:

2022-01-18 02:55:30.065  INFO: Start ApnsMessageSenderJob
2022-01-18 02:55:30.066  WARN: APNS Versand von 1 Nachricht(en)
2022-01-18 02:55:30.066  INFO: Ende ApnsMessageSenderJob
2022-01-18 02:55:30.217  WARN: APNS ID 533710277 ACK 
2022-01-18 03:44:01.707  INFO: Start ApnsMessageSenderJob
2022-01-18 03:44:01.708  WARN: APNS Versand von 1 Nachricht(en)
2022-01-18 03:44:01.708  INFO: Ende ApnsMessageSenderJob
2022-01-18 03:44:01.861  WARN: APNS ID 533710532 ACK 

2022-01-18 03:49:01.989  INFO: Start ApnsMessageSenderJob
2022-01-18 03:49:01.990  WARN: APNS Versand von 1 Nachricht(en)
2022-01-18 03:49:01.990  INFO: Ende ApnsMessageSenderJob
2022-01-18 03:49:02.145 ERROR: Notification rejected by the APNs gateway: TooManyProviderTokenUpdates 

2022-01-18 04:01:35.812  INFO: Start ApnsMessageSenderJob
2022-01-18 04:01:35.813  WARN: APNS Versand von 1 Nachricht(en)
2022-01-18 04:01:35.813  INFO: Ende ApnsMessageSenderJob
2022-01-18 04:01:35.969 ERROR: Notification rejected by the APNs gateway: TooManyProviderTokenUpdates 

2022-01-18 04:01:40.601  INFO: Start ApnsMessageSenderJob
2022-01-18 04:01:40.601  WARN: APNS Versand von 1 Nachricht(en)
2022-01-18 04:01:40.602  INFO: Ende ApnsMessageSenderJob
2022-01-18 04:01:40.757 ERROR: Notification rejected by the APNs gateway: TooManyProviderTokenUpdates 

2022-01-18 04:20:18.451  INFO: Start ApnsMessageSenderJob
2022-01-18 04:20:18.452  WARN: APNS Versand von 1 Nachricht(en)
2022-01-18 04:20:18.452  INFO: Ende ApnsMessageSenderJob
2022-01-18 04:20:18.453  INFO: Start ApnsMessageSenderJob
2022-01-18 04:20:18.453  WARN: APNS Versand von 1 Nachricht(en)
2022-01-18 04:20:18.453  INFO: Ende ApnsMessageSenderJob
2022-01-18 04:20:18.605 ERROR: Notification rejected by the APNs gateway: TooManyProviderTokenUpdates 
2022-01-18 04:20:18.758 ERROR: Notification rejected by the APNs gateway: TooManyProviderTokenUpdates 
2022-01-18 04:20:32.473  INFO: Start ApnsMessageSenderJob
2022-01-18 04:20:32.474  WARN: APNS Versand von 2 Nachricht(en)
2022-01-18 04:20:32.474  INFO: Ende ApnsMessageSenderJob
2022-01-18 04:20:32.474  INFO: Start ApnsMessageSenderJob
2022-01-18 04:20:32.475  WARN: APNS Versand von 1 Nachricht(en)
2022-01-18 04:20:32.475  INFO: Ende ApnsMessageSenderJob
2022-01-18 04:20:32.627 ERROR: Notification rejected by the APNs gateway: TooManyProviderTokenUpdates 
2022-01-18 04:20:32.780 ERROR: Notification rejected by the APNs gateway: TooManyProviderTokenUpdates 
2022-01-18 04:20:32.933 ERROR: Notification rejected by the APNs gateway: TooManyProviderTokenUpdates 

2022-01-18 04:32:16.353  INFO: Start ApnsMessageSenderJob
2022-01-18 04:32:16.354  WARN: APNS Versand von 1 Nachricht(en)
2022-01-18 04:32:16.354  INFO: Ende ApnsMessageSenderJob
2022-01-18 04:32:16.518 ERROR: Notification rejected by the APNs gateway: TooManyProviderTokenUpdates 
2022-01-18 04:33:01.040  INFO: Start ApnsMessageSenderJob
2022-01-18 04:33:01.041  WARN: APNS Versand von 1 Nachricht(en)
2022-01-18 04:33:01.041  INFO: Ende ApnsMessageSenderJob
2022-01-18 04:33:01.194 ERROR: Notification rejected by the APNs gateway: TooManyProviderTokenUpdates 
2022-01-18 04:40:49.406  INFO: Start ApnsMessageSenderJob
2022-01-18 04:40:49.406  WARN: APNS Versand von 1 Nachricht(en)
2022-01-18 04:40:49.407  INFO: Ende ApnsMessageSenderJob
2022-01-18 04:40:49.563  WARN: APNS ID 533711516 ACK 
2022-01-18 04:43:58.195  INFO: Start ApnsMessageSenderJob
2022-01-18 04:43:58.196  WARN: APNS Versand von 2 Nachricht(en)
2022-01-18 04:43:58.197  INFO: Ende ApnsMessageSenderJob
2022-01-18 04:43:58.350  WARN: APNS ID 533711523 ACK 
2022-01-18 04:43:58.350  WARN: APNS ID 533711522 ACK
kicktipp commented 2 years ago

If I do not misunderstood the code completely I might give you a hint to fix it:

What happens:

  1. At 02:58 the AuthenticationTokenProvider refreshes the token. Let's name it "TokenA"
  2. No message is sent until 03:44
  3. At 03:44 a message is sent with "TokenA"
  4. APNS-Backend sees "TokenA" for the first time and remembers the timestamp 03:44
  5. At 03:48 the AuthenticationTokenProvider refreshes "TokenA" as 50 minutes have passed since 02:58. Let's name it "TokenB".
  6. At 03:49 a message is sent with "TokenB".
  7. APNS-Backend sees the new TokenB at 03:49
  8. APNS-Backend remeberes TokenA was first seen at 03:44. Only 5 minutes have passed since the token was refreshed according to the backend
  9. APNS-Backend sends TooManyProviderTokenUpdates

How to fix it: I think you need to save the time the token was first used. I tried some naive implementation:

mypatch.txt

jchambers commented 2 years ago

@kicktipp Oof—I think you're right. That makes a lot of sense. Let me think on the implementation a bit, but it certainly seems worth a try!

kicktipp commented 2 years ago

I am glad to help. BTW: Can I donate this project?

jchambers commented 2 years ago

Can I donate this project?

I think you just did, friend ;)

To answer more directly, I'm not currently accepting monetary donations, but sincerely appreciate the gesture all the same.

jchambers commented 2 years ago

Hm. Now that I'm looking at this more closely, the proposed change would take us back to exactly the implementation we had in 0.14.2: https://github.com/jchambers/pushy/blob/0bd0752e901a1724846b1feba8287e4fa2feb912/pushy/src/main/java/com/eatthepath/pushy/apns/TokenAuthenticationApnsClientHandler.java#L102-L126

…and folks certainly complained about TooManyProviderTokenUpdates responses with that release, too. I'll have to think on this a bit more.

kicktipp commented 2 years ago

I greped through older logs for another failure with 0.15. This is a complete log. So we have no messages for example between 02:20 and 04:49: 

2021-12-13 02:20:29.101  WARN 2711790 --- [nioEventLoopGroup-2-1] d.k.core.push.apns.ApnsResponseListener  : APNS ID 521790465 ACK 
2021-12-13 04:49:05.146  WARN 2711790 --- [nioEventLoopGroup-2-1] d.k.core.push.apns.ApnsResponseListener  : APNS ID 521793369 ACK 
2021-12-13 04:49:20.690  WARN 2711790 --- [nioEventLoopGroup-2-1] d.k.core.push.apns.ApnsResponseListener  : APNS ID 521793371 ACK 
2021-12-13 04:49:37.215  WARN 2711790 --- [nioEventLoopGroup-2-1] d.k.core.push.apns.ApnsResponseListener  : APNS ID 521793372 ACK 
2021-12-13 04:49:52.926  WARN 2711790 --- [nioEventLoopGroup-2-1] d.k.core.push.apns.ApnsResponseListener  : APNS ID 521793373 ACK 
2021-12-13 04:50:07.255  WARN 2711790 --- [nioEventLoopGroup-2-1] d.k.core.push.apns.ApnsResponseListener  : APNS ID 521793374 ACK 
2021-12-13 04:50:29.415 ERROR 2711790 --- [nioEventLoopGroup-2-1] d.k.core.push.apns.ApnsResponseListener  : Notification rejected by the APNs gateway: TooManyProviderTokenUpdates 
2021-12-13 04:50:46.096 ERROR 2711790 --- [nioEventLoopGroup-2-1] d.k.core.push.apns.ApnsResponseListener  : Notification rejected by the APNs gateway: TooManyProviderTokenUpdates 
2021-12-13 04:51:00.624 ERROR 2711790 --- [nioEventLoopGroup-2-1] d.k.core.push.apns.ApnsResponseListener  : Notification rejected by the APNs gateway: TooManyProviderTokenUpdates 
2021-12-13 04:51:13.271 ERROR 2711790 --- [nioEventLoopGroup-2-1] d.k.core.push.apns.ApnsResponseListener  : Notification rejected by the APNs gateway: TooManyProviderTokenUpdates 
2021-12-13 04:51:37.289 ERROR 2711790 --- [nioEventLoopGroup-2-1] d.k.core.push.apns.ApnsResponseListener  : Notification rejected by the APNs gateway: TooManyProviderTokenUpdates 
2021-12-13 04:52:42.379 ERROR 2711790 --- [nioEventLoopGroup-2-1] d.k.core.push.apns.ApnsResponseListener  : Notification rejected by the APNs gateway: TooManyProviderTokenUpdates 
2021-12-13 04:52:56.081 ERROR 2711790 --- [nioEventLoopGroup-2-1] d.k.core.push.apns.ApnsResponseListener  : Notification rejected by the APNs gateway: TooManyProviderTokenUpdates 
2021-12-13 04:57:34.003 ERROR 2711790 --- [nioEventLoopGroup-2-1] d.k.core.push.apns.ApnsResponseListener  : Notification rejected by the APNs gateway: TooManyProviderTokenUpdates 
2021-12-13 05:26:09.985 ERROR 2711790 --- [nioEventLoopGroup-2-1] d.k.core.push.apns.ApnsResponseListener  : Notification rejected by the APNs gateway: TooManyProviderTokenUpdates 
2021-12-13 05:26:56.014 ERROR 2711790 --- [nioEventLoopGroup-2-1] d.k.core.push.apns.ApnsResponseListener  : Notification rejected by the APNs gateway: TooManyProviderTokenUpdates 
2021-12-13 05:26:56.166 ERROR 2711790 --- [nioEventLoopGroup-2-1] d.k.core.push.apns.ApnsResponseListener  : Notification rejected by the APNs gateway: TooManyProviderTokenUpdates 
2021-12-13 05:26:56.318 ERROR 2711790 --- [nioEventLoopGroup-2-1] d.k.core.push.apns.ApnsResponseListener  : Notification rejected by the APNs gateway: TooManyProviderTokenUpdates 
2021-12-13 05:26:56.471 ERROR 2711790 --- [nioEventLoopGroup-2-1] d.k.core.push.apns.ApnsResponseListener  : Notification rejected by the APNs gateway: TooManyProviderTokenUpdates 
2021-12-13 05:26:56.623 ERROR 2711790 --- [nioEventLoopGroup-2-1] d.k.core.push.apns.ApnsResponseListener  : Notification rejected by the APNs gateway: TooManyProviderTokenUpdates 
2021-12-13 05:26:56.775 ERROR 2711790 --- [nioEventLoopGroup-2-1] d.k.core.push.apns.ApnsResponseListener  : Notification rejected by the APNs gateway: TooManyProviderTokenUpdates 
2021-12-13 05:26:56.927 ERROR 2711790 --- [nioEventLoopGroup-2-1] d.k.core.push.apns.ApnsResponseListener  : Notification rejected by the APNs gateway: TooManyProviderTokenUpdates 
2021-12-13 05:26:57.080 ERROR 2711790 --- [nioEventLoopGroup-2-1] d.k.core.push.apns.ApnsResponseListener  : Notification rejected by the APNs gateway: TooManyProviderTokenUpdates 
2021-12-13 05:26:57.232 ERROR 2711790 --- [nioEventLoopGroup-2-1] d.k.core.push.apns.ApnsResponseListener  : Notification rejected by the APNs gateway: TooManyProviderTokenUpdates 
2021-12-13 05:26:57.384 ERROR 2711790 --- [nioEventLoopGroup-2-1] d.k.core.push.apns.ApnsResponseListener  : Notification rejected by the APNs gateway: TooManyProviderTokenUpdates 
2021-12-13 05:28:01.789 ERROR 2711790 --- [nioEventLoopGroup-2-1] d.k.core.push.apns.ApnsResponseListener  : Notification rejected by the APNs gateway: TooManyProviderTokenUpdates 
2021-12-13 05:28:01.941 ERROR 2711790 --- [nioEventLoopGroup-2-1] d.k.core.push.apns.ApnsResponseListener  : Notification rejected by the APNs gateway: TooManyProviderTokenUpdates 
2021-12-13 05:42:54.426  WARN 2711790 --- [nioEventLoopGroup-2-1] d.k.core.push.apns.ApnsResponseListener  : APNS ID 521793555 ACK

I do not have logs for refreshing the token as it is a log from the past. But imaging this flow:

04:00:10 Token refreshed: T1 04:49:05 T1 first usage: OK ... some more messages which are OK 04:50:07 T1 last usage: OK 04:50:10 Token refreshed: T2 04:50:29 T2 first usage. APNS sees only first usage of T1 at 04:49 and T2 at 04:50 - refreshed after 1 Minute = NOT OK ... some more messages which are not OK 05:40:10 Token refreshed: T3 05:42:54 T3 first usage: OK

I don't know what happened in 0.14.2 (or 0.14.1) which most bug reports are talking about) but it seems to me a threading issue in 0.14.1. I checked out the code and couldn't find any flaw. But most people reporting multiple threads sending messages. So this might be a different issue.

We experience these issues only at night when we have sometimes no messages as all users are sleeping (or not using our app).

So at least I think the implementation changed from refreshing the token 50 minutes after first use to 50 minutes after creation.

kicktipp commented 2 years ago

One more:

2021-12-25 06:03:31.624  WARN 711640 --- [nioEventLoopGroup-2-1] d.k.core.push.apns.ApnsResponseListener  : APNS ID 527466360 ACK 
2021-12-25 06:12:37.579  WARN 711640 --- [nioEventLoopGroup-2-1] d.k.core.push.apns.ApnsResponseListener  : APNS ID 527466366 ACK 
2021-12-25 07:08:06.871  WARN 711640 --- [nioEventLoopGroup-2-1] d.k.core.push.apns.ApnsResponseListener  : APNS ID 527466543 ACK 
2021-12-25 07:12:02.973 ERROR 711640 --- [nioEventLoopGroup-2-1] d.k.core.push.apns.ApnsResponseListener  : Notification rejected by the APNs gateway: TooManyProviderTokenUpdates 
2021-12-25 07:12:02.973 ERROR 711640 --- [nioEventLoopGroup-2-1] d.k.core.push.apns.ApnsResponseListener  : Notification rejected by the APNs gateway: TooManyProviderTokenUpdates 
2021-12-25 07:21:39.796 ERROR 711640 --- [nioEventLoopGroup-2-1] d.k.core.push.apns.ApnsResponseListener  : Notification rejected by the APNs gateway: TooManyProviderTokenUpdates 
2021-12-25 07:30:53.693 ERROR 711640 --- [nioEventLoopGroup-2-1] d.k.core.push.apns.ApnsResponseListener  : Notification rejected by the APNs gateway: TooManyProviderTokenUpdates 
2021-12-25 07:37:05.793 ERROR 711640 --- [nioEventLoopGroup-2-1] d.k.core.push.apns.ApnsResponseListener  : Notification rejected by the APNs gateway: TooManyProviderTokenUpdates 
2021-12-25 07:37:23.096 ERROR 711640 --- [nioEventLoopGroup-2-1] d.k.core.push.apns.ApnsResponseListener  : Notification rejected by the APNs gateway: TooManyProviderTokenUpdates 
2021-12-25 07:37:32.193 ERROR 711640 --- [nioEventLoopGroup-2-1] d.k.core.push.apns.ApnsResponseListener  : Notification rejected by the APNs gateway: TooManyProviderTokenUpdates 
2021-12-25 07:40:58.558 ERROR 711640 --- [nioEventLoopGroup-2-1] d.k.core.push.apns.ApnsResponseListener  : Notification rejected by the APNs gateway: TooManyProviderTokenUpdates 
2021-12-25 07:46:15.075 ERROR 711640 --- [nioEventLoopGroup-2-1] d.k.core.push.apns.ApnsResponseListener  : Notification rejected by the APNs gateway: TooManyProviderTokenUpdates 
2021-12-25 07:53:51.841 ERROR 711640 --- [nioEventLoopGroup-2-1] d.k.core.push.apns.ApnsResponseListener  : Notification rejected by the APNs gateway: TooManyProviderTokenUpdates 
2021-12-25 08:04:59.079  WARN 711640 --- [nioEventLoopGroup-2-1] d.k.core.push.apns.ApnsResponseListener  : APNS ID 527466750 ACK 
2021-12-25 08:05:24.901  WARN 711640 --- [nioEventLoopGroup-2-1] d.k.core.push.apns.ApnsResponseListener  : APNS ID 527466751 ACK

I guess:

06:20:00 token refresh (used at 07:08) 07:10:00 token refresh (used at 07:12 not OK, only 4 minutes later) 08:00:00 token refresh (used at 08:04 OK)

I can offer some help:

  1. I can add more logging
  2. Test some beta software
  3. Try to fix it and send a push request. But as I am not aware of all the stuff with eventLoops and so on, I might not be the best expert to fix it by myself.
  4. Send you some coffee

regards Janning

kicktipp commented 2 years ago

One more case. Again we had the case that in one hour only few messages were sent. The token refreshed at 10:39 was first seen by apns at 11:27. The next token was first used at 11:31, only 4 minutes after the last token was first seen. Which results in TooManyProviderTokenUpdates. 

2022-01-26 10:39:26.341  : Refreshed authentication token
2022-01-26 11:27:53.034 : APNS ID 536832903 ACK 
2022-01-26 11:27:53.035 : APNS ID 536832904 ACK 
2022-01-26 11:27:53.035 : APNS ID 536832905 ACK 
2022-01-26 11:29:26.334  : Refreshed authentication token
2022-01-26 11:31:57.890 Notification rejected by the APNs gateway: TooManyProviderTokenUpdates
2022-01-26 11:31:57.898 Notification rejected by the APNs gateway: TooManyProviderTokenUpdates
2022-01-26 11:31:57.902 Notification rejected by the APNs gateway: TooManyProviderTokenUpdates
2022-01-26 11:31:57.905 Notification rejected by the APNs gateway: TooManyProviderTokenUpdates
2022-01-26 11:36:31.421 Notification rejected by the APNs gateway: TooManyProviderTokenUpdates
2022-01-26 11:36:43.093 Notification rejected by the APNs gateway: TooManyProviderTokenUpdates
2022-01-26 11:36:58.675 Notification rejected by the APNs gateway: TooManyProviderTokenUpdates

If you like, I can try to fix it, use it production and sent you a patch request.

jchambers commented 2 years ago

Please accept my apologies for the delay. I've put together a branch that returns to the one-token-per-channel model; please see #946. If you're in a position to test it out and let me know if that solves the problem, that would be excellent.

I also added some more debug logging around token expiration/generation, so if you can turn on debug-level logging for com.eatthepath.pushy.apns.TokenAuthenticationApnsClientHandler, that would be excellent!

kicktipp commented 2 years ago

No apologies needed at all. My apologies for not helping with coding myself.

I will test it on our production cluster including logging starting in a few hours. I will give you feedback next week.

kicktipp commented 2 years ago

Works fine. We sent about 30.000 messages without any problems. I checked the gaps in the night where we do not send so many messages. The message flow would have produced an error with the last version.

I think you should merge it into master and release this version.

Thanks a lot for fixing it.

Some example log from one of our servers:

2022-02-17 00:01:59.869  : APNS ID 542931126 ACK 
2022-02-17 00:01:59.869  : APNS ID 542931125 ACK 
2022-02-17 00:05:05.621  : APNS ID 542931142 ACK 
2022-02-17 00:05:05.621  : APNS ID 542931143 ACK 
2022-02-17 00:32:48.132  : APNS ID 542931235 ACK 
2022-02-17 00:33:09.447  : APNS ID 542931237 ACK 
2022-02-17 00:41:27.815  : APNS ID 542931253 ACK 
2022-02-17 00:44:54.163 Authentication token for channel [id: 0x3840d420, L:/195.201.11.78:56078 - R:api.push.apple.com/17.188.128.37:443] has expired
2022-02-17 00:55:03.455 Generated a new authentication token for channel [id: 0x3840d420, L:/195.201.11.78:56078 - R:api.push.apple.com/17.188.128.37:443]
2022-02-17 00:55:03.600  : APNS ID 542931286 ACK 
2022-02-17 00:55:03.600  : APNS ID 542931287 ACK 
2022-02-17 01:06:15.633  : APNS ID 542931565 ACK 
2022-02-17 01:31:17.609  : APNS ID 542931584 ACK 
2022-02-17 01:31:17.609  : APNS ID 542931585 ACK
2022-02-17 01:43:47.431  : APNS ID 542932046 ACK 
2022-02-17 01:43:47.431  : APNS ID 542932045 ACK 
2022-02-17 01:43:58.544  : APNS ID 542932047 ACK 
2022-02-17 01:43:58.544  : APNS ID 542932048 ACK 
2022-02-17 01:45:03.462 Authentication token for channel [id: 0x3840d420, L:/195.201.11.78:56078 - R:api.push.apple.com/17.188.128.37:443] has expired
2022-02-17 02:11:08.935 Generated a new authentication token for channel [id: 0x3840d420, L:/195.201.11.78:56078 - R:api.push.apple.com/17.188.128.37:443]
2022-02-17 02:11:09.081  : APNS ID 542932569 ACK 
2022-02-17 03:01:08.988 Authentication token for channel [id: 0x3840d420, L:/195.201.11.78:56078 - R:api.push.apple.com/17.188.128.37:443] has expired
2022-02-17 04:05:56.046 Generated a new authentication token for channel [id: 0x3840d420, L:/195.201.11.78:56078 - R:api.push.apple.com/17.188.128.37:443]
2022-02-17 04:05:56.192  : APNS ID 542933999 ACK 
2022-02-17 04:05:56.192  : APNS ID 542934000 ACK 
2022-02-17 04:55:56.102 Authentication token for channel [id: 0x3840d420, L:/195.201.11.78:56078 - R:api.push.apple.com/17.188.128.37:443] has expired
2022-02-17 05:05:47.541 Generated a new authentication token for channel [id: 0x3840d420, L:/195.201.11.78:56078 - R:api.push.apple.com/17.188.128.37:443]
2022-02-17 05:05:47.687  : APNS ID 542934568 ACK 
2022-02-17 05:05:47.687  : APNS ID 542934569 ACK 
2022-02-17 05:14:49.035  : APNS ID 542934635 ACK 
2022-02-17 05:14:49.037  : APNS ID 542934637 ACK 
2022-02-17 05:14:49.037  : APNS ID 542934638 ACK 
2022-02-17 05:14:49.037  : APNS ID 542934639 ACK 
2022-02-17 05:14:49.039  : APNS ID 542934640 ACK 
2022-02-17 05:14:49.040  : APNS ID 542934636 ACK 
2022-02-17 05:14:49.040  : APNS ID 542934641 ACK 
2022-02-17 05:38:27.095  : APNS ID 542934712 ACK 
2022-02-17 05:55:47.562 Authentication token for channel [id: 0x3840d420, L:/195.201.11.78:56078 - R:api.push.apple.com/17.188.128.37:443] has expired
2022-02-17 05:57:30.549 Generated a new authentication token for channel [id: 0x3840d420, L:/195.201.11.78:56078 - R:api.push.apple.com/17.188.128.37:443]
2022-02-17 05:57:30.701  : APNS ID 542934762 ACK 
2022-02-17 05:57:30.701  : APNS ID 542934763 ACK 
2022-02-17 05:57:30.701  : APNS ID 542934764 ACK 
2022-02-17 05:57:30.701  : APNS ID 542934765 ACK 
2022-02-17 05:57:30.701  : APNS ID 542934766 ACK 
2022-02-17 05:57:30.701  : APNS ID 542934767 ACK 
2022-02-17 05:57:30.701  : APNS ID 542934768 ACK 
2022-02-17 05:57:30.701  : APNS ID 542934769 ACK 
2022-02-17 05:57:30.701  : APNS ID 542934771 ACK 
2022-02-17 05:57:30.701  : APNS ID 542934772 ACK
flozano commented 2 years ago

about this - as you are going back to previous model, is 0.15.1 not recommended for general usage ?

jchambers commented 2 years ago

…is 0.15.1 not recommended for general usage ?

I don't mean to split hairs, but to be clear, 0.15.1 will be a future release where we're considering the changes in #946, which will stop sharing tokens between channels. I think you mean 0.15.0, which does share tokens between channels and is affected by the issue here.

That said, I think "not recommended for general usage" may be a little extreme. Users should evaluate the problem and their own situation (do you use multiple concurrent connections for the same topic? do network conditions cause those channels to close/open frequently?) and make a judgment for themselves.

Many users have been using 0.15.0 without significant issue; it's folks with choppy network connections that are most likely to be affected. And, as discussed in #946, I do plan to put out a release whenever I can get a few uninterrupted hours to get everything together.