New issue
Advanced search Search tips

Issue 855325 link

Starred by 1 user

Issue metadata

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


Participants' hotlists:
Hotlist-Tast


Sign in to add a comment

tast.arc.* flaky

Project Member Reported by nya@chromium.org, Jun 22 2018

Issue description

tast.arc.* tests are generally flaky. Some failure patterns:

https://stainless.corp.google.com/browse/chromeos-autotest-results/210293615-chromeos-test/
2018/06/20 16:05:03 [16:05:02.218] Setting up ADB
2018/06/20 16:05:03 [16:05:02.582] External command failed: exit status 255
2018/06/20 16:05:03 [16:05:02.582] Command: '/usr/bin/adb' 'adb' 'start-server'
2018/06/20 16:05:03 [16:05:02.582] Dir: 
2018/06/20 16:05:03 [16:05:02.582] Uncaptured output:
2018/06/20 16:05:03 [16:05:02.583] Error at downloads.go:36: Failed to connect to Chrome: failed setting up ADB: setting up ADB auth: failed starting ADB local server: exit status 255

https://stainless.corp.google.com/browse/chromeos-autotest-results/210294570-chromeos-test/
2018/06/20 16:34:22 [16:34:22.121] Waiting for Android boot
2018/06/20 16:35:09 [16:35:09.368] Setting up ADB
2018/06/20 16:35:13 [16:35:13.113] External command failed: signal: killed
2018/06/20 16:35:13 [16:35:13.113] Command: '/usr/bin/adb' 'adb' 'wait-for-device'
2018/06/20 16:35:13 [16:35:13.114] Dir: 
2018/06/20 16:35:13 [16:35:13.114] Uncaptured output:
2018/06/20 16:35:13 [16:35:13.116] Error at downloads.go:36: Failed to connect to Chrome: failed setting up ADB: waiting for ADB: context deadline exceeded

https://stainless.corp.google.com/browse/chromeos-autotest-results/210296178-chromeos-test/
2018/06/20 16:22:58 [16:22:58.598] Setting up ADB
2018/06/20 16:23:01 [16:23:01.597] External command failed: signal: killed
2018/06/20 16:23:01 [16:23:01.597] Command: '/usr/bin/adb' 'adb' 'start-server'
2018/06/20 16:23:01 [16:23:01.598] Dir: 
2018/06/20 16:23:01 [16:23:01.598] Uncaptured output:
2018/06/20 16:23:01 [16:23:01.603] Error at downloads.go:36: Failed to connect to Chrome: failed setting up ADB: setting up ADB auth: failed starting ADB local server: context deadline exceeded

https://stainless.corp.google.com/browse/chromeos-autotest-results/210294810-chromeos-test/
2018/06/20 16:34:25 [16:34:24.379] Setting up ADB
2018/06/20 16:34:28 [16:34:27.394] Error at test.go:106: Test timed out: context deadline exceeded

https://stainless.corp.google.com/browse/chromeos-autotest-results/210299335-chromeos-test/
2018/06/20 16:48:17 [16:48:16.650] Waiting for Android boot
2018/06/20 16:48:58 [16:48:58.054] External command failed: signal: killed
2018/06/20 16:48:58 [16:48:58.054] Command: '/usr/sbin/android-sh' 'android-sh' '-c' 'exec "$@"' - 'logcat' '-b' 'events' '*:S' 'arc_system_event'
2018/06/20 16:48:58 [16:48:58.054] Dir: 
2018/06/20 16:48:58 [16:48:58.054] Uncaptured output:
2018/06/20 16:48:58 [16:48:58.058] Error at downloads.go:36: Failed to connect to Chrome: Android didn't boot: EOF reached (maybe logcat crashed?)

 

Comment 1 by nya@chromium.org, Jun 22 2018

One reason is, unfortunately, default 1-minute timeout is not enough on some slow devices.

Example log of arc.Boot on bob:

2018/06/22 13:13:35 [13:13:34.464] Restarting ui job
2018/06/22 13:13:56 [13:13:55.835] Waiting for org.chromium.SessionManager D-Bus service
2018/06/22 13:13:56 [13:13:55.930] Asking session_manager to enable Chrome testing
2018/06/22 13:13:56 [13:13:55.936] Waiting for Chrome to write its debugging port to /home/chronos/DevToolsActivePort
2018/06/22 13:13:57 [13:13:56.955] Removing cryptohome for testuser@gmail.com
2018/06/22 13:13:58 [13:13:57.281] Finding OOBE DevTools target
2018/06/22 13:13:58 [13:13:57.284] Connecting to Chrome at ws://127.0.0.1:36430/devtools/page/F3BBA69C5BC40E578A80B232150EAF7D
2018/06/22 13:13:58 [13:13:57.335] Waiting for OOBE
2018/06/22 13:14:00 [13:13:59.915] Logging in as user "testuser@gmail.com"
2018/06/22 13:14:00 [13:14:00.023] Waiting for cryptohome /home/user/d6c28fef084961e49faa76fc60ed56970b96d462
2018/06/22 13:14:03 [13:14:02.753] Waiting for OOBE to be dismissed
2018/06/22 13:14:07 [13:14:06.720] Enabling ARC
2018/06/22 13:14:07 [13:14:06.720] Waiting for test API extension at chrome-extension://behllobkkfkfnphdnhnkndlbkcpglgmj/_generated_background_page.html
2018/06/22 13:14:07 [13:14:06.756] Connecting to Chrome at ws://127.0.0.1:36430/devtools/page/B2C60CDC7200FC88F3F23DFDBF010113
2018/06/22 13:14:07 [13:14:06.890] Waiting for Android boot
2018/06/22 13:14:27 [13:14:26.411] Setting up ADB
2018/06/22 13:14:32 Completed test arc.Boot in 57.119s with 0 error(s)

