broken kernel causes eternal test retry loop

 * Create a container, install ssh and your ssh key:

  lxc launch autopkgtest/ubuntu/yakkety/amd64 y1
  lxc exec y1 -- apt install -y openssh-server
  lxc file push -p --uid=1000 --gid=1000 ~/.ssh/id_rsa.pub y1/home/ubuntu/.ssh/authorized_keys

 * Get the IP from "lxc list" and verify that you can ssh in without a password.

 * Create this test:

   mkdir -p /tmp/t/debian/tests/
   echo 'Test-Command: pkill -e -STOP sshd; sleep 5' > /tmp/t/debian/tests/control

 * Run it:

   lxc exec y1 -- pkill -e -CONT sshd
   autopkgtest --timeout-test=1 /tmp/t -- ssh -l ubuntu -H $IP

   ($IP is the container's IP)

Fix and test cases: https://anonscm.debian.org/cgit/autopkgtest/autopkgtest.git/commit/?id=4a0587a05

Rolled out to production.

It still seems to happen after that patch.

On the infra it now looks like this:

ERROR - 02:45:43 DEBUG| [stdout]
ERROR - 03:19:00 ERROR| [stderr] Run parser regression tests ... ok
ERROR - 03:19:01 ERROR| [stderr] test_regression_testsuite (__main__.ApparmorTestsuites)
ERROR - 03:19:05 DEBUG| [stdout] preparing apparmor_2.10.95-4ubuntu5.dsc... done
ERROR - 03:19:05 DEBUG| [stdout]
ERROR - Killed
ERROR -
ERROR - Due to the above error(s), this script is unable to continue and is terminating.
ERROR -
Connection to 10.42.46.237 closed by remote host.
autopkgtest-virt-ssh [05:07:27]: ERROR: Removing temporary files on testbed timed out
autopkgtest [05:07:36]: ERROR: testbed failure: testbed auxverb failed with exit code 255

This is harder to work around/catch, as in the new case the test does *not* time out, it just kills sshd (or something in the kernel that breaks ssh/networking). In general these are cases that we do want to treat as "tmpfail" and auto-restart, I don't want to treat an auxverb failure as failure in general.

Perhaps we need to introduce some kind of retry counter, but this would need to span at least half a day -- three tmpfails on the same worker in a row are usually a sign of a broken cloud or a broken testbed image, not a test failure. So perhaps some logic to check if other tests tmpfail on the same worker/cloud, and if not then call that test a failure.

This would all require state keeping, which we don't currently do (the only state is the AMQP queue contents).

We're getting another instance of this now. In this case there's a kernel panic. To deal with that specific case, how about something like:

If it's a tmpfail, look at the console log. Remember if there's a kernel panic. If you see a kernel panic 3 times, treat that as a real failure.

In the other case, zesty/linux/i386, there seems to be some kind of problem with the testsuite OOMing and killing autopkgtest itself. Is there any way we can catch that? Look for kill -9 and check the console log? For now I blacklisted the package as it kept coming back and killing the cloud.

> If you see a kernel panic 3 times, treat that as a real failure.

Sounds good!

> the testsuite OOMing and killing autopkgtest itself.

That is, it kills the command (i. e. debian/tests/blah) that autopkgtest runs over ssh? Shouldn't the console log also contain some trace of "OOM" which could be used as an indication that it's a real test failure?

On Tue, Jan 17, 2017 at 07:42:34AM -0000, Martin Pitt wrote:
> > If you see a kernel panic 3 times, treat that as a real failure.
>
> Sounds good!
>
> > the testsuite OOMing and killing autopkgtest itself.
>
> That is, it kills the command (i. e. debian/tests/blah) that autopkgtest
> runs over ssh? Shouldn't the console log also contain some trace of
> "OOM" which could be used as an indication that it's a real test
> failure?

Yep, you can see things being killed by the OOM killer - do you think
that autopkgtest should mark that as a failure, or the worker? If the
worker, this could be an instance of the above too. Is there something
specific we can look for being killed?

Note that autopkgtest in this case:

> ERROR - 12:55:49 ERROR| [stderr] test_regression_testsuite (__main__.ApparmorTestsuites)
> ERROR - 12:55:54 DEBUG| [stdout] preparing apparmor_2.10.95-4ubuntu5.2.dsc... done
> ERROR - 12:55:54 DEBUG| [stdout]
> ERROR - Killed
> ERROR -
> ERROR - Due to the above error(s), this script is unable to continue and is terminating.
> ERROR -
> Connection to 10.220.44.208 closed by remote host.
> Exit request sent.
> autopkgtest [13:03:42]: ERROR: testbed failure: testbed auxverb failed with exit code 255

isn't outputting the console log. I don't think that debug_failure is
surfaced all the way up to lib/adt_testbed.py, where we see this failure
- do you have an idea about how to get it out? Add a
'hook_debug_failure'?

Cheers,

--
Iain Lane [ <email address hidden> ]
Debian Developer [ <email address hidden> ]
Ubuntu Developer [ <email address hidden> ]

I've done the autopkgtest-cloud side of this:

  https://git.launchpad.net/~ubuntu-release/+git/autopkgtest-cloud/commit/?id=f9b3ee01e94d10d51a46702c6150e9c9618b6665

by overriding the return code to 4.

This already worked in production (was killing the bos01 cloud before)

  https://objectstorage.prodstack4-5.canonical.com/v1/AUTH_77e2ada1e7a84929a74ba3b87153c0ac/autopkgtest-zesty-canonical-kernel-team-unstable/zesty/ppc64el/l/linux/20170126_104055_6654d@/log.gz

Still need to do the autopkgtest side: outputting the console log in more situations.

Attaching the following patch

commit 7f37957794d3b65e8d2e236d6af7dafcb2dc79e9
Author: Iain Lane <email address hidden>
Date: Fri Feb 24 12:41:32 2017 +0000

    Add a debug-fail hook and implement it for autopkgtest-virt-ssh

    At the minute, this is mainly so that the nova script can have its
    failure information (`nova console-log') propagated up to the output, so
    that in the case of kernel panics or other random failures we get useful
    output that the driver of autopkgtest (e.g. autopkgtest-cloud) can look
    at.

    https://bugs.launchpad.net/auto-package-testing/+bug/1630578

with this we should get console output after timeout. It's not as good as just receiving the console immediately would be, but nova doesn't provide for that and it's not common/serious enough to poll for IMHO.

Please review!

friendly ping

apw wanted to unblacklist the kernel (suspecting the OOM bug to be fixed), so we did that and it turned out it wasn't.

Rather than re-blacklist, I cowboyed this patch live to test it on a production case and it seemed to work:

  https://objectstorage.prodstack4-5.canonical.com/v1/AUTH_77e2ada1e7a84929a74ba3b87153c0ac/autopkgtest-yakkety/yakkety/i386/l/linux/20170312_020902_83e4d@/log.gz

Hello Iain,

sorry for the delay!

| From 7f37957794d3b65e8d2e236d6af7dafcb2dc79e9 Mon Sep 17 00:00:00 2001
| From: Iain Lane <email address hidden>
| Date: Fri, 24 Feb 2017 12:41:32 +0000
| Subject: [PATCH] Add a debug-fail hook and implement it for
| autopkgtest-virt-ssh
|
| At the minute, this is mainly so that the nova script can have its
| failure information (`nova console-log') propagated up to the output, so
| that in the case of kernel panics or other random failures we get useful
| output that the driver of autopkgtest (e.g. autopkgtest-cloud) can look
| at.
|
| https://bugs.launchpad.net/auto-package-testing/+bug/1630578
| ---
| lib/VirtSubproc.py | 6 ++++++
| lib/adt_testbed.py | 1 +
| virt/autopkgtest-virt-ssh | 36 ++++++++++++++++++++++++++++--------
| 3 files changed, 35 insertions(+), 8 deletions(-)
|
| diff --git a/lib/VirtSubproc.py b/lib/VirtSubproc.py
| index d76a861..e4845fa 100644
| --- a/lib/VirtSubproc.py
| +++ b/lib/VirtSubproc.py
| @@ -699,6 +699,12 @@ def prepare():
| os.kill(os.getpid(), sig)
| sethandlers(handler)
|
| +def cmd_log_debug_fail(c, ce):
| + cmdnumargs(c, ce)
| + try:
| + adtlog.info(caller.hook_debug_fail())
| + except AttributeError:
| + pass
|

Needs two blank lines between functions (tests/pycodestyle will fail
otherwise). Can you please rename this s/log/auxverb/ to more clearly say what
it's for?

| --- a/virt/autopkgtest-virt-ssh
| +++ b/virt/autopkgtest-virt-ssh
| @@ -163,7 +163,7 @@ def parse_args():
| capabilities += args.capability
|
|
| -def execute_setup_script(command, fail_ok=False):
| +def execute_setup_script(command, fail_ok=False, print_stderr=True):
| '''Run the --setup-script, if given.
|
| Arguments passed after -- to the main program are passed verbatim to the
| @@ -173,10 +173,13 @@ def execute_setup_script(command, fail_ok=False):
|
| :param command: Command to execute. The command must match a function in
| the ssh script
| - :param fail_ok: If True, failures will not cause bombing, and this function
| - returns the exit code instead.
| + :param fail_ok: If True, failures will not cause bombing
| + :return: A tuple (stdout, stderr, return code). stdout and stderr may be
| + None, for example if the script fails and fail_ok is True.

Nitpick: Other functions like VirtSubproc.execute_timeout() return (rc, out, err)
so for consistency it would be nice to use the same order.

| '''
| global sshconfig, args
| + out = None
| + err = None
|
| if args.setup_script:
| fpath = args.setup_script
| @@ -194,14 +197,23 @@ def execute_setup_script(command, fail_ok=False):
| cmd += sshconfig['extraopts'].split(' ')
|
| adtlog.debug('Executing setup script: %s' % ' '.join(cmd))
| - (status, out, err) = VirtSubproc.execute_timeout(
| - None, 1800, cmd, stdout=subprocess.PIPE)
| + (status, o, e) = VirtSubproc.execute_timeout(
| + None,
| + 1800,
| + cmd,
| + stdout=subprocess.PIPE,
| + stderr=subprocess....

Thanks for the review!

On Mon, Mar 13, 2017 at 10:50:20AM -0000, Martin Pitt wrote:
> Hello Iain,
>

To rearrange slightly

> | + if print_stderr:
> | + # Keep outputting the error on stderr as well as capturing it
> | + sys.stderr.write(e)
>
> This will cause delayed stderr messages when things are hanging and autopkgtest
> runs interactively, but setting up a complex "tee" pipelining here isn't worth
> the effort, so good enough.

Yeah, I know. I had tried some crazy experiments with tee() and splice()

  https://gist.github.com/iainlane/8b96022e3b98901b25cc5bcab6b43e02

...quite fun to work out, but in the end they didn't work because I
can't use asyncio from a non-main thread apparently (at least IIRC that
was the problem). I guess you could also do some refactoring and add an
async method to VirtSubproc that gives file handles back to read from,
but I figured just printing it explicitly would be acceptable.

> | + out = o | + err = e
>
> Why the extra o and e varibles? This looks confusing. Just directly use
> "(status, out, err) = " as before?

Yeah, just a mistake that I left in from the tee stuff - fixed.

> | def hook_open():
> | host_setup('open')
> | @@ -440,7 +460,7 @@ def hook_wait_reboot():
> | global sshcmd
> |
> | if args.setup_script:
> | - rc = execute_setup_script('wait-reboot', fail_ok=True)
> | + (out, err, rc) = execute_setup_script('wait-reboot', fail_ok=True)
>
> Nitpick: Use "rc = execute..()[0]" or use "_" as variable name for unused
> components, i. e. "(rc, _, _) = execute..()".

Sure.

>
> Did you run the tests/autopkgtest SshRunner{No,With}Script tests with
> that?

Yep, they worked. For some reason I couldn't run them with
AUTOPKGTEST_TEST_LXD set to a zesty container - some seemingly unrelated
problems with apt downloading that also happen on master, but xenial
works fine.

New patch attached. I didn't run this version end to end on an example
yet - just triggered, will reply again if it's broken.

Cheers,

--
Iain Lane [ <email address hidden> ]
Debian Developer [ <email address hidden> ]
Ubuntu Developer [ <email address hidden> ]

Thanks! I pushed your patch to the autopkgtest git. Not sure if there is still an infra change to do (for the "Auto Package Testing" task).

Nope, thank you - that's all done now AFAICS. Thanks for the reviews! :)

This bug was fixed in the package autopkgtest - 5.0

---------------
autopkgtest (5.0) unstable; urgency=medium

  [ Martin Pitt ]
  * Drop obsolete adt-* CLI
    autopkgtest 4.0 with its "autopkgtest" program has been around for a
    year, Debian's and Ubuntu's CI moved to that, and the Debian 9.0 release
    is behind us. Drop "adt-run" and the corresponding adt-virt-* and
    adt-build-* command line interfaces now.
    Add Breaks: for debci for versions that still relied on adt-*.
  * lxc, qemu, ssh: Shorten path of shared directory.
    This helps to reduce socket path lengths in tests.
    (See Debian #860554, LP: #1680577)
  * Drop obsolete ubuntu-touch-session setup script.
    This hasn't been maintained/tested for ages, and with the demise of
    Ubuntu Touch this is now completely obsolete. (Closes: #835836)
  * Avoid bare "except:" clauses
  * tests/autopkgtest_args: pyflakes/pycodestyle fixes
  * tests: Don't run LXC tests with --ephemeral.
    It's not the default and ephemeral containers tend to fail to start too
    often.
  * tests/testpkg: Update Standards-Version and debhelper level.
    Priority "extra" is deprecated, so move to "optional".
  * README.package-tests.rst: Clarify role of control file, add simple
    examples (Closes: #870654)
  * README.package-tests.rst: Update Testsuite: documentation.
    All supported Debian releases now have a new enough dpkg, and Ubuntu
    14.04 will not get new tests any more. (Closes: #876008)
  * Run apt-ftparchive for local debs on testbed instead of host.
    This is slightly more correct as it will produce the format that the
    testbed's apt expects (although that doesn't matter much). It also
    allows autopkgtest to be run on non-Debian hosts.
    As apt-utils is not essential, install it if necessary.
  * README.package-tests.rst: Clarify Testsuite: values
    `autopkgtest` is not any more the only defined value for Testsuite:, as
    the paragraph below already explains.
  * setup-commands/setup-testbed: Look at /etc/os-release for determining
    distribution name. Stop hardcoding "debian|ubuntu|kali" and get this
    information from os-release's ID field. (Closes: #868678)
  * debian/rules: Drop obsolete pysupport override.
    Not necessary any more since dh compat level 9.
  * Bump Standards-Version to 4.1.0. (No changes necessary.)

  [ Stéphane Graber ]
  * debian/tests/lxd: Update to support LXD network/storage API

  [ Steve Langasek ]
  * Fix release name parsing with arch-qualified sources.list
    (Closes: #870393)

  [ Antonio Terceiro ]
  * autopkgtest-build-lxc: Correctly clean cache for Debian containers

 -- Martin Pitt <email address hidden> Sun, 17 Sep 2017 16:50:21 +0200