Ubuntu
linux package

linux autopkgtest kills sshd in testbed

Bug #1632252 reported by Martin Pitt
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
linux (Ubuntu)
Fix Released
Medium
Colin Ian King
Yakkety
Fix Released
Medium
Colin Ian King

Bug Description

The current linux autopkgtests in yakkety are caught in an eternal "temporary failure" retry loop. They stopped timing out, but in the middle of the tests they kill sshd.

Tail of test output:

09:01:00 DEBUG| [stdout] preparing apparmor_2.10.95-4ubuntu5.dsc... done
09:01:00 DEBUG| [stdout]
09:01:40 ERROR| [stderr] Run libapparmor testsuite (with python3) ... ok
09:01:40 ERROR| [stderr] test_parser_testsuite (__main__.ApparmorTestsuites)
09:01:48 DEBUG| [stdout] preparing apparmor_2.10.95-4ubuntu5.dsc... done
09:01:48 DEBUG| [stdout]
09:19:27 ERROR| [stderr] Run parser regression tests ... ok
09:19:27 ERROR| [stderr] test_regression_testsuite (__main__.ApparmorTestsuites)
09:19:33 DEBUG| [stdout] preparing apparmor_2.10.95-4ubuntu5.dsc... done
09:19:33 DEBUG| [stdout]
Killed
Killed
Connection to 10.220.42.236 closed by remote host.
Exit request sent.
autopkgtest [09:24:42]: ERROR: testbed failure: testbed auxverb failed with exit code 255

Console output during the test:

Ubuntu 16.10 autopkgtest ttyS0

