The test just launches Chrome 10 times in a row and starts Android each time. Starting Android reliably is a prerequisite for CTS testing, so this is important, even though it seems like a very rare event. Nevertheless I am going to dial this test down from blocking suites because starting Chrome/Android is too noisy right now. 

We had a failure on cave paladin
https://luci-milo.appspot.com/buildbot/chromeos/cave-paladin/163

On the 8. iteration the browser doesn't respond to the SystemInfo.getInfo request.

05/05 11:43:26.229 INFO |cheets_StartAndroi:0028| cheets_StartAndroid iteration 8
[...]
05/05 11:43:32.960 INFO |cros_browser_backe:0171| Browser is up!
05/05 11:43:32.961 INFO |           browser:0116| OS: chromeos 
05/05 11:43:32.965 DEBUG|inspector_websocke:0097| sent [{
  "id": 0, 
  "method": "SystemInfo.getInfo"
}]
05/05 11:44:05.998 ERROR|           browser:0065| Failure while starting browser backend.
Traceback (most recent call last):
  File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/browser/browser.py", line 59, in __init__
    self._LogBrowserInfo()
  File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/browser/browser.py", line 117, in _LogBrowserInfo
    if self.supports_system_info:
  File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/browser/browser.py", line 322, in supports_system_info
    return self._browser_backend.supports_system_info
  File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome/chrome_browser_backend.py", line 267, in supports_system_info
    return self.GetSystemInfo() != None
  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
    return func(*args, **kwargs)
  File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome/chrome_browser_backend.py", line 276, in GetSystemInfo
    return self._system_info_backend.GetSystemInfo(timeout=30)
  File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome/system_info_backend.py", line 25, in GetSystemInfo
    res = websocket.SyncRequest(req, timeout)
  File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_websocket.py", line 110, in SyncRequest
    res = self._Receive(timeout)
  File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome_inspector/inspector_websocket.py", line 149, in _Receive
    data = self._socket.recv()
  File "/usr/local/telemetry/src/third_party/catapult/telemetry/third_party/websocket-client/websocket/_core.py", line 293, in recv
    opcode, data = self.recv_data()
  File "/usr/local/telemetry/src/third_party/catapult/telemetry/third_party/websocket-client/websocket/_core.py", line 310, in recv_data
    opcode, frame = self.recv_data_frame(control_frame)
  File "/usr/local/telemetry/src/third_party/catapult/telemetry/third_party/websocket-client/websocket/_core.py", line 323, in recv_data_frame
    frame = self.recv_frame()
  File "/usr/local/telemetry/src/third_party/catapult/telemetry/third_party/websocket-client/websocket/_core.py", line 357, in recv_frame
    return self.frame_buffer.recv_frame()
  File "/usr/local/telemetry/src/third_party/catapult/telemetry/third_party/websocket-client/websocket/_abnf.py", line 336, in recv_frame
    self.recv_header()
  File "/usr/local/telemetry/src/third_party/catapult/telemetry/third_party/websocket-client/websocket/_abnf.py", line 286, in recv_header
    header = self.recv_strict(2)
  File "/usr/local/telemetry/src/third_party/catapult/telemetry/third_party/websocket-client/websocket/_abnf.py", line 371, in recv_strict
    bytes_ = self.recv(min(16384, shortage))
  File "/usr/local/telemetry/src/third_party/catapult/telemetry/third_party/websocket-client/websocket/_core.py", line 427, in _recv
    return recv(self.sock, bufsize)
  File "/usr/local/telemetry/src/third_party/catapult/telemetry/third_party/websocket-client/websocket/_socket.py", line 83, in recv
    raise WebSocketTimeoutException(message)
WebSocketTimeoutException: timed out


I don't see a Chrome crash in messages. And it looks like Android started at the very end, just Chrome/Telemetry had issues.
2017-05-05T18:36:04.852091+00:00 INFO session_manager[6244]: [INFO:upstart_signal_emitter.cc(38)] Emitting arc-booted Upstart signal

