coreos / bugs

Issue tracker for CoreOS Container Linux
https://coreos.com/os/eol/
146 stars 30 forks source link

cpu stalls and systemd-journald coredumps #1001

Closed jonboulle closed 8 years ago

jonboulle commented 8 years ago

Noticed on qemu-x86_64, CoreOS 845.0.0. As far as I'm aware the system was basically idling at the time this happened, and it's still up (8 days total)

  Booting `CoreOS default'

Loading (hd0,gpt4)/boot/vmlinuz
Booting CoreOS!
[    0.000000] Initializing cgroup subsys cpuset
[    0.000000] Initializing cgroup subsys cpu
[    0.000000] Initializing cgroup subsys cpuacct
[    0.000000] Linux version 4.2.2-coreos-r1 (buildbot@ip-10-204-3-57) (gcc version 4.9.3 (Gentoo Hardened 4.9.3 p1.2, pie-0.6.3) ) #2 SMP Sat Oct 24 19:42:01 UTC 2015
[    0.000000] Command line: BOOT_IMAGE=/boot/vmlinuz console=ttyS0,115200n8 console=tty0 root=LABEL=ROOT mount.usr=PARTUUID=e03dd35c-7c2d-4a47-b3fe-27f15780a57c
[    0.000000] x86/fpu: xstate_offset[2]: 0240, xstate_sizes[2]: 0100
[    0.000000] x86/fpu: Supporting XSAVE feature 0x01: 'x87 floating point registers'
[    0.000000] x86/fpu: Supporting XSAVE feature 0x02: 'SSE registers'
[    0.000000] x86/fpu: Supporting XSAVE feature 0x04: 'AVX registers'
[    0.000000] x86/fpu: Enabled xstate features 0x7, context size is 0x340 bytes, using 'standard' format.
[    0.000000] x86/fpu: Using 'eager' FPU context switches.
[    0.000000] e820: BIOS-provided physical RAM map:
[    0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable
[    0.000000] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved
[    0.000000] BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved
[    0.000000] BIOS-e820: [mem 0x0000000000100000-0x000000003ffdffff] usable
[    0.000000] BIOS-e820: [mem 0x000000003ffe0000-0x000000003fffffff] reserved
[    0.000000] BIOS-e820: [mem 0x00000000feffc000-0x00000000feffffff] reserved
[    0.000000] BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved
[    0.000000] NX (Execute Disable) protection: active
[    0.000000] SMBIOS 2.8 present.
[    0.000000] Hypervisor detected: KVM
[    0.000000] e820: last_pfn = 0x3ffe0 max_arch_pfn = 0x400000000
[    0.000000] x86/PAT: Configuration [0-7]: WB  WC  UC- UC  WB  WC  UC- WT  
[    0.000000] Using GB pages for direct mapping
[    0.000000] init_memory_mapping: [mem 0x00000000-0x000fffff]
[    0.000000] init_memory_mapping: [mem 0x3fc00000-0x3fdfffff]
[    0.000000] init_memory_mapping: [mem 0x20000000-0x3fbfffff]
[    0.000000] init_memory_mapping: [mem 0x00100000-0x1fffffff]
[    0.000000] init_memory_mapping: [mem 0x3fe00000-0x3ffdffff]
[    0.000000] ACPI: Early table checksum verification disabled
[    0.000000] ACPI: RSDP 0x00000000000F62C0 000014 (v00 BOCHS )
[    0.000000] ACPI: RSDT 0x000000003FFE178C 000034 (v01 BOCHS  BXPCRSDT 00000001 BXPC 00000001)
[    0.000000] ACPI: FACP 0x000000003FFE0BDA 000074 (v01 BOCHS  BXPCFACP 00000001 BXPC 00000001)
[    0.000000] ACPI: DSDT 0x000000003FFE0040 000B9A (v01 BOCHS  BXPCDSDT 00000001 BXPC 00000001)
[    0.000000] ACPI: FACS 0x000000003FFE0000 000040
[    0.000000] ACPI: SSDT 0x000000003FFE0C4E 000A76 (v01 BOCHS  BXPCSSDT 00000001 BXPC 00000001)
[    0.000000] ACPI: APIC 0x000000003FFE16C4 000090 (v01 BOCHS  BXPCAPIC 00000001 BXPC 00000001)
[    0.000000] ACPI: HPET 0x000000003FFE1754 000038 (v01 BOCHS  BXPCHPET 00000001 BXPC 00000001)
[    0.000000] No NUMA configuration found
[    0.000000] Faking a node at [mem 0x0000000000000000-0x000000003ffdffff]
[    0.000000] NODE_DATA(0) allocated [mem 0x3ffd9000-0x3ffdffff]
[    0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d00
[    0.000000] kvm-clock: cpu 0, msr 0:3ffd7001, primary cpu clock
[    0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns
[    0.000000] Zone ranges:
[    0.000000]   DMA      [mem 0x0000000000001000-0x0000000000ffffff]
[    0.000000]   DMA32    [mem 0x0000000001000000-0x000000003ffdffff]
[    0.000000]   Normal   empty
[    0.000000] Movable zone start for each node
[    0.000000] Early memory node ranges
[    0.000000]   node   0: [mem 0x0000000000001000-0x000000000009efff]
[    0.000000]   node   0: [mem 0x0000000000100000-0x000000003ffdffff]
[    0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x000000003ffdffff]
[    0.000000] ACPI: PM-Timer IO Port: 0x608
[    0.000000] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1])
[    0.000000] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23
[    0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl)
[    0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level)
[    0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level)
[    0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level)
[    0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level)
[    0.000000] Using ACPI (MADT) for SMP configuration information
[    0.000000] ACPI: HPET id: 0x8086a201 base: 0xfed00000
[    0.000000] smpboot: Allowing 4 CPUs, 0 hotplug CPUs
[    0.000000] PM: Registered nosave memory: [mem 0x00000000-0x00000fff]
[    0.000000] PM: Registered nosave memory: [mem 0x0009f000-0x0009ffff]
[    0.000000] PM: Registered nosave memory: [mem 0x000a0000-0x000effff]
[    0.000000] PM: Registered nosave memory: [mem 0x000f0000-0x000fffff]
[    0.000000] e820: [mem 0x40000000-0xfeffbfff] available for PCI devices
[    0.000000] Booting paravirtualized kernel on KVM
[    0.000000] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns
[    0.000000] setup_percpu: NR_CPUS:128 nr_cpumask_bits:128 nr_cpu_ids:4 nr_node_ids:1
[    0.000000] PERCPU: Embedded 32 pages/cpu @ffff88003fc00000 s91480 r8192 d31400 u524288
[    0.000000] KVM setup async PF for cpu 0
[    0.000000] kvm-stealtime: cpu 0, msr 3fc0e3c0
[    0.000000] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes)
[    0.000000] Built 1 zonelists in Node order, mobility grouping on.  Total pages: 257896
[    0.000000] Policy zone: DMA32
[    0.000000] Kernel command line: rootflags=rw mount.usrflags=ro BOOT_IMAGE=/boot/vmlinuz console=ttyS0,115200n8 console=tty0 root=LABEL=ROOT mount.usr=PARTUUID=e03dd35c-7c2d-4a47-b3fe-27f15780a57c
[    0.000000] PID hash table entries: 4096 (order: 3, 32768 bytes)
[    0.000000] Memory: 991412K/1048056K available (5314K kernel code, 1050K rwdata, 2396K rodata, 27080K init, 940K bss, 56644K reserved, 0K cma-reserved)
[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
[    0.000000] Hierarchical RCU implementation.
[    0.000000]  Build-time adjustment of leaf fanout to 64.
[    0.000000]  RCU restricting CPUs from NR_CPUS=128 to nr_cpu_ids=4.
[    0.000000] RCU: Adjusting geometry for rcu_fanout_leaf=64, nr_cpu_ids=4
[    0.000000] NR_IRQS:8448 nr_irqs:456 16
[    0.000000] Console: colour VGA+ 80x25
[    0.000000] console [tty0] enabled
[    0.000000] console [ttyS0] enabled
[    0.000000] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns
[    0.000000] tsc: Detected 2394.456 MHz processor
[    0.136603] Calibrating delay loop (skipped) preset value.. 4788.91 BogoMIPS (lpj=2394456)
[    0.138215] pid_max: default: 32768 minimum: 301
[    0.139072] ACPI: Core revision 20150619
[    0.141153] ACPI: All ACPI Tables successfully acquired
[    0.142217] Security Framework initialized
[    0.143015] SELinux:  Initializing.
[    0.143845] Dentry cache hash table entries: 131072 (order: 8, 1048576 bytes)
[    0.146468] Inode-cache hash table entries: 65536 (order: 7, 524288 bytes)
[    0.148539] Mount-cache hash table entries: 2048 (order: 2, 16384 bytes)
[    0.151185] Mountpoint-cache hash table entries: 2048 (order: 2, 16384 bytes)
[    0.153640] Initializing cgroup subsys blkio
[    0.154815] Initializing cgroup subsys memory
[    0.155665] Initializing cgroup subsys devices
[    0.156503] Initializing cgroup subsys freezer
[    0.157331] Initializing cgroup subsys net_cls
[    0.158123] Initializing cgroup subsys perf_event
[    0.158974] Initializing cgroup subsys net_prio
[    0.160851] mce: CPU supports 10 MCE banks
[    0.161654] Last level iTLB entries: 4KB 1024, 2MB 1024, 4MB 1024
[    0.162621] Last level dTLB entries: 4KB 1024, 2MB 1024, 4MB 1024, 1GB 4
[    0.163915] Freeing SMP alternatives memory: 20K (ffffffff8357a000 - ffffffff8357f000)
[    0.169769] ftrace: allocating 21487 entries in 84 pages
[    0.190856] x2apic enabled
[    0.192050] Switched APIC routing to physical x2apic.
[    0.193693] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1
[    0.194830] smpboot: CPU0: Intel(R) Core(TM) i7-4500U CPU @ 1.80GHz (fam: 06, model: 45, stepping: 01)
[    0.196822] Performance Events: 16-deep LBR, Haswell events, Intel PMU driver.
[    0.198884] ... version:                2
[    0.199895] ... bit width:              48
[    0.201014] ... generic registers:      4
[    0.202210] ... value mask:             0000ffffffffffff
[    0.203391] ... max period:             000000007fffffff
[    0.205362] ... fixed-purpose events:   3
[    0.206557] ... event mask:             000000070000000f
[    0.207753] KVM setup paravirtual spinlock
[    0.209291] x86: Booting SMP configuration:
[    0.210479] .... node  #0, CPUs:      #1
[    0.215129] kvm-clock: cpu 1, msr 0:3ffd7041, secondary cpu clock
[    0.238314] KVM setup async PF for cpu 1
[    0.241445]  #2
[    0.241445] kvm-clock: cpu 2, msr 0:3ffd7081, secondary cpu clock
[    0.244638] kvm-stealtime: cpu 1, msr 3fc8e3c0
[    0.264160] KVM setup async PF for cpu 2
[    0.268644]  #3
[    0.268644] kvm-stealtime: cpu 2, msr 3fd0e3c0
[    0.269030] kvm-clock: cpu 3, msr 0:3ffd70c1, secondary cpu clock
[    0.290543] KVM setup async PF for cpu 3
[    0.290555] x86: Booted up 1 node, 4 CPUs
[    0.290559] smpboot: Total of 4 processors activated (19155.64 BogoMIPS)
[    0.298854] kvm-stealtime: cpu 3, msr 3fd8e3c0
[    0.325397] devtmpfs: initialized
[    0.328431] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns
[    0.330253] pinctrl core: initialized pinctrl subsystem
[    0.331358] NET: Registered protocol family 16
[    0.337267] cpuidle: using governor ladder
[    0.340322] cpuidle: using governor menu
[    0.341459] ACPI: bus type PCI registered
[    0.342219] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5
[    0.343311] dca service started, version 1.12.1
[    0.344423] PCI: Using configuration type 1 for base access
[    0.345514] perf_event_intel: PMU erratum BJ122, BV98, HSD29 workaround disabled, HT off
[    0.351911] ACPI: Added _OSI(Module Device)
[    0.352726] ACPI: Added _OSI(Processor Device)
[    0.353565] ACPI: Added _OSI(3.0 _SCP Extensions)
[    0.354406] ACPI: Added _OSI(Processor Aggregator Device)
[    0.357159] ACPI: Interpreter enabled
[    0.358135] ACPI Exception: AE_NOT_FOUND, While evaluating Sleep State [\_S1_] (20150619/hwxface-580)
[    0.359809] ACPI Exception: AE_NOT_FOUND, While evaluating Sleep State [\_S2_] (20150619/hwxface-580)
[    0.361524] ACPI: (supports S0 S3 S4 S5)
[    0.362259] ACPI: Using IOAPIC for interrupt routing
[    0.363151] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug
[    0.366765] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff])
[    0.367755] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI]
[    0.368764] acpi PNP0A03:00: _OSC failed (AE_NOT_FOUND); disabling ASPM
[    0.379351] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge.
[    0.382037] acpiphp: Slot [3] registered
[    0.383017] acpiphp: Slot [4] registered
[    0.383771] acpiphp: Slot [5] registered
[    0.384549] acpiphp: Slot [6] registered
[    0.385337] acpiphp: Slot [7] registered
[    0.386089] acpiphp: Slot [8] registered
[    0.387632] acpiphp: Slot [9] registered
[    0.388487] acpiphp: Slot [10] registered
[    0.389333] acpiphp: Slot [11] registered
[    0.390097] acpiphp: Slot [12] registered
[    0.390874] acpiphp: Slot [13] registered
[    0.391632] acpiphp: Slot [14] registered
[    0.392450] acpiphp: Slot [15] registered
[    0.393283] acpiphp: Slot [16] registered
[    0.394425] acpiphp: Slot [17] registered
[    0.395325] acpiphp: Slot [18] registered
[    0.396248] acpiphp: Slot [19] registered
[    0.397384] acpiphp: Slot [20] registered
[    0.398568] acpiphp: Slot [21] registered
[    0.399416] acpiphp: Slot [22] registered
[    0.400302] acpiphp: Slot [23] registered
[    0.401188] acpiphp: Slot [24] registered
[    0.402055] acpiphp: Slot [25] registered
[    0.402931] acpiphp: Slot [26] registered
[    0.403793] acpiphp: Slot [27] registered
[    0.404644] acpiphp: Slot [28] registered
[    0.405497] acpiphp: Slot [29] registered
[    0.406293] acpiphp: Slot [30] registered
[    0.407149] acpiphp: Slot [31] registered
[    0.408214] PCI host bridge to bus 0000:00
[    0.409257] pci_bus 0000:00: root bus resource [bus 00-ff]
[    0.410121] pci_bus 0000:00: root bus resource [io  0x0000-0x0cf7 window]
[    0.411330] pci_bus 0000:00: root bus resource [io  0x0d00-0xffff window]
[    0.412362] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window]
[    0.414082] pci_bus 0000:00: root bus resource [mem 0x40000000-0xfebfffff window]
[    0.425388] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io  0x01f0-0x01f7]
[    0.426404] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io  0x03f6]
[    0.427815] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io  0x0170-0x0177]
[    0.428856] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io  0x0376]
[    0.430232] pci 0000:00:01.3: quirk: [io  0x0600-0x063f] claimed by PIIX4 ACPI
[    0.431593] pci 0000:00:01.3: quirk: [io  0x0700-0x070f] claimed by PIIX4 SMB
[    0.478116] ACPI: PCI Interrupt Link [LNKA] (IRQs 5 *10 11)
[    0.479465] ACPI: PCI Interrupt Link [LNKB] (IRQs 5 *10 11)
[    0.481567] ACPI: PCI Interrupt Link [LNKC] (IRQs 5 10 *11)
[    0.482833] ACPI: PCI Interrupt Link [LNKD] (IRQs 5 10 *11)
[    0.485239] ACPI: PCI Interrupt Link [LNKS] (IRQs *9)
[    0.486666] ACPI: Enabled 16 GPEs in block 00 to 0F
[    0.488020] vgaarb: setting as boot device: PCI:0000:00:02.0
[    0.488954] vgaarb: device added: PCI:0000:00:02.0,decodes=io+mem,owns=io+mem,locks=none
[    0.490534] vgaarb: loaded
[    0.491175] vgaarb: bridge control possible 0000:00:02.0
[    0.492119] PCI: Using ACPI for IRQ routing
[    0.493302] HPET: 3 timers in total, 0 timers will be used for per-cpu timer
[    0.494335] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0
[    0.495420] hpet0: 3 comparators, 64-bit 100.000000 MHz counter
[    0.502534] clocksource: Switched to clocksource kvm-clock
[    0.547955] pnp: PnP ACPI init
[    0.549541] pnp: PnP ACPI: found 6 devices
[    0.557015] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns
[    0.559194] NET: Registered protocol family 2
[    0.560522] TCP established hash table entries: 8192 (order: 4, 65536 bytes)
[    0.561869] TCP bind hash table entries: 8192 (order: 5, 131072 bytes)
[    0.563141] TCP: Hash tables configured (established 8192 bind 8192)
[    0.564416] UDP hash table entries: 512 (order: 2, 16384 bytes)
[    0.565619] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes)
[    0.566976] NET: Registered protocol family 1
[    0.568054] pci 0000:00:00.0: Limiting direct PCI/PCI transfers
[    0.569304] pci 0000:00:01.0: PIIX3: Enabling Passive Release
[    0.571341] pci 0000:00:01.0: Activating ISA DMA hang workarounds
[    1.130659] futex hash table entries: 1024 (order: 4, 65536 bytes)
[    1.131610] Initialise system trusted keyring
[    1.132439] audit: initializing netlink subsys (disabled)
[    1.133288] audit: type=2000 audit(1447697597.658:1): initialized
[    1.134497] HugeTLB registered 2 MB page size, pre-allocated 0 pages
[    1.137337] VFS: Disk quotas dquot_6.6.0
[    1.138126] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes)
[    1.140380] Key type asymmetric registered
[    1.141144] Asymmetric key parser 'x509' registered
[    1.142792] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 252)
[    1.144367] io scheduler noop registered
[    1.145139] io scheduler deadline registered
[    1.145958] io scheduler cfq registered (default)
[    1.147149] pci_hotplug: PCI Hot Plug PCI Core version: 0.5
[    1.148240] pciehp: PCI Express Hot Plug Controller Driver version: 0.4
[    1.149557] GHES: HEST is not enabled!
[    1.150324] ioatdma: Intel(R) QuickData Technology Driver 4.00
[    1.151455] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
[    1.175444] 00:05: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A
[    1.177669] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12
[    1.179723] serio: i8042 KBD port at 0x60,0x64 irq 1
[    1.180591] serio: i8042 AUX port at 0x60,0x64 irq 12
[    1.181475] rtc_cmos 00:00: RTC can wake from S4
[    1.182837] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input0
[    1.184437] rtc_cmos 00:00: rtc core: registered rtc_cmos as rtc0
[    1.185719] rtc_cmos 00:00: alarms up to one day, 114 bytes nvram, hpet irqs
[    1.188134] NET: Registered protocol family 10
[    1.189157] NET: Registered protocol family 17
[    1.190323] Loading compiled-in X.509 certificates
[    1.191698] Loaded X.509 cert 'Build time autogenerated kernel key: cb4c49a7d0f54acc380d8e47053c385ae2bab225'
[    1.193390] registered taskstats version 1
[    1.200474] rtc_cmos 00:00: setting system clock to 2015-11-16 18:13:17 UTC (1447697597)
[    1.205717] Freeing unused kernel memory: 27080K (ffffffff81b08000 - ffffffff8357a000)
[    1.207012] Write protecting the kernel read-only data: 10240k
[    1.208413] Freeing unused kernel memory: 820K (ffff880001533000 - ffff880001600000)
[    1.210723] Freeing unused kernel memory: 1700K (ffff880001857000 - ffff880001a00000)
[    1.217229] ip_tables: (C) 2000-2006 Netfilter Core Team
[    1.218690] random: systemd urandom read with 1 bits of entropy available
[    1.220326] systemd[1]: systemd 225 running in system mode. (-PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK -SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT -GNUTLS -ACL +XZ -LZ4 +SECCOMP +BLKID -ELFUTILS +KMOD -IDN)
[    1.222727] systemd[1]: Detected virtualization kvm.
[    1.223461] systemd[1]: Detected architecture x86-64.
[    1.224207] systemd[1]: Running in initial RAM disk.
[    1.226648] systemd[1]: No hostname configured.
[    1.227501] systemd[1]: Set hostname to <localhost>.
[    1.228386] systemd[1]: Initializing machine ID from random generator.
[    1.270471] systemd[1]: Reached target Swap.
[    1.272091] systemd[1]: Reached target Timers.
[    1.273611] systemd[1]: Reached target Local File Systems.
[    1.275520] systemd[1]: Created slice -.slice.
[    1.277111] systemd[1]: Listening on Journal Socket.
[    1.278877] systemd[1]: Listening on udev Control Socket.
[    1.280582] systemd[1]: Created slice System Slice.
[    1.282849] systemd[1]: Starting dracut cmdline hook...
[    1.287098] systemd[1]: Starting Apply Kernel Variables...
[    1.290524] systemd[1]: Starting Create list of required static device nodes for the current kernel...
[    1.294395] systemd[1]: Reached target Slices.
[    1.296294] systemd[1]: Listening on Journal Socket (/dev/log).
[    1.298120] systemd[1]: Listening on udev Kernel Socket.
[    1.300238] systemd[1]: Reached target Encrypted Volumes.
[    1.302323] systemd[1]: Listening on Journal Audit Socket.
[    1.305782] systemd[1]: Starting Journal Service...
[    1.308137] systemd[1]: Reached target Sockets.
[    1.309793] systemd[1]: Started Dispatch Password Requests to Console Directory Watch.
[    1.312278] systemd[1]: Reached target Paths.
[    1.314089] systemd[1]: Created slice system-systemd\x2dfsck.slice.
[    1.316770] systemd[1]: Started Apply Kernel Variables.
[    1.318774] audit: type=1130 audit(1447697597.622:2): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=systemd-sysctl comm="systemd" exe="/usr/lib64/systemd/systemd" hostname=? addr=? terminal=? res=success'
[    1.335011] systemd[1]: Started Create list of required static device nodes for the current kernel.
[    1.337926] audit: type=1130 audit(1447697597.641:3): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=kmod-static-nodes comm="systemd" exe="/usr/lib64/systemd/systemd" hostname=? addr=? terminal=? res=success'
[    1.341575] systemd[1]: Started Journal Service.
[    1.343357] audit: type=1130 audit(1447697597.646:4): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=systemd-journald comm="systemd" exe="/usr/lib64/systemd/systemd" hostname=? addr=? terminal=? res=success'
[    1.354367] audit: type=1130 audit(1447697597.657:5): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=systemd-tmpfiles-setup-dev comm="systemd" exe="/usr/lib64/systemd/systemd" hostname=? addr=? terminal=? res=success'
[    1.359144] audit: type=1130 audit(1447697597.662:6): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=dracut-cmdline comm="systemd" exe="/usr/lib64/systemd/systemd" hostname=? addr=? terminal=? res=success'
[    1.394027] audit: type=1130 audit(1447697597.697:7): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=dracut-pre-udev comm="systemd" exe="/usr/lib64/systemd/systemd" hostname=? addr=? terminal=? res=success'
[    1.411554] audit: type=1130 audit(1447697597.715:8): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=systemd-udevd comm="systemd" exe="/usr/lib64/systemd/systemd" hostname=? addr=? terminal=? res=success'
[    1.477264] audit: type=1130 audit(1447697597.780:9): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=dracut-pre-trigger comm="systemd" exe="/usr/lib64/systemd/systemd" hostname=? addr=? terminal=? res=success'
[    1.522799] audit: type=1130 audit(1447697597.824:10): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=systemd-udev-trigger comm="systemd" exe="/usr/lib64/systemd/systemd" hostname=? addr=? terminal=? res=success'
[    1.540562] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input3
[    1.546075] ACPI: Power Button [PWRF]
[    1.585306] SCSI subsystem initialized
[    1.608134] microcode: CPU0 sig=0x40651, pf=0x1, revision=0x1
[    1.610495] microcode: CPU1 sig=0x40651, pf=0x1, revision=0x1
[    1.614108] microcode: CPU2 sig=0x40651, pf=0x1, revision=0x1
[    1.615300] microcode: CPU3 sig=0x40651, pf=0x1, revision=0x1
[    1.619760] input: ImExPS/2 Generic Explorer Mouse as /devices/platform/i8042/serio1/input/input4
[    1.623550] microcode: Microcode Update Driver: v2.00 <tigran@aivazian.fsnet.co.uk>, Peter Oruba
[    1.650185] ACPI: PCI Interrupt Link [LNKC] enabled at IRQ 11
[    1.653479] virtio-pci 0000:00:03.0: virtio_pci: leaving for legacy driver
[    1.666025] mousedev: PS/2 mouse device common for all mice
[    1.668624] AVX2 version of gcm_enc/dec engaged.
[    1.672830] AES CTR mode by8 optimization enabled
[    1.709418] ACPI: PCI Interrupt Link [LNKD] enabled at IRQ 10
[    1.710829] virtio-pci 0000:00:04.0: virtio_pci: leaving for legacy driver
[    1.713372] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0
[    1.723146] scsi host0: ata_piix
[    1.724477] scsi host1: ata_piix
[    1.725797] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc0a0 irq 14
[    1.731990] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc0a8 irq 15
[    1.764773] ACPI: PCI Interrupt Link [LNKA] enabled at IRQ 10
[    1.765802] virtio-pci 0000:00:05.0: virtio_pci: leaving for legacy driver
[    1.779557] 9pnet: Installing 9P2000 support
[    1.796383]  vda: vda1 vda2 vda3 vda4 vda6 vda7 vda9
[    1.886426] ata2.00: ATAPI: QEMU DVD-ROM, 2.3.1, max UDMA/100
[    1.889212] ata2.00: configured for MWDMA2
[    1.897032] scsi 1:0:0:0: CD-ROM            QEMU     QEMU DVD-ROM     2.3. PQ: 0 ANSI: 5
[    1.947472] sr 1:0:0:0: [sr0] scsi3-mmc drive: 4x/4x cd/rw xa/form2 tray
[    1.949007] cdrom: Uniform CD-ROM driver Revision: 3.20
[    2.132586] tsc: Refined TSC clocksource calibration: 2394.432 MHz
[    2.134941] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x2283abd2132, max_idle_ns: 440795306562 ns
[    2.144774] EXT4-fs (vda9): mounted filesystem with ordered data mode. Opts: (null)
[    2.161862] EXT4-fs (vda4): mounted filesystem without journal. Opts: (null)
[    2.374762] systemd-journald[125]: Received SIGTERM from PID 1 (systemd).
[    2.456786] systemd[1]: Successfully loaded SELinux policy in 24.196ms.
[    2.470888] systemd[1]: Relabelled /dev and /run in 7.605ms.
[    2.622718] systemd-journald[483]: File /var/log/journal/ca43056277ff4f91b0b156757a5e7dde/system.journal corrupted or uncleanly shut down, renaming and replacing.
[    2.722571] systemd-journald[483]: Received request to flush runtime journal from PID 1
[    2.859296] 9p: Installing v9fs 9p2000 file system support
[    2.881987] EXT4-fs (vda6): recovery complete
[    2.882935] EXT4-fs (vda6): mounted filesystem with ordered data mode. Opts: commit=600
[    2.911702] FAT-fs (vda1): Volume was not properly unmounted. Some data may be corrupt. Please run fsck.

This is coreos (Linux x86_64 4.2.2-coreos-r1) 18:13:20
SSH host key: SHA256:pAdnh1wxRe/U36DZc+ntIKazgLFb5zpUidepgmtRVHU (DSA)
SSH host key: SHA256:07Qq7/ZvqNg/gOfYfr1yZkevtTxf5hapxAe4l30Y5+M (ED25519)
SSH host key: SHA256:MJXhqutwbhGLfw8JOInaumWZcjPW6hIeEiH/W5Jtf9U (RSA)
eth0: 10.0.2.15 fe80::5054:ff:fe12:3456

coreos login: [   35.074741] random: nonblocking pool is initialized
[   35.796818] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
[   35.807643] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
[   35.820693] nf_conntrack version 0.5.0 (7976 buckets, 31904 max)
[14923.526088] clocksource: timekeeping watchdog: Marking clocksource 'tsc' as unstable because the skew is too large:
[14923.540595] clocksource:                       'kvm-clock' wd_now: d92a7789a91 wd_last: cbae8c9b683 mask: ffffffffffffffff
[14923.546791] clocksource:                       'tsc' cs_now: 1e7d607e4d7c cs_last: 1e7c8c7fc3a0 mask: ffffffffffffffff
[15473.933086] hrtimer: interrupt took 16070686 ns
[174864.401227] systemd-coredump[7733]: Detected coredump of the journal daemon itself, diverted to /var/lib/systemd/coredump/core.systemd-journal.0.c6b342f91b7f4affb5575a2be8f8ba52.483.1447872459000000.xz.
[563425.739858] INFO: rcu_sched detected stalls on CPUs/tasks: { 0 1 3} (detected by 2, t=127543353 jiffies, g=59965, c=59964, q=41)
[563425.749887] Task dump for CPU 0:
[563425.751180] systemd         R  running task        0     1      0 0x00000008
[563425.753328]  ffff88003e2d7ee8 0000000000000018 ffffffff810d5217 00007ffd7c2349b0
[563425.757609]  ffffffffff7ff000 ffff88003e2d7f08 ffffffff810d52ae ffff88003e2d7f18
[563425.763947]  ffffffff810d1371 ffff88003e2d7f48 ffffffff810d22f5 000000005650c367
[563425.766073] Call Trace:
[563425.766942]  [<ffffffff810d5217>] ? __getnstimeofday64+0x37/0xc0
[563425.768280]  [<ffffffff810d52ae>] ? getnstimeofday64+0xe/0x30
[563425.769589]  [<ffffffff810d1371>] ? posix_clock_realtime_get+0x11/0x20
[563425.771815]  [<ffffffff810d22f5>] ? SyS_clock_gettime+0x45/0xa0
[563425.773236]  [<ffffffff8152bbae>] ? entry_SYSCALL_64_fastpath+0x12/0x71
[563425.774617] Task dump for CPU 1:
[563425.775543] locksmithd      R  running task        0  7927      1 0x00000088
[563425.777037]  ffff88003e3cbbd8 ffffffff8152767e ffff88003e379cc0 ffff88003d925640
[563425.779115]  ffff88003d925640 ffff88003e3cc000 ffff88003d925640 ffffc900001e1d00
[563425.781223]  0000000000000000 ffff88003e3cbcb0 ffff88003e3cbbf8 ffffffff81527c87
[563425.783362] Call Trace:
[563425.784220]  [<ffffffff8152767e>] ? __schedule+0x37e/0x950
[563425.785424]  [<ffffffff81527c87>] schedule+0x37/0x80
[563425.786667]  [<ffffffff810df801>] futex_wait_queue_me+0xd1/0x120
[563425.804416]  [<ffffffff810e0be6>] futex_wait+0x256/0x280
[563425.805705]  [<ffffffff810df571>] ? futex_wake+0x81/0x150
[563425.807076]  [<ffffffff810e1b50>] do_futex+0xe0/0xb10
[563425.808305]  [<ffffffff811d872b>] ? evict+0x11b/0x180
[563425.809617]  [<ffffffff810afc01>] ? __raw_callee_save___pv_queued_spin_unlock+0x11/0x20
[563425.811850]  [<ffffffff810afc01>] ? __raw_callee_save___pv_queued_spin_unlock+0x11/0x20
[563425.815171]  [<ffffffff81202cbe>] ? ep_poll+0x23e/0x3b0
[563425.816475]  [<ffffffff811052e1>] ? __audit_syscall_exit+0x221/0x2b0
[563425.819765]  [<ffffffff810554de>] ? kvm_clock_get_cycles+0x1e/0x20
[563425.821680]  [<ffffffff81021e93>] ? syscall_trace_leave+0x93/0xf0
[563425.823422]  [<ffffffff810d2313>] ? SyS_clock_gettime+0x63/0xa0
[563425.824809]  [<ffffffff8152bd61>] ? int_very_careful+0x38/0x41
[563425.826134] Task dump for CPU 3:
[563425.827189] swapper/3       R  running task        0     0      1 0x00000000
[563425.828622]  0000000000000000 ffffffffffffff02 ffffffff81055786 0000000000000010
[563425.830897]  0000000000000246 ffff88003e343e88 0000000000000018 7fffffffffffffff
[563425.839629]  ffff88003e343ea8 ffffffff8101d4ae ffffffff81afbcf0 ffff88003e344000
[563425.842463] Call Trace:
[563425.843509]  [<ffffffff81055786>] ? native_safe_halt+0x6/0x10
[563425.845202]  [<ffffffff8101d4ae>] ? default_idle+0x1e/0xa0
[563425.846699]  [<ffffffff8101dc2f>] ? arch_cpu_idle+0xf/0x20
[563425.847957]  [<ffffffff810a90d2>] ? default_idle_call+0x32/0x40
[563425.850852]  [<ffffffff810a93fa>] ? cpu_startup_entry+0x2ba/0x320
[563425.852350]  [<ffffffff810468c4>] ? start_secondary+0x174/0x1a0
[563425.854293] rcu_sched kthread starved for 127543353 jiffies! g59965 c59964 f0x0
[563435.210703] systemd-journald[20089]: File /var/log/journal/ca43056277ff4f91b0b156757a5e7dde/system.journal corrupted or uncleanly shut down, renaming and replacing.
[563436.596270] systemd-coredump[20070]: Detected coredump of the journal daemon itself, diverted to /var/lib/systemd/coredump/core.systemd-journal.0.c6b342f91b7f4affb5575a2be8f8ba52.7754.1448261032000000.xz.
[603007.781224] systemd-journald[20210]: File /var/log/journal/ca43056277ff4f91b0b156757a5e7dde/system.journal corrupted or uncleanly shut down, renaming and replacing.
[603007.868252] systemd-coredump[20204]: Detected coredump of the journal daemon itself, diverted to /var/lib/systemd/coredump/core.systemd-journal.0.c6b342f91b7f4affb5575a2be8f8ba52.20089.1448300604000000.xz.
[605501.087344] systemd-journald[20276]: File /var/log/journal/ca43056277ff4f91b0b156757a5e7dde/system.journal corrupted or uncleanly shut down, renaming and replacing.
[605501.879406] systemd-coredump[20267]: Detected coredump of the journal daemon itself, diverted to /var/lib/systemd/coredump/core.systemd-journal.0.c6b342f91b7f4affb5575a2be8f8ba52.20210.1448303097000000.xz.
mischief commented 8 years ago

Have you been suspending the host system? Vito and i noticed oddities in the vm when we suspended our gentoo hosts with a coreos vm in qemu running. On Nov 24, 2015 1:54 PM, "Jonathan Boulle" notifications@github.com wrote:

Noticed on qemu-x86_64, CoreOS 845.0.0. As far as I'm aware the system was basically idling at the time this happened, and it's still up (8 days total)

Booting `CoreOS default'

