New issue
Advanced search Search tips
Note: Color blocks (like or ) mean that a user may not be available. Tooltip shows the reason.

Issue 751771 link

Starred by 1 user

Issue metadata

Status: Archived
Owner: ----
Closed: May 2018
Cc:
EstimatedDays: ----
NextAction: ----
OS: ----
Pri: 2
Type: Bug



Sign in to add a comment

cheets_ContainerSmokeTest failed due to adb is not ready in 60 seconds.

Project Member Reported by shuqianz@chromium.org, Aug 2 2017

Issue description

quawks-paladin has failed due to this issue for several times:
https://luci-milo.appspot.com/buildbot/chromeos/quawks-paladin/263
https://luci-milo.appspot.com/buildbot/chromeos/quawks-paladin/301

From the suite log, it shows:
 desktopui_ExitOnSupervisedUserCrash.arc   [ PASSED ]
  cheets_ContainerSmokeTest                 [ FAILED ]
  cheets_ContainerSmokeTest                   FAIL: adb is not ready in 60 seconds.
  cheets_ContainerSmokeTest                   retry_count: 2

From the test log of cheets_ContainerSmokeTest,
...08/02 07:54:12.945 ERROR|             utils:2750| adb is not ready in 60 seconds.
08/02 07:54:12.959 INFO |               arc:0520| Starting ARC cleanup
08/02 07:54:12.960 DEBUG|             utils:0212| Running 'android-sh -c 'getprop ro.boot.partial_boot''
08/02 07:54:13.001 DEBUG|             utils:0212| Running 'adb get-state'
08/02 07:54:16.022 DEBUG|               arc:0068| adb get-state: * daemon not running. starting it now on port 5037 *
* daemon started successfully *
unknown
08/02 07:54:16.025 DEBUG|             utils:0212| Running 'android-sh -c 'cat > /data/misc/adb/adb_keys''
08/02 07:54:16.069 DEBUG|             utils:0212| Running 'android-sh -c 'restorecon /data/misc/adb/adb_keys''
08/02 07:54:16.109 DEBUG|             utils:0212| Running 'android-sh -c 'setprop sys.usb.config mtp,adb''
08/02 07:54:16.149 DEBUG|             utils:0212| Running 'adb kill-server'
08/02 07:54:16.160 DEBUG|             utils:0212| Running 'android-sh -c 'logcat -d -b events *:S arc_system_event''
08/02 07:54:16.302 DEBUG|             utils:0212| Running 'android-sh -c 'logcat -d -b events *:S arc_system_event''
08/02 07:54:16.448 DEBUG|             utils:0212| Running 'android-sh -c 'logcat -d -b events *:S arc_system_event''
08/02 07:54:16.594 DEBUG|             utils:0212| Running 'android-sh -c 'logcat -d -b events *:S arc_system_event''
08/02 07:54:16.737 DEBUG|             utils:0212| Running 'android-sh -c 'logcat -d -b events *:S arc_system_event''
.....
08/02 07:55:16.128 DEBUG|             utils:0212| Running 'android-sh -c 'logcat -d -b events *:S arc_system_event''
08/02 07:55:16.176 ERROR|             utils:2750| adb is not ready in 60 seconds.
08/02 07:55:16.292 DEBUG|          arc_util:0041| ARC is enabled in mode enabled
08/02 07:55:16.293 INFO |          arc_util:0105| Saving Android dumpstate.
08/02 07:55:32.229 INFO |          arc_util:0125| Android dumpstate successfully saved.
08/02 07:55:32.291 DEBUG|    cros_interface:0363| ListProcesses(<predicate>)->[265 processes]
08/02 07:55:32.335 DEBUG|    cros_interface:0363| ListProcesses(<predicate>)->[265 processes]
08/02 07:55:32.337 INFO |           browser:0268| Closing browser (pid=18721) ...
08/02 07:55:32.341 INFO |    cros_interface:0546| (Re)starting the ui (logs the user out)
08/02 07:55:32.378 DEBUG|    cros_interface:0439| IsServiceRunning(ui)->True
08/02 07:55:32.378 DEBUG|    cros_interface:0058| sh -c restart ui 
08/02 07:55:34.950 DEBUG|    cros_interface:0067|  > stdout=[ui start/running, process 27154
], stderr=[]
08/02 07:55:34.953 DEBUG|    cros_interface:0058| sh -c cryptohome-path user 'test@test.test' 
08/02 07:55:34.988 DEBUG|    cros_interface:0067|  > stdout=[/home/user/3ccf55a337794c6409b137fe93b56855fe2f28f8
], stderr=[]
08/02 07:55:34.989 DEBUG|    cros_interface:0058| sh -c /bin/df --output=source,target /home/user/3ccf55a337794c6409b137fe93b56855fe2f28f8 
08/02 07:55:35.013 DEBUG|    cros_interface:0067|  > stdout=[Filesystem     Mounted on
/dev/mmcblk0p1 /home
], stderr=[]
08/02 07:55:35.015 DEBUG|    cros_interface:0410| rm -rf /tmp/extension_NEtLS
08/02 07:55:35.030 INFO |           browser:0283| Browser is closed.
08/02 07:55:35.033 WARNI|              test:0612| The test failed with the following exception
Traceback (most recent call last):
  File "/usr/local/autotest/common_lib/test.py", line 573, in _exec
    _cherry_pick_call(self.initialize, *args, **dargs)
  File "/usr/local/autotest/common_lib/test.py", line 721, in _cherry_pick_call
    return func(*p_args, **p_dargs)
  File "/usr/local/autotest/common_lib/cros/arc.py", line 502, in initialize
    self.cleanup()
  File "/usr/local/autotest/common_lib/cros/arc.py", line 525, in cleanup
    raise error.TestFail(err)
