I'm seeing this in the the logs of a receiving fennec after sending it a tab: 09-02 16:55:04.680 22945-23918/? D/GeckoPushGCM: Message received. Processing on background thread. 09-02 16:55:04.681 22945-23242/? I/GeckoPushService: Google Play Services GCM message received; delivering. 09-02 16:55:04.681 22945-23242/? W/GeckoPushService: Cannot find registration corresponding to subscription for chid: 37b9ef40-8936-4923-892b-e6cb27f05936; ignoring message.

09-06 13:17:02.873 24355-24376/org.mozilla.fennec_grisha D/GeckoPushGCM: Message received. Processing on background thread. 09-06 13:17:02.878 24355-24368/org.mozilla.fennec_grisha I/GeckoPushService: Google Play Services GCM message received; delivering. 09-06 13:17:02.878 24355-24368/org.mozilla.fennec_grisha I/GeckoPushService: Message directed to service: fxa 09-06 13:17:02.878 24355-24368/org.mozilla.fennec_grisha D/Telemetry: SendUIEvent: event = action.1 method = service timestamp = 265763557 extras = dom-push-api 09-06 13:17:02.879 24355-24368/org.mozilla.fennec_grisha I/GeckoPushService: Delivering dom/push message to decode to Gecko! 09-06 13:17:02.880 24355-24373/org.mozilla.fennec_grisha I/GeckoFxAccountsPush: FxAccountsPush _decodePushMessage

Note the timestamps, a minute difference between `GeckoFxAccountsPush: FxAccountsPush _decodePushMessage` and `GeckoPushService: Handling event: FxAccountsPush:ReceivedPushMessageToDecode:Response` 09-06 14:18:05.466 24355-24535/org.mozilla.fennec_grisha D/GeckoPushGCM: Message received. Processing on background thread. 09-06 14:18:05.467 24355-24368/org.mozilla.fennec_grisha I/GeckoPushService: Google Play Services GCM message received; delivering. 09-06 14:18:05.467 24355-24368/org.mozilla.fennec_grisha I/GeckoPushService: Message directed to service: fxa 09-06 14:18:05.467 24355-24368/org.mozilla.fennec_grisha D/Telemetry: SendUIEvent: event = action.1 method = service timestamp = 269426553 extras = dom-push-api 09-06 14:18:05.468 24355-24368/org.mozilla.fennec_grisha I/GeckoPushService: Delivering dom/push message to decode to Gecko! 09-06 14:18:05.469 24355-24373/org.mozilla.fennec_grisha I/GeckoFxAccountsPush: FxAccountsPush _decodePushMessage 09-06 14:19:04.475 24355-24368/org.mozilla.fennec_grisha I/GeckoPushService: Handling event: FxAccountsPush:ReceivedPushMessageToDecode:Response 09-06 14:19:04.475 24355-24368/org.mozilla.fennec_grisha I/FxAccountPush: Handling FxA Push Message 09-06 14:19:04.477 24355-24368/org.mozilla.fennec_grisha I/GeckoLogger: fennec_grisha :: FirefoxAccounts :: Requesting sync.

