Splitted the
  DCHECK(!models_associated_ && registered_preferences_.count(name) == 0);

and the failing one is 
  [30700:30700:1127/180015.913433:FATAL:pref_model_associator.cc(456)] Check failed: !models_associated_. 

Hi Miguel, is the OP above mixing two different bug reports, or am I missing something?

#2: sorry, yeah, that's the stack of  crbug.com/788723  :-)
Correcting the description.

Currently preference sync requires that all syncable preferences are registered before initialization of sync engine. This is done in RegisterProfilePrefs methods. This particular stack attempts to register a preference after sync initialization.

mcasas@: is it possible to print which  preference is being registered? You could dump |path| parameter to PrefRegistry::SetDefaultForeignPrefValue. This would help identify which preference is being registered late.

I dumped |name| being passed to the failing DCHECK:

[23930:23930:1204/183041.209564:FATAL:pref_model_associator.cc(456)] Check failed: !models_associated_ && registered_preferences_.count(name) == 0. shelf_alignment

Hey Scott, it looks like Ash is registering prefs after the sync engine is initialized, which is against the expectations of the sync engine (cf. c#8 and c#6). Could you forward this on to the person best-suited to look at it? Thanks!

Hey - still seeing this all the time. PTAL/Fwd?

Sorry for missing this. Do you have a stack trace of where the bad initialization is happening?

Mike, do you think something you did might have changed the timing of the registration?

I definitely touched this pref's registration in the fall:
https://chromium-review.googlesource.com/c/chromium/src/+/602737
https://chromium-review.googlesource.com/c/chromium/src/+/608613
https://chromium-review.googlesource.com/c/chromium/src/+/717476

I'm not sure what's wrong with the current code to cause this. ash::Shell::RegisterProfilePrefs calls ash::ShelfController::RegisterProfilePrefs to register kShelfAlignment, similar to other prefs (though it's only one of four in Ash that are synced):
https://cs.chromium.org/chromium/src/ash/shelf/shelf_controller.cc?rcl=6ff23b0604e2edbe7ef282564ea340f5c72ab91a&l=148

Perhaps ash::Shell's use of the preferences service relays the foreign prefs to Chrome too late for sync init?
I hope Sam or James might have a thought here, I'm not super familiar with the preferences service timing relative to sync init.
Does Chrome need to delay Sync init until all other services have registered their foreign prefs?

Could it be related to the weird first-sync behavior of shelf alignment? https://cs.chromium.org/chromium/src/chrome/browser/ui/ash/launcher/chrome_launcher_controller.cc?l=950

Sam, if a pref is registered in ash but used in chrome, does chrome need to declare the pref as foreign? I seem to recall that either didn't work or wasn't necessary in the past. Pref shelf_alignment is registered in ash as public, but never registered in chrome as foreign.

https://cs.chromium.org/chromium/src/ash/shelf/shelf_controller.cc?l=157

It's definitely not related to the first-sync behavior of the shelf alignment, that's handled on the Chrome side, after their registration:
Issue 774657 and http://crbug.com/753823#c12 have tangentially related details (pref service clients can't observe when the first sync occurs).

From my naive understanding, it seems like these are the possible resolutions:
(1) Sync init must be delayed until all pref service users have registered their "foreign" syncable prefs.
(2) All "foreign" syncable prefs must be pre-registered in Chrome before the owner service actually registers them.
(4) No "foreign" prefs can be syncable, they must all be owned by Chrome and used as 'foreign' by the services that need them.
(3) Sync must allow delayed registration of synced prefs after init.

Pavel, is (4) possible? (1)-(3) all seem bad: (1) We might not even connect to all services with foreign syncable prefs on startup, so we can't delay sync init indefinitely. (2)&(3) It's bad layering to have Chrome know about all the syncable prefs used by all possible services.

I haven't hit this DCHECK myself, and doubt I'm the best owner here. This is just one instance of a wider pref service and sync issue.

 Issue 822946  has been merged into this issue.

+Mikel FYI

Also marking for re-triage by new Sync team.

Let's bump this up to P1. This issue makes it impossible to test code locally via the SimpleChrome flow with DCHECK() enabled.

Kyle/Miguel, can you give repro instructions? Is it possible to repro via running ChromeOS on Linux?

CC'ing this week's gardeners, as per  Issue 822946 

blundell@: I was able to reproduce this issue simply by logging in on my Eve. I haven't tried to reproduce via running CrOS on Linux.

Pavel is no longer working on Sync. Release the bug and +Tim and Mikel from the new Sync team.

To answer some of the questions from #16
At a high level, the Sync code assumes that all syncable prefs (not sure what "foreign" means in this context, but basically anything on this device that wants to be synced) is expected to be known by the pref service ahead of the time that the sync starts up.

If the idea is to not allow syncing prefs from non-Chrome (i.e. other services), that definitely seems like it might be a viable workaround. Mikel/Tim should make that call though.

It does seems like it would be good at some point to support dynamically registering new syncable prefs at runtime, but that likely is going to require some work.

blundell@: same here, just make sure to compile with
dcheck_always_on = true
in your simplechrome's gn (it's not there by default)

Supporting delayed registration of syncable prefs seems like the ideal outcome to me, so it would be nice to quantify the amount of work required to make that happen.

The servicification effort aims to make each service responsible for its own preferences, rather than having Chrome (or some central pref service host) know about all the preferences of all services. As each service would register its own prefs, we'd need to handle asynchronous registration, and registration may even occur some indeterminate time after startup as non-critical services are first used. It seems like pref system already supports this, but sync does not.

If support for delayed registration is a long way off and this DCHECK is actively blocking folks, we should either move the DCHECK to a NOTIMPLEMENTED or similar, or possibly revert syncable preferences back to Chrome.

My very rough estimate would be maybe a month or so of work. It involves rewriting and revisiting many of the assumption in place in PrefModelAssociator.

This might also be a good opportunity to convert Pref Sync to USS as well (FYI to Mikel).

Adding components/sync_preferences/OWNERS as FYI, and in case anybody has spare cycles. I don't know how soon the core Sync team can prioritize this.

None of the prefs OWNERS are actively working on it. It's WAI that all registrations must occur before prefs are used. If new runtime conditions breaks that it's up to the team introducing them to fix (on that note, I agree it's P1 to address DCHECKs hitting in the wild).

So, do you think that only the service hosting sync (ie. chrome) can own syncable prefs? (ie. all services ask Chrome for prefs)
Or, do you think all services must be started at boot to gather all syncable prefs before starting sync?
Both of those sound non-optimal, do you have something else in mind?

We may need a non-optimal short-term workaround, but I think we need delayed registration.

Agreed that it seems clear that the only viable long-term solution is to support dynamic registration of syncable prefs.

Nicolas: What concrete bustage does the late registration introduce in the current codebase? i.e., what is occurring on release builds where this DCHECK isn't firing? Is there some minimal amount of work we could do to limit that to "acceptable behavior" with a TODO and remove the DCHECK, given that it seems evident that there aren't resources to bring up the long-term solution in the near term? Thanks!

Converting to USS while implementing the long-term solution seems like a good plan. Still, the sync team has many higher-prio tasks on our plate.

Nicolas: do you have some quick estimate of minimal amount of work to fix it short-term?

Tim: I think we need your input on prioritization. Should we (the sync team) invest some time to figure out what is the least-effort way to fix it short term? If so, do you have someone on your mind?

Migrating preferences to USS is not a priority for ChromeSync in 2018 and I don't think we have the capacity for the 1 SWE month  fix zea@ suggested in  comment 30.

Following up on comment 27:
"""
If the idea is to not allow syncing prefs from non-Chrome (i.e. other services), that definitely seems like it might be a viable workaround. Mikel/Tim should make that call though.
"""
Does your use case actually require syncing prefs? Would not syncing prefs be a workaround for the medium term?

Users expect shelf pinned apps to sync, and shelf alignment and auto-hide to sync on first login.
Ash also registers stylus synced prefs. Servicification and Mus+Ash will continue adding more use cases.
https://cs.chromium.org/search/?q=SYNCABLE_PREF++f:ash&type=cs

Re #34, this is something for the new sync team to double check, but I suspect it's probably just not going to sync any preferences that are registered late. That seems like a regression for e.g. shelf pinned apps.

+msw, +blundell: let's set up a quick meeting to discuss this more efficiently. I'm adding something on your calendars.

Thanks Tim!

Assigning to you to decide about the future of this bug and to re-assign/de-prio/...

Outcome of this meeting: while this won't mus+ash any time soon, it's a general problem for servicification. A proper fix won't be started in Q2, we'll need to see if we can share funding between sync and s13n folks.
It's a bit concerning that other developers got hit and we're not sure this won't happen in the wild.
AIs:
tschumann: find out the actual problem and assess the severity.
msw: Reliably reproduce the problem.

Reading through the code, it seems the effect is not dramatic (i.e. no dragons flying out of people's noses):
-- any local or remote changes that get received _before_ the corresponding pref gets registered will be skipped. (remote changes won't be applied, local changes won't be synced).
-- _after_ the registration: local and remote changes will be applied. Only observable differences:
    ++ GetAllSyncedData(): does not include late-registered prefs until a local change was done. This method seems unused though.
    ++ IsPrefSynced(): returns fals for late-registered prefs until local change was done (or remote ADD was received -- which is unlikely to happen). This method seems unused, too.

Looking at the implementation, supporting this functionality looks not too hard and independent of USS work.

While the world isn't on fire, I'd like to get this in a better defined state. Next steps would be to add test coverage and see if we can remove the DCHECK with a quick fix.

Thanks Tim, that's encouraging news.

I haven't been able to repro the crash on linux desktop chromeos=1 builds yet.
From a few simple tests, the shelf prefs are syncing as expected in Mus and Mash.
Can anyone help me reliably hit the DCHECK? I'll try go/simplechrome tomorrow.

It might make sense for me to check how the DCHECK could be hit in Classic/Mus.
AFAIK, we should only be asynchronously registering preferences in Mash.
If this is happening in Classic/Mus, we'll need a more expedient resolution.

Tim: Thanks for that investigation!

WRT local changes not being synced before the pref is registered, if we assume that the first thing that a service does with the pref is register it, then there shouldn't actually be any local changes before registration, correct?

So it seems like the issue AFAICT is "remote changes to a given pref won't be applied before the pref is registered." In that case, what value would the service see when it read the pref? Whatever had previously been persisted to disk?

It would be good to delete those dead methods if they're really dead. Actually, I don't even see GetAllSyncedData() in a "git grep" of the codebase?

Concerning remote writes: Correct. The client would see whatever was last persisted locally. What's a bit concerning is that if the registration happens late enough so that we already start receiving remote results, we might miss a remote changes for a long time period (essentially since the last time Chrome was closed). Not sure how likely the timing is though.

Those methods are part of the sync framework. Not sure if it's worth deleting the implementation (tests rely on it; so we'd have to move it into TestOnly methods which overall wouldn't be a net win.).

We very likely have a race condition that [rarely] triggers this defect on Stable.
The only code path for registering Ash's profile preferences is triggered via Mojo:
The mojo interface impl SessionController::UpdateUserSession calls through to Shell::RegisterUserProfilePrefs.

IIUC, Sync tries to init immediately, and when it gets a response from the server it posts the registered syncable prefs.
So, if the Chrome->Ash mojo call to init the session, and the subsequent Ash->Chrome PrefService update is slower than the network, we hit this DCHECK.

I wrote a patch that delays the Ash->Chrome PrefService connection, and that reliably triggers the DCHECK locally:
  https://chromium-review.googlesource.com/c/chromium/src/+/1012788

So, we might want/need some near-term (M67?) mitigation to avoid these (low severity?) racy sync failures.
1) Have Chrome synchronously register Ash-owned (etc.) prefs as 'foreign' prefs to create a placeholder for syncing... (unsure if that's easy)
2) Have Chrome synchronously call ash::Shell::Register*Prefs (only applies to the Classic and Mus Ash configs, wait for delayed registration for Mash)
3) Move ownership of preferences back to Chrome (boo)
4) Have Sync store the values of unregistered preferences to allow delayed registration (not sure if possible/easy)
5) Have Sync support delayed registration of prefs in some other way?

