New issue
Advanced search Search tips

Issue 846725 link

Starred by 2 users
Status: Verified
Owner:
ljusten@chromium.org
Closed: May 2018
Components:
EstimatedDays: ----
NextAction: ----
OS: Chrome
Pri: 2
Type: Bug



Sign in to add a comment

authpolicy: Need backoff strategy for AuthenticateUser

Project Member Reported by ljusten@chromium.org, May 25 2018 
What steps will reproduce the problem?
(1) Have no network on signin screen and GoogleGuestPSK in user session
(2) Sign in

What is the expected result?
User auth succeeds.

What happens instead?
User auth fails because a DNS query fails since GoogleGuestPSK isn't fully set up yet. After a short while DNS is ready and GetUserStatus returns that the TGT is invalid, so you get a "please relog" popup. You log out and back in and auth fails again. Rinse, repeat.

Solution may be to keep retrying auth for a few times.

Comment 1 by rsorokin@chromium.org, May 28 2018

Labels: -OS-iOS
Project Member

Comment 2 by bugdroid1@chromium.org, May 30 2018 

The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/platform2/+/3910b3e93afde41748a0bca8e3f29b8cc6a71271

commit 3910b3e93afde41748a0bca8e3f29b8cc6a71271
Author: Lutz Justen <ljusten@chromium.org>
Date: Wed May 30 00:15:25 2018

authpolicy: Retry user auth on network problems

Right now, if the network is still connecting while a user logs in, the
call to AuthenticateUser() fails. Once the network is available and
Chrome calls GetUserStatus(), Chrome figures out that authentication
failed, but network is available, so Chrome pops up a dialog asking the
user to relog. The user relogs, AuthenticateUser() fails again for the
same reason and so on.

This CL implements the following retry strategy:
- Try to authenticate as many times as possible within a 10 second
  window.
- Try at least twice in case the first try takes long for some reason
  because the network is initializing.
- Make sure two tries are at least 0.5 seconds apart to prevent spam.
This should make sure authpolicyd retries long enough until the network
is available. Note that this implements a blocking wait since it does
not make much sense to allow other calls like RefreshUserPolicy() before
the user is authenticated.

BUG= chromium:846725 
TEST=P2_TEST_FILTER="AuthPolicyTest.AuthFailsNetworkProblem" cros_workon_make --board=amd64-generic --test authpolicy
     Setup on device: Disconnect ethernet, make sure no network is
     connected on login screen, log in, connect to a network (e.g.
     Google guest, assuming that has connection to AD server), log out.
     Now log in and watch /var/log/authpolicy.log. It should contain
     something like this:
       Received 'AuthenticateUser' request
       AuthenticateUser failed with network problem. Retrying. 1 tries, time left 9.9162s.
       AuthenticateUser failed with network problem. Retrying. 2 tries, time left 9.41194s.
       AuthenticateUser failed with network problem. Retrying. 3 tries, time left 8.9025s.
       AuthenticateUser failed with network problem. Retrying. 4 tries, time left 8.41222s.
       AuthenticateUser failed with network problem. Retrying. 5 tries, time left 7.91839s.
       AuthenticateUser succeeded
     There should also be no popup in Chrome asking you to relog.

Change-Id: I4fb23aadb2cc480ae11e352f20965ed02271e27e
Reviewed-on: https://chromium-review.googlesource.com/1075107
Commit-Ready: Lutz Justen <ljusten@chromium.org>
Tested-by: Lutz Justen <ljusten@chromium.org>
Reviewed-by: Roman Sorokin <rsorokin@chromium.org>

[modify] https://crrev.com/3910b3e93afde41748a0bca8e3f29b8cc6a71271/authpolicy/authpolicy_unittest.cc
[modify] https://crrev.com/3910b3e93afde41748a0bca8e3f29b8cc6a71271/authpolicy/samba_interface.cc
[modify] https://crrev.com/3910b3e93afde41748a0bca8e3f29b8cc6a71271/authpolicy/tgt_manager.cc
[modify] https://crrev.com/3910b3e93afde41748a0bca8e3f29b8cc6a71271/authpolicy/tgt_manager.h
[modify] https://crrev.com/3910b3e93afde41748a0bca8e3f29b8cc6a71271/authpolicy/samba_interface.h

