Subject: Re: [vserver] Re: Kernel Panic
From: Herbert Poetzl <herbert@13thfloor.at>
Date: Tue, 18 Oct 2011 16:13:13 +0200

On Tue, Oct 18, 2011 at 03:10:42PM +0200, Romain Riviere wrote:
> Hi list,

> There are lots of kernel logs below. I am looking for help with
> kernel panics that are getting on my nerves these days. Please
> help me restore some of my health and sanity :-) Here goes.

> I have had another panic just like the one I've already
> described. The first time, this is what happened:
> 1) Aug 30,  BUG unable to handle kernel paging request
> 2) Aug 30 to Sept 30, 1 to 2 page allocation failure per DAY,
>    the trace is almost exactly the same (see below)
> 3) Sept 30, BUG unable to handle kernel NULL pointer
>    dereference, then kernel panic

> The call trace for the first paging request and for the null
> pointer dereference consistently display this line:
> "last sysfs file: /sys/devices/platform/coretemp.3/temp1_input"

> On Oct 15, 1) happened again, and on Oct 18, 3) happened
> again. The stack traces are about 90% identical to the first
> occurrence.

first, you could collect all those traces and do an addr2line
for the EIP address and the first few stack addresses, and
put those annotated dumps somewhere to look at them ...

> The kernel is still 2.6.38.7-vs2.3.0.37-rc15, and munin always
> seems to be involved.

> My questions, if someone can make sense out of this, are:
> - the kernel paging request is consistent about the last 
>   sysfs file being coretemp.3/temp1_input: 
>   what would that indicate?

that something (munin?) is constantly polling sysfs for the
cpu temperature and coretemp.3/temp1_input is the last one
in the sequence ...

> - the page allocation failures are also very consistent in 
>   their content: same question?

not seeing that yet, but let's see when we have the annotated
collection of stack traces ...

> - I am running the same kernel on a nearly identical server
> (slightly different CPU and RAID card, 8GB RAM instead of 4)
> and *NEVER* had a single call trace since I started using the
> kernel. 

> Would this conclusively prove that it is hardware related?

no, it could be a difference in the running software or even
in the load as well, but of course, a hardware problem could
cause all kind of issues ...

IMHO simplest way to check that is to swap the software
installation between those systems, i.e. the entire software
installation (host and guests) and see what happens ...

> I am probably going to have the memory checked anyway, but any
> input would be greatly appreciated.

> Many thanks and very best,
> --
> Romain Riviere

