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. -- You received this bug notification because you are a member of Kernel Packages, which is subscribed to linux in Ubuntu. https://bugs.launchpad.net/bugs/1632252 Title: linux autopkgtest kills sshd in testbed Status in linux package in Ubuntu: Confirmed Status in linux source package in Yakkety: Confirmed 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?) To manage notifications about this bug go to: https://bugs.launchpad.net/ubuntu/+source/linux/+bug/1632252/+subscriptions -- Mailing list: https://launchpad.net/~kernel-packages Post to : kernel-packages@lists.launchpad.net Unsubscribe : https://launchpad.net/~kernel-packages More help : https://help.launchpad.net/ListHelp