In the previous logs, after Gecko was notified of a new message to decode, the results will make their way back to Java land in maybe 20-60 seconds. What I'm observing now is that a call to `nativeNotifyObservers` is a dead end, and nothing makes its way back up to Java at all. It's unclear of messages make their way to FxAccountsPush observer for decoding, since WebIDE keeps crashing on me :-(

After re-installing, everything is back to normal - messages passed through nativeNotifyObservers are promptly handled by FxPushObserver, and we get decoded messages posted back to Java in about 0.5-5 seconds, but sometimes that wait is much longer (I've seen PushCrypto take up to 60s, timing observed after a few attempts). Jim, perhaps you can point me in a right direction - what could account for: 1) Message sent via `GeckoAppShell.notifyObservers` (FxAccountsPush:ReceivedPushMessageToDecode) not making it at all to the observer which is listening for it (FxAccountsPush). and perhaps: 2) call to _decodePushMessage in FxAccountsPush (which ends up as a Promise returned from PushCrypto) taking at times up to 60s to resolve (or longer!), but usually resolving in at most 10-15 seconds and most of the time in under 5 seconds? I'm entirely unclear on why (1) could be happening, and don't have a clearly reproducible way to reproduce that state. Coincidentally, it started to happen after I've put some breakpoints via WebIDE in promise handlers, and Fennec crashed upon reaching them. For (2), it seems that there's either some queuing of work going on, or PushCrypto is actually taking an widely variable amount of time to do its thing.

One(In reply to :Grisha Kruglov from comment #4) > After re-installing, everything is back to normal - messages passed through > nativeNotifyObservers are promptly handled by FxPushObserver, and we get > decoded messages posted back to Java in about 0.5-5 seconds, but sometimes > that wait is much longer (I've seen PushCrypto take up to 60s, timing > observed after a few attempts). > > Jim, perhaps you can point me in a right direction - what could account for: > 1) Message sent via `GeckoAppShell.notifyObservers` > (FxAccountsPush:ReceivedPushMessageToDecode) not making it at all to the > observer which is listening for it (FxAccountsPush). One possibility is because the startService call is asynchronous, we could be sending the `FxAccountsPush:ReceivedPushMessageToDecode` message before GeckoService has created the FxAccountsPush component. You would need a flag similar to `PushService.canSendPushMessagesToGecko`. That flag is for PushService.jsm only, so you need a separate flag in PushService.java for FxAccountsPush.js. [1] https://dxr.mozilla.org/mozilla-central/rev/91c2b9d5c1354ca79e5b174591dbb03b32b15bbf/mobile/android/base/java/org/mozilla/gecko/push/PushService.java#92 > and perhaps: > > 2) call to _decodePushMessage in FxAccountsPush (which ends up as a Promise > returned from PushCrypto) taking at times up to 60s to resolve (or longer!), > but usually resolving in at most 10-15 seconds and most of the time in under > 5 seconds? I don't know enough about PushCrypto to say what could be wrong.

(In reply to Jim Chen [:jchen] [:darchons] from comment #5) > One(In reply to :Grisha Kruglov from comment #4) > > After re-installing, everything is back to normal - messages passed through > > nativeNotifyObservers are promptly handled by FxPushObserver, and we get > > decoded messages posted back to Java in about 0.5-5 seconds, but sometimes > > that wait is much longer (I've seen PushCrypto take up to 60s, timing > > observed after a few attempts). > > > > Jim, perhaps you can point me in a right direction - what could account for: > > 1) Message sent via `GeckoAppShell.notifyObservers` > > (FxAccountsPush:ReceivedPushMessageToDecode) not making it at all to the > > observer which is listening for it (FxAccountsPush). > > One possibility is because the startService call is asynchronous, we could > be sending the `FxAccountsPush:ReceivedPushMessageToDecode` message before > GeckoService has created the FxAccountsPush component. You would need a flag > similar to `PushService.canSendPushMessagesToGecko`. That flag is for > PushService.jsm only, so you need a separate flag in PushService.java for > FxAccountsPush.js. > > [1] > https://dxr.mozilla.org/mozilla-central/rev/ > 91c2b9d5c1354ca79e5b174591dbb03b32b15bbf/mobile/android/base/java/org/ > mozilla/gecko/push/PushService.java#92 > Thanks, that certainly seems like one part of the problem. I'm not very familiar with how these components are loaded, but I would expect that once FxAccountsPush component is created, messages will be routed to it. So I would expect to see a few fail perhaps, and then they'll start working; what I'm observing though is that nothing at all gets delivered, however long I wait for - as if, FxAccountsPush is never created at all.

(In reply to :Grisha Kruglov from comment #6) > Thanks, that certainly seems like one part of the problem. I'm not very > familiar with how these components are loaded, but I would expect that once > FxAccountsPush component is created, messages will be routed to it. So I > would expect to see a few fail perhaps, and then they'll start working; what > I'm observing though is that nothing at all gets delivered, however long I > wait for - as if, FxAccountsPush is never created at all. I've somewhat misread the code/didn't understand xpcom component life-cycle; indeed, FxAccountsPush component might not be loaded at all, so we need to keep track of its state in the PushService, which is what the above patch does. Now, I'm somewhat unsure if we actually want to decouple FxA push stuff from WebPush stuff. To handle web push, we don't need to load FxAccountsPush.js at all, we only need that to decode incoming FxA pushes. Same is true for handling FxA pushes - I don't think we need PushServiceAndroidGCM. Patch above sends off messages to Gecko if they're WebPush and PushServiceAndroidGCM is ready, or if they're FxAPush and FxAccountsPush is ready. However, this is a bit of a moot point, since we still indiscriminately request Gecko to load whatever services we need via one "android-push-service" category, which will end up loading both components. Unless both of WebPush and Sync (and specifically send tabs) are being used - and they're probably not most of the time - we're wasting some efforts and memory here. Nick, do you think this is worth refactoring a little bit?

> Nick, do you think this is worth refactoring a little bit? The original intention was to handle WebPush (Java + JS) separately from FxA Push (only Java). Since implementing the Push crypto in Java is not straight-forward, FxA Push is now (Java + JS). Given this, I don't think it's worth trying to save a few KB of memory and incur the complexity of two Push pathways. I'd suggest always loading both components, or finding a way to lazily load the FxA Push component in response to the Gecko message that triggers it. (I think that's possible.) I'll defer review until you ask me for it again, taking your investigations into account.

Comment on attachment 8789335 [details] Bug 1300230 - Queue up incoming FxA push messages until FxAccountsPush is ready Re-flag when you're ready.

Comment on attachment 8789335 [details] Bug 1300230 - Queue up incoming FxA push messages until FxAccountsPush is ready https://reviewboard.mozilla.org/r/77616/#review76018 This looks fine by me. ::: mobile/android/base/java/org/mozilla/gecko/push/PushService.java:454 (Diff revision 2) > + "; ignoring dom/push message."); > + continue; > + } > + if (SERVICE_WEBPUSH.equals(service)) { > + sendMessageToGeckoService(pushMessage); > + } else /* FxA Push */ { nit: check the `SERVICE_FXAPUSH` explicitly, to make searching for it with DXR easier.

Pushed by gkruglov@mozilla.com: https://hg.mozilla.org/integration/autoland/rev/e451469799a7 Queue up incoming FxA push messages until FxAccountsPush is ready r=nalexander