1300297 - Changing FxA password leaves device unregistered temporarily

Status: VERIFIED FIXED

(Firefox :: Firefox Accounts, defect)

Description

[Phil Booth [:pb]]

Attachment: Desktop patch

Over in bug 1296328, a bug was fixed where changing the FxA password while signed in to Sync would cause the device registration to be lost.

Train 68 of FxA, which was deployed this week, breaks it because of this change to the auth database:

https://github.com/mozilla/fxa-auth-db-mysql/pull/160

I should have tested the two changes against each other but clearly I failed to do so.

The problem is that the device registration attempt added by the patch for bug 1296328 now fails with a 400 error. This puts us back into the unregistered device state we were in before the patch landed.

However, it's not a permanent failure condition. On the next Sync, we see that the previous registration attempt failed because of a bad device id, clear that id and then register the device again from scratch. That attempt works and the database is in the correct state once again.

From the logs:

> 1472811516619      FirefoxAccounts    DEBUG      updating existing device details
> 1472811516623      Services.Common.RESTRequest        DEBUG      POST request to http://127.0.0.1:9000/v1/account/device
> 1472811516635      Hawk       DEBUG      (Response) /account/device: code: 400 - Status text: Bad Request
> 1472811516635      FirefoxAccounts    ERROR      error POSTing /account/device: {"code":400,"errno":123,"error":"Bad Request","message":"Unknown device","info":"https://github.com/mozilla/fxa-auth-server/blob/master/docs/api.md#response-format"}
> 1472811516637      FirefoxAccounts    WARN       unknown device id, clearing the local device data
> 1472811516637      FirefoxAccounts    DEBUG      _updateAccountData with items: ["deviceId"]

There is a simple fix that clears the device id as soon as we get the change password notification, attached here. But given how close we are to the merge cut-off, it seems unlikely that it can be reviewed, landed, verified and uplifted in time to join the other patch. Probably not the end of the world I guess, but a bit unfortunate.

Here is the try build for the attached patch:

https://treeherder.mozilla.org/#/jobs?repo=try&revision=9544c8bc9d03

Comment 1

[Phil Booth [:pb]]

Attachment: Desktop patch

Previous patch had the wrong bug number in the commit comment, re-attaching.

https://treeherder.mozilla.org/#/jobs?repo=try&revision=33832a80ceb3

Comment 2

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

Thanks Phil,
  Are you able to start testing this on all versions from 49->trunk, so we can try and get this fix uplifted ASAP?

Comment 3

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

