Lustre devel - Jan 2007 - [Bug 11324] LDISKFS-fs error (device sdc): ldiskfs_free_blocks

Please don''t reply to lustre-devel. Instead, comment in Bugzilla by
using the following link:
https://bugzilla.lustre.org/show_bug.cgi?id=11324

           What    |Removed                     |Added
----------------------------------------------------------------------------
           Severity|S2 (major)                  |S1 (critical)
  Status Whiteboard|2006-12-06: Suspected       |2006-01-06: Original damage
                   |hardware failure; LLNL to   |inflicted by hardware
                   |test updated e2fsk on broken|failure, e2fsck claims to
                   |filesystem                  |have repaired it, OST still
                   |                            |asserts on start.


We continue to hit the following assertions when starting the pigs[33-40] OSTs.
 A few weeks back they suffered damage due to a DDN hardware failure but have
been nothing but trouble since.  This is in spite of running many
e2fsck''s with
the latest fixes applied and finding no damage in the filesystems.  Yet when we
start the OSTs we immedately hit the following assertion once the recovery
window closes.

We need to diagnose the root cause of this issue immediately to get the
filesystem back online.  This filesystem being down is disrupting all of our OCF
systems and as of now it has been offline since 4pm (~10 hours).

Marking bug Sev 1 until the FS can be brought back online.

-----

2007-01-06 01:21:13 Assertion failure in mb_free_blocks() at
/tmp/root.29834/rpm/BUILD/lustre-1.4.6.95_17.4llnl/lustre/ldiskfs/mballoc.c:771:
"mb_test_bit(block, LDISKFS_MB_BITMAP(e3b))" 2007-01-06 01:21:13
-----------
[cut here ] --------- [please bite here ] ---------
2007-01-06 01:21:13 Kernel BUG at mballoc:771
2007-01-06 01:21:13 invalid operand: 0000 [1] SMP
2007-01-06 01:21:13 CPU 0
2007-01-06 01:21:13 Modules linked in: obdfilter(U) fsfilt_ldiskfs(U) ldiskfs(U)
jbd(U) ost(U) ptlrpc(U) obdclass(U) lvfs(U) ksocklnd(U) lnet(U) libcfs(U)
perfctr(U) i2c_i801(U) netdump(U) e752x_edac(U) edac_mc(U) i2c_dev(U)
i2c_core(U) dm_mod(U) rtc(U) md(U) uhci_hcd(U) ehci_hcd(U) floppy(U) sd_mod(U)
qla2300(U) qla2xxx(U) scsi_transport_fc(U) scsi_mod(U) unionfs(U) nfs(U)
lockd(U) sunrpc(U) e1000(U) 2007-01-06 01:21:13 Pid: 3335, comm: ll_ost_io_29
Not tainted 2.6.9-54chaos
2007-01-06 01:21:13 RIP: 0010:[<ffffffffa03b7dda>]
<ffffffffa03b7dda>{:ldiskfs:mb_free_blocks+295}
2007-01-06 01:21:13 RSP: 0018:000001005d13d588  EFLAGS: 00010212
2007-01-06 01:21:13 RAX: 00000000000000aa RBX: 000001005d13d628 RCX:
000001005b2fc4a8
2007-01-06 01:21:13 RDX: 000001007c55cc01 RSI: 0000000000000246 RDI:
ffffffff803ba240
2007-01-06 01:21:13 RBP: 0000010074cc4e48 R08: ffffffff803ba248 R09:
000001005d13d628
2007-01-06 01:21:13 R10: 0000000100000000 R11: 0000000000000000 R12:
0000000000000037
2007-01-06 01:21:13 R13: 0000000000001930 R14: 0000000000000036 R15:
0000000000001931
2007-01-06 01:21:13 FS:  0000002a95b356e0(0000) GS:ffffffff804e2900(0000)
knlGS:0000000000000000
2007-01-06 01:21:13 CS:  0010 DS: 0000 ES: 0000 CR0: 000000008005003b
2007-01-06 01:21:13 CR2: 0000002a9556c000 CR3: 0000000000101000 CR4:
00000000000006e0
2007-01-06 01:21:13 Process ll_ost_io_29 (pid: 3335, threadinfo
000001005d13c000, task 000001005d137710)
2007-01-06 01:21:13 Stack: 0000000100000000 0000000000003cb7 0000010074cc4e48
0000000000000037
2007-01-06 01:21:13        000000001e5b9930 000001004fedbc00 0000000000003cb7
ffffffffa03ba117
2007-01-06 01:21:13        000000001e5b9966 0000000000001930
2007-01-06 01:21:13 Call
Trace:<ffffffffa03ba117>{:ldiskfs:ldiskfs_mb_free_blocks+903}
2007-01-06 01:21:13       
<ffffffffa03bbdbd>{:ldiskfs:ldiskfs_free_blocks+61}
2007-01-06 01:21:13       
<ffffffffa03b678e>{:ldiskfs:ldiskfs_remove_blocks+264}
2007-01-06 01:21:13       
<ffffffffa03b629f>{:ldiskfs:ldiskfs_ext_remove_space+1223}
2007-01-06 01:21:13       
<ffffffffa03a6b5b>{:ldiskfs:ldiskfs_mark_inode_dirty+65}
2007-01-06 01:21:13       
<ffffffffa03b6e42>{:ldiskfs:ldiskfs_ext_truncate+324}
2007-01-06 01:21:13       
<ffffffffa03a8133>{:ldiskfs:ldiskfs_truncate+268}
<ffffffff8017a413>{__getblk+42}
2007-01-06 01:21:13        <ffffffff80165a11>{unmap_mapping_range+339}
<ffffffff80165abc>{vmtruncate+162}
2007-01-06 01:21:13        <ffffffff8018f479>{inode_setattr+54}
<ffffffffa03a7bc4>{:ldiskfs:ldiskfs_setattr+296}
2007-01-06 01:21:13       
<ffffffffa03d69d4>{:fsfilt_ldiskfs:fsfilt_ldiskfs_setattr+325}
2007-01-06 01:21:13       
<ffffffffa03ef19a>{:obdfilter:filter_destroy+1823}
2007-01-06 01:21:13       
<ffffffffa02e84aa>{:ptlrpc:lustre_pack_reply+1817}
2007-01-06 01:21:13        <ffffffffa037aaa7>{:ost:ost_handle+4322}
<ffffffffa01db1bb>{:libcfs:libcfs_debug_msg+1558}
2007-01-06 01:21:13        <ffffffff801e2b25>{vsnprintf+848}
<ffffffff801e2e36>{snprintf+131}
2007-01-06 01:21:13       
<ffffffffa02ed469>{:ptlrpc:ptlrpc_server_handle_request+2714}
2007-01-06 01:21:13        <ffffffff8013bb5c>{__mod_timer+293}
<ffffffffa02ee5f3>{:ptlrpc:ptlrpc_main+2127}
2007-01-06 01:21:13        <ffffffff8012f92c>{default_wake_function+0}
<ffffffffa02edd97>{:ptlrpc:ptlrpc_retry_rqbds+0}
2007-01-06 01:21:13       
<ffffffffa02edd97>{:ptlrpc:ptlrpc_retry_rqbds+0}
<ffffffff8010ff3f>{child_rip+8}
2007-01-06 01:21:13        <ffffffffa02edda4>{:ptlrpc:ptlrpc_main+0}
<ffffffff8010ff37>{child_rip+0}