autopkgtest login: [ 3512.996305] AppArmor: change_hat: Invalid input '^open'
[ 3513.000678] AppArmor: change_hat: Invalid input '^'[ 3513.013965] AppArmor: change_hat: Invalid input, NULL hat and NULL magic
[ 3513.019831] AppArmor: change_hat: Invalid input, NULL hat and NULL magic
[ 3513.024872] AppArmor: change_hat: Invalid input '^open'AppArmor: change_hat: Invalid input '^'
[ 3513.026539] AppArmor: change_hat: Invalid input '^'[ 3638.281408] Out of memory: Kill process 587 (rsyslogd) score 8 or sacrifice child
[ 3638.284907] Killed process 587 (rsyslogd) total-vm:107460kB, anon-rss:67892kB, file-rss:2548kB, shmem-rss:0kB
[ 3638.306990] Out of memory: Kill process 300 (systemd-journal) score 2 or sacrifice child
[ 3638.308985] Killed process 300 (systemd-journal) total-vm:46184kB, anon-rss:460kB, file-rss:3752kB, shmem-rss:15412kB
[ 3638.319337] Out of memory: Kill process 2636 (autotest-local) score 1 or sacrifice child
[ 3638.320394] Killed process 10325 (autotest-local) total-vm:18092kB, anon-rss:7296kB, file-rss:3544kB, shmem-rss:0kB
[ 3638.345419] Out of memory: Kill process 2636 (autotest-local) score 1 or sacrifice child
[ 3638.347095] Killed process 2638 (autotest-local) total-vm:17836kB, anon-rss:7160kB, file-rss:1752kB, shmem-rss:0kB
[ 3638.368917] Out of memory: Kill process 2636 (autotest-local) score 1 or sacrifice child
[ 3638.369954] Killed process 2637 (autotest-local) total-vm:17836kB, anon-rss:7160kB, file-rss:1684kB, shmem-rss:0kB
[ 3638.479196] Out of memory: Kill process 2636 (autotest-local) score 1 or sacrifice child
[ 3638.482968] Killed process 2636 (autotest-local) total-vm:17836kB, anon-rss:7248kB, file-rss:5864kB, shmem-rss:0kB
[ 3638.501050] Out of memory: Kill process 10619 (python) score 1 or sacrifice child
[ 3638.502022] Killed process 14752 (make) total-vm:6052kB, anon-rss:196kB, file-rss:2032kB, shmem-rss:0kB
[ 3638.511243] Out of memory: Kill process 10619 (python) score 1 or sacrifice child
[ 3638.512224] Killed process 10619 (python) total-vm:16752kB, anon-rss:5836kB, file-rss:6148kB, shmem-rss:0kB
[ 3638.525104] Out of memory: Kill process 3382 (python) score 0 or sacrifice child
[ 3638.526060] Killed process 3382 (python) total-vm:21296kB, anon-rss:3732kB, file-rss:4080kB, shmem-rss:0kB
[ 3638.545114] Out of memory: Kill process 553 (haveged) score 0 or sacrifice child
[ 3638.546068] Killed process 553 (haveged) total-vm:8028kB, anon-rss:4780kB, file-rss:1468kB, shmem-rss:0kB
[ 3638.573449] Out of memory: Kill process 10373 (sshd) score 0 or sacrifice child
[ 3638.574353] Killed process 11430 (sshd) total-vm:14444kB, anon-rss:1712kB, file-rss:2960kB, shmem-rss:0kB
[ 3638.591696] Out of memory: Kill process 10373 (sshd) score 0 or sacrifice child
[ 3638.595493] Killed process 10373 (sshd) total-vm:13460kB, anon-rss:752kB, file-rss:5476kB, shmem-rss:4kB
[ 3638.605938] Out of memory: Kill process 898 (sshd) score 0 or sacrifice child
[ 3638.607617] Killed process 911 (sshd) total-vm:13804kB, anon-rss:1120kB, file-rss:3184kB, shmem-rss:0kB
[ 3638.626950] Out of memory: Kill process 898 (sshd) score 0 or sacrifice child
[ 3638.627839] Killed process 898 (sshd) total-vm:13460kB, anon-rss:744kB, file-rss:5436kB, shmem-rss:4kB
[ 3638.641735] Out of memory: Kill process 900 (systemd) score 0 or sacrifice child
[ 3638.643448] Killed process 901 ((sd-pam)) total-vm:10360kB, anon-rss:1300kB, file-rss:48kB, shmem-rss:0kB
[ 3638.652509] Out of memory: Kill process 900 (systemd) score 0 or sacrifice child
[ 3638.653656] Killed process 900 (systemd) total-vm:9288kB, anon-rss:640kB, file-rss:4928kB, shmem-rss:0kB
[ 3638.665935] Out of memory: Kill process 11431 (bash) score 0 or sacrifice child
[ 3638.666823] Killed process 10819 (dmesg) total-vm:4236kB, anon-rss:84kB, file-rss:880kB, shmem-rss:0kB
[ 3638.675625] Out of memory: Kill process 11431 (bash) score 0 or sacrifice child
[ 3638.676541] Killed process 11431 (bash) total-vm:6656kB, anon-rss:1460kB, file-rss:2956kB, shmem-rss:0kB
[ 3638.691069] Out of memory: Kill process 9626 (bash) score 0 or sacrifice child
[ 3638.694953] Killed process 10187 (link_subset) total-vm:2420kB, anon-rss:72kB, file-rss:752kB, shmem-rss:0kB

While the test ran, I was logged in via ssh and ran "dmesg -w". Tail:

