Bugzilla

Richard Newman [:rnewman]

Reporter

Comment 2

•

7 years ago

Let me know if you need additional info from me. This bug is still haunting me

Comment 3

•

7 years ago

Chris, in the absence of Mark, could you dig into this (and dupe as appropriate)?

Assignee: nobody → ckarlof

Status: NEW → ASSIGNED

James Bonacci [:jbonacci]

Reporter

Comment 4

•

7 years ago

The latest log has changes a bit:

======================================
1407353011031	Sync.Service	INFO	Loading Weave 1.36.0
1407353011033	Sync.Engine.Clients	DEBUG	Engine initialized
1407353011035	Sync.Engine.Clients	DEBUG	Resetting clients last sync time
1407353011045	Sync.Engine.Bookmarks	DEBUG	Engine initialized
1407353011048	Sync.Engine.Forms	DEBUG	Engine initialized
1407353011054	Sync.Engine.History	DEBUG	Engine initialized
1407353011059	Sync.Engine.Passwords	DEBUG	Engine initialized
1407353011063	Sync.Engine.Prefs	DEBUG	Engine initialized
1407353011066	Sync.Engine.Tabs	DEBUG	Engine initialized
1407353011066	Sync.Engine.Tabs	DEBUG	Resetting tabs last sync time
1407353011072	Sync.Engine.Addons	DEBUG	Engine initialized
1407353011074	Sync.Service	INFO	Mozilla/5.0 (Windows NT 6.1; WOW64; rv:34.0) Gecko/20100101 Firefox/34.0
1407353011076	Sync.SyncScheduler	DEBUG	Clearing sync triggers and the global score.
1407353011077	Sync.Status	DEBUG	Status.service: success.status_ok => success.status_ok
1407353011077	Sync.Service	DEBUG	Caching URLs under storage user base: https://sync-23-us-west-2.sync.services.mozilla.com/1.5/983137/
1407353011078	Sync.Status	DEBUG	Status.service: success.status_ok => success.status_ok
1407353011078	Sync.Tracker.History	INFO	Adding Places observer.
1407353011102	Sync.Status	DEBUG	Status.service: success.status_ok => success.status_ok
1407353011105	Sync.Engine.AdblockPlus	DEBUG	Engine initialized
1407353011106	Sync.Status	DEBUG	Status.service: success.status_ok => success.status_ok
1407353011170	FirefoxAccounts	DEBUG	got keyPair
1407353011182	FirefoxAccounts	DEBUG	getCertificateSigned: true true
1407353012064	FirefoxAccounts	DEBUG	getCertificate got a new one: true
1407353012065	FirefoxAccounts	DEBUG	getAssertionFromCert
1407353012075	FirefoxAccounts	DEBUG	getAssertionFromCert returning signed: true
1407353012091	Sync.BrowserIDManager	DEBUG	Getting a token
1407353014710	Sync.BrowserIDManager	DEBUG	Successfully got a sync token
1407353014715	Sync.BulkKeyBundle	INFO	BulkKeyBundle being created for undefined
1407353014715	Sync.BrowserIDManager	INFO	Background fetch for key bundle done
1407353014716	Sync.Status	DEBUG	Status.login: success.login => success.login
1407353014716	Sync.Status	DEBUG	Status.service: success.status_ok => success.status_ok
1407353030399	Sync.SyncScheduler	DEBUG	Next sync in 3600000 ms.
1407353031648	Sync.Tracker.History	DEBUG	Saving changed IDs to history
1407353061107	Sync.Status	DEBUG	Status.service: success.status_ok => success.status_ok
1407353061108	Sync.SyncScheduler	DEBUG	Next sync in 3568892 ms.
1407353897132	Sync.Service	DEBUG	User-Agent: Firefox/34.0a1 FxSync/1.36.0.20140806030201.
1407353897132	Sync.Service	INFO	Starting sync at 2014-08-06 21:38:17
1407353897132	Sync.Service	DEBUG	In sync: should login.
1407353897133	Sync.Status	DEBUG	Status.service: success.status_ok => success.status_ok
1407353897133	Sync.Status	DEBUG	Status.service: success.status_ok => success.status_ok
1407353897133	Sync.Service	INFO	Logging in the user.
1407353897133	Sync.Service	DEBUG	Caching URLs under storage user base: https://sync-23-us-west-2.sync.services.mozilla.com/1.5/983137/
1407353897134	Sync.Service	DEBUG	Fetching unlocked auth state returned success.status_ok
1407353897135	Sync.BrowserIDManager	DEBUG	_ensureValidToken already has one
1407353898069	Sync.Resource	DEBUG	mesg: GET success 200 https://sync-23-us-west-2.sync.services.mozilla.com/1.5/983137/info/collections
1407353898069	Sync.Resource	DEBUG	GET success 200 https://sync-23-us-west-2.sync.services.mozilla.com/1.5/983137/info/collections
1407353898069	Sync.Service	DEBUG	Fetching global metadata record
1407353898070	Sync.BrowserIDManager	DEBUG	_ensureValidToken already has one
1407353898271	Sync.Resource	DEBUG	mesg: GET success 200 https://sync-23-us-west-2.sync.services.mozilla.com/1.5/983137/storage/meta/global
1407353898271	Sync.Resource	DEBUG	GET success 200 https://sync-23-us-west-2.sync.services.mozilla.com/1.5/983137/storage/meta/global
1407353898271	Sync.Service	DEBUG	Clearing cached meta record. metaModified is undefined, setting to 1407277297.2
1407353898272	Sync.BrowserIDManager	DEBUG	_ensureValidToken already has one
1407353898470	Sync.Resource	DEBUG	mesg: GET success 200 https://sync-23-us-west-2.sync.services.mozilla.com/1.5/983137/storage/meta/global
1407353898470	Sync.Resource	DEBUG	GET success 200 https://sync-23-us-west-2.sync.services.mozilla.com/1.5/983137/storage/meta/global
1407353898470	Sync.Service	DEBUG	Weave Version: 1.36.0 Local Storage: 5 Remote Storage: 5
1407353898470	Sync.Service	INFO	Sync key is up-to-date: no need to upgrade.
1407353898470	Sync.Service	DEBUG	Fetching and verifying -- or generating -- symmetric keys.
1407353898470	Sync.Service	INFO	Testing info/collections: {"passwords":1407277294.85,"adblockplus":1407277296.6,"clients":1407308613.17,"crypto":1399963936.95,"forms":1407328653.74,"meta":1407277297.2,"bookmarks":1407303875.03,"prefs":1407328862.51,"history":1407350725.98}
1407353898470	Sync.CollectionKeyManager	INFO	Testing for updateNeeded. Last modified: 0
1407353898470	Sync.Service	INFO	collection keys reports that a key update is needed.
1407353898471	Sync.BrowserIDManager	DEBUG	_ensureValidToken already has one
1407354198473	Sync.Service	WARN	Got exception "Error: Aborting due to channel inactivity." fetching cryptoKeys.
1407354198474	Sync.Status	DEBUG	Status.login: success.login => error.login.failed
1407354198474	Sync.Status	DEBUG	Status.service: success.status_ok => error.login.failed
1407354198474	Sync.Service	WARN	Failed to fetch symmetric keys. Failing remote setup.
1407354198474	Sync.Service	WARN	Remote setup failed.
1407354198474	Sync.SyncScheduler	DEBUG	Clearing sync triggers and the global score.
1407354198475	Sync.SyncScheduler	DEBUG	Next sync in 3600000 ms.

