998523 - Tools menu shows Sync Now after I log out of FxA Sync

Status: VERIFIED FIXED

(Firefox :: Sync, defect)

Description

[Chris Karlof [:ckarlof]]

STR:

1) Sign in to FxA Sync
2) Sign out

Open tools menu.

Expected: It should say: "Set up Sync"
Observed: It says "Sync Now"

Observed on Fx 29 Beta and Fx 31 Nightly. Closing the menu and re-opening causes it to correctly show "Set up Sync"

Comment 1

[Chris Karlof [:ckarlof]]

Here's a hint:

First I do a logout:

1397865175808	Sync.Service	INFO	Service.startOver dropping sync key and logging out.
1397865175808	Sync.Status	DEBUG	Status.login: success.login => error.login.reason.no_recoverykey
1397865175808	Sync.Status	DEBUG	Status.service: success.status_ok => service.client_not_configured

Transitioning to "not configured" seems right. 


1397865175808	Sync.Service	INFO	Logging out
1397865175809	Sync.Status	DEBUG	Status.service: service.client_not_configured => success.status_ok

Transitioning to "status_ok" seems suspicious.

1397865175810	Sync.Status	DEBUG	Status.service: success.status_ok => success.status_ok
1397865175810	Sync.Status	DEBUG	Status.service: success.status_ok => success.status_ok
1397865175810	Sync.Status	DEBUG	Status.service: success.status_ok => success.status_ok
1397865175811	Sync.Status	DEBUG	Status.service: success.status_ok => success.status_ok
1397865175811	Sync.Status	DEBUG	Status.service: success.status_ok => success.status_ok
1397865175811	Sync.SyncScheduler	DEBUG	Clearing sync triggers and the global score.
1397865175811	Sync.Service	INFO	Service reset.
1397865175812	Sync.Engine.Clients	DEBUG	Resetting clients last sync time
1397865175812	Sync.Engine.Bookmarks	DEBUG	Resetting bookmarks last sync time
1397865175812	Sync.Engine.Forms	DEBUG	Resetting forms last sync time
1397865175813	Sync.Engine.History	DEBUG	Resetting history last sync time
1397865175813	Sync.Engine.Passwords	DEBUG	Resetting passwords last sync time
1397865175813	Sync.Engine.Prefs	DEBUG	Resetting prefs last sync time
1397865175813	Sync.Engine.Tabs	DEBUG	Resetting tabs last sync time
1397865175814	Sync.Engine.Addons	DEBUG	Resetting addons last sync time
1397865175814	Sync.CollectionKeyManager	INFO	Clearing collection keys...
1397865175815	Sync.Tracker.Clients	DEBUG	client.name preference changed
1397865175817	Sync.BrowserIDManager	INFO	Username changed. Removing stored credentials.
1397865175823	Sync.BrowserIDManager	INFO	initializeWithCurrentIdentity has no user logged in
1397865175823	Sync.BrowserIDManager	INFO	Username changed. Removing stored credentials.
1397865175823	Sync.BrowserIDManager	ERROR	Could not authenticate: no user is logged in
1397865176815	Sync.Tracker.Clients	DEBUG	Saving changed IDs to clients

Here is where I opened the menu item, which will only show "Setup Sync" when the user needs to verify her email or state is "not configured".

1397865197871	Sync.Status	DEBUG	Status.login: error.login.reason.no_recoverykey => error.login.reason.no_username
1397865197871	Sync.Status	DEBUG	Status.service: success.status_ok => service.client_not_configured

Here is where I opened it the second time. It transitions to "not configured", which then shows the correct state.

1397865206685	Sync.Status	DEBUG	Status.login: error.login.reason.no_username => error.login.reason.no_username
1397865206685	Sync.Status	DEBUG	Status.service: service.client_not_configured => service.client_not_configured

Comment 2

[Chris Karlof [:ckarlof]]

Mark what should we do about this?

Comment 3

[Chris Karlof [:ckarlof]]

I believe this regression was caused by Bug 970769, which adds a setTimeout to updateUI() in the tools menu rendering logic:

+                         onpopupshowing="setTimeout(() => gSyncUI.updateUI());"

