Closed Bug 975625 Opened 6 years ago Closed 6 years ago

Sync fails to sync data with invalid signature on Android 2.2

Categories

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

ARM
Android
defect

Tracking

()

RESOLVED WORKSFORME

People

(Reporter: edwong, Assigned: nalexander)

References

(Blocks 1 open bug)

Details

(Whiteboard: [qa+])

Attachments

(3 files)

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
Blocks: 799726
Severity: normal → major
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!
Flags: needinfo?(edwong)
clock skew?

901): fennec :: FxAccountSyncAdapter :: Syncing FxAccount account named like XXXXXX@XXXXXXXXXX.XXX 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":""}]}
Attached file foo.txt
adb logcat | grep FxAccounts
Flags: needinfo?(edwong)
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.
Duplicate of this bug: 975142
Summary: android 2.2 fails to sync data → android 2.2 fails to sync data (clock skew)
Whiteboard: [dupeme]
Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → DUPLICATE
Duplicate of bug: clockskew
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=edog0@mailinator.com, 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 XXXXX@XXXXXXXXXX.XXX 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":""}]}
Status: RESOLVED → REOPENED
Resolution: DUPLICATE → ---
Summary: android 2.2 fails to sync data (clock skew) → android 2.2 fails to sync data with invalid signature
Status: REOPENED → NEW
Summary: android 2.2 fails to sync data with invalid signature → Android 2.2/2.3 fails to sync data with invalid signature
Whiteboard: [dupeme]
Attached file log.log
Log from my Samsung Nexus S running Aurora 29.0a2 -- network time enabled, correct  time
[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
Summary: Android 2.2/2.3 fails to sync data with invalid signature → Android 2.2/2.3 fails to sync data with invalid signature (clock skew)
For what it's worth, I successfully signed into and synced against an account today with a Galaxy Mini running Android 2.3.6.
(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.
What other variable is causing this issue? My device has correct time and date and still get invalid-timestamp after signing in today.
(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?
Flags: needinfo?(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?
Flags: needinfo?(rfkelly) → needinfo?(aaron.train)
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
Flags: needinfo?(aaron.train)
Summary: Android 2.2/2.3 fails to sync data with invalid signature (clock skew) → Sync fails to sync data with invalid signature
Attached file logcat.log
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.
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)
> {"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?
Whiteboard: [qa+]
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).
Bear in mind that Android clocks can be as wrong forward as they are back.
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."
Summary: Sync fails to sync data with invalid signature → Sync fails to sync data with invalid signature on Android 2.2
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.
(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.
(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?
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
(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.
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.
(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.
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":""}]}
:edwong that's this: Bug 980478
Assignee: nobody → nalexander
Priority: -- → P1
verified Bug 980478 is fixed - this is android 2.2 only issue.
This is fixed.
Status: NEW → RESOLVED
Closed: 6 years ago6 years ago
Resolution: --- → WORKSFORME
Product: Android Background Services → Firefox for Android
You need to log in before you can comment on or make changes to this bug.