New issue
Advanced search Search tips
Note: Color blocks (like █ or █) mean that a user may not be available. Tooltip shows the reason.

Issue 650543 link

Starred by 1 user
Status: Fixed
Owner:
xiy...@chromium.org
Closed: Sep 2016
Cc:
█ dpolukhin@chromium.org
█ alexclarke@chromium.org
haraken@chromium.org
dcheng@chromium.org
█ ginkage@chromium.org
achuith@chromium.org
sa...@chromium.org
altimin@chromium.org
Components:
EstimatedDays: ----
NextAction: ----
OS: ----
Pri: 2
Type: Bug

Blocking:
issue 624694



Sign in to add a comment

DeviceIDTest.PRE_PRE_PRE_PRE_NewUsers test fails if SuspendableTimer uses the timer task queue

Project Member Reported by dcheng@chromium.org, Sep 27 2016 
This is true, even before the change to timer task queue priority in non-visible iframes. I've been poking at this, and want to dump out some notes.

I think it's related to some timing issues around postMessage in the OOBE, possibly in https://cs.chromium.org/chromium/src/google_apis/test/embedded_setup_chromeos.html?rcl=0&l=30.

Some random debugging traces:

A good signin session looks like this:
DEBUG: Waiting for session start =====
[12373:12373:0926/181027:WARNING:CONSOLE(2295)] "Unrecognized message from GAIA: clearOldAttempts", source: chrome://oobe/gaia_auth_host.js (2295)
[12373:12373:0926/181027:WARNING:CONSOLE(2295)] "Unrecognized message from GAIA: clearOldAttempts", source: chrome://oobe/gaia_auth_host.js (2295)
[12373:12415:0926/181027:ERROR:fake_gaia.cc(315)] Unhandled request /favicon.ico
[12373:12415:0926/181027:WARNING:embedded_test_server.cc(200)] Request not handled. Returning 404: /favicon.ico
127.0.0.1 - - [26/Sep/2016 18:10:27] "GET /favicon.ico HTTP/1.1" 404 -
[12373:12373:0926/181027:WARNING:CONSOLE(2295)] "Unrecognized message from GAIA: clearOldAttempts", source: chrome://oobe/gaia_auth_host.js (2295)
[12373:12373:0926/181027:WARNING:CONSOLE(2295)] "Unrecognized message from GAIA: clearOldAttempts", source: chrome://oobe/gaia_auth_host.js (2295)
[12373:12415:0926/181028:WARNING:fake_gaia.cc(312)] Serving request /_/embedded/lookup/accountlookup
127.0.0.1 - - [26/Sep/2016 18:10:28] "POST /_/embedded/lookup/accountlookup HTTP/1.1" 200 -
[12373:12415:0926/181028:WARNING:fake_gaia.cc(312)] Serving request /_/embedded/signin/challenge
127.0.0.1 - - [26/Sep/2016 18:10:28] "POST /_/embedded/signin/challenge HTTP/1.1" 200 -
[12373:12415:0926/181028:WARNING:fake_gaia.cc(312)] Serving request /oauth2/v4/token
127.0.0.1 - - [26/Sep/2016 18:10:28] "POST /oauth2/v4/token HTTP/1.1" 200 -
[12373:12373:0926/181028:WARNING:merge_session_throttling_utils.cc(138)] Loading content for a profile without session restore?
[12373:12373:0926/181028:WARNING:merge_session_throttling_utils.cc(138)] Loading content for a profile without session restore?
[12373:12408:0926/181028:WARNING:local_extension_cache.cc(259)] Extensions will not be installed from update URLs until /tmp/.org.chromium.Chromium.tnP5gw/dQM83tP/stub_device_local_extension_cache/.initialized 
exists.
[12373:12373:0926/181028:ERROR:chrome_user_manager_impl.cc(382)] ===== DEBUG: LOOK A SESSION START =====