After a logout/disconnect, (for better or worse) Status.service ends up in success.status_ok. When the user subsequently opens the tools menu, updateUI triggers Status.service to correctly transition to service.client_not_configured, but I have a feeling that it's "too late". The Tools menu UI has already rendered and doesn't update to the "Set Up Sync" state. I have verified that removing the setTimeout from the above line results in correct UI behavior after logout (i.e., showing "Set Up Sync" item in the Tools menu). 

I'm not sure of the right solution, but one workaround would be to make sure Status.service ends up in the service.client_not_configured at the end of Service.startOver() and doesn't transition back to success.status_ok (see above log). I haven't yet determined why that's happening.

It would be nice to have this fixed for Fx30.

Comment 4

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

I don't seem able to repro this on Windows.  Tim, I heard 3rd hand that Gavin asked you to take this - is that accurate?

Comment 5

[Lukas Blakk [:lsblakk] use ?needinfo]

Does this only present in FF29 and later?  Can someone test FF28?

Comment 6

[Chris Karlof [:ckarlof]]

I can't repro on FF28. This is a FxA Sync related issue.

Comment 7

[:Gavin Sharp [email: [e-mail]]]

(In reply to Mark Hammond [:markh] from comment #4)
> I don't seem able to repro this on Windows.  Tim, I heard 3rd hand that
> Gavin asked you to take this - is that accurate?

I changed my mind! I put it in the backlog, and anyone can take it.

Comment 8

[:Gijs (he/him)]

Ugh. Note to self: see bug 970769 Comment 5 and http://hg.mozilla.org/mozilla-central/annotate/2f8af55d6e9a/browser/base/content/browser-syncui.js#l87

I guess we basically need to do at least one of:
1) figure out a way to update the UI sync instead of on a timeout if we know we already inited the authManager
2) instead of a lazy update when the menu opens, we could just try to keep correct state at all times. I'm not sure if that's hard.

Comment 9

[:Gijs (he/him)]