messages
2017-05-05T18:35:46.516501+00:00 NOTICE root[6011]: autotest runtest cheets_StartAndroid
2017-05-05T18:35:47.517673+00:00 NOTICE autotest[6040]: 11:35:47.514 ERROR|               log:0027| pre-test sysinfo error:
2017-05-05T18:35:47.521504+00:00 NOTICE autotest[6042]: 11:35:47.518 ERROR|         traceback:0013| Traceback (most recent call last):
2017-05-05T18:35:47.525316+00:00 NOTICE autotest[6044]: 11:35:47.522 ERROR|         traceback:0013|   File "/usr/local/autotest/common_lib/log.py", line 25, in decorated_func
2017-05-05T18:35:47.529045+00:00 NOTICE autotest[6046]: 11:35:47.526 ERROR|         traceback:0013|     fn(*args, **dargs)
2017-05-05T18:35:47.533049+00:00 NOTICE autotest[6048]: 11:35:47.529 ERROR|         traceback:0013|   File "/usr/local/autotest/bin/site_sysinfo.py", line 306, in log_before_each_test
2017-05-05T18:35:47.537052+00:00 NOTICE autotest[6050]: 11:35:47.534 ERROR|         traceback:0013|     log.run(log_dir=None, collect_init_status=True)
2017-05-05T18:35:47.540759+00:00 NOTICE autotest[6052]: 11:35:47.537 ERROR|         traceback:0013|   File "/usr/local/autotest/bin/site_sysinfo.py", line 217, in run
2017-05-05T18:35:47.544728+00:00 NOTICE autotest[6054]: 11:35:47.541 ERROR|         traceback:0013|     self._get_init_status_of_src_dir(self.dir)
2017-05-05T18:35:47.548455+00:00 NOTICE autotest[6056]: 11:35:47.545 ERROR|         traceback:0013|   File "/usr/local/autotest/bin/site_sysinfo.py", line 131, in _get_init_status_of_src_dir
2017-05-05T18:35:47.553218+00:00 NOTICE autotest[6058]: 11:35:47.550 ERROR|         traceback:0013|     self._log_stats[file_path] = file_stat(file_path)
2017-05-05T18:35:47.557019+00:00 NOTICE autotest[6060]: 11:35:47.553 ERROR|         traceback:0013|   File "/usr/local/autotest/bin/site_sysinfo.py", line 83, in __init__
2017-05-05T18:35:47.560919+00:00 NOTICE autotest[6062]: 11:35:47.557 ERROR|         traceback:0013|     stat = os.stat(file_path)
2017-05-05T18:35:47.565151+00:00 NOTICE autotest[6064]: 11:35:47.561 ERROR|         traceback:0013| OSError: [Errno 2] No such file or directory: '/var/log/vmlog/vmlog.1.LATEST'
2017-05-05T18:35:47.762935+00:00 NOTICE root[6070]: autotest starting iteration /usr/local/autotest/results/default/cheets_StartAndroid/sysinfo/iteration.1 on cave_1.5GHz_4GB
2017-05-05T18:35:48.056986+00:00 WARNING kernel: [  343.506094] init: debugd main process (1319) killed by TERM signal
2017-05-05T18:35:48.062766+00:00 INFO session_manager[1270]: [INFO:browser_job.cc(157)] Terminating process: 
2017-05-05T18:35:48.062781+00:00 INFO session_manager[1270]: [INFO:system_utils_impl.cc(110)] Sending 15 to 1321 as 1000
2017-05-05T18:35:48.436873+00:00 INFO session_manager[1270]: [INFO:browser_job.cc(173)] Cleaned up child 1321
2017-05-05T18:35:48.436915+00:00 INFO session_manager[1270]: [INFO:session_manager_impl.cc(291)] emitting D-Bus signal SessionStateChanged:stopped
2017-05-05T18:35:48.437079+00:00 INFO session_manager[1270]: [INFO:session_manager_service.cc(487)] SessionManagerService quitting run loop
2017-05-05T18:35:48.437190+00:00 INFO session_manager[1270]: [INFO:session_manager_service.cc(214)] SessionManagerService exiting
2017-05-05T18:35:48.571718+00:00 INFO session_manager[1270]: [INFO:policy_service.cc(182)] Persisted policy to disk.
2017-05-05T18:35:48.713952+00:00 WARNING chapsd[1335]: SRK does not exist - this is normal when the TPM is not yet owned.
2017-05-05T18:35:48.796097+00:00 ERR imageloader[6149]: Failed to read latest-version file.
2017-05-05T18:35:48.796119+00:00 ERR imageloader[6149]: Failed to verify and mount component.
2017-05-05T18:35:48.807598+00:00 WARNING kernel: [  344.257037] init: imageloader main process (6149) terminated with status 1
2017-05-05T18:35:48.864805+00:00 ERR session_manager[6244]: [ERROR:cros_config.cc(89)] Could not run command mosys platform model
2017-05-05T18:35:48.869543+00:00 WARNING session_manager[6244]: [WARNING:libpolicy.cc(36)] Could not load the device policy file.
2017-05-05T18:35:48.869823+00:00 INFO session_manager[6244]: [INFO:session_manager_main.cc(195)] Will wait 3s for graceful browser exit.
2017-05-05T18:35:48.872481+00:00 INFO session_manager[6244]: [INFO:session_manager_service.cc(142)] SessionManagerService starting
2017-05-05T18:35:48.873934+00:00 INFO session_manager[6244]: [INFO:policy_key.cc(53)] No policy key on disk at /var/lib/whitelist/owner.key
2017-05-05T18:35:48.876327+00:00 INFO session_manager[6244]: [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 --enable-native-gpu-memory-buffers --gpu-sandbox-failures-fatal=yes --enable-logging --log-level=1 --use-cras --enable-wayland-server --arc-availability=officially-supported --user-data-dir=/home/chronos --max-unused-resource-memory-usage-percentage=5 --system-developer-mode --login-profile=user --has-chromeos-keyboard --enable-touchview --default-wallpaper-large=/usr/share/chromeos-assets/wallpaper/oem_large.jpg --default-wallpaper-small=/usr/share/chromeos-assets/wallpaper/oem_small.jpg --default-wallpaper-is-oem --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 --enable-consumer-kiosk --enterprise-enrollment-initial-modulus=15 --enterprise-enrollment-modulus-limit=19 --login-manager --vmodule=*arc/*=1,*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 
2017-05-05T18:35:48.876968+00:00 INFO session_manager[6244]: [INFO:session_manager_service.cc(225)] Browser is 6274
2017-05-05T18:35:48.924596+00:00 DEBUG kernel: [  344.373857] SELinux: initialized (dev tmpfs, type tmpfs), uses transition SIDs
2017-05-05T18:35:49.103847+00:00 INFO session_manager[6244]: [INFO:browser_job.cc(149)] Terminating process group: Restarting browser on-demand.
2017-05-05T18:35:49.103867+00:00 INFO session_manager[6244]: [INFO:system_utils_impl.cc(110)] Sending 9 to -6274 as 1000
2017-05-05T18:35:49.140597+00:00 DEBUG kernel: [  344.590343] SELinux: initialized (dev proc, type proc), uses genfs_contexts
2017-05-05T18:35:49.142290+00:00 INFO session_manager[6244]: [INFO:child_exit_handler.cc(77)] Handling 6274 exit.
2017-05-05T18:35:49.142303+00:00 ERR session_manager[6244]: [ERROR:child_exit_handler.cc(85)]   Exited with signal 9
2017-05-05T18:35:49.142314+00:00 INFO session_manager[6244]: [INFO:session_manager_service.cc(274)] Exiting process is chrome.
2017-05-05T18:35:49.142322+00:00 INFO session_manager[6244]: [INFO:browser_job.cc(149)] Terminating process group: Ensuring browser processes are gone.
2017-05-05T18:35:49.142329+00:00 INFO session_manager[6244]: [INFO:system_utils_impl.cc(110)] Sending 9 to -6274 as 1000
2017-05-05T18:35:49.142366+00:00 INFO session_manager[6244]: [INFO:browser_job.cc(173)] Cleaned up child 6274
2017-05-05T18:35:49.142682+00:00 INFO session_manager[6244]: [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 --enable-native-gpu-memory-buffers --gpu-sandbox-failures-fatal=yes --enable-logging --log-level=1 --use-cras --enable-wayland-server --arc-availability=officially-supported --user-data-dir=/home/chronos --max-unused-resource-memory-usage-percentage=5 --system-developer-mode --login-profile=user --has-chromeos-keyboard --enable-touchview --default-wallpaper-large=/usr/share/chromeos-assets/wallpaper/oem_large.jpg --default-wallpaper-small=/usr/share/chromeos-assets/wallpaper/oem_small.jpg --default-wallpaper-is-oem --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 --enable-consumer-kiosk --enterprise-enrollment-initial-modulus=15 --enterprise-enrollment-modulus-limit=19 --login-manager --disable-arc-opt-in-verification --enable-net-benchmarking --metrics-recording-only --no-default-browser-check --no-first-run --enable-gpu-benchmarking --disable-background-networking --load-extension=/tmp/extension_Ak9wM/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=55557 --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.ohWhdw/.org.chromium.Chromium.4Z7UPJ --vmodule=*arc/*=1,*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 
2017-05-05T18:35:49.143157+00:00 INFO session_manager[6244]: [INFO:session_manager_service.cc(225)] Browser is 6312
2017-05-05T18:35:49.530626+00:00 DEBUG kernel: [  344.979817] SELinux: initialized (dev proc, type proc), uses genfs_contexts
2017-05-05T18:35:49.622606+00:00 DEBUG kernel: [  345.071999] SELinux: initialized (dev proc, type proc), uses genfs_contexts
2017-05-05T18:35:49.634592+00:00 DEBUG kernel: [  345.084666] SELinux: initialized (dev proc, type proc), uses genfs_contexts
2017-05-05T18:35:50.415280+00:00 INFO permission_broker[1420]: ProcessPath(/dev/bus/usb/002/003)
2017-05-05T18:35:50.418596+00:00 DEBUG kernel: [  345.868575] SELinux: initialized (dev proc, type proc), uses genfs_contexts
2017-05-05T18:35:50.483173+00:00 INFO permission_broker[1420]:   AllowUsbDeviceRule: ALLOW
2017-05-05T18:35:50.483266+00:00 INFO permission_broker[1420]:   AllowTtyDeviceRule: IGNORE
2017-05-05T18:35:50.499594+00:00 DEBUG kernel: [  345.949568] SELinux: initialized (dev proc, type proc), uses genfs_contexts
2017-05-05T18:35:50.571564+00:00 WARNING permission_broker[1420]: Could not load the device policy file.
2017-05-05T18:35:50.571763+00:00 INFO permission_broker[1420]:   DenyClaimedUsbDeviceRule: DENY
2017-05-05T18:35:50.571781+00:00 INFO permission_broker[1420]: Verdict for /dev/bus/usb/002/003: DENY
2017-05-05T18:35:50.571916+00:00 ERR permission_broker[1420]: OpenPath(...): Domain=permission_broker, Code=permission_denied, Message=Permission to open '/dev/bus/usb/002/003' denied
2017-05-05T18:35:50.832595+00:00 DEBUG kernel: [  346.282239] SELinux: initialized (dev proc, type proc), uses genfs_contexts
2017-05-05T18:35:52.946170+00:00 ERR cryptohomed[1431]: TpmIsReady: is not owned.
2017-05-05T18:35:52.946198+00:00 ERR cryptohomed[1431]: HasAuthorization: TPM not ready.
2017-05-05T18:35:52.946211+00:00 ERR cryptohomed[1431]: Destroy() called with insufficient authorization.
2017-05-05T18:35:52.963494+00:00 WARNING chapsd[1335]: SRK does not exist - this is normal when the TPM is not yet owned.
2017-05-05T18:35:52.967101+00:00 WARNING chapsd[1335]: SRK does not exist - this is normal when the TPM is not yet owned.
2017-05-05T18:35:52.967507+00:00 WARNING cryptohomed[1431]: Could not load the device policy file.
2017-05-05T18:35:53.011022+00:00 WARNING cryptohomed[1431]: Could not load the device policy file.
2017-05-05T18:35:53.011985+00:00 INFO cryptohomed[1431]: TPM error 0x2020 (Key not found in persistent storage): LoadKeyByUuid: failed LoadKeyByUUID
2017-05-05T18:35:53.042600+00:00 DEBUG kernel: [  348.491917] SELinux: initialized (dev proc, type proc), uses genfs_contexts
2017-05-05T18:35:53.053876+00:00 INFO session_manager[6244]: [INFO:upstart_signal_emitter.cc(38)] Emitting login-prompt-visible Upstart signal
2017-05-05T18:35:53.073661+00:00 ERR cryptohomed[1431]: Couldn't wrap cryptohome key
2017-05-05T18:35:54.027959+00:00 INFO cryptohomed[1431]: TPM error 0x2020 (Key not found in persistent storage): LoadKeyByUuid: failed LoadKeyByUUID
2017-05-05T18:35:54.273872+00:00 ERR cryptohomed[1431]: Couldn't wrap cryptohome key
2017-05-05T18:35:54.274910+00:00 INFO cryptohomed[1431]: Migrated (or created) user directory: /home/.shadow/7c807449acc6b545db59c4e735416e4f2c935839/vault
2017-05-05T18:35:54.280622+00:00 DEBUG kernel: [  349.730157] SELinux: initialized (dev ecryptfs, type ecryptfs), uses xattr
2017-05-05T18:35:54.282168+00:00 INFO cryptohomed[1431]: Creating pass-through directories /home/.shadow/7c807449acc6b545db59c4e735416e4f2c935839/vault/user/Cache
2017-05-05T18:35:54.282353+00:00 INFO cryptohomed[1431]: Creating pass-through directories /home/.shadow/7c807449acc6b545db59c4e735416e4f2c935839/vault/user/Downloads
2017-05-05T18:35:54.282486+00:00 INFO cryptohomed[1431]: Creating pass-through directories /home/.shadow/7c807449acc6b545db59c4e735416e4f2c935839/vault/user/GCache
2017-05-05T18:35:54.282623+00:00 INFO cryptohomed[1431]: Creating pass-through directories /home/.shadow/7c807449acc6b545db59c4e735416e4f2c935839/vault/user/GCache/v1
2017-05-05T18:35:54.282760+00:00 INFO cryptohomed[1431]: Creating pass-through directories /home/.shadow/7c807449acc6b545db59c4e735416e4f2c935839/vault/user/GCache/v1/blobs
2017-05-05T18:35:54.282906+00:00 INFO cryptohomed[1431]: Creating pass-through directories /home/.shadow/7c807449acc6b545db59c4e735416e4f2c935839/vault/user/GCache/v1/tmp
2017-05-05T18:35:54.415197+00:00 INFO cryptohomed[1431]: RecursiveCopy: /home/.shadow/7c807449acc6b545db59c4e735416e4f2c935839/mount/user/.ssh
2017-05-05T18:35:54.416881+00:00 INFO cryptohomed[1431]: RecursiveCopy: /home/.shadow/7c807449acc6b545db59c4e735416e4f2c935839/mount/user/log
2017-05-05T18:35:54.417432+00:00 INFO cryptohomed[1431]: RecursiveCopy: /home/.shadow/7c807449acc6b545db59c4e735416e4f2c935839/mount/user/.pki
2017-05-05T18:35:54.417818+00:00 INFO cryptohomed[1431]: RecursiveCopy: /home/.shadow/7c807449acc6b545db59c4e735416e4f2c935839/mount/user/.pki/nssdb
2017-05-05T18:35:54.447099+00:00 WARNING cryptohomed[1431]: TPM was not owned. TPM initialization call back will handle PKCS#11 initialization.
2017-05-05T18:35:54.450499+00:00 INFO session_manager[6244]: [INFO:policy_key.cc(53)] No policy key on disk at /home/root/7c807449acc6b545db59c4e735416e4f2c935839/session_manager/policy/key
2017-05-05T18:35:54.468890+00:00 WARNING chapsd[1335]: SRK does not exist - this is normal when the TPM is not yet owned.
2017-05-05T18:35:54.471104+00:00 WARNING chapsd[1335]: message repeated 2 times: [ SRK does not exist - this is normal when the TPM is not yet owned.]
2017-05-05T18:35:54.471433+00:00 WARNING cryptohomed[1431]: GetTpmTokenSlotForPath: Path not found.
2017-05-05T18:35:54.479377+00:00 ERR session_manager[6244]: [ERROR:nss_util.cc(151)] Not checking key because size is 0
2017-05-05T18:35:54.479468+00:00 WARNING session_manager[6244]: [WARNING:device_policy_service.cc(405)] Could not verify that owner key belongs to this user.
2017-05-05T18:35:54.486587+00:00 INFO session_manager[6244]: [INFO:upstart_signal_emitter.cc(38)] Emitting start-user-session Upstart signal
2017-05-05T18:35:54.486999+00:00 INFO session_manager[6244]: [INFO:session_manager_impl.cc(432)] Starting user session
2017-05-05T18:35:54.487280+00:00 INFO session_manager[6244]: [INFO:session_manager_impl.cc(436)] emitting D-Bus signal SessionStateChanged:started
2017-05-05T18:35:54.489460+00:00 INFO session_manager[6244]: [INFO:key_generator.cc(58)] Generating key at /home/user/7c807449acc6b545db59c4e735416e4f2c935839/key.pub using nssdb under /home/user/7c807449acc6b545db59c4e735416e4f2c935839
2017-05-05T18:35:54.540282+00:00 WARNING chapsd[1335]: SRK does not exist - this is normal when the TPM is not yet owned.
2017-05-05T18:35:54.542374+00:00 WARNING chapsd[1335]: message repeated 3 times: [ SRK does not exist - this is normal when the TPM is not yet owned.]
2017-05-05T18:35:54.561849+00:00 ERR shill[1423]: [ERROR:crypto_des_cbc.cc(103)] Unable to load key matter from /var/lib/whitelist/owner.key
2017-05-05T18:35:54.622809+00:00 ERR shill[1423]: [ERROR:crypto_des_cbc.cc(103)] Unable to load key matter from /var/lib/whitelist/owner.key
2017-05-05T18:35:54.655596+00:00 DEBUG kernel: [  350.105395] SELinux: initialized (dev proc, type proc), uses genfs_contexts
2017-05-05T18:35:54.667609+00:00 DEBUG kernel: [  350.117640] SELinux: initialized (dev proc, type proc), uses genfs_contexts
2017-05-05T18:35:54.818512+00:00 WARNING cryptohomed[1431]: Could not load the device policy file.
2017-05-05T18:35:54.899602+00:00 DEBUG kernel: [  350.348911] SELinux: initialized (dev proc, type proc), uses genfs_contexts
2017-05-05T18:35:54.934863+00:00 WARNING tcsd[1330]: TSS: Unloading a public key of size 0!
2017-05-05T18:35:54.999599+00:00 DEBUG kernel: [  350.449137] SELinux: initialized (dev proc, type proc), uses genfs_contexts
2017-05-05T18:35:55.120798+00:00 INFO session_manager[6244]: [INFO:child_exit_handler.cc(77)] Handling 6522 exit.
2017-05-05T18:35:55.120828+00:00 INFO session_manager[6244]: [INFO:session_manager_impl.cc(1054)] Processing generated key at /home/user/7c807449acc6b545db59c4e735416e4f2c935839/key.pub
2017-05-05T18:35:55.150607+00:00 INFO session_manager[6244]: [INFO:policy_key.cc(122)] wrote 294 bytes to /var/lib/whitelist/owner.key
2017-05-05T18:35:55.150789+00:00 INFO session_manager[6244]: [INFO:policy_service.cc(171)] Persisted policy key to disk.
2017-05-05T18:35:55.159872+00:00 INFO session_manager[6244]: [INFO:policy_service.cc(182)] Persisted policy to disk.
2017-05-05T18:35:55.223496+00:00 WARNING session_manager[6244]: [WARNING:session_manager_dbus_adaptor.cc(660)] Failed to get enable_vendor_privileged_app_scanning
2017-05-05T18:35:55.235303+00:00 INFO session_manager[6244]: [INFO:upstart_signal_emitter.cc(38)] Emitting start-arc-instance Upstart signal
2017-05-05T18:35:55.271632+00:00 DEBUG kernel: [  350.721495] SELinux: initialized (dev binfmt_misc, type binfmt_misc), uses genfs_contexts
2017-05-05T18:35:55.286597+00:00 DEBUG kernel: [  350.736018] SELinux: initialized (dev tmpfs, type tmpfs), uses transition SIDs
2017-05-05T18:35:55.302660+00:00 WARNING cryptohomed[1431]: RemoveKeyset: key to remove not found
2017-05-05T18:35:55.309443+00:00 DEBUG kernel: [  350.757173] SELinux: initialized (dev tmpfs, type tmpfs), uses transition SIDs
2017-05-05T18:35:55.309460+00:00 DEBUG kernel: [  350.757875] SELinux: initialized (dev tmpfs, type tmpfs), uses transition SIDs
2017-05-05T18:35:55.309462+00:00 DEBUG kernel: [  350.758612] SELinux: initialized (dev tmpfs, type tmpfs), uses transition SIDs
2017-05-05T18:35:55.679896+00:00 INFO session_manager[6244]: [INFO:container_manager_impl.cc(122)] Starting container android
2017-05-05T18:35:55.732167+00:00 INFO session_manager[6244]: libminijail[6244]: mount tmpfs -> /dev/socket type 'tmpfs'
2017-05-05T18:35:55.732614+00:00 DEBUG kernel: [  351.182173] SELinux: initialized (dev tmpfs, type tmpfs), uses transition SIDs
2017-05-05T18:35:55.732633+00:00 DEBUG kernel: [  351.182721] SELinux: initialized (dev tmpfs, type tmpfs), uses transition SIDs
2017-05-05T18:35:55.733601+00:00 DEBUG kernel: [  351.183152] SELinux: initialized (dev tmpfs, type tmpfs), uses transition SIDs
2017-05-05T18:35:55.733613+00:00 DEBUG kernel: [  351.183569] SELinux: initialized (dev devpts, type devpts), uses transition SIDs
2017-05-05T18:35:55.733766+00:00 INFO session_manager[6244]: libminijail[6244]: mount proc -> /proc type 'proc'
2017-05-05T18:35:55.733801+00:00 INFO session_manager[6244]: libminijail[6244]: mount /var/run/arc/cmdline.android -> /proc/cmdline type 'bind'
2017-05-05T18:35:55.733872+00:00 INFO session_manager[6244]: libminijail[6244]: mount sysfs -> /sys type 'sysfs'
2017-05-05T18:35:55.733890+00:00 INFO session_manager[6244]: libminijail[6244]: mount /sys/fs/selinux -> /sys/fs/selinux type 'bind'
2017-05-05T18:35:55.733903+00:00 INFO session_manager[6244]: libminijail[6244]: mount /var/run/arc/debugfs -> /sys/kernel/debug type 'bind'
2017-05-05T18:35:55.734607+00:00 DEBUG kernel: [  351.184430] SELinux: initialized (dev tmpfs, type tmpfs), uses transition SIDs
2017-05-05T18:35:55.734619+00:00 DEBUG kernel: [  351.184509] SELinux: initialized (dev tmpfs, type tmpfs), uses transition SIDs
2017-05-05T18:35:55.734660+00:00 INFO session_manager[6244]: libminijail[6244]: mount none -> / type 'none'
2017-05-05T18:35:55.735001+00:00 INFO session_manager[6244]: libminijail[6244]: mount /opt/google/containers/android/rootfs/root/system/fonts -> /system/fonts type 'bind'
2017-05-05T18:35:55.735180+00:00 INFO session_manager[6244]: libminijail[6244]: mount /var/run/arc/sdcard -> /var/run/arc/sdcard type 'bind'
2017-05-05T18:35:55.735251+00:00 INFO session_manager[6244]: libminijail[6244]: mount /var/run/arc/obb -> /var/run/arc/obb type 'bind'
2017-05-05T18:35:55.735318+00:00 INFO session_manager[6244]: libminijail[6244]: mount /var/run/arc/media -> /var/run/arc/media type 'bind'
2017-05-05T18:35:55.745172+00:00 INFO minijail0[6781]: libminijail[6781]: mount proc -> /proc type 'proc'
2017-05-05T18:35:55.745203+00:00 INFO minijail0[6781]: libminijail[6781]: mount /opt/google/containers/android/rootfs/root/system/bin/sdcard -> /system/bin/sdcard type ''
2017-05-05T18:35:55.745217+00:00 INFO minijail0[6781]: libminijail[6781]: mount /opt/google/containers/android/rootfs/android-data/data -> /data type ''
2017-05-05T18:35:55.745228+00:00 INFO minijail0[6781]: libminijail[6781]: mount /home/chronos/user/Downloads -> /Downloads type ''
2017-05-05T18:35:55.745238+00:00 INFO minijail0[6781]: libminijail[6781]: mount none -> / type 'none'
2017-05-05T18:35:55.745248+00:00 INFO minijail0[6781]: libminijail[6781]: mount /run/arc/sdcard -> /mnt/runtime type ''
2017-05-05T18:35:55.745262+00:00 INFO minijail0[6781]: libminijail[6781]: mount none -> /mnt/runtime type 'none'
2017-05-05T18:35:55.745631+00:00 DEBUG kernel: [  351.195698] SELinux: initialized (dev proc, type proc), uses genfs_contexts
2017-05-05T18:35:55.833597+00:00 DEBUG kernel: [  351.283623] SELinux: initialized (dev proc, type proc), uses genfs_contexts
2017-05-05T18:35:55.833930+00:00 INFO session_manager[6244]: [INFO:upstart_signal_emitter.cc(38)] Emitting start-arc-network Upstart signal
2017-05-05T18:35:55.835602+00:00 DEBUG kernel: [  351.285629] SELinux: initialized (dev tmpfs, type tmpfs), uses transition SIDs
2017-05-05T18:35:55.835620+00:00 DEBUG kernel: [  351.285751] SELinux: initialized (dev sysfs, type sysfs), uses genfs_contexts
2017-05-05T18:35:55.846343+00:00 INFO session_manager[6244]: [INFO:session_manager_impl.cc(1182)] Started Android container pid 6791
2017-05-05T18:35:55.846541+00:00 INFO session_manager[6244]: [INFO:child_exit_handler.cc(77)] Handling 6604 exit.
2017-05-05T18:35:55.851599+00:00 NOTICE kernel: [  351.301186] audit: type=1400 audit(1494009355.850:4): avc:  denied  { module_request } for  pid=6791 comm="init" kmod="personality-8" scontext=u:r:init:s0 tcontext=u:r:kernel:s0 tclass=system permissive=0
2017-05-05T18:35:55.851616+00:00 NOTICE kernel: [  351.301270] audit: type=1400 audit(1494009355.850:5): avc:  denied  { use } for  pid=6791 comm="init" path="/init" dev="loop1" ino=13 scontext=u:r:init:s0 tcontext=u:r:chromeos:s0 tclass=fd permissive=0
2017-05-05T18:35:55.862773+00:00 INFO minijail0[6804]: libminijail[6804]: mount /opt/google/containers/android/rootfs/android-data/data -> /data type 'none'
2017-05-05T18:35:55.862791+00:00 INFO minijail0[6804]: libminijail[6804]: mount none -> /data type 'none'
2017-05-05T18:35:55.862800+00:00 INFO minijail0[6804]: libminijail[6804]: mount /lib -> /lib type 'none'
2017-05-05T18:35:55.862807+00:00 INFO minijail0[6804]: libminijail[6804]: mount none -> /lib type 'none'
2017-05-05T18:35:55.862815+00:00 INFO minijail0[6804]: libminijail[6804]: mount /lib64 -> /lib64 type 'none'
2017-05-05T18:35:55.862820+00:00 INFO minijail0[6804]: libminijail[6804]: mount none -> /lib64 type 'none'
2017-05-05T18:35:55.862827+00:00 INFO minijail0[6804]: libminijail[6804]: mount proc -> /proc type 'proc'
2017-05-05T18:35:55.862833+00:00 INFO minijail0[6804]: libminijail[6804]: mount /usr -> /usr type 'none'
2017-05-05T18:35:55.862840+00:00 INFO minijail0[6804]: libminijail[6804]: mount none -> /usr type 'none'
2017-05-05T18:35:55.862847+00:00 INFO minijail0[6804]: libminijail[6804]: mount /run/dbus -> /var/run/dbus type 'none'
2017-05-05T18:35:55.862855+00:00 INFO minijail0[6804]: libminijail[6804]: mount none -> /var/run/dbus type 'none'
2017-05-05T18:35:55.862881+00:00 INFO minijail0[6804]: libminijail[6804]: mount none -> / type 'none'
2017-05-05T18:35:55.862915+00:00 INFO minijail0[6804]: libminijail[6804]: mount /run/arc/obb -> /var/run/arc/obb type 'none'
2017-05-05T18:35:55.862924+00:00 INFO minijail0[6804]: libminijail[6804]: mount none -> /var/run/arc/obb type 'none'
2017-05-05T18:35:55.868597+00:00 DEBUG kernel: [  351.318533] SELinux: initialized (dev proc, type proc), uses genfs_contexts
2017-05-05T18:35:55.893595+00:00 INFO kernel: [  351.343667] IPv6: ADDRCONF(NETDEV_UP): veth_android: link is not ready
2017-05-05T18:35:55.897935+00:00 INFO minijail0[6801]: libminijail[6801]: mount /bin -> /bin type 'none'
2017-05-05T18:35:55.897954+00:00 INFO minijail0[6801]: libminijail[6801]: mount /bin -> /bin type 'none'
2017-05-05T18:35:55.897962+00:00 INFO minijail0[6801]: libminijail[6801]: mount /etc -> /etc type 'none'
2017-05-05T18:35:55.897970+00:00 INFO minijail0[6801]: libminijail[6801]: mount /etc -> /etc type 'none'
2017-05-05T18:35:55.897976+00:00 INFO minijail0[6801]: libminijail[6801]: mount /lib -> /lib type 'none'
2017-05-05T18:35:55.897982+00:00 INFO minijail0[6801]: libminijail[6801]: mount /lib -> /lib type 'none'
2017-05-05T18:35:55.897989+00:00 INFO minijail0[6801]: libminijail[6801]: mount /sbin -> /sbin type 'none'
2017-05-05T18:35:55.897996+00:00 INFO minijail0[6801]: libminijail[6801]: mount /sbin -> /sbin type 'none'
2017-05-05T18:35:55.898004+00:00 INFO minijail0[6801]: libminijail[6801]: mount /usr -> /usr type 'none'
2017-05-05T18:35:55.898011+00:00 INFO minijail0[6801]: libminijail[6801]: mount /usr -> /usr type 'none'
2017-05-05T18:35:55.898018+00:00 INFO minijail0[6801]: libminijail[6801]: mount proc -> /proc type 'proc'
2017-05-05T18:35:55.898026+00:00 INFO minijail0[6801]: libminijail[6801]: mount none -> / type 'none'
2017-05-05T18:35:55.898036+00:00 INFO minijail0[6801]: libminijail[6801]: mount /media/removable -> /mnt/source type 'none'
2017-05-05T18:35:55.898051+00:00 INFO minijail0[6801]: message repeated 2 times: [ libminijail[6801]: mount /media/removable -> /mnt/source type 'none']
2017-05-05T18:35:55.898059+00:00 INFO minijail0[6801]: libminijail[6801]: mount /run/arc/media/removable -> /mnt/dest type 'none'
2017-05-05T18:35:55.898773+00:00 INFO kernel: [  351.348491] device veth_android entered promiscuous mode
2017-05-05T18:35:55.898067+00:00 INFO minijail0[6801]: libminijail[6801]: mount /run/arc/media/removable -> /mnt/dest type 'none'
2017-05-05T18:35:55.899655+00:00 INFO arc-obb-mounter[6819]: libminijail[2]: mount /opt/google/containers/android/rootfs/android-data/data -> /data type 'none'
2017-05-05T18:35:55.899673+00:00 INFO arc-obb-mounter[6819]: libminijail[2]: mount none -> /data type 'none'
2017-05-05T18:35:55.899681+00:00 INFO arc-obb-mounter[6819]: libminijail[2]: mount /lib -> /lib type 'none'
2017-05-05T18:35:55.899687+00:00 INFO arc-obb-mounter[6819]: libminijail[2]: mount none -> /lib type 'none'
2017-05-05T18:35:55.899694+00:00 INFO arc-obb-mounter[6819]: libminijail[2]: mount /lib64 -> /lib64 type 'none'
2017-05-05T18:35:55.899701+00:00 INFO arc-obb-mounter[6819]: libminijail[2]: mount none -> /lib64 type 'none'
2017-05-05T18:35:55.899707+00:00 INFO arc-obb-mounter[6819]: libminijail[2]: mount proc -> /proc type 'proc'
2017-05-05T18:35:55.899712+00:00 INFO arc-obb-mounter[6819]: libminijail[2]: mount /usr -> /usr type 'none'
2017-05-05T18:35:55.899718+00:00 INFO arc-obb-mounter[6819]: libminijail[2]: mount none -> /usr type 'none'
2017-05-05T18:35:55.899725+00:00 INFO arc-obb-mounter[6819]: libminijail[2]: mount /run/dbus -> /var/run/dbus type 'none'
2017-05-05T18:35:55.899732+00:00 INFO arc-obb-mounter[6819]: libminijail[2]: mount none -> /var/run/dbus type 'none'
2017-05-05T18:35:55.899738+00:00 INFO arc-obb-mounter[6819]: libminijail[2]: mount none -> / type 'none'
2017-05-05T18:35:55.899745+00:00 INFO arc-obb-mounter[6819]: libminijail[2]: mount /run/arc/obb -> /var/run/arc/obb type 'none'
2017-05-05T18:35:55.899753+00:00 INFO arc-obb-mounter[6819]: libminijail[2]: mount none -> /var/run/arc/obb type 'none'
2017-05-05T18:35:55.903599+00:00 DEBUG kernel: [  351.353490] SELinux: initialized (dev proc, type proc), uses genfs_contexts
2017-05-05T18:35:55.918612+00:00 DEBUG kernel: [  351.368516] SELinux: initialized (dev tmpfs, type tmpfs), uses transition SIDs
2017-05-05T18:35:55.919591+00:00 DEBUG kernel: [  351.369533] SELinux: initialized (dev tmpfs, type tmpfs), uses transition SIDs
2017-05-05T18:35:55.926600+00:00 DEBUG kernel: [  351.376485] SELinux: initialized (dev tmpfs, type tmpfs), uses transition SIDs
2017-05-05T18:35:56.033603+00:00 DEBUG kernel: [  351.482919] SELinux: initialized (dev tmpfs, type tmpfs), uses transition SIDs
2017-05-05T18:35:56.038270+00:00 INFO mount-passthrough[6828]: libminijail[1]: mount /bin -> /bin type 'none'
2017-05-05T18:35:56.038286+00:00 INFO mount-passthrough[6828]: libminijail[1]: mount /bin -> /bin type 'none'
2017-05-05T18:35:56.038294+00:00 INFO mount-passthrough[6828]: libminijail[1]: mount /etc -> /etc type 'none'
2017-05-05T18:35:56.038301+00:00 INFO mount-passthrough[6828]: libminijail[1]: mount /etc -> /etc type 'none'
2017-05-05T18:35:56.038307+00:00 INFO mount-passthrough[6828]: libminijail[1]: mount /lib -> /lib type 'none'
2017-05-05T18:35:56.038313+00:00 INFO mount-passthrough[6828]: libminijail[1]: mount /lib -> /lib type 'none'
2017-05-05T18:35:56.038320+00:00 INFO mount-passthrough[6828]: libminijail[1]: mount /sbin -> /sbin type 'none'
2017-05-05T18:35:56.038326+00:00 INFO mount-passthrough[6828]: libminijail[1]: mount /sbin -> /sbin type 'none'
2017-05-05T18:35:56.038333+00:00 INFO mount-passthrough[6828]: libminijail[1]: mount /usr -> /usr type 'none'
2017-05-05T18:35:56.038340+00:00 INFO mount-passthrough[6828]: libminijail[1]: mount /usr -> /usr type 'none'
2017-05-05T18:35:56.038346+00:00 INFO mount-passthrough[6828]: libminijail[1]: mount proc -> /proc type 'proc'
2017-05-05T18:35:56.038353+00:00 INFO mount-passthrough[6828]: libminijail[1]: mount none -> / type 'none'
2017-05-05T18:35:56.038360+00:00 INFO mount-passthrough[6828]: libminijail[1]: mount /media/removable -> /mnt/source type 'none'
2017-05-05T18:35:56.038372+00:00 INFO mount-passthrough[6828]: message repeated 2 times: [ libminijail[1]: mount /media/removable -> /mnt/source type 'none']
2017-05-05T18:35:56.038380+00:00 INFO mount-passthrough[6828]: libminijail[1]: mount /run/arc/media/removable -> /mnt/dest type 'none'
2017-05-05T18:35:56.044607+00:00 NOTICE kernel: [  351.493819] audit: type=1400 audit(1494009356.043:6): avc:  denied  { mounton } for  pid=6791 comm="init" path="/sys/kernel/debug" dev="tmpfs" ino=31016 scontext=u:r:init:s0 tcontext=u:object_r:debugfs:s0 tclass=dir permissive=0
2017-05-05T18:35:56.046652+00:00 DEBUG kernel: [  351.496513] SELinux: initialized (dev fuse, type fuse), uses genfs_contexts
2017-05-05T18:35:56.055607+00:00 INFO kernel: [  351.505511] arc0: renamed from slave_android
2017-05-05T18:35:56.038387+00:00 INFO mount-passthrough[6828]: libminijail[1]: mount /run/arc/media/removable -> /mnt/dest type 'none'
2017-05-05T18:35:56.097602+00:00 NOTICE kernel: [  351.547510] audit: type=1400 audit(1494009356.096:7): avc:  denied  { module_request } for  pid=6791 comm="init" kmod="fs-configfs" scontext=u:r:init:s0 tcontext=u:r:kernel:s0 tclass=system permissive=0
2017-05-05T18:35:56.790850+00:00 DEBUG kernel: [  352.238475] SELinux: initialized (dev fuse, type fuse), uses genfs_contexts
2017-05-05T18:35:56.790868+00:00 DEBUG kernel: [  352.238792] SELinux: initialized (dev fuse, type fuse), uses genfs_contexts
2017-05-05T18:35:56.790870+00:00 DEBUG kernel: [  352.239068] SELinux: initialized (dev fuse, type fuse), uses genfs_contexts
2017-05-05T18:35:56.939273+00:00 ERR cryptohomed[1431]: TPM initialization took 2129ms
2017-05-05T18:35:56.939512+00:00 INFO cryptohomed[1431]: TPM error 0x2020 (Key not found in persistent storage): LoadKeyByUuid: failed LoadKeyByUUID
2017-05-05T18:35:57.613411+00:00 INFO cryptohomed[1431]: Created new cryptohome key.
2017-05-05T18:35:58.272589+00:00 INFO kernel: [  353.722641] capability: warning: `main' uses 32-bit capabilities (legacy support in use)
2017-05-05T18:35:58.516436+00:00 INFO cryptohomed[1431]: Finalizing TPM initialization, ownership taken: 1.
2017-05-05T18:35:58.516460+00:00 INFO cryptohomed[1431]: Putting a Pkcs11_Initialize on the mount thread.
2017-05-05T18:35:58.908007+00:00 INFO cryptohomed[1431]: Lockbox created.
2017-05-05T18:35:58.946183+00:00 WARNING cryptohomed[1431]: Attestation: Using default PCA. Alternate PCA will not be available.
2017-05-05T18:35:58.946205+00:00 INFO cryptohomed[1431]: Attestation: Preparing for enrollment...
2017-05-05T18:35:59.831600+00:00 DEBUG kernel: [  355.281135] SELinux: initialized (dev proc, type proc), uses genfs_contexts
2017-05-05T18:36:01.965281+00:00 ERR cras_server[1783]: No chmap queried!
2017-05-05T18:36:03.292610+00:00 INFO kernel: [  358.741942] IPv6: ADDRCONF(NETDEV_CHANGE): veth_android: link becomes ready
2017-05-05T18:36:03.292624+00:00 INFO kernel: [  358.742034] br0: port 1(veth_android) entered forwarding state
2017-05-05T18:36:03.292627+00:00 INFO kernel: [  358.742067] br0: port 1(veth_android) entered forwarding state
2017-05-05T18:36:03.432604+00:00 NOTICE kernel: [  358.882426] audit: type=1400 audit(1494009363.431:8): avc:  denied  { create } for  pid=7208 comm="system_server" name="1" scontext=u:r:system_server:s0 tcontext=u:object_r:cache_backup_file:s0 tclass=dir permissive=0
2017-05-05T18:36:04.852091+00:00 INFO session_manager[6244]: [INFO:upstart_signal_emitter.cc(38)] Emitting arc-booted Upstart signal
2017-05-05T18:36:05.110245+00:00 INFO cryptohomed[1431]: Attestation: Prepared successfully (6164ms).
2017-05-05T18:36:05.110290+00:00 INFO cryptohomed[1431]: Finalizing() 2 bytes.
2017-05-05T18:36:05.575826+00:00 INFO cryptohomed[1431]: Encrypted partition finalized.
2017-05-05T18:36:05.583547+00:00 INFO cryptohomed[1431]: InstallAttributes have been finalized.
2017-05-05T18:36:05.615301+00:00 INFO chapsd[1335]: Opening database in: /var/lib/chaps
2017-05-05T18:36:05.637143+00:00 NOTICE root[7874]: autotest finished iteration /usr/local/autotest/results/default/cheets_StartAndroid/sysinfo/iteration.1