egression/apparmor/link_subset" name="/tmp/sdtest.9626-16014-y5JvIx/link_mraCxk" pid=10187 comm="link_subset" requested_mask="l" denied_mask="l" fsuid=0 ouid=0 target="/tmp/sdtest.9626-16014-y5JvIx/target_mrwPixlk"
[ 3638.404240] audit: type=1400 audit(1476177816.588:151906): apparmor="DENIED" operation="link" info="link not subset of target" error=-13 profile="/tmp/testlibu87fac/source/yakkety/apparmor-2.10.95/tests/regression/apparmor/link_subset" name="/tmp/sdtest.9626-16014-y5JvIx/link_mCxlk" pid=10187 comm="link_subset" requested_mask="x" denied_mask="x" fsuid=0 ouid=0 target="/tmp/sdtest.9626-16014-y5JvIx/target_mrwPixlk"
[ 3638.404254] audit: type=1400 audit(1476177816.588:151907): apparmor="DENIED" operation="link" info="link not subset of target" error=-13 profile="/tmp/testlibu87fac/source/yakkety/apparmor-2.10.95/tests/regression/apparmor/link_subset" name="/tmp/sdtest.9626-16014-y5JvIx/link_mwCxlk" pid=10187 comm="link_subset" requested_mask="x" denied_mask="x" fsuid=0 ouid=0 target="/tmp/sdtest.9626-16014-y5JvIx/target_mrwPixlk"
[ 3638.404267] audit: type=1400 audit(1476177816.588:151908): apparmor="DENIED" operation="link" info="link not subset of target" error=-13 profile="/tmp/testlibu87fac/source/yakkety/apparmor-2.10.95/tests/regression/apparmor/link_subset" name="/tmp/sdtest.9626-16014-y5JvIx/link_mrCxlk" pid=10187 comm="link_subset" requested_mask="x" denied_mask="x" fsuid=0 ouid=0 target="/tmp/sdtest.9626-16014-y5JvIx/target_mrwPixlk"
[ 3638.404280] audit: type=1400 audit(1476177816.588:151909): apparmor="DENIED" operation="link" info="link not subset of target" error=-13 profile="/tmp/testlibu87fac/source/yakkety/apparmor-2.10.95/tests/regression/apparmor/link_subset" name="/tmp/sdtest.9626-16014-y5JvIx/link_mrwCxlk" pid=10187 comm="link_subset" requested_mask="x" denied_mask="x" fsuid=0 ouid=0 target="/tmp/sdtest.9626-16014-y5JvIx/target_mrwPixlk"
[ 3638.404293] audit: type=1400 audit(1476177816.588:151910): apparmor="DENIED" operation="link" info="link not subset of target" error=-13 profile="/tmp/testlibu87fac/source/yakkety/apparmor-2.10.95/tests/regression/apparmor/link_subset" name="/tmp/sdtest.9626-16014-y5JvIx/link_maCxlk" pid=10187 comm="link_subset" requested_mask="x" denied_mask="x" fsuid=0 ouid=0 target="/tmp/sdtest.9626-16014-y5JvIx/target_mrwPixlk"
[ 3638.404306] audit: type=1400 audit(1476177816.588:151911): apparmor="DENIED" operation="link" info="link not subset of target" error=-13 profile="/tmp/testlibu87fac/source/yakkety/apparmor-2.10.95/tests/regression/apparmor/link_subset" name="/tmp/sdtest.9626-16014-y5JvIx/link_mraCxlk" pid=10187 comm="link_subset" requested_mask="x" denied_mask="x" fsuid=0 ouid=0 target="/tmp/sdtest.9626-16014-y5JvIx/target_mrwPixlk"
[ 3638.404318] audit: type=1400 audit(1476177816.588:151912): apparmor="DENIED" operation="link" profile="/tmp/testlibu87fac/source/yakkety/apparmor-2.10.95/tests/regression/apparmor/link_subset" name="/tmp/sdtest.9626-16014-y5JvIx/link_cx" pid=10187 comm="link_subset" requested_mask="l" denied_mask="l" fsuid=0 ouid=0 target="/tmp/sdtest.9626-16014-y5JvIx/target_mrwPixlk"
[ 3638.404330] audit: type=1400 audit(1476177816.588:151913): apparmor="DENIED" operation="link" profile="/tmp/testlibu87fac/source/yakkety/apparmor-2.10.95/tests/regression/apparmor/link_subset" name="/tmp/sdtest.9626-16014-y5JvIx/link_wcx" pid=10187 comm="link_subset" requested_mask="l" denied_mask="l" fsuid=0 ouid=0 target="/tmp/sdtest.9626-16014-y5JvIx/target_mrwPixlk"
[ 3638.404342] audit: type=1400 audit(1476177816.588:151914): apparmor="DENIED" operation="link" profile="/tmp/testlibu87fac/source/yakkety/apparmor-2.10.95/tests/regression/apparmor/link_subset" name="/tmp/sdtest.9626-16014-y5JvIx/link_rcx" pid=10187 comm="link_subset" requested_mask="l" denied_mask="l" fsuid=0 ouid=0 target="/tmp/sdtest.9626-16014-y5JvIx/target_mrwPixlk"
[ 3638.404354] audit: type=1400 audit(1476177816.588:151915): apparmor="DENIED" operation="link" profile="/tmp/testlibu87fac/source/yakkety/apparmor-2.10.95/tests/regression/apparmor/link_subset" name="/tmp/sdtest.9626-16014-y5JvIx/link_rwcx" pid=10187 comm="link_subset" requested_mask="l" denied_mask="l" fsuid=0 ouid=0 target="/tmp/sdtest.9626-16014-y5JvIx/target_mrwPixlk"
[ 3638.404365] audit: type=1400 audit(1476177816.588:151916): apparmor="DENIED" operation="link" profile="/tmp/testlibu87fac/source/yakkety/apparmor-2.10.95/tests/regression/apparmor/link_subset" name="/tmp/sdtest.9626-16014-y5JvIx/link_acx" pid=10187 comm="link_subset" requested_mask="l" denied_mask="l" fsuid=0 ouid=0 target="/tmp/sdtest.9626-16014-y5JvIx/target_mrwPixlk"
[ 3638.404377] audit: type=1400 audit(1476177816.588:151917): apparmor="DENIED" operation="link" profile="/tmp/testlibu87fac/source/yakkety/apparmor-2.10.95/tests/regression/apparmor/link_subset" name="/tmp/sdtest.9626-16014-y5JvIx/link_racx" pid=10187 comm="link_subset" requested_mask="l" denied_mask="l" fsuid=0 ouid=0 target="/tmp/sdtest.9626-16014-y5JvIx/target_mrwPixlk"
[ 3638.404390] audit: type=1400 audit(1476177816.588:151918): apparmor="DENIED" operation="link" info="link not subset of target" error=-13 profile="/tmp/testlibu87fac/source/yakkety/apparmor-2.10.95/tests/regression/apparmor/link_subset" name="/tmp/sdtest.9626-16014-y5JvIx/link_cxl" pid=10187 comm="link_subset" requested_mask="x" denied_mask="x" fsuid=0 ouid=0 target="/tmp/sdtest.9626-16014-y5JvIx/target_mrwPixlk"
[ 3638.404419] audit: type=1400 audit(1476177816.588:151919): apparmor="DENIED" operation="link" info="link not subset of target" error=-13 profile="/tmp/testlibu87fac/source/yakkety/apparmor-2.10.95/tests/regression/apparmor/link_subset" name="/tmp/sdtest.9626-16014-y5JvIx/link_wcxl" pid=10187 comm="link_subset" requested_mask="x" denied_mask="x" fsuid=0 ouid=0 target="/tmp/sdtest.9626-16014-y5JvIx/target_mrwPixlk"
[ 3638.404438] audit: type=1400 audit(1476177816.588:151920): apparmor="DENIED" operation="link" info="link not subset of target" error=-13 profile="/tmp/testlibu87fac/source/yakkety/apparmor-2.10.95/tests/regression/apparmor/link_subset" name="/tmp/sdtest.9626-16014-y5JvIx/link_rcxl" pid=10187 comm="link_subset" requested_mask="x" denied_mask="x" fsuid=0 ouid=0 target="/tmp/sdtest.9626-16014-y5JvIx/target_mrwPixlk"
[ 3638.404452] audit: type=1400 audit(1476177816.588:151921): apparmor="DENIED" operation="link" info="link not subset of target" error=-13 profile="/tmp/testlibu87fac/source/yakkety/apparmor-2.10.95/tests/regression/apparmor/link_subset" name="/tmp/sdtest.9626-16014-y5JvIx/link_rwcxl" pid=10187 comm="link_subset" requested_mask="x" denied_mask="x" fsuid=0 ouid=0 target="/tmp/sdtest.9626-16014-y5JvIx/target_mrwPixlk"
[ 3638.404465] audit: type=1400 audit(1476177816.588:151922): apparmor="DENIED" operation="link" info="link not subset of target" error=-13 profile="/tmp/testlibu87fac/source/yakkety/apparmor-2.10.95/tests/regression/apparmor/link_subset" name="/tmp/sdtest.9626-16014-y5JvIx/link_acxl" pid=10187 comm="link_subset" requested_maspacket_write_wait: Connection to 10.220.42.236: Broken pipe