(fwiw, I also can't reproduce, at least on Windows...)

Comment 10

[:Gijs (he/him)]

Chris, can you provide more detailed STR, in particular, how/where you're signing in/out, whether you have in-content prefs on, and whether you're able to reproduce this every time (on current nightly)?

Comment 11

[:Gijs (he/him)]

(I'm confused in any case because the tools menu never says "sync now" - instead it shows my account name when I'm logged in)

Comment 12

[Chris Karlof [:ckarlof]]

Gijs, I was able to reproduce every time on a Mac OS X computer. I'll double check with current nightly. :markh also couldn't reproduce on Windows, so we suspected this was a Mac OS X only issue.

Comment 13

[:Gijs (he/him)]

(In reply to Chris Karlof [:ckarlof] from comment #12)
> Gijs, I was able to reproduce every time on a Mac OS X computer. I'll double
> check with current nightly. :markh also couldn't reproduce on Windows, so we
> suspected this was a Mac OS X only issue.

OK. I can reproduce there being a short time where I can see the account name rather than "Sign in to sync", but not "Sync Now"... did that string just change since you reported? :-)

Comment 14

[:Gijs (he/him)]

(In reply to :Gijs Kruitbosch from comment #13)
> (In reply to Chris Karlof [:ckarlof] from comment #12)
> > Gijs, I was able to reproduce every time on a Mac OS X computer. I'll double
> > check with current nightly. :markh also couldn't reproduce on Windows, so we
> > suspected this was a Mac OS X only issue.
> 
> OK. I can reproduce there being a short time where I can see the account
> name rather than "Sign in to sync", but not "Sync Now"... did that string
> just change since you reported? :-)

OH. You mean like the main global OS X menu bar tools menu. I am still so stuck to Australis. I thought you meant the bar thing at the bottom of the main menu (tools menu, hamburger menu, 'open menu' (because of the tooltip), main menu - people name this thing all kinds of things). :-|

Sorry!

(and I can reproduce the original issue there - even after the hamburger menu has been updated already. Which is weird. Investigating...)

Comment 15

[:Gijs (he/him)]

Attachment: updateUI after logout,

Per discussions with Mark on IRC, listening for this notification and updating the UI should prevent any issues there. I've been cheeky and actually just went and removed the timeouted updateUI. I would probably do a beta patch without removing that, but for trunk, IMO, we should always have the UI in the right state. The same method is used for the sync button, which should equally always be up to date already, so... Unfortunately, it seems we don't have great tests for this, so we should probably not take that part on branch. Tim, does this look right to you?

Comment 16

[:Gijs (he/him)]

Attachment: updateUI after logout,

Per more discussion with markh, this might not have the desired results initially as weave doesn't start up until after 10 seconds. Going to leave filing appropriate followups to him, and leave this focused on fixing the issue at hand.

Comment 17

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

Comment on attachment 8422794 [details] [diff] [review]
updateUI after logout,

Review of attachment 8422794 [details] [diff] [review]:
-----------------------------------------------------------------

::: browser/base/content/browser-syncui.js
@@ +223,5 @@
>    },
>  
> +  onStartOverFinish: function SUI_onStartOverFinish() {
> +    this.updateUI();
> +  },

this function doesn't seem used.

@@ +511,5 @@
>        case "weave:service:start-over":
>          this.onStartOver();
>          break;
> +      case "weave:service:start-over:finish":
> +        this.updateUI();

I can understand why this might make the state correct, but from IRC, you suggested that once the mac menu is being shown, any updated don't actually update the menu.  If that's correct it seems this might not fix the problem.

(OTOH though, if it was too hard to fix the problem only in the case when the menu is already being shown as the state transitions but the menu is correct on the next show, I think we could consider that edge-casey-enough to be OK for now)

My OSX VM is broken, so I can't test this - and IMO it needs manual testing before review.  Maybe ckarlof can see if it fixes it for him?

Comment 18

[:Gijs (he/him)]

(In reply to Mark Hammond [:markh] from comment #17)
> > +  onStartOverFinish: function SUI_onStartOverFinish() {
> > +    this.updateUI();
> > +  },
> 
> this function doesn't seem used.

D'oh.
 
> @@ +511,5 @@
> >        case "weave:service:start-over":
> >          this.onStartOver();
> >          break;
> > +      case "weave:service:start-over:finish":
> > +        this.updateUI();
> 
> I can understand why this might make the state correct, but from IRC, you
> suggested that once the mac menu is being shown, any updated don't actually
> update the menu.  If that's correct it seems this might not fix the problem.

That depends if you click the menu REALLY QUICKLY after logging out. Right now, there is nothing that resets the menu (!) except this user-interaction-triggered call to updateUI. If you look at the log in comment 1, you will notice that in fact, the menu is wrong even when the user opens it a full 20 seconds after logging out. That's what this patch is fixing.

> My OSX VM is broken, so I can't test this - and IMO it needs manual testing
> before review.  Maybe ckarlof can see if it fixes it for him?

I managed to reproduce this quite easily in the end, once I actually understood the problem correctly (see comment 14). It's confusing because the element in the "main" hamburger menu updates state correctly because it's managed by the fxa-only newfangled UI code, which /also/ has an updateUI function. Not confusing at all.

In any case, I've verified that the patch does fix it. I'll put up a new patch with my "it is midnight, lalalala, hey look, the bug is fixed" idiocy removed. :-)

Thinking about this a little more, you should be able to verify that it's fixed even on Windows by making the timeout for the setTimeout e.g. 5 seconds and keeping the menu open. Pre-patch, you'll see the label updating while the menu is open. Post-patch, you shouldn't see that anymore.

Comment 19

[:Gijs (he/him)]

Attachment: updateUI after logout,

Comment 20

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

Comment on attachment 8423066 [details] [diff] [review]
updateUI after logout,

Review of attachment 8423066 [details] [diff] [review]:
-----------------------------------------------------------------

sold! :)

Comment 21

[:Gijs (he/him)]

remote:   https://hg.mozilla.org/integration/fx-team/rev/d65835b006b4

Comment 22

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/d65835b006b4

Comment 23

[:Gijs (he/him)]

Comment on attachment 8423066 [details] [diff] [review]
updateUI after logout,

[Approval Request Comment]
Bug caused by (feature/regressing bug #): New sync
User impact if declined: on OS X, the Tools menu's sync option will have the wrong label after a log out the first time the menu is opened
Testing completed (on m-c, etc.): local, on m-c
Risk to taking this patch (and alternatives if risky): low
String or IDL/UUID changes made by this patch: none

Comment 24

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/81edb9d02ccc
https://hg.mozilla.org/releases/mozilla-beta/rev/dfcd5c18e0a8

Comment 25

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-b2g30_v1_4/rev/dfcd5c18e0a8

Comment 26

[Tracy Walker [:tracy]]

I have checked this across channels and it is working as expected: on disconnect, the tools menu shows Set Up Sync...