New issue
Advanced search Search tips

Issue 828654 link

Starred by 1 user

Issue metadata

Status: Fixed
Owner:
Closed: Apr 2018
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: Chrome
Pri: 2
Type: Bug



Sign in to add a comment

Avoid double-reporting timeouts in Tast tests

Project Member Reported by derat@chromium.org, Apr 3 2018

Issue description

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.
 
Project Member

Comment 1 by bugdroid1@chromium.org, Apr 4 2018

The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/platform/tast/+/1e2e415d6cee0474a43c42cadc3501d82c437e14

commit 1e2e415d6cee0474a43c42cadc3501d82c437e14
Author: Daniel Erat <derat@chromium.org>
Date: Wed Apr 04 04:40:54 2018

tast: Avoid double-reporting test timeouts.

Expose a separate, shorter-in-duration context to test
functions to give them a chance to report their own timeouts
before Test.Run adds its own "Test timed out" error.

BUG= chromium:828654 
TEST=updated unit tests; also manually verified that a test
     that (correctly) does <-s.Context().Done() and then
     immediately calls s.Error() only reports a single
     error, while an error is also still reported for a
     misbehaving test that just calls time.Sleep() to snooze
     past its deadline

Change-Id: Iecb110b2eeaebc26c9ade6c3c4ad04f7bdd574d8
Reviewed-on: https://chromium-review.googlesource.com/994385
Commit-Ready: Dan Erat <derat@chromium.org>
Tested-by: Dan Erat <derat@chromium.org>
Reviewed-by: Jason Clinton <jclinton@chromium.org>

[modify] https://crrev.com/1e2e415d6cee0474a43c42cadc3501d82c437e14/src/chromiumos/tast/testing/test_test.go
[modify] https://crrev.com/1e2e415d6cee0474a43c42cadc3501d82c437e14/src/chromiumos/tast/testing/state_test.go
[modify] https://crrev.com/1e2e415d6cee0474a43c42cadc3501d82c437e14/src/chromiumos/tast/testing/state.go
[modify] https://crrev.com/1e2e415d6cee0474a43c42cadc3501d82c437e14/src/chromiumos/tast/bundle/bundle.go
[modify] https://crrev.com/1e2e415d6cee0474a43c42cadc3501d82c437e14/src/chromiumos/tast/testing/test.go

Comment 2 by derat@chromium.org, Apr 4 2018

Status: Fixed (was: Started)

Sign in to add a comment