Triage ping: Any updates on this? Is this really a P1?

sorry for the long radio silence on this bug.
Thanks Mike for the repro, I'll look into this follow up next week.
Lowering to P2.

tschumann@: I'm hitting this DCHECK systematically on 3 different
devices -- since the situation is well known, could you change it
to an e.g. LOG(ERROR) ? Happy to write the CL.

Also been hitting this one pretty regularly (name = shelf_alignment), please fix this.

mcasas, I don't think turning DCHECKs into LOG(ERROR) is a viable solution long-term (it promotes disabling DCHECKs, and then not really fixing the core problem).

isandrk@ I agree, but since the DCHECK() and the situation it signals
is well known, having developers constantly see the callstack is not
adding any information, right?. 

Since tschumann@ is going to be addressing it soon, they can also 
revert my crrev.com/c/1038523 at the same time.

Turning this DCHECK into a LOG(ERROR), is the wrong thing to do.
The component is not used correctly and this might cause data loss.
The whole way how sync is dealing with preferences (and the preference registration model) is simply not designed for this use case. Properly fixing this is a larger effort.

Given we are looking at a relatively simple race during start-up (both services are started around the same time), maybe we can find a simpler work-around. We could keep this part of sync in an earlier state until after other services finished their prefs registration.

services / pref-services folks: Would it be possible to track the initialization of other services and call 
a new method on PrefServiceSyncable once all registration is complete? Seems like the cleanest short-term solution.