TestFail: adb is not ready in 60 seconds.
08/02 07:55:35.058 DEBUG|              test:0617| Running cleanup for test.
08/02 07:55:35.058 INFO |               arc:0520| Starting ARC cleanup
08/02 07:55:35.061 ERROR|               arc:0359| is_android_container_alive failed: TestError('Android container not available',)
08/02 07:55:35.083 DEBUG|          arc_util:0041| ARC is enabled in mode enabled
08/02 07:55:35.084 INFO |          arc_util:0105| Saving Android dumpstate.
08/02 07:55:35.086 ERROR|          arc_util:0128| Failed to save Android dumpstate.
Traceback (most recent call last):
  File "/usr/local/autotest/common_lib/cros/arc_util.py", line 111, in _save_android_dumpstate
    fd = os.open(_DUMPSTATE_PIPE_PATH, os.O_RDONLY | os.O_NONBLOCK)
OSError: [Errno 2] No such file or directory: '/var/run/arc/bugreport/pipe'
08/02 07:55:35.102 ERROR|              test:0620| Ignoring exception during cleanup() phase:
08/02 07:55:35.119 ERROR|         traceback:0013| Traceback (most recent call last):
08/02 07:55:35.132 ERROR|         traceback:0013|   File "/usr/local/autotest/common_lib/test.py", line 618, in _exec
08/02 07:55:35.148 ERROR|         traceback:0013|     _cherry_pick_call(self.cleanup, *args, **dargs)
08/02 07:55:35.166 ERROR|         traceback:0013|   File "/usr/local/autotest/common_lib/test.py", line 721, in _cherry_pick_call
08/02 07:55:35.183 ERROR|         traceback:0013|     return func(*p_args, **p_dargs)
08/02 07:55:35.199 ERROR|         traceback:0013|   File "/usr/local/autotest/common_lib/cros/arc.py", line 531, in cleanup
08/02 07:55:35.207 ERROR|         traceback:0013|     self._chrome.close()
08/02 07:55:35.227 ERROR|         traceback:0013|   File "/usr/local/autotest/common_lib/cros/chrome.py", line 310, in close
08/02 07:55:35.242 ERROR|         traceback:0013|     self._browser.Close()
08/02 07:55:35.253 ERROR|         traceback:0013|   File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/browser/browser.py", line 278, in Close
08/02 07:55:35.288 ERROR|         traceback:0013|     self._browser_backend.Close()
08/02 07:55:35.297 ERROR|         traceback:0013|   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
08/02 07:55:35.315 ERROR|         traceback:0013|     return func(*args, **kwargs)
08/02 07:55:35.328 ERROR|         traceback:0013|   File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome/cros_browser_backend.py", line 187, in Close
08/02 07:55:35.343 ERROR|         traceback:0013|     py_utils.WaitFor(lambda: not self._IsCryptohomeMounted(), 180)
08/02 07:55:35.350 ERROR|         traceback:0013|   File "/usr/local/telemetry/src/third_party/catapult/common/py_utils/py_utils/__init__.py", line 129, in WaitFor
08/02 07:55:35.365 ERROR|         traceback:0013|     res = condition()
08/02 07:55:35.372 ERROR|         traceback:0013|   File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome/cros_browser_backend.py", line 187, in <lambda>
08/02 07:55:35.380 ERROR|         traceback:0013|     py_utils.WaitFor(lambda: not self._IsCryptohomeMounted(), 180)
08/02 07:55:35.387 ERROR|         traceback:0013|   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
08/02 07:55:35.395 ERROR|         traceback:0013|     return func(*args, **kwargs)
08/02 07:55:35.402 ERROR|         traceback:0013|   File "/usr/local/telemetry/src/third_party/catapult/telemetry/telemetry/internal/backends/chrome/cros_browser_backend.py", line 250, in _IsCryptohomeMounted
08/02 07:55:35.409 ERROR|         traceback:0013|     return self._cri.IsCryptohomeMounted(username, self._is_guest)
08/02 07:55:35.417 ERROR|         traceback:0013| AttributeError: 'NoneType' object has no attribute 'IsCryptohomeMounted'
08/02 07:55:35.425 ERROR|              test:0624| Now raising the earlier <class 'autotest_lib.client.common_lib.error.TestFail'> error
08/02 07:55:35.433 DEBUG|   logging_manager:0627| Logging subprocess finished
08/02 07:55:35.436 DEBUG|   logging_manager:0627| Logging subprocess finished

