This failed a pre-CQ run of mine too:
https://luci-milo.appspot.com/buildbot/chromiumos.tryserver/pre_cq/21699

if Davit hit thi in a pre-cq, it's more likely a bug-on-tot than a bad CL.

I haven't seen this since that build, and the Connection refused makes me think it might be a flake.  I guess we can keep an eye out and see if we're seeing a lot more instances of this.

I took a look at the blame list but no one seems suspicious. And so far as leecy@ mentioned all following builds succeeded. Probably just flake, mark as WontFix for now unless we've seen more.

Two more examples found while annotating old failed builds:

https://luci-milo.appspot.com/buildbot/chromiumos/x86-generic-paladin/28898

https://luci-milo.appspot.com/buildbot/chromiumos/x86-generic-paladin/28903

just happened

https://luci-milo.appspot.com/buildbot/chromiumos/x86-generic-paladin/28952

I believe it's a flaky test. I saw this error in the PreCQ, resubmitted CL:452731, and passed.

I have no idea why or where it came from, but it looks like a bug in TOT (either code or test, hard to tell).

This failed a pre-CQ run of mine too: https://luci-milo.appspot.com/buildbot/chromiumos.tryserver/pre_cq/23480 (change https://chromium-review.googlesource.com/#/c/447865/ )

I've seen it happen a few times on the waterfall too, though I can't find a link anymore. I'll try to reproduce locally.

I managed to repro relatively consistently locally, against a self-built ~ToT x86-generic VM image.

Steps to repro:
Start the VM:
$ qemu-system-x86_64 -smp 4 --enable-kvm -daemonize -display none -m 2G -vga cirrus -net nic,model=virtio -net user,hostfwd=tcp:127.0.0.1:9222-:22 -drive format=raw,file=${CROS_CHECKOUT}/src/build/images/x86-generic/R59-9388.0.2017_03_22_1720-a1/chromiumos_qemu_image.bin,cache=unsafe

Run the test in a loop:
chroot$ for loop in `seq 1 50`; do echo "RUNNING ITERATION $loop"; test_that -b x86-generic 127.0.0.1:9222 desktopui_ScreenLocker || break; done


I ran that twice, the first time it failed after 40 iterations, the second time after 7 iterations.

I tried removing "cache=unsafe" from the qemu command (vpalatin@ had reported that signing in the Play Store would often fail until he removed that option) and it seemed to improve reliability somewhat, but I did get a failure after 198 iterations. So it may not have actually made it more reliable and it could be a coincidence that it took longer to fail in that case.

Note that I could not get it to fail against a cyan image (with cache=unsafe) after running the 50 iterations test 3 times. That may be random, or cyan may be less flaky. It does happen occasionally though: https://uberchromegw.corp.google.com/i/chromeos.chrome/builders/cyan-tot-chrome-pfq-informational/builds/1969

Achuith, would you be the right owner for that?

Jake is probably the right owner.

Having a closer look at the VM, it looks like Chrome crashed at the time the test failed. Attaching various logs, the coredump itself is too large to be attached.

Deleted: chrome_logs.tar.gz 12.0 KB

chrome_logs.tar.gz 12.0 KB Download

Deleted: messages.gz 5.1 MB

messages.gz 5.1 MB Download

Deleted: ui_logs.tar.gz 4.9 KB

ui_logs.tar.gz 4.9 KB Download

Full test results, including the core file: https://drive.google.com/a/google.com/file/d/0B1HHKpeDpzYnNWFlYnNtSzdPOWs/view?usp=sharing

Similar error, but this time:
1_autotest_tests/results-20-desktopui_ScreenLocker                                      [  FAILED  ]
1_autotest_tests/results-20-desktopui_ScreenLocker                                            FAIL: Unhandled DevToolsClientConnectionError: [Errno 104] Connection reset by peer
1_autotest_tests/results-20-desktopui_ScreenLocker/desktopui_ScreenLocker                   [  FAILED  ]
1_autotest_tests/results-20-desktopui_ScreenLocker/desktopui_ScreenLocker                     FAIL: Unhandled DevToolsClientConnectionError: [Errno 104] Connection reset by peer