FTR, we're currently also looking into other work arounds, e.g duplicating the registration across the services (https://groups.google.com/a/google.com/d/msg/chrome-sync-dev/y1gumsYtYN4/9JWGiqaYAgAJ).

If Chrome can wait for Ash to register prefs before initializing sync, then that's probably an okay short-term workaround.
(I'm not sure what other services, if any, will be registering syncable prefs in the near term... Colin?)

Otherwise, we should DCHECK *more strictly* (anytime a service registers a syncable foreign-to-Chrome pref), and move ownership of these prefs back to Chrome until we have a proper solution.

to throw in an alternative:
We just did a deep dive through the preference stack and how we receive the data from sync. The conclusion is that we could also change the code to process sync data independently of it being registered. The only required change would be to have a new method like SetUnregisteredForSync() to PrefService allowing to store remote changes.

Given that the data coming from sync is already in the system, this should be safe to do. The only concern might be that we start storing state which might be irrelevant for the platform. One way would be to start with a white-list and collect UMA metrics about the general case allowing us to move forward.

This would be in-line with larger plans around sync, especially thinking about a Preference service supporting services which might get start at arbitrary times.

That sounds like a great first pass at delayed syncable pref registration!
I'm definitely in favor of that approach with loads of moral support :)

The NextAction date has arrived: 2018-05-03

Here's the proposal doc: https://docs.google.com/document/d/1qiVru_tzdKFnV6WkLq-KiH2sJPqiaE1RNjUaBwqWa_E/edit?ts=5aeb4b4d#

to reduce risks, I'd suggest initially only syncing a whitelist of unregistered prefs. Mike, can you help me to get that initial whitelist collected?

Yes, I'll gather a list of Ash's syncable prefs.
We'll want to add DCHECKs or similar to ensure that syncable prefs aren't registered by other services without being white-listed.

These prefs trigger the PrefModelAssociator::RegisterPref DCHECK ( testing via https://chromium-review.googlesource.com/c/chromium/src/+/1012788 )
 ash::prefs::kShelfAlignment / "shelf_alignment"
 ash::prefs::kTapDraggingEnabled / "settings.touchpad.enable_tap_dragging"
 ash::prefs::kShelfAutoHideBehavior / "auto_hide_behavior"
 ash::prefs::kLaunchPaletteOnEjectEvent / "settings.launch_palette_on_eject_event"
 ash::prefs::kEnableStylusTools / "settings.enable_stylus_tools"

I also found this one that seems to be test-only via codesearch:
 ash::prefs::kEnableAutoScreenLock / "settings.enable_screen_lock"

Here's a helpful codesearch link to check again when you're authoring the whitelist:
  https://cs.chromium.org/search/?q=SYNCABLE(_PRIORITY)*_PREF+f:Ash&type=cs
(hopefully ash isn't pulling in code from elsewhere that registers syncable prefs)

Hopefully we'll DCHECK anytime a syncable pref is registered as foreign (owned outside Chrome) and isn't on the whitelist (whether sync has initialized or not), to reliably provide instructions for adding prefs to the whitelist.

https://chromium-review.googlesource.com/1074688 supporting lazy registrations got submitted (https://bugs.chromium.org/p/chromium/issues/detail?id=840332#c2).

Next step: change PrefRegistrySyncable to whitelist the ash preferences. I'm OOO this week; if someone wants to pick this up in the meantime, feel free :)

Hey Tim, thanks for pushing through support for lazy registration!
I modified my earlier CL to whitelists Ash's syncable foreign prefs:
 https://chromium-review.googlesource.com/c/chromium/src/+/1012788

It would be nice to add something that notifies authors adding new foreign syncable prefs.
Ideally, some DCHECK would be triggered for *any* non-whitelisted foreign syncable pref.
As-is, DCHECKs only fire when the race condition triggers sync init before pref registration.

FYI, jamescook@ also wants more strict DCHECKs like I suggest in #62:
  http://crrev.com/c/1012788/7/chrome/browser/chromeos/preferences.cc#121

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/fbd7cd51202b857cd4305b02639a4632c3f7ce03

commit fbd7cd51202b857cd4305b02639a4632c3f7ce03
Author: Mike Wasserman <msw@chromium.org>
Date: Wed May 30 22:39:16 2018

cros: Whitelist delayed registration of Ash's foreign syncable prefs

Use PrefRegistrySyncable's new whitelist for delayed pref registration.
(there's a race between ash prefs connecting to chrome and sync init)
Avoids PrefServiceSyncable::AddRegisteredSyncablePreference DCHECKs.

See the bug and earlier patch sets for debug code to trigger the race:
1) Build chromeos=1 on linux desktop with this patch applied
2) Run chrome --user-data-dir=/tmp/foo --login-manager
3) Go through setup, sign in to an existing account
4) Launch chrome again, sign in quickly, wait ~10s for a DCHECK

