Cryptohome has been changing a lot lately + the cryptohome error messages make it the most likely candidate. We call out to cryptohome to check the password via the CheckKeyEx method.

2017-05-08T08:55:18.643952-05:00 INFO session_manager[7176]: [INFO:session_manager_impl.cc(625)] LockScreen() method called.
2017-05-08T08:55:18.655405-05:00 DEBUG kernel: [ 1230.308879] SELinux: initialized (dev proc, type proc), uses genfs_contexts
2017-05-08T08:55:18.948465-05:00 WARNING kernel: [ 1230.601080] hwrng: no data available
2017-05-08T08:55:19.402078-05:00 INFO session_manager[7176]: [INFO:session_manager_impl.cc(629)] HandleLockScreenShown() method called.
*** 2017-05-08T08:55:19.591608-05:00 ERR cryptohomed[788]: DecryptFinal Error: 101077092: digital envelope routines, EVP_DecryptFinal_ex, bad decrypt
*** 2017-05-08T08:55:20.001798-05:00 ERR cryptohomed[788]: Vault Keyset Scrypt decryption returned error code: 11
2017-05-08T08:55:20.798998-05:00 WARNING cryptohomed[788]: RemoveKeyset: key to remove not found
2017-05-08T08:55:21.461571-05:00 INFO session_manager[7176]: [INFO:session_manager_impl.cc(635)] HandleLockScreenDismissed() method called.
2017-05-08T08:55:21.547651-05:00 INFO session_manager[7176]: [INFO:session_manager_impl.cc(625)] LockScreen() method called.
2017-05-08T08:55:21.553414-05:00 DEBUG kernel: [ 1233.206760] SELinux: initialized (dev proc, type proc), uses genfs_contexts
2017-05-08T08:55:22.155399-05:00 INFO session_manager[7176]: [INFO:session_manager_impl.cc(629)] HandleLockScreenShown() method called.
2017-05-08T08:55:22.456052-05:00 WARNING cryptohomed[788]: RemoveKeyset: key to remove not found
2017-05-08T08:55:23.231470-05:00 DEBUG kernel: [ 1234.884318] SELinux: initialized (dev proc, type proc), uses genfs_contexts
2017-05-08T08:55:28.949821-05:00 WARNING kernel: [ 1240.602113] hwrng: no data available
2017-05-08T08:55:32.224847-05:00 NOTICE autotest[7559]: 08:55:32.210 ERROR|             utils:2745| Failed to unlock screen

Trying to make sense of the logs.

1) Am I right that the fact that Chrome sent HandleLockScreenDismissed to the session_manager, means that the screen unlock succeeded? 
2) Is it possible that the test user in this autotest has several keysets (e.g. PIN unlock enabled)?

Note the following sequence in the logs:

2017-05-08T08:55:19.402078-05:00 INFO session_manager[7176]: [INFO:session_manager_impl.cc(629)] HandleLockScreenShown() method called.
...
2017-05-08T08:55:19.591608-05:00 ERR cryptohomed[788]: DecryptFinal Error: 101077092: digital envelope routines, EVP_DecryptFinal_ex, bad decrypt
2017-05-08T08:55:20.001798-05:00 ERR cryptohomed[788]: Vault Keyset Scrypt decryption returned error code: 11
...
2017-05-08T08:55:21.461571-05:00 INFO session_manager[7176]: [INFO:session_manager_impl.cc(635)] HandleLockScreenDismissed() method called.

The cryptohome errors in the middle mean that when checking the credentials, a vault keyset for the user's homedir was found, but decrypting that vault keyset with the provided credentials failed. That may or may not be an indication of an error, however. If there are several vault keyset files for the user (e.g. a PIN and a password), when attempting to unlock, cryptohomed goes through all of them until one of them works. And all keysets tried unsuccessfully before the last one worked would print out this error.