Please don''t reply to lustre-devel. Instead, comment in Bugzilla by
using the following link:
https://bugzilla.lustre.org/show_bug.cgi?id=11324



Created an attachment (id=9285)
Please don''t reply to lustre-devel. Instead, comment in Bugzilla by
using the following link:
 --> (https://bugzilla.lustre.org/attachment.cgi?id=9285&action=view)
Console log from OSS with assertion 

The fscks run immediately before this OSS was started detected absolutely not
damage on the disk.  We''re going to need to take a careful look at the
disk I
think and discover what the fsck check is missing and why.  Thoughts?

Please don''t reply to lustre-devel. Instead, comment in Bugzilla by
using the following link:
https://bugzilla.lustre.org/show_bug.cgi?id=11324



Ahh one more thought.  The version of lustre running on the servers lustre
1.4.6.95-17.4llnl which does not contain Alex''s last fix in bug 10090
to prevent
in-core vs on-disk discerpencies in the bitmaps from occuring in low memory
situations.  Also for still unknown reasons these nodes always appear to be
running in a low memory state with the OOM killer running regularly. 
I''m not
convinced that explains this issue just yet but it''s good to keep in
mind.

Please don''t reply to lustre-devel. Instead, comment in Bugzilla by
using the following link:
https://bugzilla.lustre.org/show_bug.cgi?id=11324



Created an attachment (id=9286)
Please don''t reply to lustre-devel. Instead, comment in Bugzilla by
using the following link:
 --> (https://bugzilla.lustre.org/attachment.cgi?id=9286&action=view)
show block''s details in case of ASSERT

Brian, could you add this patch to ldiskfs series, rebuild it and rerun so that

we know exactly inode and block number. then we''d check on-disk bitmaps
with
debugfs. next step would be to get the image (e2image <dev>
<image-file>; bzip2

-3 <image-file>) and try recent e2fsck to understand why it
didn''t catch the
issue.

Please don''t reply to lustre-devel. Instead, comment in Bugzilla by
using the following link:
https://bugzilla.lustre.org/show_bug.cgi?id=11324



Thanks for the quick reply Alex.  After catching a few hours of sleep I gave
your debugging patch a spin this morning with one modification.  Since we have 3
4TB ldiskfs devices on this node I added inode->i_sb->s_id to the output
to
indentify the correct device.

<From pigs33 with patch>
double-free on sdc of inode 115544101''s block 924357008 (bit 4496 in
group 28209)
Assertion failure in mb_free_blocks() at
/tmp/root.26989/rpm/BUILD/lustre-1.4.6.95_17.6llnl/lustre/ldiskfs/mballoc.c:782:
"mb_test_bit(block, LDISKFS_MB_BITMAP(e3b))"

debugfs:  stat <115544101>
Inode: 115544101   Type: regular    Mode:  0600   Flags: 0x80000   Generation:
1120456138
User: 53738   Group: 53738   Size: 2428900
File ACL: 0    Directory ACL: 0
Links: 1   Blockcount: 8
Fragment:  Address: 0    Number: 0    Size: 0
ctime: 0x4584a338 -- Sat Dec 16 17:54:00 2006
atime: 0x4584a338 -- Sat Dec 16 17:54:00 2006
mtime: 0x4584a338 -- Sat Dec 16 17:54:00 2006
Size of extra inode fields: 4
Extended attributes stored in inode body:
  fid = "28 26 f6 6e 00 00 00 00 5b eb fc 32 01 00 00 00 87 33 14 00 00 00
00 00
00 00 00 00 00 00 00 00 " (32)
BLOCKS:
(IND):924357007
TOTAL: 1
> then we''d check on-disk bitmaps with debugfs.
Results from debugfs attached to bug.

> next step would be to get the image...
Sadly I don''t think this is going to be possible.  I''ve never
been able to
successfully use e2image with luns in excess of 2TB, and these are 4TB.  Plus
these are diskless nodes and I''m not sure we have space to store the
image.
Regardless, I''ll see what can be done.

Please don''t reply to lustre-devel. Instead, comment in Bugzilla by
using the following link:
https://bugzilla.lustre.org/show_bug.cgi?id=11324



Created an attachment (id=9287)
Please don''t reply to lustre-devel. Instead, comment in Bugzilla by
using the following link:
 --> (https://bugzilla.lustre.org/attachment.cgi?id=9287&action=view)
pigs33 sdc block 924357007

Please don''t reply to lustre-devel. Instead, comment in Bugzilla by
using the following link:
https://bugzilla.lustre.org/show_bug.cgi?id=11324



Created an attachment (id=9288)
Please don''t reply to lustre-devel. Instead, comment in Bugzilla by
using the following link:
 --> (https://bugzilla.lustre.org/attachment.cgi?id=9288&action=view)
pigs33 sdc block 924357008

Please don''t reply to lustre-devel. Instead, comment in Bugzilla by
using the following link:
https://bugzilla.lustre.org/show_bug.cgi?id=11324

           What    |Removed                     |Added
----------------------------------------------------------------------------
Attachment #9287 is|0                           |1
           obsolete|                            |


Created an attachment (id=9289)
Please don''t reply to lustre-devel. Instead, comment in Bugzilla by
using the following link:
 --> (https://bugzilla.lustre.org/attachment.cgi?id=9289&action=view)
pigs33 sdc block 924357007

dd if=/dev/sdc of=/var/tmp/pigs33-sdc-blk-924357007 skip=924357007 count=1
bs=4096

Please don''t reply to lustre-devel. Instead, comment in Bugzilla by
using the following link:
https://bugzilla.lustre.org/show_bug.cgi?id=11324

           What    |Removed                     |Added
----------------------------------------------------------------------------
Attachment #9288 is|0                           |1
           obsolete|                            |


Created an attachment (id=9290)
Please don''t reply to lustre-devel. Instead, comment in Bugzilla by
using the following link:
 --> (https://bugzilla.lustre.org/attachment.cgi?id=9290&action=view)
pigs33 sdc block 924357008

dd if=/dev/sdc of=/var/tmp/pigs33-sdc-blk-924357008 skip=924357008 count=1
bs=4096

Please don''t reply to lustre-devel. Instead, comment in Bugzilla by
using the following link:
https://bugzilla.lustre.org/show_bug.cgi?id=11324



Created an attachment (id=9291)
Please don''t reply to lustre-devel. Instead, comment in Bugzilla by
using the following link:
 --> (https://bugzilla.lustre.org/attachment.cgi?id=9291&action=view)
pig33 sdc fsck resuts run immediately after assertion

Please don''t reply to lustre-devel. Instead, comment in Bugzilla by
using the following link:
https://bugzilla.lustre.org/show_bug.cgi?id=11324



Created an attachment (id=9292)
Please don''t reply to lustre-devel. Instead, comment in Bugzilla by
using the following link:
 --> (https://bugzilla.lustre.org/attachment.cgi?id=9292&action=view)
pigs33 sdc block 924352516

debugfs:  imap <115544101>
Inode 115544101 is part of block group 28209
	located at block 924352516, offset 0x0400

dd if=/dev/sdc of=/var/tmp/pigs33-sdc-blk-924352516 skip=924352516 count=1
bs=4096

Sorry about the bad blocks the first time around Alex.	I just forget to set
the
bs and didn''t sanity check them before attaching them to the bug. 
I''ve
attached
the correct blocks now.

Please don''t reply to lustre-devel. Instead, comment in Bugzilla by
using the following link:
https://bugzilla.lustre.org/show_bug.cgi?id=11324



Looking at the the inode in some detail also shows some suspicious values.

debugfs:  mi <115544101>
                          Mode    [0100600]
                       User ID    [53738]
                      Group ID    [53738]
                          Size    [2428900]
                 Creation time    [1166320440]
             Modification time    [1166320440]
                   Access time    [1166320440]
                 Deletion time    [0]
                    Link count    [1]
              Block count high    [0]
                   Block count    [8]
                    File flags    [0x80000]
                    Generation    [0x42c8cdca]
                      File acl    [0]
           High 32bits of size    [0]
              Fragment address    [0]
               Direct Block #0    [127754]
               Direct Block #1    [65540]
               Direct Block #2    [19]
               Direct Block #3    [6400]
               Direct Block #4    [924357007]
               Direct Block #5    [0]
               Direct Block #6    [3]
               Direct Block #7    [95]
               Direct Block #8    [924356611]
               Direct Block #9    [99]
              Direct Block #10    [174]
              Direct Block #11    [924356707]
                Indirect Block    [274]
         Double Indirect Block    [124]
         Triple Indirect Block    [924356882]

Alex I''ve also now run Andreas''s latest version with his
version of the
extents header checking.  It also didn''t find any damage, but
it''s probably
the best place for you to start.  I downloaded from the FTP site here:

ftp://ftp.clusterfs.com/pub/lustre/other/e2fsprogs/testing/*-1.39.cfs3*

Please don''t reply to lustre-devel. Instead, comment in Bugzilla by
using the following link:
https://bugzilla.lustre.org/show_bug.cgi?id=11324



The direct and indirect block values just looked odd to me.  For example, I
wasn''t expecting a double or tripple indirect block based on the file
size.  But
I also wasn''t aware mi doesn''t support extents yet.  So if I
ignore the
direct/indirect blocks things look ok.

Please let me know if you manage to craft an fsck which detects the corrupted
extent header.  We have probably 10 or so ldiskfs devices with damage similar to
this so we''ve got lots of places to verify it works!  I may fix one or
two as
best as I can for now by simply zeroing out the direct/indirect blocks in the
inode, and verifiying that''s the only issue.

Please don''t reply to lustre-devel. Instead, comment in Bugzilla by
using the following link:
https://bugzilla.lustre.org/show_bug.cgi?id=11324



To get us limping again I''ve gone through all the nodes which were
hitting those
double-free asserion on started up and manually zero''d the inodes with
debugfs.
 This has allowed us to restart the servers for now and get the FS back online
but I''m sure there''s additional as yet undiscovered damage. 
So we still need
that improved e2fsck as soon as possible.

Please don''t reply to lustre-devel. Instead, comment in Bugzilla by
using the following link:
https://bugzilla.lustre.org/show_bug.cgi?id=11324

           What    |Removed                     |Added
----------------------------------------------------------------------------
                 CC|                            |alex@clusterfs.com


Alex, please log a separate bug (S2) describing the changes required to e2fsck
to handle this (corrupted extent header) and other important use cases.
We''ll
get Livermore to rank it in their list of priorities, but I think it should be
very high.

Please don''t reply to lustre-devel. Instead, comment in Bugzilla by
using the following link:
https://bugzilla.lustre.org/show_bug.cgi?id=11324



Created an attachment (id=9309)
Please don''t reply to lustre-devel. Instead, comment in Bugzilla by
using the following link:
 --> (https://bugzilla.lustre.org/attachment.cgi?id=9309&action=view)
incremental patch to ldiskfs

this patch reworks consistency checks in ldiskfs''s extents code. the
patch
isn''t supposed to be applied directly, rather to track changes in
readable
manner.

Please don''t reply to lustre-devel. Instead, comment in Bugzilla by
using the following link:
https://bugzilla.lustre.org/show_bug.cgi?id=11324



Created an attachment (id=9310)
Please don''t reply to lustre-devel. Instead, comment in Bugzilla by
using the following link:
 --> (https://bugzilla.lustre.org/attachment.cgi?id=9310&action=view)
patch to apply to lustre tree

this is the same change as 9309, but it can be applied directly to lustre tree.

Please don''t reply to lustre-devel. Instead, comment in Bugzilla by
using the following link:
https://bugzilla.lustre.org/show_bug.cgi?id=11324



Alex,
We just want to insure that ldiskfs EXT_ASSERTs
are all related to code invariants (i.e. the
code itself is messed up in its assumptions), and
NOT that there is invalid data from the filesystem.
A quick perusal indicates that in auditing the code
we might have to trace the data being EXT_ASSERTed on,
to its origins to be sure it isn''t data originally
from the filesystem that is causing the assert.
(hopefully this comment makes sense to you)

Please don''t reply to lustre-devel. Instead, comment in Bugzilla by
using the following link:
https://bugzilla.lustre.org/show_bug.cgi?id=11324



Created an attachment (id=9350)
Please don''t reply to lustre-devel. Instead, comment in Bugzilla by
using the following link:
 --> (https://bugzilla.lustre.org/attachment.cgi?id=9350&action=view)
Fixes memory leak introduced by attachment 9309

While skimming this new patch in our patch series I spotted a small memory 
leak which was accidentally introduced.  The attached patch is an incremetal 
fix to plug the hole.

Please don''t reply to lustre-devel. Instead, comment in Bugzilla by
using the following link:
https://bugzilla.lustre.org/show_bug.cgi?id=11324

           What    |Removed                     |Added
----------------------------------------------------------------------------
   Attachment #9350|review?(alex@clusterfs.com) |review+
               Flag|                            |


(From update of attachment 9350)
you''re right, of course.

Please don''t reply to lustre-devel. Instead, comment in Bugzilla by
using the following link:
https://bugzilla.lustre.org/show_bug.cgi?id=11324



LDISKFS-fs error (device sdb): ldiskfs_ext_remove_space: bad headerin inode
#3751979: unexpected eh_depth - magic f30a, entries 5, max 340(340), depth 1(0)

LDISKFS-fs error (device sdc): ldiskfs_ext_remove_space: bad headerin inode
#82870318: unexpected eh_depth - magic f30a, entries 5, max 340(340), depth 1(0)

LDISKFS-fs error (device sda): ldiskfs_ext_remove_space: bad header in inode
#74317911: unexpected eh_depth - magic f30a, entries 6, max 340(340), depth 1(0)

Many of these failures observed when running with the incremental patch to
ldiskfs applied to our tree, attachment 9309.  The magic looks good, its
complaining about the eh_depth, so my current thinking is for this call path a
bad expected value is simply being passed to ldiskfs_ext_check_header().  In
particular I think the second check in ldiskfs_ext_remove_space is suspect since
it always passes in a 0.

Please don''t reply to lustre-devel. Instead, comment in Bugzilla by
using the following link:
https://bugzilla.lustre.org/show_bug.cgi?id=11324

           What    |Removed                     |Added
----------------------------------------------------------------------------
Attachment #9309 is|0                           |1
           obsolete|                            |


Created an attachment (id=9373)
Please don''t reply to lustre-devel. Instead, comment in Bugzilla by
using the following link:
 --> (https://bugzilla.lustre.org/attachment.cgi?id=9373&action=view)
incremental patch to ldiskfs

includes memleak fix

Please don''t reply to lustre-devel. Instead, comment in Bugzilla by
using the following link:
https://bugzilla.lustre.org/show_bug.cgi?id=11324

           What    |Removed                     |Added
----------------------------------------------------------------------------
Attachment #9373 is|0                           |1
           obsolete|                            |


Created an attachment (id=9375)
Please don''t reply to lustre-devel. Instead, comment in Bugzilla by
using the following link:
 --> (https://bugzilla.lustre.org/attachment.cgi?id=9375&action=view)
incremental patch to ldiskfs

tested with depth=2