Bug:  788918 
Change-Id: Ib505194900b34154b3896373b93c951a6eeb8715
Reviewed-on: https://chromium-review.googlesource.com/1012788
Reviewed-by: James Cook <jamescook@chromium.org>
Commit-Queue: Michael Wasserman <msw@chromium.org>
Cr-Commit-Position: refs/heads/master@{#563037}
[modify] https://crrev.com/fbd7cd51202b857cd4305b02639a4632c3f7ce03/chrome/browser/chromeos/preferences.cc

about #62 and #64: About adding DCHECKs.
The current implementation has the same DCHECK behavior as before: If a pref has not been whitelisted and is being
a) registered after the initial sync happened or
b) modified via sync before being registered
debug builds will crash as that behavior is not supported.

to the request:
"""
Ideally, some DCHECK would be triggered for *any* non-whitelisted foreign syncable 
pref.
"""

I feel, this change is outside the scope of synced preferences but more a feature request for foreign preferences. I'm not sure I have the bandwidth for that.

For this particular bug, my suggested next steps would be:
a) sanity check the UMA histograms on dev (July) and beta (beginning of August)
b) wait until it it's on stable (goes out with M69 on Sept 4th)
c) remove the whitelist all together with M70 (if b) looks good).

I'm satisfied with that, thanks.

