1071786 - Diagnose and respond to situations where the keyFetchToken is missing

Status: RESOLVED WORKSFORME

(Firefox :: Firefox Accounts, defect, P3)

Description

[Ryan Kelly [:rfkelly]]

In FxAccountsInternal.getKeys, we explicitly check for a keyFetchToken and error out if we don't have one, producing the "No keyFetchToken" log message as seen in e.g. Bug 1067702:

  http://hg.mozilla.org/mozilla-central/file/9e193395b912/services/fxaccounts/FxAccounts.jsm#l611

However, getKeys calls the internal fetchAndUnwrapKeys method, and that one has special handling to trigger a sign-out when missing keyFetchToken:

  http://hg.mozilla.org/mozilla-central/file/9e193395b912/services/fxaccounts/FxAccounts.jsm#l641

It seems like the force-signout behavior is what we want, since otherwise there's no way to actually obtain a new keyFetchToken.  But this path is never triggered because getKeys fails out without calling it.

Perhaps getKeys should also trigger sign-out in this case, and/or just let it fall through to the handling inside fetchAndUnwrapKeys?

Alternately, perhaps we need to surface this "No keyFetchToken" as an AuthenticationError so that it will be handled better in the error reporting at:

    http://hg.mozilla.org/mozilla-central/file/9e193395b912/services/sync/modules/browserid_identity.js#l573

Comment 1

[Mike Hoye [:mhoye]]

This looks like a good mentored bug. Chris, feel like mentoring this if a contributor comes by?

Comment 2

[Chris Karlof [:ckarlof]]

Sure.

Comment 3

[James Bonacci [:jbonacci]]

Upped the Priority based on https://bugzilla.mozilla.org/show_bug.cgi?id=1047700#c16

Comment 4

[Chris Karlof [:ckarlof]]

> Alternately, perhaps we need to surface this "No keyFetchToken" as an AuthenticationError so that it will be handled better in the error reporting at:
> http://hg.mozilla.org/mozilla-central/file/9e193395b912/services/sync/modules/browserid_identity.js#l573

This would certainly help. I don't exactly know how we got in the situation where these users didn't have a keyFetchToken, but they do need to log back in to fix it. 

Service.verifyLogin is supposed to raise the appropriate authentication error earlier on if the keys or keyFetchToken are missing (http://hg.mozilla.org/mozilla-central/file/9e193395b912/services/sync/modules/service.js#l694), so it's unclear how Karl and Henrik seemed to have gotten as far as they did without either. Something related to MP being enabled?

Comment 5

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

(In reply to Chris Karlof [:ckarlof] from comment #4)

> This would certainly help. I don't exactly know how we got in the situation
> where these users didn't have a keyFetchToken, but they do need to log back
> in to fix it. 

I'm looking at a quick patch for this.  I don't think we should sign the user out, as that would be surprising to the user and avoid some of the nice UI we have - putting things in a "needs reauth" state makes far more sense to me.

> modules/service.js#l694), so it's unclear how Karl and Henrik seemed to have
> gotten as far as they did without either. Something related to MP being
> enabled?

Yes, I've spent some time trying to reproduce this and I've failed.  It could be MP enabled, but I can't provoke it.  My next best guess is either a replacement login manager, or a corrupt login store.  Or something :)

Comment 6

[Chris Karlof [:ckarlof]]

(In reply to Mark Hammond [:markh] from comment #5)
> (In reply to Chris Karlof [:ckarlof] from comment #4)
 
> I'm looking at a quick patch for this.  I don't think we should sign the
> user out, as that would be surprising to the user and avoid some of the nice
> UI we have - putting things in a "needs reauth" state makes far more sense
> to me.
> 

Yes, I agree. This is what I meant.

The confusing part to me is that it seems like this is what unlockAndVerifyAuthState is supposed to do when called in Service.

Comment 7

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

(In reply to Chris Karlof [:ckarlof] from comment #6)
> The confusing part to me is that it seems like this is what
> unlockAndVerifyAuthState is supposed to do when called in Service.

Indeed, even more confusing is that in browserid_identity's _fetchTokenForUser, there is a call to this._canFetchKeys() - so if we have no kA/kB and no keyFetchToken it looks like we can't get into this._fxaService.getKeys() - but that is where we are failing due to no keyFetchToken.  If we *do* have kA/kB we don't even try to get into getKeys().

But - I think we are simply looking at clients before this change landed - bug 1013064 landed in 34.

However, even on trunk I think we have a problem - if I simulate us not having kA, kB or keyFetchToken, then (a) I hit this block and bail early and (b) sync still never shows the error notification bar due to sync never starting (which seems due to timing - this error causes us to bail early enough that sync never gets into a STATUS_OK state, so never starts a sync, whereas the "normal" failing case means we are still doing the auth dance and briefly have STATUS_OK before we notice an auth error)

I think browserid_identity needs a bit of a make-over so the bulk of the auth dance happens in ensureLoggedIn() rather than a side-effect of the manager being initialized.

So I'm still quite lost here...

Comment 8

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

Ryan is getting this too.  I wonder if it is OSX only?

Comment 9

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

(In reply to Mark Hammond [:markh] from comment #8)
> Ryan is getting this too.  I wonder if it is OSX only?

(In reply to Mark Hammond [:markh] from comment #7)
> But - I think we are simply looking at clients before this change landed -
> bug 1013064 landed in 34.

Also FTR, in the logs Ryan sent me, 33.1 is the version being used.  So it's still unclear if we are seeing this in 34+

Comment 10

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

hrmp - sorry for spamming, but I just had another thought:  running 34 will migrate credentials to the login manager then remove some from the .json on disk.  If you then start 33 again you may well get into this state!  I need to see if I can repro this way.

Comment 11

[Randy Wright]

My experience tends to support the idea in comment 10 that migrating between versions, especially going backwards - may put sync into this state.  This occurs for me on a Linux installation on which I frequently switch between firefox versions - standard 35.0.1, esr 31.4.0, and developer edition 37.0a2.  Sync works fine in the standard and developer editions, but then when I switch back to esr, the error shows up:

1424616708142	Sync.ErrorHandler	DEBUG	Flushing file log.
1424616708143	Sync.BrowserIDManager	ERROR	Background fetch for key bundle failed: No keyFetchToken
1424616708143	Sync.BrowserIDManager	ERROR	Could not authenticate: No keyFetchToken
1424616708144	Sync.SyncScheduler	DEBUG	Clearing sync triggers and the global score.
1424616708144	Sync.SyncScheduler	DEBUG	Next sync in 3600000 ms.

Disconnecting from sync and then logging back into sync tends to fix it.

Comment 12

[Chris Karlof [:ckarlof]]

Mark, I'm trying to re-prioritize this bug. Based on our past telemetry data on auth errors, do we have any sense of how often this happens in practice?

Comment 15

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

TIL that, sadly, as soon as you remove a probe from Nightly, the telemetry system stop collecting that probe from *all* channels. We removed problems in 48 (bug 1261181) under the assumption we could still get telemetry from 47 while it is in release. That turns out to not be true.

We probably need to re-add these probes to get meaningful data :(

Comment 16

[komalbharadiya]

Hey,Is this issue open? Can I work on this? Need help!

Comment 17

[Mike Hoye [:mhoye]]

It might be, let's find out.

Comment 18

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

(In reply to komalbharadiya from comment #16)

Hey,Is this issue open? Can I work on this? Need help!

Thanks for your interest, but we haven't seen this bug for quite some time, so I'm going to close it. I see you also asked about some other bugs, hopefully one of them will work out for you!