Surprisingly, restarting UI alone takes as long as 21s. User session login takes +11s. Enabling ARC is +25s. Fortunately this trial passed, but it's very close to the deadline.

Enabling ARC is reasonably heavy process, so I think 25s is acceptable. I'm not sure what's happening for restart ui.

Comment 2 by derat@chromium.org, Jun 22 2018

I think that I've occasionally seen the ui job take a long time to restart as well. Maybe Chrome is hanging on shutdown? Does the messages log have any clues about what was happening between 13:13:34.464 and 13:13:55.835?

Comment 3 by nya@chromium.org, Jun 22 2018

In my local run, suspicious logs (from another run) are:

2018-06-22T06:16:51.778493+00:00 INFO session_manager[2348]: [INFO:browser_job.cc(157)] Terminating process group: Browser took more than 3 seconds to exit after signal.
2018-06-22T06:17:08.099107+00:00 WARNING cryptohomed[2734]: Long sync(): 13 seconds

Ah, I was booting DUT from USB stick, so it can be a source of the problem.


But anyway, seems like some DUTs in lab takes more than 40 seconds to boot Android:

2018/06/20 16:33:42 [16:33:41.679] Waiting for Android boot
2018/06/20 16:34:25 [16:34:24.379] Setting up ADB
https://storage.cloud.google.com/chromeos-autotest-results/210294810-chromeos-test/chromeos6-row1-rack18-host15/tast/results/tests/arc.Downloads/log.txt

Project Member

Comment 4 by bugdroid1@chromium.org, Jun 22 2018

The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/platform/tast-tests/+/ec16162adaf671b92eadaf5c06f51fd2b0d1a6ff

commit ec16162adaf671b92eadaf5c06f51fd2b0d1a6ff
Author: Shuhei Takahashi <nya@chromium.org>
Date: Fri Jun 22 13:00:22 2018

tast-tests: Use killall to stop local ADB server.

adb kill-server returns before the local ADB server actually exits,
and running adb start-server immediately can hit race conditions.
Instead, use killall --wait to stop the server.

BUG= chromium:855325 
TEST=tast -verbose run bob-DUT arc.Boot  # 10 times

Change-Id: I33c4365692191d00dee2a7a5fddfb514dadbed57
Reviewed-on: https://chromium-review.googlesource.com/1111737
Commit-Ready: Shuhei Takahashi <nya@chromium.org>
Tested-by: Shuhei Takahashi <nya@chromium.org>
Reviewed-by: Dan Erat <derat@chromium.org>

[modify] https://crrev.com/ec16162adaf671b92eadaf5c06f51fd2b0d1a6ff/src/chromiumos/tast/local/arc/adb.go

Project Member

Comment 5 by bugdroid1@chromium.org, Jun 22 2018

The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/platform/tast-tests/+/79c8bdc98916e16c6181d460e4eddbe3b69b62d5

commit 79c8bdc98916e16c6181d460e4eddbe3b69b62d5
Author: Shuhei Takahashi <nya@chromium.org>
Date: Fri Jun 22 13:00:25 2018

tast-tests: Increase ARC test timeout.

Booting ARC takes tens of seconds and makes ARC tests timeout on
slow devices.

BUG= chromium:855325 
TEST=tast -verbose run bob-DUT arc.Boot  # 10 times

Change-Id: I14ae5102145bbf6361e0fbbf768e2d100bc47df5
Reviewed-on: https://chromium-review.googlesource.com/1111738
Commit-Ready: Shuhei Takahashi <nya@chromium.org>
Tested-by: Shuhei Takahashi <nya@chromium.org>
Reviewed-by: Shuhei Takahashi <nya@chromium.org>

[modify] https://crrev.com/79c8bdc98916e16c6181d460e4eddbe3b69b62d5/src/chromiumos/tast/local/bundles/cros/arc/boot.go
[modify] https://crrev.com/79c8bdc98916e16c6181d460e4eddbe3b69b62d5/src/chromiumos/tast/local/bundles/cros/arc/downloads.go
[modify] https://crrev.com/79c8bdc98916e16c6181d460e4eddbe3b69b62d5/src/chromiumos/tast/local/bundles/cros/arc/intent_forward.go

Comment 6 by nya@chromium.org, Jun 26 2018

Status: Fixed (was: Started)
Largest flakiness has been resolved. We still see occasional failures, but let's file another bug for them.

Sign in to add a comment