Updated

•

7 years ago

Whiteboard: [qa?]

Comment 5

•

7 years ago

This looks like it could be a network-connectivity issue, causing failures at different parts of the stack on different runs.  Henrik, does this failure occur on every sync or is it sporadic?  (You can check this by turning the "services.sync.log.appender.file.logOnSuccess" setting in about:config, and checking for any success logs in amongst all the errors.)

Flags: needinfo?(bugzilla)

Reporter

Comment 6

•

7 years ago

the sync seems to have started to be ok (I think)

At least I get a "success-1407787012136.txt" file generated

Not sure why there would be any problem with my network. I have a perfectly fine network. Never had a problem with any other applications in regards to the network.


The latest error log file "only" says:

1407779567326	Sync.ErrorHandler	DEBUG	Flushing file log.
1407779567327	Sync.Service	DEBUG	Exception: Error: App. Quitting (resource://services-sync/resource.js:394:18) JS Stack trace: Res_get@resource.js:414:12 < Sync11Service.prototype._fetchInfo@service.js:540:14 < sync@enginesync.js:77:16 < onNotify@service.js:1275:7 < WrappedNotify@util.js:148:21 < WrappedLock@util.js:103:16 < _lockedSync@service.js:1265:12 < sync/<@service.js:1257:14 < WrappedCatch@util.js:77:16 < sync@service.js:1245:5
1407779567328	Sync.BrowserIDManager	DEBUG	Getting an assertion
1407779567329	FirefoxAccounts	DEBUG	enter getAssertion()
1407779567352	FirefoxAccounts	DEBUG	getKeyPair: already have a keyPair
1407779567352	FirefoxAccounts	DEBUG	 getCertificate already had one
1407779567352	FirefoxAccounts	DEBUG	getAssertionFromCert
1407779567354	Sync.ErrorHandler	DEBUG	Log cleanup threshold time: 1406915567354
1407779567492	FirefoxAccounts	DEBUG	getAssertionFromCert returning signed: true
1407779567494	Sync.BrowserIDManager	DEBUG	Getting a token
1407779567544	Sync.ErrorHandler	DEBUG	Done deleting files.
1407779567617	Sync.BrowserIDManager	ERROR	Non-authentication error in _fetchTokenForUser: Client error.
1407779567617	Sync.Status	DEBUG	Status.login: success.login => error.login.reason.network
1407779567617	Sync.Status	DEBUG	Status.service: success.status_ok => error.login.failed
1407779567617	Sync.SyncScheduler	DEBUG	Clearing sync triggers and the global score.
1407779567618	Sync.SyncScheduler	DEBUG	Next sync in 600000 ms.

Flags: needinfo?(bugzilla)

Richard Newman [:rnewman]

Comment 7

•

7 years ago

> Not sure why there would be any problem with my network. I have a perfectly fine network.
> Never had a problem with any other applications in regards to the network.

It could also be some problems on the server side that simply show up as network timeouts on your end.

> 1407779567327	Sync.Service	DEBUG	Exception: Error: App. Quitting 

This is normal, it simply means that you happened to quit firefox while it was in the middle of a sync.  No harm should come form this.

> 1407779567617	Sync.BrowserIDManager	ERROR	Non-authentication error in _fetchTokenForUser: Client error.

But here we have another, different error occurring in roughly the same place.  I'll dig in a little further, but I'm encouraged by the fact that it succeeds at least *some* of the time.

Comment 8

•

7 years ago

(In reply to Ryan Kelly [:rfkelly] from comment #7)

> > 1407779567327	Sync.Service	DEBUG	Exception: Error: App. Quitting 
> 
> This is normal, it simply means that you happened to quit firefox while it
> was in the middle of a sync.  No harm should come form this.

Or that an async operation in the middle of a sync never returned, which seems to be happening a lot these days. The endless waiting is interrupted by "App. Quitting", which prompts the log to write and everything to continue to a near-normal failure. It looks just like a quit.

Comment 9

•

7 years ago

The error string "Client error." turns out to narrow it down a little.  The thing being logged is either a TokenServerClientError or a TokenServerClientNetworkError, whose default "message" attribute is the only instance of this string I can find in the client code.

Since I can't find anywhere that creates a raw TokenServerClientError with its default "message" attribute, I presume it's actually a TokenServerClientNetworkError instance being thrown.  Which would tie in with the theory of sporadic network trouble somewhere between the client and the tokenserver.

The logging code here should really be calling toString() on the error, rather than directly accessing its "message" attribute, to give more details of what's going on.

Chris Karlof [:ckarlof]

Assignee

Comment 10

•

7 years ago

It's early to dup, but this could be the same error as in Bug 1052549.

"This could be a regression of Bug 624436. Gavin suggested that it may have been introduced by resolution of Bug 237623."

Comment 11

•

7 years ago

Henrik, when these errors occur do they present as a user-visible error bar (like the one in Bug 1052549) or do they just result in error logs being written in the background?

Flags: needinfo?(bugzilla)

Reporter

Comment 12

•

7 years ago

I saw both. I saw an error bar, but I was mostly watching the error logs

Flags: needinfo?(bugzilla)

Comment 13

•

7 years ago

Attached file Earliest captured error log — Details

Comment 14

•

7 years ago

Attached file Latest captured error log — Details

Comment 15

•

7 years ago

I'm experiencing the same thing with my home browser (Iceweasel 31) -- FxA Sync had been working fine for me up until about two weeks ago.  I got an error bar with 'Sync has not been able to sync for 14 days' -- so I went and dug out the logs and attached them.  I'm not sure there's anything terribly useful in there, but there they are.

Chris Karlof [:ckarlof]

Assignee

Comment 16

•

7 years ago

Given that Karl also has a missing keyFetchToken, maybe we should prioritize Bug 1071786 more.

Chris Karlof [:ckarlof]

Assignee

Comment 17

•

7 years ago

Karl or Henrik, do you have Master Password enabled with FxA Sync?

Flags: needinfo?(kthiessen)

Flags: needinfo?(bugzilla)

Comment 18

•

7 years ago

I do not.

Flags: needinfo?(kthiessen)

Mark Hammond [:markh] [:mhammond]

Comment 19

•

7 years ago

Strange data point:  That profile syncs fine if I use Nightly (currently 36.0a1 (2014-10-14)) -- it's just in Iceweasel 31.1.0 that it fails.

Hope this is helpful.

Comment 20

•

7 years ago

Karl, what addons do you have installed?  I'm particularly interested in login manager extensions/replacements.

Flags: needinfo?(kthiessen)

Comment 21

•

7 years ago

On Iceweasel, I have: Adblock Plus 2.6.4, DuckDuckGo Plus 0.4.2, HttpFox 0.8.14, It's All Text! 1.8.1, OverbiteFF 3.0.1627, Send tab to device 0.6, SQLite Manager 0.8.1, and Test Pilot 1.2.3.

I do not have any login manager extensions/replacements installed that I am aware of.

Flags: needinfo?(kthiessen)