Bug 743746

Moving it to "kernel". The bug is about IRQs being disabed when they should be enabled in ... -> __ext3_get_inode_loc() -> sb_getblk() -> __getblk() -> __find_get_block() -> bh_lru_install() -> check_irqs_on().

I'm reminded of bug 707552 / bug 713399, but that was a RHEL-6 guest fix.

(In reply to comment #1)
> I'm reminded of bug 707552 / bug 713399, but that was a RHEL-6 guest fix.

fix for bug 713399 doesn't affects ia64 in any way, it is only applicable to x86_32 xen pv guest.

This problem was observed also with kernel 2.6.18-238.28.1.el5 xen:

kernel BUG at fs/buffer.c:1479! 
watchdog.sh[23848]: bugcheck! 0 [1] 
Modules linked in: autofs4 hidp rfcomm l2cap bluetooth lockd sunrpc be2iscsi ib_iser rdma_cm ib_cm iw_cm ib_sa ib_mad ib_core ib_addr iscsi_tcp bnx2i cnic ipv6 xfrm_nalgo crypto_api uio cxgb3i cxgb3 8021q libiscsi_tcp libiscsi2 scsi_transport_iscsi2 scsi_transport_iscsi vfat fat loop dm_multipath scsi_dh wmi power_meter hwmon button parport_pc lp parport joydev tpm_tis tpm shpchp tpm_bios tg3 sg dm_raid45 dm_message dm_region_hash dm_mem_cache dm_snapshot dm_zero dm_mirror dm_log dm_mod qla2xxx scsi_transport_fc mptsas mptscsih mptbase scsi_transport_sas sd_mod scsi_mod ext3 jbd uhci_hcd ohci_hcd ehci_hcd 
 
Pid: 23848, CPU 3, comm:          watchdog.sh 
psr : 0000101008522010 ifs : 800000000000048c ip  : [<a00000010018c280>]    Tainted: G      (2.6.18-238.28.1.el5xen) 
ip is at __find_get_block+0x600/0x800 
unat: 0000000000000000 pfs : 800000000000048c rsc : 000000000000000b 
rnat: 0000000000000000 bsps: 0000000000000000 pr  : 000000000056a559 
ldrs: 0000000000000000 ccv : 0000000000000000 fpsr: 0009804c8a70033f 
csd : 0000000000000000 ssd : 0000000000000000 
b0  : a00000010018c280 b6  : a000000100019900 b7  : 0000000000000000 
f6  : 000000000000000000000 f7  : 000000000000000000000 
f8  : 000000000000000000000 f9  : 000000000000000000000 
f10 : 000000000000000000000 f11 : 000000000000000000000 
r1  : a000000100c78420 r2  : a000000100a91860 r3  : a000000100a91b78 
r8  : 0000000000000023 r9  : a000000100a91890 r10 : a000000100a91890 
r11 : 0000000000000000 r12 : e00000016a827b60 r13 : e00000016a820000 
r14 : a000000100a91860 r15 : 0000000000000000 r16 : a000000100a91b78 
r17 : e0000001ab88fe18 r18 : 0000000000000001 r19 : fffffffffff04c18 
r20 : a0000001008a9380 r21 : a000000100a78ab8 r22 : a000000100a91868 
r23 : a000000100a91868 r24 : 0000000000000000 r25 : a0000001009bd780 
r26 : fffffffffff00091 r27 : 0000000000000001 r28 : fffffffffff04c18 
r29 : 0000141208526010 r30 : 8000000000000006 r31 : 000000000056a959 
 
Call Trace: 
 [<a00000010001d240>] show_stack+0x40/0xa0 
                                sp=e00000016a8276f0 bsp=e00000016a821cd8 
 [<a00000010001db70>] show_regs+0x870/0x8c0 
                                sp=e00000016a8278c0 bsp=e00000016a821c80 
 [<a000000100043160>] die+0x1c0/0x380 
                                sp=e00000016a8278c0 bsp=e00000016a821c38 
 [<a000000100043370>] die_if_kernel+0x50/0x80 
                                sp=e00000016a8278e0 bsp=e00000016a821c08 
 [<a000000100695870>] ia64_bad_break+0x270/0x4a0 
                                sp=e00000016a8278e0 bsp=e00000016a821bd8 
 [<a00000010006ae80>] xen_leave_kernel+0x0/0x3e0 
                                sp=e00000016a827990 bsp=e00000016a821bd8 
 [<a00000010018c280>] __find_get_block+0x600/0x800 
                                sp=e00000016a827b60 bsp=e00000016a821b78 
 [<a00000010018c4b0>] __getblk+0x30/0x600 
                                sp=e00000016a827ba0 bsp=e00000016a821b28 
 [<a00000020122e1d0>] __ext3_get_inode_loc+0x310/0x920 [ext3] 
                                sp=e00000016a827ba0 bsp=e00000016a821ab8 
 [<a00000020122e820>] ext3_get_inode_loc+0x40/0x60 [ext3] 
                                sp=e00000016a827ba0 bsp=e00000016a821a90 
 [<a00000020122e880>] ext3_reserve_inode_write+0x40/0x180 [ext3] 
                                sp=e00000016a827ba0 bsp=e00000016a821a50 
 [<a00000020122e9f0>] ext3_mark_inode_dirty+0x30/0xa0 [ext3] 
                                sp=e00000016a827ba0 bsp=e00000016a821a28 
 [<a000000201236350>] ext3_dirty_inode+0xd0/0x120 [ext3] 
                                sp=e00000016a827bc0 bsp=e00000016a8219f0 
 [<a0000001001e61b0>] __mark_inode_dirty+0x90/0x400 
                                sp=e00000016a827bc0 bsp=e00000016a8219b0 
 [<a000000201227cd0>] ext3_new_blocks+0xbf0/0xec0 [ext3] 
                                sp=e00000016a827bc0 bsp=e00000016a821910 
 [<a00000020122ffa0>] ext3_get_blocks_handle+0xa00/0x18e0 [ext3] 
                                sp=e00000016a827be0 bsp=e00000016a821850 
 [<a0000002012315b0>] ext3_get_block+0x130/0x1e0 [ext3] 
                                sp=e00000016a827c90 bsp=e00000016a8217f0 
 [<a00000010018f640>] __block_prepare_write+0x3e0/0x8c0 
                                sp=e00000016a827c90 bsp=e00000016a821750 
 [<a00000010018fce0>] block_write_begin+0x120/0x200 
                                sp=e00000016a827cb0 bsp=e00000016a8216e8 
 [<a000000201234bc0>] ext3_write_begin+0x160/0x3e0 [ext3] 
                                sp=e00000016a827cb0 bsp=e00000016a821650 
 [<a000000100127910>] generic_file_buffered_write+0x1d0/0xd00 
                                sp=e00000016a827cc0 bsp=e00000016a821588 
 [<a000000100128b30>] __generic_file_aio_write_nolock+0x6f0/0x800 
                                sp=e00000016a827cf0 bsp=e00000016a821510 
 [<a000000100128d30>] generic_file_aio_write+0xf0/0x200 
                                sp=e00000016a827d30 bsp=e00000016a8214b0 
 [<a000000201229c80>] ext3_file_write+0x60/0x200 [ext3] 
                                sp=e00000016a827d40 bsp=e00000016a821478 
 [<a000000100185a10>] do_sync_write+0x170/0x1e0 
                                sp=e00000016a827d40 bsp=e00000016a821438 
 [<a000000100187240>] vfs_write+0x200/0x3a0 
                                sp=e00000016a827e20 bsp=e00000016a8213e0 
 [<a000000100187d90>] sys_write+0x70/0xe0 
                                sp=e00000016a827e20 bsp=e00000016a821368 
 [<a00000010006ab80>] xen_trace_syscall+0x100/0x140 
                                sp=e00000016a827e30 bsp=e00000016a821368 
 [<a000000000010620>] __start_ivt_text+0xffffffff00010620/0x400 
                                sp=e00000016a828000 bsp=e00000016a821368 
 <0>Kernel panic - not syncing: Fatal exception 
 (XEN) Domain 0 crashed: rebooting machine in 5 seconds.

Why is there "xen_trace_syscall" in the stack dump? Is something ptraced or (based on xen-devel postings) is "audit enabled"? Does scrashme enable audit somehow which in combination with new(ish?) ext3 code exposes a long-standing IA64 virt bug? (See eg. bug 208638.)

include/asm-ia64/xen/privop.h
-----------------------------

/* these routines utilize privilege-sensitive or performance-sensitive
 * privileged instructions so the code must be replaced with
 * paravirtualized versions */

#define   ia64_trace_syscall              xen_trace_syscall

arch/ia64/xen/xenentry.S
------------------------

	/*
	 * Invoke a system call, but do some tracing before and after the call.
	 * We MUST preserve the current register frame throughout this routine
	 * because some system calls (such as ia64_execve) directly
	 * manipulate ar.pfs.
	 */
#ifdef CONFIG_XEN
GLOBAL_ENTRY(xen_trace_syscall)
	PT_REGS_UNWIND_INFO(0)
	movl r16=running_on_xen;;
	ld4 r16=[r16];;
	cmp.eq p7,p0=r16,r0
(p7)	br.cond.sptk.many __ia64_trace_syscall;;
#else

I grepped the source for "ia64_trace_syscall", but it occurs mainly in super-low-level IA64 assembly code, which is completely Greek to me.

Why are the syscalls traced in the first place?

We could waste time on bisecting 5.6.z, and we'd probably end up with an innocent fs change. By the way, my 5.6.z clone doesn't even know about 2.6.18-238.28.1.el5, the latest tag is "kernel-2.6.18-238.27.1.el5". I love how a new build is being tested in Beaker and I have no chance to look at the source.

no hypervisor patches from .27.1 to .28.1, last patch is

Patch20255: xen-mm-fix-race-with-ept_entry-management.patch

So does this mean the problem appeared between .27.1 and .28.1?  IOW did .27.1 pass?  I didn't see that explicitly stated...

(In reply to comment #11)
> So does this mean the problem appeared between .27.1 and .28.1?  IOW did .27.1
> pass?

That's my assumption. I'll try to rerun the tests on the affected machines sometime, under all builds in (27.1, 28.1] if necessary. But with that effort I could put even 27.1 in the set.

Ok.  Nothing in the patches between the two seem to be obvious culprits, but I've been surprised before.

The second attempt passed too, on both machines.

scrashme runs in randomized mode. Without the random seed *or* the scrashme call logs it's virtually impossible to reproduce the problem. The bug may have existed for ages. Please modify the test case so that the seed is printed to the console. Also the scrashme logs should be sent to a different machine over network or serial, in "sync" (= line buffered or similar) mode.

I tried to follow the stack traces again.

Firs, I have absolutely no idea what and why xen_trace_syscall does; I don't speak ia64 assembly.

Second, I was a little bit wrong in comment 1:

> Moving it to "kernel". The bug is about IRQs being disabed when they should be
> enabled in ... -> __ext3_get_inode_loc() -> sb_getblk() -> __getblk() ->
> __find_get_block() -> bh_lru_install() -> check_irqs_on().

The last line should be (could be?)

    __find_get_block() -> lookup_bh_lru() -> check_irqs_on().

__find_get_block():

/*
 * Perform a pagecache lookup for the matching buffer.  If it's there, refresh
 * it in the LRU and mark it as accessed.  If it is not present then return
 * NULL
 */

The last sentence is incorrect, if it's not present (ie. lookup_bh_lru() failed) then __find_get_block_slow() is called, and if that one succeeds, the result is added to the cache (with bh_lru_install()). Both lookup_bh_lru() and bh_lru_install() call check_irqs_on().

(
__getblk() also calls might_sleep() after __find_get_block() returns (which, in our case, doesn't return). 

/**
 * might_sleep - annotation for functions that can sleep
 *
 * this macro will print a stack trace if it is executed in an atomic
 * context (spinlock, irq-handler, ...).
 *
 * This is a useful debugging help to be able to catch problems early and not
 * be biten later when the calling function happens to sleep when it is not
 * supposed to.
 */

Since CONFIG_DEBUG_SPINLOCK_SLEEP is not set in configs/kernel-2.6.18-ia64-xen.config, might_sleep() is toothless, because it won't call __might_sleep(), which would check for irqs_disabled() and dump the stack. If __find_get_block() returned and we had CONFIG_DEBUG_SPINLOCK_SLEEP enabled, then might_sleep() would dump the stack too.
)

With CONFIG_IA64_DEBUG_IRQ (which we don't have set), we could at least save the IP when the IRQs get disabled (last_cli_ip).

Something's messed up. I took the faulting IP from comment 3 (a00000010018c280) and:

$ addr2line -ife /usr/lib/debug/lib/modules/2.6.18-238.28.1.el5xen/vmlinux \
    <<<a00000010018c280

bh_lru_install
/usr/src/debug/kernel-2.6.18/linux-2.6.18.ia64/fs/buffer.c:1508
__find_get_block
/usr/src/debug/kernel-2.6.18/linux-2.6.18.ia64/fs/buffer.c:1572

buffer.c:1572 is indeed __find_get_block()'s call to bh_lru_install(). Which should answer the question whether it's lookup_bh_lru() or bh_lru_install() blows up. However:

(1) how do we get to bh_lru_install(), when we call lookup_bh_lru() microseconds before that, which *also* calls check_irqs_on()? Basically:

__find_get_block()

  -> lookup_bh_lru()
    -> check_irqs_on() -- no problem!
    -> bh_lru_lock()
      -> local_irq_disable()
    -> bh_lru_unlock()
      -> local_irq_enable()

  -> __find_get_block_slow()

  -> bh_lru_install()
    -> check_irqs_on() -- BOOM

So it *must* happen in __find_get_block_slow() somewhere.

(2) buffer.c:1508 is also a BUG_ON() line, directly in bh_lru_install(). However, we don't bug on that, according to the kernel message. I don't understand.

Do we still think this is related to Xen?

Could be stack/register corruption?

Or a consequence of inlining. check_irqs_on(), which instantiates the BUG_ON macro, is "inline".

I couldn't find anything in __find_get_block_slow() that would leave interrupts disabled. Perhaps "something" interrupts __find_get_block() between lookup_bh_lru() and bh_lru_install(), due to the scrashme junk calls, and leaves interrupts disabled.

> Version-Release number of selected component (if applicable):
> kernel-xen-2.6.18-286.el5.wtf1

Um, what is that kernel?  It's not in Brew, and it's not tagged in Git.

I believe it's a bisection / manual reversion kernel. Or even more likely, something that Beaker created. I suggest to ask Jarod; I seem to remember wtf1 kernels after one of my patches broke testing in Beaker, and Jarod was hunting for the offender.

Yeah, the "wtf#" tagged kernels are my scratch builds when debugging/bisecting issues, trying to figure out wtf went wrong. :)

Jarod, so how do we find out what was actually in that kernel? :)

(In reply to comment #36)
> Jarod, so how do we find out what was actually in that kernel? :)

Its a touch convoluted, but doable... And its a fairly long list. I'll shoot you a copy.

Jarod, got it, thanks.

At this point, I think I would like to punt this back to the reporter and say "please reproduce on a kernel tagged in Brew"

I'm not sure it's wise to go chasing "wtf1" kernel oopses.  Feel free to set me straight if I'm misunderstanding anything.  :)

So, needinfo:  Can this be reproduced on a non-wtf kernel?

(In reply to comment #38)
> Jarod, got it, thanks.
> 
> At this point, I think I would like to punt this back to the reporter and say
> "please reproduce on a kernel tagged in Brew"
> 
> I'm not sure it's wise to go chasing "wtf1" kernel oopses.  Feel free to set me
> straight if I'm misunderstanding anything.  :)
> 
> So, needinfo:  Can this be reproduced on a non-wtf kernel?

I tried it on the same system with 2.6.18-295 kernel , it didn't reproduce. beaker job#154629

Ok; since it only reproduces on a "wtf" kernel, I am closing it "notabug" by decree. :)  If you see it again, please re-open.

*** Bug 797711 has been marked as a duplicate of this bug. ***

Sorry for closing earlier when comment #3 showed it happened on a stock kernel - lost track.

*** Bug 1015341 has been marked as a duplicate of this bug. ***

This bug/component is not included in scope for RHEL-5.11.0 which is the last RHEL5 minor release. This Bugzilla will soon be CLOSED as WONTFIX (at the end of RHEL5.11 development phase (Apr 22, 2014)). Please contact your account manager or support representative in case you need to escalate this bug.

Per comment #51, just closing this now to get it off our radar.  Scrashme has done "something bad" to the kernel; we don't know what.  Without a deterministic testcase I don't see that we can fix this.  (And based on comment #49, apparently not a regression)