The many DENIED are just expected errors from the AppArmor tests, and the "broken pipe" is from ssh when the testbed side kills sshd (presumably due to OOM?)

Martin Pitt (pitti)
tags: added: autopkgtest bot-stop-nagging yakkety
Changed in linux (Ubuntu):
status: New → Confirmed
Revision history for this message
Joseph Salisbury (jsalisbury) wrote :

Would it be possible for you to test the latest upstream kernel? Refer to https://wiki.ubuntu.com/KernelMainlineBuilds . Please test the latest v4.8 kernel[0].

If this bug is fixed in the mainline kernel, please add the following tag 'kernel-fixed-upstream'.

If the mainline kernel does not fix this bug, please add the tag: 'kernel-bug-exists-upstream'.

Once testing of the upstream kernel is complete, please mark this bug as "Confirmed".

Thanks in advance.

[0] http://kernel.ubuntu.com/~kernel-ppa/mainline/v4.8

Changed in linux (Ubuntu):
importance: Undecided → Medium
tags: added: kernel-da-key
Revision history for this message
Martin Pitt (pitti) wrote :

It is still happening. I was running journalctl -f on the testbed while it ran, and was able to copy the last 9000 lines of scrollback from tmux.

Revision history for this message
Martin Pitt (pitti) wrote :