> Aug 30 05:45:04 srv505 BUG: unable to handle kernel 
> Aug 30 05:45:04 srv505 paging request
> Aug 30 05:45:04 srv505 at 00200200
> Aug 30 05:45:04 srv505 IP:
> Aug 30 05:45:04 srv505 [<c10ae56c>] unlink_anon_vmas+0x1c/0x93
> Aug 30 05:45:04 srv505 *pdpt = 0000000000000000 
> Aug 30 05:45:04 srv505 *pde = f000ff53f000e2c3 
> Aug 30 05:45:04 srv505 
> Aug 30 05:45:04 srv505 Oops: 0000 [#1] 
> Aug 30 05:45:04 srv505 SMP 
> Aug 30 05:45:04 srv505 
> Aug 30 05:45:04 srv505 last sysfs file: /sys/devices/platform/coretemp.3/temp1_input
> Aug 30 05:45:04 srv505 
> Aug 30 05:45:04 srv505 Pid: 30663, comm: munin-node Not tainted 2.6.38.7-vs2.3.0.37-rc15
#2
> Aug 30 05:45:04 srv505 
> Aug 30 05:45:04 srv505 Supermicro X7SBi
> Aug 30 05:45:04 srv505 /
> Aug 30 05:45:04 srv505 X7SBi
> Aug 30 05:45:04 srv505 
> Aug 30 05:45:04 srv505 EIP: 0060:[<c10ae56c>] EFLAGS: 00010206 CPU: 0
				   ~~~~~~~~~~~~ EIP address
> Aug 30 05:45:04 srv505 EIP is at unlink_anon_vmas+0x1c/0x93
> Aug 30 05:45:04 srv505 EAX: f263fd80 EBX: f263fd78 ECX: f277e934 EDX: 00100100
> Aug 30 05:45:04 srv505 ESI: 00200200 EDI: 001000f8 EBP: f277ec24 ESP: d989dedc
> Aug 30 05:45:04 srv505 DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068
> Aug 30 05:45:04 srv505 Process munin-node (pid: 30663, ti=d989c000 task=f2898430 task.ti=d989c000)
> (...)
> Aug 30 05:45:04 srv505 Call Trace:
> Aug 30 05:45:04 srv505 [<c10a90f1>] ? free_pgtables+0x43/0x7e
			 ~~~~~~~~~~~~ first stack address
> Aug 30 05:45:04 srv505 [<c10aa6ec>] ? exit_mmap+0xc4/0x113
> Aug 30 05:45:04 srv505 [<c104d76d>] ? mmput+0x1c/0x7a
> Aug 30 05:45:04 srv505 [<c1050a96>] ? exit_mm+0x103/0x10b
> Aug 30 05:45:04 srv505 [<c1052006>] ? do_exit+0x1ca/0x618
> Aug 30 05:45:04 srv505 [<c10524ae>] ? do_group_exit+0x5a/0x7d
> Aug 30 05:45:04 srv505 [<c10524e2>] ? sys_exit_group+0x11/0x14
> Aug 30 05:45:04 srv505 [<c102514c>] ? sysenter_do_call+0x12/0x22


> Sep  5 00:50:10 srv505 kworker/0:1: page allocation failure. order:1, mode:0x20
> Sep  5 00:50:10 srv505 Pid: 0, comm: kworker/0:1 Tainted: G      D     2.6.38.7-vs2.3.0.37-rc15
#2
> Sep  5 00:50:10 srv505 Call Trace:
> Sep  5 00:50:10 srv505 [<c1098b54>] ? __alloc_pages_nodemask+0x527/0x56d
> Sep  5 00:50:10 srv505 [<c13d3aad>] ? __nf_ct_refresh_acct+0x41/0xa2
> Sep  5 00:50:10 srv505 [<c10b5b55>] ? cache_alloc_refill+0x23a/0x418
> Sep  5 00:50:10 srv505 [<c10b5dff>] ? kmem_cache_alloc+0x40/0x62
> Sep  5 00:50:10 srv505 [<c13a313a>] ? sk_prot_alloc+0x1a/0x84
> Sep  5 00:50:10 srv505 [<c13a3259>] ? sk_clone+0x15/0x28e
> Sep  5 00:50:10 srv505 [<c13f5bbc>] ? inet_csk_clone+0xd/0x76
> Sep  5 00:50:10 srv505 [<c140826f>] ? tcp_create_openreq_child+0x1a/0x3d0
> Sep  5 00:50:10 srv505 [<c1406e05>] ? tcp_v4_syn_recv_sock+0x48/0x181
> Sep  5 00:50:10 srv505 [<c1408133>] ? tcp_check_req+0x227/0x349
> Sep  5 00:50:10 srv505 [<c14065d2>] ? tcp_v4_do_rcv+0xc1/0x1c3
> Sep  5 00:50:10 srv505 [<c1406b16>] ? tcp_v4_rcv+0x442/0x6e9
> Sep  5 00:50:10 srv505 [<c13ee1e6>] ? ip_local_deliver_finish+0x13d/0x216
> Sep  5 00:50:10 srv505 [<c13eddfc>] ? ip_rcv_finish+0x2fc/0x30f
> Sep  5 00:50:10 srv505 [<c13ac109>] ? __netif_receive_skb+0x410/0x437
> Sep  5 00:50:10 srv505 [<c13acb67>] ? netif_receive_skb+0x5a/0x5f
> Sep  5 00:50:10 srv505 [<c1324644>] ? e1000_receive_skb+0x17/0x4e
> Sep  5 00:50:10 srv505 [<c13acc29>] ? napi_skb_finish+0x1b/0x30
> Sep  5 00:50:10 srv505 [<c13248ac>] ? e1000_clean_rx_irq+0x231/0x2da
> Sep  5 00:50:10 srv505 [<c12bcfe9>] ? scsi_run_queue+0x295/0x319
> Sep  5 00:50:10 srv505 [<c1325ded>] ? e1000_clean+0x63/0x21b
> Sep  5 00:50:10 srv505 [<c13ad183>] ? net_rx_action+0x8c/0x16e
> Sep  5 00:50:10 srv505 [<c105372e>] ? __do_softirq+0x6a/0xed
> Sep  5 00:50:10 srv505 [<c10536c4>] ? __do_softirq+0x0/0xed
> Sep  5 00:50:10 srv505 <IRQ> 
> Sep  5 00:50:10 srv505 [<c1026581>] ? do_IRQ+0x73/0x84
> Sep  5 00:50:10 srv505 [<c10256a9>] ? common_interrupt+0x29/0x30
> Sep  5 00:50:10 srv505 [<c102a026>] ? mwait_idle+0x51/0x56
> Sep  5 00:50:10 srv505 [<c10244b4>] ? cpu_idle+0x37/0x4f


> Le 30 sept. 2011 à 08:56, Romain Riviere a écrit :

>> Hello,

>> Here's a panic I just had this morning and that, for once, I was able to get information
for, thanks to netconsole. This *might* be a bug that I have had with vserver kernels
since approx 2.6.36+ and for which I have found no solution yet. Any help would be GREATLY
appreciated.

>> Cheers,
>> --
>> Romain

>> Here goes:

>> Sep 30 05:36:43 srv505 Kernel panic - not syncing: Fatal exception in interrupt
>> Sep 30 05:36:43 srv505 Pid: 0, comm: swapper Tainted: G      D 2.6.38.7-vs2.3.0.37-rc15
#2
>> Sep 30 05:36:43 srv505 Call Trace:
>> Sep 30 05:36:43 srv505 [<c14aed50>] ? panic+0x4d/0x12b
>> Sep 30 05:36:43 srv505 [<c10279a1>] ? oops_end+0x6b/0x75
>> Sep 30 05:36:43 srv505 [<c103acb9>] ? no_context+0x13c/0x145
>> Sep 30 05:36:43 srv505 [<c103adbd>] ? __bad_area_nosemaphore+0xfb/0x103
>> Sep 30 05:36:43 srv505 [<c106af36>] ? vx_update_load+0x18/0x1e6
>> Sep 30 05:36:43 srv505 [<c10444bb>] ? update_cfs_load+0x129/0x1d6
>> Sep 30 05:36:43 srv505 [<c103adcf>] ? bad_area_nosemaphore+0xa/0xc
>> Sep 30 05:36:43 srv505 [<c103b08b>] ? do_page_fault+0x157/0x344
>> Sep 30 05:36:43 srv505 [<c104c5b2>] ? try_to_wake_up+0x25a/0x266
>> Sep 30 05:36:43 srv505 [<c106204f>] ? autoremove_wake_function+0xd/0x2d
>> Sep 30 05:36:43 srv505 [<c1042551>] ? __wake_up_common+0x34/0x59
>> Sep 30 05:36:43 srv505 [<c103af34>] ? do_page_fault+0x0/0x344
>> Sep 30 05:36:43 srv505 [<c14b130a>] ? error_code+0x5a/0x60
>> Sep 30 05:36:43 srv505 [<c1226d1c>] ? cfq_completed_request+0x0/0x433
>> Sep 30 05:36:43 srv505 [<c104007b>] ? aes_dec_blk+0x4cb/0xb6c
>> Sep 30 05:36:43 srv505 [<c103af34>] ? do_page_fault+0x0/0x344
>> Sep 30 05:36:43 srv505 [<c1226d42>] ? cfq_completed_request+0x26/0x433
>> Sep 30 05:36:43 srv505 [<c128bf0d>] ? credit_entropy_bits+0x6a/0x7d
>> Sep 30 05:36:43 srv505 [<c128bfe9>] ? add_timer_randomness+0xc9/0xd0
>> Sep 30 05:36:43 srv505 [<c1219425>] ? elv_completed_request+0x3d/0x3f
>> Sep 30 05:36:43 srv505 [<c121af09>] ? __blk_put_request+0x27/0x95
>> Sep 30 05:36:43 srv505 [<c121b34e>] ? blk_end_bidi_request+0x31/0x47
>> Sep 30 05:36:43 srv505 [<c121b393>] ? blk_end_request+0x7/0x9
>> Sep 30 05:36:43 srv505 [<c12be01a>] ? scsi_io_completion+0x15d/0x380
>> Sep 30 05:36:43 srv505 [<c12b9628>] ? scsi_finish_command+0x72/0x8a
>> Sep 30 05:36:43 srv505 [<c121f183>] ? blk_done_softirq+0x47/0x53
>> Sep 30 05:36:43 srv505 [<c105372e>] ? __do_softirq+0x6a/0xed
>> Sep 30 05:36:43 srv505 [<c10536c4>] ? __do_softirq+0x0/0xed
>> Sep 30 05:36:43 srv505 <IRQ>
>> Sep 30 05:36:43 srv505 [<c14b0eae>] ? call_function_single_interrupt+0x2a/0x30
>> Sep 30 05:36:43 srv505 [<c102a026>] ? mwait_idle+0x51/0x56
>> Sep 30 05:36:43 srv505 [<c10244b4>] ? cpu_idle+0x37/0x4f
>> Sep 30 05:36:43 srv505 [<c16b2951>] ? start_kernel+0x2bd/0x2c0

>> This was preceded by :
>> Sep 30 05:36:43 srv505 BUG: unable to handle kernel
>> Sep 30 05:36:43 srv505 NULL pointer dereference
>> Sep 30 05:36:43 srv505 at 0000029c
>> Sep 30 05:36:43 srv505 IP:
>> Sep 30 05:36:43 srv505 [<c1226d42>] cfq_completed_request+0x26/0x433
>> Sep 30 05:36:43 srv505 *pdpt = 00000000320ec001
>> Sep 30 05:36:43 srv505 *pde = 0000000000000000
>> Sep 30 05:36:43 srv505
>> Sep 30 05:36:43 srv505 Oops: 0000 [#2]
>> Sep 30 05:36:43 srv505 SMP
>> Sep 30 05:36:43 srv505
>> Sep 30 05:36:43 srv505 last sysfs file: /sys/devices/platform/coretemp.3/temp1_input
>> Sep 30 05:36:43 srv505
>> Sep 30 05:36:43 srv505 Pid: 0, comm: swapper Tainted: G      D 2.6.38.7-vs2.3.0.37-rc15
#2
>> Sep 30 05:36:43 srv505
>> Sep 30 05:36:43 srv505 Supermicro X7SBi
>> Sep 30 05:36:43 srv505 /
>> Sep 30 05:36:43 srv505 X7SBi
>> Sep 30 05:36:43 srv505
>> Sep 30 05:36:43 srv505 EIP: 0060:[<c1226d42>] EFLAGS: 00010096 CPU: 0
>> Sep 30 05:36:43 srv505 EIP is at cfq_completed_request+0x26/0x433
>> Sep 30 05:36:43 srv505 EAX: 00000001 EBX: f36a5760 ECX: c1226d1c EDX: f36a5760
>> Sep 30 05:36:43 srv505 ESI: f356bd84 EDI: 00000000 EBP: a356d4ec ESP: f340bf28
>> Sep 30 05:36:43 srv505 DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068
>> Sep 30 05:36:43 srv505 Process swapper (pid: 0, ti=f340a000 task=c1676320 task.ti=c1658000)
>> Sep 30 05:36:43 srv505 Stack:
>> Sep 30 05:36:43 srv505 00000202
>> Sep 30 05:36:43 srv505 c128bf0d
>> Sep 30 05:36:43 srv505 00000000
>> Sep 30 05:36:43 srv505 00000002
>> Sep 30 05:36:43 srv505 00000004
>> Sep 30 05:36:43 srv505 f2f71980
>> Sep 30 05:36:43 srv505 00000202
>> Sep 30 05:36:43 srv505 c128bfe9
>> Sep 30 05:36:43 srv505
>> Sep 30 05:36:43 srv505 00000001
>> Sep 30 05:36:43 srv505 f36a4b30
>> Sep 30 05:36:43 srv505 f36a5760
>> Sep 30 05:36:43 srv505 f36a4b30
>> Sep 30 05:36:43 srv505 f36a4b30
>> Sep 30 05:36:43 srv505 c1219425
>> Sep 30 05:36:43 srv505 f36a5760
>> Sep 30 05:36:43 srv505 c121af09
>> Sep 30 05:36:43 srv505
>> Sep 30 05:36:43 srv505 00000246
>> Sep 30 05:36:43 srv505 f36a5760
>> Sep 30 05:36:43 srv505 00000000
>> Sep 30 05:36:43 srv505 c121b34e
>> Sep 30 05:36:43 srv505 f21dc0c0
>> Sep 30 05:36:43 srv505 00000000
>> Sep 30 05:36:43 srv505 f36a5760
>> Sep 30 05:36:43 srv505 f36a5760
>> Sep 30 05:36:43 srv505
>> Sep 30 05:36:43 srv505 Call Trace:
>> Sep 30 05:36:43 srv505 [<c128bf0d>] ? credit_entropy_bits+0x6a/0x7d
>> Sep 30 05:36:43 srv505 [<c128bfe9>] ? add_timer_randomness+0xc9/0xd0
>> Sep 30 05:36:43 srv505 [<c1219425>] ? elv_completed_request+0x3d/0x3f
>> Sep 30 05:36:43 srv505 [<c121af09>] ? __blk_put_request+0x27/0x95
>> Sep 30 05:36:43 srv505 [<c121b34e>] ? blk_end_bidi_request+0x31/0x47
>> Sep 30 05:36:43 srv505 [<c121b393>] ? blk_end_request+0x7/0x9
>> Sep 30 05:36:43 srv505 [<c12be01a>] ? scsi_io_completion+0x15d/0x380
>> Sep 30 05:36:43 srv505 [<c12b9628>] ? scsi_finish_command+0x72/0x8a
>> Sep 30 05:36:43 srv505 [<c121f183>] ? blk_done_softirq+0x47/0x53
>> Sep 30 05:36:43 srv505 [<c105372e>] ? __do_softirq+0x6a/0xed
>> Sep 30 05:36:43 srv505 [<c10536c4>] ? __do_softirq+0x0/0xed
>> Sep 30 05:36:43 srv505 <IRQ>
>> Sep 30 05:36:43 srv505
>> Sep 30 05:36:43 srv505 [<c14b0eae>] ? call_function_single_interrupt+0x2a/0x30
>> Sep 30 05:36:43 srv505 [<c102a026>] ? mwait_idle+0x51/0x56
>> Sep 30 05:36:43 srv505 [<c10244b4>] ? cpu_idle+0x37/0x4f
>> Sep 30 05:36:43 srv505 [<c16b2951>] ? start_kernel+0x2bd/0x2c0
>> Sep 30 05:36:43 srv505 Code:
>> Sep 30 05:36:43 srv505 5b
>> Sep 30 05:36:43 srv505 5e
>> Sep 30 05:36:43 srv505 5f
>> Sep 30 05:36:43 srv505 5d
>> Sep 30 05:36:43 srv505 c3
>> Sep 30 05:36:43 srv505 55
>> Sep 30 05:36:43 srv505 57
>> Sep 30 05:36:43 srv505 56
>> Sep 30 05:36:43 srv505 53
>> Sep 30 05:36:43 srv505 89
>> Sep 30 05:36:43 srv505 d3
>> Sep 30 05:36:43 srv505 83
>> Sep 30 05:36:43 srv505 ec
>> Sep 30 05:36:43 srv505 24
>> Sep 30 05:36:43 srv505 8b
>> Sep 30 05:36:43 srv505 72
>> Sep 30 05:36:43 srv505 5c
>> Sep 30 05:36:43 srv505 8b
>> Sep 30 05:36:43 srv505 42
>> Sep 30 05:36:43 srv505 20
>> Sep 30 05:36:43 srv505 8b
>> Sep 30 05:36:43 srv505 7e
>> Sep 30 05:36:43 srv505 08
>> Sep 30 05:36:43 srv505 83
>> Sep 30 05:36:43 srv505 e0
>> Sep 30 05:36:43 srv505 11
>> Sep 30 05:36:43 srv505 8b
>> Sep 30 05:36:43 srv505 2d
>> Sep 30 05:36:43 srv505 40
>> Sep 30 05:36:43 srv505 da
>> Sep 30 05:36:43 srv505 65
>> Sep 30 05:36:43 srv505 c1
>> Sep 30 05:36:43 srv505 48
>> Sep 30 05:36:43 srv505 0f
>> Sep 30 05:36:43 srv505 95
>> Sep 30 05:36:43 srv505 c0
>> Sep 30 05:36:43 srv505 0f
>> Sep 30 05:36:43 srv505 b6
>> Sep 30 05:36:43 srv505 c0
>> Sep 30 05:36:43 srv505 89
>> Sep 30 05:36:43 srv505 44
>> Sep 30 05:36:43 srv505 24
>> Sep 30 05:36:43 srv505 20
>> Sep 30 05:36:43 srv505 syslog-ng[3301]: Error processing log message: <8b>
>> Sep 30 05:36:43 srv505 87
>> Sep 30 05:36:43 srv505 9c
>> Sep 30 05:36:43 srv505 02
>> Sep 30 05:36:43 srv505 00
>> Sep 30 05:36:43 srv505 00
>> Sep 30 05:36:43 srv505 8b
>> Sep 30 05:36:43 srv505 97
>> Sep 30 05:36:43 srv505 e4
>> Sep 30 05:36:43 srv505 02
>> Sep 30 05:36:43 srv505 00
>> Sep 30 05:36:43 srv505 00
>> Sep 30 05:36:43 srv505 3b
>> Sep 30 05:36:43 srv505 87
>> Sep 30 05:36:43 srv505 b0
>> Sep 30 05:36:43 srv505 02
>> Sep 30 05:36:43 srv505 00
>> Sep 30 05:36:43 srv505 00
>> Sep 30 05:36:43 srv505 7e
>> Sep 30 05:36:43 srv505 06
>> Sep 30 05:36:43 srv505 89
>> Sep 30 05:36:43 srv505
>> Sep 30 05:36:43 srv505 EIP: [<c1226d42>]
>> Sep 30 05:36:43 srv505 cfq_completed_request+0x26/0x433
>> Sep 30 05:36:43 srv505 SS:ESP 0068:f340bf28
>> Sep 30 05:36:43 srv505 CR2: 000000000000029c
>> Sep 30 05:36:43 srv505 ---[ end trace ab3174360ff1a69e ]---