setting next action to verify histograms on dev.

The NextAction date has arrived: 2018-06-25

Checked on dev: https://uma.googleplex.com/p/chrome/histograms/?endDate=latest&dayCount=7&histograms=Sync.Preferences.ClearedLocalPrefOnTypeMismatch%2CSync.Preferences.RemotePrefTypeMismatch%2CSync.Preferences.SyncingUnknownPrefs&fixupData=true&showMax=true&filters=platform%2Cone_of%2CA%7CC%7Ci%7CL%7CM%7CT%7CW%2Cchannel%2Ceq%2C2%2Cisofficial%2Ceq%2CTrue&implicitFilters=isofficial

Only few error events happened within the last 7 days:
Sync.Preferences.ClearedLocalPrefOnTypeMismatch: 1,048 
Sync.Preferences.RemotePrefTypeMismatch: 15
Sync.Preferences.SyncingUnknownPrefs
  -0: 3,611,580
  -1: 11
  -2: 3

sync-triage ping: any updates?

The NextAction date has arrived: 2018-08-09

numbers on beta look good: https://uma.googleplex.com/p/chrome/histograms/?endDate=latest&dayCount=7&histograms=Sync.Preferences.ClearedLocalPrefOnTypeMismatch%2CSync.Preferences.RemotePrefTypeMismatch%2CSync.Preferences.SyncingUnknownPrefs&fixupData=true&uniqueUsers=true&showMax=true&filters=platform%2Cone_of%2CA%7CC%7Ci%7CL%7CM%7CT%7CW%2Cchannel%2Ceq%2C3%2Cmilestone%2Ceq%2C69%2Cisofficial%2Ceq%2CTrue&implicitFilters=isofficial

