Comment 4 for bug 1634519

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

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).