When a Tast test times out, it often produces two errors rather than just one. For example:
...
2018/04/03 00:55:05 Started test ui.MashLogin
2018/04/03 00:55:05 [00:55:04.587] Restarting ui job
2018/04/03 00:55:53 [00:55:53.140] Waiting for org.chromium.SessionManager D-Bus service
2018/04/03 00:55:53 [00:55:53.149] Asking session_manager to enable Chrome testing
2018/04/03 00:55:53 [00:55:53.150] Waiting for Chrome to write its debugging port
2018/04/03 00:55:54 [00:55:53.791] Clearing cryptohome for testuser@gmail.com
2018/04/03 00:55:54 [00:55:53.824] Finding OOBE DevTools target
2018/04/03 00:56:05 [00:56:04.587] Error at test.go:90: Test timed out: context deadline exceeded
2018/04/03 00:56:05 [00:56:04.587] Stack trace:
chromiumos/tast/testing.(*Test).Run(0xc4201e2500, 0xc42012b800)
/build/eve/tmp/portage/chromeos-base/tast-local-tests-cros-0.0.1-r29/work/tast-local-tests-cros-0.0.1/tast-base/src/chromiumos/tast/testing/test.go:90 +0x228
chromiumos/tast/bundle.runTests(0x5b516d603140, 0xc420014058, 0xc42006e500, 0x6)
/build/eve/tmp/portage/chromeos-base/tast-local-tests-cros-0.0.1-r29/work/tast-local-tests-cros-0.0.1/tast-base/src/chromiumos/tast/bundle/bundle.go:194 +0x4aa
chromiumos/tast/bundle.Local(0xc420010080, 0x6, 0x6, 0x5b516d1f898f)
/build/eve/tmp/portage/chromeos-base/tast-local-tests-cros-0.0.1-r29/work/tast-local-tests-cros-0.0.1/tast-base/src/chromiumos/tast/bundle/local.go:27 +0xcd
main.main()
/build/eve/tmp/portage/chromeos-base/tast-local-tests-cros-0.0.1-r29/work/tast-local-tests-cros-0.0.1/src/chromiumos/tast/local/bundles/cros/main.go:23 +0x65
2018/04/03 00:56:05 [00:56:04.588] Error at mash_login.go:34: Chrome probably crashed on startup: OOBE target not found: context deadline exceeded
2018/04/03 00:56:05 [00:56:04.588] Stack trace:
chromiumos/tast/local/bundles/cros/ui.MashLogin(0xc42012b800)
/build/eve/tmp/portage/chromeos-base/tast-local-tests-cros-0.0.1-r29/work/tast-local-tests-cros-0.0.1/src/chromiumos/tast/local/bundles/cros/ui/mash_login.go:34 +0x15c
chromiumos/tast/testing.(*Test).Run.func1(0xc42012b800, 0xc4202bd030, 0xc4201e2500)
/build/eve/tmp/portage/chromeos-base/tast-local-tests-cros-0.0.1-r29/work/tast-local-tests-cros-0.0.1/tast-base/src/chromiumos/tast/testing/test.go:83 +0x66
created by chromiumos/tast/testing.(*Test).Run
/build/eve/tmp/portage/chromeos-base/tast-local-tests-cros-0.0.1-r29/work/tast-local-tests-cros-0.0.1/tast-base/src/chromiumos/tast/testing/test.go:76 +0xb3
2018/04/03 00:56:05 Completed test ui.MashLogin in 1m0.002s with 2 error(s)
...
2018/04/03 00:56:21 --------------------------------------------------------------------------------
...
2018/04/03 00:56:21 ui.MashLogin [ FAIL ] Test timed out: context deadline exceeded
2018/04/03 00:56:21 Chrome probably crashed on startup: OOBE target not found: context deadline exceeded
...
2018/04/03 00:56:21 --------------------------------------------------------------------------------
One of these errors ("Chrome probably crashed on startup") is from the test function doing the right thing and failing when it sees that its context's deadline is reached. The other error ("Test timed out") is added by the test harness as a result of watching the same context. Both goroutines are watching the same thing, so they each add their own error at about the same time.
The harness already gives the test function a bit of time to finish cleaning up after a timeout before moving on. I should slightly modify Test.Run so that it only adds the "Test timed out" error after both the test timeout and the additional cleanup timeout have elapsed.
Comment 1 by bugdroid1@chromium.org
, Apr 4 2018