Open Bug 1195569 Opened 5 years ago Updated 3 years ago

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

Categories

(Firefox :: Firefox Accounts, defect, P3)

defect

Tracking

()

REOPENED

People

(Reporter: markh, Unassigned)

References

Details

(Whiteboard: [fxsync])

Attachments

(5 files)

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: AccountState.prototype.resolve@FxAccounts.jsm:155:29 < getUserAccountData/<@FxAccounts.jsm:139:14 < Handler.prototype.process@Promise-backend.js:934:23 < this.PromiseWalker.walkerLoop@Promise-backend.js:813:7 < Promise*this.PromiseWalker.scheduleWalkerLoop@Promise-backend.js:744:11 < this.PromiseWalker.schedulePromise@Promise-backend.js:776:7 < this.PromiseWalker.completePromise@Promise-backend.js:711:7 < onReady@Weave.js:94:7 < this.Observers.notify@observers.js:93:5 < onNextTick@service.js: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.
Flags: firefox-backlog?
Flags: firefox-backlog? → firefox-backlog+
Component: Sync → FxAccounts
Priority: -- → P1
Product: Firefox → Core
Whiteboard: [fxsync]
Iteration: --- → 43.3 - Sep 21
Assignee: nobody → zack.carter
Via bug 1209481, it seems this happens both when creating a new account and logging in to an existing one.
Iteration: 43.3 - Sep 21 → ---
Re-assigning to Kit.
Assignee: zack.carter → kcambridge
Status: NEW → ASSIGNED
`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.
Kazz, can you please attach the relevant parts of your log file showing the error you mention?
Flags: needinfo?(kazz)
Flags: needinfo?(kazz)
Attached file 2nd log
Attached file 3rd log
(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?
Thanks for the update - the issues in the logs aren't related to this specific bug, so I opened bug 1243594
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":"kcambridge+sync1@mozilla.com"},"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":"kcambridge+sync1@mozilla.com","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
Flags: needinfo?(markh)
Yeah, I can no longer reproduce this, so closing.
Status: ASSIGNED → RESOLVED
Closed: 5 years ago
Flags: needinfo?(markh)
Resolution: --- → WORKSFORME
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
Flags: needinfo?(markh)
Attached file error-sync-Beta.txt
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.
Assignee: kcambridge → nobody
Status: RESOLVED → REOPENED
Flags: needinfo?(markh)
Resolution: WORKSFORME → ---
Summary: First sync always creates an error log → First sync after creating a new account always creates an error log
Priority: P1 → P3
This also happens when a user changes their password. In all cases, I believe it only happens sometimes.
Duplicate of this bug: 1014266
Product: Core → Firefox
You need to log in before you can comment on or make changes to this bug.