I am able to reproduce this locally by using the "ssh" runner on a manually started QEMU instance, instead of the "qemu" runner directly; so this is much easier to investigate.

First this needs a small new feature in autopkgtest's ssh runner: https://anonscm.debian.org/cgit/autopkgtest/autopkgtest.git/commit/?id=9aa6fdbef . Easiest to just run autopkgtest from git (see reproducer below).

 * Take a standard autopkgtest yakkety image (autopkgtest-buildvm-ubuntu-cloud) and run it in QEMU:

  qemu-system-x86_64 -enable-kvm -m 4096 -smp 2 -nographic -drive file=path/to/autopkgtest-yakkety-amd64.img,if=virtio -net nic,model=virtio -net user,hostfwd=tcp::22000-:22

 * Log in (ubuntu/ubuntu) and scp/install your host's ssh key info ~/.ssh/authorized_keys

 * Run the test:

   git clone https://anonscm.debian.org/git/autopkgtest/autopkgtest.git
   autopkgtest/runner/autopkgtest --testname ubuntu-regression-suite linux -- ssh -H localhost -l ubuntu -p 22000 --reboot --capability=isolation-machine --capability=revert --capability=revert-full-system

This takes an hour or so, then the test fails with "testbed failure: testbed auxverb failed with exit code 255" and the console (in qemu) is completely dead. So notably this fails later than on the production infra (where it OOM-kills sshd during AppArmor tests), here it fails right after

  12:39:40 DEBUG| [stdout] selftests: breakpoint_test [PASS]

but this could be variance due to the infra instances having more CPUs and memory, or it's just an artifact of truncating the log earlier.

Revision history for this message
Martin Pitt (pitti) wrote :

After the hang, even SysRq doesn't work (I tried "sync" with Ctrl+A b s -- Ctrl+A b is the QEMU console key combo for sending SysRq, see Ctrl-A ?)

Colin Ian King (colin-king)
Changed in linux (Ubuntu Yakkety):
assignee: nobody → Colin Ian King (colin-king)
Revision history for this message
Martin Pitt (pitti) wrote :

With the QEMU runner this gets further, but it fails for me with

14:33:01 DEBUG| Running 'git clone https://git.launchpad.net/~ubuntu-kernel/ubuntu/+source/linux/+git/yakkety linux'
14:33:01 ERROR| [stderr] Cloning into 'linux'...
autopkgtest [16:02:54]: ERROR: timed out on command "..." (kind: test)
autopkgtest [16:02:54]: test ubuntu-regression-suite: -----------------------]
Exception in thread copyin:
OSError: [Errno 28] No space left on device

