-UI>Browser>Sessions as that is for session restore where as these logs are from login.

If this message is from the sign-in process then why is it popping up (regularly) in the log long after sign-in has taken place?

Since I only converted this code from one content interface (ResourceThrottle) to another (NavigationThrottle), I am not very familiar with what it's doing.

Adding achuith who is listed as an owner for ChromeOS login and might have a better idea.

Could you attach some logs to this bug? +xiyuan for the merge session throttling utils message

Re #4: Can you be more specific as to which logging you're asking for? I can share you a copy of a full log off-bug if you like (too much logspam to attach to the bug), or if there is something specific you're looking for then I can probably provide that on-bug.

The warning happens when we launched browser before actually starts the session restore process. Not sure how this gets happened though. UserSessionManager::RestoreAuthSessionImpl should be called before we create browsers in UserSessionManager::InitializeUserSession.

Issue 639204 has been merged into this issue.

Re #6: Might that explain why we lose the session-restore option entirely if Chrome happens to crash again before the user has clicked the "Restore" button?

 Issue 614757  has been merged into this issue.

This is still an issue at 55.0.2878.0. Achuith, can you take a look for M55, plz?

FWIW these log messages all occur within the first 1-2 seconds of startup, according to the log, but there are loads of them logged.

Looking at the relevant code, it seems this will be logged every time ShouldDelayRequestForProfile() is invoked and finds that we are in the unexpected state of being signed-in but with session-restore not yet started. See https://cs.chromium.org/chromium/src/chrome/browser/chromeos/login/signin/merge_session_throttling_utils.cc?sq=package:chromium&rcl=1475752711&l=130

These log messages therefore mean either that the session-restore throttle logic is wrong about that being an invalid state, or that something has changed elsewhere that puts us in an invalid state; either way seems bad.

 Issue 654061  has been merged into this issue.

I'm able to repro this consistently in my ToT cyan builds, so I added some logging in the three files that call the ShouldDelayRequest* methods. It looks like the calls that generate the warnings are coming from this code in chrome/browser/search/search.cc:

---

bool ShouldShowLocalNewTab(const GURL& url, Profile* profile) {
#if defined(OS_CHROMEOS)
  // On Chrome OS, if the session hasn't merged yet, we need to avoid loading
  // the remote NTP because that will trigger showing the merge session throttle
  // interstitial page, which can show for 5+ seconds.  crbug.com/591530 .
  if (merge_session_throttling_utils::ShouldDelayRequestForProfile(profile) &&
      merge_session_throttling_utils::ShouldDelayUrl(url)) {
    return true;
  }
#endif  // defined(OS_CHROMEOS)

  if (!profile->IsOffTheRecord() &&
      base::FeatureList::IsEnabled(kUseGoogleLocalNtp) &&
      DefaultSearchProviderIsGoogle(profile)) {
    return true;
  }

  return false;
}

----

When I log url.spec() in this function, it appears to be empty.

I'm not sure why this is called so many times, either. I count 20 early calls that produce the "Loading content for a profile without session restore?" warning, and then many more calls later from search.cc still have empty URLs but don't generate the warning, with a few calls with NTP URLs interspersed:

...
[19029:19029:1010/105555:VERBOSE1:oauth2_login_manager.cc(106)] Loading OAuth2 refresh token from database.
[19029:19029:1010/105555:VERBOSE1:arc_bridge_service_impl.cc(51)] Session started
[19029:19029:1010/105555:VERBOSE1:arc_bridge_service_impl.cc(78)] Prerequisites changed. state=0, session_started=1
[19029:19029:1010/105555:INFO:arc_bridge_service_impl.cc(84)] Prerequisites met, starting ARC
[19029:19029:1010/105555:VERBOSE1:input_events_blocker.cc(15)] InputEventsBlocker 0x38ca68e2e1e0 created.
[19029:19029:1010/105555:VERBOSE1:user_session_manager.cc(663)] RespectLocalePreference: app_locale='en-US', bkup_locale='en-US', account_loc
ale - unused.  Selected 'en-US'
[19029:19029:1010/105555:ERROR:search.cc(182)] XXX checking for 
[19029:19029:1010/105555:ERROR:search.cc(182)] XXX checking for 
[19029:19029:1010/105555:ERROR:search.cc(182)] XXX checking for 
[19029:19029:1010/105555:ERROR:search.cc(182)] XXX checking for 
[19029:19029:1010/105555:ERROR:search.cc(182)] XXX checking for 
[19029:19029:1010/105555:ERROR:search.cc(182)] XXX checking for 
[19029:19029:1010/105555:ERROR:search.cc(182)] XXX checking for 
[19029:19029:1010/105555:ERROR:search.cc(182)] XXX checking for 
[19029:19029:1010/105555:ERROR:search.cc(182)] XXX checking for 
[19029:19029:1010/105555:ERROR:search.cc(182)] XXX checking for 
[19029:19029:1010/105555:ERROR:search.cc(182)] XXX checking for 
[19029:19029:1010/105555:ERROR:search.cc(182)] XXX checking for 
[19029:19029:1010/105555:ERROR:search.cc(182)] XXX checking for 
[19029:19029:1010/105555:ERROR:search.cc(182)] XXX checking for 
[19029:19029:1010/105555:ERROR:search.cc(182)] XXX checking for 
[19029:19029:1010/105555:ERROR:search.cc(182)] XXX checking for 
[19029:19029:1010/105555:ERROR:search.cc(182)] XXX checking for 
[19029:19029:1010/105555:ERROR:search.cc(182)] XXX checking for 
[19029:19029:1010/105555:ERROR:search.cc(182)] XXX checking for 
[19029:19029:1010/105555:ERROR:search.cc(182)] XXX checking for 
[19029:19029:1010/105555:ERROR:search.cc(182)] XXX checking for 
[19029:19029:1010/105555:ERROR:search.cc(182)] XXX checking for 
[19029:19029:1010/105555:ERROR:search.cc(182)] XXX checking for 
[19029:19029:1010/105555:ERROR:search.cc(182)] XXX checking for 
[19029:19029:1010/105555:ERROR:search.cc(182)] XXX checking for 
[19029:19029:1010/105555:ERROR:search.cc(182)] XXX checking for 
[19029:19029:1010/105555:ERROR:search.cc(182)] XXX checking for 
[19029:19029:1010/105555:ERROR:search.cc(182)] XXX checking for 
[19029:19029:1010/105555:ERROR:search.cc(182)] XXX checking for https://www.google.com/_/chrome/newtab?espv=2&ie=UTF-8
[19029:19029:1010/105555:ERROR:search.cc(182)] XXX checking for 
[19029:19029:1010/105555:ERROR:search.cc(182)] XXX checking for 
[19029:19029:1010/105555:ERROR:search.cc(182)] XXX checking for 
[19029:19029:1010/105555:ERROR:search.cc(182)] XXX checking for 
[19029:19029:1010/105555:ERROR:search.cc(182)] XXX checking for 
[19029:19029:1010/105555:ERROR:search.cc(182)] XXX checking for 
[19029:19029:1010/105555:ERROR:search.cc(182)] XXX checking for https://www.google.com/_/chrome/newtab?espv=2&ie=UTF-8
[19029:19029:1010/105555:ERROR:search.cc(182)] XXX checking for 
[19029:19029:1010/105555:ERROR:search.cc(182)] XXX checking for 
[19029:19029:1010/105555:ERROR:search.cc(182)] XXX checking for 
[19029:19029:1010/105555:ERROR:search.cc(182)] XXX checking for 
[19029:19029:1010/105555:ERROR:search.cc(182)] XXX checking for 
[19029:19029:1010/105555:ERROR:search.cc(182)] XXX checking for 
[19029:19029:1010/105555:VERBOSE1:user_session_manager.cc(1720)] Launching browser...
[19029:19029:1010/105555:VERBOSE1:arc_net_host_impl.cc(629)] New default network: /service/1
[19029:19029:1010/105555:ERROR:search.cc(182)] XXX checking for https://www.google.com/_/chrome/newtab?espv=2&ie=UTF-8
[19029:19029:1010/105555:ERROR:search.cc(182)] XXX checking for 
[19029:19029:1010/105555:ERROR:search.cc(182)] XXX checking for 
[19029:19029:1010/105555:ERROR:search.cc(182)] XXX checking for 
[19029:19029:1010/105555:ERROR:search.cc(182)] XXX checking for 
[19029:19029:1010/105555:ERROR:search.cc(182)] XXX checking for 
[19029:19029:1010/105555:ERROR:search.cc(182)] XXX checking for 
[19029:19029:1010/105555:ERROR:search.cc(182)] XXX checking for https://www.google.com/_/chrome/newtab?espv=2&ie=UTF-8
[19029:19029:1010/105555:ERROR:search.cc(182)] XXX checking for
...

