1195569 - First sync after creating a new account always creates an error log

Status: REOPENED

(Firefox :: Firefox Accounts, defect, P3)

Description

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

A first Sync always seem to generate entries:

> 1439791522587	browserwindow.syncui	DEBUG	observed: weave:service:ready
> 1439791522587	browserwindow.syncui	DEBUG	_loginFailed has sync state=error.login.reason.no_username
> 1439791522589	Sync.Status	DEBUG	Status.login: error.login.reason.no_username => error.login.reason.no_username
> 1439791522589	Sync.Status	DEBUG	Status.service: service.client_not_configured => service.client_not_configured
> 1439791522589	FirefoxAccounts	DEBUG	setSignedInUser - aborting any existing flows
> 1439791522589	FirefoxAccounts	TRACE	StorageManager finalizing
> 1439791522589	FirefoxAccounts	INFO	An accountState promise was resolved, but was actually rejected due to a different user being signed in. Originally resolved with: null
> 1439791522590	FirefoxAccounts	ERROR	Error updating FxA account info: Error: A different user signed in (resource://gre/modules/FxAccounts.jsm:155:29) JS Stack trace: [e-mail]:155:29 < getUserAccountData/<@FxAccounts.jsm:139:14 < [e-mail]:934:23 < [e-mail]:813:7 < Promise*[e-mail]:744:11 < [e-mail]:776:7 < [e-mail]:711:7 < [e-mail]:94:7 < [e-mail]:93:5 < [e-mail]:406:7

While the ERROR appears benign, the fact it is an error means an error log is generated and a message about the error is written to the browser console.

Comment 1

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

Via bug 1209481, it seems this happens both when creating a new account and logging in to an existing one.

Comment 2

[Chris Karlof [:ckarlof]]

Re-assigning to Kit.

Comment 3

[Kazumasa Hasegawa (Kazz)]

`Sync encountered an error - see about:sync-log for the log file. policies.js:677:0`
is always logged in the browser console, since I've updated Firefox to 46.0a2.
Not only at start up, also every time Sync starts.
Although the error is logged, data is properly synchronized by the Sync.

Comment 4

[Chris Karlof [:ckarlof]]

Kazz, can you please attach the relevant parts of your log file showing the error you mention?

Comment 5

[Kazumasa Hasegawa (Kazz)]

Attachment: 1st log (at Firefox start up)

Comment 6

[Kazumasa Hasegawa (Kazz)]

Attachment: 2nd log

Comment 7

[Kazumasa Hasegawa (Kazz)]

Attachment: 3rd log

Comment 8

[Kazumasa Hasegawa (Kazz)]

(In reply to Chris Karlof [:ckarlof] from comment #4)
Uploaded 3 log files.
Some values (which seems to be personal related) are omitted.

> Kazz, can you please attach the relevant parts of your log file showing the
> error you mention?

Comment 9

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

Thanks for the update - the issues in the logs aren't related to this specific bug, so I opened bug 1243594

Comment 10

[Lina Butler [:lina]]

Is there a specific way to trigger this? I tried starting with a fresh profile and disconnecting/reconnecting Sync. Here's what I see:

> 1455322155725 browserwindow.syncui  DEBUG observed: weave:service:ready
> 1455322155735 browserwindow.syncui  DEBUG _loginFailed has sync state=error.login.reason.no_username
> 1455322157902 FirefoxAccounts DEBUG FxAccountsWebChannel message received: fxaccounts:loaded
> 1455322157904 FirefoxAccounts DEBUG FxAccountsWebChannel message details: {"command":"fxaccounts:loaded","messageId":null}
> 1455322157905 FirefoxAccounts WARN  Unrecognized FxAccountsWebChannel command: fxaccounts:loaded
> 1455322160962 FirefoxAccounts DEBUG FxAccountsWebChannel message received: fxaccounts:can_link_account
> 1455322160962 FirefoxAccounts DEBUG FxAccountsWebChannel message details: > {"command":"fxaccounts:can_link_account","data":{"email":"[e-mail]"},"messageId":1455322160913}
> 1455322160963 FirefoxAccounts DEBUG FxAccountsWebChannel response: > {"command":"fxaccounts:can_link_account","messageId":1455322160913,"data":{"ok":true}}
> 1455322161594 FirefoxAccounts DEBUG FxAccountsWebChannel message received: fxaccounts:login
> 1455322161594 FirefoxAccounts DEBUG FxAccountsWebChannel message details: > {"command":"fxaccounts:login","data":{"customizeSync":false,"email":"[e-mail]","keyFetchToken":"...","sessionToken":"...","uid":"f49cc49e62104d779f8f4431f2192259","unwrapBKey":"...","verified":true,"verifiedCanLinkAccount":true},"messageId":null}
> 1455322161597 FirefoxAccounts DEBUG setSignedInUser - aborting any existing flows
> 1455322161604 FirefoxAccounts WARN  Unknown FxA field name in user data, treating as in-memory: customizeSync
> 1455322161604 FirefoxAccounts WARN  Unknown FxA field name in user data, treating as in-memory: declinedSyncEngines
> 1455322161609 FirefoxAccounts DEBUG writing plain storage: ["email","sessionToken","uid","verified"]
> 1455322161628 FirefoxAccounts DEBUG writing secure storage: ["keyFetchToken","unwrapBKey"]
> 1455322161649 FirefoxAccounts DEBUG registering new device details
> 1455322161723 FirefoxAccounts DEBUG _updateAccountData with items: ["deviceId","isDeviceStale"]
> 1455322161724 FirefoxAccounts DEBUG Notifying observers of fxaccounts:onlogin
> 1455322161728 FirefoxAccounts DEBUG already verified
> 1455322161734 FirefoxAccounts DEBUG FxAccountsProfileClient: Initialized
> 1455322161736 FirefoxAccounts DEBUG already verified
> 1455322161737 FirefoxAccounts DEBUG fetchAndUnwrapKeys: token: 995d9f3732cd341eff1876d39be87d94af221e85e671e117dbb909f5d50500c2
> 1455322161738 FirefoxAccounts DEBUG fetchKeys: true
> 1455322161738 FirefoxAccounts DEBUG fetchKeys - the token is 995d9f3732cd341eff1876d39be87d94af221e85e671e117dbb909f5d50500c2
> 1455322161745 FirefoxAccounts DEBUG writing plain storage: ["email","sessionToken","uid","verified","deviceId"]
> 1455322161746 FirefoxAccounts DEBUG FxAccountsProfileClient: Requested profile
> 1455322161747 FirefoxAccounts DEBUG getOAuthToken enter
> 1455322161754 FirefoxAccounts DEBUG FxAccountsOAuthGrantClient Initialized
> 1455322161754 FirefoxAccounts DEBUG getOAuthToken fetching new token from: https://oauth.accounts.firefox.com/v1

Comment 11

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

Yeah, I can no longer reproduce this, so closing.

Comment 12

[Ada [:adalucinet]]

This issue is still reproducible with 46.0b10 (Build ID: 20160411042519) and also with latest Nightly 48.0a1, across platforms [1], with the following str:

1. Launch Firefox.
2. Via the 46 FirstRun page (https://www.mozilla.org/en-US/firefox/46.0/firstrun/) create a Firefox account.
3. Verify the account via e-mail.
Result: as soon as the account is verified, 'Sync encountered an error - see about:sync-log for the log file.' is thrown in the Browser Console. 

Please see the attached log files, for both Beta and Nightly. 

Mark, any ideas? Should we reopen this report or file a new one?

[1] Ubuntu 12.04 64-bit, Mac OS X 10.8, Windows 8.1 x86 and Windows XP x64

Comment 13

[Ada [:adalucinet]]

Attachment: error-sync-Beta.txt

Comment 14

[Ada [:adalucinet]]

Attachment: error-sync-Nightly.txt

Comment 15

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

Thanks - I think we probably failed to repro it as we didn't create a new account - I've reopened it and updated the summary.

Comment 16

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

This also happens when a user changes their password. In all cases, I believe it only happens sometimes.