The adb host is not ready error seems like a flake to me. But the 'NoneType' object has no attribute 'IsCryptohomeMounted' seems like a bug.

 
NoneType access is actually a bug of arc.py, IMO, but triggered by adb timeout.
In timeout case, ArcTest.cleanup is called manually.
https://cs.corp.google.com/chromeos_public/src/third_party/autotest/files/client/common_lib/cros/arc.py?q=arc.py+file:%5Esrc/third_party/autotest/files/+package:%5Echromeos_public$&l=502

In the function, Chrome is closed once, which releases cri.
However, it is again called by testing framework itself, so it causes double-close, and None access here.
Project Member

Comment 2 by bugdroid1@chromium.org, Aug 4 2017

The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/third_party/autotest/+/1984650b228d4bb0d2f8fc9210d32ec1b270d1e6

commit 1984650b228d4bb0d2f8fc9210d32ec1b270d1e6
Author: Hidehiko Abe <hidehiko@chromium.org>
Date: Fri Aug 04 04:51:43 2017

Do not call cleanup in initialize on error.

cleanup will be called in testing framework (common_lib/test.py)
regardless of test status.
Calling it twice causes double-close, so do not it.

BUG= chromium:751771 
TEST=Ran try.

Change-Id: I927b91d58efbeeef3ebecba82b66315511ea64bf
Reviewed-on: https://chromium-review.googlesource.com/598663
Commit-Ready: Hidehiko Abe <hidehiko@chromium.org>
Tested-by: Hidehiko Abe <hidehiko@chromium.org>
Reviewed-by: Kazuhiro Inaba <kinaba@chromium.org>

[modify] https://crrev.com/1984650b228d4bb0d2f8fc9210d32ec1b270d1e6/client/common_lib/cros/arc.py

Status: Archived (was: Untriaged)

Sign in to add a comment