Hopefully this is cheap, because we sure are calling it a lot. :-)

We added the logic in https://codereview.chromium.org/1910693002 to avoid showing the merge session throttle interstitial page for NTP.

afakhry@, could you take a look?

Looks like ownership didn't get updated correctly here. This is still present.

This is very very hairy that I won't be able to explain it without the use of a graph, so I created one [attached].

I recorded 16 times the message "Loading content for a profile without session restore?". Two of them originate at the path starting at ProfileImpl::OnLocaleReady() [lower left-corner graph]. The remaining 14 originate at the path starting at drive::DriveIntegrationService::InitializeAfterMetadataInitialized() [top graph].

For drive::DriveIntegrationService::InitializeAfterMetadataInitialized(), we have two extensions listening to OnVolumeMounted events, namely:

  hhaomjibdihmijegdhdafkllkbggdgoj: // Files.app
  pmfjbimdmchhbnneeidfognadeopoehp: // Image Loader

So when broadcasting that event, the code emitting the log spam is reached 7 times for each listening extension.

The problem is that too many paths end up calling search::(anonymous namespace)::NewTabURLDetails::ForProfile(). Notice from the graph how all paths merge there (either directly or indirectly).

I'm not sure what would the right solution to this problem be! Suppress the warning after several times? Change some of those paths?

Deleted: call_stack.png 1.6 MB

	call_stack.png 1.6 MB View Download

What's the warning actually warning us about? Why is it a problem if we load content for a profile outside of session restore?

If this doesn't indicate a bug, we should just delete the warning.

Re #16: Based on the comment at:

https://cs.chromium.org/chromium/src/chrome/browser/chromeos/login/signin/merge_session_throttling_utils.cc?q=%22Loading+content%22&sq=package:chromium&dr=C&l=130

the message is complaining that _a tab_ is being loaded after user sign-in, but before session restore has even started, presumably because that function is only called from NewTabURLDetails?

In this case it's being called because various extensions are having events queued to them before session restore starts, and those events are for some reason calling NewTabURLDetails - so I'd echo afahkry@'s question: is it correct to be calling it in all these situations?  Bear in mind that it will potentially result in different values before and after session restore starts.

Re my final point in #17: The different values before and after session restore starts will at least impact the behaviour of the NewTabPageInterceptor, so I'd expect that users with a (remote) search URL as their NTP see slightly broken behaviour right now.

xiyuan@ and I have brainstormed this issue. The warning is raised because the function is used before we have even properly completed loading the profile.

Here is what we think will do the trick here to get rid of this warning. Please test this:

https://codereview.chromium.org/2505723002

Re #19: Aren't those early-exits effectively equivalent to the case that's issuing the warning though? The warning is being issued, IIUC, because it genuinely doesn't make sense to call this function prior to session-restore starting.

In at least one of the calling code paths the behaviour will differ if that path is executed prematurely, so the warning seems to indicate a real underlying issue.

I re-ran the experiment again today, but this time I logged 53 warnings!! All originating from paths that start with either of the following three calls:

- extensions::SerialExtensionHostQueue::ProcessOneHost()
- drive::DriveIntegrationService::InitializeAfterMetadataInitialized()
- ProfileImpl::OnLocaleReady()

The proposed fix in #19 only hides the warnings we get from the path starting at ProfileImpl::OnLocaleReady(), but it doesn't work for the other two.

chromeos::ChromeSessionManager::SessionStarted() is always received later after all three paths have returned, but the warnings have already been emitted a lot of times.