A bad signin session looks like this:
[13278:13278:0926/181254:ERROR:device_id_browsertest.cc(113)] ===== DEBUG: Waiting for session start =====
[13278:13278:0926/181254:WARNING:CONSOLE(2295)] "Unrecognized message from GAIA: clearOldAttempts", source: chrome://oobe/gaia_auth_host.js (2295)
[13278:13278:0926/181254:WARNING:CONSOLE(2295)] "Unrecognized message from GAIA: clearOldAttempts", source: chrome://oobe/gaia_auth_host.js (2295)
[13278:13323:0926/181254:ERROR:fake_gaia.cc(315)] Unhandled request /favicon.ico
[13278:13323:0926/181254:WARNING:embedded_test_server.cc(200)] Request not handled. Returning 404: /favicon.ico
127.0.0.1 - - [26/Sep/2016 18:12:54] "GET /favicon.ico HTTP/1.1" 404 -
[13278:13278:0926/181254:WARNING:CONSOLE(2295)] "Unrecognized message from GAIA: clearOldAttempts", source: chrome://oobe/gaia_auth_host.js (2295)
[13278:13323:0926/181255:WARNING:fake_gaia.cc(312)] Serving request /_/embedded/lookup/accountlookup
127.0.0.1 - - [26/Sep/2016 18:12:55] "POST /_/embedded/lookup/accountlookup HTTP/1.1" 200 -
[13278:13323:0926/181255:WARNING:fake_gaia.cc(312)] Serving request /_/embedded/signin/challenge
127.0.0.1 - - [26/Sep/2016 18:12:55] "POST /_/embedded/signin/challenge HTTP/1.1" 200 -
[13278:13278:0926/181255:INFO:signin_screen_handler.cc(1288)] Login WebUI >> active: 0, source: account-picker
[13278:13278:0926/181255:WARNING:CONSOLE(2295)] "Unrecognized message from GAIA: clearOldAttempts", source: chrome://oobe/gaia_auth_host.js (2295)
Still waiting for the following processes to finish:

There's a small initial difference: in the original code, clearOldAttempts() runs before the signin page posts a response to the signin challenge.
However, in the new code, the clearOldAttempts message comes after the signin page already posted a response. So maybe this is somehow clobbering the login cookies?

Another interesting thing to note is that the warning message is coming from https://cs.chromium.org/chromium/src/chrome/browser/resources/gaia_auth_host/authenticator.js?rcl=0&l=610, which would seem to indicate that it's not actually handled and shouldn't be doing anything. Next debugging steps are to instrument some JS code with console.log to see what's actually getting run.

Comment 1 by dcheng@chromium.org, Sep 27 2016 

Hmm, that might not be it. In PRE_PRE_PRE_PRE_PRE_NewUser, the callbacks occur in different orders, but the signin still works.

The stack where chrome::NOTIFICATION_SESSION_STARTED looks a little different in the two as well, but I'm not yet sure this is the cause either.

Comment 2 by dcheng@chromium.org, Sep 27 2016

Cc: dpolukhin@chromium.org ginkage@chromium.org achuith@chromium.org
CCing people who wrote this test.

Is there an easy way to debug the renderers involved in this? I tried just using console.log, but --single-process is broken. I suspect there's some sort of race, but I'm not familiar with the Gaia internals, which is making debugging this harder than necessary

Comment 3 by dcheng@chromium.org, Sep 29 2016

Cc: dcheng@chromium.org
Owner: xiy...@chromium.org
xiyuan@ has found the problem and will prepare a patch: apparently attemptLogin is unused (?) and the actually race is between a postmessage to send the password (in https://cs.chromium.org/chromium/src/google_apis/test/embedded_setup_chromeos.html?rcl=0&l=47) and maybeCompleteAuth_ in the loadcommit event in the webview.

This timing changes with the Blink changes, since posted messages are delivered with SuspendableTimer, exposing this race.
Project Member

Comment 4 by bugdroid1@chromium.org, Sep 30 2016 

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

commit 4caa576572fa920a66f1e9449daa9f41ce80b76f
Author: xiyuan <xiyuan@chromium.org>
Date: Fri Sep 30 16:35:54 2016

cros: Fix API 'add' password and complete auth racing

Authenticator.maybeCompleteAuth_ is attempted on webview.loadcommit
and webview.request.onCompleted events. Auth is completed when all
info is collected. Gaia uses credential passing API to send back the
password. This, however, is not bound to the two events. If the
two events happen before the 'add' API calls through, auth never
gets completed. This CL fixes the racing by adding maybeCompleteAuth_
on the API 'add' call.

BUG= 650543 
TEST=Existing login tests should pass.
CQ_INCLUDE_TRYBOTS=master.tryserver.chromium.linux:closure_compilation

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

[modify] https://crrev.com/4caa576572fa920a66f1e9449daa9f41ce80b76f/chrome/browser/resources/gaia_auth_host/authenticator.js
[modify] https://crrev.com/4caa576572fa920a66f1e9449daa9f41ce80b76f/chrome/browser/resources/gaia_auth_host/saml_handler.js

Comment 5 by xiy...@chromium.org, Sep 30 2016

Status: Fixed (was: Started)
Let's see how the test goes with CL https://codereview.chromium.org/2250553002/.
►

Sign in to add a comment