[https://build.chromium.org/p/chromiumos/builders/x86-generic-paladin/builds/29148]

In https://pantheon.corp.google.com/storage/browser/chromeos-image-archive/x86-generic-paladin/R59-9411.0.0-rc1/vm_test_results_1/smoke_suite/test_harness/all/SimpleTestVerify/1_autotest_tests/results-20-desktopui_ScreenLocker/desktopui_ScreenLocker/sysinfo/var/log_diff/ui/

  ui.20170329-085105 has a crash dump, not actionable as-is:
[20294:20294:0329/085119.589155:ERROR:base_screen_handler_utils.cc(70)] Failed to deserialize 'test@test.test'
[20294:20294:0329/085119.917608:ERROR:extended_authenticator_impl.cc(340)] Supervised user cryptohome error, code: 2
[20294:20294:0329/085119.918062:ERROR:core_oobe_handler.cc(173)] CoreOobeHandler::ShowSignInError: error_text=Sorry, your password could not be verified. Please try again.
[20294:20294:0329/085120.093286:ERROR:base_screen_handler_utils.cc(70)] Failed to deserialize 'test@test.test'
[20294:20294:0329/085121.876218:ERROR:base_screen_handler_utils.cc(70)] Failed to deserialize 'test@test.test'
Received signal 11 SEGV_MAPERR 000000000150
#0 0x000057fa72c6 <unknown>
#1 0x000057fa6d27 <unknown>
#2 0x000057fa77f6 <unknown>
#3 0x000077786a28 ([vdso]+0xa27)
#4 0x000057571a66 <unknown>
#5 0x00005765bc38 <unknown>
#6 0x000056351774 <unknown>
#7 0x00005751ba7e <unknown>
#8 0x00005751e495 <unknown>
#9 0x00005751ee4b <unknown>
#10 0x000057556a98 <unknown>
#11 0x000057570272 <unknown>
#12 0x00005a5aaa97 <unknown>
#13 0x000055ae3094 <unknown>
#14 0x0000571a1951 <unknown>
#15 0x00005600691d <unknown>
#16 0x0000565444f6 <unknown>
#17 0x000056543f5a <unknown>
#18 0x00005654472d <unknown>
#19 0x00005652a985 <unknown>
#20 0x0000564009e3 <unknown>
#21 0x000056413292 <unknown>
#22 0x0000563f9e12 <unknown>
#23 0x00005866a1af <unknown>
#24 0x000056000c2d <unknown>
#25 0x00005805fc81 <unknown>
#26 0x000057fce930 <unknown>
#27 0x000057fcee00 <unknown>
#28 0x000057fd132c <unknown>
#29 0x000057fd1a6f <unknown>
#30 0x000057fce608 <unknown>
#31 0x000057ffc205 <unknown>
#32 0x000057b37353 <unknown>
#33 0x0000560ee48b <unknown>
#34 0x0000560f38c6 <unknown>
#35 0x0000560e9ea8 <unknown>
#36 0x000057ab93f2 <unknown>
#37 0x000057ab94e2 <unknown>
#38 0x000057ab7c25 <unknown>
#39 0x00005950073b <unknown>
#40 0x000057ab7d69 <unknown>
#41 0x000055a2dab7 <unknown>
#42 0x000055a2a837 <unknown>
#43 0x000076e96699 __libc_start_main
#44 0x000055a2d837 <unknown>
  gs: 00000033  fs: 00000000  es: 0000007b  ds: 0000007b
 edi: 576528d0 esi: 607c5160 ebp: 7fdde3c8 esp: 7fdde3b0
 ebx: 5fdbec1c edx: 60edc4b0 ecx: 60bd9e00 eax: 00000000
 trp: 0000000e err: 00000004  ip: 57571a66  cs: 00000073
 efl: 00010202 usp: 7fdde3b0  ss: 0000007b
[end of stack trace]

I'm seeing desktopui_ScreenLocker failures in caroline-pre-cq, for example:
https://luci-milo.appspot.com/buildbot/chromiumos.tryserver/pre_cq/26658

I have a commit that has failed pre-cq twice on this failure. I don't think it's my CL:
https://chromium-review.googlesource.com/c/470366/

04/07 17:11:13.348 INFO | test_runner_utils:0198| autoserv| AUTOTEST_STATUS::		FAIL	desktopui_ScreenLocker	desktopui_ScreenLocker	timestamp=1491603073	localtime=Apr 07 17:11:13	Unhandled LoginException: Timed out going through login screen. Cryptohome not mounted. OOBE not dismissed.
04/07 17:11:13.349 INFO | test_runner_utils:0198| autoserv| FAIL	desktopui_ScreenLocker	desktopui_ScreenLocker	timestamp=1491603073	localtime=Apr 07 17:11:13	Unhandled LoginException: Timed out going through login screen. Cryptohome not mounted. OOBE not dismissed.
04/07 17:11:13.349 INFO | test_runner_utils:0198| autoserv| AUTOTEST_STATUS::  Traceback (most recent call last):
04/07 17:11:13.350 INFO | test_runner_utils:0198| autoserv| AUTOTEST_STATUS::    File "/usr/local/autotest/common_lib/test.py", line 817, in _call_test_function
04/07 17:11:13.350 INFO | test_runner_utils:0198| autoserv| AUTOTEST_STATUS::      return func(*args, **dargs)
04/07 17:11:13.350 INFO | test_runner_utils:0198| autoserv| AUTOTEST_STATUS::    File "/usr/local/autotest/common_lib/test.py", line 470, in execute
04/07 17:11:13.351 INFO | test_runner_utils:0198| autoserv| AUTOTEST_STATUS::      dargs)
04/07 17:11:13.351 INFO | test_runner_utils:0198| autoserv| AUTOTEST_STATUS::    File "/usr/local/autotest/common_lib/test.py", line 347, in _call_run_once_with_retry
04/07 17:11:13.351 INFO | test_runner_utils:0198| autoserv| AUTOTEST_STATUS::      postprocess_profiled_run, args, dargs)
04/07 17:11:13.352 INFO | test_runner_utils:0198| autoserv| AUTOTEST_STATUS::    File "/usr/local/autotest/common_lib/test.py", line 380, in _call_run_once
04/07 17:11:13.352 INFO | test_runner_utils:0198| autoserv| AUTOTEST_STATUS::      self.run_once(*args, **dargs)
04/07 17:11:13.352 INFO | test_runner_utils:0198| autoserv| AUTOTEST_STATUS::    File "/usr/local/autotest/tests/desktopui_ScreenLocker/desktopui_ScreenLocker.py", line 164, in run_once
04/07 17:11:13.353 INFO | test_runner_utils:0198| autoserv| AUTOTEST_STATUS::      with chrome.Chrome(autotest_ext=True) as self._chrome:
04/07 17:11:13.353 INFO | test_runner_utils:0198| autoserv| AUTOTEST_STATUS::    File "/usr/local/autotest/common_lib/cros/chrome.py", line 158, in __init__
04/07 17:11:13.353 INFO | test_runner_utils:0198| autoserv| AUTOTEST_STATUS::      self._browser = browser_to_create.Create(finder_options)
04/07 17:11:13.354 INFO | test_runner_utils:0198| autoserv| AUTOTEST_STATUS::    File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome/cros_browser_finder.py", line 50, in Create
04/07 17:11:13.354 INFO | test_runner_utils:0198| autoserv| AUTOTEST_STATUS::      self._credentials_path)
04/07 17:11:13.354 INFO | test_runner_utils:0198| autoserv| AUTOTEST_STATUS::    File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome/cros_browser_with_oobe.py", line 14, in __init__
04/07 17:11:13.355 INFO | test_runner_utils:0198| autoserv| AUTOTEST_STATUS::      backend, platform_backend, credentials_path)
04/07 17:11:13.355 INFO | test_runner_utils:0198| autoserv| AUTOTEST_STATUS::    File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/browser/browser.py", line 58, in __init__
04/07 17:11:13.355 INFO | test_runner_utils:0198| autoserv| AUTOTEST_STATUS::      self._browser_backend.Start()
04/07 17:11:13.356 INFO | test_runner_utils:0198| autoserv| AUTOTEST_STATUS::    File "/usr/local/telemetry/src/third_party/catapult/common/py_trace_event/py_trace_event/trace_event_impl/decorators.py", line 52, in traced_function
04/07 17:11:13.356 INFO | test_runner_utils:0198| autoserv| AUTOTEST_STATUS::      return func(*args, **kwargs)
04/07 17:11:13.356 INFO | test_runner_utils:0198| autoserv| AUTOTEST_STATUS::    File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome/cros_browser_backend.py", line 169, in Start
04/07 17:11:13.356 INFO | test_runner_utils:0198| autoserv| AUTOTEST_STATUS::      + self._GetLoginStatus())
04/07 17:11:13.357 INFO | test_runner_utils:0198| autoserv| AUTOTEST_STATUS::    File "/usr/local/telemetry/src/third_party/catapult/common/py_trace_event/py_trace_event/trace_event_impl/decorators.py", line 52, in traced_function
04/07 17:11:13.357 INFO | test_runner_utils:0198| autoserv| AUTOTEST_STATUS::      return func(*args, **kwargs)
04/07 17:11:13.357 INFO | test_runner_utils:0198| autoserv| AUTOTEST_STATUS::    File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome/cros_browser_backend.py", line 277, in _RaiseOnLoginFailure
04/07 17:11:13.358 INFO | test_runner_utils:0198| autoserv| AUTOTEST_STATUS::      raise exceptions.LoginException(error)
04/07 17:11:13.358 INFO | test_runner_utils:0198| autoserv| AUTOTEST_STATUS::  LoginException: Timed out going through login screen. Cryptohome not mounted. OOBE not dismissed.
04/07 17:11:13.371 INFO | test_runner_utils:0198| autoserv| AUTOTEST_STATUS::	END FAIL	desktopui_ScreenLocker	desktopui_ScreenLocker	timestamp=1491603073	localtime=Apr 07 17:11:13
04/07 17:11:13.372 INFO | test_runner_utils:0198| autoserv| END FAIL	desktopui_ScreenLocker	desktopui_ScreenLocker	timestamp=1491603073	localtime=Apr 07 17:11:13
04/07 17:11:13.401 INFO | test_runner_utils:0198| autoserv| AUTOTEST_TEST_COMPLETE:/usr/local/autotest/tmp/_autotmp_b2wSEiharness-fifo/autoserv.fifo