The only way we can eliminate the warnings entirely is by removing these two lines: https://cs.chromium.org/chromium/src/chrome/browser/search/search.cc?type=cs&q=NewTabURLDetails&sq=package:chromium&l=221-222, which check if we should show the local NTP. We added those lines in https://codereview.chromium.org/1910693002 to avoid showing the slow merge session interstitial page, so if we remove them,  issue 591530  comes back.

Deleted: call_stack_2.png 8.0 MB

	call_stack_2.png 8.0 MB View Download

Re #21: I suspect the logs you saw for the first two are for signin profiles since they happen before ProfileImpl::OnLocaleReady().

Could you see if they go away if we add signin profile check in ShouldDelayRequestForProfile, 
i.e. bail out if profile == ProfileHelper::GetSigninProfile() there ?

Thanks for the suggestion. That unfortunately doesn't work. I'm sorry I should have clarified that the functions listed in #21 are not ordered. The correct order is:

(1) - ProfileImpl::OnLocaleReady()
(2) - drive::DriveIntegrationService::InitializeAfterMetadataInitialized()
(3) - extensions::SerialExtensionHostQueue::ProcessOneHost()

Before (1) returns, the profile is not created yet. That's why the fix in #19 removes only the warnings generated from that path, but not the others.

The condition profile == ProfileHelper::GetSigninProfile() is never met.

Thank you for trying it out.

In this case, maybe we should reconsider how we fix  issue 591530 . How about redirecting to local NTP in NewTabPageInterceptor during merge session instead? 

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

commit 50ade576fb3292ed44ba4d8e3e1d1a999840da82
Author: afakhry <afakhry@chromium.org>
Date: Wed Dec 07 18:29:44 2016

Prevent the pre-session-restore log spam

Avoid using merge_session_throttling_utils::ShouldDelayRequestForProfile() which
spams the logs with warnings and changes the state of the profile, and instead use
the newly added function in this CL to show the local NTP if the session restore
is still pending.

BUG= 641191 

Review-Url: https://codereview.chromium.org/2537263002
Cr-Commit-Position: refs/heads/master@{#437013}

[modify] https://crrev.com/50ade576fb3292ed44ba4d8e3e1d1a999840da82/chrome/browser/chromeos/login/signin/merge_session_throttling_utils.cc
[modify] https://crrev.com/50ade576fb3292ed44ba4d8e3e1d1a999840da82/chrome/browser/chromeos/login/signin/merge_session_throttling_utils.h
[modify] https://crrev.com/50ade576fb3292ed44ba4d8e3e1d1a999840da82/chrome/browser/search/search.cc

Your change meets the bar and is auto-approved for M56 (branch: 2924)

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

commit 08948799b9c4a497563bd2ed2afb58ab8ce880db
Author: Ahmed Fakhry <afakhry@google.com>
Date: Thu Dec 08 18:21:11 2016

[Merge to M56] Prevent the pre-session-restore log spam

Avoid using merge_session_throttling_utils::ShouldDelayRequestForProfile() which
spams the logs with warnings and changes the state of the profile, and instead use
the newly added function in this CL to show the local NTP if the session restore
is still pending.

TBR=xiyuan@chromium.org,treib@chromium.org
BUG= 641191 

Review-Url: https://codereview.chromium.org/2537263002
Cr-Commit-Position: refs/heads/master@{#437013}
(cherry picked from commit 50ade576fb3292ed44ba4d8e3e1d1a999840da82)

Review URL: https://codereview.chromium.org/2560023002 .

Cr-Commit-Position: refs/branch-heads/2924@{#411}
Cr-Branched-From: 3a87aecc31cd1ffe751dd72c04e5a96a1fc8108a-refs/heads/master@{#433059}

[modify] https://crrev.com/08948799b9c4a497563bd2ed2afb58ab8ce880db/chrome/browser/chromeos/login/signin/merge_session_throttling_utils.cc
[modify] https://crrev.com/08948799b9c4a497563bd2ed2afb58ab8ce880db/chrome/browser/chromeos/login/signin/merge_session_throttling_utils.h
[modify] https://crrev.com/08948799b9c4a497563bd2ed2afb58ab8ce880db/chrome/browser/search/search.cc

Chrome:57.0.2987.6/ChromeOS:9202.1.0 (Official Build) dev-channel