Which bears the questions:

 (1) why is this timing out -- shouldn't failures like this cause an immediate exit? ISTM that the test suite is very prone to just hanging when anything goes wrong; can this be robustified somehow?

 (2) Is it really necessary to clone the entire kernel for the test? This will both take ages (it is running through a proxy in the infra!) and also take lots of disk space. If this just needs a few files, can you get them individually instead? If this needs to compile some helper/test binaries, can this happen during package build and you ship them in linux-source, linux-tools-XX, or maybe the -dbgsym package?

Revision history for this message
Colin Ian King (colin-king) wrote :

I'm not able to reproduce the issues you are seeing, however I do see:

16:01:15 DEBUG| [stdout] Test read watchpoint 3 with len: 8 local: 1 global: 1 [Ok]
16:01:15 DEBUG| [stdout] Test icebp [Ok]
16:01:15 DEBUG| [stdout] Test int 3 trap [Ok]
16:01:15 DEBUG| [stdout] selftests: breakpoint_test [PASS]

and one of the last processes to be exec'd is: step_after_susp /sys/power/state

and klog is showing:

[ 3387.159435] PM: Syncing filesystems ... done.
[ 3393.174633] PM: Preparing system for sleep (mem)

and then it does not wake up from suspend.

Revision history for this message
Colin Ian King (colin-king) wrote :

..and the last things to be exec'd are:

16:01:15 exit 1165 0 0.037 ./breakpoint_test
16:01:15 exit 1164 0 0.043 /bin/sh -c for TEST in breakpoint_test step_after_suspend_test; do (./$TEST && echo "selftests: $TEST [PASS]") || echo "selftests: $TEST [FAIL]"; done;
16:01:15 exit 1166 0 0.036 ./breakpoint_test
Time Event PID Info Duration Process
16:01:15 fork 1163 parent /bin/sh -c for TEST in breakpoint_test step_after_suspend_test; do (./$TEST && echo "selftests: $TEST [PASS]") || echo "selftests: $TEST [FAIL]"; done;
16:01:15 fork 1167 child /bin/sh -c for TEST in breakpoint_test step_after_suspend_test; do (./$TEST && echo "selftests: $TEST [PASS]") || echo "selftests: $TEST [FAIL]"; done;
16:01:15 fork 1167 parent /bin/sh -c for TEST in breakpoint_test step_after_suspend_test; do (./$TEST && echo "selftests: $TEST [PASS]") || echo "selftests: $TEST [FAIL]"; done;
16:01:15 fork 1168 child /bin/sh -c for TEST in breakpoint_test step_after_suspend_test; do (./$TEST && echo "selftests: $TEST [PASS]") || echo "selftests: $TEST [FAIL]"; done;
16:01:15 exec 1168 ./step_after_suspend_test
16:01:21 fork 333 parent /lib/systemd/systemd-udevd
16:01:21 fork 1169 child /lib/systemd/systemd-udevd
16:01:21 fork 1169 parent /lib/systemd/systemd-udevd
16:01:21 fork 1170 child /lib/systemd/systemd-udevd
16:01:21 fork 333 parent /lib/systemd/systemd-udevd
16:01:21 fork 1171 child /lib/systemd/systemd-udevd

So, I'm basically ssh'ing to the running qemu instance and running on three terminals:

dmesg -w, forkstat and fnotifystat to see what happens before it gets stuck

Revision history for this message
Colin Ian King (colin-king) wrote :

OK, so S3 sleep works OK in the VM, going to debug step_after_susp /sys/power/state

Revision history for this message
Colin Ian King (colin-king) wrote :

So the linux kernel regression test ./linux/tools/testing/selftests/breakpoints/step_after_suspend_test is being run and does not return. However, running this in a clean instance it does pass. It basically sets the RTC to wake in 5 seconds and does a suspend and the RTC wakealarm wakes it up. Perhaps the 5 second RTC wakealarm is too short when the system is a bit loaded and it takes more than 5 seconds to get to sleep, hence the wakealarm has already fired and does not wake it up when in deep sleep.

Revision history for this message
Colin Ian King (colin-king) wrote :

So I've added a fix to the autotest client tests that modify the wakealarm sleep time to 30 seconds and test VM now gets woken up and the test no longer hangs forever at the point reported in comment #3.

