Page MenuHomePhabricator

Instance deadlocking in June 2016
Closed, ResolvedPublic

Description

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

Nameci-jessie-wikimedia-152695
Instance ID1484908c-bd9b-4b4f-903a-39914a7e408e
Wikitechhttps://wikitech.wikimedia.org/wiki/Nova_Resource:Ci-jessie-wikimedia-152695.contintcloud.eqiad.wmflabs
ec2 idi-0002492b
Hostlabvirt1010
Base imaged604ca6b-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 ...
6text is deprecated. Use set gfxpayload=vga=normal before linux command
7instead.
8text is deprecated. Use set gfxpayload=vga=normal before linux command
9instead.
10Loading 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)
288Loading, 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
317Begin: Loading essential drivers ... done.
318Begin: Running /scripts/init-premount ... done.
319Begin: Mounting root file system ... Begin: Running /scripts/local-top ... done.
320Begin: Running /scripts/local-premount ... done.
321Begin: 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
323cloudimg-rootfs: recovering journal
324cloudimg-rootfs: Clearing orphaned inode 13966 (uid=108, gid=112, mode=0100600, size=0)
325cloudimg-rootfs: Clearing orphaned inode 13965 (uid=108, gid=112, mode=0100600, size=0)
326cloudimg-rootfs: Clearing orphaned inode 13964 (uid=108, gid=112, mode=0100600, size=0)
327cloudimg-rootfs: Clearing orphaned inode 13963 (uid=108, gid=112, mode=0100600, size=0)
328cloudimg-rootfs: Clearing orphaned inode 13962 (uid=108, gid=112, mode=0100600, size=0)
329cloudimg-rootfs: Clearing orphaned inode 524505 (uid=0, gid=0, mode=0100644, size=160344)
330cloudimg-rootfs: Clearing orphaned inode 524504 (uid=0, gid=0, mode=0100644, size=122440)
331cloudimg-rootfs: Clearing orphaned inode 530021 (uid=0, gid=0, mode=0100644, size=9869280)
332cloudimg-rootfs: Clearing orphaned inode 524520 (uid=0, gid=0, mode=0100644, size=89240)
333cloudimg-rootfs: Clearing orphaned inode 524515 (uid=0, gid=0, mode=0100644, size=114200)
334cloudimg-rootfs: Clearing orphaned inode 524525 (uid=0, gid=0, mode=0100644, size=415168)
335cloudimg-rootfs: Clearing orphaned inode 524517 (uid=0, gid=0, mode=0100644, size=68696)
336cloudimg-rootfs: Clearing orphaned inode 524508 (uid=0, gid=0, mode=0100644, size=36168)
337cloudimg-rootfs: Clearing orphaned inode 524507 (uid=0, gid=0, mode=0100644, size=155560)
338cloudimg-rootfs: Clearing orphaned inode 524506 (uid=0, gid=0, mode=0100644, size=60504)
339cloudimg-rootfs: Clearing orphaned inode 524521 (uid=0, gid=0, mode=0100644, size=44680)
340cloudimg-rootfs: Clearing orphaned inode 524519 (uid=0, gid=0, mode=0100644, size=143224)
341cloudimg-rootfs: Clearing orphaned inode 524518 (uid=0, gid=0, mode=0100644, size=27912)
342cloudimg-rootfs: Clearing orphaned inode 524516 (uid=0, gid=0, mode=0100644, size=53880)
343cloudimg-rootfs: Clearing orphaned inode 524524 (uid=0, gid=0, mode=0100644, size=52376)
344cloudimg-rootfs: Clearing orphaned inode 524509 (uid=0, gid=0, mode=0100644, size=102584)
345cloudimg-rootfs: Clearing orphaned inode 15801 (uid=0, gid=0, mode=0100644, size=194544)
346cloudimg-rootfs: Clearing orphaned inode 5563 (uid=0, gid=0, mode=0100644, size=165864)
347cloudimg-rootfs: Clearing orphaned inode 14380 (uid=0, gid=0, mode=0100644, size=1607712)
348cloudimg-rootfs: Clearing orphaned inode 8472 (uid=0, gid=0, mode=0100666, size=0)
349cloudimg-rootfs: clean, 98108/10321920 files, 1500205/10484756 blocks
350[ 1.212057] usb 1-1: new full-speed USB device number 2 using uhci_hcd
351done.
352[ 1.324224] EXT4-fs (vda1): mounted filesystem with ordered data mode. Opts: (null)
353done.
354Begin: Running /scripts/local-bottom ... done.
355Begin: 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
365Welcome 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
439Starting 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
574Debian GNU/Linux 8 ci-jessie-wikimedia-152695 ttyS0
575
576ci-jessie-wikimedia-152695 login: [ 10.376147] random: nonblocking pool is initialized
577ci-info: +++++Authorized keys from /home/debian/.ssh/authorized_keys for user debian++++++
578ci-info: +---------+-------------------------------------------------+---------+---------+
579ci-info: | Keytype | Fingerprint (md5) | Options | Comment |
580ci-info: +---------+-------------------------------------------------+---------+---------+
581ci-info: | ssh-rsa | 70:15:e4:b5:db:7e:b7:c6:de:60:cf:06:bd:72:46:6a | - | - |
582ci-info: +---------+-------------------------------------------------+---------+---------+
583ec2:
584ec2: #############################################################
585ec2: -----BEGIN SSH HOST KEY FINGERPRINTS-----
586ec2: 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)
587ec2: 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)
588ec2: 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)
589ec2: -----END SSH HOST KEY FINGERPRINTS-----
590ec2: #############################################################
591-----BEGIN SSH HOST KEY KEYS-----
592ecdsa-sha2-nistp256 AAAAE2VjZHNhLXNoYTItbmlzdHAyNTYAAAAIbmlzdHAyNTYAAABBBFyJusyyw+iRZd9fuYPmb5cOHPJIq/1DuXJrkzrC2X1VSnr6KmU4UjKVhROGV/wS5A5635CzyWdpe/8esI7q8dM= root@ci-jessie-wikimedia-152695
593ssh-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.

Event Timeline

Restricted Application added a subscriber: Aklapper. · View Herald TranscriptDec 7 2016, 12:49 PM
hashar closed this task as Resolved.Dec 7 2016, 12:52 PM
hashar claimed this task.

The actual issue is fixed. I filled this task as an umbrella Tracking-Neverending task for several related issues (T129891 T138281 T140256).

It all solved, most probably via a kernel upgrade.