This is failing the initial chrome login (before the screen can be locked), so it doesn't seem specific to desktopui_ScreenLocker

Cryptohome is failing [1]; this looks like a separate issue.

chrome:    
    [12544:12544:0407/165602.816550:ERROR:device_event_log_impl.cc(137)] [16:56:02.816] Login: homedir_methods.cc:413 HomedirMethods MountEx error: 5
    [12544:12544:0407/165602.816612:ERROR:device_event_log_impl.cc(137)] [16:56:02.816] Login: cryptohome_authenticator.cc:900 Cryptohome failure: state=2, code=1
    [12544:12544:0407/165602.816634:VERBOSE1:cryptohome_authenticator.cc(745)] Resolved state to: 2
    [12544:12544:0407/165602.816767:ERROR:device_event_log_impl.cc(137)] [16:56:02.816] Login: cryptohome_authenticator.cc:678 Login failed: Could not mount cryptohome.
    [12544:12544:0407/165602.816820:ERROR:login_performer.cc(63)] Login failure, reason=1, error.state=0
    [12544:12544:0407/165602.816913:VERBOSE1:existing_user_controller.cc(1123)] Could not mount cryptohome.


messages:
    2017-04-07T21:40:51.012516+00:00 WARNING cryptohomed[820]: TSS: Got a list of valid IPs
    2017-04-07T21:40:51.012780+00:00 WARNING cryptohomed[820]: TSS: Could not connect to machine: localhost
    2017-04-07T21:40:51.012806+00:00 ERR cryptohomed[820]: TSS: Could not connect to any machine in the list.
    2017-04-07T21:40:51.012814+00:00 ERR cryptohomed[820]: TSS: Failed to send packet
    2017-04-07T21:40:51.113166+00:00 WARNING cryptohomed[820]: TSS: Failed unix connect: /var/run/tcsd.socket - No such file or directory
    2017-04-07T21:40:51.113233+00:00 WARNING cryptohomed[820]: TSS: Got a list of valid IPs
    2017-04-07T21:40:51.113501+00:00 WARNING cryptohomed[820]: TSS: Could not connect to machine: localhost
    2017-04-07T21:40:51.113525+00:00 ERR cryptohomed[820]: TSS: Could not connect to any machine in the list.
    2017-04-07T21:40:51.113534+00:00 ERR cryptohomed[820]: TSS: Failed to send packet
    2017-04-07T21:40:51.214249+00:00 WARNING cryptohomed[820]: TSS: Failed unix connect: /var/run/tcsd.socket - No such file or directory
    2017-04-07T21:40:51.214319+00:00 WARNING cryptohomed[820]: TSS: Got a list of valid IPs
    2017-04-07T21:40:51.214631+00:00 WARNING cryptohomed[820]: TSS: Could not connect to machine: localhost
    2017-04-07T21:40:51.214655+00:00 ERR cryptohomed[820]: TSS: Could not connect to any machine in the list.
    2017-04-07T21:40:51.214664+00:00 ERR cryptohomed[820]: TSS: Failed to send packet
    2017-04-07T21:40:51.315180+00:00 ERR cryptohomed[820]: TPM error 0x3011 (Communication failure): Error calling Tspi_Context_Connect
    2017-04-07T21:40:51.315295+00:00 ERR cryptohomed[820]: ConnectContextAsUser: Could not open the TPM
    2017-04-07T21:40:51.315316+00:00 ERR cryptohomed[820]: ExtendPCR: Failed to connect to the TPM.
    2017-04-07T21:40:51.315358+00:00 WARNING cryptohomed[820]: Failed to finalize boot lockbox.
    2017-04-07T21:40:51.315416+00:00 WARNING cryptohomed[820]: Could not load the device policy file.
    2017-04-07T21:40:51.316013+00:00 WARNING cryptohomed[820]: No valid keysets on disk for 93b58ca74bea4d48b61a7eb7450ac0e27acbff19
    2017-04-07T21:40:51.316034+00:00 ERR cryptohomed[820]: Failed to decrypt any keysets for 93b58ca74bea4d48b61a7eb7450ac0e27acbff19
    2017-04-07T21:40:51.316051+00:00 ERR cryptohomed[820]: Error, cryptohome must be re-created because of fatal error.
    2017-04-07T21:40:51.375621+00:00 ERR cryptohomed[820]: Fatal decryption error, but unable to remove cryptohome.
    2017-04-07T21:40:51.375975+00:00 WARNING cryptohomed[820]: PKCS#11 initialization requested but cryptohome is not mounted.
    

1: https://pantheon.corp.google.com/storage/browser/chromeos-image-archive/trybot-caroline-pre-cq/R59-9440.0.0-b26658/vm_test_results_1/smoke_suite/test_harness/all/SimpleTestVerify/1_autotest_tests/results-10-desktopui_ScreenLocker/desktopui_ScreenLocker/sysinfo/var/log_diff/

See  issue 709693