Loading (hd0,gpt4)/boot/vmlinuz Booting CoreOS! [ 0.000000] Initializing cgroup subsys cpuset [ 0.000000] Initializing cgroup subsys cpu [ 0.000000] Initializing cgroup subsys cpuacct [ 0.000000] Linux version 4.2.2-coreos-r1 (buildbot@ip-10-204-3-57) (gcc version 4.9.3 (Gentoo Hardened 4.9.3 p1.2, pie-0.6.3) ) #2 SMP Sat Oct 24 19:42:01 UTC 2015 [ 0.000000] Command line: BOOT_IMAGE=/boot/vmlinuz console=ttyS0,115200n8 console=tty0 root=LABEL=ROOT mount.usr=PARTUUID=e03dd35c-7c2d-4a47-b3fe-27f15780a57c

[ 0.000000] x86/fpu: Supporting XSAVE feature 0x01: 'x87 floating point registers' [ 0.000000] x86/fpu: Supporting XSAVE feature 0x02: 'SSE registers' [ 0.000000] x86/fpu: Supporting XSAVE feature 0x04: 'AVX registers' [ 0.000000] x86/fpu: Enabled xstate features 0x7, context size is 0x340 bytes, using 'standard' format. [ 0.000000] x86/fpu: Using 'eager' FPU context switches. [ 0.000000] e820: BIOS-provided physical RAM map: [ 0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable [ 0.000000] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved [ 0.000000] BIOS-e820: [mem 0x0000000000100000-0x000000003ffdffff] usable [ 0.000000] BIOS-e820: [mem 0x000000003ffe0000-0x000000003fffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000feffc000-0x00000000feffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved [ 0.000000] NX (Execute Disable) protection: active [ 0.000000] SMBIOS 2.8 present. [ 0.000000] Hypervisor detected: KVM [ 0.000000] e820: last_pfn = 0x3ffe0 max_arch_pfn = 0x400000000 [ 0.000000] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WC UC- WT [ 0.000000] Using GB pages for direct mapping [ 0.000000] init_memory_mapping: [mem 0x00000000-0x000fffff] [ 0.000000] init_memory_mapping: [mem 0x3fc00000-0x3fdfffff] [ 0.000000] init_memory_mapping: [mem 0x20000000-0x3fbfffff] [ 0.000000] init_memory_mapping: [mem 0x00100000-0x1fffffff] [ 0.000000] init_memory_mapping: [mem 0x3fe00000-0x3ffdffff] [ 0.000000] ACPI: Early table checksum verification disabled [ 0.000000] ACPI: RSDP 0x00000000000F62C0 000014 (v00 BOCHS ) [ 0.000000] ACPI: RSDT 0x000000003FFE178C 000034 (v01 BOCHS BXPCRSDT 00000001 BXPC 00000001) [ 0.000000] ACPI: FACP 0x000000003FFE0BDA 000074 (v01 BOCHS BXPCFACP 00000001 BXPC 00000001) [ 0.000000] ACPI: DSDT 0x000000003FFE0040 000B9A (v01 BOCHS BXPCDSDT 00000001 BXPC 00000001) [ 0.000000] ACPI: FACS 0x000000003FFE0000 000040 [ 0.000000] ACPI: SSDT 0x000000003FFE0C4E 000A76 (v01 BOCHS BXPCSSDT 00000001 BXPC 00000001) [ 0.000000] ACPI: APIC 0x000000003FFE16C4 000090 (v01 BOCHS BXPCAPIC 00000001 BXPC 00000001) [ 0.000000] ACPI: HPET 0x000000003FFE1754 000038 (v01 BOCHS BXPCHPET 00000001 BXPC 00000001) [ 0.000000] No NUMA configuration found [ 0.000000] Faking a node at [mem 0x0000000000000000-0x000000003ffdffff] [ 0.000000] NODE_DATA(0) allocated [mem 0x3ffd9000-0x3ffdffff] [ 0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d00 [ 0.000000] kvm-clock: cpu 0, msr 0:3ffd7001, primary cpu clock [ 0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns [ 0.000000] Zone ranges: [ 0.000000] DMA [mem 0x0000000000001000-0x0000000000ffffff] [ 0.000000] DMA32 [mem 0x0000000001000000-0x000000003ffdffff] [ 0.000000] Normal empty [ 0.000000] Movable zone start for each node [ 0.000000] Early memory node ranges [ 0.000000] node 0: [mem 0x0000000000001000-0x000000000009efff] [ 0.000000] node 0: [mem 0x0000000000100000-0x000000003ffdffff] [ 0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x000000003ffdffff] [ 0.000000] ACPI: PM-Timer IO Port: 0x608 [ 0.000000] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1]) [ 0.000000] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23 [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level) [ 0.000000] Using ACPI (MADT) for SMP configuration information [ 0.000000] ACPI: HPET id: 0x8086a201 base: 0xfed00000 [ 0.000000] smpboot: Allowing 4 CPUs, 0 hotplug CPUs [ 0.000000] PM: Registered nosave memory: [mem 0x00000000-0x00000fff] [ 0.000000] PM: Registered nosave memory: [mem 0x0009f000-0x0009ffff] [ 0.000000] PM: Registered nosave memory: [mem 0x000a0000-0x000effff] [ 0.000000] PM: Registered nosave memory: [mem 0x000f0000-0x000fffff] [ 0.000000] e820: [mem 0x40000000-0xfeffbfff] available for PCI devices [ 0.000000] Booting paravirtualized kernel on KVM [ 0.000000] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns [ 0.000000] setup_percpu: NR_CPUS:128 nr_cpumask_bits:128 nr_cpu_ids:4 nr_node_ids:1 [ 0.000000] PERCPU: Embedded 32 pages/cpu @ffff88003fc00000 s91480 r8192 d31400 u524288 [ 0.000000] KVM setup async PF for cpu 0 [ 0.000000] kvm-stealtime: cpu 0, msr 3fc0e3c0 [ 0.000000] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes) [ 0.000000] Built 1 zonelists in Node order, mobility grouping on. Total pages: 257896 [ 0.000000] Policy zone: DMA32 [ 0.000000] Kernel command line: rootflags=rw mount.usrflags=ro BOOT_IMAGE=/boot/vmlinuz console=ttyS0,115200n8 console=tty0 root=LABEL=ROOT mount.usr=PARTUUID=e03dd35c-7c2d-4a47-b3fe-27f15780a57c [ 0.000000] PID hash table entries: 4096 (order: 3, 32768 bytes) [ 0.000000] Memory: 991412K/1048056K available (5314K kernel code, 1050K rwdata, 2396K rodata, 27080K init, 940K bss, 56644K reserved, 0K cma-reserved) [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 [ 0.000000] Hierarchical RCU implementation. [ 0.000000] Build-time adjustment of leaf fanout to 64. [ 0.000000] RCU restricting CPUs from NR_CPUS=128 to nr_cpu_ids=4. [ 0.000000] RCU: Adjusting geometry for rcu_fanout_leaf=64, nr_cpu_ids=4 [ 0.000000] NR_IRQS:8448 nr_irqs:456 16 [ 0.000000] Console: colour VGA+ 80x25 [ 0.000000] console [tty0] enabled [ 0.000000] console [ttyS0] enabled [ 0.000000] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns [ 0.000000] tsc: Detected 2394.456 MHz processor [ 0.136603] Calibrating delay loop (skipped) preset value.. 4788.91 BogoMIPS (lpj=2394456) [ 0.138215] pid_max: default: 32768 minimum: 301 [ 0.139072] ACPI: Core revision 20150619 [ 0.141153] ACPI: All ACPI Tables successfully acquired [ 0.142217] Security Framework initialized [ 0.143015] SELinux: Initializing. [ 0.143845] Dentry cache hash table entries: 131072 (order: 8, 1048576 bytes) [ 0.146468] Inode-cache hash table entries: 65536 (order: 7, 524288 bytes) [ 0.148539] Mount-cache hash table entries: 2048 (order: 2, 16384 bytes) [ 0.151185] Mountpoint-cache hash table entries: 2048 (order: 2, 16384 bytes) [ 0.153640] Initializing cgroup subsys blkio [ 0.154815] Initializing cgroup subsys memory [ 0.155665] Initializing cgroup subsys devices [ 0.156503] Initializing cgroup subsys freezer [ 0.157331] Initializing cgroup subsys net_cls [ 0.158123] Initializing cgroup subsys perf_event [ 0.158974] Initializing cgroup subsys net_prio [ 0.160851] mce: CPU supports 10 MCE banks [ 0.161654] Last level iTLB entries: 4KB 1024, 2MB 1024, 4MB 1024 [ 0.162621] Last level dTLB entries: 4KB 1024, 2MB 1024, 4MB 1024, 1GB 4 [ 0.163915] Freeing SMP alternatives memory: 20K (ffffffff8357a000 - ffffffff8357f000) [ 0.169769] ftrace: allocating 21487 entries in 84 pages [ 0.190856] x2apic enabled [ 0.192050] Switched APIC routing to physical x2apic. [ 0.193693] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.194830] smpboot: CPU0: Intel(R) Core(TM) i7-4500U CPU @ 1.80GHz (fam: 06, model: 45, stepping: 01) [ 0.196822] Performance Events: 16-deep LBR, Haswell events, Intel PMU driver. [ 0.198884] ... version: 2 [ 0.199895] ... bit width: 48 [ 0.201014] ... generic registers: 4 [ 0.202210] ... value mask: 0000ffffffffffff [ 0.203391] ... max period: 000000007fffffff [ 0.205362] ... fixed-purpose events: 3 [ 0.206557] ... event mask: 000000070000000f [ 0.207753] KVM setup paravirtual spinlock [ 0.209291] x86: Booting SMP configuration: [ 0.210479] .... node #0, CPUs: #1 [ 0.215129] kvm-clock: cpu 1, msr 0:3ffd7041, secondary cpu clock [ 0.238314] KVM setup async PF for cpu 1 [ 0.241445] #2 [ 0.241445] kvm-clock: cpu 2, msr 0:3ffd7081, secondary cpu clock [ 0.244638] kvm-stealtime: cpu 1, msr 3fc8e3c0 [ 0.264160] KVM setup async PF for cpu 2 [ 0.268644] #3 [ 0.268644] kvm-stealtime: cpu 2, msr 3fd0e3c0 [ 0.269030] kvm-clock: cpu 3, msr 0:3ffd70c1, secondary cpu clock [ 0.290543] KVM setup async PF for cpu 3 [ 0.290555] x86: Booted up 1 node, 4 CPUs [ 0.290559] smpboot: Total of 4 processors activated (19155.64 BogoMIPS) [ 0.298854] kvm-stealtime: cpu 3, msr 3fd8e3c0 [ 0.325397] devtmpfs: initialized [ 0.328431] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.330253] pinctrl core: initialized pinctrl subsystem [ 0.331358] NET: Registered protocol family 16 [ 0.337267] cpuidle: using governor ladder [ 0.340322] cpuidle: using governor menu [ 0.341459] ACPI: bus type PCI registered [ 0.342219] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.343311] dca service started, version 1.12.1 [ 0.344423] PCI: Using configuration type 1 for base access [ 0.345514] perf_event_intel: PMU erratum BJ122, BV98, HSD29 workaround disabled, HT off [ 0.351911] ACPI: Added _OSI(Module Device) [ 0.352726] ACPI: Added _OSI(Processor Device) [ 0.353565] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.354406] ACPI: Added _OSI(Processor Aggregator Device) [ 0.357159] ACPI: Interpreter enabled [ 0.358135] ACPI Exception: AE_NOT_FOUND, While evaluating Sleep State S1 [ 0.359809] ACPI Exception: AE_NOT_FOUND, While evaluating Sleep State S2 [ 0.361524] ACPI: (supports S0 S3 S4 S5) [ 0.362259] ACPI: Using IOAPIC for interrupt routing [ 0.363151] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.366765] ACPI: PCI Root Bridge [PCI0](domain 0000 [bus 00-ff]) [ 0.367755] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI] [ 0.368764] acpi PNP0A03:00: _OSC failed (AE_NOT_FOUND); disabling ASPM [ 0.379351] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.382037] acpiphp: Slot [3] registered [ 0.383017] acpiphp: Slot [4] registered [ 0.383771] acpiphp: Slot [5] registered [ 0.384549] acpiphp: Slot [6] registered [ 0.385337] acpiphp: Slot [7] registered [ 0.386089] acpiphp: Slot [8] registered [ 0.387632] acpiphp: Slot [9] registered [ 0.388487] acpiphp: Slot [10] registered [ 0.389333] acpiphp: Slot [11] registered [ 0.390097] acpiphp: Slot [12] registered [ 0.390874] acpiphp: Slot [13] registered [ 0.391632] acpiphp: Slot [14] registered [ 0.392450] acpiphp: Slot [15] registered [ 0.393283] acpiphp: Slot [16] registered [ 0.394425] acpiphp: Slot [17] registered [ 0.395325] acpiphp: Slot [18] registered [ 0.396248] acpiphp: Slot [19] registered [ 0.397384] acpiphp: Slot [20] registered [ 0.398568] acpiphp: Slot [21] registered [ 0.399416] acpiphp: Slot [22] registered [ 0.400302] acpiphp: Slot [23] registered [ 0.401188] acpiphp: Slot [24] registered [ 0.402055] acpiphp: Slot [25] registered [ 0.402931] acpiphp: Slot [26] registered [ 0.403793] acpiphp: Slot [27] registered [ 0.404644] acpiphp: Slot [28] registered [ 0.405497] acpiphp: Slot [29] registered [ 0.406293] acpiphp: Slot [30] registered [ 0.407149] acpiphp: Slot [31] registered [ 0.408214] PCI host bridge to bus 0000:00 [ 0.409257] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.410121] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.411330] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.412362] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.414082] pci_bus 0000:00: root bus resource [mem 0x40000000-0xfebfffff window] [ 0.425388] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.426404] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.427815] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.428856] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.430232] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.431593] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.478116] ACPI: PCI Interrupt Link [LNKA](IRQs 5 10 11) [ 0.479465] ACPI: PCI Interrupt Link [LNKB](IRQs 5 10 11) [ 0.481567] ACPI: PCI Interrupt Link [LNKC](IRQs 5 10 11) [ 0.482833] ACPI: PCI Interrupt Link [LNKD](IRQs 5 10 11) [ 0.485239] ACPI: PCI Interrupt Link [LNKS](IRQs *9) [ 0.486666] ACPI: Enabled 16 GPEs in block 00 to 0F [ 0.488020] vgaarb: setting as boot device: PCI:0000:00:02.0 [ 0.488954] vgaarb: device added: PCI:0000:00:02.0,decodes=io+mem,owns=io+mem,locks=none [ 0.490534] vgaarb: loaded [ 0.491175] vgaarb: bridge control possible 0000:00:02.0 [ 0.492119] PCI: Using ACPI for IRQ routing [ 0.493302] HPET: 3 timers in total, 0 timers will be used for per-cpu timer [ 0.494335] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.495420] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.502534] clocksource: Switched to clocksource kvm-clock [ 0.547955] pnp: PnP ACPI init [ 0.549541] pnp: PnP ACPI: found 6 devices [ 0.557015] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.559194] NET: Registered protocol family 2 [ 0.560522] TCP established hash table entries: 8192 (order: 4, 65536 bytes) [ 0.561869] TCP bind hash table entries: 8192 (order: 5, 131072 bytes) [ 0.563141] TCP: Hash tables configured (established 8192 bind 8192) [ 0.564416] UDP hash table entries: 512 (order: 2, 16384 bytes) [ 0.565619] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes) [ 0.566976] NET: Registered protocol family 1 [ 0.568054] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 0.569304] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 0.571341] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 1.130659] futex hash table entries: 1024 (order: 4, 65536 bytes) [ 1.131610] Initialise system trusted keyring [ 1.132439] audit: initializing netlink subsys (disabled) [ 1.133288] audit: type=2000 audit(1447697597.658:1): initialized [ 1.134497] HugeTLB registered 2 MB page size, pre-allocated 0 pages [ 1.137337] VFS: Disk quotas dquot_6.6.0 [ 1.138126] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 1.140380] Key type asymmetric registered [ 1.141144] Asymmetric key parser 'x509' registered [ 1.142792] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 252) [ 1.144367] io scheduler noop registered [ 1.145139] io scheduler deadline registered [ 1.145958] io scheduler cfq registered (default) [ 1.147149] pci_hotplug: PCI Hot Plug PCI Core version: 0.5 [ 1.148240] pciehp: PCI Express Hot Plug Controller Driver version: 0.4 [ 1.149557] GHES: HEST is not enabled! [ 1.150324] ioatdma: Intel(R) QuickData Technology Driver 4.00 [ 1.151455] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 1.175444] 00:05: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 1.177669] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 1.179723] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 1.180591] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 1.181475] rtc_cmos 00:00: RTC can wake from S4 [ 1.182837] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input0 [ 1.184437] rtc_cmos 00:00: rtc core: registered rtc_cmos as rtc0 [ 1.185719] rtc_cmos 00:00: alarms up to one day, 114 bytes nvram, hpet irqs [ 1.188134] NET: Registered protocol family 10 [ 1.189157] NET: Registered protocol family 17 [ 1.190323] Loading compiled-in X.509 certificates [ 1.191698] Loaded X.509 cert 'Build time autogenerated kernel key: cb4c49a7d0f54acc380d8e47053c385ae2bab225' [ 1.193390] registered taskstats version 1 [ 1.200474] rtc_cmos 00:00: setting system clock to 2015-11-16 18:13:17 UTC (1447697597) [ 1.205717] Freeing unused kernel memory: 27080K (ffffffff81b08000 - ffffffff8357a000) [ 1.207012] Write protecting the kernel read-only data: 10240k [ 1.208413] Freeing unused kernel memory: 820K (ffff880001533000 - ffff880001600000) [ 1.210723] Freeing unused kernel memory: 1700K (ffff880001857000 - ffff880001a00000) [ 1.217229] ip_tables: (C) 2000-2006 Netfilter Core Team [ 1.218690] random: systemd urandom read with 1 bits of entropy available [ 1.220326] systemd[1]: systemd 225 running in system mode. (-PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK -SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT -GNUTLS -ACL +XZ -LZ4 +SECCOMP +BLKID -ELFUTILS +KMOD -IDN) [ 1.222727] systemd[1]: Detected virtualization kvm. [ 1.223461] systemd[1]: Detected architecture x86-64. [ 1.224207] systemd[1]: Running in initial RAM disk. [ 1.226648] systemd[1]: No hostname configured. [ 1.227501] systemd[1]: Set hostname to . [ 1.228386] systemd[1]: Initializing machine ID from random generator. [ 1.270471] systemd[1]: Reached target Swap. [ 1.272091] systemd[1]: Reached target Timers. [ 1.273611] systemd[1]: Reached target Local File Systems. [ 1.275520] systemd[1]: Created slice -.slice. [ 1.277111] systemd[1]: Listening on Journal Socket. [ 1.278877] systemd[1]: Listening on udev Control Socket. [ 1.280582] systemd[1]: Created slice System Slice. [ 1.282849] systemd[1]: Starting dracut cmdline hook... [ 1.287098] systemd[1]: Starting Apply Kernel Variables... [ 1.290524] systemd[1]: Starting Create list of required static device nodes for the current kernel... [ 1.294395] systemd[1]: Reached target Slices. [ 1.296294] systemd[1]: Listening on Journal Socket (/dev/log). [ 1.298120] systemd[1]: Listening on udev Kernel Socket. [ 1.300238] systemd[1]: Reached target Encrypted Volumes. [ 1.302323] systemd[1]: Listening on Journal Audit Socket. [ 1.305782] systemd[1]: Starting Journal Service... [ 1.308137] systemd[1]: Reached target Sockets. [ 1.309793] systemd[1]: Started Dispatch Password Requests to Console Directory Watch. [ 1.312278] systemd[1]: Reached target Paths. [ 1.314089] systemd[1]: Created slice system-systemd\x2dfsck.slice. [ 1.316770] systemd[1]: Started Apply Kernel Variables. [ 1.318774] audit: type=1130 audit(1447697597.622:2): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=systemd-sysctl comm="systemd" exe="/usr/lib64/systemd/systemd" hostname=? addr=? terminal=? res=success' [ 1.335011] systemd[1]: Started Create list of required static device nodes for the current kernel. [ 1.337926] audit: type=1130 audit(1447697597.641:3): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=kmod-static-nodes comm="systemd" exe="/usr/lib64/systemd/systemd" hostname=? addr=? terminal=? res=success' [ 1.341575] systemd[1]: Started Journal Service. [ 1.343357] audit: type=1130 audit(1447697597.646:4): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=systemd-journald comm="systemd" exe="/usr/lib64/systemd/systemd" hostname=? addr=? terminal=? res=success' [ 1.354367] audit: type=1130 audit(1447697597.657:5): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=systemd-tmpfiles-setup-dev comm="systemd" exe="/usr/lib64/systemd/systemd" hostname=? addr=? terminal=? res=success' [ 1.359144] audit: type=1130 audit(1447697597.662:6): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=dracut-cmdline comm="systemd" exe="/usr/lib64/systemd/systemd" hostname=? addr=? terminal=? res=success' [ 1.394027] audit: type=1130 audit(1447697597.697:7): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=dracut-pre-udev comm="systemd" exe="/usr/lib64/systemd/systemd" hostname=? addr=? terminal=? res=success' [ 1.411554] audit: type=1130 audit(1447697597.715:8): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=systemd-udevd comm="systemd" exe="/usr/lib64/systemd/systemd" hostname=? addr=? terminal=? res=success' [ 1.477264] audit: type=1130 audit(1447697597.780:9): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=dracut-pre-trigger comm="systemd" exe="/usr/lib64/systemd/systemd" hostname=? addr=? terminal=? res=success' [ 1.522799] audit: type=1130 audit(1447697597.824:10): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=systemd-udev-trigger comm="systemd" exe="/usr/lib64/systemd/systemd" hostname=? addr=? terminal=? res=success' [ 1.540562] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input3 [ 1.546075] ACPI: Power Button [PWRF] [ 1.585306] SCSI subsystem initialized [ 1.608134] microcode: CPU0 sig=0x40651, pf=0x1, revision=0x1 [ 1.610495] microcode: CPU1 sig=0x40651, pf=0x1, revision=0x1 [ 1.614108] microcode: CPU2 sig=0x40651, pf=0x1, revision=0x1 [ 1.615300] microcode: CPU3 sig=0x40651, pf=0x1, revision=0x1 [ 1.619760] input: ImExPS/2 Generic Explorer Mouse as /devices/platform/i8042/serio1/input/input4 [ 1.623550] microcode: Microcode Update Driver: v2.00 tigran@aivazian.fsnet.co.uk, Peter Oruba [ 1.650185] ACPI: PCI Interrupt Link [LNKC] enabled at IRQ 11 [ 1.653479] virtio-pci 0000:00:03.0: virtio_pci: leaving for legacy driver [ 1.666025] mousedev: PS/2 mouse device common for all mice [ 1.668624] AVX2 version of gcm_enc/dec engaged. [ 1.672830] AES CTR mode by8 optimization enabled [ 1.709418] ACPI: PCI Interrupt Link [LNKD] enabled at IRQ 10 [ 1.710829] virtio-pci 0000:00:04.0: virtio_pci: leaving for legacy driver [ 1.713372] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 1.723146] scsi host0: ata_piix [ 1.724477] scsi host1: ata_piix [ 1.725797] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc0a0 irq 14 [ 1.731990] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc0a8 irq 15 [ 1.764773] ACPI: PCI Interrupt Link [LNKA] enabled at IRQ 10 [ 1.765802] virtio-pci 0000:00:05.0: virtio_pci: leaving for legacy driver [ 1.779557] 9pnet: Installing 9P2000 support [ 1.796383] vda: vda1 vda2 vda3 vda4 vda6 vda7 vda9 [ 1.886426] ata2.00: ATAPI: QEMU DVD-ROM, 2.3.1, max UDMA/100 [ 1.889212] ata2.00: configured for MWDMA2 [ 1.897032] scsi 1:0:0:0: CD-ROM QEMU QEMU DVD-ROM 2.3. PQ: 0 ANSI: 5 [ 1.947472] sr 1:0:0:0: [sr0] scsi3-mmc drive: 4x/4x cd/rw xa/form2 tray [ 1.949007] cdrom: Uniform CD-ROM driver Revision: 3.20 [ 2.132586] tsc: Refined TSC clocksource calibration: 2394.432 MHz [ 2.134941] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x2283abd2132, max_idle_ns: 440795306562 ns [ 2.144774] EXT4-fs (vda9): mounted filesystem with ordered data mode. Opts: (null) [ 2.161862] EXT4-fs (vda4): mounted filesystem without journal. Opts: (null) [ 2.374762] systemd-journald[125]: Received SIGTERM from PID 1 (systemd). [ 2.456786] systemd[1]: Successfully loaded SELinux policy in 24.196ms. [ 2.470888] systemd[1]: Relabelled /dev and /run in 7.605ms. [ 2.622718] systemd-journald[483]: File /var/log/journal/ca43056277ff4f91b0b156757a5e7dde/system.journal corrupted or uncleanly shut down, renaming and replacing. [ 2.722571] systemd-journald[483]: Received request to flush runtime journal from PID 1 [ 2.859296] 9p: Installing v9fs 9p2000 file system support [ 2.881987] EXT4-fs (vda6): recovery complete [ 2.882935] EXT4-fs (vda6): mounted filesystem with ordered data mode. Opts: commit=600 [ 2.911702] FAT-fs (vda1): Volume was not properly unmounted. Some data may be corrupt. Please run fsck.

This is coreos (Linux x86_64 4.2.2-coreos-r1) 18:13:20 SSH host key: SHA256:pAdnh1wxRe/U36DZc+ntIKazgLFb5zpUidepgmtRVHU (DSA) SSH host key: SHA256:07Qq7/ZvqNg/gOfYfr1yZkevtTxf5hapxAe4l30Y5+M (ED25519) SSH host key: SHA256:MJXhqutwbhGLfw8JOInaumWZcjPW6hIeEiH/W5Jtf9U (RSA) eth0: 10.0.2.15 fe80::5054:ff:fe12:3456

coreos login: [ 35.074741] random: nonblocking pool is initialized [ 35.796818] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready [ 35.807643] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready [ 35.820693] nf_conntrack version 0.5.0 (7976 buckets, 31904 max) [14923.526088] clocksource: timekeeping watchdog: Marking clocksource 'tsc' as unstable because the skew is too large: [14923.540595] clocksource: 'kvm-clock' wd_now: d92a7789a91 wd_last: cbae8c9b683 mask: ffffffffffffffff [14923.546791] clocksource: 'tsc' cs_now: 1e7d607e4d7c cs_last: 1e7c8c7fc3a0 mask: ffffffffffffffff [15473.933086] hrtimer: interrupt took 16070686 ns [174864.401227] systemd-coredump[7733]: Detected coredump of the journal daemon itself, diverted to /var/lib/systemd/coredump/core.systemd-journal.0.c6b342f91b7f4affb5575a2be8f8ba52.483.1447872459000000.xz. [563425.739858] INFO: rcu_sched detected stalls on CPUs/tasks: { 0 1 3} (detected by 2, t=127543353 jiffies, g=59965, c=59964, q=41) [563425.749887] Task dump for CPU 0: [563425.751180] systemd R running task 0 1 0 0x00000008 [563425.753328] ffff88003e2d7ee8 0000000000000018 ffffffff810d5217 00007ffd7c2349b0 [563425.757609] ffffffffff7ff000 ffff88003e2d7f08 ffffffff810d52ae ffff88003e2d7f18 [563425.763947] ffffffff810d1371 ffff88003e2d7f48 ffffffff810d22f5 000000005650c367 [563425.766073] Call Trace: [563425.766942] [] ? getnstimeofday64+0x37/0xc0 [563425.768280] [] ? getnstimeofday64+0xe/0x30 [563425.769589] [] ? posix_clock_realtime_get+0x11/0x20 [563425.771815] [] ? SyS_clock_gettime+0x45/0xa0 [563425.773236] [] ? entry_SYSCALL_64_fastpath+0x12/0x71 [563425.774617] Task dump for CPU 1: [563425.775543] locksmithd R running task 0 7927 1 0x00000088 [563425.777037] ffff88003e3cbbd8 ffffffff8152767e ffff88003e379cc0 ffff88003d925640 [563425.779115] ffff88003d925640 ffff88003e3cc000 ffff88003d925640 ffffc900001e1d00 [563425.781223] 0000000000000000 ffff88003e3cbcb0 ffff88003e3cbbf8 ffffffff81527c87 [563425.783362] Call Trace: [563425.784220] [] ? schedule+0x37e/0x950 [563425.785424] [] schedule+0x37/0x80 [563425.786667] [] futex_wait_queue_me+0xd1/0x120 [563425.804416] [] futex_wait+0x256/0x280 [563425.805705] [] ? futex_wake+0x81/0x150 [563425.807076] [] do_futex+0xe0/0xb10 [563425.808305] [] ? evict+0x11b/0x180 [563425.809617] [] ? raw_callee_save___pv_queued_spin_unlock+0x11/0x20 [563425.811850] [] ? raw_callee_save_pv_queued_spin_unlock+0x11/0x20 [563425.815171] [] ? ep_poll+0x23e/0x3b0 [563425.816475] [] ? audit_syscall_exit+0x221/0x2b0 [563425.819765] [] ? kvm_clock_get_cycles+0x1e/0x20 [563425.821680] [] ? syscall_trace_leave+0x93/0xf0 [563425.823422] [] ? SyS_clock_gettime+0x63/0xa0 [563425.824809] [] ? int_very_careful+0x38/0x41 [563425.826134] Task dump for CPU 3: [563425.827189] swapper/3 R running task 0 0 1 0x00000000 [563425.828622] 0000000000000000 ffffffffffffff02 ffffffff81055786 0000000000000010 [563425.830897] 0000000000000246 ffff88003e343e88 0000000000000018 7fffffffffffffff [563425.839629] ffff88003e343ea8 ffffffff8101d4ae ffffffff81afbcf0 ffff88003e344000 [563425.842463] Call Trace: [563425.843509] [] ? native_safe_halt+0x6/0x10 [563425.845202] [] ? default_idle+0x1e/0xa0 [563425.846699] [] ? arch_cpu_idle+0xf/0x20 [563425.847957] [] ? default_idle_call+0x32/0x40 [563425.850852] [] ? cpu_startup_entry+0x2ba/0x320 [563425.852350] [] ? start_secondary+0x174/0x1a0 [563425.854293] rcu_sched kthread starved for 127543353 jiffies! g59965 c59964 f0x0 [563435.210703] systemd-journald[20089]: File /var/log/journal/ca43056277ff4f91b0b156757a5e7dde/system.journal corrupted or uncleanly shut down, renaming and replacing. [563436.596270] systemd-coredump[20070]: Detected coredump of the journal daemon itself, diverted to /var/lib/systemd/coredump/core.systemd-journal.0.c6b342f91b7f4affb5575a2be8f8ba52.7754.1448261032000000.xz. [603007.781224] systemd-journald[20210]: File /var/log/journal/ca43056277ff4f91b0b156757a5e7dde/system.journal corrupted or uncleanly shut down, renaming and replacing. [603007.868252] systemd-coredump[20204]: Detected coredump of the journal daemon itself, diverted to /var/lib/systemd/coredump/core.systemd-journal.0.c6b342f91b7f4affb5575a2be8f8ba52.20089.1448300604000000.xz. [605501.087344] systemd-journald[20276]: File /var/log/journal/ca43056277ff4f91b0b156757a5e7dde/system.journal corrupted or uncleanly shut down, renaming and replacing. [605501.879406] systemd-coredump[20267]: Detected coredump of the journal daemon itself, diverted to /var/lib/systemd/coredump/core.systemd-journal.0.c6b342f91b7f4affb5575a2be8f8ba52.20210.1448303097000000.xz.

— Reply to this email directly or view it on GitHub https://github.com/coreos/bugs/issues/1001.

jonboulle commented 8 years ago

Yep. Host is Fedora x86-64 (currently 4.2.5 kernel)

On Tue, Nov 24, 2015 at 5:05 PM, Nick Owens notifications@github.com wrote:

Have you been suspending the host system? Vito and i noticed oddities in the vm when we suspended our gentoo hosts with a coreos vm in qemu running. On Nov 24, 2015 1:54 PM, "Jonathan Boulle" notifications@github.com wrote:

Noticed on qemu-x86_64, CoreOS 845.0.0. As far as I'm aware the system was basically idling at the time this happened, and it's still up (8 days total)

Booting `CoreOS default'

Loading (hd0,gpt4)/boot/vmlinuz Booting CoreOS! [ 0.000000] Initializing cgroup subsys cpuset [ 0.000000] Initializing cgroup subsys cpu [ 0.000000] Initializing cgroup subsys cpuacct [ 0.000000] Linux version 4.2.2-coreos-r1 (buildbot@ip-10-204-3-57) (gcc version 4.9.3 (Gentoo Hardened 4.9.3 p1.2, pie-0.6.3) ) #2 SMP Sat Oct 24 19:42:01 UTC 2015 [ 0.000000] Command line: BOOT_IMAGE=/boot/vmlinuz console=ttyS0,115200n8 console=tty0 root=LABEL=ROOT mount.usr=PARTUUID=e03dd35c-7c2d-4a47-b3fe-27f15780a57c

[ 0.000000] x86/fpu: Supporting XSAVE feature 0x01: 'x87 floating point registers' [ 0.000000] x86/fpu: Supporting XSAVE feature 0x02: 'SSE registers' [ 0.000000] x86/fpu: Supporting XSAVE feature 0x04: 'AVX registers' [ 0.000000] x86/fpu: Enabled xstate features 0x7, context size is 0x340 bytes, using 'standard' format. [ 0.000000] x86/fpu: Using 'eager' FPU context switches. [ 0.000000] e820: BIOS-provided physical RAM map: [ 0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable [ 0.000000] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved [ 0.000000] BIOS-e820: [mem 0x0000000000100000-0x000000003ffdffff] usable [ 0.000000] BIOS-e820: [mem 0x000000003ffe0000-0x000000003fffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000feffc000-0x00000000feffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved [ 0.000000] NX (Execute Disable) protection: active [ 0.000000] SMBIOS 2.8 present. [ 0.000000] Hypervisor detected: KVM [ 0.000000] e820: last_pfn = 0x3ffe0 max_arch_pfn = 0x400000000 [ 0.000000] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WC UC- WT [ 0.000000] Using GB pages for direct mapping [ 0.000000] init_memory_mapping: [mem 0x00000000-0x000fffff] [ 0.000000] init_memory_mapping: [mem 0x3fc00000-0x3fdfffff] [ 0.000000] init_memory_mapping: [mem 0x20000000-0x3fbfffff] [ 0.000000] init_memory_mapping: [mem 0x00100000-0x1fffffff] [ 0.000000] init_memory_mapping: [mem 0x3fe00000-0x3ffdffff] [ 0.000000] ACPI: Early table checksum verification disabled [ 0.000000] ACPI: RSDP 0x00000000000F62C0 000014 (v00 BOCHS ) [ 0.000000] ACPI: RSDT 0x000000003FFE178C 000034 (v01 BOCHS BXPCRSDT 00000001 BXPC 00000001) [ 0.000000] ACPI: FACP 0x000000003FFE0BDA 000074 (v01 BOCHS BXPCFACP 00000001 BXPC 00000001) [ 0.000000] ACPI: DSDT 0x000000003FFE0040 000B9A (v01 BOCHS BXPCDSDT 00000001 BXPC 00000001) [ 0.000000] ACPI: FACS 0x000000003FFE0000 000040 [ 0.000000] ACPI: SSDT 0x000000003FFE0C4E 000A76 (v01 BOCHS BXPCSSDT 00000001 BXPC 00000001) [ 0.000000] ACPI: APIC 0x000000003FFE16C4 000090 (v01 BOCHS BXPCAPIC 00000001 BXPC 00000001) [ 0.000000] ACPI: HPET 0x000000003FFE1754 000038 (v01 BOCHS BXPCHPET 00000001 BXPC 00000001) [ 0.000000] No NUMA configuration found [ 0.000000] Faking a node at [mem 0x0000000000000000-0x000000003ffdffff] [ 0.000000] NODE_DATA(0) allocated [mem 0x3ffd9000-0x3ffdffff] [ 0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d00 [ 0.000000] kvm-clock: cpu 0, msr 0:3ffd7001, primary cpu clock [ 0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns [ 0.000000] Zone ranges: [ 0.000000] DMA [mem 0x0000000000001000-0x0000000000ffffff] [ 0.000000] DMA32 [mem 0x0000000001000000-0x000000003ffdffff] [ 0.000000] Normal empty [ 0.000000] Movable zone start for each node [ 0.000000] Early memory node ranges [ 0.000000] node 0: [mem 0x0000000000001000-0x000000000009efff] [ 0.000000] node 0: [mem 0x0000000000100000-0x000000003ffdffff] [ 0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x000000003ffdffff] [ 0.000000] ACPI: PM-Timer IO Port: 0x608 [ 0.000000] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1]) [ 0.000000] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23 [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level) [ 0.000000] Using ACPI (MADT) for SMP configuration information [ 0.000000] ACPI: HPET id: 0x8086a201 base: 0xfed00000 [ 0.000000] smpboot: Allowing 4 CPUs, 0 hotplug CPUs [ 0.000000] PM: Registered nosave memory: [mem 0x00000000-0x00000fff] [ 0.000000] PM: Registered nosave memory: [mem 0x0009f000-0x0009ffff] [ 0.000000] PM: Registered nosave memory: [mem 0x000a0000-0x000effff] [ 0.000000] PM: Registered nosave memory: [mem 0x000f0000-0x000fffff] [ 0.000000] e820: [mem 0x40000000-0xfeffbfff] available for PCI devices [ 0.000000] Booting paravirtualized kernel on KVM [ 0.000000] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns [ 0.000000] setup_percpu: NR_CPUS:128 nr_cpumask_bits:128 nr_cpu_ids:4 nr_node_ids:1 [ 0.000000] PERCPU: Embedded 32 pages/cpu @ffff88003fc00000 s91480 r8192 d31400 u524288 [ 0.000000] KVM setup async PF for cpu 0 [ 0.000000] kvm-stealtime: cpu 0, msr 3fc0e3c0 [ 0.000000] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes) [ 0.000000] Built 1 zonelists in Node order, mobility grouping on. Total pages: 257896 [ 0.000000] Policy zone: DMA32 [ 0.000000] Kernel command line: rootflags=rw mount.usrflags=ro BOOT_IMAGE=/boot/vmlinuz console=ttyS0,115200n8 console=tty0 root=LABEL=ROOT mount.usr=PARTUUID=e03dd35c-7c2d-4a47-b3fe-27f15780a57c [ 0.000000] PID hash table entries: 4096 (order: 3, 32768 bytes) [ 0.000000] Memory: 991412K/1048056K available (5314K kernel code, 1050K rwdata, 2396K rodata, 27080K init, 940K bss, 56644K reserved, 0K cma-reserved) [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 [ 0.000000] Hierarchical RCU implementation. [ 0.000000] Build-time adjustment of leaf fanout to 64. [ 0.000000] RCU restricting CPUs from NR_CPUS=128 to nr_cpu_ids=4. [ 0.000000] RCU: Adjusting geometry for rcu_fanout_leaf=64, nr_cpu_ids=4 [ 0.000000] NR_IRQS:8448 nr_irqs:456 16 [ 0.000000] Console: colour VGA+ 80x25 [ 0.000000] console [tty0] enabled [ 0.000000] console [ttyS0] enabled [ 0.000000] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns [ 0.000000] tsc: Detected 2394.456 MHz processor [ 0.136603] Calibrating delay loop (skipped) preset value.. 4788.91 BogoMIPS (lpj=2394456) [ 0.138215] pid_max: default: 32768 minimum: 301 [ 0.139072] ACPI: Core revision 20150619 [ 0.141153] ACPI: All ACPI Tables successfully acquired [ 0.142217] Security Framework initialized [ 0.143015] SELinux: Initializing. [ 0.143845] Dentry cache hash table entries: 131072 (order: 8, 1048576 bytes) [ 0.146468] Inode-cache hash table entries: 65536 (order: 7, 524288 bytes) [ 0.148539] Mount-cache hash table entries: 2048 (order: 2, 16384 bytes) [ 0.151185] Mountpoint-cache hash table entries: 2048 (order: 2, 16384 bytes) [ 0.153640] Initializing cgroup subsys blkio [ 0.154815] Initializing cgroup subsys memory [ 0.155665] Initializing cgroup subsys devices [ 0.156503] Initializing cgroup subsys freezer [ 0.157331] Initializing cgroup subsys net_cls [ 0.158123] Initializing cgroup subsys perf_event [ 0.158974] Initializing cgroup subsys net_prio [ 0.160851] mce: CPU supports 10 MCE banks [ 0.161654] Last level iTLB entries: 4KB 1024, 2MB 1024, 4MB 1024 [ 0.162621] Last level dTLB entries: 4KB 1024, 2MB 1024, 4MB 1024, 1GB 4 [ 0.163915] Freeing SMP alternatives memory: 20K (ffffffff8357a000 - ffffffff8357f000) [ 0.169769] ftrace: allocating 21487 entries in 84 pages [ 0.190856] x2apic enabled [ 0.192050] Switched APIC routing to physical x2apic. [ 0.193693] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.194830] smpboot: CPU0: Intel(R) Core(TM) i7-4500U CPU @ 1.80GHz (fam: 06, model: 45, stepping: 01) [ 0.196822] Performance Events: 16-deep LBR, Haswell events, Intel PMU driver. [ 0.198884] ... version: 2 [ 0.199895] ... bit width: 48 [ 0.201014] ... generic registers: 4 [ 0.202210] ... value mask: 0000ffffffffffff [ 0.203391] ... max period: 000000007fffffff [ 0.205362] ... fixed-purpose events: 3 [ 0.206557] ... event mask: 000000070000000f [ 0.207753] KVM setup paravirtual spinlock [ 0.209291] x86: Booting SMP configuration: [ 0.210479] .... node #0, CPUs: #1 [ 0.215129] kvm-clock: cpu 1, msr 0:3ffd7041, secondary cpu clock [ 0.238314] KVM setup async PF for cpu 1 [ 0.241445] #2 [ 0.241445] kvm-clock: cpu 2, msr 0:3ffd7081, secondary cpu clock [ 0.244638] kvm-stealtime: cpu 1, msr 3fc8e3c0 [ 0.264160] KVM setup async PF for cpu 2 [ 0.268644] #3 [ 0.268644] kvm-stealtime: cpu 2, msr 3fd0e3c0 [ 0.269030] kvm-clock: cpu 3, msr 0:3ffd70c1, secondary cpu clock [ 0.290543] KVM setup async PF for cpu 3 [ 0.290555] x86: Booted up 1 node, 4 CPUs [ 0.290559] smpboot: Total of 4 processors activated (19155.64 BogoMIPS) [ 0.298854] kvm-stealtime: cpu 3, msr 3fd8e3c0 [ 0.325397] devtmpfs: initialized [ 0.328431] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.330253] pinctrl core: initialized pinctrl subsystem [ 0.331358] NET: Registered protocol family 16 [ 0.337267] cpuidle: using governor ladder [ 0.340322] cpuidle: using governor menu [ 0.341459] ACPI: bus type PCI registered [ 0.342219] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.343311] dca service started, version 1.12.1 [ 0.344423] PCI: Using configuration type 1 for base access [ 0.345514] perf_event_intel: PMU erratum BJ122, BV98, HSD29 workaround disabled, HT off [ 0.351911] ACPI: Added _OSI(Module Device) [ 0.352726] ACPI: Added _OSI(Processor Device) [ 0.353565] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.354406] ACPI: Added _OSI(Processor Aggregator Device) [ 0.357159] ACPI: Interpreter enabled [ 0.358135] ACPI Exception: AE_NOT_FOUND, While evaluating Sleep State S1 [ 0.359809] ACPI Exception: AE_NOT_FOUND, While evaluating Sleep State S2 [ 0.361524] ACPI: (supports S0 S3 S4 S5) [ 0.362259] ACPI: Using IOAPIC for interrupt routing [ 0.363151] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.366765] ACPI: PCI Root Bridge [PCI0](domain 0000 [bus 00-ff]) [ 0.367755] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI] [ 0.368764] acpi PNP0A03:00: _OSC failed (AE_NOT_FOUND); disabling ASPM [ 0.379351] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.382037] acpiphp: Slot [3] registered [ 0.383017] acpiphp: Slot [4] registered [ 0.383771] acpiphp: Slot [5] registered [ 0.384549] acpiphp: Slot [6] registered [ 0.385337] acpiphp: Slot [7] registered [ 0.386089] acpiphp: Slot [8] registered [ 0.387632] acpiphp: Slot [9] registered [ 0.388487] acpiphp: Slot [10] registered [ 0.389333] acpiphp: Slot [11] registered [ 0.390097] acpiphp: Slot [12] registered [ 0.390874] acpiphp: Slot [13] registered [ 0.391632] acpiphp: Slot [14] registered [ 0.392450] acpiphp: Slot [15] registered [ 0.393283] acpiphp: Slot [16] registered [ 0.394425] acpiphp: Slot [17] registered [ 0.395325] acpiphp: Slot [18] registered [ 0.396248] acpiphp: Slot [19] registered [ 0.397384] acpiphp: Slot [20] registered [ 0.398568] acpiphp: Slot [21] registered [ 0.399416] acpiphp: Slot [22] registered [ 0.400302] acpiphp: Slot [23] registered [ 0.401188] acpiphp: Slot [24] registered [ 0.402055] acpiphp: Slot [25] registered [ 0.402931] acpiphp: Slot [26] registered [ 0.403793] acpiphp: Slot [27] registered [ 0.404644] acpiphp: Slot [28] registered [ 0.405497] acpiphp: Slot [29] registered [ 0.406293] acpiphp: Slot [30] registered [ 0.407149] acpiphp: Slot [31] registered [ 0.408214] PCI host bridge to bus 0000:00 [ 0.409257] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.410121] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.411330] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.412362] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.414082] pci_bus 0000:00: root bus resource [mem 0x40000000-0xfebfffff window] [ 0.425388] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.426404] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.427815] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.428856] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.430232] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.431593] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.478116] ACPI: PCI Interrupt Link [LNKA](IRQs 5 10 11) [ 0.479465] ACPI: PCI Interrupt Link [LNKB](IRQs 5 10 11) [ 0.481567] ACPI: PCI Interrupt Link [LNKC](IRQs 5 10 11) [ 0.482833] ACPI: PCI Interrupt Link [LNKD](IRQs 5 10 11) [ 0.485239] ACPI: PCI Interrupt Link [LNKS](IRQs *9) [ 0.486666] ACPI: Enabled 16 GPEs in block 00 to 0F [ 0.488020] vgaarb: setting as boot device: PCI:0000:00:02.0 [ 0.488954] vgaarb: device added: PCI:0000:00:02.0,decodes=io+mem,owns=io+mem,locks=none [ 0.490534] vgaarb: loaded [ 0.491175] vgaarb: bridge control possible 0000:00:02.0 [ 0.492119] PCI: Using ACPI for IRQ routing [ 0.493302] HPET: 3 timers in total, 0 timers will be used for per-cpu timer [ 0.494335] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.495420] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.502534] clocksource: Switched to clocksource kvm-clock [ 0.547955] pnp: PnP ACPI init [ 0.549541] pnp: PnP ACPI: found 6 devices [ 0.557015] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.559194] NET: Registered protocol family 2 [ 0.560522] TCP established hash table entries: 8192 (order: 4, 65536 bytes) [ 0.561869] TCP bind hash table entries: 8192 (order: 5, 131072 bytes) [ 0.563141] TCP: Hash tables configured (established 8192 bind 8192) [ 0.564416] UDP hash table entries: 512 (order: 2, 16384 bytes) [ 0.565619] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes) [ 0.566976] NET: Registered protocol family 1 [ 0.568054] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 0.569304] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 0.571341] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 1.130659] futex hash table entries: 1024 (order: 4, 65536 bytes) [ 1.131610] Initialise system trusted keyring [ 1.132439] audit: initializing netlink subsys (disabled) [ 1.133288] audit: type=2000 audit(1447697597.658:1): initialized [ 1.134497] HugeTLB registered 2 MB page size, pre-allocated 0 pages [ 1.137337] VFS: Disk quotas dquot_6.6.0 [ 1.138126] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 1.140380] Key type asymmetric registered [ 1.141144] Asymmetric key parser 'x509' registered [ 1.142792] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 252) [ 1.144367] io scheduler noop registered [ 1.145139] io scheduler deadline registered [ 1.145958] io scheduler cfq registered (default) [ 1.147149] pci_hotplug: PCI Hot Plug PCI Core version: 0.5 [ 1.148240] pciehp: PCI Express Hot Plug Controller Driver version: 0.4 [ 1.149557] GHES: HEST is not enabled! [ 1.150324] ioatdma: Intel(R) QuickData Technology Driver 4.00 [ 1.151455] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 1.175444] 00:05: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 1.177669] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 1.179723] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 1.180591] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 1.181475] rtc_cmos 00:00: RTC can wake from S4 [ 1.182837] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input0 [ 1.184437] rtc_cmos 00:00: rtc core: registered rtc_cmos as rtc0 [ 1.185719] rtc_cmos 00:00: alarms up to one day, 114 bytes nvram, hpet irqs [ 1.188134] NET: Registered protocol family 10 [ 1.189157] NET: Registered protocol family 17 [ 1.190323] Loading compiled-in X.509 certificates [ 1.191698] Loaded X.509 cert 'Build time autogenerated kernel key: cb4c49a7d0f54acc380d8e47053c385ae2bab225' [ 1.193390] registered taskstats version 1 [ 1.200474] rtc_cmos 00:00: setting system clock to 2015-11-16 18:13:17 UTC (1447697597) [ 1.205717] Freeing unused kernel memory: 27080K (ffffffff81b08000 - ffffffff8357a000) [ 1.207012] Write protecting the kernel read-only data: 10240k [ 1.208413] Freeing unused kernel memory: 820K (ffff880001533000 - ffff880001600000) [ 1.210723] Freeing unused kernel memory: 1700K (ffff880001857000 - ffff880001a00000) [ 1.217229] ip_tables: (C) 2000-2006 Netfilter Core Team [ 1.218690] random: systemd urandom read with 1 bits of entropy available [ 1.220326] systemd[1]: systemd 225 running in system mode. (-PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK -SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT -GNUTLS -ACL +XZ -LZ4 +SECCOMP +BLKID -ELFUTILS +KMOD -IDN) [ 1.222727] systemd[1]: Detected virtualization kvm. [ 1.223461] systemd[1]: Detected architecture x86-64. [ 1.224207] systemd[1]: Running in initial RAM disk. [ 1.226648] systemd[1]: No hostname configured. [ 1.227501] systemd[1]: Set hostname to . [ 1.228386] systemd[1]: Initializing machine ID from random generator. [ 1.270471] systemd[1]: Reached target Swap. [ 1.272091] systemd[1]: Reached target Timers. [ 1.273611] systemd[1]: Reached target Local File Systems. [ 1.275520] systemd[1]: Created slice -.slice. [ 1.277111] systemd[1]: Listening on Journal Socket. [ 1.278877] systemd[1]: Listening on udev Control Socket. [ 1.280582] systemd[1]: Created slice System Slice. [ 1.282849] systemd[1]: Starting dracut cmdline hook... [ 1.287098] systemd[1]: Starting Apply Kernel Variables... [ 1.290524] systemd[1]: Starting Create list of required static device nodes for the current kernel... [ 1.294395] systemd[1]: Reached target Slices. [ 1.296294] systemd[1]: Listening on Journal Socket (/dev/log). [ 1.298120] systemd[1]: Listening on udev Kernel Socket. [ 1.300238] systemd[1]: Reached target Encrypted Volumes. [ 1.302323] systemd[1]: Listening on Journal Audit Socket. [ 1.305782] systemd[1]: Starting Journal Service... [ 1.308137] systemd[1]: Reached target Sockets. [ 1.309793] systemd[1]: Started Dispatch Password Requests to Console Directory Watch. [ 1.312278] systemd[1]: Reached target Paths. [ 1.314089] systemd[1]: Created slice system-systemd\x2dfsck.slice. [ 1.316770] systemd[1]: Started Apply Kernel Variables. [ 1.318774] audit: type=1130 audit(1447697597.622:2): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=systemd-sysctl comm="systemd" exe="/usr/lib64/systemd/systemd" hostname=? addr=? terminal=? res=success' [ 1.335011] systemd[1]: Started Create list of required static device nodes for the current kernel. [ 1.337926] audit: type=1130 audit(1447697597.641:3): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=kmod-static-nodes comm="systemd" exe="/usr/lib64/systemd/systemd" hostname=? addr=? terminal=? res=success' [ 1.341575] systemd[1]: Started Journal Service. [ 1.343357] audit: type=1130 audit(1447697597.646:4): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=systemd-journald comm="systemd" exe="/usr/lib64/systemd/systemd" hostname=? addr=? terminal=? res=success' [ 1.354367] audit: type=1130 audit(1447697597.657:5): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=systemd-tmpfiles-setup-dev comm="systemd" exe="/usr/lib64/systemd/systemd" hostname=? addr=? terminal=? res=success' [ 1.359144] audit: type=1130 audit(1447697597.662:6): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=dracut-cmdline comm="systemd" exe="/usr/lib64/systemd/systemd" hostname=? addr=? terminal=? res=success' [ 1.394027] audit: type=1130 audit(1447697597.697:7): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=dracut-pre-udev comm="systemd" exe="/usr/lib64/systemd/systemd" hostname=? addr=? terminal=? res=success' [ 1.411554] audit: type=1130 audit(1447697597.715:8): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=systemd-udevd comm="systemd" exe="/usr/lib64/systemd/systemd" hostname=? addr=? terminal=? res=success' [ 1.477264] audit: type=1130 audit(1447697597.780:9): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=dracut-pre-trigger comm="systemd" exe="/usr/lib64/systemd/systemd" hostname=? addr=? terminal=? res=success' [ 1.522799] audit: type=1130 audit(1447697597.824:10): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=systemd-udev-trigger comm="systemd" exe="/usr/lib64/systemd/systemd" hostname=? addr=? terminal=? res=success' [ 1.540562] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input3 [ 1.546075] ACPI: Power Button [PWRF] [ 1.585306] SCSI subsystem initialized [ 1.608134] microcode: CPU0 sig=0x40651, pf=0x1, revision=0x1 [ 1.610495] microcode: CPU1 sig=0x40651, pf=0x1, revision=0x1 [ 1.614108] microcode: CPU2 sig=0x40651, pf=0x1, revision=0x1 [ 1.615300] microcode: CPU3 sig=0x40651, pf=0x1, revision=0x1 [ 1.619760] input: ImExPS/2 Generic Explorer Mouse as /devices/platform/i8042/serio1/input/input4 [ 1.623550] microcode: Microcode Update Driver: v2.00 < tigran@aivazian.fsnet.co.uk>, Peter Oruba [ 1.650185] ACPI: PCI Interrupt Link [LNKC] enabled at IRQ 11 [ 1.653479] virtio-pci 0000:00:03.0: virtio_pci: leaving for legacy driver [ 1.666025] mousedev: PS/2 mouse device common for all mice [ 1.668624] AVX2 version of gcm_enc/dec engaged. [ 1.672830] AES CTR mode by8 optimization enabled [ 1.709418] ACPI: PCI Interrupt Link [LNKD] enabled at IRQ 10 [ 1.710829] virtio-pci 0000:00:04.0: virtio_pci: leaving for legacy driver [ 1.713372] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 1.723146] scsi host0: ata_piix [ 1.724477] scsi host1: ata_piix [ 1.725797] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc0a0 irq 14 [ 1.731990] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc0a8 irq 15 [ 1.764773] ACPI: PCI Interrupt Link [LNKA] enabled at IRQ 10 [ 1.765802] virtio-pci 0000:00:05.0: virtio_pci: leaving for legacy driver [ 1.779557] 9pnet: Installing 9P2000 support [ 1.796383] vda: vda1 vda2 vda3 vda4 vda6 vda7 vda9 [ 1.886426] ata2.00: ATAPI: QEMU DVD-ROM, 2.3.1, max UDMA/100 [ 1.889212] ata2.00: configured for MWDMA2 [ 1.897032] scsi 1:0:0:0: CD-ROM QEMU QEMU DVD-ROM 2.3. PQ: 0 ANSI: 5 [ 1.947472] sr 1:0:0:0: [sr0] scsi3-mmc drive: 4x/4x cd/rw xa/form2 tray [ 1.949007] cdrom: Uniform CD-ROM driver Revision: 3.20 [ 2.132586] tsc: Refined TSC clocksource calibration: 2394.432 MHz [ 2.134941] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x2283abd2132, max_idle_ns: 440795306562 ns [ 2.144774] EXT4-fs (vda9): mounted filesystem with ordered data mode. Opts: (null) [ 2.161862] EXT4-fs (vda4): mounted filesystem without journal. Opts: (null) [ 2.374762] systemd-journald[125]: Received SIGTERM from PID 1 (systemd). [ 2.456786] systemd[1]: Successfully loaded SELinux policy in 24.196ms. [ 2.470888] systemd[1]: Relabelled /dev and /run in 7.605ms.

/var/log/journal/ca43056277ff4f91b0b156757a5e7dde/system.journal corrupted or uncleanly shut down, renaming and replacing. [ 2.722571] systemd-journald[483]: Received request to flush runtime journal from PID 1 [ 2.859296] 9p: Installing v9fs 9p2000 file system support [ 2.881987] EXT4-fs (vda6): recovery complete [ 2.882935] EXT4-fs (vda6): mounted filesystem with ordered data mode. Opts: commit=600 [ 2.911702] FAT-fs (vda1): Volume was not properly unmounted. Some data may be corrupt. Please run fsck.

This is coreos (Linux x86_64 4.2.2-coreos-r1) 18:13:20 SSH host key: SHA256:pAdnh1wxRe/U36DZc+ntIKazgLFb5zpUidepgmtRVHU (DSA) SSH host key: SHA256:07Qq7/ZvqNg/gOfYfr1yZkevtTxf5hapxAe4l30Y5+M (ED25519) SSH host key: SHA256:MJXhqutwbhGLfw8JOInaumWZcjPW6hIeEiH/W5Jtf9U (RSA) eth0: 10.0.2.15 fe80::5054:ff:fe12:3456

coreos login: [ 35.074741] random: nonblocking pool is initialized [ 35.796818] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready [ 35.807643] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready [ 35.820693] nf_conntrack version 0.5.0 (7976 buckets, 31904 max) [14923.526088] clocksource: timekeeping watchdog: Marking clocksource 'tsc' as unstable because the skew is too large: [14923.540595] clocksource: 'kvm-clock' wd_now: d92a7789a91 wd_last: cbae8c9b683 mask: ffffffffffffffff [14923.546791] clocksource: 'tsc' cs_now: 1e7d607e4d7c cs_last: 1e7c8c7fc3a0 mask: ffffffffffffffff [15473.933086] hrtimer: interrupt took 16070686 ns [174864.401227] systemd-coredump[7733]: Detected coredump of the journal daemon itself, diverted to /var/lib/systemd/coredump/core.systemd-journal.0.c6b342f91b7f4affb5575a2be8f8ba52.483.1447872459000000.xz. [563425.739858] INFO: rcu_sched detected stalls on CPUs/tasks: { 0 1 3} (detected by 2, t=127543353 jiffies, g=59965, c=59964, q=41) [563425.749887] Task dump for CPU 0: [563425.751180] systemd R running task 0 1 0 0x00000008 [563425.753328] ffff88003e2d7ee8 0000000000000018 ffffffff810d5217 00007ffd7c2349b0 [563425.757609] ffffffffff7ff000 ffff88003e2d7f08 ffffffff810d52ae ffff88003e2d7f18 [563425.763947] ffffffff810d1371 ffff88003e2d7f48 ffffffff810d22f5 000000005650c367 [563425.766073] Call Trace: [563425.766942] [] ? getnstimeofday64+0x37/0xc0 [563425.768280] [] ? getnstimeofday64+0xe/0x30 [563425.769589] [] ? posix_clock_realtime_get+0x11/0x20 [563425.771815] [] ? SyS_clock_gettime+0x45/0xa0 [563425.773236] [] ? entry_SYSCALL_64_fastpath+0x12/0x71 [563425.774617] Task dump for CPU 1: [563425.775543] locksmithd R running task 0 7927 1 0x00000088 [563425.777037] ffff88003e3cbbd8 ffffffff8152767e ffff88003e379cc0 ffff88003d925640 [563425.779115] ffff88003d925640 ffff88003e3cc000 ffff88003d925640 ffffc900001e1d00 [563425.781223] 0000000000000000 ffff88003e3cbcb0 ffff88003e3cbbf8 ffffffff81527c87 [563425.783362] Call Trace: [563425.784220] [] ? schedule+0x37e/0x950 [563425.785424] [] schedule+0x37/0x80 [563425.786667] [] futex_wait_queue_me+0xd1/0x120 [563425.804416] [] futex_wait+0x256/0x280 [563425.805705] [] ? futex_wake+0x81/0x150 [563425.807076] [] do_futex+0xe0/0xb10 [563425.808305] [] ? evict+0x11b/0x180 [563425.809617] [] ? raw_callee_save___pv_queued_spin_unlock+0x11/0x20 [563425.811850] [] ? raw_callee_save_pv_queued_spin_unlock+0x11/0x20 [563425.815171] [] ? ep_poll+0x23e/0x3b0 [563425.816475] [] ? audit_syscall_exit+0x221/0x2b0 [563425.819765] [] ? kvm_clock_get_cycles+0x1e/0x20 [563425.821680] [] ? syscall_trace_leave+0x93/0xf0 [563425.823422] [] ? SyS_clock_gettime+0x63/0xa0 [563425.824809] [] ? int_very_careful+0x38/0x41 [563425.826134] Task dump for CPU 3: [563425.827189] swapper/3 R running task 0 0 1 0x00000000 [563425.828622] 0000000000000000 ffffffffffffff02 ffffffff81055786 0000000000000010 [563425.830897] 0000000000000246 ffff88003e343e88 0000000000000018 7fffffffffffffff [563425.839629] ffff88003e343ea8 ffffffff8101d4ae ffffffff81afbcf0 ffff88003e344000 [563425.842463] Call Trace: [563425.843509] [] ? native_safe_halt+0x6/0x10 [563425.845202] [] ? default_idle+0x1e/0xa0 [563425.846699] [] ? arch_cpu_idle+0xf/0x20 [563425.847957] [] ? default_idle_call+0x32/0x40 [563425.850852] [] ? cpu_startup_entry+0x2ba/0x320 [563425.852350] [] ? start_secondary+0x174/0x1a0 [563425.854293] rcu_sched kthread starved for 127543353 jiffies! g59965 c59964 f0x0

/var/log/journal/ca43056277ff4f91b0b156757a5e7dde/system.journal corrupted or uncleanly shut down, renaming and replacing. [563436.596270] systemd-coredump[20070]: Detected coredump of the journal daemon itself, diverted to /var/lib/systemd/coredump/core.systemd-journal.0.c6b342f91b7f4affb5575a2be8f8ba52.7754.1448261032000000.xz.

/var/log/journal/ca43056277ff4f91b0b156757a5e7dde/system.journal corrupted or uncleanly shut down, renaming and replacing. [603007.868252] systemd-coredump[20204]: Detected coredump of the journal daemon itself, diverted to /var/lib/systemd/coredump/core.systemd-journal.0.c6b342f91b7f4affb5575a2be8f8ba52.20089.1448300604000000.xz.

/var/log/journal/ca43056277ff4f91b0b156757a5e7dde/system.journal corrupted or uncleanly shut down, renaming and replacing. [605501.879406] systemd-coredump[20267]: Detected coredump of the journal daemon itself, diverted to /var/lib/systemd/coredump/core.systemd-journal.0.c6b342f91b7f4affb5575a2be8f8ba52.20210.1448303097000000.xz.

— Reply to this email directly or view it on GitHub https://github.com/coreos/bugs/issues/1001.

— Reply to this email directly or view it on GitHub https://github.com/coreos/bugs/issues/1001#issuecomment-159452828.

vcaputo commented 8 years ago

https://github.com/systemd/systemd/pull/1783 is one I fixed which triggered via suspending the host for long periods, but the issues in this ticket look different, looks like the guest's kernel is getting balled up in rcu land over timekeeping

The systemd daemons have watchdogs which will trigger coredumps on expiration, which may be what's causing the coredumps above, and the root cause could just be suspend/resume-induced time shifts.

They increased the timeouts recently because journald was apparently getting false-positives on the watchdog expiration due to IO latency: https://github.com/systemd/systemd/commit/c2fc2c2560f0ca0fab383753c065e45d76f465e5 and http://github.com/systemd/systemd/issues/1353

I haven't dug into this, but from a casual/speculative perspective thinking about it:

  1. watchdog pings, gets pong, records time.
  2. watchdog pings
  3. host is suspended
  4. sufficient time passes for ping to expire
  5. host is resumed
  6. watchdog coredumps daemon daemon for not responding in time

Maybe the watchdog needs to defer dropping the hammer to see if the time is jumping.

kayrus commented 8 years ago

one of coreos users has probably similar problem (CoreOS-stable-766.3.0-hvm (ami-f396fa96)):

http://stackoverflow.com/questions/34315322/systemd-docker-or-systemd-journal-on-stable-coreos-using-high-cpu https://www.evernote.com/shard/s111/sh/a8e232dd-872b-4972-92d4-826e420b7003/b209c87c56db3ec7

He also has coredumps:

-rw-r----- 1 root root 137584 Dec 14 22:06 core.nginx.0.b0a549a683374aa4966e9a3b5f71bcde.25576.1450130793000000.xz
-rw-r----- 1 root root 137056 Dec 14 21:59 core.nginx.0.b0a549a683374aa4966e9a3b5f71bcde.20975.1450130380000000.xz
-rw-r----- 1 root root 135688 Dec 14 21:56 core.nginx.0.b0a549a683374aa4966e9a3b5f71bcde.893.1450130203000000.xz
-rw-r----- 1 root root 233536 Dec 14 19:00 core.systemd-udevd.0.b0a549a683374aa4966e9a3b5f71bcde.30993.1450119624000000.xz
vcaputo commented 8 years ago

I'm closing this due to inactivity, please reopen if more journald errors like this emerge, we've fixed a number of things which might have resulted in such crashes.