Issue 30953 in chromium-os: One alex failed AU during HWTest

[chrom...@googlecode.com]

Status: Assigned
Owner: garn...@chromium.org
CC: dgarr...@chromium.org, so...@chromium.org, cma...@chromium.org,
sco...@chromium.org
Labels: Type-Bug Pri-1 Area-Installer Sev-1 TreeCloser Iteration-56

New issue 30953 by cma...@chromium.org: One alex failed AU during HWTest
http://code.google.com/p/chromium-os/issues/detail?id=30953

http://chromegw/i/chromeos/builders/x86-alex%20canary/builds/2066

CrOS version: x86-alex-release/R21-2302.0.0

Logs from the AU attempt that failed:
https://sandbox.google.com/storage/?arg=chromeos-autotest-results/227947-chromeos-test/#chromeos-autotest-results%2F227947-chromeos-test%2Fchromeos-rack4-host6

[chrom...@googlecode.com]

Comment #1 on issue 30953 by garn...@chromium.org: One alex failed AU
during HWTest
http://code.google.com/p/chromium-os/issues/detail?id=30953

What exactly is (or is not) happening? I'm seeing nothing unusual on the
logs other that this is a dev build, and therefore periodic update checks
are suppressed. Where you trying to trigger a manual update and failed?

[chrom...@googlecode.com]

Comment #2 on issue 30953 by cma...@chromium.org: One alex failed AU
during HWTest
http://code.google.com/p/chromium-os/issues/detail?id=30953

This is in the lab. On machine chromeos-rack4-host6, it's timing out
with "Update failed. Timed out waiting for system to mark new kernel as
successful."

I thought the GS link would point to that host's logs, but it doesn't.
That's aggravating.

[chrom...@googlecode.com]

Comment #3 on issue 30953 by garn...@chromium.org: One alex failed AU
during HWTest
http://code.google.com/p/chromium-os/issues/detail?id=30953

Looks like a timing issue in the autotest to me. The last entry in
/var/log/messages is from 06:01:49, indicating that an ssh session from
172.22.73.7 was closed. Apparently, update_engine started at 06:01:08 and
did not engage in updating boot flags until 06:01:55 (as it should), which
might have been too late. Makes sense?

[chrom...@googlecode.com]

Comment #4 on issue 30953 by cma...@chromium.org: One alex failed AU
during HWTest
http://code.google.com/p/chromium-os/issues/detail?id=30953

Why would it take so long?

[chrom...@googlecode.com]

Comment #5 on issue 30953 by garn...@chromium.org: One alex failed AU
during HWTest
http://code.google.com/p/chromium-os/issues/detail?id=30953

We're using a fixed delay (45 seconds) as a substitute for the real
dependency. See http://code.google.com/p/chromium-os/issues/detail?id=26749

[chrom...@googlecode.com]

Comment #6 on issue 30953 by cma...@chromium.org: One alex failed AU
during HWTest
http://code.google.com/p/chromium-os/issues/detail?id=30953

Hm. The code has a 60s timeout that it'll wait for that, which I guess
seems like cutting it close?

[chrom...@googlecode.com]

Comment #7 on issue 30953 by garn...@chromium.org: One alex failed AU
during HWTest
http://code.google.com/p/chromium-os/issues/detail?id=30953

Yep, absolutely. I'm surprised it wasn't noticed before. Can it be easily
extended, to (say) 90 seconds? Is there a reason not to?

[chrom...@googlecode.com]

Updates:
Owner: cma...@chromium.org

Comment #8 on issue 30953 by cma...@chromium.org: One alex failed AU
during HWTest
http://code.google.com/p/chromium-os/issues/detail?id=30953

Ok, I'll take this on. WE're just going to extend the timeout. That will
still let us catch issues where the kernel is bad or the device is horked.

[chrom...@googlecode.com]

Comment #9 on issue 30953 by garn...@chromium.org: One alex failed AU
during HWTest
http://code.google.com/p/chromium-os/issues/detail?id=30953

Yes. But we should not extend it too much, I think---there's a point in
ensuring the system does not procrastinate marking the new partition as
stable.

[chrom...@googlecode.com]

Updates:
Cc: jrbarne...@chromium.org

Comment #10 on issue 30953 by dgarr...@chromium.org: One alex failed AU
during HWTest
http://code.google.com/p/chromium-os/issues/detail?id=30953

There are some test frameworks that reboot machines rapidly (including boot
performance benchmarking, for one). We need to make sure they don't
downgrade.

[chrom...@googlecode.com]

Comment #11 on issue 30953 by cma...@chromium.org: One alex failed AU
during HWTest
http://code.google.com/p/chromium-os/issues/detail?id=30953

Success will not be detected any more slowly with the proposed change. The
only way such tests would regress is if the update engine starts taking
longer to mark the kernel as stable.

[chrom...@googlecode.com]

Comment #13 on issue 30953 by jrbarne...@chromium.org: One alex failed AU
during HWTest
http://code.google.com/p/chromium-os/issues/detail?id=30953

The 60 second timer doesn't start running until the target is responding
to ssh on the network, which can't happen until the time that update_engine
is invoked. That means that the 60 second timeout allows 15 seconds of
grace, and in turn means that something prevented update_engine from
starting its 45 second timer for over 15 seconds after it should have been
invoked.

I can't say that it's wrong for update_engine to be delayed for so long, but
it's certainly very odd. Is there anything else we can extract from this
failure?

[chrom...@googlecode.com]

Comment #14 on issue 30953 by bugdro...@chromium.org: One alex failed AU
during HWTest
http://code.google.com/p/chromium-os/issues/detail?id=30953#c14

Commit: 163ceadfc654da81c2e82caf5032aa451dc1ec9d
Email: cma...@chromium.org

[autotest] Extend _KERNEL_UPDATE_TIMEOUT in site_host.py

site_host.ChromiumOSHost implements a method that knows how to
install a new cros image on a device and do some checks to
make sure that it's not obviously bad. This has a timeout
that it's willing to wait for update_engine to mark the new
kernel as good. That timeout is currently only 15s longer
than the time that update_engine waits before even trying to
check on the kernel. We run afoul of this at times.

Extending the timeout costs us no correctness and reduces
flakiness. There's not a good way to determine reliably
when we should start waiting for this timeout, so this
method is the lesser of known evils.

BUG=chromium-os:30953
TEST=run_suite.py, which will reimage devices as a matter of course

Change-Id: Iec2d85d3412ccebaf8821c7f31ffeb9b8bdbf50e
Reviewed-on: https://gerrit.chromium.org/gerrit/22839
Tested-by: Chris Masone <cma...@chromium.org>
Reviewed-by: Scott Zawalski <sco...@chromium.org>
Commit-Ready: Chris Masone <cma...@chromium.org>

M server/hosts/site_host.py

[chrom...@googlecode.com]

Updates:
Status: Fixed

Comment #15 on issue 30953 by cma...@chromium.org: One alex failed AU
during HWTest
http://code.google.com/p/chromium-os/issues/detail?id=30953

Gilad looked at the logs already and did not see anything interesting.

If we need a test that imposes a tighter constraint on the time taken to
mark a kernel good, then a test to specifically check that should be
written -- and that work should be tracked elsewhere :-)