Second run: Nothing useful at all in "nova console-log" (just the normal
boot up to "login:"), test output tail is
07:32:01 DEBUG| [stdout] nice PASSED
07:32:11 DEBUG| [stdout] null PASSED
07:32:21 DEBUG| [stdout] opcode PASSED
07:32:31 DEBUG| [stdout] open PASSED
07:32:41 DEBUG| [stdout] personality PASSED
07:32:51 DEBUG| [stdout] pipe PASSED
07:33:01 DEBUG| [stdout] poll PASSED
dmesg tail is more interesting, as it has some trace:
[ 1.568250] AppArmor: AppArmor sha1 policy hashing enabled
[21/1103]
[ 1.569433] ima: No TPM chip found, activating TPM-bypass!
[ 1.570642] evm: HMAC attrs: 0x1
[ 1.571783] Magic number: 4:640:161
[ 1.572860] rtc_cmos 00:00: setting system clock to 2016-10-21 04:10:09 UTC
(1477023009)
[ 1.574813] BIOS EDD facility v0.16 2004-Jun-25, 0 devices found
[ 1.576127] EDD information not available.
[ 1.577057] PM: Hibernation image not present or could not be loaded.
[ 1.653017] isapnp: No Plug & Play device found
[ 1.654764] Freeing unused kernel memory: 984K (d3c21000 - d3d17000)
[ 1.656407] Write protecting the kernel text: 8252k
[ 1.657711] Write protecting the kernel read-only data: 3324k
[ 1.658992] NX-protecting the kernel data: 6084k
[ 1.660357] ------------[ cut here ]------------
[ 1.661352] WARNING: CPU: 0 PID: 1 at
/build/linux-yFroJZ/linux-4.8.0/arch/x86/mm/dump_pagetables.c:225
note_page+0x6a1/0x880
[ 1.663740] x86/mm: Found insecure W+X mapping at address c00a0000/0xc00a0000
[ 1.665280] Modules linked in:
[ 1.666020] CPU: 0 PID: 1 Comm: swapper/0 Not tainted 4.8.0-26-generic
#28-Ubuntu
[ 1.667603] Hardware name: OpenStack Foundation OpenStack Nova, BIOS Bochs
01/01/2011
[ 1.669270] d3b54967 625585ec 00200286 d7cabe70 d33da625 d7cabeb4 d3a38b68
d7cabea0
[ 1.669270] d3071b9a d3a38b30 d7cabed4 00000001 d3a38b68 000000e1 d30682a1
000000e1
[ 1.669270] d7cabf34 80000000 00000000 d7cabec0 d3071c06 00000009 00000000
d7cabeb4
[ 1.669270] Call Trace:
[ 1.669270] [<d33da625>] dump_stack+0x58/0x73
[ 1.669270] [<d3071b9a>] __warn+0xea/0x110
[ 1.669270] [<d30682a1>] ? note_page+0x6a1/0x880
[ 1.669270] [<d3071c06>] warn_slowpath_fmt+0x46/0x60
[ 1.669270] [<d30682a1>] note_page+0x6a1/0x880
[ 1.669270] [<d3068675>] ptdump_walk_pgd_level_core+0x1f5/0x300
[ 1.669270] [<d30687b6>] ptdump_walk_pgd_level_checkwx+0x16/0x20
[ 1.669270] [<d305e04d>] mark_rodata_ro+0xfd/0x130
[ 1.669270] [<d3801aac>] kernel_init+0x2c/0x100
[ 1.669270] [<d309b4b1>] ? schedule_tail+0x11/0x50
[ 1.669270] [<d380c3e2>] ret_from_kernel_thread+0xe/0x24
[ 1.669270] [<d3801a80>] ? rest_init+0x70/0x70
[ 1.688344] ---[ end trace c05a9abbb5340752 ]---
[ 1.689410] x86/mm: Checked W+X mappings: FAILED, 96 W+X pages found.
[ 1.708425] random: systemd-udevd: uninitialized urandom read (16 bytes read)
[ 1.710325] random: udevadm: uninitialized urandom read (16 bytes read)
[ 1.710853] random: udevadm: uninitialized urandom read (16 bytes read)
[ 1.711745] random: udevadm: uninitialized urandom read (16 bytes read)
[ 1.711864] random: udevadm: uninitialized urandom read (16 bytes read)
[ 1.712433] random: udevadm: uninitialized urandom read (16 bytes read)
[ 1.712560] random: udevadm: uninitialized urandom read (16 bytes read)
[ 1.712670] random: udevadm: uninitialized urandom read (16 bytes read)
[ 1.712787] random: udevadm: uninitialized urandom read (16 bytes read)
[ 1.712907] random: udevadm: uninitialized urandom read (16 bytes read)
[ 1.763408] virtio_net virtio0 ens2: renamed from eth0
[ 1.787845] input: VirtualPS/2 VMware VMMouse as
/devices/platform/i8042/serio1/input/input4
[ 1.790353] input: VirtualPS/2 VMware VMMouse as
/devices/platform/i8042/serio1/input/input3
[ 1.809191] FDC 0 is a S82078B
[ 1.960057] raid6: mmxx1 gen() 1882 MB/s
[ 2.028044] raid6: mmxx2 gen() 3964 MB/s
[ 2.096071] raid6: sse1x1 gen() 1800 MB/s
[ 2.164055] raid6: sse1x2 gen() 3682 MB/s
[ 2.232054] raid6: sse2x1 gen() 3614 MB/s
[ 2.300046] raid6: sse2x1 xor() 3707 MB/s
[ 2.368047] raid6: sse2x2 gen() 6710 MB/s
[ 2.436044] raid6: sse2x2 xor() 4994 MB/s
[ 2.437024] raid6: using algorithm sse2x2 gen() 6710 MB/s
[ 2.438174] raid6: .... xor() 4994 MB/s, rmw enabled
[ 2.439221] raid6: using ssse3x1 recovery algorithm
[ 2.445977] xor: automatically using best checksumming function: avx
[ 2.506401] Btrfs loaded, crc32c=crc32c-intel
[ 2.579605] EXT4-fs (vda1): mounted filesystem with ordered data mode. Opts:
(null)
[ 2.686394] ip_tables: (C) 2000-2006 Netfilter Core Team
[ 2.689931] random: fast init done
[ 2.725766] systemd[1]: systemd 231 running in system mode. (+PAM +AUDIT
+SELINUX +IMA +APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS
+ACL +XZ -LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN)
[ 2.729703] systemd[1]: Detected virtualization bochs.
[ 2.730793] systemd[1]: Detected architecture x86.
[ 2.734449] systemd[1]: Set hostname to <autopkgtest>.
[ 2.819482] systemd[1]: Started Forward Password Requests to Wall Directory
Watch.
[ 2.824442] systemd[1]: Created slice User and Session Slice.
[ 2.828247] systemd[1]: Listening on Journal Audit Socket.
[ 2.831708] systemd[1]: Listening on udev Kernel Socket.
[ 2.834599] systemd[1]: Created slice System Slice.
[ 2.837037] systemd[1]: Listening on /dev/initctl Compatibility Named Pipe.
[ 2.916481] EXT4-fs (vda1): re-mounted. Opts: (null)
[ 2.991240] systemd-journald[299]: Received request to flush runtime journal
from PID 1
[ 2.994597] random: crng init done
[ 3.085783] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0xb100,
revision 0
[ 3.308361] ppdev: user-space parallel port driver
[ 3.330475] kvm: Nested Virtualization enabled
[ 3.918194] audit: type=1400 audit(1477023011.840:2): apparmor="STATUS"
operation="profile_load" profile="unconfined" name="/usr/sbin/haveged" pid=596
comm="apparmor_parser"
[ 3.922393] audit: type=1400 audit(1477023011.844:3): apparmor="STATUS"
operation="profile_load" profile="unconfined" name="/sbin/dhclient" pid=595
comm="apparmor_parser"
[ 3.922402] audit: type=1400 audit(1477023011.844:4): apparmor="STATUS"
operation="profile_load" profile="unconfined"
name="/usr/lib/NetworkManager/nm-dhcp-client.action" pid=595
comm="apparmor_parser"
[ 3.922408] audit: type=1400 audit(1477023011.844:5): apparmor="STATUS"
operation="profile_load" profile="unconfined"
name="/usr/lib/NetworkManager/nm-dhcp-helper" pid=595 comm="apparmor_parser"
[ 3.922414] audit: type=1400 audit(1477023011.844:6): apparmor="STATUS"
operation="profile_load" profile="unconfined"
name="/usr/lib/connman/scripts/dhclient-script" pid=595 comm="apparmor_parser"
[ 3.923555] audit: type=1400 audit(1477023011.844:7): apparmor="STATUS"
operation="profile_load" profile="unconfined" name="/usr/sbin/tcpdump" pid=598
comm="apparmor_parser"
The timestamps look like a fresh reboot? It's still curious, as I was
getting these *through* ssh -- so apparently rebooting worked, ssh came
back and gave me the tail, and now it's stuck -- I can't ssh to that
instance again (connection refused) although it's running (according to
nova).
--
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/1634519
Title:
linux autopkgtest: eternal hang/ BUG: soft lockup
Status in linux package in Ubuntu:
Confirmed
Bug description:
Following up to bug 1632252, tests still hang (but not due to the
suspend issue any more). In a local QEMU run:
$ autopkgtest --testname ubuntu-regression-suite linux -- qemu
--ram-size=4096 -o /var/cache/martin /srv/vm/autopkgtest-yakkety-amd64.img
[...]
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).
On the currently running amd64 yakkety test on the ifrastructure, the
int trap bug fails:
13:15:46 DEBUG| [stdout] Test icebp [Ok]
13:15:46 DEBUG| [stdout] Test int 3 trap [Failed]
13:15:46 DEBUG| [stdout] selftests: breakpoint_test [PASS]
and then it's apparently hung at exactly the same problem. But unlike
with local QEMU I cannot ssh in any more (Connection refused), and
console-log shows trouble:
autopkgtest login: [ 1927.192886] AppArmor: change_hat: Invalid input '^open'
[ 1927.194060] AppArmor: change_hat: Invalid input '^'[ 1927.198501]
AppArmor: change_hat: Invalid input, NULL hat and NULL magic
[ 1927.203181] AppArmor: change_hat: Invalid input, NULL hat and NULL magic
[ 1927.207249] AppArmor: change_hat: Invalid input '^open'AppArmor:
change_hat: Invalid input '^'
[ 1927.208826] AppArmor: change_hat: Invalid input '^'[[0;32m OK [0m]
Stopped target Graphical Interface.
[[0;32m OK [0m] Stopped target Multi-User System.
Stopping OpenBSD Secure Shell server...
Stopping autopkgtest root shell on ttyS1...
[ 2909.360975] NMI watchdog: BUG: soft lockup - CPU#3 stuck for 22s!
[swapper/3:0]
[ 2937.360965] NMI watchdog: BUG: soft lockup - CPU#3 stuck for 22s!
[swapper/3:0]
[ 2941.368025] INFO: rcu_sched self-detected stall on CPU
[ 2941.368095] 3-...: (1 GPs behind) idle=ea7/2/0 softirq=544443/544443
fqs=6600
[ 2941.368095] (t=15000 jiffies g=205236 c=205235 q=134637)
[ 2969.360984] NMI watchdog: BUG: soft lockup - CPU#3 stuck for 22s!
[swapper/3:0]
[ 2997.360987] NMI watchdog: BUG: soft lockup - CPU#3 stuck for 22s!
[swapper/3:0]
[ 3021.796060] INFO: task systemd:1 blocked for more than 120 seconds.
[ 3021.797626] Tainted: G W OEL 4.8.0-25-generic #27-Ubuntu
[ 3021.797627] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables
this message.
[ 3021.797727] INFO: task systemd-journal:285 blocked for more than 120
seconds.
[ 3021.797728] Tainted: G W OEL 4.8.0-25-generic #27-Ubuntu
[ 3021.797728] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables
this message.
[ 3021.797772] INFO: task kworker/1:2:303 blocked for more than 120 seconds.
[ 3021.797772] Tainted: G W OEL 4.8.0-25-generic #27-Ubuntu
[ 3021.797773] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables
this message.
[ 3021.797814] INFO: task kworker/2:2:350 blocked for more than 120 seconds.
[ 3021.797815] Tainted: G W OEL 4.8.0-25-generic #27-Ubuntu
[ 3021.797815] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables
this message.
[ 3021.797853] INFO: task acpid:659 blocked for more than 120 seconds.
[ 3021.797853] Tainted: G W OEL 4.8.0-25-generic #27-Ubuntu
[ 3021.797854] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables
this message.
[ 3021.797940] INFO: task (exim4):31259 blocked for more than 120 seconds.
[ 3021.797941] Tainted: G W OEL 4.8.0-25-generic #27-Ubuntu
[ 3021.797941] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables
this message.
[ 3025.361006] NMI watchdog: BUG: soft lockup - CPU#3 stuck for 22s!
[swapper/3:0]
[ 3053.360962] NMI watchdog: BUG: soft lockup - CPU#3 stuck for 22s!
[swapper/3:0]
[ 3081.360962] NMI watchdog: BUG: soft lockup - CPU#3 stuck for 22s!
[swapper/3:0]
[ 3109.360971] NMI watchdog: BUG: soft lockup - CPU#3 stuck for 22s!
[swapper/3:0]
... and a couple of similar repetitions.
To manage notifications about this bug go to:
https://bugs.launchpad.net/ubuntu/+source/linux/+bug/1634519/+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
