1404044 - Passwords are not syncing to android.

Status: RESOLVED FIXED

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

Description

[Skt.diaz]

Attachment: firefox bug.doc

User Agent: Mozilla/5.0 (Android 7.0; Mobile; rv:57.0) Gecko/57.0 Firefox/57.0
Build ID: 20170926071548

Steps to reproduce:

I Logged in with my Firefox account on both Firefox stable release and Firefox beta for Android but passwords are not syncing from Firefox for windows. Everything else syncs.


Actual results:

Passwords not syncing


Expected results:

Passwords should sync

Comment 1

[:Grisha Kruglov]

Just to clarify what you are seeing:
- you're logged into Firefox Account on your Android device and in desktop Firefox on your Windows computer
- everything syncs between Android and Windows except for passwords

Is password sync enabled? You can check under Sync Preferences on either of your devices.

Do you have master password enabled anywhere?

Comment 2

[Skt.diaz]

(In reply to :Grisha Kruglov from comment #1)
> Just to clarify what you are seeing:
> - you're logged into Firefox Account on your Android device and in desktop
> Firefox on your Windows computer
> - everything syncs between Android and Windows except for passwords
> 
> Is password sync enabled? You can check under Sync Preferences on either of
> your devices.
> 
> Do you have master password enabled anywhere?

Yes, Password sync is enabled on both devices. I previously had master password enabled on windows for a few days and then disbaled it. I also deleted my account, made a fresh one, imported passwords from chrome and tried syncing again. Still not working. It was working before I had enabled master password for the first time in my previous account.

Comment 3

[Skt.diaz]

I just saw that under history tab in Firefox beta for Android, the number of synced devices are zero. But under manage account settings I can see that my Android and Windows desktop are being synced.

Comment 4

[Skt.diaz]

(In reply to Skt.diaz from comment #3)
> I just saw that under history tab in Firefox beta for Android, the number of
> synced devices are zero. But under manage account settings I can see that my
> Android and Windows desktop are being synced.

Sorry, that maybe because I'm not syncing history across devices.

Comment 5

[Skt.diaz]

just realised that new passwords are not syncing from android to pc as well.(In reply to Skt.diaz from comment #2)
> (In reply to :Grisha Kruglov from comment #1)
> > Just to clarify what you are seeing:
> > - you're logged into Firefox Account on your Android device and in desktop
> > Firefox on your Windows computer
> > - everything syncs between Android and Windows except for passwords
> > 
> > Is password sync enabled? You can check under Sync Preferences on either of
> > your devices.
> > 
> > Do you have master password enabled anywhere?
> 
> Yes, Password sync is enabled on both devices. I previously had master
> password enabled on windows for a few days and then disbaled it. I also
> deleted my account, made a fresh one, imported passwords from chrome and
> tried syncing again. Still not working. It was working before I had enabled
> master password for the first time in my previous account.

Comment 6

[Julie McCracken (:julie)]

Could you provide about:sync-log?  Here are some instructions:  https://wiki.mozilla.org/CloudServices/Sync/File_a_desktop_bug

Comment 7

[Skt.diaz]

Attachment: firefox windows sync-log

Comment 8

[Skt.diaz]

(In reply to Julie McCracken (:julie) from comment #6)
> Could you provide about:sync-log?  Here are some instructions: 
> https://wiki.mozilla.org/CloudServices/Sync/File_a_desktop_bug

please check the attachment

Comment 9

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

Thanks for the log, but unfortunately that only shows a sync error that was probably caused by a transient network error.

In https://wiki.mozilla.org/CloudServices/Sync/File_a_desktop_bug, there is documentation for enabling "success" logs - it would be great if you can do that, then save a new password on desktop, sync, and upload any new logs that appear.

Another thing to do would be to install the addon https://addons.mozilla.org/en-US/firefox/addon/about-sync/, look for the "passwords" collection, and see if the username and password is what you expect and set on desktop. If it is, it probably points at an Android issue (ie, desktop would then appear to be doing the right thing). If it isn't, then it's probably a desktop issue and the new logs would probably help us understand why.

Thanks!

Comment 10

[Skt.diaz]

Attachment: synclog.pdf

Comment 11

[Skt.diaz]

(In reply to Mark Hammond [:markh] from comment #9)
> Thanks for the log, but unfortunately that only shows a sync error that was
> probably caused by a transient network error.
> 
> In https://wiki.mozilla.org/CloudServices/Sync/File_a_desktop_bug, there is
> documentation for enabling "success" logs - it would be great if you can do
> that, then save a new password on desktop, sync, and upload any new logs
> that appear.
> 
> Another thing to do would be to install the addon
> https://addons.mozilla.org/en-US/firefox/addon/about-sync/, look for the
> "passwords" collection, and see if the username and password is what you
> expect and set on desktop. If it is, it probably points at an Android issue
> (ie, desktop would then appear to be doing the right thing). If it isn't,
> then it's probably a desktop issue and the new logs would probably help us
> understand why.
> 
> Thanks!

i installed the add-on and my username/passwords match. i have attached the new log, hopefully its correct this time.

Comment 12

[:Grisha Kruglov]

(In reply to Skt.diaz from comment #10)
> Created attachment 8915130 [details]
> synclog.pdf

If this is a sync after a new password was saved, then it does appear that a password is being uploaded. If that password did not show up on Firefox for Android after you've synced it, this seems to point to an Android problem.

At this point it would help to see the Android sync logs. Unfortunately, getting at those is a bit more involved - you'll need to install Android SDK (so that you have a tool called 'adb'), enable USB debugging on your phone, connect phone to your computer via USB cable, run 'adb logcat' while Firefox for Android is syncing and save ("pipe") the logcat output to a file. There are some instructions on the specific steps here: https://developer.mozilla.org/en-US/docs/Mozilla/QA/Fennec_Android:_Logging_with_the_Android_Debug_and_Logcat

If you run into issues with the above steps, don't hesitate to reach out for help - either here, or in IRC (see https://wiki.mozilla.org/IRC - you can find us in the #sync channel, but asking for help in #mobile will work as well).

Comment 13

[:Grisha Kruglov]

Please see Comment 12.

Comment 14

[Skt.diaz]

(In reply to :Grisha Kruglov from comment #12)
> (In reply to Skt.diaz from comment #10)
> > Created attachment 8915130 [details]
> > synclog.pdf
> 
> If this is a sync after a new password was saved, then it does appear that a
> password is being uploaded. If that password did not show up on Firefox for
> Android after you've synced it, this seems to point to an Android problem.
> 
> At this point it would help to see the Android sync logs. Unfortunately,
> getting at those is a bit more involved - you'll need to install Android SDK
> (so that you have a tool called 'adb'), enable USB debugging on your phone,
> connect phone to your computer via USB cable, run 'adb logcat' while Firefox
> for Android is syncing and save ("pipe") the logcat output to a file. There
> are some instructions on the specific steps here:
> https://developer.mozilla.org/en-US/docs/Mozilla/QA/Fennec_Android:
> _Logging_with_the_Android_Debug_and_Logcat
> 
> If you run into issues with the above steps, don't hesitate to reach out for
> help - either here, or in IRC (see https://wiki.mozilla.org/IRC - you can
> find us in the #sync channel, but asking for help in #mobile will work as
> well).

can i share the file through google drive url? the log file is around 200mb, is it supposed to be this large?

Comment 15

[Skt.diaz]

Attachment: adb sync log for firefox android

Comment 16

[:Grisha Kruglov]

Looking at the telemetry data from android's sync engines, we see a clear regression in success rates of passwords syncing, starting roughly around Sept 26 (this bug was filed on the 28th). Top error is "othererror - store:unknown". This is the error that goes up in volume from sporadic to steady around Sept 26.

Firefox 56 was released on 2017-09-28.

Comment 17

[:Grisha Kruglov]

Correction, top error is "othererror/fetch:unknown", but the errors with visibly increased volume are "othererror/store:unknown" and "fetch:NumberFormatException".

For reference:
Overall success rate graph: https://screenshots.firefoxusercontent.com/images/39566acc-a403-480b-b088-4784b9233127.png
Breakdown by errors graph: https://screenshots.firefoxusercontent.com/images/ae10bbf8-bc32-44fe-82e6-f4030d58cf82.png

We'll fail a sync in case of remote store errors, not the local ones. Which means that "store:unknown" is happening in the second part of the sync, while attempting to write records to the server.

Error is marked as "unknown" because we didn't have a "storeException" set. Somehow we've incremented a store failure count, but didn't set an exception (or overrode it with 'null') which would have been the cause of a store failure.

Comment 18

[:Grisha Kruglov]

From the logs in Comment 15.

We're failing to decrypt incoming records in the crypto middleware, because of a JSON parsing error:

java.lang.NumberFormatException: For input string: 18446732429235952000.

This number is about an order of magnitude larger than what would fit in a Java's Long.

Password record has a number of timestamps:

    timeLastUsed unsigned long
    timeCreated unsigned long
    timePasswordChanged unsigned long
    timesUsed unsigned long

If our sync docs are following C99 definition of an unsigned long, then the failing number is in the 99.999th percentile of the range. I'm guessing these records are coming from gecko's passwords layer (going by the incoming number being very close to a max unsigned long in C), perhaps we're doing some form of clamping for some of these timestamps?

Comment 19

[Nick Alexander :nalexander [he/him]]

(In reply to :Grisha Kruglov from comment #18)
> From the logs in Comment 15.
> 
> We're failing to decrypt incoming records in the crypto middleware, because
> of a JSON parsing error:
> 
> java.lang.NumberFormatException: For input string: 18446732429235952000.
> 
> This number is about an order of magnitude larger than what would fit in a
> Java's Long.
> 
> Password record has a number of timestamps:
> 
>     timeLastUsed unsigned long
>     timeCreated unsigned long
>     timePasswordChanged unsigned long
>     timesUsed unsigned long
> 
> If our sync docs are following C99 definition of an unsigned long, then the
> failing number is in the 99.999th percentile of the range. I'm guessing
> these records are coming from gecko's passwords layer (going by the incoming
> number being very close to a max unsigned long in C), perhaps we're doing
> some form of clamping for some of these timestamps?

micros vs millis vs nanos?  This happens fairly frequently...

Comment 20

[Lina Butler [:lina]]

(In reply to :Grisha Kruglov from comment #18)
> java.lang.NumberFormatException: For input string: 18446732429235952000.

That number looks familiar; we saw it in bug 1404044.

Comment 21

[Lina Butler [:lina]]

Er, sorry, I meant bug 1240278.

Comment 22

[Thom Chiovoloni [:tcsc] (ex-moco)]

After discussion in IRC I think I can get a patch up for this pretty quickly.

Comment 23

[Thom Chiovoloni [:tcsc] (ex-moco)]

Attachment: Bug 1404044 - Prevent android sync from failing on overlarge timestamps in password sync

This was done by way of hacking our vendored version of org.simple.json.

Review commit: https://reviewboard.mozilla.org/r/191680/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/191680/

Comment 24

[:Grisha Kruglov]

Comment on attachment 8920680 [details]
Bug 1404044 - Prevent android sync from failing on overlarge timestamps in password sync

https://reviewboard.mozilla.org/r/191680/#review196924

We will be swapping all of this code away relatively soon in Bug 1204559, and hopefully the new parser will behave better. As a stop-gap measure, my main concern about this patch is that we might simply break the parser for some other inputs.

::: mobile/android/thirdparty/org/json/simple/parser/Yylex.java:668
(Diff revision 1)
> +              Long val = Long.valueOf(text);
> +              return new Yytoken(Yytoken.TYPE_VALUE, val);
> +            } catch (NumberFormatException e) {
> +              // Change from default org.simple.json, adjust parser to make bugs like
> +              // 1404044 possible to handle.
> +              Double val = Double.valueOf(text);

My one concern about this is that Double's toString method (which this ends up running) will be materially different to Long's toString in its output, and cause problems in some narrow cases with the parser, which probably makes assumptions about its value inputs.

Obviously we'll need to weight this against the benefit, but it's not obvious to me that this won't introduce some obscure bug elsewhere in the services or telemetry code.

What do you think?

Comment 25

[Thom Chiovoloni [:tcsc] (ex-moco)]

Comment on attachment 8920680 [details]
Bug 1404044 - Prevent android sync from failing on overlarge timestamps in password sync

https://reviewboard.mozilla.org/r/191680/#review196924

> My one concern about this is that Double's toString method (which this ends up running) will be materially different to Long's toString in its output, and cause problems in some narrow cases with the parser, which probably makes assumptions about its value inputs.
> 
> Obviously we'll need to weight this against the benefit, but it's not obvious to me that this won't introduce some obscure bug elsewhere in the services or telemetry code.
> 
> What do you think?

I strongly doubt it. Any code that hits this would already have an error, since it will only be hit in the case where it fails to parse a long[0].  This just gives code that was already going to complain about a NumberFormatException due to a bad Long a chance to handle it by handling getting a Double.

[0] More than that, if I understand the lexer correctly (admittedly, I definitely might not), it would have to fail to parse it due to overflow, I think at this point the lexer has already determined it looks more or less like a number (e.g. it's a bunch of digits in a row).

Comment 26

[:Grisha Kruglov]

Comment on attachment 8920680 [details]
Bug 1404044 - Prevent android sync from failing on overlarge timestamps in password sync

https://reviewboard.mozilla.org/r/191680/#review196932

OK, let's roll with this patch, given that try's all green. We'll replot the graphs for Nightly in a few days to see if this had made an impact.

Comment 27

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/38d2f90e0bc5
Prevent android sync from failing on overlarge timestamps in password sync r=Grisha

Comment 28

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

https://hg.mozilla.org/mozilla-central/rev/38d2f90e0bc5

Comment 29

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

(In reply to :Grisha Kruglov from comment #26)
> We'll replot the
> graphs for Nightly in a few days to see if this had made an impact.

ni? Grisha to followup on this.

Comment 30

[:Grisha Kruglov]

Noisy passwords error engine breakdown on the Nightly channel:
https://screenshots.firefox.com/MfE4hXNKUCOxEPPx/localhost

NumberFormatException takes a nose dive after the patch landed, so I'd call patch in Comment 28 a success.

That error wasn't the top one, and the overall success rate graph is very noisy (likely due to my low sample rate) - but it does look an improvement:
https://screenshots.firefox.com/2RzvBXuViZgEP6Oc/localhost

fetch:unknown errors are now 90-100% of all errors, so let's focus on them in Bug 1073680.