So, it looks like the 1st attempted screen unlock actually succeeded. Then the screen was locked again and the second unlock was attempted, and this time it failed:

2017-05-08T08:55:21.547651-05:00 INFO session_manager[7176]: [INFO:session_manager_impl.cc(625)] LockScreen() method called.
...
2017-05-08T08:55:22.155399-05:00 INFO session_manager[7176]: [INFO:session_manager_impl.cc(629)] HandleLockScreenShown() method called.
...
2017-05-08T08:55:32.224847-05:00 NOTICE autotest[7559]: 08:55:32.210 ERROR|             utils:2745| Failed to unlock screen

This time there were no cryptohomed errors. Iiuc, that probably means that CheckKeyEx was not called, or actually completed successfully. Otherwise, there would either be a "No valid keysets on disk for <s_h_o_u>" warning from HomeDirs::GetValidKeyset(), or one or more "Vault Keyset Scrypt decryption returned error code: XX" errors from Crypto::DecryptScrypt() as before. The only other way to CheckKeyEx to silently fail seems to be the absence of the home directory for the user, or having ephemeral users enabled in the policy and not being the device owner.

I'm also a bit confused by the (unsuccessful) calls to Homedirs::RemoveKeyset between locking and unlocking the screen ("RemoveKeyset: key to remove not found"). They can only be be triggered by RemoveKeyEx requests from Chrome. Is there anything in the test that'd cause those calls?

Gardener here. Any updates on this issue? It just failed again:

https://luci-milo.appspot.com/buildbot/chromiumos.chromium/amd64-generic-tot-chromium-pfq-informational/12197

I don't really know anything about screen lock/unlock or this test. I do see this in the test logs:

05/10 13:09:39.863 INFO |    input_playback:0437| Playing back finger-movement on /dev/input/event3, file=/usr/local/autotest/cros/input_playback/keyboard_search+L.
05/10 13:09:40.061 INFO |    input_playback:0465| Blocking for 0.478221893311 seconds after playback.
05/10 13:09:50.648 ERROR|             utils:2745| Failed to unlock screen

The keyboard_search+L makes me think that you are right and the first unlock succeeds (based on test source in original description).

+xiyuan, any ideas here?

Not sure. Yes, it seems the 2nd unlock fails.

In #5 log, 

First lock:
2017-05-10T20:09:37.207777+00:00 INFO session_manager[3467]: [INFO:session_manager_impl.cc(625)] LockScreen() method called.
...
2017-05-10T20:09:38.211440+00:00 INFO session_manager[3467]: [INFO:session_manager_impl.cc(629)] HandleLockScreenShown() method called.

Try bad password, fail to unlock:
2017-05-10T20:09:38.363622+00:00 ERR cryptohomed[823]: DecryptFinal Error: 101077092: digital envelope routines, EVP_DecryptFinal_ex, bad decrypt
...

Correct password unlocks
2017-05-10T20:09:39.740480+00:00 INFO session_manager[3467]: [INFO:session_manager_impl.cc(635)] HandleLockScreenDismissed() method called
...

Lock via accelerator
2017-05-10T20:09:39.905199+00:00 INFO session_manager[3467]: [INFO:session_manager_impl.cc(625)] LockScreen() method called.
2017-05-10T20:09:40.942858+00:00 INFO session_manager[3467]: [INFO:session_manager_impl.cc(629)] HandleLockScreenShown() method called.
...

This unlock times out, but we have this
2017-05-10T20:09:41.573957+00:00 WARNING cryptohomed[823]: RemoveKeyset: key to remove not found

This should be a result of UserSessionManager::GetInstance()->UpdateEasyUnlockKeys() in screen_locker.cc [1]

[1]: https://cs.chromium.org/chromium/src/chrome/browser/chromeos/login/lock/screen_locker.cc?rcl=6c27b49745a0438d33ca75f939a90a3bf8205d77&l=337

I think the OnAuthSuccess for the 2nd unlock is called. But somehow, the lock screen is not dismissed.