Comment 3 by ljusten@chromium.org, May 30 2018

Owner: ljusten@chromium.org
Status: Fixed (was: Assigned)

Comment 4 by ibezmenov@chromium.org, Jun 19 2018 

To verify this bug I have performed the following steps:

1. Enroll and join device to AD
2. Login as user
3. Logout, disconnect network
4. Login -> "please relog" popup
5. Connect network, logout
6. Login, check /var/log/authpolicy.log

There is no popup in Chrome asking to relog and everything looks correct, however I don't see "AuthenticateUser failed with network problem. Retrying..." messages in authpolicy.log (attached).

Lutz, could you please confirm if this is a correct behavior?

Chrome OS: 10718.27.0
Chrome: 68.0.3440.31
Device: Reks
authpolicy.log
16.1 KB View Download

Comment 5 by ljusten@chromium.org, Jun 20 2018 

This is not the intended behavior. However, I noticed you're testing in M68, but the CL missed M68. The first build that has it is 10734.0.0.

Comment 6 by ibezmenov@chromium.org, Jun 20 2018 

Sorry, didn't check where CL is landed.

Now I tested this in M69:

1. Enroll and join device to AD
2. Login as user
3. Logout, disconnect network
4. Login -> no "please relog" popup
5. Connect network -> "please relog" popup, logout
6. Login, check /var/log/authpolicy.log

