752514 - "Aborting sync: User password has changed" after profile migration has failed

Status: VERIFIED FIXED

(Firefox for Android Graveyard :: General, defect)

Description

[Cristian Nicolae (:xti)]

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]]

What's the story here?

Comment 2

[Richard Newman [:rnewman]]

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 4

[Richard Newman [:rnewman]]

Bug 753464 has a log with credentials.

Comment 5

[Nick Alexander :nalexander [he/him]]

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]

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]

(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]

(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]

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 [he/him]]

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 [he/him]]

(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]

Attachment: 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 [he/him]]

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]

Attachment: 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 [he/him]]

(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]

(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 [he/him]]

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]

Attachment: fix swapped sync key/password

I confirmed this fixes the authentication error I was seeing.

Comment 19

[Nick Alexander :nalexander [he/him]]

(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]

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 [he/him]]

> 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]

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)]

https://hg.mozilla.org/mozilla-central/rev/233a09b3de85

Comment 24

[Allison Naaktgeboren :ally]

The sync team would like this uplifted as soon as possible, though we understand that this may not make the first beta.

Comment 25

[:Margaret Leibovic]

https://hg.mozilla.org/releases/mozilla-aurora/rev/c79b814c8538

Comment 26

[Richard Newman [:rnewman]]

Teensy follow-up to correct misleading comment:

https://hg.mozilla.org/integration/mozilla-inbound/rev/db9b1d2966d7

Comment 27

[Ed Morley [:emorley]]

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