975625 - Sync fails to sync data with invalid signature on Android 2.2

Status: RESOLVED WORKSFORME

(Firefox for Android Graveyard :: Android Sync, defect, P1)

Description

[Edwin Wong [:edwong]]

I'm on galaxy s with android 2.2 Fx nightly.

1. add account
2. sign in with existing account
3. in Fx - add a bookmark
4. goto settings > accounts
5. tap sync now icon

actual: bookmark is not sync to my desktop, nor does my desktop fx sync mobile > bookmarks

Comment 1

[Richard Newman [:rnewman]]

Edwin: you can save everyone a bunch of time if you provide a full ADB log for the period in question whenever you file. It's the first thing we're going to ask for.

Thanks!

Comment 2

[ewong]

clock skew?

901): fennec :: FxAccountSyncAdapter :: Syncing FxAccount account named like [e-mail] for authority org.mozilla.fennec.db.browser with instance org.mozilla.gecko.fxa.sync.FxAccountSyncAdapter@47da5ba8.
I/FxAccounts( 3901): fennec :: FxAccountSyncAdapter :: handleTransition: LogMessage('sign succeeded') to Married
I/FxAccounts( 3901): fennec :: FxAccountSyncAdapter :: handleFinal: in Married
W/FxAccounts( 3901): fennec :: TokenServerClient :: {"location":"body","description":"Unauthorized","name":""}
W/FxAccounts( 3901): fennec :: FxAccountSyncAdapter :: Remote verifier returned failure: {"reason":"invalid signature","status":"failure"}
E/FxAccounts( 3901): fennec :: FxAccountSyncAdapter :: Failed to get token.
E/FxAccounts( 3901): org.mozilla.gecko.tokenserver.TokenServerException$TokenServerInvalidCredentialsException: {"status":"invalid-credentials","errors":[{"location":"body","description":"Unauthorized","name":""}]}

Comment 3

[ewong]

Attachment: foo.txt

adb logcat | grep FxAccounts

Comment 4

[Nick Alexander :nalexander [he/him]]

Comment on attachment 8380072 [details]
foo.txt

edwin, this log is pretty useful.  Thanks!  It sure looks like persistent skew that we never get past.  Digging in.

Comment 7

[Edwin Wong [:edwong]]

we've disabled clock skew issues from the server temporarily and I'm still failing to sync on android 2.2.  I'm using Aurora today, since Nightly is busted.  Here's my adb logcat | grep -in account

6019:D/SyncManager( 2505): failed sync operation authority: org.mozilla.fennec_aurora.db.browser account: Account {name=[e-mail], type=org.mozilla.fennec_account} extras: [] syncSource: 0 when: 7476378 expedited: false, SyncResult: stats [ numIoExceptions: 1 numUpdates: 1]
6034:D/GoogleLoginService( 2678): onBind: Intent { act=android.accounts.AccountAuthenticator cmp=com.google.android.gsf/.loginservice.GoogleLoginService }
6035:W/GoogleLoginService( 2678): Device has no accounts: sending Intent { act=com.google.android.gsf.LOGIN_ACCOUNTS_MISSING }
6036:E/vending ( 5100): [16] AccountManagerHelper.getAuthTokenBlocking(): no matching accounts for ANDROID
6069:I/FxAccounts( 5166): fennec_aurora :: FxAccountSyncAdapter :: Syncing FxAccount account named like [e-mail] for authority org.mozilla.fennec_aurora.db.browser with instance org.mozilla.gecko.fxa.sync.FxAccountSyncAdapter@47c60778.
6076:I/FxAccounts( 5166): fennec_aurora :: FxAccountSyncAdapter :: handleTransition: LogMessage('sign succeeded') to Married
6077:I/FxAccounts( 5166): fennec_aurora :: FxAccountSyncAdapter :: handleFinal: in Married
6086:W/FxAccounts( 5166): fennec_aurora :: TokenServerClient :: {"location":"body","description":"Unauthorized","name":""}
6092:W/FxAccounts( 5166): fennec_aurora :: FxAccountSyncAdapter :: Remote verifier returned failure: {"reason":"invalid signature","status":"failure"}
6093:E/FxAccounts( 5166): fennec_aurora :: FxAccountSyncAdapter :: Failed to get token.
6094:E/FxAccounts( 5166): org.mozilla.gecko.tokenserver.TokenServerException$TokenServerInvalidCredentialsException: {"status":"invalid-credentials","errors":[{"location":"body","description":"Unauthorized","name":""}]}

