Last Comment Bug 752514 - "Aborting sync: User password has changed" after profile migration has failed
: "Aborting sync: User password has changed" after profile migration has failed
Status: VERIFIED FIXED
[sumo]
:
Product: Firefox for Android
Classification: Client Software
Component: General (show other bugs)
: unspecified
: ARM Android
: -- normal (vote)
: Firefox 15
Assigned To: :Margaret Leibovic
:
Mentors:
: 753464 (view as bug list)
Depends on: 715550
Blocks:
  Show dependency treegraph
 
Reported: 2012-05-07 08:32 PDT by Cristian Nicolae (:xti)
Modified: 2012-10-17 07:31 PDT (History)
16 users (show)
See Also:
Crash Signature:
(edit)
QA Whiteboard:
Iteration: ---
Points: ---
Has Regression Range: ---
Has STR: ---
fixed
fixed
betaN+


Attachments
logcat (175.10 KB, text/plain)
2012-05-10 16:53 PDT, :Margaret Leibovic
no flags Details
logcat attempt #2 (187.98 KB, text/plain)
2012-05-10 17:07 PDT, :Margaret Leibovic
no flags Details
fix swapped sync key/password (1.62 KB, patch)
2012-05-11 15:19 PDT, :Margaret Leibovic
rnewman: review+
bugzilla: approval‑mozilla‑aurora+
Details | Diff | Review

Description Cristian Nicolae (:xti) 2012-05-07 08:32:58 PDT
Firefox 15.0a1 (2012-05-07)
Device: Samsung Captivate
OS: Android 2.2

Steps to reproduce:
1. Perform the str from bug 752492
2. Go to Android Setting > Accounts and Sync and tap on the Firefox Sync account
3. Tap on Sync Now to sync Native Nightly

Expected result:
After step 3, sync process starts. No errors will occur/interrupt the Sync activity.

Actual result:
After step 3, the following errors will occur each time when step 3 is performed:

W/GlobalSession(11761): Aborting sync: User password has changed.
W/GlobalSession(11761): org.mozilla.gecko.sync.NodeAuthenticationException
W/GlobalSession(11761): at org.mozilla.gecko.sync.stage.EnsureClusterURLStage$2.handleSuccess(EnsureClusterURLStage.java:199)
W/GlobalSession(11761): at org.mozilla.gecko.sync.stage.EnsureClusterURLStage$1.handleHttpResponse(EnsureClusterURLStage.java:135)
W/GlobalSession(11761): at org.mozilla.gecko.sync.net.BaseResource.execute(BaseResource.java:247)
W/GlobalSession(11761): at org.mozilla.gecko.sync.net.BaseResource.go(BaseResource.java:269)
W/GlobalSession(11761): at org.mozilla.gecko.sync.net.BaseResource.get(BaseResource.java:275)
W/GlobalSession(11761): at org.mozilla.gecko.sync.stage.EnsureClusterURLStage.fetchClusterURL(EnsureClusterURLStage.java:176)
W/GlobalSession(11761): at org.mozilla.gecko.sync.stage.EnsureClusterURLStage$3.run(EnsureClusterURLStage.java:249)
W/GlobalSession(11761): at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441)
W/GlobalSession(11761): at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:305)
W/GlobalSession(11761): at java.util.concurrent.FutureTask.run(FutureTask.java:137)
W/GlobalSession(11761): at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1068)
W/GlobalSession(11761): at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:561)
W/GlobalSession(11761): at java.lang.Thread.run(Thread.java:1096)
I/SyncAdapter(11761): GlobalSession indicated error. Flagging auth token as invalid, just in case.
I/SyncAdapter(11761): Notifying sync monitor.
I/SyncAdapter(11761): Setting minimum next sync time to 1336512975385
Comment 1 Aaron Train [:aaronmt] 2012-05-08 07:05:52 PDT
What's the story here?
Comment 2 Richard Newman [:rnewman] 2012-05-08 08:45:40 PDT
What you're describing indicates that the Sync username or password didn't make it into the Android Account. There doesn't seem to be any reason for that, so I'm hoping that gcp's investigation into ANR during migration will just make this go away.
Comment 3 Richard Newman [:rnewman] 2012-05-09 17:07:43 PDT
*** Bug 753464 has been marked as a duplicate of this bug. ***
Comment 4 Richard Newman [:rnewman] 2012-05-09 17:08:15 PDT
Bug 753464 has a log with credentials.
Comment 5 Nick Alexander :nalexander 2012-05-10 12:19:55 PDT
Per https://bugzilla.mozilla.org/show_bug.cgi?id=752492#c14 I can't duplicate the STR of the first bug.  Hopefully movement on 752492 will move this ticket forward.
Comment 6 :Margaret Leibovic 2012-05-10 15:33:54 PDT
Cristian, if you try reproducing this with the latest Nightly, do you still get the same stack? Part of this issue might have been resolved by bug 753175.

