1484059 - Tab is not received on Android device

Status: VERIFIED FIXED

(Firefox :: Sync, defect, P1)

Description

[Kanchan Kumari QA]

STR:
1. Sign in to multiple device with newly created Fx account(two desktops, iOS, Android), the latest nightly for Android and Desktops, Latest beta for iOS
2. Sync all device, devices are matching fine in send tab device list on all devices
3. On Desktops change identity.fxaccounts.commands.enabled;true
4. Restart browsers on desktops
5. Send tab from desktop to Desktop and Android
 Browser console shows expected messages
Sending a tab to test2 using FxA commands. browser-sync.js:344:7
Sending a tab to Nightly on D6503 using Sync. (Android device) 

Observed: Tab is not received on Android

Send tab from Android to desktop is working fine.

Comment 1

[Edouard Oger [:eoger]]

I've checked the logs and we end up here:
https://searchfox.org/mozilla-central/rev/5dbfd833bbb114afe758db4d4bdbc5b13bcc33ef/mobile/android/components/FxAccountsPush.js#115

Why do we enter this state is a mystery, since Java does have the registration on its side.

Comment 2

[Kanchan Kumari QA]

I am seeing this issue on the today's nightly (2018-09-13)too.

Comment 3

[Kanchan Kumari QA]

Android is not receiving tab from iOS as well.

Comment 4

[Mark Hammond [:markh] [:mhammond]]

I'm also seeing this problem on 63.0b5 (although I can't see a build number anywhere - but no update is pending). logcat is showing:

09-18 10:10:10.562 11447 11495 D GeckoFxAccountsPush: Error while decoding incoming message : Error: No subscription found
09-18 10:10:10.563 11447 11479 I GeckoPushService: Handling event: FxAccountsPush:ReceivedPushMessageToDecode:Response
09-18 10:10:10.563 11447 11479 E GeckoPushService: callback must not be null in FxAccountsPush:ReceivedPushMessageToDecode:Response

which looks like bug 1484090 - although the patch there doesn't seem to log anything when it tries to resubscribe, so I can't be sure we've tried to resubscribe.

Ed, is there anything else I can do/check here?

Comment 5

[Edouard Oger [:eoger]]

It's not perfect, but you should see something like:

GeckoPushService: Error getting subscription [number]

Then on the next sync:

FxADeviceRegistrator: Attempting registration for an existing device

Comment 6

[Kanchan Kumari QA]

see also bug 1484057

Comment 7

[Kanchan Kumari QA]

Sometimes sent tab appear in Android mobile notifications but doesn't automatically open in opened Fx nightly browser. Clicking on the notification link gives option to open with any available browser (Chrome, Fx Nightly).

Comment 8

[Kanchan Kumari QA]

I do see when identity.fxaccounts.commands.enabled;false then clicking on received tab notification on Android link opens tab in opened nightly browser.

Comment 9

[Edouard Oger [:eoger]]

Just to be clear this bug is present independently of the enablement of FxA commands (always been there).
It doesn't mean it's not an important problem, but it shouldn't block new send tab from shipping.

Comment 10

[Mark Hammond [:markh] [:mhammond]]