(I'm also assuming that the patch from bug 1296328 is still needed here - we reset the device ID when updating the credentials, then the call to updateDeviceRegistration() from bug 1296328 will then register a new ID - without this patch we were attempting to re-register the existing device ID which is now invalid, right?)

Comment 4

[Ryan Kelly [:rfkelly]]

> However, it's not a permanent failure condition. On the next Sync, we see that the previous
> registration attempt failed because of a bad device id, clear that id and then
> register the device again from scratch.

IIUC, this means that even without the fix in this bug, we're still better off having Bug 1296328 landed than not.  Prior to Bug 1296328 the device would go without a device record indefinitely, whereas at least now it will re-create one on the next sync.

In other words, it's not all bad :-)

I think our long-term strategy should be to try keep device IDs stable as much as possible, meaning I'd like to see us allow the device to re-register with its existing ID in this case.  But I'm happy with clearing it as a short-term fix.

Comment 5

[Phil Booth [:pb]]

(In reply to Mark Hammond [:markh] from comment #3)
> (I'm also assuming that the patch from bug 1296328 is still needed here - we
> reset the device ID when updating the credentials, then the call to
> updateDeviceRegistration() from bug 1296328 will then register a new ID -
> without this patch we were attempting to re-register the existing device ID
> which is now invalid, right?)

Correct, both this patch and the patch from bug 1296328 are needed.

(In reply to Ryan Kelly [:rfkelly] from comment #4)
> IIUC, this means that even without the fix in this bug, we're still better
> off having Bug 1296328 landed than not.  Prior to Bug 1296328 the device
> would go without a device record indefinitely, whereas at least now it will
> re-create one on the next sync.

Yep, correct.

(In reply to Ryan Kelly [:rfkelly] from comment #4)
> I think our long-term strategy should be to try keep device IDs stable as
> much as possible, meaning I'd like to see us allow the device to re-register
> with its existing ID in this case.  But I'm happy with clearing it as a
> short-term fix.

Understood, I'll add it to my to-do list.

Comment 6

[Phil Booth [:pb]]

(In reply to Mark Hammond [:markh] from comment #2)
> Are you able to start testing this on all versions from 49->trunk, so we
> can try and get this fix uplifted ASAP?

Tested (alongside the patch from bug 1296328) against release, beta, aurora and default. I can verify that it works correctly in all cases.

Comment 7

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/mozilla-inbound/rev/438fa35a91c9
Ensure FxA device id is cleared on password change. r=markh

Comment 8

[Phil Ringnalda (:philor)]

https://hg.mozilla.org/mozilla-central/rev/438fa35a91c9

Comment 9

[Phil Booth [:pb]]

Comment on attachment 8787875 [details] [diff] [review]
Desktop patch

Approval Request Comment
[Feature/regressing bug #]: n/a
[User impact if declined]: Users changing their Sync password may get stale device information in synced-tabs and general sync UI
[Describe test coverage new/current, TreeHerder]: Manual and automated
[Risks and why]: Low risk, localized fix limited to when Sync users change password
[String/UUID change made/needed]: None

Comment 10

[Liz Henry (:lizzard) (relman/hg->git project)]

Comment on attachment 8787875 [details] [diff] [review]
Desktop patch

Let's uplift this for RC2. It sounds like otherwise sync would be effectively not working for people who change their passwords. 

We should verify it once we do the RC2 (likely tomorrow)

Comment 11

[Liz Henry (:lizzard) (relman/hg->git project)]

Comment on attachment 8787875 [details] [diff] [review]
Desktop patch

Also please bring this to m-r since we are past the beta to release merge and want this in RC2.

Comment 12

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/releases/mozilla-beta/rev/76be57211b9bbef53e7a45f2cb0c304bf4763f69
https://hg.mozilla.org/releases/mozilla-release/rev/76be57211b9bbef53e7a45f2cb0c304bf4763f69

Comment 13

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/releases/mozilla-aurora/rev/06c6b6cc7d36

Comment 14

[Paul Silaghi, QA [:pauly]]

Attachment: error-sync-1473344092176.txt

I confirm that I no longer see the "code: 400" error in the error-sync-1473340895967.txt on FX 49 build 2, but I wonder why is it displayed at all the error-sync-1473340895967.txt in about:sync-log?

Comment 15

[Phil Booth [:pb]]

(In reply to Paul Silaghi, QA [:pauly] from comment #14)
> Created attachment 8789409 [details]
> error-sync-1473344092176.txt
> 
> I confirm that I no longer see the "code: 400" error in the
> error-sync-1473340895967.txt on FX 49 build 2, but I wonder why is it
> displayed at all the error-sync-1473340895967.txt in about:sync-log?

Apologies :pauly, I'm not sure I understand the question. Wonder why what is displayed?

The attachment has a different name to the log file you mention, did you attach the correct one?

Comment 16

[Paul Silaghi, QA [:pauly]]

(In reply to Phil Booth [:pb] from comment #15)
> Apologies :pauly, I'm not sure I understand the question. Wonder why what is
> displayed?
Is it expected on password change to appear an error-sync-xxx.file in about:sync-log, on a build that contains the fix of this bug?

> The attachment has a different name to the log file you mention, did you
> attach the correct one?
It seems I messed up the names a bit, but it shouldn't matter, it's the same sync log from a different Firefox profile.

Comment 17

[Phil Booth [:pb]]

(In reply to Paul Silaghi, QA [:pauly] from comment #16)
> Is it expected on password change to appear an error-sync-xxx.file in
> about:sync-log, on a build that contains the fix of this bug?

I can't see anything in that log file to indicate that it is related to a password change, although I'm not an expert on the Sync code. Is it possible that it might have been logged before the password was changed?

So I don't *think* it's anything to do with this patch, but maybe :markh can weigh in with a more authoritative opinion?

Comment 18

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

(In reply to Phil Booth [:pb] from comment #17)
> (In reply to Paul Silaghi, QA [:pauly] from comment #16)
> > Is it expected on password change to appear an error-sync-xxx.file in
> > about:sync-log, on a build that contains the fix of this bug?

That's bug 1195569 - it should be harmless (although is annoying and we should fix it)

Comment 19

[Paul Silaghi, QA [:pauly]]

Thanks for clarifying.

Comment 20

[Andrei Vaida [:avaida]]

Removing the qe-verify flag, since this fix has been already verified on Fx49. Phil, feel free to set it back if you think there's value in verifying this on Fx50 as well.