I ask because the issue I filed in bug 753464 doesn't have the same stack, and I'm wondering if you can reproduce that same 401 error.

rnewman or nalexander, what do you think of those logs in bug 753464? I'll look into where what we do with the credentials we get from the migration, but it's possible this problem could be on the sync side of things.
Comment 7 :Margaret Leibovic 2012-05-10 15:41:24 PDT
(In reply to Margaret Leibovic [:margaret] from comment #6)

> rnewman or nalexander, what do you think of those logs in bug 753464? I'll
> look into where what we do with the credentials we get from the migration,
> but it's possible this problem could be on the sync side of things.

Actually, don't look too hard just yet... I may have found something. I'll follow up when I know more.
Comment 8 :Margaret Leibovic 2012-05-10 16:30:34 PDT
(In reply to Margaret Leibovic [:margaret] from comment #7)
> (In reply to Margaret Leibovic [:margaret] from comment #6)
> 
> > rnewman or nalexander, what do you think of those logs in bug 753464? I'll
> > look into where what we do with the credentials we get from the migration,
> > but it's possible this problem could be on the sync side of things.
> 
> Actually, don't look too hard just yet... I may have found something. I'll
> follow up when I know more.

Hm, I was looking into how we pass parameters to SyncAccountParameters, but nothing I've tried has fixed the problem.

I can confirm that the credentials that get logged are the same as what shows up in my password manager on desktop. Is there something we're failing to do when creating this new account? I was thinking maybe sync is getting upset by another client trying to use the same clientGuid, so I got rid of the last 3 paramters here, since they're not required, but that didn't fix anything: http://mxr.mozilla.org/mozilla-central/source/mobile/android/base/ProfileMigrator.java#638.

Any ideas?
Comment 9 :Margaret Leibovic 2012-05-10 16:34:01 PDT
Update: after going to Settings->Sync, unchecking rechecking the checkbox a few times, sync appears to be working. This really makes me think this is a sync issue, not a migration issue.
Comment 10 Nick Alexander :nalexander 2012-05-10 16:35:29 PDT
Margaret, the interesting log tags are SyncAccounts and FxSync (when things go terribly wrong).  Can you bump those up to VERBOSE and see what Android Sync is telling you?
(In reply to Margaret Leibovic [:margaret] from comment #8)
> (In reply to Margaret Leibovic [:margaret] from comment #7)
> > (In reply to Margaret Leibovic [:margaret] from comment #6)
> > 
> > > rnewman or nalexander, what do you think of those logs in bug 753464? I'll
> > > look into where what we do with the credentials we get from the migration,
> > > but it's possible this problem could be on the sync side of things.
> > 
> > Actually, don't look too hard just yet... I may have found something. I'll
> > follow up when I know more.
> 
> Hm, I was looking into how we pass parameters to SyncAccountParameters, but
> nothing I've tried has fixed the problem.
> 
> I can confirm that the credentials that get logged are the same as what
> shows up in my password manager on desktop. Is there something we're failing
> to do when creating this new account? I was thinking maybe sync is getting
> upset by another client trying to use the same clientGuid, so I got rid of
> the last 3 paramters here, since they're not required, but that didn't fix
> anything:
> http://mxr.mozilla.org/mozilla-central/source/mobile/android/base/
> ProfileMigrator.java#638.
> 
> Any ideas?

Margaret, the interesting log tags are SyncAccounts and FxSync (when things go terribly wrong).  Can you bump those up to VERBOSE and see what Android Sync is telling you?
Comment 11 Nick Alexander :nalexander 2012-05-10 16:36:03 PDT
(In reply to Margaret Leibovic [:margaret] from comment #9)
> Update: after going to Settings->Sync, unchecking rechecking the checkbox a
> few times, sync appears to be working. This really makes me think this is a
> sync issue, not a migration issue.

I can't reproduce at the moment, but I'll try with fresh nightlies tomorrow and see what turns up.
Comment 12 :Margaret Leibovic 2012-05-10 16:53:11 PDT
Created attachment 622973 [details]
logcat

Actually, I take back what I said - the error state from the settings UI went away, but sync doesn't seem to be working.

Here's what I got with |adb logcat FxSync:V SyncAccounts:V|. It doesn't seem to have much - is that the right way to be getting verbose logs?
Comment 13 Nick Alexander :nalexander 2012-05-10 16:57:34 PDT
I don't think so.  Try

adb shell setprop log.tag.FxSync VERBOSE
adb shell setprop log.tag.SyncAccounts VERBOSE

then restart Fennec (needed to clear log level cache in Android Sync).  Then try it again -- sorry :(
Comment 14 :Margaret Leibovic 2012-05-10 17:07:57 PDT
Created attachment 622978 [details]
logcat attempt #2

Sorry about the confusion. This is the log following your instructions. Unfortunately it doesn't really give us much more information.
Comment 15 Nick Alexander :nalexander 2012-05-10 17:14:38 PDT
(In reply to Margaret Leibovic [:margaret] from comment #14)
> Created attachment 622978 [details]
> logcat attempt #2
> 
> Sorry about the confusion. This is the log following your instructions.
> Unfortunately it doesn't really give us much more information.

Not at all -- log shows that everything was hunky-dory creating the account from Sync's side.

Look's rather like this one's on us.  I will fetch fresh nightlies and try to reproduce tomorrow morning.
Comment 16 :Margaret Leibovic 2012-05-11 08:29:19 PDT
(In reply to Nick Alexander :nalexander from comment #15)

> Look's rather like this one's on us.  I will fetch fresh nightlies and try
> to reproduce tomorrow morning.

Bouncing over to the sync component then.
Comment 17 Nick Alexander :nalexander 2012-05-11 14:48:12 PDT
I think the issue is that at http://mxr.mozilla.org/mozilla-central/source/mobile/android/base/ProfileMigrator.java#629 the sync key and sync password should be reversed.  We have

            final String syncKey = mSyncSettingsMap.get("Mozilla Services Password");
            final String syncPass = mSyncSettingsMap.get("Mozilla Services Encryption Passphrase");

But the "encryption passphrase" is really the sync key.

On the sync side, we could throw an error if the sync key is not the correct length (26 alpha characters?).

Thoughts?
Comment 18 :Margaret Leibovic 2012-05-11 15:19:35 PDT
Created attachment 623324 [details] [diff] [review]
fix swapped sync key/password

I confirmed this fixes the authentication error I was seeing.
Comment 19 Nick Alexander :nalexander 2012-05-11 15:27:18 PDT
(In reply to Margaret Leibovic [:margaret] from comment #18)
> Created attachment 623324 [details] [diff] [review]
> fix swapped sync key/password
> 
> I confirmed this fixes the authentication error I was seeing.

Patch looks fine, but I'm probably not the right person to r+.  I emailed :ally and :rnewman about escalating.
Comment 20 :Margaret Leibovic 2012-05-11 15:40:09 PDT
Zoink, moving back to Fennec Native. Landed on inbound:
https://hg.mozilla.org/integration/mozilla-inbound/rev/233a09b3de85

nalexander and I also talked about how the comment in SyncAccounts.java that confused me should be fixed:
http://mxr.mozilla.org/mozilla-central/source/mobile/android/base/sync/setup/SyncAccounts.java#68
Comment 21 Nick Alexander :nalexander 2012-05-11 15:41:17 PDT
> nalexander and I also talked about how the comment in SyncAccounts.java that
> confused me should be fixed:
> http://mxr.mozilla.org/mozilla-central/source/mobile/android/base/sync/setup/
> SyncAccounts.java#68

https://github.com/mozilla-services/android-sync/pull/190
Comment 22 :Margaret Leibovic 2012-05-11 15:42:49 PDT
Comment on attachment 623324 [details] [diff] [review]
fix swapped sync key/password

[Approval Request Comment]
Regression caused by (bug #): n/a
User impact if declined: sync account migration fails because password/key values are swapped :/
Testing completed (on m-c, etc.): just landed on inbound
Risk to taking this patch (and alternatives if risky): self-contained variable switch fix
String changes made by this patch: n/a

It's unfortunate that it's likely too late for this to make it into the first beta, but users can fix this problem by removing/re-adding their sync account. We should let SUMO know about this in case beta users expect their sync accounts to be migrated properly.
Comment 23 Matt Brubeck (:mbrubeck) 2012-05-12 09:03:50 PDT
https://hg.mozilla.org/mozilla-central/rev/233a09b3de85
Comment 24 Allison Naaktgeboren :ally 2012-05-12 21:55:15 PDT
The sync team would like this uplifted as soon as possible, though we understand that this may not make the first beta.
Comment 26 Richard Newman [:rnewman] 2012-05-15 11:14:25 PDT
Teensy follow-up to correct misleading comment:

https://hg.mozilla.org/integration/mozilla-inbound/rev/db9b1d2966d7
Comment 27 Ed Morley [:emorley] 2012-05-16 03:41:58 PDT
https://hg.mozilla.org/mozilla-central/rev/db9b1d2966d7

Note You need to log in before you can comment on or make changes to this bug.