Closed Bug 1747893 Opened 2 years ago Closed 2 years ago

Sync error: CreditCards is not initialized

Categories

(Firefox :: Sync, defect, P2)

Product:
Firefox
Component:
Sync
Version:
Firefox 97
Type:
defect

Tracking

()

Status:
VERIFIED FIXED
Milestone:
99 Branch
Tracking Flags:
Tracking Status
firefox-esr91 --- unaffected
firefox95 --- unaffected
firefox96 --- unaffected
firefox97 --- disabled
firefox98 --- disabled
firefox99 --- verified

People

(Reporter: lilydjwg, Assigned: tgiles)

References

(Regression)

Details

(Keywords: regression)

Attachments

(2 files)

image.png
22.92 KB, image/png
Details
Bug 1747893 - Fix credit cards not syncing correctly once disabled on subsequent startup. r=sgalich!
48 bytes, text/x-phabricator-request
Details | Review

User Agent: Mozilla/5.0 (X11; Linux x86_64; rv:97.0) Gecko/20100101 Firefox/97.0

Steps to reproduce:

update my nightly from 20211214 to 20211226.

Actual results:

Firefox Sync no longer works (last synced reports days ago and I no longer see new data from my other devices). In the error log I find:

1640788374167	Sync.Synchronizer	DEBUG	Updating enabled engines failed: Error: CreditCards is not initialized. Please restart if you flip the pref manually.(resource://autofill/FormAutofillStorageBase.jsm:2008:21) JS Stack trace: get@FormAutofillStorageBase.jsm:2008:21
get storage@FormAutofillSync.jsm:95:7
_resetClient@FormAutofillSync.jsm:317:5

Expected results:

Firefox Sync should continue to work, no matter if syncing credit cards is supported or not.

I tried to disable syncing credit cards in Preferences but it still happened. I read the source code and changed extensions.formautofill.creditCards.available from detect to on, it finally started to work.

My nightly is the zh-CN variant and I'm in China.

The Bugbug bot thinks this bug should belong to the 'Firefox::Sync' component, and is moving the bug to that component. Please revert this change in case you think the bot is wrong.

Component: Untriaged → Sync

I haven't seen any sync errors and I was able to sync (some logins and credit cards), tried on macOS Big Sur 11.6 using the latest Nightly 97 (Build ID: 20211229214859, en-GB build, and zh-CN build).

In my case worked having the preference extensions.formautofill.creditCards.available to "on" - if it is set to "detect" I'm not even seeing the option of the Autofill credit cards feature.

credit-cards default to being enabled in some locales and disabled in others. The problem will be syncing between 2 profiles with a mismatch. I'm not sure what we will end up doing, but most likely is simply ignoring them if they are disabled (ie, we should not print that error, but instead should silently do nothing re credit-cards on that profile)

The issue is that (at least) my tabs and history doesn't get synced, and last-sync time doesn't get updated (both in application and accounts.firefox.com). When I set the pref to on, they can get synced sometimes.

Sometimes I still see the error, but things get synced. Sometimes I don't see an error and last-sync time gets updated, but tabs are not synced. I'm still flipping the Credits checkbox to try to figure out.

My latest test result is:

  • extensions.formautofill.creditCards.available on + Credits checked: see error but syncs
  • extensions.formautofill.creditCards.available on + Credits unchecked: no error but doesn't sync
  • extensions.formautofill.creditCards.available detect + Credits checked: see error and doesn't sync
  • extensions.formautofill.creditCards.available detect + Credits unchecked: no error but doesn't sync

In the test when I say doesn't sync, I mean I changed my tabs on desktop nightly, clicked "Sync now" and waited until it finished, and on my Android nightly, clicked "Sync" and waited until it finished, I didn't see my tabs updated to the same set on my desktop.

So, the error message is a minor issue (I get a desktop notification about it, which probably comes from the addon). The major issue is it stops syncing. I don't care about credits but I do care about tabs and history and others.

Sorry, but I mis-spoke before - this is a regression and I think was caused by bug 1745248. My logs show

1641349723275   Sync.ErrorHandler       TRACE   Handling weave:engine:sync:error
1641349723275   Sync.Status     DEBUG   Status for engine creditcards: error.engine.reason.unknown_fail
1641349723275   Sync.Status     DEBUG   Status.service: success.status_ok => error.sync.failed_partial
1641349723276   Sync.ErrorHandler       DEBUG   creditcards failed: Error: CreditCards is not initialized. Please restart if you flip the pref manually.(resource://autofill/FormAutofillStorageBase.jsm:2008:21) JS Stack trace: get@FormAutofillStorageBase.jsm:2008:21
get storage@FormAutofillSync.jsm:95:7
trackRemainingChanges@FormAutofillSync.jsm:308:5
_syncCleanup@engines.js:1954:18
_sync@engines.js:1983:18
1641349723276   Sync.SyncScheduler      TRACE   Handling weave:engine:sync:error
1641349723276   Sync.Telemetry  TRACE   observed weave:engine:sync:error creditcards

STR is to toggle extensions.formautofill.creditCards.available from detect to true - I'm in a locale where detection ends up returning false, which may or may not be necessary to reproduce.

A brief look at the failing code shows that FormAutofill.isAutofillCreditCardsAvailable is returning false when it used to return true in this scenario.

I'll keep having a look, but hopefully Tim has some additional context

Flags: needinfo?(tgiles)
Regressed by: 1745248
Has Regression Range: --- → yes
Attached image image.png —

STR is to toggle extensions.formautofill.creditCards.available from detect to true

hrm - as noted above, it appears as though on is expected rather then true, and that's backed up by the code - and setting it to on actually works OK in my testing, so not quite sure what is going on here exactly - but our telemetry is definitely showing a major regression for credit-cards that started when bug 1745248 landed.

Some update: with that pref set to on there has been no error logs since 2022-01-01 (date) and the last update before that was nightly version 20211229. I've just set it back to default value detect and sync is working as expected now. I'll see if it works for longer time.

I don't quite understand the intent of refactoring the sync prefs in that bug, but it's worth noting that services.sync.engine.creditcards.available and services.sync.engine.creditcards.enabled are distinct from extensions.formautofill.creditCards.available - see, eg, https://searchfox.org/mozilla-central/source/browser/components/preferences/dialogs/syncChooseWhatToSync.js. One particular regression here is when creditcards are enabled somewhere else on the sync account, but not on this device, so we end up errors applying the incoming records.

I'm still confused why Nightly is showing ~50% of syncs failing, and why addresses don't seem impacted, but given I'm not quite sure if that refactor was intentional or accidental I'm going to wait for Tim to comment. Sync is complicated, so in general, it's probably worth getting a review from the sync team whenever a patch touches any of its preferences.

Set release status flags based on info from the regressing bug 1745248

status-firefox95: --- → unaffected
status-firefox-esr91: --- → unaffected

Thanks for looping me in Mark. Any changes to the behavior of the sync preferences was accidental, I only meant to refactor the preferences of form autofill being enabled/available. Previously, the entire form autofill module was controlled by the extensions.formautofill.available pref, which could be detect, on, or off. This caused issues since adding new supported countries to form autofill would enable both credit card autofill and address autofill. We tested and fixed issues for credit card autofill so we needed some way to only enable credit card autofill per region. So we ended up having an available pref for each feature so they could be controlled independently.

For the extensions.formautofill.creditCards.available pref, the only valid values are detect, on, or off so I guess I understand why you would get the CreditCards is not initialized error when extensions.formautofill.creditCards.available is set to any other value (true in this case). I suppose we need to migrate the pref's value from true or false to on or detect respectively.

One particular regression here is when creditcards are enabled somewhere else on the sync account, but not on this device, so we end up errors applying the incoming records.

Do you think this the main issue causing sync to not work as expected when credit card autofill isn't available? It seems like if credit cards are not available, that shouldn't break the other sync records (but obviously I don't know a lot about sync or its complexity). So I guess if a particular engine was previously available, then on next start it becomes not available, this situation causes some issue?

[I'm still confused as to] why addresses don't seem impacted

This is because the availability of addresses didn't change. There was no extensions.formautofill.addresses.available pref before Bug 1745248. But even then, the address availability check is the exact same as it was before Bug 1745248, it just uses extensions.formautofill.addresses.available instead of extensions.formautofill.available.

I'm thinking the main solution is to either:

  • Migrate the extensions.formautofill.creditCards.available pref
  • Add some logic to form autofill so that it treats extensions.formautofill.creditCards.available=true as extensions.formautofill.creditCards.available=on
    Happy to hear other solutions though.
Flags: needinfo?(tgiles) → needinfo?(markh)

Oh yeah, totally forgot to mention another possible solution: backing out the patch entirely. However this might cause the same issue for another set of people since the extensions.formautofill.creditCards.available pref might already have one of the new string values.

:markh, some more information for you to consider (might as well have too much information so you can make an educated decision when you're back online).

Given some more consideration, I'm not sure we can successfully migrate the extensions.formautofill.creditCards.available pref. Here's my thought process:

  • The previous values for extensions.formautofill.creditCards.available were true and false.
  • Using those boolean values causes issues in the current implementation, so they need to be changed.
  • The new values for extensions.formautofill.creditCards.available can be detect, on, off.
  • Alright so let's migrate false to off, that's straightforward.
  • How do we migrate true?
    • If we migrate true to on, we bypass all the work that went into Bug 1745248 and end up enabling credit card autofill for all locales.
    • If we migrate true to detect, then the same issue reported in Comment #0 will happen, given the same situation described in Comment #0 will occur.
      • Since credit card autofill (and sync) was previously enabled in a non-supported country, then on the next startup of Firefox, the detect value will kick in and determine that the sync engine for credit cards is no longer available which should cause the CreditCards is not initialized error which then causes some other issues with Sync if a Sync account previously was syncing credit cards.
Depends on: 1748677
No longer depends on: 1748677
See Also: → 1748793

Thanks for that info. I suspect that changing the type of extensions.formautofill.creditCards.available from bool to string might bite - see below.

Do you think this the main issue causing sync to not work as expected when credit card autofill isn't available? It seems like if credit cards are not available, that shouldn't break the other sync records (but obviously I don't know a lot about sync or its complexity). So I guess if a particular engine was previously available, then on next start it becomes not available, this situation causes some issue?

In my testing, I can't see sync fail entirely - just that engine fails, and an error log is created, but everything else works. I see that exact same storage exception, but with a different stack that handles it. However, as above, another symptom is:

1640788374167 Sync.Synchronizer DEBUG Updating enabled engines failed: Error: CreditCards is not initialized. ...

which is where Sync is (incorrectly in this case) believing the user explicitly chose to stop syncing credit-cards - which is a more "fatal" error. There's probably no good reason for it to be that fatal - so I opened bug 1748793 - but I don't quite understand how that profile got into that state, and I can't reproduce it. Because it's trying to disable, another bad side-effect of this is that we are likely to also delete the credit-card data from the server - not from other devices, but there are still cases where the user might consider this data-loss. But that other bug is worth landing as it means sync continues to work even after screwing something up :)

Since credit card autofill (and sync) was previously enabled in a non-supported country, then on the next startup of Firefox, the detect value will kick in and determine that the sync engine for credit cards is no longer available

Right - that seems particularly bad and the root of the original problem - non-US users who opted in to credit-cards (say) 2 years ago now find them disabled? And conversely, US users who explicitly opted out from credit-cards now find them enabled? That seems true in my testing, and not at all what the user would either expect or want.

So yeah, I suggest that we need to "migrate" these prefs - I think it's too late to do this correctly for Nightly users (eg, I believe it's now impossible to know what extensions.formautofill.creditCards.available was before) but we certainly don't want this change to ride the trains IMO.

I'm thinking the main solution is to either:

  • Migrate the extensions.formautofill.creditCards.available pref

If we ignore Nightly (ie, just thinking about profiles yet to have these changes) then I think we need to migrate more than just that pref - extensions.formautofill.available being anything other than "detect" means thatextensions.formautofill.creditCards.available would never be detect, but instead either on or off based on the previously bool value of the same pref name. TBH I'm not sure how possible that will be given the change in type (from bool to string) - so really you might need to rename that pref, so the old bool value is available for inspection before setting the new string value - but I'm really not sure how the prefs service will deal with that.

I'm also slightly confused why our telemetry is showing nearly 50% of credit-card syncs are failing - I really doubt that 50% of Nightly users are in non-US locales who toggled credit-cards to on but now find it off. OTOH, other telemetry around failures doesn't look that bad, so I'm really not sure how widespread this actually is.

I'll try and play a bit more tomorrow, but in great timing, that's my last day before 2 weeks PTO :) cc Sammy for that period :)

Status: UNCONFIRMED → NEW
Ever confirmed: true
Flags: needinfo?(markh)
See Also: → 1748677

:markh, :skhamis just to keep you in the loop, I'm trying to get Bug 1745248 backed out since the migration of the prefs would be pretty difficult in the current timeline. The plan is (as long as the patches get backed out) to land Bug 1745248 in the next cycle and have the pref migration with it. That should prevent any non-Nightly users from running into this issue when we try to land Bug 1745248 next time.

lilydjwg, the patch that caused this original issue has been backed out, so your credit card autofill may become disabled again after updating your Nightly, apologies for that. You'll need to set extensions.formautofill.available back to on and things should work as expected from that point of view, not 100% sure about the Sync issue. I'll work on a migration of that pref so this issue is avoided in the future.

Thanks again for filing this and bringing it to our attention!

Flags: needinfo?(lilydjwg)

Thanks, I updated to latest nightly and it's working as before.

Flags: needinfo?(lilydjwg)

The severity field is not set for this bug.
:bdeankawamura, could you have a look please?

For more information, please visit auto_nag documentation.

Flags: needinfo?(bdeankawamura)
Severity: -- → S3
Flags: needinfo?(bdeankawamura)

lilydjwg, are you running into this issue again? Some of the telemetry around credit card sync seems to imply this might be happening again and so I wanted to check in and verify.

Flags: needinfo?(lilydjwg)

Alright, so the issue seems to be straightforward. Form Autofill storage is throwing an error because credit cards were available and then credit cards become unavailable (I believe we've already established this but for clarity). Sync catches this "credit cards unavailable error" then causes an error log to appear. For whatever reason, we don't have this FormAutofill.isAutofillCreditCardsAvailable check for addresses and not having this address available doesn't seem to cause any issues (at least according to the telemetry). I haven't noticed any oddities in the browser when switching address autofill on and off. I went ahead and removed the if/else statement where this error can be thrown locally which caused Sync to sync successfully every time. I ran the Sync unit tests and this change seems to have no impact to previous behavior, while there's only one part of form autofill's unit test that needs to be updated, pretty minor change.

The failing form autofill test is a test called test_creditCardFillUnavailable but for some reason, we don't have an equivalent test for addresses. Based on this information, it appears this task can be removed entirely and we can simplify the initialization of addresses and credit cards. Again, I didn't notice any strange behavior when turning the supported prefs for address and credit card autofill on and off; the browser behaves as expected and no new Sync errors occurred.

What bug caused this re-regression?

Flags: needinfo?(tgiles)

I've been running 2022-02-01 for hours and do not see any issue, at least no error notifications and history is synced as expected.

Flags: needinfo?(lilydjwg)

:markh, I landed Bug 1745248 again (after getting two sync reviewers this time). I'm still not sure why this issue keeps appearing but if I had to pinpoint what's causing the issue, I'd throw a dart at L274-280 in FormAutofillSync.jsm. It seems like the form autofill sync code will attempt to start up regardless if the sync engines are available or not. The other potential issue could be from the fact that Form Autofill would always call initialize() on addresses, regardless if address autofill was available or not. Nothing bad seems to happen if we call initialize on a set of empty records from the form autofill storage side of things, which we can see in the sync telemetry since address sync success rate doesn't drop.

Flags: needinfo?(tgiles)
Assignee: nobody → tgiles
Status: NEW → ASSIGNED
Attachment #9261950 - Attachment description: Bug 1747893 - Fix credit cards not syncing correctly once disabled on subsequent startup. r=sgalich!,markh! → Bug 1747893 - Fix credit cards not syncing correctly once disabled on subsequent startup. r=sgalich!
Attachment #9261950 - Attachment description: Bug 1747893 - Fix credit cards not syncing correctly once disabled on subsequent startup. r=sgalich! → Bug 1747893 - Fix credit cards not syncing correctly once disabled on subsequent startup. r=sgalich!,markh!
Attachment #9261950 - Attachment description: Bug 1747893 - Fix credit cards not syncing correctly once disabled on subsequent startup. r=sgalich!,markh! → Bug 1747893 - Fix credit cards not syncing correctly once disabled on subsequent startup. r=sgalich!

(In reply to Tim Giles [:tgiles] from comment #22)

which we can see in the sync telemetry since address sync success rate doesn't drop.

It's important we get to the underlying problem here rather than throwing darts and checking telemetry after the fact.

Priority: -- → P2
Keywords: leave-open

Steps to verify this bug:

Pre-conditions:

  1. Have a Firefox Account with credit card data synced to it.
  2. Ensure extensions.formautofill.creditCards.supported is set to "on"

Verification steps:

  1. Start browser
  2. Sync account
  3. Navigate to about:sync-log and verify no error log was created
  4. Change pref value of extensions.formautofill.creditCards.supported to "off"
  5. Restart browser
  6. Sync account
  7. Navigate to about:sync-log and verify no error log was created
Flags: qe-verify+
Pushed by tgiles@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/d8ac36c3cfe4
Fix credit cards not syncing correctly once disabled on subsequent startup. r=sgalich
See Also: 1748677 →

Reproduced the initial issue in Nightly 97.0a1 (build id: 20211230095735).
Verified - Fixed in latest Nightly 99.0a1 (build id: 20220214092817) using Windows 10 and macOS 11 with US region, following the steps from comment 25. No error log is created.
Thanks for all the details.

Flags: qe-verify+
status-firefox99: --- → verified
Target Milestone: --- → 99 Branch

Since the status are different for nightly and release, what's the status for beta?
For more information, please visit auto_nag documentation.

status-firefox98: --- → ?
Status: ASSIGNED → RESOLVED
Closed: 2 years ago
Keywords: leave-open
Resolution: --- → FIXED
Status: RESOLVED → VERIFIED

I think the warning message I see in my local testing of C-C thunderbird is related to this bugzilla. Or maybe a different bug?

 3:14.83 GECKO(387953) [Parent 387956, Main Thread] WARNING: Rejected attempt to change type of pref extensions.formautofill.creditCards.available's user value from bool to string: file /NEW-SSD/NREF-COMM-CENTRAL/mozilla/modules/libpref/Preferences.cpp:1715

I am not entire sure what to make of this warning. Can we simply ignore it for now?

You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: