The unregistering of push tokens is synchronously blocking the prosody process, causing the server to stall. This happens from time to time, and the delay depends on the server load on Google servers, apparently. This is just from today's log:
Jul 02 07:07:20 mod_log_slow_events warn Slow event 'unregister-push-token' took 32.18s: no recognised data
Jul 02 07:07:27 mod_log_slow_events warn Slow event 'unregister-push-token' took 1.42s: no recognised data
Jul 02 08:08:17 mod_log_slow_events warn Slow event 'unregister-push-token' took 10.37s: no recognised data
Jul 02 08:39:09 mod_log_slow_events warn Slow event 'unregister-push-token' took 2.69s: no recognised data
Jul 02 09:07:38 mod_log_slow_events warn Slow event 'unregister-push-token' took 2.37s: no recognised data
Jul 02 10:43:55 mod_log_slow_events warn Slow event 'unregister-push-token' took 2.79s: no recognised data
Jul 02 12:17:47 mod_log_slow_events warn Slow event 'unregister-push-token' took 3.22s: no recognised data
Jul 02 14:59:06 mod_log_slow_events warn Slow event 'unregister-push-token' took 36.41s: no recognised data
Here is a single event that failed, look at the time gap after "Unregistering failing FCM token":
Jul 02 14:58:29 push.yax.im:push_appserver_fcm warn FCM returned 1 failures:
Jul 02 14:58:29 push.yax.im:push_appserver_fcm warn Got FCM error: 'NotRegistered'
Jul 02 14:58:29 push.yax.im:push_appserver_fcm debug Adding unregister-push-token to prosody event queue...
Jul 02 14:58:29 push.yax.im:push_appserver warn Push handler for type 'fcm' not executed successfully: NotRegistered
Jul 02 14:58:29 yax.im:cloud_notify debug Got error of type 'wait' (internal-server-error) for identifier 'push.yax.im<*********': NOT increasing error count for this identifier
Jul 02 14:58:29 push.yax.im:push_appserver_fcm warn Unregistering failing FCM token *************
<!-- server stalls for 36 seconds -->
Jul 02 14:59:06 datamanager debug Removing empty push_appserver datastore for user *****@push.yax.im
Jul 02 14:59:06 push.yax.im:push_appserver info Unregistered push device, returning: 'OK', '*****', '******************************'
Jul 02 14:59:06 push.yax.im:push_appserver debug settings were: {
last_successful_push = "2020-07-02T03:56:02Z",
type = "fcm",
secret = "************************",
last_push_error = "2020-07-02T12:58:29Z",
renewed = "2020-07-02T03:39:27Z",
token = "*************************************************",
registered = "2020-07-01T13:59:27Z",
node = "********"
}
Jul 02 14:59:06 mod_log_slow_events warn Slow event 'unregister-push-token' took 36.41s: no recognised data