Details
-
Bug
-
Resolution: Fixed
-
Blocker
-
Lustre 2.3.0, Lustre 2.4.0
-
None
-
CONFIG_DEBUG_SLAB=y
-
3
-
4237
Description
Lustre: DEBUG MARKER: == sanity test 103: acl test ========================================================================= 19:57:07 (1346774227)
/work/lustre/head/clean/lustre/utils/l_getidentity
Slab corruption (Tainted: P --------------- ): size-2048 start=dac6c470, len=2048
Redzone: 0x9f911029d74e35b/0x9f911029d74e35b.
Last user: [<dff39e58>](cfs_free+0x8/0x10 [libcfs])
310: 02 00 00 00 01 00 07 00 ff ff ff ff 02 00 05 00
320: 01 00 00 00 02 00 07 00 02 00 00 00 04 00 07 00
330: ff ff ff ff 10 00 07 00 ff ff ff ff 20 00 05 00
340: ff ff ff ff 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b
Next obj: start=dac6cc88, len=2048
Redzone: 0x9f911029d74e35b/0x9f911029d74e35b.
Last user: [<dff39e58>](cfs_free+0x8/0x10 [libcfs])
000: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b
010: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b
02000000:00000010:1.0:1346774231.327841:1804:3373:0:(sec_null.c:217:null_alloc_repbuf()) kmalloced 'req->rq_repbuf': 2048 at dac6c470.
...
02000000:00000010:1.0:1346774231.328361:836:3373:0:(sec_null.c:231:null_free_repbuf()) kfreed 'req->rq_repbuf': 2048 at dac6c470.
Attachments
Issue Links
Activity
Keith, PAGEALLOC debug is a more powerful (and slow) kernel feature to track random memory writes. What it does is when you free a page instead of merely writing it with some poison value to check later (what you are hitting, and once hit - no way to know who made the write) it actually unmaps the page from address space, so when the offender comes to do the write, the page is not there and we get the nice oops pointing at the red-handed writer to the place they are not supposed to be writing.
Keith, can you please fix Yu Jian's patches that hit build failures. The 2.3.50 patch failed to build due to built-in version checks, so it needs to be rebased one patch later (git hash 388111848489ef99b1fa31ce8fef255ab9c08e84). I haven't investigated the other failure, but hopefully it is similarly trivial. Please get to this ASAP so that the testing can be started on these patches, and hopefully we can isolate this serious defect more quickly.
I have started a fresh build/bisect setup with client-7 client-17 client-18. I am able to reliability re-create here. This is the exact build that does not trigger on my system and the same config changes at Yu's. I fear that running on a random setups (via autotest) may lead to false negatives since some setups produce the error and some don't. I will kick the builds along but I would not trust any single run passes as "Not Broken".
Oleg are you testing with DEBUG_SLAB as well? child_rip is the only thing that seems common there is no mention of the slab code path and cfs_free in your back trace.
Can you confirm that the slab errors have gone away with your patch? I have put your patch in my test queue on the bisect setup as well.
Ok, my current theory is we have a problem coming from patch in LU-998.
mdd_declare_attr_set:
if (ma->ma_attr.la_valid & LA_MODE) {
mdd_read_lock(env, obj, MOR_TGT_CHILD);
rc = mdo_xattr_get(env, obj, buf, XATTR_NAME_ACL_ACCESS,
BYPASS_CAPA);
mdd_read_unlock(env, obj);
here we'll just use whatever happens to be in buf which sometimes ends up as garbage.
I am not exactly clear on how it's supposed to be used, but it looks like the buffer should be reinitialized every time it's about to be used afresh (frankly I am not even sure why is it needed because it seems to be always duplicated in some local vars that we pass around). Other cases in that same function do initialize the buffer address.
My reading of the code is such that we are just trying to make sure the xattrs exist at all, but if the buf happens to contain some pointer from before and declared size is big enough to fit the xattr, we read them to the buffer overwriting whatever important data was there (and it seems it's frequently points to freed and then possibly reallocated data too).
The fix for this particular problem is to probably pass in &LU_BUF_NULL instead of buf argument. (patch at http://review.whamcloud.com/3928 and seems to be holding well in my testing)
The wider question if the buf is supposed to point to freed memory at any time still remains to be open and I need somebody's help to determine this.
If that is not supposed to happen, we can track down offending user (and I imagine it's probably not super valid because occasionally on shutdown we do try to free that memory that buffer points to and if it's invalid, that's a problem, even though nobody has ever seen this before for some reason).
Ok, I enabled debug pagealloc and caught the offender I think:
[ 3201.251050] Lustre: 9532:0:(mdt_lproc.c:418:lprocfs_wr_identity_upcall()) lus
tre-MDT0000: identity upcall set to /home/green/git/lustre-release/lustre/utils/
l_getidentity
[ 3204.127208] BUG: unable to handle kernel paging request at ffff88021851ab48
[ 3204.129164] IP: [<ffffffff811d9dd8>] posix_acl_to_xattr+0x28/0x80
[ 3204.130098] PGD 1a26063 PUD 2766067 PMD 2829067 PTE 800000021851a160
[ 3204.130673] Oops: 0002 [#1] SMP DEBUG_PAGEALLOC
[ 3204.130673] last sysfs file: /sys/devices/system/cpu/possible
[ 3204.130673] CPU 1
[ 3204.130673] Modules linked in: lustre obdfilter ost cmm mdt osd_ldiskfs fsfil
t_ldiskfs ldiskfs mdd mds mgs lquota obdecho mgc lov osc mdc lmv fid fld ptlrpc obdclass lvfs ksocklnd lnet libcfs ext2 exportfs jbd sha512_generic sha256_gener
ic sunrpc ipv6 microcode virtio_balloon virtio_net i2c_piix4 i2c_core ext4 mbcac
he jbd2 virtio_blk virtio_pci virtio_ring virtio pata_acpi ata_generic ata_piix
dm_mirror dm_region_hash dm_log dm_mod [last unloaded: libcfs]
[ 3204.130673]
[ 3204.130673] Pid: 8603, comm: mdt00_001 Not tainted 2.6.32-debug #3 Bochs Boch
s
[ 3204.130673] RIP: 0010:[<ffffffff811d9dd8>] [<ffffffff811d9dd8>] posix_acl_to
_xattr+0x28/0x80
[ 3204.130673] RSP: 0018:ffff88027a9459d0 EFLAGS: 00010287
[ 3204.130673] RAX: 0000000000000034 RBX: ffff88021851ab48 RCX: 0000000000000034
[ 3204.130673] RDX: 0000000000000060 RSI: ffff88021851ab48 RDI: ffff88023a694e50
[ 3204.130673] RBP: ffff88027a9459d0 R08: ffffffffa055f3cd R09: ffffffffa05f8e36
[ 3204.130673] R10: 0000000000000000 R11: ffffffffa05fee98 R12: ffff88023a694e50
[ 3204.130673] R13: 0000000000000060 R14: ffffffffa055f3cd R15: ffff8802470b5b98
[ 3204.130673] FS: 00007fcc8f724700(0000) GS:ffff880028240000(0000) knlGS:0000000000000000
[ 3204.130673] CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b
[ 3204.130673] CR2: ffff88021851ab48 CR3: 00000002653cb000 CR4: 00000000000006e0
[ 3204.130673] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 3204.130673] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
[ 3204.130673] Process mdt00_001 (pid: 8603, threadinfo ffff88027a944000, task ffff88027a942540)
[ 3204.130673] Stack:
[ 3204.130673] ffff88027a945a10 ffffffffa05ac598 ffff88027a9459f0 ffffffffa067b661
[ 3204.130673] <d> 0000000000000010 ffff880222a70ef0 ffff880202a25bb8 ffff88027848b928
[ 3204.130673] <d> ffff88027a945a20 ffffffffa05ac612 ffff88027a945a30 ffffffff811a0147
[ 3204.130673] Call Trace:
[ 3204.130673] [<ffffffffa05ac598>] ldiskfs_xattr_get_acl+0x78/0xa0 [ldiskfs]
[ 3204.130673] [<ffffffffa067b661>] ? libcfs_debug_msg+0x41/0x50 [libcfs]
[ 3204.130673] [<ffffffffa05ac612>] ldiskfs_xattr_get_acl_access+0x22/0x30 [ldiskfs]
[ 3204.130673] [<ffffffff811a0147>] generic_getxattr+0x87/0x90
[ 3204.130673] [<ffffffffa074af64>] osd_xattr_get+0x284/0x360 [osd_ldiskfs]
[ 3204.130673] [<ffffffffa05356d0>] mdd_attr_set+0x15b0/0x2250 [mdd]
[ 3204.130673] [<ffffffffa067b661>] ? libcfs_debug_msg+0x41/0x50 [libcfs]
[ 3204.130673] [<ffffffffa0888a26>] cml_attr_set+0x66/0x1a0 [cmm]
[ 3204.130673] [<ffffffffa07bc768>] mdt_attr_set+0x2a8/0x590 [mdt]
[ 3204.130673] [<ffffffffa07bd096>] mdt_reint_setattr+0x646/0x13f0 [mdt]
[ 3204.130673] [<ffffffffa067b661>] ? libcfs_debug_msg+0x41/0x50 [libcfs]
[ 3204.130673] [<ffffffffa07b6081>] mdt_reint_rec+0x41/0xe0 [mdt]
[ 3204.130673] [<ffffffffa07af42a>] mdt_reint_internal+0x50a/0x810 [mdt]
[ 3204.130673] [<ffffffffa07af774>] mdt_reint+0x44/0xe0 [mdt]
[ 3204.130673] [<ffffffffa07a1d42>] mdt_handle_common+0x922/0x1740 [mdt]
[ 3204.130673] [<ffffffffa07a2c35>] mdt_regular_handle+0x15/0x20 [mdt]
[ 3204.130673] [<ffffffffa0f7486f>] ptlrpc_server_handle_request+0x44f/0xee0 [ptlrpc]
[ 3204.130673] [<ffffffffa066b66e>] ? cfs_timer_arm+0xe/0x10 [libcfs]
[ 3204.130673] [<ffffffffa0f6d711>] ? ptlrpc_wait_event+0xb1/0x2a0 [ptlrpc]
[ 3204.130673] [<ffffffffa067b661>] ? libcfs_debug_msg+0x41/0x50 [libcfs]
[ 3204.130673] [<ffffffff81051f73>] ? __wake_up+0x53/0x70
[ 3204.130673] [<ffffffffa0f773de>] ptlrpc_main+0xaee/0x1800 [ptlrpc]
[ 3204.130673] [<ffffffffa0f768f0>] ? ptlrpc_main+0x0/0x1800 [ptlrpc]
[ 3204.130673] [<ffffffff8100c14a>] child_rip+0xa/0x20
[ 3204.130673] [<ffffffffa0f768f0>] ? ptlrpc_main+0x0/0x1800 [ptlrpc]
[ 3204.130673] [<ffffffffa0f768f0>] ? ptlrpc_main+0x0/0x1800 [ptlrpc]
[ 3204.130673] [<ffffffff8100c140>] ? child_rip+0x0/0x20
[ 3204.130673] Code: c3 90 90 55 48 89 e5 0f 1f 44 00 00 48 63 47 04 48 85 f6 8d 04 c5 04 00 00 00 75 07 c9 c3 0f 1f 44 00 00 48 63 c8 48 39 d1 77 48 <c7> 06 02 00 00 00 8b 57 04 85 d2 74 e4 48 83 c6 04 31 d2 0f 1f
[ 3204.130673] RIP [<ffffffff811d9dd8>] posix_acl_to_xattr+0x28/0x80
[ 3204.130673] RSP <ffff88027a9459d0>
[ 3204.130673] CR2: ffff88021851ab48
[ 3204.130673] ---[ end trace f9aa2ef75b2f20bf ]---
Keith, can you please fix Yu Jian's patches that hit build failures.
The 2.3.50 patch failed to build due to built-in version checks, so it needs to be rebased one patch later (git hash 388111848489ef99b1fa31ce8fef255ab9c08e84). I haven't investigated the other failure, but hopefully it is similarly trivial. Please get to this ASAP so that the testing can be started on these patches, and hopefully we can isolate this serious defect more quickly.
Hi Keith,
I created several test patches per the following comments from Andreas:
If there are no obvious sources of this corruption, it probably makes sense to submit this test patch as several separate changes, each based on one of the recent 2.2.* tags, to see if we can isolate when this corruption started.
Patch on tag 2.2.94: http://review.whamcloud.com/#change,3921
Patch on tag 2.3.50: http://review.whamcloud.com/#change,3918
Patch on tag 2.2.93: http://review.whamcloud.com/#change,3919
Patch on tag 2.2.92: http://review.whamcloud.com/#change,3920
Hope we can isolate the issue.
I acquired some torro nods today and am starting to setup. My mds vm crashed while running " REFORMAT=y ONLY=103 sh sanity.sh", it took about 30 hours to trigger). This could be the bad cfs_free path that is corrupting the slab.
I will try and attach the whole dmesg.
This was master + kernel-2.6.32-279 on the MDS vm node.
Lustre: DEBUG MARKER: == sanity test 103: acl test =========================================== 06:06:43 (1347109603) kfree_debugcheck: out of range ptr 6000100000002h. ------------[ cut here ]------------ kernel BUG at mm/slab.c:2911! invalid opcode: 0000 [#1] SMP last sysfs file: /sys/devices/LNXSYSTM:00/LNXSYBUS:00/PNP0A03:00/PNP0C0A:00/power_supply/BAT0/energy_full CPU 0 Modules linked in: cmm(U) osd_ldiskfs(U) mdt(U) mdd(U) mds(U) fsfilt_ldiskfs(U) exportfs mgs(U) mgc(U) ldiskfs(U) lustre(U) lquota(U) lov(U) osc(U) mdc(U) fid(U) fld(U) ptlrpc(U) obdclass(U) lvfs(U) ksocklnd(U) lnet(U) sha512_generic sha256_generic libcfs(U) autofs4 sunrpc ipv6 ppdev parport_pc parport microcode i2c_piix4 i2c_core snd_intel8x0 snd_ac97_codec ac97_bus snd_seq snd_seq_device snd_pcm snd_timer snd soundcore snd_page_alloc e1000 sg ext4 mbcache jbd2 sd_mod crc_t10dif sr_mod cdrom ahci pata_acpi ata_generic ata_piix dm_mirror dm_region_hash dm_log dm_mod [last unloaded: speedstep_lib] Pid: 24218, comm: jbd2/dm-2-8 Not tainted 2.6.32.masterDEBUG11A #1 innotek GmbH VirtualBox RIP: 0010:[<ffffffff81162530>] [<ffffffff81162530>] kfree_debugcheck+0x30/0x40 RSP: 0018:ffff88002733dba0 EFLAGS: 00010082 RAX: 0000000000000039 RBX: 0006000100000002 RCX: 0000000000007a74 RDX: 0000000000000000 RSI: 0000000000000046 RDI: 0000000000000046 RBP: ffff88002733dbb0 R08: 0000000000000000 R09: ffffffff8163acc0 R10: 0000000000000001 R11: 0000000000000000 R12: 0000000000000202 R13: 0006000100000002 R14: ffff880024d9d298 R15: ffff880024d9d298 FS: 0000000000000000(0000) GS:ffff880002200000(0000) knlGS:0000000000000000 CS: 0010 DS: 0018 ES: 0018 CR0: 000000008005003b CR2: 0000003ac2ef5170 CR3: 000000003d0e0000 CR4: 00000000000006f0 DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000 DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400 Process jbd2/dm-2-8 (pid: 24218, threadinfo ffff88002733c000, task ffff88003d640ae0) Stack: ffff880000000020 ffffffffa035ebae ffff88002733dc00 ffffffff8116594b <d> ffff88002851f720 ffff88003f810080 ffff88002733dc20 0006000100000002 <d> ffff880024d9d240 0000000000000000 ffff880024d9d298 ffff880024d9d298 Call Trace: [<ffffffffa035ebae>] ? cfs_free+0xe/0x10 [libcfs] [<ffffffff8116594b>] kfree+0x5b/0x2a0 [<ffffffffa035ebae>] cfs_free+0xe/0x10 [libcfs] [<ffffffffa04ceb73>] lu_global_key_fini+0xa3/0xf0 [obdclass] [<ffffffffa04cf380>] key_fini+0x60/0x190 [obdclass] [<ffffffffa04cf4df>] keys_fini+0x2f/0x120 [obdclass] [<ffffffffa04cf5fd>] lu_context_fini+0x2d/0xc0 [obdclass] [<ffffffffa0b86aa2>] osd_trans_commit_cb+0xe2/0x2b0 [osd_ldiskfs] [<ffffffffa0a3f21a>] ldiskfs_journal_commit_callback+0x8a/0xc0 [ldiskfs] [<ffffffffa00a18af>] jbd2_journal_commit_transaction+0x110f/0x1530 [jbd2] [<ffffffff810096f0>] ? __switch_to+0xd0/0x320 [<ffffffff8107eabb>] ? try_to_del_timer_sync+0x7b/0xe0 [<ffffffffa00a7128>] kjournald2+0xb8/0x220 [jbd2] [<ffffffff81091d66>] kthread+0x96/0xa0 [<ffffffff8100c14a>] child_rip+0xa/0x20 [<ffffffff81091cd0>] ? kthread+0x0/0xa0 [<ffffffff8100c140>] ? child_rip+0x0/0x20 Code: 48 83 ec 08 0f 1f 44 00 00 48 89 fb e8 7a 67 ee ff 84 c0 74 07 48 83 c4 08 5b c9 c3 48 89 de 48 c7 c7 c8 0b 7a 81 e8 ed cc 39 00 <0f> 0b eb fe 66 66 66 2e 0f 1f 84 00 00 00 00 00 55 48 89 e5 41 RIP [<ffffffff81162530>] kfree_debugcheck+0x30/0x40 RSP <ffff88002733dba0> ---[ end trace ff4011ce2a20c79c ]--- Kernel panic - not syncing: Fatal exception Pid: 24218, comm: jbd2/dm-2-8 Tainted: G D --------------- 2.6.32.masterDEBUG11A #1 Call Trace: [<ffffffff814ff155>] ? panic+0xa0/0x168 [<ffffffff815032e4>] ? oops_end+0xe4/0x100 [<ffffffff8100f26b>] ? die+0x5b/0x90 [<ffffffff81502bb4>] ? do_trap+0xc4/0x160 [<ffffffff8100ce35>] ? do_invalid_op+0x95/0xb0 [<ffffffff81162530>] ? kfree_debugcheck+0x30/0x40 [<ffffffffa036def3>] ? libcfs_debug_vmsg2+0x4e3/0xb60 [libcfs] [<ffffffff8100bedb>] ? invalid_op+0x1b/0x20 [<ffffffff81162530>] ? kfree_debugcheck+0x30/0x40 [<ffffffffa035ebae>] ? cfs_free+0xe/0x10 [libcfs] [<ffffffff8116594b>] ? kfree+0x5b/0x2a0 [<ffffffffa035ebae>] ? cfs_free+0xe/0x10 [libcfs] [<ffffffffa04ceb73>] ? lu_global_key_fini+0xa3/0xf0 [obdclass] [<ffffffffa04cf380>] ? key_fini+0x60/0x190 [obdclass] [<ffffffffa04cf4df>] ? keys_fini+0x2f/0x120 [obdclass] [<ffffffffa04cf5fd>] ? lu_context_fini+0x2d/0xc0 [obdclass] [<ffffffffa0b86aa2>] ? osd_trans_commit_cb+0xe2/0x2b0 [osd_ldiskfs] [<ffffffffa0a3f21a>] ? ldiskfs_journal_commit_callback+0x8a/0xc0 [ldiskfs] [<ffffffffa00a18af>] ? jbd2_journal_commit_transaction+0x110f/0x1530 [jbd2] [<ffffffff810096f0>] ? __switch_to+0xd0/0x320 [<ffffffff8107eabb>] ? try_to_del_timer_sync+0x7b/0xe0 [<ffffffffa00a7128>] ? kjournald2+0xb8/0x220 [jbd2] [<ffffffff810920d0>] ? autoremove_wake_function+0x0/0x40 [<ffffffffa00a7070>] ? kjournald2+0x0/0x220 [jbd2] [<ffffffff81091d66>] ? kthread+0x96/0xa0 [<ffffffff8100c14a>] ? child_rip+0xa/0x20 [<ffffffff81091cd0>] ? kthread+0x0/0xa0 [<ffffffff8100c140>] ? child_rip+0x0/0x20
Moving kernels does not seem to reproduce the issue so it is not a lead. I am going to try some client nodes tomorrow. I saw the error on the MDS as well on my initial Master run but have not see it since.
Oleg I am familiar with PAGEALLOC. I am just wondering if it is a separate issue or not. I didn't get a chance to test your patch but I will do it first thing tomorrow.
On my nodes can produce the issue I was able to test 2.2.59 and I don't see the issue but lu-998 code should be present it the release.
I am building on the client nodes now to speed thing up I hope tomorrow I can get thing greatly narrowed down if Oleg's patch is not the root issue.
Sorry I didn't get a change to push Yu's build errors yet.