This was on guado_moblab, which has a lot of strange failures -- see e.g.  issue 898781  and  issue 901249 .

Keith, can you shed some light on how guado_moblab devices are expected to differ from other boards? Specifically, are there any sorts of tests (e.g. login, security) that aren't expected to pass reliably on guado_moblab? (See the other issues I linked to.)

I do not know muvch about cryptohome - I know that moblab has the stateful encryption switched off https://cs.corp.google.com/chromeos_public/src/overlays/project-mobbase/profiles/base/make.defaults?rcl=913907e58a986a291c83f954933566d27b93d121&l=1

Moblabs run in dev mode - and are a chromium build so anything that requires that to be enabled will fail.

Hm, I see that at the time when the test wants to create a user (assuming -08:00 timezone), TPM is indeed not owned yet

11/05 13:31:31.542 INFO |             utils:0287| [stdout] [13:31:31.080] Logging in as user "testuser@gmail.com"
[8488:8488:1105/133131.588451:VERBOSE1:webui_login_view.cc(604)] Login WebUI >> login-prompt-visible

2018-11-05T21:31:31.356895+00:00 ERR cryptohomed[886]: TpmIsReady: is not owned.
2018-11-05T21:31:31.356915+00:00 ERR cryptohomed[886]: HasAuthorization: TPM not ready.
2018-11-05T21:31:31.356927+00:00 ERR cryptohomed[886]: Destroy() called with insufficient authorization.

11/05 13:31:31.850 INFO |             utils:0287| [stdout] [13:31:31.386] Waiting for cryptohome for user "testuser@gmail.com"

Then we timeout:
11/05 13:33:23.668 INFO |             utils:0287| [stdout] [13:33:23.205] cryptohome status: [...]
11/05 13:33:23.698 INFO |             utils:0287| [stdout] [13:33:23.235] /sys/class/misc/tpm0/device/owned contains "0"
11/05 13:33:23.699 INFO |             utils:0287| [stdout] [13:33:23.236] Error at chrome_crash_logged_in.go:26: Chrome login failed: not mounted for testuser@gmail.com: context deadline exceeded; last error follows: /home/user/2ddf6cac31a9e6ea059dffc6262dbab50a688a36 not found

And then TPM initialization is triggered after session restart, and goes fine:
2018-11-05T21:33:29.994008+00:00 ERR cryptohomed[886]: Taking TPM ownership took 2612ms
2018-11-05T21:33:29.994134+00:00 INFO cryptohomed[886]: Configuring TPM, ownership taken: 1.

2018-11-05T21:33:30.708625+00:00 INFO cryptohomed[886]: Attestation: Preparing for enrollment...

2018-11-05T21:33:37.999834+00:00 INFO cryptohomed[886]: Attestation: Prepared successfully (7291 ms).


Not sure if that's the scenario (logging in on a yet unowned system) we want to test here (see  issue 901363 , for example).
But, in any case, the fact that TPM is not owned shouldn't prevent the user from being created. Users can log in before the TPM is owned, they just use software keys temporarily in such case.


There is also this from chrome:
[8488:8488:1105/133132.064219:WARNING:enrollment_screen_handler.cc(673)] EnrollmentScreenHandler::UpdateState(): state=online, reason=update
[8488:8488:1105/133132.483905:ERROR:CONSOLE(0)] "Error in event handler for webViewInternal.onHeadersReceived/34: Error: Invalid value for argument 4. Property 'frameId': Unexpected property, Property 'method': Unexpected property, Property 'parentFrameId': Unexpected property, Property 'requestId': Unexpected property, Property 'statusCode': Unexpected property, Property 'statusLine': Unexpected property, Property 'tabId': Unexpected property, Property 'timeStamp': Unexpected property, Property 'type': Unexpected property, Property 'url': Unexpected property.", source: chrome://oobe/oobe (0)
[8488:8488:1105/133133.980795:ERROR:CONSOLE(0)] "Error in event handler for webViewInternal.onHeadersReceived/34: Error: Invalid value for argument 4. Property 'frameId': Unexpected property, Property 'method': Unexpected property, Property 'parentFrameId': Unexpected property, Property 'requestId': Unexpected property, Property 'statusCode': Unexpected property, Property 'statusLine': Unexpected property, Property 'tabId': Unexpected property, Property 'timeStamp': Unexpected property, Property 'type': Unexpected property, Property 'url': Unexpected property.", source: chrome://oobe/oobe (0)
[8488:8488:1105/133133.992539:ERROR:CONSOLE(0)] "Error in event handler for webViewInternal.onHeadersReceived/34: Error: Invalid value for argument 4. Property 'frameId': Unexpected property, Property 'method': Unexpected property, Property 'parentFrameId': Unexpected property, Property 'requestId': Unexpected property, Property 'statusCode': Unexpected property, Property 'statusLine': Unexpected property, Property 'tabId': Unexpected property, Property 'timeStamp': Unexpected property, Property 'type': Unexpected property, Property 'url': Unexpected property.", source: chrome://oobe/oobe (0)
[8488:8488:1105/133134.259598:WARNING:enrollment_screen_handler.cc(673)] EnrollmentScreenHandler::UpdateState(): state=online, reason=update
[8488:8488:1105/133134.298290:WARNING:CONSOLE(17379)] "Unrecognized message from GAIA: showConfirmCancel", source: chrome://oobe/oobe.js (17379)
[8488:8488:1105/133201.398658:WARNING:enrollment_screen_handler.cc(673)] EnrollmentScreenHandler::UpdateState(): state=online, reason=update
[8488:8488:1105/133231.419176:WARNING:enrollment_screen_handler.cc(673)] EnrollmentScreenHandler::UpdateState(): state=online, reason=update
[8488:8488:1105/133236.005416:ERROR:CONSOLE(0)] "Error in event handler for webViewInternal.onHeadersReceived/34: Error: Invalid value for argument 4. Property 'frameId': Unexpected property, Property 'method': Unexpected property, Property 'parentFrameId': Unexpected property, Property 'requestId': Unexpected property, Property 'statusCode': Unexpected property, Property 'statusLine': Unexpected property, Property 'tabId': Unexpected property, Property 'timeStamp': Unexpected property, Property 'type': Unexpected property, Property 'url': Unexpected property.", source: chrome://oobe/oobe (0)
[8488:8488:1105/133253.314857:WARNING:enrollment_screen_handler.cc(673)] EnrollmentScreenHandler::UpdateState(): state=online, reason=update

So, is it still showing enrollment screen for some reason, and doing some kind of update, instead of login?

I'm hopeful that making Tast take ownership of the TPM before running tests ( issue 901363 ) will help here. If this is still happening after that, I'll either reopen this or file a new more-specific bug.