Comment 8

[Aaron Train [:aaronmt]]

Attachment: log.log

Log from my Samsung Nexus S running Aurora 29.0a2 -- network time enabled, correct  time

Comment 9

[Edwin Wong [:edwong]]

[14:33]  <rnewman> rfkelly: did the clock-ignore change roll out to fxa, token, and storage production yet?
[14:33]  <rfkelly> I'll check
[14:35]  <rfkelly> rnewman AaronMT nope, it didn't get rolled out yet; I'll push for it to be so

Comment 10

[Nick Alexander :nalexander [he/him]]

For what it's worth, I successfully signed into and synced against an account today with a Galaxy Mini running Android 2.3.6.

Comment 11

[Nick Alexander :nalexander [he/him]]

(In reply to Nick Alexander :nalexander from comment #10)
> For what it's worth, I successfully signed into and synced against an
> account today with a Galaxy Mini running Android 2.3.6.

This morning, before (I think!) any token server mitigations were live in production.

Comment 12

[Aaron Train [:aaronmt]]

What other variable is causing this issue? My device has correct time and date and still get invalid-timestamp after signing in today.

Comment 13

[Richard Newman [:rnewman]]

(In reply to Aaron Train [:aaronmt] from comment #12)
> What other variable is causing this issue? My device has correct time and
> date and still get invalid-timestamp after signing in today.

Ryan, any thoughts?

Comment 14

[Ryan Kelly [:rfkelly]]

I'm not aware of any other common causes of this error.  For clarity, are we talking about an "invalid-timestamp" response from the tokenerver?  Can we please get a fresh logfile of a failed login attempt and I'll trawl through it for additional clues?

Comment 15

[Aaron Train [:aaronmt]]

Yet again I see this on my Samsung Galaxy SIV (Android 4.4.2) today. Network time, no variance.

> For clarity, are we talking about an "invalid-timestamp" response from the tokenerver?

You tell me?

See attached logcat

Comment 16

[Aaron Train [:aaronmt]]

Attachment: logcat.log

Comment 17

[Aaron Train [:aaronmt]]

What's happening to me today is that first Sync (on sign-in) does not work at all (see above log).

Second attempt at syncing *does* work.

Comment 18

[Aaron Train [:aaronmt]]

Nick explained to me that what I am seeing is actually expected (see bug 979075)

... "11:44  nalexander: all it is is that the first time we talk to the relevant server, we don't have the skew correct. We'll do an extra HTTP request to get the skew in future. We anticipated a server-side mitigation landing earlier for this; apparently that got delayed.  Expect the above ticket to land in a few days."(In reply to Aaron Train [:aaronmt] from comment #17)

Comment 19

[Ryan Kelly [:rfkelly]]

> {"reason":"assertion issued later than verification date","status":"failure"}

This is new and unusual, and not treated by any server-side mitigation.  It suggests that your network-time-synced device has its clock a tiny bit ahead of the verifier, and you're hitting this longstanding bug in jwcrypto: https://github.com/mozilla/jwcrypto/issues/58

Nick, does android apply the "issue things 10 seconds in the past" hack that we had to apply on the server to work around this issue?

Comment 20

[Ryan Kelly [:rfkelly]]

I want to note that we seem to be dealing with two separate issues here.

Aaron's issue is timestamp-related and could be partially mitigated by the server-side fixes, and maybe with the issue-in-the-past hack if it's not done already.

Edwin's issue appears to be a problem with the actual signature generated by his client device, which we've been debugging in IRC.  (Specifically it seems to be attaching an "SHA1withRSA" signature when it should be attaching an "SHA256withRSA" signature).

Comment 21

[Richard Newman [:rnewman]]

Bear in mind that Android clocks can be as wrong forward as they are back.

Comment 22

[Nick Alexander :nalexander [he/him]]

This appears to be a multi-faceted issue, but I dug deep into edwong's PII logs (thanks!) and now I believe that Android 2.2 just screws the SHA256withRSA signature entirely.  The signature is different on my Android 2.2 emulator (and agrees with edwong's device) than it is on my desktop and many Android 2.3+ phones.  It's just wrong.

I think there are other confounding issues here, but I'll dig in further to find a report of this bug and to generate a test case for edwong to reproduce, and then we'll make a decision about mitigation.

My Android motto is now: "Android: doing the right thing right is not enough."

Comment 23

[Richard Newman [:rnewman]]

Very inclined to say "no Sync on 2.2". We already know the perf will be unsatisfactory, and sinking time into a platform that we only continue to support because we don't have 2.3 test machines seems foolish.

Comment 24

[Nick Alexander :nalexander [he/him]]

(In reply to Richard Newman [:rnewman] from comment #23)
> Very inclined to say "no Sync on 2.2". We already know the perf will be
> unsatisfactory, and sinking time into a platform that we only continue to
> support because we don't have 2.3 test machines seems foolish.

I am inclined to agree, but the technical details of "no Sync on 2.2" are not, to my eye, easy to arrange.  There are many Sync entry points, and I know of no way to smoothly condition them all on the device's platform level at runtime.

We might be able to finesse this particular problem by using DSA signatures instead; the code exists and is decently tested.  We'd just need to flip a switch and migrate some users.

Comment 25

[Richard Newman [:rnewman]]

(In reply to Nick Alexander :nalexander from comment #24)

> I am inclined to agree, but the technical details of "no Sync on 2.2" are
> not, to my eye, easy to arrange.  There are many Sync entry points, and I
> know of no way to smoothly condition them all on the device's platform level
> at runtime.

Dynamically remove Settings menu item (it's just code).

Don't show Sync promo banner (slightly more messy to make it 'nice', but still not hard to achieve).

Have FxAccountGetStartedActivity throw you at a SUMO page saying "sorry, Sync isn't supported on your version of Android".

Remove all of these hacks in a few months when we kill 2.2.

What am I missing?

Comment 26

[Edwin Wong [:edwong]]

I can try this on a android 2.3 device.  Android 2.x is 20% of the market... if you believe this:
http://developer.android.com/about/dashboards/index.html

Comment 27

[Nick Alexander :nalexander [he/him]]

(In reply to Edwin Wong [:edwong] from comment #26)
> I can try this on a android 2.3 device.  Android 2.x is 20% of the market...
> if you believe this:
> http://developer.android.com/about/dashboards/index.html

Please do.  I see people posting about this issue for 2.2 devices, but not 2.3 devices.  I successfully tested on a 2.3.6 device.  If we're just cutting out 2.2 devices, I see 1.2%, which I deem Reasonable To Ignore.

Comment 28

[Richard Newman [:rnewman]]

I think we have fairly solid plans to drop 2.2 as soon as we can. And even disregarding the market as a whole, I'd go so far as to term Sync incompatible with 2.2, because you are almost guaranteed not to have enough RAM or storage, and almost guaranteed not to have the patience to have it chew up all of your CPU. See also Bug 792148.

Comment 29

[Aaron Train [:aaronmt]]

(In reply to Ryan Kelly [:rfkelly] from comment #20)
> I want to note that we seem to be dealing with two separate issues here.
> 
> Aaron's issue is timestamp-related and could be partially mitigated by the
> server-side fixes, and maybe with the issue-in-the-past hack if it's not
> done already.

Splitting this into a new bug.

Comment 30

[Edwin Wong [:edwong]]

I have a 2.3.3 Droid X (version 1) and i get this in logcat:
10985:03-06 14:58:02.469  3493  3696 W FxAccounts: fennec :: TokenServerClient :: {"location":"body","description":"Unauthorized","name":""}
10986:03-06 14:58:03.883  3493  3696 W FxAccounts: fennec :: FxAccountSyncAdapter :: Remote verifier returned failure: {"reason":"assertion issued later than verification date","status":"failure"}
10987:03-06 14:58:03.922  3493  3696 E FxAccounts: fennec :: FxAccountSyncAdapter :: Failed to get token.
10988:03-06 14:58:03.922  3493  3696 E FxAccounts: org.mozilla.gecko.tokenserver.TokenServerException$TokenServerInvalidCredentialsException: {"status":"invalid-timestamp","errors":[{"location":"body","description":"Unauthorized","name":""}]}

Comment 31

[Ryan Kelly [:rfkelly]]

:edwong that's this: Bug 980478

Comment 32

[Edwin Wong [:edwong]]

verified Bug 980478 is fixed - this is android 2.2 only issue.

Comment 33

[Aaron Train [:aaronmt]]

This is fixed.