(In reply to Edouard Oger [:eoger] from comment #5)
> It's not perfect, but you should see something like:
> 
> GeckoPushService: Error getting subscription [number]
> 
> Then on the next sync:
> 
> FxADeviceRegistrator: Attempting registration for an existing device

I don't see that :( With the browser not running, I sent a tab. logcat shows:

> 09-25 11:45:59.991   747   811 I GeckoPushService: Google Play Services GCM message received; delivering.
> 09-25 11:45:59.991   747   811 I GeckoPushService: Message directed to service: fxa
> 09-25 11:45:59.997   747   811 I GeckoPushService: Required service not initialized, adding message to queue.
> 09-25 11:46:00.047   747   811 I GeckoPushService: Handling event: FxAccountsPush:Initialized
> 09-25 11:46:00.050   747   811 I GeckoPushService: Delivering dom/push message to decode to Gecko!
> 09-25 11:46:00.370   747   825 I GeckoFxAccountsPush: FxAccountsPush _decodePushMessage
> 09-25 11:46:00.384   747   825 D GeckoFxAccountsPush: Error while decoding incoming message : Error: No subscription found
> 09-25 11:46:00.384   747   811 I GeckoPushService: Handling event: FxAccountsPush:ReceivedPushMessageToDecode:Response
> 09-25 11:46:00.384   747   811 E GeckoPushService: callback must not be null in FxAccountsPush:ReceivedPushMessageToDecode:Response

I then manually started the browser:

> 09-25 11:57:03.668  3478  3674 D GeckoPushService: Registered Gecko event listener.
> 09-25 11:57:03.668  3478  3674 I GeckoPushService: Starting up.
> 09-25 11:57:03.726  3478  3674 I GeckoPushService: Google Play Services GCM message received; delivering.
> 09-25 11:57:03.727  3478  3674 I GeckoPushService: Message directed to service: fxa
> 09-25 11:57:03.746  3478  3674 I GeckoPushService: Required service not initialized, adding message to queue.
> 09-25 11:57:05.230  3478  3674 I GeckoPushService: Handling event: FxAccountsPush:Initialized
> 09-25 11:57:05.279  3478  3674 I GeckoPushService: Handling event: PushServiceAndroidGCM:Configure
> 09-25 11:57:05.398  3478  3674 I GeckoPushService: Handling event: PushServiceAndroidGCM:Initialized
> 09-25 11:57:05.402  3478  3674 I GeckoPushService: Delivering dom/push message to decode to Gecko!
> 09-25 11:57:05.420  3478  3679 I GeckoFxAccountsPush: FxAccountsPush _decodePushMessage
> 09-25 11:57:05.611  3478  3679 D GeckoFxAccountsPush: Error while decoding incoming message : Error: No subscription found
> 09-25 11:57:05.611  3478  3674 I GeckoPushService: Handling event: FxAccountsPush:ReceivedPushMessageToDecode:Response
> 09-25 11:57:05.612  3478  3674 E GeckoPushService: callback must not be null in FxAccountsPush:ReceivedPushMessageToDecode:Response

still not tab. So I force a sync:

> 09-25 11:58:04.037  3478  3478 I FxAccounts: firefox_beta :: FirefoxAccounts :: Requesting sync.
> 09-25 11:58:04.037  3478  3478 I FxAccounts: firefox_beta :: FirefoxAccounts :: Sync options -- scheduling now: true
> 09-25 11:58:04.042  3478  3478 I FxAccounts: firefox_beta :: FxAccountStatusFragment :: Got sync started message; refreshing.
> 09-25 11:58:04.062  3478  4017 I FxAccounts: firefox_beta :: FxAccountSyncAdapter :: Syncing FxAccount account named like [e-mail] for authority org.mozilla.firefox_beta.db.browser with instance org.mozilla.gecko.fxa.sync.FxAccountSyncAdapter@785be77.
> 09-25 11:58:04.064  3478  4017 I FxAccounts: firefox_beta :: FxAccountSyncAdapter :: Account last synced at: 1537839874767
> 09-25 11:58:04.064  3478  4017 I FxAccounts: firefox_beta :: FirefoxAccounts :: Sync options -- scheduling now: true
> <etc - sync works - but no reference to push subscriptions>
> 09-25 11:58:11.876  3478  3478 I FxAccounts: firefox_beta :: FxAccountStatusFragment :: Got sync finished message; refreshing.

tab appears! Then, while the browser is still running I send another tab:

> 09-25 11:59:24.618  3478  3674 I GeckoPushService: Google Play Services GCM message received; delivering.
> 09-25 11:59:24.619  3478  3674 I GeckoPushService: Message directed to service: fxa
> 09-25 11:59:24.619  3478  3674 I GeckoPushService: Delivering dom/push message to decode to Gecko!
> 09-25 11:59:24.620  3478  3679 I GeckoFxAccountsPush: FxAccountsPush _decodePushMessage
> 09-25 11:59:24.626  3478  3679 D GeckoFxAccountsPush: Error while decoding incoming message : Error: No subscription found
> 09-25 11:59:24.627  3478  3674 I GeckoPushService: Handling event: FxAccountsPush:ReceivedPushMessageToDecode:Response
> 09-25 11:59:24.627  3478  3674 E GeckoPushService: callback must not be null in FxAccountsPush:ReceivedPushMessageToDecode:Response

So we seem to be back at square 1. Ed, thoughts?

Comment 11

[Edouard Oger [:eoger]]

Are you on Firefox Nightly though?

Comment 12

[Mark Hammond [:markh] [:mhammond]]

(In reply to Edouard Oger [:eoger] from comment #11)
> Are you on Firefox Nightly though?

I'm on beta 63 - I thought this was supposed to have been fixed in bug 1484090, which is listed as fixed in 63?

Comment 13

[Julie McCracken (:julie)]

FxA Messages is shipping with Fx64, so that's where the testing is taking place.

Comment 14

[Edouard Oger [:eoger]]

Patch to come

Comment 15

[Edouard Oger [:eoger]]

Attachment: Bug 1484059 p1 - Pass both the profile name and the profile dir in initGecko()

GeckoProfile.initFromArgs is called using the values set in initGecko.
initFromArgs will then only recognize a profileDir, leave profileName null,
and then call GeckoProfile.get who will then create a "Custom (anonymous)
profile with specified dir." type of GeckoProfile, which is incorrect.
We fix the profile by specifying both -profile and -P in the args string.

Comment 16

[Edouard Oger [:eoger]]

Attachment: Bug 1484059 p2 - Use sendRequestForResult instead of sendRequest when dispatching an error

The Java PushService drops messages without a callback, fix this by calling
sendRequestForResult instead which sends a callback along messages.

Depends on D7671

Comment 17

[Edouard Oger [:eoger]]

I have attached two commits.

* Part 1 fixes the underlying issue of getSubscription() returning null:
Under a certain set of conditions (memory pressure, processes killed etc), we initialize GeckoProfile incorrectly.
Because we are "technically" using a different profile, the java push subscription database we have is empty.
Finally, when we initialize the Gecko Push Service, it is confused because its own db contains a subscription that the Java side doesn't have, and ends up dropping every subscription it had [0]. I assume this bug also affected push subscriptions created from content which is pretty bad.

[0] https://searchfox.org/mozilla-central/rev/3c85ea2f8700ab17e38b82d77cd44644b4dae703/dom/push/PushServiceAndroidGCM.jsm#175-189

* Part 2 fixes the fix from bug 1484090, I have finally be able to reproduce the issue so I can confirm the fix works.

What does this means for users which Send Tab is not working at the moment?

Next tab they'll receive, part 2 will enter in action, and on their next sync we'll re-do the whole FxA device registration all over again, with a set of fresh push subscription and subsequently fixing send-tab for them.

Comment 18

[Lina Butler (ex-Mozilla)]

(In reply to Edouard Oger [:eoger] from comment #17)
> I assume this bug also affected
> push subscriptions created from content which is pretty bad.

Yep. :-( We store subscriptions from content in the same Push DB.

Comment 19

[Edouard Oger [:eoger]]

Attachment: Bug 1484059 p3 - Bump the device registration version to 3

MozReview-Commit-ID: AIoImE4SqiY

Depends on D7672

Comment 20

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/bc929f19bbee
p1 - Pass both the profile name and the profile dir in initGecko() r=jchen
https://hg.mozilla.org/integration/autoland/rev/9580ad0dbf28
p2 - Use sendRequestForResult instead of sendRequest when dispatching an error r=lina
https://hg.mozilla.org/integration/autoland/rev/6b2841fea17d
p3 - Bump the device registration version to 3 r=rfkelly

Comment 21

[Cosmin Sabou [:CosminS]]

https://hg.mozilla.org/mozilla-central/rev/bc929f19bbee
https://hg.mozilla.org/mozilla-central/rev/9580ad0dbf28
https://hg.mozilla.org/mozilla-central/rev/6b2841fea17d

Comment 22

[Edouard Oger [:eoger]]

Comment on attachment 9014233 [details]
Bug 1484059 p1 - Pass both the profile name and the profile dir in initGecko()

[Beta/Release Uplift Approval Request]

Feature/Bug causing the regression: 1433968?

User impact if declined: - We'll continue, under certain circumstances, to drop every push subscription a user has on Android.
- Send tab will be/continue to be broken for Android users.

Is this code covered by automated tests?: No

Has the fix been verified in Nightly?: Yes

Needs manual test from QE?: No

If yes, steps to reproduce: 

List of other uplifts needed: None

Risk to taking this patch: Low

Why is the change risky/not risky? (and alternatives if risky): These are all trivial changes.

String changes made/needed:

Comment 23

[Edouard Oger [:eoger]]

Comment on attachment 9014234 [details]
Bug 1484059 p2 - Use sendRequestForResult instead of sendRequest when dispatching an error

See p1

[Beta/Release Uplift Approval Request]

Feature/Bug causing the regression: None

User impact if declined: 

Is this code covered by automated tests?: Yes

Has the fix been verified in Nightly?: Yes

Needs manual test from QE?: Yes

If yes, steps to reproduce: 

List of other uplifts needed: None

Risk to taking this patch: Low

Why is the change risky/not risky? (and alternatives if risky): 

String changes made/needed:

Comment 24

[Edouard Oger [:eoger]]

Comment on attachment 9014666 [details]
Bug 1484059 p3 - Bump the device registration version to 3

See p1

[Beta/Release Uplift Approval Request]

Feature/Bug causing the regression: None

User impact if declined: 

Is this code covered by automated tests?: Yes

Has the fix been verified in Nightly?: Yes

Needs manual test from QE?: Yes

If yes, steps to reproduce: 

List of other uplifts needed: None

Risk to taking this patch: Low

Why is the change risky/not risky? (and alternatives if risky): 

String changes made/needed:

Comment 25

[Pascal Chevrel:pascalc]

Comment on attachment 9014233 [details]
Bug 1484059 p1 - Pass both the profile name and the profile dir in initGecko()

Tracked P1 regression in 63, uplift approved for 63 beta 13, thanks.

Comment 26

[Pascal Chevrel:pascalc]

Comment on attachment 9014666 [details]
Bug 1484059 p3 - Bump the device registration version to 3

Note to sheriffs: there are 3 patches in this uplift.

Comment 27

[Andreea Pavel [:apavel]]

https://hg.mozilla.org/releases/mozilla-beta/rev/cfaf1ec5c361
https://hg.mozilla.org/releases/mozilla-beta/rev/4d163a122200
https://hg.mozilla.org/releases/mozilla-beta/rev/f6c157c1d4c4

Comment 28

[Edouard Oger [:eoger]]

Appreciate it thanks!

Comment 29

[Kanchan Kumari QA]

Attachment: Android logs

I am seeing this issue on today's nightly 
User Agent 	Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:64.0) Gecko/20100101 Firefox/64.0

Android : 64.0a1 (2018-10-09)

Please see the attached Android logs.

Comment 30

[Kanchan Kumari QA]

Tab (In reply to Kanchan Kumari QA from comment #7)
> Sometimes sent tab appear in Android mobile notifications but doesn't
> automatically open in opened Fx nightly browser. Clicking on the
> notification link gives option to open with any available browser (Chrome,
> Fx Nightly).

Only difference I see that received Tab appears on mobile notification every time but same, it doesn't automatically open in opened Fx nightly browser. Clicking on the notification link gives option to open with any available browser (Chrome, Fx Nightly).

Comment 31

[Edouard Oger [:eoger]]

These logs show an Android device sending tabs, not receiving them. Are you sure these are the right logs?

Comment 32

[Kanchan Kumari QA]

After this code fix I am receiving tab in android notification reliably from the latest nightly (Build ID 20181010100123)and beta 63 CI build (FxA enabled/disabled)
Version 	63.0b13
Build ID 	20181008144252
User Agent 	Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:63.0) Gecko/20100101 Firefox/63.0



As per Edourd, tab is getting received in notification (not automatically open in opened Firefox nightly/beta) seems to be ok. In latest testing clicking on notification opens the tab in opened nightly on Android (without giving option to open with Chrome, Fx Nightly).