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

Issue 844097 link

Starred by 4 users

Issue metadata

Status: Verified
Owner:
Last visit 15 days ago
Closed: May 2018
Cc:
EstimatedDays: ----
NextAction: ----
OS: Chrome
Pri: 1
Type: Bug



Sign in to add a comment

cheets_CleanShutDown failed on caroline-tot-chrome-pfq-informational with "adb is not ready in 60 seconds."

Project Member Reported by derat@chromium.org, May 17 2018

Issue description

cheets_CleanShutDown failed on caroline-tot-chrome-pfq-informational at http://cros-goldeneye/chromeos/healthmonitoring/buildDetails?buildbucketId=8946285831348530528 with "adb is not ready in 60 seconds.":

...
05/17 06:07:48.527 INFO |        arc_common:0037| Waiting for Android to boot completely.
05/17 06:07:52.710 INFO |        arc_common:0043| Android has booted completely.
05/17 06:08:52.930 ERROR|             utils:2732| Will raise error TestFail('adb is not ready in 60 seconds.',) due to unexpected return: False
05/17 06:08:53.007 WARNI|              test:0637| The test failed with the following exception
Traceback (most recent call last):
  File "/usr/local/autotest/common_lib/test.py", line 631, in _exec
    _call_test_function(self.execute, *p_args, **p_dargs)
  File "/usr/local/autotest/common_lib/test.py", line 831, in _call_test_function
    return func(*args, **dargs)
  File "/usr/local/autotest/common_lib/test.py", line 495, in execute
    dargs)
  File "/usr/local/autotest/common_lib/test.py", line 362, in _call_run_once_with_retry
    postprocess_profiled_run, args, dargs)
  File "/usr/local/autotest/common_lib/test.py", line 400, in _call_run_once
    self.run_once(*args, **dargs)
  File "/usr/local/autotest/tests/cheets_CleanShutDown/cheets_CleanShutDown.py", line 20, in run_once
    arc.wait_for_android_process('org.chromium.arc.intent_helper')
  File "/usr/local/autotest/common_lib/cros/arc.py", line 395, in wait_for_android_process
    sleep_interval=_PROCESS_CHECK_INTERVAL_SECONDS)
  File "/usr/local/autotest/common_lib/utils.py", line 2726, in poll_for_condition
    value = condition()
  File "/usr/local/autotest/common_lib/cros/arc.py", line 391, in <lambda>
    condition = lambda: is_android_process_running(process_name)
  File "/usr/local/autotest/common_lib/cros/arc.py", line 316, in is_android_process_running
    output = adb_shell('pgrep -c -f %s' % pipes.quote(process_name))
  File "/usr/local/autotest/common_lib/cros/arc.py", line 176, in adb_shell
    output = adb_cmd('shell %s' % pipes.quote(cmd), **kwargs)
  File "/usr/local/autotest/common_lib/cros/arc.py", line 167, in adb_cmd
    wait_for_adb_ready()
  File "/usr/local/autotest/common_lib/cros/arc.py", line 146, in wait_for_adb_ready
    timeout)
  File "/usr/local/autotest/common_lib/utils.py", line 2733, in poll_for_condition
    raise exception
TestFail: adb is not ready in 60 seconds.

 Issue 843118  reports the same error on kevin-paladin, but I don't know if the cause is the same.
 
Cc: lhchavez@chromium.org
The container was up and running because /var/log/messages has

  2018-05-17T13:07:51.085467+00:00 INFO session_manager[15859]: [INFO:upstart_signal_emitter.cc(35)] Emitting arc-booted Upstart signal

(which means the container reached the boot_progress_enable_screen phase and the mojo connection was working), and android.kmsg, arc-lifetime.log, and /var/run/android/ (run_oci log) don't say container was shut down. So it's safe to say the container was up, but for some reason adb didn't work.

android.kmsg has 

  [  667.862115] <5>init: Starting service 'adbd'...
  <EOF>

so the container at least tried to start it, but that's all I can tell. logcat logs seem missing which is also strange and because of that, it's hard to tell what happened in the container.

Luis, since this is adb, do you have any idea why this happened?

No idea, but maybe the way we are checking some random logcat output for a string is Considered Harmfulâ„¢. I'll add some more logging to begin with.
As to why logcat is missing, that's because cheets_CleanShutDown is not an arc.ArcTest, so logcat collection is not enabled :(
Cc: yusukes@chromium.org
Owner: lhchavez@chromium.org
Status: Started (was: Assigned)
Sent a few patches to improve this situation, and to have better logs. I guess I'll take the bug.

Comment 5 by kinaba@chromium.org, May 18 2018

Labels: ArcConstable
Project Member

Comment 6 by bugdroid1@chromium.org, May 19 2018

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

commit 3e6a9350390e555c7c63f0a14fe8c18cf05a7a81
Author: Luis Hector Chavez <lhchavez@google.com>
Date: Sat May 19 00:19:53 2018

arc: Make the adb connection a bit more robust

This change:

* Stops needlessly tying some random container state to adb connection
  being ready. Instead, just connect!
* Adds logging if the connection cannot be established on time.

BUG= chromium:844097 
TEST=test_that ${DUT} cheets_ContainerSmokeTest

Change-Id: I8a2ef316d72fad8dac5a89c51861080352b8bedb
Reviewed-on: https://chromium-review.googlesource.com/1064548
Commit-Ready: Luis Hector Chavez <lhchavez@chromium.org>
Tested-by: Luis Hector Chavez <lhchavez@chromium.org>
Reviewed-by: Yusuke Sato <yusukes@chromium.org>
Reviewed-by: Victor Hsieh <victorhsieh@chromium.org>

[modify] https://crrev.com/3e6a9350390e555c7c63f0a14fe8c18cf05a7a81/client/common_lib/cros/arc.py

Project Member

Comment 8 by bugdroid1@chromium.org, May 23 2018

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

commit b740ab9dbc7ff362970ad8203e5dec1ce702fa5d
Author: Luis Hector Chavez <lhchavez@google.com>
Date: Wed May 23 19:50:50 2018

arc: Extract the logcat collection logic

This change adds a Logcat context manager, that can be used in
non-arc.ArcTest tests.

BUG= chromium:844097 
TEST=cheets_ContainerSmokeTest

Change-Id: I52271a84ce69bea867658424173fdf88a966d718
Reviewed-on: https://chromium-review.googlesource.com/1064549
Commit-Ready: Luis Hector Chavez <lhchavez@chromium.org>
Tested-by: Luis Hector Chavez <lhchavez@chromium.org>
Reviewed-by: Luis Hector Chavez <lhchavez@chromium.org>
Reviewed-by: Victor Hsieh <victorhsieh@chromium.org>

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

Project Member

Comment 9 by bugdroid1@chromium.org, May 30 2018

The following revision refers to this bug:
  https://chrome-internal.googlesource.com/chromeos/autotest-cheets/+/f9c79b0954a589061f31cec8c0f03d43cfd1e64c

commit f9c79b0954a589061f31cec8c0f03d43cfd1e64c
Author: Luis Hector Chavez <lhchavez@google.com>
Date: Wed May 30 00:15:24 2018

Cc: dgreid@chromium.org mtyin@chromium.org
 Issue 843118  has been merged into this issue.

Sign in to add a comment