Closed Bug 1047700 Opened 10 years ago Closed 8 years ago

ERROR Non-authentication error in _fetchTokenForUser: undefined

Categories

(Firefox :: Sync, defect)

Product:
Firefox
Component:
Sync
Platform:
x86_64
Windows 7
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

()

Status:
RESOLVED WORKSFORME

People

(Reporter: bugzilla, Assigned: ckarlof)

References

(Blocks 1 open bug)

Details

(Whiteboard: [qa?])

Attachments

(2 files)

Earliest captured error log
2.70 KB, text/plain
Details
Latest captured error log
2.00 KB, text/plain
Details
after updating to latest nightly I keep getting: 1406933528779 Sync.ErrorHandler DEBUG Flushing file log. 1406933528780 Sync.Status DEBUG Status.sync: error.sync.prolonged_failure => error.sync.prolonged_failure 1406933528780 Sync.Status DEBUG Status.service: error.sync.failed => error.sync.failed 1406933528780 Sync.Service DEBUG Exception: No keyFetchToken No traceback available 1406933528780 Sync.Service DEBUG Not syncing: login returned false. 1406933528781 Sync.BrowserIDManager INFO currentAuthState returning error.login.reason.network due to previous failure 1406933528781 Sync.Status DEBUG Status.login: error.login.reason.network => error.login.reason.network 1406933528781 Sync.Status DEBUG Status.service: error.sync.failed => error.login.failed 1406933528781 Sync.BrowserIDManager INFO currentAuthState returning error.login.reason.network due to previous failure 1406933528781 Sync.Status DEBUG Status.login: error.login.reason.network => error.login.reason.network 1406933528781 Sync.Status DEBUG Status.service: error.login.failed => error.login.failed 1406933528782 Sync.BrowserIDManager INFO currentAuthState returning error.login.reason.network due to previous failure 1406933528782 Sync.Status DEBUG Status.login: error.login.reason.network => error.login.reason.network 1406933528782 Sync.Status DEBUG Status.service: error.login.failed => error.login.failed 1406933528782 Sync.BrowserIDManager INFO currentAuthState returning error.login.reason.network due to previous failure 1406933528782 Sync.Status DEBUG Status.login: error.login.reason.network => error.login.reason.network 1406933528782 Sync.Status DEBUG Status.service: error.login.failed => error.login.failed 1406933528785 Sync.ErrorHandler DEBUG Log cleanup threshold time: 1406069528785 1406933528804 Sync.ErrorHandler DEBUG No logs to clean up. 1406933528805 Sync.ErrorHandler DEBUG Log cleanup threshold time: 1406069528805 1406933528810 Sync.ErrorHandler DEBUG No logs to clean up. 1406934798481 Sync.Service DEBUG User-Agent: Firefox/34.0a1 FxSync/1.36.0.20140801030201. 1406934798481 Sync.Service INFO Starting sync at 2014-08-02 01:13:18 1406934798482 Sync.Service DEBUG In sync: should login. 1406934798482 Sync.BrowserIDManager INFO currentAuthState returning error.login.reason.network due to previous failure 1406934798482 Sync.Status DEBUG Status.login: error.login.reason.network => error.login.reason.network 1406934798482 Sync.Status DEBUG Status.service: error.login.failed => error.login.failed 1406934798482 Sync.BrowserIDManager INFO currentAuthState returning error.login.reason.network due to previous failure 1406934798482 Sync.Status DEBUG Status.login: error.login.reason.network => error.login.reason.network 1406934798482 Sync.Status DEBUG Status.service: error.login.failed => error.login.failed 1406934798485 Sync.BrowserIDManager INFO Waiting for user to be verified. 1406934798485 FirefoxAccounts DEBUG already verified 1406934798486 Sync.BrowserIDManager INFO Starting fetch for key bundle. 1406934798486 Sync.BrowserIDManager INFO Fetching assertion and token from: https://token.services.mozilla.com/1.0/sync/1.5 1406934798486 FirefoxAccounts DEBUG already verified 1406934798487 Sync.BrowserIDManager ERROR Non-authentication error in _fetchTokenForUser: undefined 1406934798488 Sync.Status DEBUG Status.login: error.login.reason.network => error.login.reason.network 1406934798488 Sync.Status DEBUG Status.service: error.login.failed => error.login.failed 1406934798488 Sync.SyncScheduler DEBUG Clearing sync triggers and the global score. 1406934798488 Sync.SyncScheduler DEBUG Next sync in 3600000 ms.
Let me know if you need additional info from me. This bug is still haunting me
Chris, in the absence of Mark, could you dig into this (and dupe as appropriate)?
Assignee: nobody → ckarlof
Status: NEW → ASSIGNED
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.
Whiteboard: [qa?]
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)
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)
> 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.
(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.
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.
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."
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)
I saw both. I saw an error bar, but I was mostly watching the error logs
Flags: needinfo?(bugzilla)
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.
Given that Karl also has a missing keyFetchToken, maybe we should prioritize Bug 1071786 more.
Karl or Henrik, do you have Master Password enabled with FxA Sync?
Flags: needinfo?(kthiessen)
Flags: needinfo?(bugzilla)
I do not.
Flags: needinfo?(kthiessen)
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.
Karl, what addons do you have installed? I'm particularly interested in login manager extensions/replacements.
Flags: needinfo?(kthiessen)
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)
Flags: needinfo?(bugzilla)
I also had issues with authentication during sync. My error log looked pretty much the same as the one in this bug report, which is why Google led me here. The error occurred on both machines in my home network for several weeks. The issue was solved by restarting my router! I cannot really explain why that would make sense, as I never had any (other) network issues. Anyway, affected people should also look at their network infrastructure: Does the issue persist when connecting through a different Internet entry point? (It did not for me...)
We've tweaked the logging at various times over the last year or so, so we're confident the logs are now more descriptive. Please reopen if you still have uninformative logs.
Status: ASSIGNED → RESOLVED
Closed: 8 years ago
Resolution: --- → WORKSFORME
Component: Firefox Sync: Backend → Sync
Product: Cloud Services → Firefox
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: