Description of problem:
In the last week, I've seen the same error reported in bug #476533 on two hosts
running kernel-2.6.18-128.1.6.el5 (CentOS dev hosts). One host was a KVM
guest, the other was a physical system with a 3ware controller.
Version-Release number of selected component (if applicable):
kernel-2.6.18-128.1.6.el5
Fortunately, on the second host, the /var partition wasn't the one that went
read-only, so a little more information is available from /var/log/messages:
Apr 7 01:39:54 bucket kernel: Linux version 2.6.18-128.1.6.el5
(mockbuild@builder10.centos.org) (gcc version 4.1.2 20080704 (Red Hat
4.1.2-44)) #1 SMP Wed
Apr 1 09:10:25 EDT 2009
...
Apr 8 03:41:54 bucket kernel: EXT3-fs error (device sdc1):
ext3_free_blocks_sb: bit already cleared for block 170872073
Apr 8 03:41:54 bucket kernel: Aborting journal on device sdc1.
Apr 8 03:41:54 bucket kernel: ext3_abort called.
Apr 8 03:41:54 bucket kernel: EXT3-fs error (device sdc1):
ext3_journal_start_sb: Detected aborted journal
Apr 8 03:41:54 bucket kernel: Remounting filesystem read-only
Apr 8 03:41:54 bucket kernel: EXT3-fs error (device sdc1) in
ext3_reserve_inode_write: Journal has aborted
Apr 8 03:41:54 bucket kernel: EXT3-fs error (device sdc1) in ext3_truncate:
Journal has aborted
Apr 8 03:41:54 bucket kernel: EXT3-fs error (device sdc1) in
ext3_reserve_inode_write: Journal has aborted
Apr 8 03:41:54 bucket kernel: EXT3-fs error (device sdc1) in ext3_orphan_del:
Journal has aborted
Apr 8 03:41:54 bucket kernel: EXT3-fs error (device sdc1) in
ext3_reserve_inode_write: Journal has aborted
Apr 8 03:41:54 bucket kernel: __journal_remove_journal_head: freeing
b_committed_data
Apr 8 03:41:54 bucket last message repeated 18 times
I set up a test environment under KVM on Fedora 10. The test system was
running CentOS 5.3 with the latest kernel:
# uname -a
Linux backup 2.6.18-128.1.6.el5 #1 SMP Wed Apr 1 09:19:18 EDT 2009 i686 athlon
i386 GNU/Linux
This is an identical setup to the VM that I first saw fail. Overnight, I ran
two instances of bonnie++ in a loop in different directories under /var/tmp.
Additionally, I ran a loop copying /usr to a directory under /var/tmp and then
removing it. After around 12 hours, the rsync loop quit when it could not
remove one of the files. The kernel recorded:
Apr 14 09:10:44 backup kernel: attempt to access beyond end of device
Apr 14 09:10:44 backup kernel: hda3: rw=0, want=1719008864, limit=3357585
I booted the system into single user mode to run fsck on the filesystems and
found a considerable amount of corruption on the /var partition, presumably
caused by the two "bonnie++" loops and the rsync loop. Running "fsck
/dev/hda3" reported that the filesystem was clean, despite the fact that the
kernel had noticed an attempt to access beyond the end of the device. I ran
"fsck -n -f /dev/hda3" to get a list of the errors on the filesystem. Its
output will be attached. The damaged filesystem is still available if any
further information about it would be helpful.
While the systems exhibiting the problem are not RHEL systems, I believe it is
likely that they are affected. Please help me confirm this bug.
Created attachment 339534 [details]
Output from "fsck -n -f /dev/hda3"
the problem in comment #2 looks like a different problem, FWIW - at least a
different end result. Both could be caused by any sort of corruption,
including kernel in-memory corruption, or hardware problems. Or bugs ...
I can try the same test mentioned in #2 to see if I can reproduce on RHEL5.3.
this problem also exists in kernel version 2.6.18-128.1.10.el5xen
Similar problems show up on RHEL4.7 (kernel 2.6.9-78.0.17smp).
Also verified with "fsstress" utility. (thanks to LKML)
Any ext3 filesystem shows errors if run with arguments like this:
mkfs.ext3 /dev/ram0
mount -t ext3 /dev/ram0 /mnt/test_file_system
mkdir -p /mnt/test_file_system/work
fsstress -d /mnt/test_file_system/work -p 3 -l 0 -n 100000000
Will try to test other kernel versions in short time.
Verified on latest RHEL5 update:
2.6.18-128.1.14.el5 #1 SMP Mon Jun 1 15:52:36 EDT 2009 i686 i686 i386 GNU/Linux
problem exists.
Verified on old unpatched RHEL3:
2.4.21-4.ELsmp #1 SMP Fri Oct 3 17:52:56 EDT 2003 i686 i686 i386 GNU/Linux
kernel panic trying to umount ext3 fs.
Verified on very old RedHat 7.2 :)
2.4.7-10 #1 Thu Sep 6 17:27:27 EDT 2001 i686 unknown
no problems. ok, unfair, there is only ext2.
(In reply to comment #7)
> Similar problems show up on RHEL4.7 (kernel 2.6.9-78.0.17smp).
Similar, or same? bug #476533 reports this should be fixed in 78.0.14.EL so
perhaps there is yet another root cause if it's the exact same problem.
(In reply to comment #7)
> Verified on latest RHEL5 update:
>
> 2.6.18-128.1.14.el5 #1 SMP Mon Jun 1 15:52:36 EDT 2009 i686 i686 i386 GNU/Linux
>
> problem exists.
This kernel also has the same fix as bug #476533, fixed in bug #225172
You did the same test as in comment #6?
Thanks,
-Eric
OK, short summary:
We have pre-production system RHEL4.7 (kernel -78.0.17).
Got error "ext3_free_blocks_sb: bit already cleared for block" on two different
servers.
Database server produces lot of oracle archivelog files. 100gb filesystem
sometimes get full, then older files are deleted. Error appears after 2 months
of testing.
Application server writes to some 20-30 logfiles simultaneously. Error appears
after performance testing, within couple days.
This error "ext3_free_blocks_sb: bit already cleared for block" should be fixed
in 78.0.14, right?
Then i started to search for test tools.
Found this:
http://lkml.org/lkml/2008/11/14/121
fixed in vanilla kernel 2.6.29
Changelog here:
http://www.kernel.org/pub/linux/kernel/v2.6/ChangeLog-2.6.29
Exaple:
# uname -a
Linux gasha-rhel5 2.6.18-128.1.14.el5
fsck errors:
/dev/ram2: Inode 251, i_size is 205449, should be 995328. FIXED.
/dev/ram2: Inode 3416, i_size is 654163, should be 1212416. FIXED.
/dev/ram2: Inode 4032, i_size is 868310, should be 1138688. FIXED.
/dev/ram2: Inode 3530, i_size is 1458533, should be 1900544. FIXED.
Compiled fresh vanilla 2.6.30 kernel with "make oldconfig".
gasha-rhel5 kernel: Linux version 2.6.30 (root@gasha-rhel5) (gcc version 4.1.2
20080704 (Red Hat 4.1.2-44)) #1 SMP Sun Jun 28 00:39:51 EEST 2009
No fsck errors.
I cannot say, that these two error messages have the same roots. Then i need to
run these stress tests longer.
Ok, this bug is ranging all over now... It was opened for a very distinct
error message:
Read-only filesystem after 'ext3_free_blocks_sb: bit already cleared for block'
errors
But the testcase in comment #9, while it does seem to be an issue in RHEL5 that
I'll investigate, looks like it exposes a different problem. It also appears
to provoke a problem yet upstream, though manifesting differently.
However, I'm still trying to reproduce anything on RHEL5 that looks like the
original bug reported here.
-Eric
Unfortunately, I think this bug started out ranging all over, and I take
responsibility for that. I believe that I initially saw this bug on a system
early in my deploying 5.3. I was working on a system whose RAID array had
failed, and didn't save information on the failure because I suspected the
hardware. Subsequent hardware tests did not reveal any problems. This system
wasn't mentioned in my initial report, because I had no data.
Later, I saw a similar failure on another system with a 3ware controller, which
I did mention. I've recently determined that this system had hardware
problems. This data should be ignored. That was "bucket", mentioned in
comment #1. Unfortunately, since I opened the ticket with information from
this host, the summary and half of the information I provided is incorrect.
I'm still fairly confident that the KVM guest mentioned in comments #2 and #3
was a legitimate bug in Linux. Since the nature of the bug isn't clear to me,
I'm not sure what kinds of corruption may result, so it may not be possible to
determine whether or not all of the commenters are seeing the same corruption
bug. We should probably focus on the test case in comment #9.
Please let me know what additional information I can provide, or what testing I
can do.
Another data point
------------------
We've seen a similar problem (I think) on one RHEL4 machine (we've got 7
identical ones in terms of hardware, and its just this one.
What we see is that the /var partition will just suddenly go read only. Of
course the problem is, the minute it goes read only it can't write to the log
files.
A mount -o remount,rw /var does not clear the problem, only a reboot will do
it.
We're currently running the 2.6.9-89 SMP kernel.
Scott, if there's any chance for a serial console, or a look at a physical
console, maybe you can get more information about what's gone wrong?
Or is "bit already cleared for block" the only info...
Thanks,
-Eric
We're actually not even seeing that, it just suddenly flips to read only.
Next time it happens I'll look at the physical console and see what I see.
Unfortunately, it appears to be non-repeatedly, and inconsistent as to when it
happens.
Created attachment 354320 [details]
ext3 error after sync
we found ext3 errors 4 identical Linux machines (installed via jumpstart,
kernel 2.6.18-128.el5, x86_64)
always in /var, which was remounted read only
attached console messages, on serial console, there is nothing more produced.
I'm still trying to reproduce error using "fsstress" utility on dedicated
stress system. No luck.
I think it has wrong pattern. Real thing should be 2-cpu server, and and
simultaneous writes to MANY open files, at the same time. Some kind of race
condition.
For what it's worth, I've been poking around this all day today (i.e. testcase
in comment #9 with fsstress). This is what I've found so far:
Testing with:
fsstress -d /mnt/test_file_system/work -p 3 -l 0 -n 100000000 -X. Some tests
re-run with -p 1 to remove the possibility of parallel tasks impacting the
test.
RHEL 5.4 beta kernel version 2.6.18-157.el5 (otherwise a stock 5.3 install). No
other processes are accesting the test_file_system.
RHEL is running as a vmware esxi 4.0 guest, 2vcpu, 2GB ram. No errors in dmesg.
1. fails on ext2, blocksizes 1024, 2048, 4096, when mounted on a loop device
(loop0) losetup against a file in /dev/shm (tmpfs).
2. fails on ext2, blocksizes 1024, 2048, 4096, when mounted on a ramdisk (ram0)
using the new brd driver (part of rhel 5.4).
3. fails on ext3, blocksizes 1024, 2048, 4096, when mounted on a loop device
(loop0) losetup against a file in /dev/shm (tmpfs), ext3 mount options
data=writeback and data=ordered
4. fails on ext3, blocksizes 1024, 2048, 4096, when mounted on a ramdisk (ram0)
using the new brd driver (part of rhel 5.4), ext3 mount options data=writeback
and data=ordered
5. fails on ext3, blocksize default, when mounted on a loop device (loop0)
losetup against a file in / (exiting ext3 filesystem).
6. succeeds on ext3 for the above, with data=journal mount option.
7. Basically, as best I can tell, ext3 with data=journal always works, and
nothing else does.
8. Doesn't appear to be limited to ramdisk (or at least, loop devices on the
actual hard drive fail also).
9. I tried ext4.. it also failed. I don't recall which variation I used above.
It was mounted with default mount options.
note:
"Fail" is evidenced by some combination of errors similar to:
+ e2fsck -fvp /dev/ram0
/dev/ram0: HTREE directory inode 61596 has an invalid root node.
HTREE INDEX CLEARED.
/dev/ram0: HTREE directory inode 61604 has an invalid root node.
HTREE INDEX CLEARED.
/dev/ram0: HTREE directory inode 61632 has an invalid root node.
HTREE INDEX CLEARED.
/dev/ram0: HTREE directory inode 61644 has an invalid root node.
HTREE INDEX CLEARED.
/dev/ram0: HTREE directory inode 61660 has an invalid root node.
HTREE INDEX CLEARED.
/dev/ram0: Inode 69395, i_size is 902294, should be 1906688. FIXED.
/dev/ram0: Inode 69723, i_size is 1277952, should be 1280000. FIXED.
/dev/ram0: Inode 69781, i_size is 0, should be 939008. FIXED.
/dev/ram0: Inode 70098, i_size is 662593, should be 1267712. FIXED.
/dev/ram0: Inode 70227, i_size is 0, should be 330752. FIXED.
/dev/ram0: Inode 70418, i_size is 892928, should be 896000. FIXED.
/dev/ram0: Inode 70541, i_size is 380928, should be 382976. FIXED.
/dev/ram0: Inode 71272, i_size is 503808, should be 506880. FIXED.
/dev/ram0: Inode 71663, i_size is 2002944, should be 2004992. FIXED.
/dev/ram0: Inode 72421, i_size is 348160, should be 350208. FIXED.
/dev/ram0: Inode 73392, i_size is 958464, should be 960512. FIXED.
/dev/ram0: Inode 73980, i_size is 434176, should be 437248. FIXED.
/dev/ram0: Inode 74468, i_size is 466944, should be 470016. FIXED.
/dev/ram0: Inode 76077, i_size is 200704, should be 202752. FIXED.
/dev/ram0: Inode 71114, i_size is 0, should be 103424. FIXED.
/dev/ram0: Inode 70462, i_size is 0, should be 72704. FIXED.
/dev/ram0: Entry 'c638' in /work/p0/d1/d141/d3d7/d4ed (61644) has an incorrect
filetype (was 3, should be 1).
/dev/ram0: UNEXPECTED INCONSISTENCY; RUN fsck MANUALLY.
(i.e., without -a or -p options)
"Success" was evidenced by no errors after repeated iterations (in my case, I
let it run a couple hundred runs).
Furthermore, I put a bunch of links into a comment I put against the RHEL 5.4
brd driver info discussing various aspects I found today. The info is viewable
from rhel regarding the use of the new brd ramdisk driver in rhel 5.4:
https://bugzilla.redhat.com/show_bug.cgi?id=480663
Thanks,
Devin
This bug has attracted several seemingly unrelated issues - please open
distinct bugzilla tickets when you change the storage/virt/etc stack since all
of these can produce unique issues.
I'll open 30 tickets if necessary ;) I was kind of hoping that since Red Hat
can see evidence of corruption in ext2, ext3, and ext4, that your team might be
more interested in the internal processes than me.
Please confirm you want new tickets for each combo? FYI, I'm now testing
against a physical box (IBM server) as well. Same results.
Thanks,
Devin Nate
Devin, your testcase & error seem to be on-disk-corruption and/or fsck related,
with no mention of "bit already cleared for block" in the kernel messages,
which was the original error report for this bug. That's why we'd like a new
bug to track this seemingly distinct problem.
If your failure case is always more or less the same basic corruption found,
I'd be happy with 1 new bug from you, in which you clearly describe the
testcase (attaching or pasting the test script you used would be great), and
test environment, and also the problematic results you encountered after the
tests.
Thanks,
-Eric
Hi Eric, thank you very much. What/where/how would you like it opened? I
appreciate the response, just want to make sure it gets appropriate attention
(and really have no idea how to open a bug to accomplish that - in fact I've
never opened a new rhel bug before). Any guidance would be helpful, and I'll
upload all info.
Currently compiling a stock kernel 2.6.30.4 to see there, based on the rhel 5.4
.config for the kernel.
Thanks,
Devin
Devin, you can go here:
https://bugzilla.redhat.com/enter_bug.cgi?product=Red%20Hat%20Enterprise%20Linux%205
and file a bug agains the kernel component.
Or if you're a RHEL customer, going through your support contacts is often
encouraged as well.
Thanks Eric. We are a RHEL customer.. have no idea who our support contact is.
I've opened a new bug:
https://bugzilla.redhat.com/show_bug.cgi?id=515529
If I could trouble you to take a glance at it to make sure I've opened it
properly for redhat.
Thanks,
Devin
I've just deployed a system with RedHat 5.3 and we are seeing the same issue:
------------------------------------------------------------------------
EXT3-fs error (device sdb1): ext3_free_blocks_sb: bit already cleared for block
731165448
Aborting journal on device sdb1.
EXT3-fs error (device sdb1): ext3_free_blocks_sb: bit already cleared for block
731165449
EXT3-fs error (device sdb1) in ext3_free_blocks_sb: Journal has aborted
EXT3-fs error (device sdb1) in ext3_free_blocks_sb: Journal has aborted
EXT3-fs error (device sdb1) in ext3_free_blocks_sb: Journal has aborted
EXT3-fs error (device sdb1) in ext3_free_blocks_sb: Journal has aborted
EXT3-fs error (device sdb1) in ext3_free_blocks_sb: Journal has aborted
EXT3-fs error (device sdb1) in ext3_free_blocks_sb: Journal has aborted
EXT3-fs error (device sdb1) in ext3_reserve_inode_write: Journal has aborted
EXT3-fs error (device sdb1) in ext3_truncate: Journal has aborted
EXT3-fs error (device sdb1) in ext3_reserve_inode_write: Journal has aborted
EXT3-fs error (device sdb1) in ext3_orphan_del: Journal has aborted
EXT3-fs error (device sdb1) in ext3_reserve_inode_write: Journal has aborted
EXT3-fs error (device sdb1) in ext3_delete_inode: Journal has aborted
__journal_remove_journal_head: freeing b_committed_data
__journal_remove_journal_head: freeing b_committed_data
__journal_remove_journal_head: freeing b_committed_data
__journal_remove_journal_head: freeing b_committed_data
__journal_remove_journal_head: freeing b_committed_data
__journal_remove_journal_head: freeing b_committed_data
__journal_remove_journal_head: freeing b_committed_data
__journal_remove_journal_head: freeing b_committed_data
__journal_remove_journal_head: freeing b_committed_data
__journal_remove_journal_head: freeing b_committed_data
__journal_remove_journal_head: freeing b_committed_data
__journal_remove_journal_head: freeing b_committed_data
__journal_remove_journal_head: freeing b_committed_data
__journal_remove_journal_head: freeing b_committed_data
__journal_remove_journal_head: freeing b_committed_data
__journal_remove_journal_head: freeing b_committed_data
ext3_abort called.
EXT3-fs error (device sdb1): ext3_journal_start_sb: Detected aborted journal
Remounting filesystem read-only
------------------------------------------------------------------------
The issue occurs under heavy disk i/o while performing a Oracle RMAN restore.
Our configuration is on a Dell with a Perc 6 (LSI/megasas) raid controller with
an external eSATA storage device, MD1000(JBOD).
Please let me know if there is anything I can do to help provide some insight
into the problem.
As a general plea for folks who are RHEL customers, please also ping your
support channel about this problem, it'll help prioritize the bug.
Thanks,
-Eric
Oh, and for anyone hitting the i_size problems on fsck post-fsstress, that
issue has been moved over to bug #515529, if that's your issue you might want
to cc: over there.
Justin, I'll try to make some headway on this original bug soon, too.
And for folks w/ RHEL4 problems, you need to open a different bug, or get your
support folks to do it.
Sorry but we have to keep things focused here ;)
And now, back to "bit already cleared for block" on RHEL5....
Thanks,
-Eric
For those hitting the bit already cleared for block error:
Let's try a jprobe to see what path we're hitting the error on, it may at least
discern between types of blocks being freed and give a clue to what's
happening.
http://people.redhat.com/esandeen/bz494927/
has a pre-built jprobe module for x86_64, and source & a Makefile that could be
rebuilt on any arch by putting the Makefile and ext3_error_jprobe.c in a
directory, cd into that dir, and:
# make -C /lib/modules/`uname -r`/build M=`pwd`
to build the module. Then you can:
# insmod ./ext3_error_jprobe.ko
It will dump a stack backtrace to dmesg whenever ext3_error() is hit, while the
module is loaded.
Thanks,
-Eric
Oh, for the above "make" to work you need kernel-devel for the kernel matching:
# uname -r
installed as well.
If anyone gets a nice backtrace when the bit already cleared for block error
pops up, please add it to this bug.
Thanks,
-Eric
(In reply to comment #24)
We tracked this problem down to a faulty PERC 6 Raid controller. Once it was
replaced, the error went away.
Event posted on 11-05-2009 11:27am EST by mgoodwin
Hi all,
Comparing the previous event (Aug 28 2009) with this new event
(Oct 31 2009), a smoking gun has emerged. Both events occurred at
exactly the same time (23:53:01) on exactly the same filesystem
(/var mounted on vg00-var, which is dm-7), and both reported free
list corruption for exactly the same block (149827).
Further more, in /etc/cron.d/sysstat, we have :
# generate a daily summary of process accounting at 23:53
53 23 * * * root /usr/lib64/sa/sa2 -A
This site is running sysstat-7.0.2-3.el5-x86_64.
Here are the two log snippets :
This event, Oct 31 :
Oct 31 23:51:04 srpamp35 dhclient: DHCPREQUEST on eth2 to 148.126.2.5 port
67
Oct 31 23:51:43 srpamp35 last message repeated 3 times
Oct 31 23:52:47 srpamp35 last message repeated 5 times
Oct 31 23:52:52 srpadm62 snmpd[3108]: Connection from UDP:
[148.126.25.56]:1725
Oct 31 23:53:01 srpamp74 kernel: jprobe: ext3_error
Oct 31 23:53:01 srpamp74 syslogd: /var/log/messages: Read-only file
system
Oct 31 23:53:01 srpamp74 kernel:
Oct 31 23:53:01 srpamp74 kernel: Call Trace:
Oct 31 23:53:01 srpamp74 kernel: [<ffffffff8850b017>]
:ext3_error_jprobe:jext3_error+0x17/0x20
Oct 31 23:53:01 srpamp74 kernel: [<ffffffff8804a93c>]
:ext3:ext3_free_blocks_sb+0x31b/0x48b
Oct 31 23:53:01 srpamp74 kernel: [<ffffffff8804aada>]
:ext3:ext3_free_blocks+0x2e/0x79
Oct 31 23:53:01 srpamp74 kernel: [<ffffffff8804f07c>]
:ext3:ext3_free_data+0x84/0xfe
Oct 31 23:53:01 srpamp74 kernel: [<ffffffff8804f839>]
:ext3:ext3_truncate+0x567/0x8e1
Oct 31 23:53:01 srpamp74 kernel: [<ffffffff8003fa10>]
pagevec_lookup+0x17/0x1e
Oct 31 23:53:01 srpamp74 kernel: [<ffffffff88032152>]
:jbd:journal_start+0xc9/0x100
Oct 31 23:53:01 srpamp74 kernel: [<ffffffff88050256>]
:ext3:ext3_delete_inode+0x7d/0xd4
Oct 31 23:53:01 srpamp74 kernel: [<ffffffff880501d9>]
:ext3:ext3_delete_inode+0x0/0xd4
Oct 31 23:53:01 srpamp74 kernel: [<ffffffff8002f49e>]
generic_delete_inode+0xc6/0x143
Oct 31 23:53:01 srpamp74 kernel: [<ffffffff8003c75c>]
do_unlinkat+0xd5/0x141
Oct 31 23:53:01 srpamp74 kernel: [<ffffffff8005dde9>]
error_exit+0x0/0x84
Oct 31 23:53:01 srpamp74 kernel: [<ffffffff8005d116>]
system_call+0x7e/0x83
Oct 31 23:53:01 srpamp74 kernel:
Oct 31 23:53:01 srpamp74 kernel: EXT3-fs error (device dm-7):
ext3_free_blocks_sb: bit already cleared for block 149827
Oct 31 23:53:01 srpamp74 kernel: Aborting journal on device dm-7.
Oct 31 23:53:01 srpamp74 kernel: EXT3-fs error (device dm-7) in
ext3_free_blocks_sb: Journal has aborted
Oct 31 23:53:01 srpamp74 kernel: EXT3-fs error (device dm-7) in
ext3_free_blocks_sb: Journal has aborted
Oct 31 23:53:01 srpamp74 kernel: EXT3-fs error (device dm-7) in
ext3_reserve_inode_write: Journal has aborted
Oct 31 23:53:01 srpamp74 kernel: EXT3-fs error (device dm-7) in
ext3_truncate: Journal has aborted
Oct 31 23:53:01 srpamp74 kernel: EXT3-fs error (device dm-7) in
ext3_reserve_inode_write: Journal has aborted
Oct 31 23:53:01 srpamp74 kernel: EXT3-fs error (device dm-7) in
ext3_orphan_del: Journal has aborted
Oct 31 23:53:01 srpamp74 kernel: EXT3-fs error (device dm-7) in
ext3_reserve_inode_write: Journal has aborted
Oct 31 23:53:01 srpamp74 kernel: EXT3-fs error (device dm-7) in
ext3_delete_inode: Journal has aborted
Oct 31 23:53:01 srpamp74 kernel: __journal_remove_journal_head: freeing
b_committed_data
Oct 31 23:53:01 srpamp74 kernel: journal commit I/O error
Oct 31 23:53:01 srpamp74 kernel: ext3_abort called.
Oct 31 23:53:01 srpamp74 kernel: EXT3-fs error (device dm-7):
ext3_journal_start_sb: Detected aborted journal
Oct 31 23:53:01 srpamp74 kernel: Remounting filesystem read-only
Previous event, on August 28 :
Aug 28 23:51:26 srpamp74 kernel: scsi(0): Asynchronous PORT UPDATE ignored
0000/0007/0b00.
Aug 28 23:53:01 srpamp74 syslogd: /var/log/messages: Read-only file
system
Aug 28 23:53:01 srpamp74 kernel: EXT3-fs error (device dm-7):
ext3_free_blocks_sb: bit already cleared for block 149827
Aug 28 23:53:01 srpamp74 kernel: Aborting journal on device dm-7.
Aug 28 23:53:01 srpamp74 kernel: ext3_abort called.
Aug 28 23:53:01 srpamp74 kernel: EXT3-fs error (device dm-7):
ext3_journal_start_sb: Detected aborted journal
Aug 28 23:53:01 srpamp74 kernel: Remounting filesystem read-only
Aug 28 23:53:01 srpamp74 kernel: EXT3-fs error (device dm-7) in
ext3_free_blocks_sb: Journal has aborted
Aug 28 23:53:01 srpamp74 kernel: EXT3-fs error (device dm-7) in
ext3_reserve_inode_write: Journal has aborted
Aug 28 23:53:01 srpamp74 kernel: EXT3-fs error (device dm-7) in
ext3_truncate: Journal has aborted
Aug 28 23:53:01 srpamp74 kernel: EXT3-fs error (device dm-7) in
ext3_reserve_inode_write: Journal has aborted
Aug 28 23:53:01 srpamp74 kernel: EXT3-fs error (device dm-7) in
ext3_orphan_del: Journal has aborted
Aug 28 23:53:01 srpamp74 kernel: EXT3-fs error (device dm-7) in
ext3_reserve_inode_write: Journal has aborted
Aug 28 23:53:01 srpamp74 kernel: __journal_remove_journal_head: freeing
b_committed_data
Aug 28 23:53:01 srpamp74 syslogd: /var/log/maillog: Read-only file system
Aug 28 23:53:01 srpamp74 syslogd: /var/log/cron: Read-only file system
Aug 28 23:53:01 srpamp74 auditd[4261]: Record was not written to disk
(Read-only file system)
Aug 28 23:53:01 srpamp74 auditd[4261]: write: Audit daemon detected an
error writing an event to disk (Read-only file system)
Aug 28 23:53:01 srpamp74 auditd[13430]: Audit daemon failed to exec
(null)
Aug 28 23:53:01 srpamp74 auditd[13430]: The audit daemon is exiting.
John,
Known bugs in the /usr/lib64/sa/sa2 script could be related here,
maybe BZ 101574? (that BZ has an easy reproducer recipe, maybe
give it a try).
Also, since /dev/vg00/var is less than 1G, could we please get a
compressed dd image? Might be worth investigating if the /var/log/sa
directory inode is stored near block 149827.
Cheers
-- Mark Goodwin
Internal Status set to 'Waiting on Support'
This event sent from IssueTracker by mgoodwin
issue 347967
Same problem here in a production virtual server running on vSphere 4.0.0 build
208111 servers.
Virtual server info:
Red Hat Enterprise Linux Server release 5.3 (Tikanga)
kernel 2.6.18-128.2.1.el5
Issues only appears in filesystems mounted on SAN.
Today I have three issues in two different filesystems (each one a LUN on EMC
SAN).
- message log:
Jul 26 12:29:02 nobel kernel: EXT3-fs error (device sde1): ext3_free_blocks_sb:
bit already cleared for block 70722697
Jul 26 12:29:02 nobel kernel: Aborting journal on device sde1.
Jul 26 12:29:02 nobel kernel: ext3_abort called.
Jul 26 12:29:02 nobel kernel: EXT3-fs error (device sde1):
ext3_journal_start_sb: Detected aborted journal
Jul 26 12:29:02 nobel kernel: Remounting filesystem read-only
Jul 26 12:29:02 nobel kernel: EXT3-fs error (device sde1) in
ext3_reserve_inode_write: Journal has aborted
Jul 26 12:29:02 nobel kernel: EXT3-fs error (device sde1) in ext3_truncate:
Journal has aborted
Jul 26 12:29:02 nobel kernel: EXT3-fs error (device sde1) in
ext3_reserve_inode_write: Journal has aborted
Jul 26 12:29:02 nobel kernel: EXT3-fs error (device sde1) in ext3_orphan_del:
Journal has aborted
Jul 26 12:29:02 nobel kernel: EXT3-fs error (device sde1) in
ext3_reserve_inode_write: Journal has aborted
Jul 26 12:29:02 nobel kernel: __journal_remove_journal_head: freeing
b_committed_data
Jul 26 12:35:24 nobel kernel: __journal_remove_journal_head: freeing
b_committed_data
Jul 26 12:35:24 nobel kernel: ext3_abort called.
Jul 26 12:35:24 nobel kernel: EXT3-fs error (device sde1): ext3_put_super:
Couldn't clean up the journal
==> Command to check filesystem: fsck.ext3 -f -C 0 -y /dev/sde1
Jul 26 14:43:05 nobel kernel: ext3_abort called.
Jul 26 14:43:05 nobel kernel: EXT3-fs error (device sdg1):
ext3_journal_start_sb: Detected aborted journal
Jul 26 14:43:05 nobel kernel: Remounting filesystem read-only
Jul 26 14:52:50 nobel kernel: ext3_abort called.
Jul 26 14:52:50 nobel kernel: EXT3-fs error (device sdg1): ext3_put_super:
Couldn't clean up the journal
==> Command to check filesystem: fsck.ext3 -C 0 -y /dev/sdg1
Jul 26 15:48:29 nobel kernel: EXT3-fs error (device sdg1): ext3_lookup:
unlinked inode 22093862 in dir #18956368
Jul 26 15:48:29 nobel kernel: Aborting journal on device sdg1.
Jul 26 15:48:29 nobel kernel: __journal_remove_journal_head: freeing
b_committed_data
Jul 26 15:48:29 nobel kernel: ext3_abort called.
Jul 26 15:48:29 nobel kernel: EXT3-fs error (device sdg1):
ext3_journal_start_sb: Detected aborted journal
Jul 26 15:48:29 nobel kernel: Remounting filesystem read-only
Jul 26 16:05:06 nobel kernel: ext3_abort called.
Jul 26 16:05:06 nobel kernel: EXT3-fs error (device sdg1): ext3_put_super:
Couldn't clean up the journal
Jul 26 16:05:39 nobel kernel: kjournald starting. Commit interval 5 seconds
Jul 26 16:05:39 nobel kernel: EXT3-fs warning (device sdg1):
ext3_clear_journal_err: Filesystem error recorded from previous mount: IO
failure
Jul 26 16:05:39 nobel kernel: EXT3-fs warning (device sdg1):
ext3_clear_journal_err: Marking fs in need of filesystem check.
Jul 26 16:05:39 nobel kernel: EXT3-fs warning: mounting fs with errors, running
e2fsck is recommended
Jul 26 16:05:39 nobel kernel: EXT3 FS on sdg1, internal journal
Jul 26 16:05:39 nobel kernel: EXT3-fs: recovery complete.
Jul 26 16:05:39 nobel kernel: EXT3-fs: mounted filesystem with ordered data
mode.
==> Command to check filesystem: fsck.ext3 -f -C 0 -y /dev/sdg1
The original poster to this bugzilla said that fsck did in fact fix this
problem. For the person who commented in c #51, please open a support ticket
so they can debug the problem further.
Benefits of being at a storage conference, I was just reminded of this fix
upstream:
commit f25f624263445785b94f39739a6339ba9ed3275d
Author: Jan Kara <jack@suse.cz>
Date: Mon Jul 12 21:04:31 2010 +0200
ext3: Avoid filesystem corruption after a crash under heavy delete load
It can happen that ext3_free_branches calls ext3_forget() for an indirect
block
in an earlier transaction than a transaction in which we clear pointer to
this
indirect block. Thus if we crash before a transaction clearing the block
pointer is committed, we will see indirect block pointing to already freed
blocks and complain during orphan list cleanup.
The fix is simple: Make sure ext3_forget() is called in the transaction
doing block pointer clearing.
This is a backport of an ext4 fix by Amir G.
<amir73il@users.sourceforge.net>
Signed-off-by: Jan Kara <jack@suse.cz>
which may well be the problem here. It would be interesting to investigate the
image with debugfs and see if it is indeed an indirect block which points to a
freed block.
-Eric
ext4 version upstream:
commit 40389687382bf0ae71458e7c0f828137a438a956
Author: Amir G <amir73il@users.sourceforge.net>
Date: Tue Jul 27 11:56:05 2010 -0400
ext4: Fix block bitmap inconsistencies after a crash when deleting files
We have experienced bitmap inconsistencies after crash during file
delete under heavy load. The crash is not file system related and I
the following patch in ext4_free_branches() fixes the recovery
problem.
If the transaction is restarted and there is a crash before the new
transaction is committed, then after recovery, the blocks that this
indirect block points to have been freed, but the indirect block
itself has not been freed and may still point to some of the free
blocks (because of the ext4_forget()).
So ext4_forget() should be called inside ext4_free_blocks() to avoid
this problem.
Signed-off-by: Amir Goldstein <amir73il@users.sf.net>
Signed-off-by: "Theodore Ts'o" <tytso@mit.edu>
This request was evaluated by Red Hat Product Management for inclusion in a Red
Hat Enterprise Linux maintenance release. Product Management has requested
further review of this request by Red Hat Engineering, for potential
inclusion in a Red Hat Enterprise Linux Update release for currently deployed
products. This request is not yet committed for inclusion in an Update
release.
Eric, I'm setting up a bridged VM for you running RHEL 5.6, with the
unpacked image available. Be ready in ~ 1 hour.
There are plenty of ways to hit this warning; I keep finding new ones.
For example, from yet another image:
Multiply-claimed block(s) in inode 32802: 69654 69654
If that inode is unlinked, it will try to block 69654 twice, and the 2nd one
would issue this error.
There is more than one root cause which could get us to this error message.
In my testing, commit f1015c447781729060c415f5133164c638561f25 has reduced a
1%-2% occurence of journal replay corruption to 0 (out of about 3500 replays).
In most cases it's mild corruption but over hours of testing I have seen bit
already cleared errors and some other more severe things.
I will be pushing that commit for RHEL5 soon and I expect that it will resolve
most of these issues, at least for customers who have the problem at any time
after experiencing a crash. (Note that the corruption could "like dormant"
until it was stumbled on again at runtime. Think for example of a rotated log
that only gets deleted after 6 months, and -that- is when the problem shows up,
6 months after the crash...)
-Eric
This request was evaluated by Red Hat Product Management for inclusion in a Red
Hat Enterprise Linux maintenance release. Product Management has requested
further review of this request by Red Hat Engineering, for potential
inclusion in a Red Hat Enterprise Linux Update release for currently deployed
products. This request is not yet committed for inclusion in an Update
release.
Created attachment 493679 [details]
script to generate dirty snapshots
Invocation:
./dirty_snapshot -s $SOURCE_LVNAME /dev/$COW_DEVICE $SNAPSHOTNAME i.e.
./dirty_snapshot -s testvg-testlv /dev/sdb3 testlv_snap
to create a new dirty snapshot called "testlv_snap" from
/dev/mapper/testvg-testlv, with /dev/sdb3 as the cow device.
./dirty_snapshot -d testvg-testlv /dev/sdb3 testlv_snap
removes it again.
Created attachment 493681 [details]
script to drive dirty_snapshot script
This script runs fsstress (which I grabbed from xfstests) constantly, while
creating snapshots that require recovery.
It checks the recovered snapshot and if it's corrupted, makes a copy of it, and
tries mounting it and removing all files to hit runtime errors.
You'll need to edit the invocation of the dirty snapshot script to give it the
right parameters. It also expects to have fsstress in the same dir, and
mountpoints mnt/ and mnt2/ as well. Sorry, it's a bit rough.
The main lv I tested was 128M in size, made with 4k blocks.
I saw some sort of corruption in about 1%-2% of the replayed filesystems.
Eric, you mentioned the following commits - do you still think we may need
them?
40389687382bf0ae71458e7c0f828137a438a956
86963918965eb8fe0c8ae009e7c1b4c630f533d5
(In reply to comment #87)
> Eric, you mentioned the following commits - do you still think we may need
> them?
>
> 40389687382bf0ae71458e7c0f828137a438a956
> 86963918965eb8fe0c8ae009e7c1b4c630f533d5
Ultimately they probably should go in, but not as a last-minute 5.7 update, I
think.
40389687382bf0ae71458e7c0f828137a438a956 requires a crash right in the middle
of restarting a transaction while unlinking a large file, if I read it right.
86963918965eb8fe0c8ae009e7c1b4c630f533d5 is also explicitly related to crashes
while deleting.
In short, much narrower windows, and the commit I sent is most likely to be
hit.
Mark tells me you have your own testcase, though, so if you can still hit any
problems with the one commit, we can talk again. :)
Patch(es) available in kernel-2.6.18-261.el5
You can download this test kernel (or newer) from
http://people.redhat.com/jwilson/el5
Detailed testing feedback is always welcomed.
Hello,
i have the same problem but with RHEL 5.5 x86. Ocurried 3 times in a server in
less than two weeks in production. Here is the lines in /var/log/message
May 27 02:31:16 hostname kernel: EXT3-fs error (device sdh): ext3_lookup:
unlinked inode 3918926 in dir #5570561
May 27 02:31:16 hostname kernel: Aborting journal on device sdh.
May 27 02:31:16 hostname kernel: __journal_remove_journal_head: freeing
b_committed_data
May 27 02:31:16 hostname kernel: ext3_abort called.
May 27 02:31:16 hostname kernel: EXT3-fs error (device sdh):
ext3_journal_start_sb: Detected aborted journal
May 27 02:31:16 hostname kernel: Remounting filesystem read-only
To solve this only works rebooting the machine.
Is this the same problem?
(In reply to comment #109)
> Hello,
>
> i have the same problem but with RHEL 5.5 x86. Ocurried 3 times in a server in
> less than two weeks in production. Here is the lines in /var/log/message
>
>
> May 27 02:31:16 hostname kernel: EXT3-fs error (device sdh): ext3_lookup:
> unlinked inode 3918926 in dir #5570561
> May 27 02:31:16 hostname kernel: Aborting journal on device sdh.
> May 27 02:31:16 hostname kernel: __journal_remove_journal_head: freeing
> b_committed_data
> May 27 02:31:16 hostname kernel: ext3_abort called.
> May 27 02:31:16 hostname kernel: EXT3-fs error (device sdh):
> ext3_journal_start_sb: Detected aborted journal
> May 27 02:31:16 hostname kernel: Remounting filesystem read-only
>
> To solve this only works rebooting the machine.
>
> Is this the same problem?
Probably not. You might try to run e2sfck -f on the fs to see if there is
corruption. If the error is ongoing, please open a case with your RHEL support
contacts.
Thanks,
-Eric
(In reply to comment #110)
> (In reply to comment #109)
> > Hello,
> >
> > i have the same problem but with RHEL 5.5 x86. Ocurried 3 times in a server in
> > less than two weeks in production. Here is the lines in /var/log/message
> >
> >
> > May 27 02:31:16 hostname kernel: EXT3-fs error (device sdh): ext3_lookup:
> > unlinked inode 3918926 in dir #5570561
> > May 27 02:31:16 hostname kernel: Aborting journal on device sdh.
> > May 27 02:31:16 hostname kernel: __journal_remove_journal_head: freeing
> > b_committed_data
> > May 27 02:31:16 hostname kernel: ext3_abort called.
> > May 27 02:31:16 hostname kernel: EXT3-fs error (device sdh):
> > ext3_journal_start_sb: Detected aborted journal
> > May 27 02:31:16 hostname kernel: Remounting filesystem read-only
> >
> > To solve this only works rebooting the machine.
> >
> > Is this the same problem?
>
> Probably not. You might try to run e2sfck -f on the fs to see if there is
> corruption. If the error is ongoing, please open a case with your RHEL support
> contacts.
>
> Thanks,
> -Eric
Really this error only saw one time, the other two times the system crashed and
it freezed all, ping works, ssh request login and password but when type
password don´t work.
I think the other times the system was in read only mode in "/var" and "/"
volume and i could not see the same error because it could not write into log.
This system was in tests during three weeks and connected via fibre channel to
DAS, always OK without any error. Two weeks in production and three crashes.
I have kernel 2.6.18-194.el5PAE .
Thanks
An advisory has been issued which should help the problem
described in this bug report. This report is therefore being
closed with a resolution of ERRATA. For more information
on therefore solution and/or where to find the updated files,
please follow the link below. You may reopen this bug report
if the solution does not work for you.
http://rhn.redhat.com/errata/RHSA-2011-1065.html
Same problem again in a production virtual server running on vSphere 4.0.0
build
208167 servers.
Virtual server info:
Red Hat Enterprise Linux Server release 5.3 (Tikanga)
Issues only appears in filesystems mounted on SAN.
We installed patched kernel 2.6.18-265.el5PAE on 23th of May.
An issue appeared on 30th of September and server had installed the patched
kernel 2.6.18-265.el5PAE (almost 3)
That day I installed patched kernel 2.6.18-285.el5PAE.
But another issue appeared yesterday (with patched kernel 2.6.18-285.el5PAE
installed).
Then I installed the last patched kernel: 2.6.18-286.el5PAE
- message log:
EXT3-fs error (device sdh1): ext3_free_blocks_sb: bit already cleared for block
43055512
Aborting journal on device sdh1.
EXT3-fs error (device sdh1) in ext3_reserve_inode_write: Journal has aborted
EXT3-fs error (device sdh1) in ext3_truncate: Journal has aborted
EXT3-fs error (device sdh1) in ext3_reserve_inode_write: Journal has aborted
EXT3-fs error (device sdh1) in ext3_orphan_del: Journal has aborted
EXT3-fs error (device sdh1) in ext3_reserve_inode_write: Journal has aborted
EXT3-fs error (device sdh1) in ext3_delete_inode: Journal has aborted
__journal_remove_journal_head: freeing b_committed_data
__journal_remove_journal_head: freeing b_committed_data
__journal_remove_journal_head: freeing b_committed_data
__journal_remove_journal_head: freeing b_committed_data
__journal_remove_journal_head: freeing b_committed_data
__journal_remove_journal_head: freeing b_committed_data
__journal_remove_journal_head: freeing b_committed_data
__journal_remove_journal_head: freeing b_committed_data
__journal_remove_journal_head: freeing b_committed_data
ext3_abort called.
EXT3-fs error (device sdh1): ext3_journal_start_sb: Detected aborted journal
Remounting filesystem read-only
==> Procedure to solve the problem:
1. Unmounting the file system (/dev/sdc14)
2. Nuke the ext3 journal
tune2fs -O ^has_journal /dev/sdc14
3. check disk
nohup e2fsck -fy -C 0 /dev/sdc14 &
4. Rebuild the journal
tune2fs -j /dev/sdc14
5. Mounting the file system (/dev/sdc14)
It's not clear to me why you would need to nuke the journal...?
In any case, this bug is closed; based on our investigations we have shipped a
fix for the root cause encountered by the original reporter. As Josef already
mentioned in comment #52, if you have a new issue, please contact your Red Hat
support channel and get a new issue logged.
Thanks,
-Eric
| 
No comments:
Post a Comment