In June 2016 we had instance being completely locked apparently due to a Kernel bug. This task is to keep track of all tasks opened at that time and offers some kind of a summary of the situation. The common symptom is the console/kernel emitting a message such as:
task jbd2/vda1-8:105 blocked for more than 120 seconds.
As of November 2016, it is entirely solved, most probably by a Linux Kernel upgrade on OpenStack compute nodes.
From T138281:
Looking at the instance via Horizon and Wikitech
| Name | ci-jessie-wikimedia-152695 |
| Instance ID | 1484908c-bd9b-4b4f-903a-39914a7e408e |
| Wikitech | https://wikitech.wikimedia.org/wiki/Nova_Resource:Ci-jessie-wikimedia-152695.contintcloud.eqiad.wmflabs |
| ec2 id | i-0002492b |
| Host | labvirt1010 |
| Base image | d604ca6b-3e3f-45f3-b13d-e1b45ecb17e6 |
| 1 | [H[J[1;1H[?25l[m[H[J[1;1H[2;22HGNU GRUB version 2.02~beta2-22+deb8u1 |
|---|---|
| 2 | |
| 3 | [m[4;2H+----------------------------------------------------------------------------+[5;2H|[5;79H|[6;2H|[6;79H|[7;2H|[7;79H|[8;2H|[8;79H|[9;2H|[9;79H|[10;2H|[10;79H|[11;2H|[11;79H|[12;2H|[12;79H|[13;2H|[13;79H|[14;2H|[14;79H|[15;2H|[15;79H|[16;2H|[16;79H|[17;2H+----------------------------------------------------------------------------+[m[18;2H[19;2H[m Use the ^ and v keys to select which entry is highlighted. |
| 4 | Press enter to boot the selected OS, `e' to edit the commands |
| 5 | before booting or `c' for a command-line. [5;80H [7m[5;3H*Debian GNU/Linux [m[5;78H[m[m[6;3H Advanced options for Debian GNU/Linux [m[6;78H[m[m[7;3H [m[7;78H[m[m[8;3H [m[8;78H[m[m[9;3H [m[9;78H[m[m[10;3H [m[10;78H[m[m[11;3H [m[11;78H[m[m[12;3H [m[12;78H[m[m[13;3H [m[13;78H[m[m[14;3H [m[14;78H[m[m[15;3H [m[15;78H[m[m[16;3H [m[16;78H[m[16;80H [5;78H[22;1H The highlighted entry will be executed automatically in 5s. [5;78H[22;1H The highlighted entry will be executed automatically in 4s. [5;78H[22;1H The highlighted entry will be executed automatically in 3s. [5;78H[22;1H The highlighted entry will be executed automatically in 2s. [5;78H[22;1H The highlighted entry will be executed automatically in 1s. [5;78H[22;1H The highlighted entry will be executed automatically in 0s. [5;78H[?25h[H[J[1;1H[H[J[1;1HLoading Linux 3.16.0-4-amd64 ... |
| 6 | text is deprecated. Use set gfxpayload=vga=normal before linux command |
| 7 | instead. |
| 8 | text is deprecated. Use set gfxpayload=vga=normal before linux command |
| 9 | instead. |
| 10 | Loading initial ramdisk ... |
| 11 | [ 0.000000] Initializing cgroup subsys cpuset |
| 12 | [ 0.000000] Initializing cgroup subsys cpu |
| 13 | [ 0.000000] Initializing cgroup subsys cpuacct |
| 14 | [ 0.000000] Linux version 3.16.0-4-amd64 (debian-kernel@lists.debian.org) (gcc version 4.8.4 (Debian 4.8.4-1) ) #1 SMP Debian 3.16.7-ckt25-2 (2016-04-08) |
| 15 | [ 0.000000] Command line: BOOT_IMAGE=/boot/vmlinuz-3.16.0-4-amd64 root=LABEL=cloudimg-rootfs ro nofb nomodeset vga=normal console=tty0 console=ttyS0,115200 no_timer_check nofb nomodeset vga=normal |
| 16 | [ 0.000000] e820: BIOS-provided physical RAM map: |
| 17 | [ 0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable |
| 18 | [ 0.000000] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved |
| 19 | [ 0.000000] BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved |
| 20 | [ 0.000000] BIOS-e820: [mem 0x0000000000100000-0x00000000bffdffff] usable |
| 21 | [ 0.000000] BIOS-e820: [mem 0x00000000bffe0000-0x00000000bfffffff] reserved |
| 22 | [ 0.000000] BIOS-e820: [mem 0x00000000feffc000-0x00000000feffffff] reserved |
| 23 | [ 0.000000] BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved |
| 24 | [ 0.000000] BIOS-e820: [mem 0x0000000100000000-0x000000013fffffff] usable |
| 25 | [ 0.000000] NX (Execute Disable) protection: active |
| 26 | [ 0.000000] SMBIOS 0.8 present. |
| 27 | [ 0.000000] Hypervisor detected: KVM |
| 28 | [ 0.000000] AGP: No AGP bridge found |
| 29 | [ 0.000000] e820: last_pfn = 0x140000 max_arch_pfn = 0x400000000 |
| 30 | [ 0.000000] x86 PAT enabled: cpu 0, old 0x7040600070406, new 0x7010600070106 |
| 31 | [ 0.000000] e820: last_pfn = 0xbffe0 max_arch_pfn = 0x400000000 |
| 32 | [ 0.000000] found SMP MP-table at [mem 0x000f0ea0-0x000f0eaf] mapped at [ffff8800000f0ea0] |
| 33 | [ 0.000000] Using GB pages for direct mapping |
| 34 | [ 0.000000] init_memory_mapping: [mem 0x00000000-0x000fffff] |
| 35 | [ 0.000000] init_memory_mapping: [mem 0x13fe00000-0x13fffffff] |
| 36 | [ 0.000000] init_memory_mapping: [mem 0x13c000000-0x13fdfffff] |
| 37 | [ 0.000000] init_memory_mapping: [mem 0x100000000-0x13bffffff] |
| 38 | [ 0.000000] init_memory_mapping: [mem 0x00100000-0xbffdffff] |
| 39 | [ 0.000000] RAMDISK: [mem 0x36116000-0x37082fff] |
| 40 | [ 0.000000] ACPI: Early table checksum verification disabled |
| 41 | [ 0.000000] ACPI: RSDP 0x00000000000F0C30 000014 (v00 BOCHS ) |
| 42 | [ 0.000000] ACPI: RSDT 0x00000000BFFE1884 000030 (v01 BOCHS BXPCRSDT 00000001 BXPC 00000001) |
| 43 | [ 0.000000] ACPI: FACP 0x00000000BFFE0E48 000074 (v01 BOCHS BXPCFACP 00000001 BXPC 00000001) |
| 44 | [ 0.000000] ACPI: DSDT 0x00000000BFFE0040 000E08 (v01 BOCHS BXPCDSDT 00000001 BXPC 00000001) |
| 45 | [ 0.000000] ACPI: FACS 0x00000000BFFE0000 000040 |
| 46 | [ 0.000000] ACPI: SSDT 0x00000000BFFE0EBC 000948 (v01 BOCHS BXPCSSDT 00000001 BXPC 00000001) |
| 47 | [ 0.000000] ACPI: APIC 0x00000000BFFE1804 000080 (v01 BOCHS BXPCAPIC 00000001 BXPC 00000001) |
| 48 | [ 0.000000] No NUMA configuration found |
| 49 | [ 0.000000] Faking a node at [mem 0x0000000000000000-0x000000013fffffff] |
| 50 | [ 0.000000] Initmem setup node 0 [mem 0x00000000-0x13fffffff] |
| 51 | [ 0.000000] NODE_DATA [mem 0x13fff9000-0x13fffdfff] |
| 52 | [ 0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d00 |
| 53 | [ 0.000000] kvm-clock: cpu 0, msr 1:3fff1001, primary cpu clock |
| 54 | [ 0.000000] Zone ranges: |
| 55 | [ 0.000000] DMA [mem 0x00001000-0x00ffffff] |
| 56 | [ 0.000000] DMA32 [mem 0x01000000-0xffffffff] |
| 57 | [ 0.000000] Normal [mem 0x100000000-0x13fffffff] |
| 58 | [ 0.000000] Movable zone start for each node |
| 59 | [ 0.000000] Early memory node ranges |
| 60 | [ 0.000000] node 0: [mem 0x00001000-0x0009efff] |
| 61 | [ 0.000000] node 0: [mem 0x00100000-0xbffdffff] |
| 62 | [ 0.000000] node 0: [mem 0x100000000-0x13fffffff] |
| 63 | [ 0.000000] ACPI: PM-Timer IO Port: 0x608 |
| 64 | [ 0.000000] ACPI: LAPIC (acpi_id[0x00] lapic_id[0x00] enabled) |
| 65 | [ 0.000000] ACPI: LAPIC (acpi_id[0x01] lapic_id[0x01] enabled) |
| 66 | [ 0.000000] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1]) |
| 67 | [ 0.000000] ACPI: IOAPIC (id[0x00] address[0xfec00000] gsi_base[0]) |
| 68 | [ 0.000000] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23 |
| 69 | [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl) |
| 70 | [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level) |
| 71 | [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level) |
| 72 | [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level) |
| 73 | [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level) |
| 74 | [ 0.000000] Using ACPI (MADT) for SMP configuration information |
| 75 | [ 0.000000] smpboot: Allowing 2 CPUs, 0 hotplug CPUs |
| 76 | [ 0.000000] PM: Registered nosave memory: [mem 0x0009f000-0x0009ffff] |
| 77 | [ 0.000000] PM: Registered nosave memory: [mem 0x000a0000-0x000effff] |
| 78 | [ 0.000000] PM: Registered nosave memory: [mem 0x000f0000-0x000fffff] |
| 79 | [ 0.000000] PM: Registered nosave memory: [mem 0xbffe0000-0xbfffffff] |
| 80 | [ 0.000000] PM: Registered nosave memory: [mem 0xc0000000-0xfeffbfff] |
| 81 | [ 0.000000] PM: Registered nosave memory: [mem 0xfeffc000-0xfeffffff] |
| 82 | [ 0.000000] PM: Registered nosave memory: [mem 0xff000000-0xfffbffff] |
| 83 | [ 0.000000] PM: Registered nosave memory: [mem 0xfffc0000-0xffffffff] |
| 84 | [ 0.000000] e820: [mem 0xc0000000-0xfeffbfff] available for PCI devices |
| 85 | [ 0.000000] Booting paravirtualized kernel on KVM |
| 86 | [ 0.000000] setup_percpu: NR_CPUS:512 nr_cpumask_bits:512 nr_cpu_ids:2 nr_node_ids:1 |
| 87 | [ 0.000000] PERCPU: Embedded 27 pages/cpu @ffff88013fc00000 s80896 r8192 d21504 u1048576 |
| 88 | [ 0.000000] KVM setup async PF for cpu 0 |
| 89 | [ 0.000000] kvm-stealtime: cpu 0, msr 13fc0d080 |
| 90 | [ 0.000000] Built 1 zonelists in Node order, mobility grouping on. Total pages: 1034089 |
| 91 | [ 0.000000] Policy zone: Normal |
| 92 | [ 0.000000] Kernel command line: BOOT_IMAGE=/boot/vmlinuz-3.16.0-4-amd64 root=LABEL=cloudimg-rootfs ro nofb nomodeset vga=normal console=tty0 console=ttyS0,115200 no_timer_check nofb nomodeset vga=normal |
| 93 | [ 0.000000] PID hash table entries: 4096 (order: 3, 32768 bytes) |
| 94 | [ 0.000000] xsave: enabled xstate_bv 0x7, cntxt size 0x340 |
| 95 | [ 0.000000] AGP: Checking aperture... |
| 96 | [ 0.000000] AGP: No AGP bridge found |
| 97 | [ 0.000000] Memory: 4042740K/4193784K available (5222K kernel code, 947K rwdata, 1836K rodata, 1204K init, 840K bss, 151044K reserved) |
| 98 | [ 0.000000] Hierarchical RCU implementation. |
| 99 | [ 0.000000] RCU dyntick-idle grace-period acceleration is enabled. |
| 100 | [ 0.000000] RCU restricting CPUs from NR_CPUS=512 to nr_cpu_ids=2. |
| 101 | [ 0.000000] RCU: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=2 |
| 102 | [ 0.000000] NR_IRQS:33024 nr_irqs:512 16 |
| 103 | [ 0.000000] Console: colour VGA+ 80x25 |
| 104 | [ 0.000000] console [tty0] enabled |
| 105 | [ 0.000000] console [ttyS0] enabled |
| 106 | [ 0.000000] tsc: Detected 2596.990 MHz processor |
| 107 | [ 0.008000] Calibrating delay loop (skipped) preset value.. 5193.98 BogoMIPS (lpj=10387960) |
| 108 | [ 0.008000] pid_max: default: 32768 minimum: 301 |
| 109 | [ 0.008000] ACPI: Core revision 20140424 |
| 110 | [ 0.009878] ACPI: All ACPI Tables successfully acquired |
| 111 | [ 0.012642] Security Framework initialized |
| 112 | [ 0.013949] AppArmor: AppArmor disabled by boot time parameter |
| 113 | [ 0.015126] Yama: disabled by default; enable with sysctl kernel.yama.* |
| 114 | [ 0.016893] Dentry cache hash table entries: 524288 (order: 10, 4194304 bytes) |
| 115 | [ 0.020917] Inode-cache hash table entries: 262144 (order: 9, 2097152 bytes) |
| 116 | [ 0.022871] Mount-cache hash table entries: 8192 (order: 4, 65536 bytes) |
| 117 | [ 0.024017] Mountpoint-cache hash table entries: 8192 (order: 4, 65536 bytes) |
| 118 | [ 0.026638] Initializing cgroup subsys memory |
| 119 | [ 0.027599] Initializing cgroup subsys devices |
| 120 | [ 0.028017] Initializing cgroup subsys freezer |
| 121 | [ 0.029151] Initializing cgroup subsys net_cls |
| 122 | [ 0.030106] Initializing cgroup subsys blkio |
| 123 | [ 0.032018] Initializing cgroup subsys perf_event |
| 124 | [ 0.033050] Initializing cgroup subsys net_prio |
| 125 | [ 0.034742] mce: CPU supports 10 MCE banks |
| 126 | [ 0.035568] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 |
| 127 | [ 0.035568] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 |
| 128 | [ 0.035568] tlb_flushall_shift: 6 |
| 129 | [ 0.036292] Freeing SMP alternatives memory: 20K (ffffffff81a1b000 - ffffffff81a20000) |
| 130 | [ 0.042948] ftrace: allocating 21683 entries in 85 pages |
| 131 | [ 0.052323] Enabling x2apic |
| 132 | [ 0.053009] Enabled x2apic |
| 133 | [ 0.053904] Switched APIC routing to physical x2apic. |
| 134 | [ 0.057748] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 |
| 135 | [ 0.059102] smpboot: CPU0: Intel Xeon E312xx (Sandy Bridge) (fam: 06, model: 2a, stepping: 01) |
| 136 | [ 0.061435] Performance Events: unsupported p6 CPU model 42 no PMU driver, software events only. |
| 137 | [ 0.064000] x86: Booting SMP configuration: |
| 138 | [ 0.064006] .... node #0, CPUs: #1 |
| 139 | [ 0.008000] kvm-clock: cpu 1, msr 1:3fff1041, secondary cpu clock |
| 140 | [ 0.076172] NMI watchdog: disabled (cpu0): hardware events not enabled |
| 141 | [ 0.080047] x86: Booted up 1 node, 2 CPUs |
| 142 | [ 0.080033] KVM setup async PF for cpu 1 |
| 143 | [ 0.080033] kvm-stealtime: cpu 1, msr 13fd0d080 |
| 144 | [ 0.081722] smpboot: Total of 2 processors activated (10387.96 BogoMIPS) |
| 145 | [ 0.082760] devtmpfs: initialized |
| 146 | [ 0.086358] pinctrl core: initialized pinctrl subsystem |
| 147 | [ 0.086358] NET: Registered protocol family 16 |
| 148 | [ 0.088104] cpuidle: using governor ladder |
| 149 | [ 0.088579] cpuidle: using governor menu |
| 150 | [ 0.089115] ACPI: bus type PCI registered |
| 151 | [ 0.089581] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 |
| 152 | [ 0.090349] PCI: Using configuration type 1 for base access |
| 153 | [ 0.100180] ACPI: Added _OSI(Module Device) |
| 154 | [ 0.100581] ACPI: Added _OSI(Processor Device) |
| 155 | [ 0.101084] ACPI: Added _OSI(3.0 _SCP Extensions) |
| 156 | [ 0.101592] ACPI: Added _OSI(Processor Aggregator Device) |
| 157 | [ 0.103044] ACPI: Interpreter enabled |
| 158 | [ 0.104009] ACPI Exception: AE_NOT_FOUND, While evaluating Sleep State [\_S1_] (20140424/hwxface-580) |
| 159 | [ 0.105088] ACPI Exception: AE_NOT_FOUND, While evaluating Sleep State [\_S2_] (20140424/hwxface-580) |
| 160 | [ 0.106154] ACPI: (supports S0 S3 S4 S5) |
| 161 | [ 0.106604] ACPI: Using IOAPIC for interrupt routing |
| 162 | [ 0.107150] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug |
| 163 | [ 0.109818] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) |
| 164 | [ 0.110466] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI] |
| 165 | [ 0.111156] acpi PNP0A03:00: _OSC failed (AE_NOT_FOUND); disabling ASPM |
| 166 | [ 0.112064] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. |
| 167 | [ 0.113429] acpiphp: Slot [3] registered |
| 168 | [ 0.113905] acpiphp: Slot [4] registered |
| 169 | [ 0.114387] acpiphp: Slot [5] registered |
| 170 | [ 0.114856] acpiphp: Slot [6] registered |
| 171 | [ 0.115536] acpiphp: Slot [7] registered |
| 172 | [ 0.116013] acpiphp: Slot [8] registered |
| 173 | [ 0.116487] acpiphp: Slot [9] registered |
| 174 | [ 0.116960] acpiphp: Slot [10] registered |
| 175 | [ 0.117438] acpiphp: Slot [11] registered |
| 176 | [ 0.118106] acpiphp: Slot [12] registered |
| 177 | [ 0.118579] acpiphp: Slot [13] registered |
| 178 | [ 0.120020] acpiphp: Slot [14] registered |
| 179 | [ 0.120503] acpiphp: Slot [15] registered |
| 180 | [ 0.120979] acpiphp: Slot [16] registered |
| 181 | [ 0.121449] acpiphp: Slot [17] registered |
| 182 | [ 0.121919] acpiphp: Slot [18] registered |
| 183 | [ 0.122391] acpiphp: Slot [19] registered |
| 184 | [ 0.123029] acpiphp: Slot [20] registered |
| 185 | [ 0.123519] acpiphp: Slot [21] registered |
| 186 | [ 0.124028] acpiphp: Slot [22] registered |
| 187 | [ 0.124521] acpiphp: Slot [23] registered |
| 188 | [ 0.124994] acpiphp: Slot [24] registered |
| 189 | [ 0.125466] acpiphp: Slot [25] registered |
| 190 | [ 0.125944] acpiphp: Slot [26] registered |
| 191 | [ 0.127190] acpiphp: Slot [27] registered |
| 192 | [ 0.128020] acpiphp: Slot [28] registered |
| 193 | [ 0.128506] acpiphp: Slot [29] registered |
| 194 | [ 0.128995] acpiphp: Slot [30] registered |
| 195 | [ 0.129483] acpiphp: Slot [31] registered |
| 196 | [ 0.129960] PCI host bridge to bus 0000:00 |
| 197 | [ 0.130448] pci_bus 0000:00: root bus resource [bus 00-ff] |
| 198 | [ 0.131031] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7] |
| 199 | [ 0.131667] pci_bus 0000:00: root bus resource [io 0x0d00-0xadff] |
| 200 | [ 0.132006] pci_bus 0000:00: root bus resource [io 0xae0f-0xaeff] |
| 201 | [ 0.132741] pci_bus 0000:00: root bus resource [io 0xaf20-0xafdf] |
| 202 | [ 0.133367] pci_bus 0000:00: root bus resource [io 0xafe4-0xffff] |
| 203 | [ 0.133997] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff] |
| 204 | [ 0.134677] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff] |
| 205 | [ 0.141235] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] |
| 206 | [ 0.142727] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] |
| 207 | [ 0.143760] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] |
| 208 | [ 0.144005] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] |
| 209 | [ 0.151898] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI |
| 210 | [ 0.152011] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB |
| 211 | [ 0.199803] ACPI: PCI Interrupt Link [LNKA] (IRQs 5 *10 11) |
| 212 | [ 0.200833] ACPI: PCI Interrupt Link [LNKB] (IRQs 5 *10 11) |
| 213 | [ 0.202286] ACPI: PCI Interrupt Link [LNKC] (IRQs 5 10 *11) |
| 214 | [ 0.204110] ACPI: PCI Interrupt Link [LNKD] (IRQs 5 10 *11) |
| 215 | [ 0.205495] ACPI: PCI Interrupt Link [LNKS] (IRQs *9) |
| 216 | [ 0.207044] ACPI: Enabled 16 GPEs in block 00 to 0F |
| 217 | [ 0.208137] vgaarb: setting as boot device: PCI:0000:00:02.0 |
| 218 | [ 0.208993] vgaarb: device added: PCI:0000:00:02.0,decodes=io+mem,owns=io+mem,locks=none |
| 219 | [ 0.210441] vgaarb: loaded |
| 220 | [ 0.211042] vgaarb: bridge control possible 0000:00:02.0 |
| 221 | [ 0.212093] PCI: Using ACPI for IRQ routing |
| 222 | [ 0.213294] Switched to clocksource kvm-clock |
| 223 | [ 0.222138] pnp: PnP ACPI init |
| 224 | [ 0.222864] ACPI: bus type PNP registered |
| 225 | [ 0.224364] pnp: PnP ACPI: found 6 devices |
| 226 | [ 0.225162] ACPI: bus type PNP unregistered |
| 227 | [ 0.236732] NET: Registered protocol family 2 |
| 228 | [ 0.238809] TCP established hash table entries: 32768 (order: 6, 262144 bytes) |
| 229 | [ 0.240233] TCP bind hash table entries: 32768 (order: 7, 524288 bytes) |
| 230 | [ 0.242113] TCP: Hash tables configured (established 32768 bind 32768) |
| 231 | [ 0.243224] TCP: reno registered |
| 232 | [ 0.243900] UDP hash table entries: 2048 (order: 4, 65536 bytes) |
| 233 | [ 0.244933] UDP-Lite hash table entries: 2048 (order: 4, 65536 bytes) |
| 234 | [ 0.246508] NET: Registered protocol family 1 |
| 235 | [ 0.247351] pci 0000:00:00.0: Limiting direct PCI/PCI transfers |
| 236 | [ 0.248372] pci 0000:00:01.0: PIIX3: Enabling Passive Release |
| 237 | [ 0.250658] pci 0000:00:01.0: Activating ISA DMA hang workarounds |
| 238 | [ 0.286459] ACPI: PCI Interrupt Link [LNKD] enabled at IRQ 11 |
| 239 | [ 0.323750] Unpacking initramfs... |
| 240 | [ 0.656748] Freeing initrd memory: 15796K (ffff880036116000 - ffff880037083000) |
| 241 | [ 0.658296] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) |
| 242 | [ 0.659074] software IO TLB [mem 0xbbfe0000-0xbffe0000] (64MB) mapped at [ffff8800bbfe0000-ffff8800bffdffff] |
| 243 | [ 0.686209] microcode: CPU0 sig=0x206a1, pf=0x1, revision=0x1 |
| 244 | [ 0.687100] microcode: CPU1 sig=0x206a1, pf=0x1, revision=0x1 |
| 245 | [ 0.688518] microcode: Microcode Update Driver: v2.00 <tigran@aivazian.fsnet.co.uk>, Peter Oruba |
| 246 | [ 0.690820] futex hash table entries: 512 (order: 3, 32768 bytes) |
| 247 | [ 0.692086] audit: initializing netlink subsys (disabled) |
| 248 | [ 0.694015] audit: type=2000 audit(1466472478.423:1): initialized |
| 249 | [ 0.695808] HugeTLB registered 2 MB page size, pre-allocated 0 pages |
| 250 | [ 0.697093] zbud: loaded |
| 251 | [ 0.698171] VFS: Disk quotas dquot_6.5.2 |
| 252 | [ 0.699093] Dquot-cache hash table entries: 512 (order 0, 4096 bytes) |
| 253 | [ 0.700456] msgmni has been set to 7926 |
| 254 | [ 0.702076] alg: No test for stdrng (krng) |
| 255 | [ 0.703009] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 252) |
| 256 | [ 0.704667] io scheduler noop registered |
| 257 | [ 0.706540] io scheduler deadline registered |
| 258 | [ 0.707601] io scheduler cfq registered (default) |
| 259 | [ 0.708754] pci_hotplug: PCI Hot Plug PCI Core version: 0.5 |
| 260 | [ 0.709918] pciehp: PCI Express Hot Plug Controller Driver version: 0.4 |
| 261 | [ 0.711262] GHES: HEST is not enabled! |
| 262 | [ 0.712243] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled |
| 263 | [ 0.739695] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A |
| 264 | [ 0.768088] 00:05: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A |
| 265 | [ 0.769616] Linux agpgart interface v0.103 |
| 266 | [ 0.770317] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 |
| 267 | [ 0.772180] serio: i8042 KBD port at 0x60,0x64 irq 1 |
| 268 | [ 0.774193] serio: i8042 AUX port at 0x60,0x64 irq 12 |
| 269 | [ 0.775947] mousedev: PS/2 mouse device common for all mice |
| 270 | [ 0.778430] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input0 |
| 271 | [ 0.779691] rtc_cmos 00:00: RTC can wake from S4 |
| 272 | [ 0.780580] rtc_cmos 00:00: rtc core: registered rtc_cmos as rtc0 |
| 273 | [ 0.782253] rtc_cmos 00:00: alarms up to one day, 114 bytes nvram |
| 274 | [ 0.783016] ledtrig-cpu: registered to indicate activity on CPUs |
| 275 | [ 0.783817] AMD IOMMUv2 driver by Joerg Roedel <joerg.roedel@amd.com> |
| 276 | [ 0.784592] AMD IOMMUv2 functionality not available on this system |
| 277 | [ 0.785419] TCP: cubic registered |
| 278 | [ 0.785999] NET: Registered protocol family 10 |
| 279 | [ 0.787330] mip6: Mobile IPv6 |
| 280 | [ 0.787799] NET: Registered protocol family 17 |
| 281 | [ 0.788393] mpls_gso: MPLS GSO support |
| 282 | [ 0.790543] registered taskstats version 1 |
| 283 | [ 0.791532] rtc_cmos 00:00: setting system clock to 2016-06-21 01:27:57 UTC (1466472477) |
| 284 | [ 0.794125] Freeing unused kernel memory: 1204K (ffffffff818ee000 - ffffffff81a1b000) |
| 285 | [ 0.795167] Write protecting the kernel read-only data: 8192k |
| 286 | [ 0.796552] Freeing unused kernel memory: 912K (ffff88000151c000 - ffff880001600000) |
| 287 | [ 0.798266] Freeing unused kernel memory: 212K (ffff8800017cb000 - ffff880001800000) |
| 288 | Loading, please wait... |
| 289 | [ 0.810465] systemd-udevd[60]: starting version 215 |
| 290 | [ 0.811709] random: systemd-udevd urandom read with 1 bits of entropy available |
| 291 | [ 0.818832] SCSI subsystem initialized |
| 292 | [ 0.828546] ACPI: bus type USB registered |
| 293 | [ 0.829379] usbcore: registered new interface driver usbfs |
| 294 | [ 0.830140] usbcore: registered new interface driver hub |
| 295 | [ 0.844191] usbcore: registered new device driver usb |
| 296 | [ 0.845307] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver |
| 297 | [ 0.846363] uhci_hcd: USB Universal Host Controller Interface driver |
| 298 | [ 0.848302] FDC 0 is a S82078B |
| 299 | [ 0.859392] ACPI: PCI Interrupt Link [LNKC] enabled at IRQ 10 |
| 300 | [ 0.862648] scsi0 : ata_piix |
| 301 | [ 0.863175] scsi1 : ata_piix |
| 302 | [ 0.863622] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc0a0 irq 14 |
| 303 | [ 0.864307] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc0a8 irq 15 |
| 304 | [ 0.893512] uhci_hcd 0000:00:01.2: UHCI Host Controller |
| 305 | [ 0.894260] uhci_hcd 0000:00:01.2: new USB bus registered, assigned bus number 1 |
| 306 | [ 0.895251] uhci_hcd 0000:00:01.2: detected 2 ports |
| 307 | [ 0.895950] uhci_hcd 0000:00:01.2: irq 11, io base 0x0000c040 |
| 308 | [ 0.896755] usb usb1: New USB device found, idVendor=1d6b, idProduct=0001 |
| 309 | [ 0.897981] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1 |
| 310 | [ 0.898954] usb usb1: Product: UHCI Host Controller |
| 311 | [ 0.899584] usb usb1: Manufacturer: Linux 3.16.0-4-amd64 uhci_hcd |
| 312 | [ 0.900428] usb usb1: SerialNumber: 0000:00:01.2 |
| 313 | [ 0.901358] hub 1-0:1.0: USB hub found |
| 314 | [ 0.902093] hub 1-0:1.0: 2 ports detected |
| 315 | [ 0.950937] ACPI: PCI Interrupt Link [LNKA] enabled at IRQ 10 |
| 316 | [ 0.959370] vda: vda1 |
| 317 | Begin: Loading essential drivers ... done. |
| 318 | Begin: Running /scripts/init-premount ... done. |
| 319 | Begin: Mounting root file system ... Begin: Running /scripts/local-top ... done. |
| 320 | Begin: Running /scripts/local-premount ... done. |
| 321 | Begin: Will now check root file system ... fsck from util-linux 2.25.2 |
| 322 | [/sbin/fsck.ext4 (1) -- /dev/vda1] fsck.ext4 -a -C0 /dev/vda1 |
| 323 | cloudimg-rootfs: recovering journal |
| 324 | cloudimg-rootfs: Clearing orphaned inode 13966 (uid=108, gid=112, mode=0100600, size=0) |
| 325 | cloudimg-rootfs: Clearing orphaned inode 13965 (uid=108, gid=112, mode=0100600, size=0) |
| 326 | cloudimg-rootfs: Clearing orphaned inode 13964 (uid=108, gid=112, mode=0100600, size=0) |
| 327 | cloudimg-rootfs: Clearing orphaned inode 13963 (uid=108, gid=112, mode=0100600, size=0) |
| 328 | cloudimg-rootfs: Clearing orphaned inode 13962 (uid=108, gid=112, mode=0100600, size=0) |
| 329 | cloudimg-rootfs: Clearing orphaned inode 524505 (uid=0, gid=0, mode=0100644, size=160344) |
| 330 | cloudimg-rootfs: Clearing orphaned inode 524504 (uid=0, gid=0, mode=0100644, size=122440) |
| 331 | cloudimg-rootfs: Clearing orphaned inode 530021 (uid=0, gid=0, mode=0100644, size=9869280) |
| 332 | cloudimg-rootfs: Clearing orphaned inode 524520 (uid=0, gid=0, mode=0100644, size=89240) |
| 333 | cloudimg-rootfs: Clearing orphaned inode 524515 (uid=0, gid=0, mode=0100644, size=114200) |
| 334 | cloudimg-rootfs: Clearing orphaned inode 524525 (uid=0, gid=0, mode=0100644, size=415168) |
| 335 | cloudimg-rootfs: Clearing orphaned inode 524517 (uid=0, gid=0, mode=0100644, size=68696) |
| 336 | cloudimg-rootfs: Clearing orphaned inode 524508 (uid=0, gid=0, mode=0100644, size=36168) |
| 337 | cloudimg-rootfs: Clearing orphaned inode 524507 (uid=0, gid=0, mode=0100644, size=155560) |
| 338 | cloudimg-rootfs: Clearing orphaned inode 524506 (uid=0, gid=0, mode=0100644, size=60504) |
| 339 | cloudimg-rootfs: Clearing orphaned inode 524521 (uid=0, gid=0, mode=0100644, size=44680) |
| 340 | cloudimg-rootfs: Clearing orphaned inode 524519 (uid=0, gid=0, mode=0100644, size=143224) |
| 341 | cloudimg-rootfs: Clearing orphaned inode 524518 (uid=0, gid=0, mode=0100644, size=27912) |
| 342 | cloudimg-rootfs: Clearing orphaned inode 524516 (uid=0, gid=0, mode=0100644, size=53880) |
| 343 | cloudimg-rootfs: Clearing orphaned inode 524524 (uid=0, gid=0, mode=0100644, size=52376) |
| 344 | cloudimg-rootfs: Clearing orphaned inode 524509 (uid=0, gid=0, mode=0100644, size=102584) |
| 345 | cloudimg-rootfs: Clearing orphaned inode 15801 (uid=0, gid=0, mode=0100644, size=194544) |
| 346 | cloudimg-rootfs: Clearing orphaned inode 5563 (uid=0, gid=0, mode=0100644, size=165864) |
| 347 | cloudimg-rootfs: Clearing orphaned inode 14380 (uid=0, gid=0, mode=0100644, size=1607712) |
| 348 | cloudimg-rootfs: Clearing orphaned inode 8472 (uid=0, gid=0, mode=0100666, size=0) |
| 349 | cloudimg-rootfs: clean, 98108/10321920 files, 1500205/10484756 blocks |
| 350 | [ 1.212057] usb 1-1: new full-speed USB device number 2 using uhci_hcd |
| 351 | done. |
| 352 | [ 1.324224] EXT4-fs (vda1): mounted filesystem with ordered data mode. Opts: (null) |
| 353 | done. |
| 354 | Begin: Running /scripts/local-bottom ... done. |
| 355 | Begin: Running /scripts/init-bottom ... done. |
| 356 | [ 1.373021] usb 1-1: New USB device found, idVendor=0627, idProduct=0001 |
| 357 | [ 1.374614] usb 1-1: New USB device strings: Mfr=1, Product=3, SerialNumber=5 |
| 358 | [ 1.375947] usb 1-1: Product: QEMU USB Tablet |
| 359 | [ 1.376914] usb 1-1: Manufacturer: QEMU |
| 360 | [ 1.378390] usb 1-1: SerialNumber: 42 |
| 361 | [ 1.422216] systemd[1]: systemd 215 running in system mode. (+PAM +AUDIT +SELINUX +IMA +SYSVINIT +LIBCRYPTSETUP +GCRYPT +ACL +XZ -SECCOMP -APPARMOR) |
| 362 | [ 1.424761] systemd[1]: Detected virtualization 'kvm'. |
| 363 | [ 1.426342] systemd[1]: Detected architecture 'x86-64'. |
| 364 | |
| 365 | Welcome to [1mDebian GNU/Linux 8 (jessie)[0m! |
| 366 | |
| 367 | [ 1.451857] systemd[1]: Inserted module 'autofs4' |
| 368 | [ 1.454136] systemd[1]: Set hostname to <ci-jessie-wikimedia-1466259240>. |
| 369 | [ 1.573321] systemd[1]: Cannot add dependency job for unit dbus.socket, ignoring: Unit dbus.socket failed to load: No such file or directory. |
| 370 | [ 1.576075] systemd[1]: Cannot add dependency job for unit display-manager.service, ignoring: Unit display-manager.service failed to load: No such file or directory. |
| 371 | [ 1.579904] systemd[1]: Expecting device dev-ttyS0.device... |
| 372 | Expecting device dev-ttyS0.device... |
| 373 | [ 1.583028] systemd[1]: Starting Forward Password Requests to Wall Directory Watch. |
| 374 | [ 1.584523] systemd[1]: Started Forward Password Requests to Wall Directory Watch. |
| 375 | [ 1.586708] systemd[1]: Starting Remote File Systems (Pre). |
| 376 | [[32m OK [0m] Reached target Remote File Systems (Pre). |
| 377 | [ 1.589989] systemd[1]: Reached target Remote File Systems (Pre). |
| 378 | [ 1.591862] systemd[1]: Starting Dispatch Password Requests to Console Directory Watch. |
| 379 | [ 1.594190] systemd[1]: Started Dispatch Password Requests to Console Directory Watch. |
| 380 | [ 1.595312] systemd[1]: Starting Paths. |
| 381 | [[32m OK [0m] Reached target Paths. |
| 382 | [ 1.596561] systemd[1]: Reached target Paths. |
| 383 | [ 1.602617] systemd[1]: Starting Encrypted Volumes. |
| 384 | [[32m OK [0m] Reached target Encrypted Volumes. |
| 385 | [ 1.604395] systemd[1]: Reached target Encrypted Volumes. |
| 386 | [ 1.605590] systemd[1]: Starting Arbitrary Executable File Formats File System Automount Point. |
| 387 | [[32m OK [0m] Set up automount Arbitrary Executable File Formats F...utomount Point. |
| 388 | [ 1.607839] systemd[1]: Set up automount Arbitrary Executable File Formats File System Automount Point. |
| 389 | [ 1.609123] systemd[1]: Starting Swap. |
| 390 | [[32m OK [0m] Reached target Swap. |
| 391 | [ 1.610525] systemd[1]: Reached target Swap. |
| 392 | [ 1.611117] systemd[1]: Starting Root Slice. |
| 393 | [[32m OK [0m] Created slice Root Slice. |
| 394 | [ 1.612566] systemd[1]: Created slice Root Slice. |
| 395 | [ 1.613512] systemd[1]: Starting User and Session Slice. |
| 396 | [[32m OK [0m] Created slice User and Session Slice. |
| 397 | [ 1.615015] systemd[1]: Created slice User and Session Slice. |
| 398 | [ 1.615854] systemd[1]: Starting Delayed Shutdown Socket. |
| 399 | [[32m OK [0m] Listening on Delayed Shutdown Socket. |
| 400 | [ 1.618063] systemd[1]: Listening on Delayed Shutdown Socket. |
| 401 | [ 1.618841] systemd[1]: Starting /dev/initctl Compatibility Named Pipe. |
| 402 | [[32m OK [0m] Listening on /dev/initctl Compatibility Named Pipe. |
| 403 | [ 1.620990] systemd[1]: Listening on /dev/initctl Compatibility Named Pipe. |
| 404 | [ 1.622276] systemd[1]: Starting Journal Socket (/dev/log). |
| 405 | [[32m OK [0m] Listening on Journal Socket (/dev/log). |
| 406 | [ 1.623880] systemd[1]: Listening on Journal Socket (/dev/log). |
| 407 | [ 1.624773] systemd[1]: Starting udev Kernel Socket. |
| 408 | [[32m OK [0m] Listening on udev Kernel Socket. |
| 409 | [ 1.626389] systemd[1]: Listening on udev Kernel Socket. |
| 410 | [ 1.627202] systemd[1]: Starting udev Control Socket. |
| 411 | [[32m OK [0m] Listening on udev Control Socket. |
| 412 | [ 1.628730] systemd[1]: Listening on udev Control Socket. |
| 413 | [ 1.629907] systemd[1]: Starting Journal Socket. |
| 414 | [[32m OK [0m] Listening on Journal Socket. |
| 415 | [ 1.631469] systemd[1]: Listening on Journal Socket. |
| 416 | [ 1.632211] systemd[1]: Starting System Slice. |
| 417 | [[32m OK [0m] Created slice System Slice. |
| 418 | [ 1.634226] systemd[1]: Created slice System Slice. |
| 419 | [ 1.634913] systemd[1]: Started File System Check on Root Device. |
| 420 | [ 1.635716] systemd[1]: Starting system-getty.slice. |
| 421 | [[32m OK [0m] Created slice system-getty.slice. |
| 422 | [ 1.637329] systemd[1]: Created slice system-getty.slice. |
| 423 | [ 1.638095] systemd[1]: Starting system-serial\x2dgetty.slice. |
| 424 | [[32m OK [0m] Created slice system-serial\x2dgetty.slice. |
| 425 | [ 1.639728] systemd[1]: Created slice system-serial\x2dgetty.slice. |
| 426 | [ 1.640842] systemd[1]: Starting Increase datagram queue length... |
| 427 | Starting Increase datagram queue length... |
| 428 | [ 1.644694] systemd[1]: Starting Load Kernel Modules... |
| 429 | Starting Load Kernel Modules... |
| 430 | [ 1.646407] systemd[1]: Starting Create list of required static device nodes for the current kernel... |
| 431 | Starting Create list of required static device nodes...rrent kernel... |
| 432 | [ 1.649825] systemd[1]: Started Set Up Additional Binary Formats. |
| 433 | [ 1.650674] systemd[1]: Mounting POSIX Message Queue File System... |
| 434 | Mounting POSIX Message Queue File System... |
| 435 | [ 1.654080] systemd[1]: Mounting Huge Pages File System... |
| 436 | Mounting Huge Pages File System... |
| 437 | [ 1.657909] systemd[1]: Starting udev Coldplug all Devices... |
| 438 | [ 1.660547] tsc: Refined TSC clocksource calibration: 2597.016 MHz |
| 439 | Starting udev Coldplug all Devices... |
| 440 | [ 1.663819] systemd[1]: Mounting Debug File System... |
| 441 | Mounting Debug File System... |
| 442 | [ 1.667362] systemd[1]: Starting Slices. |
| 443 | [[32m OK [0m] Reached target Slices. |
| 444 | [ 1.668930] systemd[1]: Reached target Slices. |
| 445 | [ 1.670191] systemd[1]: Starting Remount Root and Kernel File Systems... |
| 446 | [ 1.670262] input: ImExPS/2 Generic Explorer Mouse as /devices/platform/i8042/serio1/input/input2 |
| 447 | Starting Remount Root and Kernel File Systems... |
| 448 | [[32m OK [0m] Mounted Debug File System. |
| 449 | [ 1.676041] systemd[1]: Mounted Debug File System. |
| 450 | [[32m OK [0m] Mounted Huge Pages File System. |
| 451 | [ 1.678648] systemd[1]: Mounted Huge Pages File System. |
| 452 | [[32m OK [0m] Mounted POSIX Message Queue File System. |
| 453 | [ 1.680323] systemd[1]: Mounted POSIX Message Queue File System. |
| 454 | [[32m OK [0m] Started Increase datagram queue length. |
| 455 | [ 1.683216] systemd[1]: Started Increase datagram queue length. |
| 456 | [ 1.684806] EXT4-fs (vda1): re-mounted. Opts: errors=remount-ro |
| 457 | [[32m OK [0m] Started Load Kernel Modules. |
| 458 | [ 1.687711] systemd[1]: Started Load Kernel Modules. |
| 459 | [[32m OK [0m] Started Create list of required static device nodes ...current kernel. |
| 460 | [ 1.690437] systemd[1]: Started Create list of required static device nodes for the current kernel. |
| 461 | [[32m OK [0m] Started Remount Root and Kernel File Systems. |
| 462 | [ 1.693423] systemd[1]: Started Remount Root and Kernel File Systems. |
| 463 | [[32m OK [0m] Started udev Coldplug all Devices. |
| 464 | [ 1.703313] systemd[1]: Started udev Coldplug all Devices. |
| 465 | [ 1.705664] systemd[1]: Started Various fixups to make systemd work better on Debian. |
| 466 | [ 1.706784] systemd[1]: Starting Load/Save Random Seed... |
| 467 | Starting Load/Save Random Seed... |
| 468 | [ 1.708444] systemd[1]: Starting Create Static Device Nodes in /dev... |
| 469 | Starting Create Static Device Nodes in /dev... |
| 470 | [ 1.710450] systemd[1]: Starting Apply Kernel Variables... |
| 471 | Starting Apply Kernel Variables... |
| 472 | [ 1.712376] systemd[1]: Mounted FUSE Control File System. |
| 473 | [ 1.713999] systemd[1]: Mounted Configuration File System. |
| 474 | [ 1.714857] systemd[1]: Starting Syslog Socket. |
| 475 | [[32m OK [0m] Listening on Syslog Socket. |
| 476 | [ 1.717549] systemd[1]: Listening on Syslog Socket. |
| 477 | [ 1.718413] systemd[1]: Starting Sockets. |
| 478 | [[32m OK [0m] Reached target Sockets. |
| 479 | [ 1.719915] systemd[1]: Reached target Sockets. |
| 480 | [ 1.720671] systemd[1]: Starting Journal Service... |
| 481 | Starting Journal Service... |
| 482 | [[32m OK [0m] Started Journal Service. |
| 483 | [ 1.724727] systemd[1]: Started Journal Service. |
| 484 | [[32m OK [0m] Started Load/Save Random Seed. |
| 485 | [[32m OK [0m] Started Apply Kernel Variables. |
| 486 | [[32m OK [0m] Started Create Static Device Nodes in /dev. |
| 487 | Starting udev Kernel Device Manager... |
| 488 | [[32m OK [0m] Reached target Local File Systems (Pre). |
| 489 | [[32m OK [0m] Reached target Local File Systems. |
| 490 | Starting Create Volatile Files and Directories... |
| 491 | Starting LSB: Raise network interfaces.... |
| 492 | [[32m OK [0m] Reached target Remote File Systems. |
| 493 | [ 1.757739] systemd-udevd[172]: starting version 215 |
| 494 | Starting Trigger Flushing of Journal to Persistent Storage... |
| 495 | Starting LSB: Prepare console... |
| 496 | [[32m OK [0m] Started udev Kernel Device Manager. |
| 497 | [[32m OK [0m] Started Create Volatile Files and Directories. |
| 498 | [ 1.782676] systemd-journald[170]: Received request to flush runtime journal from PID 1 |
| 499 | Starting Update UTMP about System Boot/Shutdown... |
| 500 | Starting Copy rules generated while the root was ro... |
| 501 | [[32m OK [0m] Started Trigger Flushing of Journal to Persistent Storage. |
| 502 | [[32m OK [0m] Started Copy rules generated while the root was ro. |
| 503 | [[32m OK [0m] Started Update UTMP about System Boot/Shutdown. |
| 504 | [ 1.822861] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input3 |
| 505 | [ 1.824041] ACPI: Power Button [PWRF] |
| 506 | [ 1.836437] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 |
| 507 | [ 1.849575] [drm] Initialized drm 1.1.0 20060810 |
| 508 | [[32m OK [0m] Found device /dev/ttyS0. |
| 509 | [ 1.861694] hidraw: raw HID events driver (C) Jiri Kosina |
| 510 | [ 1.862519] AVX2 version of gcm_enc/dec engaged. |
| 511 | [ 1.871721] usbcore: registered new interface driver usbhid |
| 512 | [ 1.872563] usbhid: USB HID core driver |
| 513 | [ 1.879547] ppdev: user-space parallel port driver |
| 514 | [ 1.882230] input: QEMU QEMU USB Tablet as /devices/pci0000:00/0000:00:01.2/usb1/1-1/1-1:1.0/0003:0627:0001.0001/input/input4 |
| 515 | [ 1.884969] hid-generic 0003:0627:0001.0001: input,hidraw0: USB HID v0.01 Pointer [QEMU QEMU USB Tablet] on usb-0000:00:01.2-1/input0 |
| 516 | [ 1.886045] alg: No test for __gcm-aes-aesni (__driver-gcm-aes-aesni) |
| 517 | [ 1.897097] alg: No test for crc32 (crc32-pclmul) |
| 518 | [ 2.012827] intel_rapl: no valid rapl domains found in package 0 |
| 519 | [ 2.125816] intel_rapl: no valid rapl domains found in package 0 |
| 520 | [[32m OK [0m] Started LSB: Prepare console. |
| 521 | [[32m OK [0m] Started LSB: Raise network interfaces.. |
| 522 | [[32m OK [0m] Reached target Network. |
| 523 | [[32m OK [0m] Reached target Network is Online. |
| 524 | [[32m OK [0m] Reached target System Initialization. |
| 525 | [[32m OK [0m] Reached target Timers. |
| 526 | [[32m OK [0m] Reached target Basic System. |
| 527 | Starting Permanent X virtual framebuffer... |
| 528 | [[32m OK [0m] Started Permanent X virtual framebuffer. |
| 529 | Starting system statistics collector... |
| 530 | [[32m OK [0m] Started system statistics collector. |
| 531 | Starting etcd - highly-available key value store... |
| 532 | Starting Puppet agent... |
| 533 | Starting Regular background program processing daemon... |
| 534 | [[32m OK [0m] Started Regular background program processing daemon. |
| 535 | Starting /etc/rc.local Compatibility... |
| 536 | Starting getty on tty2-tty6 if dbus and logind are not available... |
| 537 | Starting LSB: Start and stop the mysql database server daemon... |
| 538 | Starting LSB: Zuul Merger... |
| 539 | Starting LSB: Cloud init local... |
| 540 | Starting LSB: puppet queue... |
| 541 | Starting LSB: Apache2 web server... |
| 542 | Starting LSB: Zuul... |
| 543 | Starting System Logging Service... |
| 544 | Starting Permit User Sessions... |
| 545 | [[32m OK [0m] Started /etc/rc.local Compatibility. |
| 546 | [[32m OK [0m] Started LSB: Zuul Merger. |
| 547 | [[32m OK [0m] Started LSB: puppet queue. |
| 548 | [[32m OK [0m] Started Permit User Sessions. |
| 549 | [[32m OK [0m] Started System Logging Service. |
| 550 | [[32m OK [0m] Started LSB: Zuul. |
| 551 | Starting Getty on tty4... |
| 552 | [[32m OK [0m] Started Getty on tty4. |
| 553 | Starting Getty on tty3... |
| 554 | [[32m OK [0m] Started Getty on tty3. |
| 555 | Starting Getty on tty2... |
| 556 | [[32m OK [0m] Started Getty on tty2. |
| 557 | Starting Getty on tty1... |
| 558 | [[32m OK [0m] Started Getty on tty1. |
| 559 | Starting Serial Getty on ttyS0... |
| 560 | [[32m OK [0m] Started Serial Getty on ttyS0. |
| 561 | [[32m OK [0m] Started etcd - highly-available key value store. |
| 562 | Starting Getty on tty5... |
| 563 | [[32m OK [0m] Started Getty on tty5. |
| 564 | Starting Getty on tty6... |
| 565 | [[32m OK [0m] Started Getty on tty6. |
| 566 | [[32m OK [0m] Started getty on tty2-tty6 if dbus and logind are not available. |
| 567 | [[32m OK [0m] Reached target Login Prompts. |
| 568 | [[32m OK [0m] Started LSB: Cloud init local. |
| 569 | Starting LSB: Cloud init... |
| 570 | [[32m OK [0m] Started LSB: Start and stop the mysql database server daemon. |
| 571 | [[32m OK [0m] Started LSB: Apache2 web server. |
| 572 | [[32m OK [0m] Started Puppet agent. |
| 573 | |
| 574 | Debian GNU/Linux 8 ci-jessie-wikimedia-152695 ttyS0 |
| 575 | |
| 576 | ci-jessie-wikimedia-152695 login: [ 10.376147] random: nonblocking pool is initialized |
| 577 | ci-info: +++++Authorized keys from /home/debian/.ssh/authorized_keys for user debian++++++ |
| 578 | ci-info: +---------+-------------------------------------------------+---------+---------+ |
| 579 | ci-info: | Keytype | Fingerprint (md5) | Options | Comment | |
| 580 | ci-info: +---------+-------------------------------------------------+---------+---------+ |
| 581 | ci-info: | ssh-rsa | 70:15:e4:b5:db:7e:b7:c6:de:60:cf:06:bd:72:46:6a | - | - | |
| 582 | ci-info: +---------+-------------------------------------------------+---------+---------+ |
| 583 | ec2: |
| 584 | ec2: ############################################################# |
| 585 | ec2: -----BEGIN SSH HOST KEY FINGERPRINTS----- |
| 586 | ec2: 1024 44:8b:c5:4c:7c:46:37:55:d6:0e:50:b0:84:27:9b:62 /etc/ssh/ssh_host_dsa_key.pub (DSA) |
| 587 | ec2: 256 12:44:f4:b7:47:2b:53:12:d9:6d:67:ad:8e:df:ab:02 /etc/ssh/ssh_host_ecdsa_key.pub (ECDSA) |
| 588 | ec2: 2048 8b:c0:27:69:e9:90:79:2e:0e:f2:db:1b:ad:78:e8:42 /etc/ssh/ssh_host_rsa_key.pub (RSA) |
| 589 | ec2: -----END SSH HOST KEY FINGERPRINTS----- |
| 590 | ec2: ############################################################# |
| 591 | -----BEGIN SSH HOST KEY KEYS----- |
| 592 | ecdsa-sha2-nistp256 AAAAE2VjZHNhLXNoYTItbmlzdHAyNTYAAAAIbmlzdHAyNTYAAABBBFyJusyyw+iRZd9fuYPmb5cOHPJIq/1DuXJrkzrC2X1VSnr6KmU4UjKVhROGV/wS5A5635CzyWdpe/8esI7q8dM= root@ci-jessie-wikimedia-152695 |
| 593 | ssh-rsa AAAAB3NzaC1yc2EAAAADAQABAAABAQC2WXCZx4Kb2i1D3Ukgu5ne4jNzpJD6AR3U6m8wtX4tN3YSSLHgqVIdEndqQljlflv0CQcsB1aZ+Ohe6AEN/nsh7+gSdK/3I4+XZKZX4+Iw+pWQA9LwMqNZY2o9WV4g4mNq6swn19amXnJypp4Gm2fPhyUzsSEFdSUeL7ycBbocLAw0OfapZzlJQn4P/jS1zCROLDj9hpxTXS02L9wySvQfudWl/2yCEVImRKupwOE2aBkkm7xnoQfOPgojDsYX+SonN/JjsDLEY/i5h5ZJTQnTaE2UspAdoabNWdoU6t1Obqy1zhv+KpZKjt3eJwS96ctLiAMYWqo9F47fHWns/dPJ root@ci-jessie-wikimedia-152695 |
| 594 | -----END SSH HOST KEY KEYS----- |
| 595 | [ 9240.100098] INFO: task jbd2/vda1-8:105 blocked for more than 120 seconds. |
| 596 | [ 9240.102134] Not tainted 3.16.0-4-amd64 #1 |
| 597 | [ 9240.103091] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. |
| 598 | [ 9240.104738] jbd2/vda1-8 D ffff880139db3078 0 105 2 0x00000000 |
| 599 | [ 9240.105960] ffff880139db2c20 0000000000000046 0000000000012f00 ffff8801398fffd8 |
| 600 | [ 9240.106738] 0000000000012f00 ffff880139db2c20 ffff88013fd137b0 ffff88013ffc7170 |
| 601 | [ 9240.107495] 0000000000000002 ffffffff811d7620 ffff8801398ffc80 ffff880139df2398 |
| 602 | [ 9240.108268] Call Trace: |
| 603 | [ 9240.108507] [<ffffffff811d7620>] ? generic_block_bmap+0x50/0x50 |
| 604 | [ 9240.109061] [<ffffffff815114a9>] ? io_schedule+0x99/0x120 |
| 605 | [ 9240.109585] [<ffffffff811d762a>] ? sleep_on_buffer+0xa/0x10 |
| 606 | [ 9240.110114] [<ffffffff8151182c>] ? __wait_on_bit+0x5c/0x90 |
| 607 | [ 9240.110665] [<ffffffff811d7620>] ? generic_block_bmap+0x50/0x50 |
| 608 | [ 9240.111225] [<ffffffff815118d7>] ? out_of_line_wait_on_bit+0x77/0x90 |
| 609 | [ 9240.111831] [<ffffffff810a7e90>] ? autoremove_wake_function+0x30/0x30 |
| 610 | [ 9240.112458] [<ffffffffa015442e>] ? jbd2_journal_commit_transaction+0x175e/0x1950 [jbd2] |
| 611 | [ 9240.113477] [<ffffffff810a2f21>] ? pick_next_task_fair+0x6e1/0x820 |
| 612 | [ 9240.114187] [<ffffffffa0157be2>] ? kjournald2+0xb2/0x240 [jbd2] |
| 613 | [ 9240.114869] [<ffffffff810a7e60>] ? prepare_to_wait_event+0xf0/0xf0 |
| 614 | [ 9240.115574] [<ffffffffa0157b30>] ? commit_timeout+0x10/0x10 [jbd2] |
| 615 | [ 9240.116287] [<ffffffff8108809d>] ? kthread+0xbd/0xe0 |
| 616 | [ 9240.116883] [<ffffffff81087fe0>] ? kthread_create_on_node+0x180/0x180 |
| 617 | [ 9240.117629] [<ffffffff81514958>] ? ret_from_fork+0x58/0x90 |
| 618 | [ 9240.118274] [<ffffffff81087fe0>] ? kthread_create_on_node+0x180/0x180 |
| 619 | [ 9240.119007] INFO: task etcd:436 blocked for more than 120 seconds. |
| 620 | [ 9240.119709] Not tainted 3.16.0-4-amd64 #1 |
| 621 | [ 9240.120269] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. |
| 622 | [ 9240.121254] etcd D ffff8800373dcff8 0 436 1 0x00000000 |
| 623 | [ 9240.122063] ffff8800373dcba0 0000000000000082 0000000000012f00 ffff880139f3ffd8 |
| 624 | [ 9240.123056] 0000000000012f00 ffff8800373dcba0 ffff880139df2000 000000000000586e |
| 625 | [ 9240.124056] ffff880139df2088 ffff880139df2024 ffff880139f3fed0 ffff880139df20a0 |
| 626 | [ 9240.125061] Call Trace: |
| 627 | [ 9240.125431] [<ffffffffa0157625>] ? jbd2_log_wait_commit+0x95/0x100 [jbd2] |
| 628 | [ 9240.126194] [<ffffffff810a7e60>] ? prepare_to_wait_event+0xf0/0xf0 |
| 629 | [ 9240.126905] [<ffffffffa0169770>] ? ext4_sync_file+0x280/0x310 [ext4] |
| 630 | [ 9240.127629] [<ffffffff811d5f0b>] ? do_fsync+0x4b/0x70 |
| 631 | [ 9240.128243] [<ffffffff8108695d>] ? posix_clock_realtime_get+0xd/0x10 |
| 632 | [ 9240.128965] [<ffffffff811d617c>] ? SyS_fsync+0xc/0x10 |
| 633 | [ 9240.129845] [<ffffffff81514a0d>] ? system_call_fast_compare_end+0x10/0x15 |
| 634 | [ 9360.128113] INFO: task jbd2/vda1-8:105 blocked for more than 120 seconds. |
| 635 | [ 9360.130404] Not tainted 3.16.0-4-amd64 #1 |
| 636 | [ 9360.130966] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. |
| 637 | [ 9360.131963] jbd2/vda1-8 D ffff880139db3078 0 105 2 0x00000000 |
| 638 | [ 9360.132823] ffff880139db2c20 0000000000000046 0000000000012f00 ffff8801398fffd8 |
| 639 | [ 9360.133829] 0000000000012f00 ffff880139db2c20 ffff88013fd137b0 ffff88013ffc7170 |
| 640 | [ 9360.134821] 0000000000000002 ffffffff811d7620 ffff8801398ffc80 ffff880139df2398 |
| 641 | [ 9360.135818] Call Trace: |
| 642 | [ 9360.136192] [<ffffffff811d7620>] ? generic_block_bmap+0x50/0x50 |
| 643 | [ 9360.136879] [<ffffffff815114a9>] ? io_schedule+0x99/0x120 |
| 644 | [ 9360.137521] [<ffffffff811d762a>] ? sleep_on_buffer+0xa/0x10 |
| 645 | [ 9360.138170] [<ffffffff8151182c>] ? __wait_on_bit+0x5c/0x90 |
| 646 | [ 9360.138827] [<ffffffff811d7620>] ? generic_block_bmap+0x50/0x50 |
| 647 | [ 9360.139508] [<ffffffff815118d7>] ? out_of_line_wait_on_bit+0x77/0x90 |
| 648 | [ 9360.140243] [<ffffffff810a7e90>] ? autoremove_wake_function+0x30/0x30 |
| 649 | [ 9360.140985] [<ffffffffa015442e>] ? jbd2_journal_commit_transaction+0x175e/0x1950 [jbd2] |
| 650 | [ 9360.142811] [<ffffffff810a2f21>] ? pick_next_task_fair+0x6e1/0x820 |
| 651 | [ 9360.143547] [<ffffffffa0157be2>] ? kjournald2+0xb2/0x240 [jbd2] |
| 652 | [ 9360.144263] [<ffffffff810a7e60>] ? prepare_to_wait_event+0xf0/0xf0 |
| 653 | [ 9360.144978] [<ffffffffa0157b30>] ? commit_timeout+0x10/0x10 [jbd2] |
| 654 | [ 9360.145703] [<ffffffff8108809d>] ? kthread+0xbd/0xe0 |
| 655 | [ 9360.146308] [<ffffffff81087fe0>] ? kthread_create_on_node+0x180/0x180 |
| 656 | [ 9360.147048] [<ffffffff81514958>] ? ret_from_fork+0x58/0x90 |
| 657 | [ 9360.147696] [<ffffffff81087fe0>] ? kthread_create_on_node+0x180/0x180 |
| 658 | [ 9360.148456] INFO: task etcd:436 blocked for more than 120 seconds. |
| 659 | [ 9360.149170] Not tainted 3.16.0-4-amd64 #1 |
| 660 | [ 9360.149730] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. |
| 661 | [ 9360.150714] etcd D ffff8800373dcff8 0 436 1 0x00000000 |
| 662 | [ 9360.151531] ffff8800373dcba0 0000000000000082 0000000000012f00 ffff880139f3ffd8 |
| 663 | [ 9360.152554] 0000000000012f00 ffff8800373dcba0 ffff880139df2000 000000000000586e |
| 664 | [ 9360.153988] ffff880139df2088 ffff880139df2024 ffff880139f3fed0 ffff880139df20a0 |
| 665 | [ 9360.154998] Call Trace: |
| 666 | [ 9360.155370] [<ffffffffa0157625>] ? jbd2_log_wait_commit+0x95/0x100 [jbd2] |
| 667 | [ 9360.156174] [<ffffffff810a7e60>] ? prepare_to_wait_event+0xf0/0xf0 |
| 668 | [ 9360.156906] [<ffffffffa0169770>] ? ext4_sync_file+0x280/0x310 [ext4] |
| 669 | [ 9360.157656] [<ffffffff811d5f0b>] ? do_fsync+0x4b/0x70 |
| 670 | [ 9360.158280] [<ffffffff8108695d>] ? posix_clock_realtime_get+0xd/0x10 |
| 671 | [ 9360.159017] [<ffffffff811d617c>] ? SyS_fsync+0xc/0x10 |
| 672 | [ 9360.159645] [<ffffffff81514a0d>] ? system_call_fast_compare_end+0x10/0x15 |
| 673 | [ 9480.160101] INFO: task jbd2/vda1-8:105 blocked for more than 120 seconds. |
| 674 | [ 9480.162484] Not tainted 3.16.0-4-amd64 #1 |
| 675 | [ 9480.163679] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. |
| 676 | [ 9480.166293] jbd2/vda1-8 D ffff880139db3078 0 105 2 0x00000000 |
| 677 | [ 9480.167136] ffff880139db2c20 0000000000000046 0000000000012f00 ffff8801398fffd8 |
| 678 | [ 9480.168159] 0000000000012f00 ffff880139db2c20 ffff88013fd137b0 ffff88013ffc7170 |
| 679 | [ 9480.169172] 0000000000000002 ffffffff811d7620 ffff8801398ffc80 ffff880139df2398 |
| 680 | [ 9480.170174] Call Trace: |
| 681 | [ 9480.170540] [<ffffffff811d7620>] ? generic_block_bmap+0x50/0x50 |
| 682 | [ 9480.171290] [<ffffffff815114a9>] ? io_schedule+0x99/0x120 |
| 683 | [ 9480.171930] [<ffffffff811d762a>] ? sleep_on_buffer+0xa/0x10 |
| 684 | [ 9480.172603] [<ffffffff8151182c>] ? __wait_on_bit+0x5c/0x90 |
| 685 | [ 9480.173326] [<ffffffff811d7620>] ? generic_block_bmap+0x50/0x50 |
| 686 | [ 9480.174015] [<ffffffff815118d7>] ? out_of_line_wait_on_bit+0x77/0x90 |
| 687 | [ 9480.174738] [<ffffffff810a7e90>] ? autoremove_wake_function+0x30/0x30 |
| 688 | [ 9480.175481] [<ffffffffa015442e>] ? jbd2_journal_commit_transaction+0x175e/0x1950 [jbd2] |
| 689 | [ 9480.176499] [<ffffffff810a2f21>] ? pick_next_task_fair+0x6e1/0x820 |
| 690 | [ 9480.177459] [<ffffffffa0157be2>] ? kjournald2+0xb2/0x240 [jbd2] |
| 691 | [ 9480.178708] [<ffffffff810a7e60>] ? prepare_to_wait_event+0xf0/0xf0 |
| 692 | [ 9480.179595] [<ffffffffa0157b30>] ? commit_timeout+0x10/0x10 [jbd2] |
| 693 | [ 9480.180366] [<ffffffff8108809d>] ? kthread+0xbd/0xe0 |
| 694 | [ 9480.181080] [<ffffffff81087fe0>] ? kthread_create_on_node+0x180/0x180 |
| 695 | [ 9480.182127] [<ffffffff81514958>] ? ret_from_fork+0x58/0x90 |
| 696 | [ 9480.182797] [<ffffffff81087fe0>] ? kthread_create_on_node+0x180/0x180 |
| 697 | [ 9480.183555] INFO: task etcd:436 blocked for more than 120 seconds. |
| 698 | [ 9480.184284] Not tainted 3.16.0-4-amd64 #1 |
| 699 | [ 9480.184834] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. |
| 700 | [ 9480.186131] etcd D ffff8800373dcff8 0 436 1 0x00000000 |
| 701 | [ 9480.186984] ffff8800373dcba0 0000000000000082 0000000000012f00 ffff880139f3ffd8 |
| 702 | [ 9480.187999] 0000000000012f00 ffff8800373dcba0 ffff880139df2000 000000000000586e |
| 703 | [ 9480.189026] ffff880139df2088 ffff880139df2024 ffff880139f3fed0 ffff880139df20a0 |
| 704 | [ 9480.190104] Call Trace: |
| 705 | [ 9480.190472] [<ffffffffa0157625>] ? jbd2_log_wait_commit+0x95/0x100 [jbd2] |
| 706 | [ 9480.191237] [<ffffffff810a7e60>] ? prepare_to_wait_event+0xf0/0xf0 |
| 707 | [ 9480.191949] [<ffffffffa0169770>] ? ext4_sync_file+0x280/0x310 [ext4] |
| 708 | [ 9480.192694] [<ffffffff811d5f0b>] ? do_fsync+0x4b/0x70 |
| 709 | [ 9480.193307] [<ffffffff8108695d>] ? posix_clock_realtime_get+0xd/0x10 |
| 710 | [ 9480.194035] [<ffffffff811d617c>] ? SyS_fsync+0xc/0x10 |
| 711 | [ 9480.194641] [<ffffffff81514a0d>] ? system_call_fast_compare_end+0x10/0x15 |
| 712 | [ 9600.192134] INFO: task jbd2/vda1-8:105 blocked for more than 120 seconds. |
| 713 | [ 9600.194263] Not tainted 3.16.0-4-amd64 #1 |
| 714 | [ 9600.195498] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. |
| 715 | [ 9600.197655] jbd2/vda1-8 D ffff880139db3078 0 105 2 0x00000000 |
| 716 | [ 9600.199420] ffff880139db2c20 0000000000000046 0000000000012f00 ffff8801398fffd8 |
| 717 | [ 9600.201806] 0000000000012f00 ffff880139db2c20 ffff88013fd137b0 ffff88013ffc7170 |
| 718 | [ 9600.202836] 0000000000000002 ffffffff811d7620 ffff8801398ffc80 ffff880139df2398 |
| 719 | [ 9600.203849] Call Trace: |
| 720 | [ 9600.204236] [<ffffffff811d7620>] ? generic_block_bmap+0x50/0x50 |
| 721 | [ 9600.204925] [<ffffffff815114a9>] ? io_schedule+0x99/0x120 |
| 722 | [ 9600.205593] [<ffffffff811d762a>] ? sleep_on_buffer+0xa/0x10 |
| 723 | [ 9600.206245] [<ffffffff8151182c>] ? __wait_on_bit+0x5c/0x90 |
| 724 | [ 9600.206890] [<ffffffff811d7620>] ? generic_block_bmap+0x50/0x50 |
| 725 | [ 9600.207618] [<ffffffff815118d7>] ? out_of_line_wait_on_bit+0x77/0x90 |
| 726 | [ 9600.208370] [<ffffffff810a7e90>] ? autoremove_wake_function+0x30/0x30 |
| 727 | [ 9600.209114] [<ffffffffa015442e>] ? jbd2_journal_commit_transaction+0x175e/0x1950 [jbd2] |
| 728 | [ 9600.210125] [<ffffffff810a2f21>] ? pick_next_task_fair+0x6e1/0x820 |
| 729 | [ 9600.210836] [<ffffffffa0157be2>] ? kjournald2+0xb2/0x240 [jbd2] |
| 730 | [ 9600.211522] [<ffffffff810a7e60>] ? prepare_to_wait_event+0xf0/0xf0 |
| 731 | [ 9600.212251] [<ffffffffa0157b30>] ? commit_timeout+0x10/0x10 [jbd2] |
| 732 | [ 9600.212961] [<ffffffff8108809d>] ? kthread+0xbd/0xe0 |
| 733 | [ 9600.213799] [<ffffffff81087fe0>] ? kthread_create_on_node+0x180/0x180 |
| 734 | [ 9600.214552] [<ffffffff81514958>] ? ret_from_fork+0x58/0x90 |
| 735 | [ 9600.215214] [<ffffffff81087fe0>] ? kthread_create_on_node+0x180/0x180 |
| 736 | [ 9600.215978] INFO: task etcd:436 blocked for more than 120 seconds. |
| 737 | [ 9600.216712] Not tainted 3.16.0-4-amd64 #1 |
| 738 | [ 9600.217288] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. |
| 739 | [ 9600.218290] etcd D ffff8800373dcff8 0 436 1 0x00000000 |
| 740 | [ 9600.219128] ffff8800373dcba0 0000000000000082 0000000000012f00 ffff880139f3ffd8 |
| 741 | [ 9600.220172] 0000000000012f00 ffff8800373dcba0 ffff880139df2000 000000000000586e |
| 742 | [ 9600.221224] ffff880139df2088 ffff880139df2024 ffff880139f3fed0 ffff880139df20a0 |
| 743 | [ 9600.222230] Call Trace: |
| 744 | [ 9600.222599] [<ffffffffa0157625>] ? jbd2_log_wait_commit+0x95/0x100 [jbd2] |
| 745 | [ 9600.223373] [<ffffffff810a7e60>] ? prepare_to_wait_event+0xf0/0xf0 |
| 746 | [ 9600.224104] [<ffffffffa0169770>] ? ext4_sync_file+0x280/0x310 [ext4] |
| 747 | [ 9600.224831] [<ffffffff811d5f0b>] ? do_fsync+0x4b/0x70 |
| 748 | [ 9600.225463] [<ffffffff8108695d>] ? posix_clock_realtime_get+0xd/0x10 |
| 749 | [ 9600.226186] [<ffffffff811d617c>] ? SyS_fsync+0xc/0x10 |
| 750 | [ 9600.226793] [<ffffffff81514a0d>] ? system_call_fast_compare_end+0x10/0x15 |
| 751 | [ 9720.224107] INFO: task jbd2/vda1-8:105 blocked for more than 120 seconds. |
| 752 | [ 9720.226898] Not tainted 3.16.0-4-amd64 #1 |
| 753 | [ 9720.228161] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. |
| 754 | [ 9720.230328] jbd2/vda1-8 D ffff880139db3078 0 105 2 0x00000000 |
| 755 | [ 9720.232118] ffff880139db2c20 0000000000000046 0000000000012f00 ffff8801398fffd8 |
| 756 | [ 9720.241292] 0000000000012f00 ffff880139db2c20 ffff88013fd137b0 ffff88013ffc7170 |
| 757 | [ 9720.242302] 0000000000000002 ffffffff811d7620 ffff8801398ffc80 ffff880139df2398 |
| 758 | [ 9720.243296] Call Trace: |
| 759 | [ 9720.243659] [<ffffffff811d7620>] ? generic_block_bmap+0x50/0x50 |
| 760 | [ 9720.244356] [<ffffffff815114a9>] ? io_schedule+0x99/0x120 |
| 761 | [ 9720.244992] [<ffffffff811d762a>] ? sleep_on_buffer+0xa/0x10 |
| 762 | [ 9720.245651] [<ffffffff8151182c>] ? __wait_on_bit+0x5c/0x90 |
| 763 | [ 9720.246295] [<ffffffff811d7620>] ? generic_block_bmap+0x50/0x50 |
| 764 | [ 9720.246982] [<ffffffff815118d7>] ? out_of_line_wait_on_bit+0x77/0x90 |
| 765 | [ 9720.247706] [<ffffffff810a7e90>] ? autoremove_wake_function+0x30/0x30 |
| 766 | [ 9720.248470] [<ffffffffa015442e>] ? jbd2_journal_commit_transaction+0x175e/0x1950 [jbd2] |
| 767 | [ 9720.249518] [<ffffffff810a2f21>] ? pick_next_task_fair+0x6e1/0x820 |
| 768 | [ 9720.250269] [<ffffffffa0157be2>] ? kjournald2+0xb2/0x240 [jbd2] |
| 769 | [ 9720.250964] [<ffffffff810a7e60>] ? prepare_to_wait_event+0xf0/0xf0 |
| 770 | [ 9720.251673] [<ffffffffa0157b30>] ? commit_timeout+0x10/0x10 [jbd2] |
| 771 | [ 9720.252399] [<ffffffff8108809d>] ? kthread+0xbd/0xe0 |
| 772 | [ 9720.253026] [<ffffffff81087fe0>] ? kthread_create_on_node+0x180/0x180 |
| 773 | [ 9720.253773] [<ffffffff81514958>] ? ret_from_fork+0x58/0x90 |
| 774 | [ 9720.254415] [<ffffffff81087fe0>] ? kthread_create_on_node+0x180/0x180 |
| 775 | [ 9720.255149] INFO: task etcd:436 blocked for more than 120 seconds. |
| 776 | [ 9720.255845] Not tainted 3.16.0-4-amd64 #1 |
| 777 | [ 9720.256431] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. |
| 778 | [ 9720.257419] etcd D ffff8800373dcff8 0 436 1 0x00000000 |
| 779 | [ 9720.258261] ffff8800373dcba0 0000000000000082 0000000000012f00 ffff880139f3ffd8 |
| 780 | [ 9720.259259] 0000000000012f00 ffff8800373dcba0 ffff880139df2000 000000000000586e |
| 781 | [ 9720.260267] ffff880139df2088 ffff880139df2024 ffff880139f3fed0 ffff880139df20a0 |
| 782 | [ 9720.261285] Call Trace: |
| 783 | [ 9720.261651] [<ffffffffa0157625>] ? jbd2_log_wait_commit+0x95/0x100 [jbd2] |
| 784 | [ 9720.262415] [<ffffffff810a7e60>] ? prepare_to_wait_event+0xf0/0xf0 |
| 785 | [ 9720.263134] [<ffffffffa0169770>] ? ext4_sync_file+0x280/0x310 [ext4] |
| 786 | [ 9720.263867] [<ffffffff811d5f0b>] ? do_fsync+0x4b/0x70 |
| 787 | [ 9720.264492] [<ffffffff8108695d>] ? posix_clock_realtime_get+0xd/0x10 |
| 788 | [ 9720.265231] [<ffffffff811d617c>] ? SyS_fsync+0xc/0x10 |
| 789 | [ 9720.265836] [<ffffffff81514a0d>] ? system_call_fast_compare_end+0x10/0x15 |
Really the disk is stall on that instance and the build timeout / Jenkins can not abort the build:
[ 9240.100098] INFO: task jbd2/vda1-8:105 blocked for more than 120 seconds. [ 9240.102134] Not tainted 3.16.0-4-amd64 #1 [ 9240.108507] [<ffffffff811d7620>] ? generic_block_bmap+0x50/0x50 [ 9240.109061] [<ffffffff815114a9>] ? io_schedule+0x99/0x120 [ 9240.109585] [<ffffffff811d762a>] ? sleep_on_buffer+0xa/0x10 [ 9240.110114] [<ffffffff8151182c>] ? __wait_on_bit+0x5c/0x90 [ 9240.110665] [<ffffffff811d7620>] ? generic_block_bmap+0x50/0x50 [ 9240.111225] [<ffffffff815118d7>] ? out_of_line_wait_on_bit+0x77/0x90 [ 9240.111831] [<ffffffff810a7e90>] ? autoremove_wake_function+0x30/0x30 [ 9240.112458] [<ffffffffa015442e>] ? jbd2_journal_commit_transaction+0x175e/0x1950 [jbd2] [ 9240.113477] [<ffffffff810a2f21>] ? pick_next_task_fair+0x6e1/0x820 [ 9240.114187] [<ffffffffa0157be2>] ? kjournald2+0xb2/0x240 [jbd2] [ 9240.114869] [<ffffffff810a7e60>] ? prepare_to_wait_event+0xf0/0xf0 [ 9240.115574] [<ffffffffa0157b30>] ? commit_timeout+0x10/0x10 [jbd2] [ 9240.116287] [<ffffffff8108809d>] ? kthread+0xbd/0xe0 [ 9240.116883] [<ffffffff81087fe0>] ? kthread_create_on_node+0x180/0x180 [ 9240.117629] [<ffffffff81514958>] ? ret_from_fork+0x58/0x90 [ 9240.118274] [<ffffffff81087fe0>] ? kthread_create_on_node+0x180/0x180 .... ---- >>! In T140256#2827310, @MoritzMuehlenhoff wrote: >>>! In T140256#2825802, @hashar wrote: >> I haven't seen that kernel soft lock occurring for a while. I guess it was a bug in the kernel that ran on labvirt hosts. > > That makes sense, the labvirt hosts were upgraded from 3.13 to 4.4 about a month ago.