Can we turn on screen_locker vlog for this test? It seems we don't have them currently.

xiyuan - can you take a look at this?

I tried this with a ToT Chrome OS image (self-built) in a VM and I could not repro. I can see it go through the expected sequence on screen.

(Note: You can't use go/cros-vm because the screen is black because the fix for issue 719983 has not yet made it into the VM images.)

We are already passing vmodule=screen_locker=2 to chrome when running this test. I don't know why the logs don't show up.

/var/log/messages:

2017-05-11T23:50:51.071745+00:00 INFO session_manager[6999]: [INFO:browser_job.cc(140)] Running child /opt/google/chrome/chrome --ppapi-flash-path=/opt/google/chrome/pepper/libpepflashplayer.so --ppapi-flash-version=26.0.0.89 --ui-prioritize-in-gpu-process --use-gl=egl --gpu-sandbox-failures-fatal=no --enable-logging --log-level=1 --use-cras --enable-wayland-server --user-data-dir=/home/chronos --max-unused-resource-memory-usage-percentage=5 --system-developer-mode --login-profile=user --aura-legacy-power-button --default-wallpaper-large=/usr/share/chromeos-assets/wallpaper/default_large.jpg --default-wallpaper-small=/usr/share/chromeos-assets/wallpaper/default_small.jpg --child-wallpaper-large=/usr/share/chromeos-assets/wallpaper/child_large.jpg --child-wallpaper-small=/usr/share/chromeos-assets/wallpaper/child_small.jpg --guest-wallpaper-large=/usr/share/chromeos-assets/wallpaper/guest_large.jpg --guest-wallpaper-small=/usr/share/chromeos-assets/wallpaper/guest_small.jpg --enable-prefixed-encrypted-media --enterprise-enrollment-initial-modulus=15 --enterprise-enrollment-modulus-limit=19 --login-manager --enable-net-benchmarking --metrics-recording-only --no-default-browser-check --no-first-run --enable-gpu-benchmarking --disable-background-networking --load-extension=/tmp/extension_hZXiX/autotest_private_ext --disable-component-extensions-with-background-pages --disable-default-apps --disable-search-geolocation-disclosure --enable-smooth-scrolling --enable-threaded-compositing --remote-debugging-port=54421 --start-maximized --ash-disable-system-sounds --allow-failed-policy-fetch-for-test --oobe-skip-postlogin --disable-gaia-services --testing-channel=NamedTestingInterface:/tmp/.org.chromium.Chromium.Uy090A/.org.chromium.Chromium.ZdSxqV --vmodule=*chromeos/login/*=1,auto_enrollment_controller=1,*plugin*=2,*zygote*=1,*/ui/ozone/*=1,*/ui/display/manager/chromeos/*=1,power_button_observer=2,webui_login_view=2,lock_state_controller=2,webui_screen_locker=2,screen_locker=2,*/chromeos/net/*=2,*/chromeos/login/*=2,chrome_browser_main_posix=2 

The screen lock log on "Failed to unlock screen" error seems suggest that SigninScreenHandler::HandleAuthenticateUser bailed out. There is an account id deserialize error, which means the handler is called. But there is no more log after that. So most likely, we bailed on null |delegate_| there.

Looking at desktopui_ScreenLocker.py and WebUIScreenLocker::LockScreen code. There seems to be a race:
- In WebUIScreenLocker::LockScreen, we load the lock screen URL then call
  GetOobeUI()->ShowSigninScreen() to pass in the delegate;
- In desktopui_ScreenLocker.py, both lock_screen and
  lock_screen_through_keyboard calls screenlocker_visible to ensure screen
  locker webui is initialized. However, screenlocker_visible could return
  true after lock screen URL is loaded but before ShowSigninScreen() happen.
  And when this happens, Oobe.authenticateForTesting will be silently ignored.

We probably need a better condition to test screen locker ready to use.