Let's check again in two weeks

The NextAction date has arrived: 2018-08-21

Beta looks good. Checking again on stable rollout.

The NextAction date has arrived: 2018-09-10

Metrics still look good. Given that the M69 rollout is still around 10%, will check again next week before closing.

https://uma.googleplex.com/p/chrome/histograms/?endDate=latest&dayCount=7&histograms=Sync.Preferences.ClearedLocalPrefOnTypeMismatch%2CSync.Preferences.RemotePrefTypeMismatch%2CSync.Preferences.SyncingUnknownPrefs&fixupData=true&uniqueUsers=true&showMax=true&filters=platform%2Cone_of%2CA%7CC%7Ci%7CL%7CM%7CT%7CW%2Cchannel%2Ceq%2C4%2Cmilestone%2Ceq%2C69%2Cisofficial%2Ceq%2CTrue&implicitFilters=isofficial

The NextAction date has arrived: 2018-09-20

tschumann@: can this be closed now? Thanks!

Checked the metrics again for M69+ on stable-- all good.

Sync.Preferences.ClearedLocalPrefOnTypeMismatch: 
estimated user count: 7,008
count: 163,826

Sync.Preferences.RemotePrefTypeMismatch
(client ignores these)
estimated user count: 1,041
count: 14,507

Sync.Preferences.SyncingUnknownPrefs
0: 161M users
1: 2,362 users / 3,699 count
2: 1,056 users / 1,406 count
3: 315 users /  407 count
4: 1 user / 1 count