Fix committed:

http://kernel.ubuntu.com/git/ubuntu/autotest-client-tests.git/commit/?id=cad22c2ed884014b2b2ad88deb6f5535ad580689

Please re-run and let me know if there are further problems and/or if this fix solves the issue for you.

Revision history for this message
Martin Pitt (pitti) wrote :

It's better now -- in my local QEMU test the last output is now

14:46:41 DEBUG| [stdout] Test icebp [Ok]
14:46:41 DEBUG| [stdout] Test int 3 trap [Ok]
14:46:41 DEBUG| [stdout] selftests: breakpoint_test [PASS]

and since then (1 hour) it's hung. But now I still can log into ttyS0. dmesg is almost empty:

[ 5501.499217] ata2.01: NODEV after polling detection
[ 5501.500138] ata2.00: configured for MWDMA2

(something in the test clears the ring buffer), and journalctl confirms that suspend/resume worked fine:

Oct 18 14:47:11 autopkgtest kernel: PM: suspend of devices complete after 65.273 msecs
Oct 18 14:47:11 autopkgtest kernel: PM: late suspend of devices complete after 0.172 msecs
Oct 18 14:47:11 autopkgtest kernel: PM: noirq suspend of devices complete after 1.963 msecs
Oct 18 14:47:11 autopkgtest kernel: ACPI: Preparing to enter system sleep state S3
Oct 18 14:47:11 autopkgtest kernel: PM: Saving platform NVS memory
Oct 18 14:47:11 autopkgtest kernel: Disabling non-boot CPUs ...
Oct 18 14:47:11 autopkgtest kernel: kvm-clock: cpu 0, msr 1:3fff4001, primary cpu clock, resume
Oct 18 14:47:11 autopkgtest kernel: ACPI: Low-level resume complete
Oct 18 14:47:11 autopkgtest kernel: PM: Restoring platform NVS memory
Oct 18 14:47:11 autopkgtest kernel: ACPI: Waking up from system sleep state S3
Oct 18 14:47:11 autopkgtest kernel: PM: noirq resume of devices complete after 6.973 msecs
Oct 18 14:47:11 autopkgtest kernel: PM: early resume of devices complete after 0.105 msecs
Oct 18 14:47:11 autopkgtest kernel: pci 0000:00:01.0: PIIX3: Enabling Passive Release
Oct 18 14:47:11 autopkgtest kernel: rtc_cmos 00:00: System wakeup disabled by ACPI
Oct 18 14:47:11 autopkgtest kernel: PM: resume of devices complete after 8.898 msecs
Oct 18 14:47:11 autopkgtest kernel: PM: Finishing wakeup.
Oct 18 14:47:11 autopkgtest systemd[1]: Time has been changed
Oct 18 14:47:11 autopkgtest systemd[1]: apt-daily.timer: Adding 10h 56min 28.694439s random time.
Oct 18 14:47:11 autopkgtest systemd[3986]: Time has been changed
Oct 18 14:47:11 autopkgtest kernel: Restarting tasks ... done.
Oct 18 14:47:11 autopkgtest sudo[30731]: pam_unix(sudo:session): session closed for user root
Oct 18 14:47:11 autopkgtest kernel: ata2.01: NODEV after polling detection
Oct 18 14:47:11 autopkgtest kernel: ata2.00: configured for MWDMA2

But also, no messages beyond that (last message one hour ago).

Colin wants a new bug for this, so I filed bug 1634519.

Revision history for this message
Martin Pitt (pitti) wrote :

Indeed we did get a "proper" timeout now \o/

https://objectstorage.prodstack4-5.canonical.com/v1/AUTH_77e2ada1e7a84929a74ba3b87153c0ac/autopkgtest-yakkety/yakkety/amd64/l/linux/20161018_180219_53396@/log.gz

So closing this one, and using bug 1634519 for the new timeout.

Changed in linux (Ubuntu Yakkety):
status: Confirmed → Fix Released
Changed in linux (Ubuntu):
status: Confirmed → Fix Released
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.
Subscribing...

Other bug subscribers

Bug attachments

Remote bug watches

Bug watches keep track of this bug in other bug trackers.