localhost / # grep -i Authen /var/log/authpolicy.log 
2018-06-20T17:31:08.265604+00:00 INFO authpolicyd[2896]: #033[107;1;30mReceived 'AuthenticateUser' request#033[0m
2018-06-20T17:31:20.340617+00:00 INFO authpolicyd[2896]: #033[42;1;97mAuthenticateUser succeeded#033[0m
2018-06-20T17:31:20.340713+00:00 WARNING authpolicyd[2896]: Timer AuthPolicy.TimeToAuthenticateUser failed to report.
2018-06-20T17:32:26.482503+00:00 INFO authpolicyd[4876]: #033[107;1;30mReceived 'AuthenticateUser' request#033[0m
2018-06-20T17:32:26.606043+00:00 WARNING authpolicyd[4876]: AuthenticateUser failed with network problem. Retrying. 1 tries, time left 9.87821s.
2018-06-20T17:32:27.125764+00:00 WARNING authpolicyd[4876]: AuthenticateUser failed with network problem. Retrying. 2 tries, time left 9.35858s.
2018-06-20T17:32:27.617101+00:00 WARNING authpolicyd[4876]: AuthenticateUser failed with network problem. Retrying. 3 tries, time left 8.86715s.
2018-06-20T17:32:28.120150+00:00 WARNING authpolicyd[4876]: AuthenticateUser failed with network problem. Retrying. 4 tries, time left 8.36411s.
2018-06-20T17:32:28.610243+00:00 WARNING authpolicyd[4876]: AuthenticateUser failed with network problem. Retrying. 5 tries, time left 7.87401s.
2018-06-20T17:32:29.119777+00:00 WARNING authpolicyd[4876]: AuthenticateUser failed with network problem. Retrying. 6 tries, time left 7.36448s.
2018-06-20T17:32:29.614328+00:00 WARNING authpolicyd[4876]: AuthenticateUser failed with network problem. Retrying. 7 tries, time left 6.86992s.
2018-06-20T17:32:30.109937+00:00 WARNING authpolicyd[4876]: AuthenticateUser failed with network problem. Retrying. 8 tries, time left 6.37432s.
2018-06-20T17:32:30.613366+00:00 WARNING authpolicyd[4876]: AuthenticateUser failed with network problem. Retrying. 9 tries, time left 5.87089s.
2018-06-20T17:32:31.121721+00:00 WARNING authpolicyd[4876]: AuthenticateUser failed with network problem. Retrying. 10 tries, time left 5.36253s.
2018-06-20T17:32:31.612139+00:00 WARNING authpolicyd[4876]: AuthenticateUser failed with network problem. Retrying. 11 tries, time left 4.87211s.
2018-06-20T17:32:32.122821+00:00 WARNING authpolicyd[4876]: AuthenticateUser failed with network problem. Retrying. 12 tries, time left 4.36143s.
2018-06-20T17:32:32.624464+00:00 WARNING authpolicyd[4876]: AuthenticateUser failed with network problem. Retrying. 13 tries, time left 3.85979s.
2018-06-20T17:32:33.111356+00:00 WARNING authpolicyd[4876]: AuthenticateUser failed with network problem. Retrying. 14 tries, time left 3.3729s.
2018-06-20T17:32:33.612807+00:00 WARNING authpolicyd[4876]: AuthenticateUser failed with network problem. Retrying. 15 tries, time left 2.87145s.
2018-06-20T17:32:34.111662+00:00 WARNING authpolicyd[4876]: AuthenticateUser failed with network problem. Retrying. 16 tries, time left 2.37259s.
2018-06-20T17:32:34.681523+00:00 WARNING authpolicyd[4876]: AuthenticateUser failed with network problem. Retrying. 17 tries, time left 1.80273s.
2018-06-20T17:32:35.158314+00:00 WARNING authpolicyd[4876]: AuthenticateUser failed with network problem. Retrying. 18 tries, time left 1.32594s.
2018-06-20T17:32:35.638124+00:00 WARNING authpolicyd[4876]: AuthenticateUser failed with network problem. Retrying. 19 tries, time left 0.846131s.
2018-06-20T17:32:36.150557+00:00 WARNING authpolicyd[4876]: AuthenticateUser failed with network problem. Retrying. 20 tries, time left 0.333699s.
2018-06-20T17:32:36.645069+00:00 INFO authpolicyd[4876]: #033[41;1;97mAuthenticateUser failed with code 19#033[0m
2018-06-20T17:32:36.645135+00:00 WARNING authpolicyd[4876]: Timer AuthPolicy.TimeToAuthenticateUser failed to report.
2018-06-20T17:32:36.645513+00:00 ERR authpolicyd[4876]: User not logged in. Did AuthenticateUser() fail?
2018-06-20T17:44:16.151126+00:00 INFO authpolicyd[6784]: #033[107;1;30mReceived 'AuthenticateUser' request#033[0m
2018-06-20T17:44:28.159367+00:00 INFO authpolicyd[6784]: #033[42;1;97mAuthenticateUser succeeded#033[0m
2018-06-20T17:44:28.159464+00:00 WARNING authpolicyd[6784]: Timer AuthPolicy.TimeToAuthenticateUser failed to report.
localhost / # 

Now it looks correct?

Chrome OS: 10798.0.0
Chrome: 69.0.3464.0
Device: Robo
authpolicy.log
963 KB View Download

Comment 7 by ljusten@chromium.org, Jun 20 2018 

I would expect a few failed attempts during step 6) around

2018-06-20T17:44:16.151126+00:00 INFO authpolicyd[6784]: #033[107;1;30mReceived 'AuthenticateUser' request#033[0m
2018-06-20T17:44:28.159367+00:00 INFO authpolicyd[6784]: #033[42;1;97mAuthenticateUser succeeded#033[0m

For me, auth fails for about 4 seconds and then it succeeds. Did you check that you had no network on the login screen before step 6? For the validation it's important that it connects to a network while you log in.

If you don't get the same results, it's also possible that it's because your setup is different, so don't bother too much. For instance, your auth takes 12 seconds, for me it's only about 3.

Comment 8 by ibezmenov@chromium.org, Jun 20 2018

Status: Verified (was: Fixed)
Ok, now I was able to get the correct results connecting to a network while login during step 6:

2018-06-20T22:25:22.900450+00:00 WARNING authpolicyd[6458]: AuthenticateUser failed with network problem. Retrying. 20 tries, time left 0.274347s.
2018-06-20T22:25:24.417425+00:00 INFO authpolicyd[6458]: #033[41;1;97mAuthenticateUser failed with code 19#033[0m
2018-06-20T22:25:24.417653+00:00 WARNING authpolicyd[6458]: Timer AuthPolicy.TimeToAuthenticateUser failed to report.
2018-06-20T22:25:24.418219+00:00 ERR authpolicyd[6458]: User not logged in. Did AuthenticateUser() fail?
2018-06-20T22:28:27.027586+00:00 INFO authpolicyd[7394]: #033[107;1;30mReceived 'AuthenticateUser' request#033[0m
2018-06-20T22:28:27.145215+00:00 WARNING authpolicyd[7394]: AuthenticateUser failed with network problem. Retrying. 1 tries, time left 9.88246s.
2018-06-20T22:28:27.647433+00:00 WARNING authpolicyd[7394]: AuthenticateUser failed with network problem. Retrying. 2 tries, time left 9.38025s.
2018-06-20T22:28:28.138717+00:00 WARNING authpolicyd[7394]: AuthenticateUser failed with network problem. Retrying. 3 tries, time left 8.88896s.
2018-06-20T22:28:28.651422+00:00 WARNING authpolicyd[7394]: AuthenticateUser failed with network problem. Retrying. 4 tries, time left 8.37626s.
2018-06-20T22:28:29.189603+00:00 WARNING authpolicyd[7394]: AuthenticateUser failed with network problem. Retrying. 5 tries, time left 7.83807s.
2018-06-20T22:28:29.651856+00:00 WARNING authpolicyd[7394]: AuthenticateUser failed with network problem. Retrying. 6 tries, time left 7.37582s.
2018-06-20T22:28:30.162580+00:00 WARNING authpolicyd[7394]: AuthenticateUser failed with network problem. Retrying. 7 tries, time left 6.8651s.
2018-06-20T22:28:30.660898+00:00 WARNING authpolicyd[7394]: AuthenticateUser failed with network problem. Retrying. 8 tries, time left 6.36678s.
2018-06-20T22:28:31.156311+00:00 WARNING authpolicyd[7394]: AuthenticateUser failed with network problem. Retrying. 9 tries, time left 5.87137s.
2018-06-20T22:28:31.658784+00:00 WARNING authpolicyd[7394]: AuthenticateUser failed with network problem. Retrying. 10 tries, time left 5.36889s.
2018-06-20T22:28:32.155540+00:00 WARNING authpolicyd[7394]: AuthenticateUser failed with network problem. Retrying. 11 tries, time left 4.87214s.
2018-06-20T22:28:32.645444+00:00 WARNING authpolicyd[7394]: AuthenticateUser failed with network problem. Retrying. 12 tries, time left 4.38223s.
2018-06-20T22:28:33.144118+00:00 WARNING authpolicyd[7394]: AuthenticateUser failed with network problem. Retrying. 13 tries, time left 3.88356s.
2018-06-20T22:28:33.688864+00:00 WARNING authpolicyd[7394]: AuthenticateUser failed with network problem. Retrying. 14 tries, time left 3.33881s.
2018-06-20T22:28:34.142188+00:00 WARNING authpolicyd[7394]: AuthenticateUser failed with network problem. Retrying. 15 tries, time left 2.88549s.
2018-06-20T22:28:34.657895+00:00 WARNING authpolicyd[7394]: AuthenticateUser failed with network problem. Retrying. 16 tries, time left 2.36978s.
2018-06-20T22:28:45.843025+00:00 INFO authpolicyd[7394]: #033[42;1;97mAuthenticateUser succeeded#033[0m
2018-06-20T22:28:45.843195+00:00 WARNING authpolicyd[7394]: Timer AuthPolicy.TimeToAuthenticateUser failed to report.
localhost / # 

Thanks, Lutz! Marking this as "Verified".
►

Sign in to add a comment