Skip to contentSkip to conversation

BUG_ON at mballoc.c:3752

DISCUSSION Eric Sesterhenn 5 participants 15 messages Jan 31, 2008 – Feb 8, 2008 ext4 file system

lore
Share & tools
lore

Eric Sesterhenn

author
#0 lore raw

hi,

while running a modified version of fsfuzzer i triggered the BUG() in ext4_mb_release_inode_pa(). Sadly I am not able to reproduce this using the generated image, but running the fuzzer will usually trigger this in less than 40 attempts. Increasing the JBD2 Debug level didnt give more information. The kernel is current git with ext4-fix-null-pointer-deref-in-journal_wait_on_commit_record.patch applied.

Greetings, Eric

[ 1570.971980] EXT4-fs error (device loop0) in ext4_reserve_inode_write: Journal has aborted
[ 1570.972077] pa c6512330: logic 16, phys. 2337, len 16
[ 1570.972103] free 2, pa_free 1
[ 1570.972191] ------------[ cut here ]------------
[ 1570.972217] kernel BUG at fs/ext4/mballoc.c:3752!
[ 1570.972241] invalid opcode: 0000 [#1] PREEMPT DEBUG_PAGEALLOC
[ 1570.972386] Modules linked in:
[ 1570.972425] 
[ 1570.972509] Pid: 6629, comm: fstest Not tainted (2.6.24-05749-g8af03e7-dirty #19)
[ 1570.972534] EIP: 0060:[<c02266b9>] EFLAGS: 00010202 CPU: 0
[ 1570.972570] EIP is at ext4_mb_release_inode_pa+0x169/0x1a0
[ 1570.972595] EAX: 00000001 EBX: 00000930 ECX: 00000001 EDX: 00000001
[ 1570.972678] ESI: 00000930 EDI: c6512330 EBP: cb638b28 ESP: cb638a84
[ 1570.972703]  DS: 007b ES: 007b FS: 0000 GS: 0033 SS: 0068
[ 1570.972728] Process fstest (pid: 6629, ti=cb638000 task=cb698000 task.ti=cb638000)
[ 1570.972751] Stack: c07c21bb 00000002 00000001 00000921 00000010 cbff34e0 cb638b54 00000002 
[ 1570.972899]        cb5fa430 c64824a0 cb5fb920 00000022 cbff34e0 cb638ad4 00000246 00000400 
[ 1570.972899]        cbfa2000 cb5fb920 cbff34e0 00000000 0000092e 00000000 00000002 cbfa2000 
[ 1570.972899] Call Trace:
[ 1570.972899]  [<c020e3a4>] ? read_block_bitmap+0x54/0x120
[ 1570.972899]  [<c022bd24>] ? ext4_mb_discard_inode_preallocations+0x124/0x300
[ 1570.972899]  [<c022bda5>] ? ext4_mb_discard_inode_preallocations+0x1a5/0x300
[ 1570.972899]  [<c0223577>] ? ext4_ext_get_blocks+0x3a7/0x4b0
[ 1570.972899]  [<c0213928>] ? ext4_get_blocks_wrap+0xe8/0x130
[ 1570.972899]  [<c0213bce>] ? ext4_get_block+0x7e/0xf0
[ 1570.972899]  [<c019d7ba>] ? __block_prepare_write+0x17a/0x3a0
[ 1570.972899]  [<c019da68>] ? block_write_begin+0x48/0xe0
[ 1570.972899]  [<c0213b50>] ? ext4_get_block+0x0/0xf0
[ 1570.972899]  [<c0215127>] ? ext4_write_begin+0xb7/0x190
[ 1570.972899]  [<c0213b50>] ? ext4_get_block+0x0/0xf0
[ 1570.972899]  [<c01557e9>] ? generic_perform_write+0xa9/0x190
[ 1570.972899]  [<c01575bd>] ? generic_file_buffered_write+0x6d/0x130
[ 1570.972899]  [<c01578c1>] ? __generic_file_aio_write_nolock+0x241/0x550
[ 1570.972899]  [<c0144b44>] ? trace_hardirqs_on+0xc4/0x150
[ 1570.972899]  [<c0157c2c>] ? generic_file_aio_write+0x5c/0xd0
[ 1570.972899]  [<c015ab0d>] ? free_one_page+0x1ed/0x220
[ 1570.972899]  [<c0210410>] ? ext4_file_write+0x50/0x160
[ 1570.972899]  [<c017b11d>] ? do_sync_write+0xcd/0x110
[ 1570.972899]  [<c01096f9>] ? native_sched_clock+0x69/0xc0
[ 1570.972899]  [<c01373c0>] ? autoremove_wake_function+0x0/0x50
[ 1570.972899]  [<c01070e5>] ? do_softirq+0x55/0xd0
[ 1570.972899]  [<c01050d3>] ? restore_nocheck+0x12/0x15
[ 1570.972899]  [<c0144b44>] ? trace_hardirqs_on+0xc4/0x150
[ 1570.972899]  [<c017b959>] ? vfs_write+0x99/0x130
[ 1570.972899]  [<c017b050>] ? do_sync_write+0x0/0x110
[ 1570.972899]  [<c017c048>] ? sys_pwrite64+0x68/0x70
[ 1570.972899]  [<c0104fea>] ? sysenter_past_esp+0x5f/0xa5
[ 1570.972899]  =======================
[ 1570.972899] Code: ff 0f b7 47 4e 89 44 24 08 8b 85 78 ff ff ff c7 04 24 bb 21 7c c0 89 44 24 04 e8 c3 e0 ef ff 0f b7 47 4e 39 85 78 ff ff ff 74 07 <0f> 0b eb fe 8d 76 00 8b 85 78 ff ff ff 8b 95 7c ff ff ff 01 82 
[ 1570.972899] EIP: [<c02266b9>] ext4_mb_release_inode_pa+0x169/0x1a0 SS:ESP 0068:cb638a84
[ 1570.972942] ---[ end trace 51819e80cd9431da ]---
[ 1570.972969] note: fstest[6629] exited with preempt_count 1
[ 1570.973013] BUG: sleeping function called from invalid context at kernel/rwsem.c:21
[ 1570.973039] in_atomic():1, irqs_disabled():0
[ 1570.973077] INFO: lockdep is turned off.
[ 1570.973104] Pid: 6629, comm: fstest Tainted: G      D 2.6.24-05749-g8af03e7-dirty #19
[ 1570.973159]  [<c011e1a6>] __might_sleep+0xc6/0xf0
[ 1570.973224]  [<c06b2c99>] down_read+0x19/0x80
[ 1570.973295]  [<c013a7fd>] ? hrtimer_try_to_cancel+0x3d/0x80
[ 1570.973396]  [<c0125a27>] exit_mm+0x27/0xd0
[ 1570.973467]  [<c01272f3>] do_exit+0x133/0x2e0
[ 1570.973529]  [<c010611c>] die+0x13c/0x140
[ 1570.973590]  [<c0135197>] ? search_exception_tables+0x27/0x30
[ 1570.973993]  [<c01061b1>] do_trap+0x91/0xc0
[ 1570.974054]  [<c0106440>] ? do_invalid_op+0x0/0xa0
[ 1570.974133]  [<c01064c9>] do_invalid_op+0x89/0xa0
[ 1570.974195]  [<c02266b9>] ? ext4_mb_release_inode_pa+0x169/0x1a0
[ 1570.974290]  [<c012007b>] ? account_system_time+0x9b/0xd0
[ 1570.974370]  [<c01245de>] ? vprintk+0x1ce/0x360
[ 1570.974465]  [<c06b4492>] error_code+0x6a/0x70
[ 1570.974531]  [<c012007b>] ? account_system_time+0x9b/0xd0
[ 1570.974626]  [<c02266b9>] ? ext4_mb_release_inode_pa+0x169/0x1a0
[ 1570.974707]  [<c020e3a4>] ? read_block_bitmap+0x54/0x120
[ 1570.974803]  [<c022bd24>] ? ext4_mb_discard_inode_preallocations+0x124/0x300
[ 1570.975151]  [<c022bda5>] ext4_mb_discard_inode_preallocations+0x1a5/0x300
[ 1570.975221]  [<c0223577>] ext4_ext_get_blocks+0x3a7/0x4b0
[ 1570.975289]  [<c0213928>] ext4_get_blocks_wrap+0xe8/0x130
[ 1570.975352]  [<c0213bce>] ext4_get_block+0x7e/0xf0
[ 1570.975413]  [<c019d7ba>] __block_prepare_write+0x17a/0x3a0
[ 1570.975479]  [<c019da68>] block_write_begin+0x48/0xe0
[ 1570.975541]  [<c0213b50>] ? ext4_get_block+0x0/0xf0
[ 1570.975635]  [<c0215127>] ext4_write_begin+0xb7/0x190
[ 1570.975697]  [<c0213b50>] ? ext4_get_block+0x0/0xf0
[ 1570.975776]  [<c01557e9>] generic_perform_write+0xa9/0x190
[ 1570.975838]  [<c01575bd>] generic_file_buffered_write+0x6d/0x130
[ 1570.975944]  [<c01578c1>] __generic_file_aio_write_nolock+0x241/0x550
[ 1570.976007]  [<c0144b44>] ? trace_hardirqs_on+0xc4/0x150
[ 1570.976105]  [<c0157c2c>] generic_file_aio_write+0x5c/0xd0
[ 1570.976166]  [<c015ab0d>] ? free_one_page+0x1ed/0x220
[ 1570.976247]  [<c0210410>] ext4_file_write+0x50/0x160
[ 1570.976308]  [<c017b11d>] do_sync_write+0xcd/0x110
[ 1570.976372]  [<c01096f9>] ? native_sched_clock+0x69/0xc0
[ 1570.976470]  [<c01373c0>] ? autoremove_wake_function+0x0/0x50
[ 1570.976567]  [<c01070e5>] ? do_softirq+0x55/0xd0
[ 1570.976662]  [<c01050d3>] ? restore_nocheck+0x12/0x15
[ 1570.976741]  [<c0144b44>] ? trace_hardirqs_on+0xc4/0x150
[ 1570.976837]  [<c017b959>] vfs_write+0x99/0x130
[ 1570.976933]  [<c017b050>] ? do_sync_write+0x0/0x110
[ 1570.977014]  [<c017c048>] sys_pwrite64+0x68/0x70
[ 1570.977075]  [<c0104fea>] sysenter_past_esp+0x5f/0xa5
[ 1570.977137]  =======================
[ 1570.977400] BUG: scheduling while atomic: fstest/6629/0x00000002
[ 1570.977426] INFO: lockdep is turned off.
[ 1570.977468] Pid: 6629, comm: fstest Tainted: G      D 2.6.24-05749-g8af03e7-dirty #19
[ 1570.977494]  [<c0120125>] __schedule_bug+0x75/0x80
[ 1570.977557]  [<c06b1db5>] schedule+0x2d5/0x3a0
[ 1570.977621]  [<c06b3325>] rwsem_down_failed_common+0x75/0x170
[ 1570.977684]  [<c0142fde>] ? __lock_contended+0xbe/0x110
[ 1570.977780]  [<c06b343d>] rwsem_down_write_failed+0x1d/0x30
[ 1570.977842]  [<c06b34ca>] call_rwsem_down_write_failed+0x6/0x8
[ 1570.977933]  [<c06b2d81>] ? down_write+0x81/0x90
[ 1570.978013]  [<c021058c>] ? ext4_release_file+0x6c/0x80
[ 1570.978108]  [<c021058c>] ext4_release_file+0x6c/0x80
[ 1570.978168]  [<c017c484>] __fput+0xb4/0x1b0
[ 1570.978231]  [<c017c788>] fput+0x18/0x20
[ 1570.978291]  [<c0179827>] filp_close+0x47/0x70
[ 1570.978352]  [<c0125dd0>] close_files+0x70/0x80
[ 1570.978415]  [<c0125e0a>] put_files_struct+0x2a/0x60
[ 1570.978477]  [<c0125e80>] __exit_files+0x40/0x50
[ 1570.978538]  [<c0127301>] do_exit+0x141/0x2e0
[ 1570.978600]  [<c010611c>] die+0x13c/0x140
[ 1570.978661]  [<c0135197>] ? search_exception_tables+0x27/0x30
[ 1570.978741]  [<c01061b1>] do_trap+0x91/0xc0
[ 1570.978803]  [<c0106440>] ? do_invalid_op+0x0/0xa0
[ 1570.979039]  [<c01064c9>] do_invalid_op+0x89/0xa0
[ 1570.979104]  [<c02266b9>] ? ext4_mb_release_inode_pa+0x169/0x1a0
[ 1570.979185]  [<c012007b>] ? account_system_time+0x9b/0xd0
[ 1570.979280]  [<c01245de>] ? vprintk+0x1ce/0x360
[ 1570.979360]  [<c06b4492>] error_code+0x6a/0x70
[ 1570.979423]  [<c012007b>] ? account_system_time+0x9b/0xd0
[ 1570.979519]  [<c02266b9>] ? ext4_mb_release_inode_pa+0x169/0x1a0
[ 1570.979600]  [<c020e3a4>] ? read_block_bitmap+0x54/0x120
[ 1570.979700]  [<c022bd24>] ? ext4_mb_discard_inode_preallocations+0x124/0x300
[ 1570.979797]  [<c022bda5>] ext4_mb_discard_inode_preallocations+0x1a5/0x300
[ 1570.979861]  [<c0223577>] ext4_ext_get_blocks+0x3a7/0x4b0
[ 1570.979964]  [<c0213928>] ext4_get_blocks_wrap+0xe8/0x130
[ 1570.980026]  [<c0213bce>] ext4_get_block+0x7e/0xf0
[ 1570.980087]  [<c019d7ba>] __block_prepare_write+0x17a/0x3a0
[ 1570.980153]  [<c019da68>] block_write_begin+0x48/0xe0
[ 1570.980215]  [<c0213b50>] ? ext4_get_block+0x0/0xf0
[ 1570.980309]  [<c0215127>] ext4_write_begin+0xb7/0x190
[ 1570.980371]  [<c0213b50>] ? ext4_get_block+0x0/0xf0
[ 1570.980450]  [<c01557e9>] generic_perform_write+0xa9/0x190
[ 1570.980513]  [<c01575bd>] generic_file_buffered_write+0x6d/0x130
[ 1570.980576]  [<c01578c1>] __generic_file_aio_write_nolock+0x241/0x550
[ 1570.980639]  [<c0144b44>] ? trace_hardirqs_on+0xc4/0x150
[ 1570.980735]  [<c0157c2c>] generic_file_aio_write+0x5c/0xd0
[ 1570.980796]  [<c015ab0d>] ? free_one_page+0x1ed/0x220
[ 1570.980932]  [<c0210410>] ext4_file_write+0x50/0x160
[ 1570.980995]  [<c017b11d>] do_sync_write+0xcd/0x110
[ 1570.981058]  [<c01096f9>] ? native_sched_clock+0x69/0xc0
[ 1570.981142]  [<c01373c0>] ? autoremove_wake_function+0x0/0x50
[ 1570.981238]  [<c01070e5>] ? do_softirq+0x55/0xd0
[ 1570.981317]  [<c01050d3>] ? restore_nocheck+0x12/0x15
[ 1570.981410]  [<c0144b44>] ? trace_hardirqs_on+0xc4/0x150
[ 1570.981491]  [<c017b959>] vfs_write+0x99/0x130
[ 1570.981552]  [<c017b050>] ? do_sync_write+0x0/0x110
[ 1570.981646]  [<c017c048>] sys_pwrite64+0x68/0x70
[ 1570.981708]  [<c0104fea>] sysenter_past_esp+0x5f/0xa5
[ 1570.981769]  =======================
author
#1 lore raw
Quoted 9 lines · * Eric Sesterhenn ([email protected]) wrote:

hi,

while running a modified version of fsfuzzer i triggered the BUG() in ext4_mb_release_inode_pa(). Sadly I am not able to reproduce this using the generated image, but running the fuzzer will usually trigger this in less than 40 attempts. Increasing the JBD2 Debug level didnt give more information. The kernel is current git with ext4-fix-null-pointer-deref-in-journal_wait_on_commit_record.patch applied.

I am now able to reproduce this using this image:
http://www.cccmz.de/~snakebyte/ext4.24.img.bz2

the following commands will trigger the oops for me

mount cfs/ext4.24.img /media/test -t ext4dev -o extents -o loop
mkdir /media/test/stress
chown snakebyte:snakebyte /media/test/stress && sudo -u snakebyte fstest -n 10 -l 10 -f 5 -s 40000 -p /media/test/stress/

The && between the chown and fstest seems necessary

Greetings, Eric

#2 lore raw
Quoted 11 lines · Eric Sesterhenn
Quoted 9 lines · * Eric Sesterhenn ([email protected]) wrote:

hi,

while running a modified version of fsfuzzer i triggered the BUG() in ext4_mb_release_inode_pa(). Sadly I am not able to reproduce this using the generated image, but running the fuzzer will usually trigger this in less than 40 attempts. Increasing the JBD2 Debug level didnt give more information. The kernel is current git with ext4-fix-null-pointer-deref-in-journal_wait_on_commit_record.patch applied.

Quoted 9 lines

I am now able to reproduce this using this image:
http://www.cccmz.de/~snakebyte/ext4.24.img.bz2

the following commands will trigger the oops for me

mount cfs/ext4.24.img /media/test -t ext4dev -o extents -o loop
mkdir /media/test/stress
chown snakebyte:snakebyte /media/test/stress && sudo -u snakebyte fstest -n 10 -l 10 -f 5 -s 40000 -p /media/test/stress/

The file system is corrupted. The BUG_ON indicate that the free spcae marked in the prealloc space and found by looking at the bitmap are not same. Do you have a set of steps that i can follow to reproduce this ? on a clean file system ? Where do i find the fsfuzzer that you are using ?

kvaneesh@skywalker:/tmp$/home/opensource/patches/e2fsprogs-1.40.4.cfs1/e2fsck/e2fsck.static -f ./ext4.24.img e2fsck 1.40.4.cfs1 (31-Dec-2007)
Superblock has an invalid ext3 journal (inode 8).
Clear<y>? yes

*** ext3 journal has been deleted - filesystem is now ext2 only ***

Pass 1: Checking inodes, blocks, and sizes
Inode 7 has illegal block(s). Clear<y>? yes

Illegal block #552 (9568256) in inode 7. CLEARED. Illegal block #647 (4063232) in inode 7. CLEARED. Illegal block #659 (12517376) in inode 7. CLEARED. Illegal block #766 (2600468480) in inode 7. CLEARED. Illegal block #944 (51200) in inode 7. CLEARED. Illegal block #1135 (2583691264) in inode 7. CLEARED. Illegal block #1214 (15925248) in inode 7. CLEARED. Illegal block #1345 (771751936) in inode 7. CLEARED.

Illegal block #1384 (10092544) in inode 7.  CLEARED.
Illegal block #1416 (14811136) in inode 7.  CLEARED.
Illegal block #1470 (10420224) in inode 7.  CLEARED.
Illegal block #1709 (10158080) in inode 7.  CLEARED.

Too many illegal blocks in inode 7.
Clear inode<y>? yes

Journal inode is not in use, but contains data. Clear<y>? yes

Deleted inode 160 has zero dtime. Fix<y>? yes

Deleted inode 257 has zero dtime. Fix<y>? yes

Deleted inode 638 has zero dtime. Fix<y>? yes

Deleted inode 1407 has zero dtime. Fix<y>? yes

Deleted inode 1650 has zero dtime. Fix<y>? yes

Deleted inode 1656 has zero dtime. Fix<y>? yes

Deleted inode 1677 has zero dtime. Fix<y>? yes

Deleted inode 1720 has zero dtime. Fix<y>? yes

Inode 11 has illegal block(s). Clear<y>? yes

Illegal block #249 (15990784) in inode 11. CLEARED. Inode 11, i_size is 12288, should be 33792. Fix<y>? yes

Inode 11, i_blocks is 24, should be 28. Fix<y>? yes

Recreate journal to make the filesystem ext3 again? Fix<y>? yes

-aneesh

author
#3 lore raw
Quoted 17 lines · * Aneesh Kumar K.V ([email protected]) wrote:
Quoted 16 lines · Eric Sesterhenn
Quoted 9 lines · * Eric Sesterhenn ([email protected]) wrote:

hi,

while running a modified version of fsfuzzer i triggered the BUG() in ext4_mb_release_inode_pa(). Sadly I am not able to reproduce this using the generated image, but running the fuzzer will usually trigger this in less than 40 attempts. Increasing the JBD2 Debug level didnt give more information. The kernel is current git with ext4-fix-null-pointer-deref-in-journal_wait_on_commit_record.patch applied.

I am now able to reproduce this using this image:
http://www.cccmz.de/~snakebyte/ext4.24.img.bz2

the following commands will trigger the oops for me

Quoted 8 lines
Quoted 4 lines

mount cfs/ext4.24.img /media/test -t ext4dev -o extents -o loop
mkdir /media/test/stress
chown snakebyte:snakebyte /media/test/stress && sudo -u snakebyte fstest -n 10 -l 10 -f 5 -s 40000 -p /media/test/stress/

The file system is corrupted. The BUG_ON indicate that the free spcae marked in the prealloc space and found by looking at the bitmap are not same. Do you have a set of steps that i can follow to reproduce this ?

just compile the mangle.c and run the modified fuzzer for a while (link below) or use the steps above

Quoted 1 line

on a clean file system ?

had no luck on a clean fs with this

Quoted 1 line

Where do i find the fsfuzzer that you are using ?

http://www.cccmz.de/~snakebyte/fsfuzzer-0.6-lmh-eric.tar.bz2
http://www.cccmz.de/~snakebyte/fsfuzz.diff

needs user/group nobody:nobody and stuff like fstest, fsx, iozone, fsstress

The changes i made are basically changing the fuzzing ratio, adding udf, hfsplus and ext4, reducing the number of runs to 100 (not unlimited), saving a backup of the image before mounting and running the tests, and mounting ext3 with -o debug

Greetings, Eric

#4 lore raw
In reply to Aneesh Kumar K.V
Quoted 15 lines · Aneesh Kumar K.V
Quoted 14 lines · Eric Sesterhenn
Quoted 9 lines · * Eric Sesterhenn ([email protected]) wrote:

hi,

while running a modified version of fsfuzzer i triggered the BUG() in ext4_mb_release_inode_pa(). Sadly I am not able to reproduce this using the generated image, but running the fuzzer will usually trigger this in less than 40 attempts. Increasing the JBD2 Debug level didnt give more information. The kernel is current git with ext4-fix-null-pointer-deref-in-journal_wait_on_commit_record.patch applied.

I am now able to reproduce this using this image:
http://www.cccmz.de/~snakebyte/ext4.24.img.bz2

Quoted 8 lines
Quoted 6 lines

the following commands will trigger the oops for me

mount cfs/ext4.24.img /media/test -t ext4dev -o extents -o loop
mkdir /media/test/stress
chown snakebyte:snakebyte /media/test/stress && sudo -u snakebyte fstest -n 10 -l 10 -f 5 -s 40000 -p /media/test/stress/

The file system is corrupted.

That's what fsfuzzer does.

Quoted 3 lines

The BUG_ON indicate that the free spcae
marked in the prealloc space and found by looking at the bitmap are not same.

File systems should not call BUG() due to a corrupt file system. Instead the code should fail the operation, possibly marking the file system read-only (or panicking) depending on the errors= mount option.

Signature · 2 lines
David Kleikamp
IBM Linux Technology Center
#5 lore raw
Quoted 5 lines · Dave Kleikamp

File systems should not call BUG() due to a corrupt file system. Instead the code should fail the operation, possibly marking the file system read-only (or panicking) depending on the errors= mount option.

Eric Sandeen explained me the same on IRC. I was busy with the migrate locking bug. That's why i didn't update here. Today i tried to reproduce the problem using the image provided. But in my case it is not hitting the BUG_ON (mostly due to single cpu). I did look at the code and am not still not clear how we can hit that BUG_ON. prealloc free space pa_free is generated out of bitmap. So only if something corrupted bitmap after we initialized prealloc space we will hit this case. In mballoc we error out if the block allocated or fall in system zone. One thing i noticed is, the journal is corrupt. So the only possibility that i have is journal write resulted in bitmap corruption.

I also looked at the mballoc to make sure we don't panic in case of a corrupt bitmap. Below is the patch that i have now. This one is yet to go through the ABAT test but it would be nice to see whether the below change cause any other issues.

Eric ,
can you run the test with below patch and see if this makes any difference ?. I know we are not fixing any bugs in the below patch.

ext4: Don't panic in case of corrupt bitmap

From: Aneesh Kumar K.V <[email protected]>

Multiblock allocator was calling BUG_ON in many case if the free and used blocks count obtained looking at the bitmap is different from what the allocator internally accounted for. Use ext4_error in such case and don't panic the system.

Signed-off-by Aneesh Kumar K.V <[email protected]>

---

 fs/ext4/mballoc.c |   35 +++++++++++++++++++++--------------
 1 files changed, 21 insertions(+), 14 deletions(-)
fs/ext4/mballoc.c +21 -14
index 06d1f52..656729b 100644
@@ -680,7 +680,6 @@ static void *mb_find_buddy(struct ext4_buddy *e4b, int order, int *max)
 {
 	char *bb;
 
-	/* FIXME!! is this needed */
 	BUG_ON(EXT4_MB_BITMAP(e4b) == EXT4_MB_BUDDY(e4b));
 	BUG_ON(max == NULL);
 

@@ -964,7 +963,7 @@ static void ext4_mb_generate_buddy(struct super_block *sb,
 	grp->bb_fragments = fragments;
 
 	if (free != grp->bb_free) {
-		printk(KERN_DEBUG
+		ext4_error(sb, __FUNCTION__,
 			"EXT4-fs: group %lu: %u blocks in bitmap, %u in gd\n",
 			group, free, grp->bb_free);
 		grp->bb_free = free;

@@ -1821,13 +1820,24 @@ static void ext4_mb_complex_scan_group(struct ext4_allocation_context *ac,
 		i = ext4_find_next_zero_bit(bitmap,
 						EXT4_BLOCKS_PER_GROUP(sb), i);
 		if (i >= EXT4_BLOCKS_PER_GROUP(sb)) {
-			BUG_ON(free != 0);
+			/*
+			 * IF we corrupt the bitmap  we won't find any
+			 * free blocks even though group info says we
+			 * we have free blocks
+			 */
+			ext4_error(sb, __FUNCTION__, "%d free blocks as per "
+					"group info. But bitmap says 0\n",
+					free);
 			break;
 		}
 
 		mb_find_extent(e4b, 0, i, ac->ac_g_ex.fe_len, &ex);
 		BUG_ON(ex.fe_len <= 0);
-		BUG_ON(free < ex.fe_len);
+		if (free < ex.fe_len) {
+			ext4_error(sb, __FUNCTION__, "%d free blocks as per "
+					"group info. But got %d blocks\n",
+					free, ex.fe_len);
+		}
 
 		ext4_mb_measure_extent(ac, &ex, e4b);
 

@@ -3354,13 +3364,10 @@ static void ext4_mb_use_group_pa(struct ext4_allocation_context *ac,
 	ac->ac_pa = pa;
 
 	/* we don't correct pa_pstart or pa_plen here to avoid
-	 * possible race when tte group is being loaded concurrently
+	 * possible race when the group is being loaded concurrently
 	 * instead we correct pa later, after blocks are marked
-	 * in on-disk bitmap -- see ext4_mb_release_context() */
-	/*
-	 * FIXME!! but the other CPUs can look at this particular
-	 * pa and think that it have enought free blocks if we
-	 * don't update pa_free here right ?
+	 * in on-disk bitmap -- see ext4_mb_release_context()
+	 * Other CPUs are prevented from allocating from this pa by lg_mutex
 	 */
 	mb_debug("use %u/%u from group pa %p\n", pa->pa_lstart-len, len, pa);
 }

@@ -3743,13 +3750,13 @@ static int ext4_mb_release_inode_pa(struct ext4_buddy *e4b,
 		bit = next + 1;
 	}
 	if (free != pa->pa_free) {
-		printk(KERN_ERR "pa %p: logic %lu, phys. %lu, len %lu\n",
+		printk(KERN_CRIT "pa %p: logic %lu, phys. %lu, len %lu\n",
 			pa, (unsigned long) pa->pa_lstart,
 			(unsigned long) pa->pa_pstart,
 			(unsigned long) pa->pa_len);
-		printk(KERN_ERR "free %u, pa_free %u\n", free, pa->pa_free);
+		ext4_error(sb, __FUNCTION__, "free %u, pa_free %u\n",
+						free, pa->pa_free);
 	}
-	BUG_ON(free != pa->pa_free);
 	atomic_add(free, &sbi->s_mb_discarded);
 
 	return err;

@@ -4405,7 +4412,7 @@ void ext4_mb_free_blocks(handle_t *handle, struct inode *inode,
 			unsigned long block, unsigned long count,
 			int metadata, unsigned long *freed)
 {
-	struct buffer_head *bitmap_bh = 0;
+	struct buffer_head *bitmap_bh = NULL;
 	struct super_block *sb = inode->i_sb;
 	struct ext4_allocation_context ac;
 	struct ext4_group_desc *gdp;
#6 lore raw
Quoted 9 lines · Aneesh Kumar K.V

ext4: Don't panic in case of corrupt bitmap

From: Aneesh Kumar K.V <[email protected]>

Multiblock allocator was calling BUG_ON in many case if the free and used blocks count obtained looking at the bitmap is different from what the allocator internally accounted for. Use ext4_error in such case and don't panic the system.

There seems a lot of BUG_ON() and BUG() in mballoc code, other than this case. Should it always panic the whole system in those cases? Perhaps replacing with ext4_error() or some cases just WARN_ON is enough.

Mingming

Quoted 105 lines
Signed-off-by Aneesh Kumar K.V <[email protected]>

---

 fs/ext4/mballoc.c |   35 +++++++++++++++++++++--------------
 1 files changed, 21 insertions(+), 14 deletions(-)
fs/ext4/mballoc.c +21 -15
index 06d1f52..656729b 100644
@@ -680,7 +680,6 @@ static void *mb_find_buddy(struct ext4_buddy *e4b, int order, int *max)
 {
 	char *bb;
 
-	/* FIXME!! is this needed */
 	BUG_ON(EXT4_MB_BITMAP(e4b) == EXT4_MB_BUDDY(e4b));
 	BUG_ON(max == NULL);
 

@@ -964,7 +963,7 @@ static void ext4_mb_generate_buddy(struct super_block *sb,
 	grp->bb_fragments = fragments;
 
 	if (free != grp->bb_free) {
-		printk(KERN_DEBUG
+		ext4_error(sb, __FUNCTION__,
 			"EXT4-fs: group %lu: %u blocks in bitmap, %u in gd\n",
 			group, free, grp->bb_free);
 		grp->bb_free = free;

@@ -1821,13 +1820,24 @@ static void ext4_mb_complex_scan_group(struct ext4_allocation_context *ac,
 		i = ext4_find_next_zero_bit(bitmap,
 						EXT4_BLOCKS_PER_GROUP(sb), i);
 		if (i >= EXT4_BLOCKS_PER_GROUP(sb)) {
-			BUG_ON(free != 0);
+			/*
+			 * IF we corrupt the bitmap  we won't find any
+			 * free blocks even though group info says we
+			 * we have free blocks
+			 */
+			ext4_error(sb, __FUNCTION__, "%d free blocks as per "
+					"group info. But bitmap says 0\n",
+					free);
 			break;
 		}
 
 		mb_find_extent(e4b, 0, i, ac->ac_g_ex.fe_len, &ex);
 		BUG_ON(ex.fe_len <= 0);
-		BUG_ON(free < ex.fe_len);
+		if (free < ex.fe_len) {
+			ext4_error(sb, __FUNCTION__, "%d free blocks as per "
+					"group info. But got %d blocks\n",
+					free, ex.fe_len);
+		}
 
 		ext4_mb_measure_extent(ac, &ex, e4b);
 

@@ -3354,13 +3364,10 @@ static void ext4_mb_use_group_pa(struct ext4_allocation_context *ac,
 	ac->ac_pa = pa;
 
 	/* we don't correct pa_pstart or pa_plen here to avoid
-	 * possible race when tte group is being loaded concurrently
+	 * possible race when the group is being loaded concurrently
 	 * instead we correct pa later, after blocks are marked
-	 * in on-disk bitmap -- see ext4_mb_release_context() */
-	/*
-	 * FIXME!! but the other CPUs can look at this particular
-	 * pa and think that it have enought free blocks if we
-	 * don't update pa_free here right ?
+	 * in on-disk bitmap -- see ext4_mb_release_context()
+	 * Other CPUs are prevented from allocating from this pa by lg_mutex
 	 */
 	mb_debug("use %u/%u from group pa %p\n", pa->pa_lstart-len, len, pa);
 }

@@ -3743,13 +3750,13 @@ static int ext4_mb_release_inode_pa(struct ext4_buddy *e4b,
 		bit = next + 1;
 	}
 	if (free != pa->pa_free) {
-		printk(KERN_ERR "pa %p: logic %lu, phys. %lu, len %lu\n",
+		printk(KERN_CRIT "pa %p: logic %lu, phys. %lu, len %lu\n",
 			pa, (unsigned long) pa->pa_lstart,
 			(unsigned long) pa->pa_pstart,
 			(unsigned long) pa->pa_len);
-		printk(KERN_ERR "free %u, pa_free %u\n", free, pa->pa_free);
+		ext4_error(sb, __FUNCTION__, "free %u, pa_free %u\n",
+						free, pa->pa_free);
 	}
-	BUG_ON(free != pa->pa_free);
 	atomic_add(free, &sbi->s_mb_discarded);
 
 	return err;

@@ -4405,7 +4412,7 @@ void ext4_mb_free_blocks(handle_t *handle, struct inode *inode,
 			unsigned long block, unsigned long count,
 			int metadata, unsigned long *freed)
 {
-	struct buffer_head *bitmap_bh = 0;
+	struct buffer_head *bitmap_bh = NULL;
 	struct super_block *sb = inode->i_sb;
 	struct ext4_allocation_context ac;
 	struct ext4_group_desc *gdp;
-

To unsubscribe from this list: send the line "unsubscribe linux-ext4" in the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html

#7 lore raw
Quoted 12 lines · Mingming Cao
Quoted 9 lines · Aneesh Kumar K.V

ext4: Don't panic in case of corrupt bitmap

From: Aneesh Kumar K.V <[email protected]>

Multiblock allocator was calling BUG_ON in many case if the free and used blocks count obtained looking at the bitmap is different from what the allocator internally accounted for. Use ext4_error in such case and don't panic the system.

Quoted 4 lines

There seems a lot of BUG_ON() and BUG() in mballoc code, other than this case. Should it always panic the whole system in those cases? Perhaps replacing with ext4_error() or some cases just WARN_ON is enough.

I had looked at the BUG_ON in mballoc code and found them very useful while stabilizing the mballoc code. It helped to catch wrong usage of functions. Most of the BUG_ON are there to make sure we call the API with the lock held or the API should not return value greater than 'x' Should not call the function with a particular argument as NULL ...etc kind of thing. So i would suggest to keep them as such.

-aneesh

#8 lore raw
Quoted 17 lines · Aneesh Kumar K.V
Quoted 6 lines · Mingming Cao
Quoted 4 lines · Aneesh Kumar K.V

ext4: Don't panic in case of corrupt bitmap

From: Aneesh Kumar K.V <[email protected]>

Quoted 9 lines
Quoted 5 lines

Multiblock allocator was calling BUG_ON in many case if the free and used blocks count obtained looking at the bitmap is different from what the allocator internally accounted for. Use ext4_error in such case and don't panic the system.

There seems a lot of BUG_ON() and BUG() in mballoc code, other than this case. Should it always panic the whole system in those cases? Perhaps replacing with ext4_error() or some cases just WARN_ON is enough.

Quoted 6 lines

I had looked at the BUG_ON in mballoc code and found them very useful while stabilizing the mballoc code. It helped to catch wrong usage of functions. Most of the BUG_ON are there to make sure we call the API with the lock held or the API should not return value greater than 'x' Should not call the function with a particular argument as NULL ...etc kind of thing. So i would suggest to keep them as such.

Yep - as long as the BUG_ONs are for programming errors, and not things like memory allocation failures or corrupted disks, I think it's ok. Not that I've audited them all. :)

I asked about this early on, and got that answer... I'm reasonably satisfied with it.

-Eric

author
#9 lore raw
In reply to Aneesh Kumar K.V
Quoted 18 lines · * Aneesh Kumar K.V ([email protected]) wrote:
Quoted 5 lines · Dave Kleikamp

File systems should not call BUG() due to a corrupt file system. Instead the code should fail the operation, possibly marking the file system read-only (or panicking) depending on the errors= mount option.

Eric Sandeen explained me the same on IRC. I was busy with the migrate locking bug. That's why i didn't update here. Today i tried to reproduce the problem using the image provided. But in my case it is not hitting the BUG_ON (mostly due to single cpu). I did look at the code and am not still not clear how we can hit that BUG_ON. prealloc free space pa_free is generated out of bitmap. So only if something corrupted bitmap after we initialized prealloc space we will hit this case. In mballoc we error out if the block allocated or fall in system zone. One thing i noticed is, the journal is corrupt. So the only possibility that i have is journal write resulted in bitmap corruption.

Quoted 8 lines

I also looked at the mballoc to make sure we don't panic in case of a corrupt bitmap. Below is the patch that i have now. This one is yet to go through the ABAT test but it would be nice to see whether the below change cause any other issues.

Eric ,
can you run the test with below patch and see if this makes any difference ?. I know we are not fixing any bugs in the below patch.

hi,

so far i am not able to reproduce this on 2.6.24-08039-g488b5ec neither with the ext4-fix-null-pointer-deref-in-journal_wait_on_commit_record.patch nor without it. I will try 2.6.24-05749-g8af03e7 with the patch and your change later today.

Greetings, Eric

author
#10 lore raw
In reply to Aneesh Kumar K.V
Quoted 3 lines

Eric ,
can you run the test with below patch and see if this makes any difference ?. I know we are not fixing any bugs in the below patch.

ok, i checked out the old version again and applied both patches, the BUG is gone (no surprise)
In the case where it would have hit the BUG i now get the following message:

[  740.400288] Aborting journal on device loop0.
[  740.405032] ext4_abort called.
[  740.405097] EXT4-fs error (device loop0): ext4_journal_start_sb: Detected aborted journal
[  740.405178] Remounting filesystem read-only
[  740.410974] EXT4-fs error (device loop0) in ext4_ordered_write_end: IO failure
[  740.414300] EXT4-fs error (device loop0) in ext4_reserve_inode_write: Journal has aborted
[  740.414422] pa cba56990: logic 16, phys. 1953, len 16
[  740.414447] EXT4-fs error (device loop0): ext4_mb_release_inode_pa: free 4, pa_free 3
[  740.414548] EXT4-fs error (device loop0) in ext4_mb_free_blocks: Journal has aborted

Greetings, Eric

#11 lore raw
Quoted 9 lines · Eric Sesterhenn
Quoted 3 lines

Eric ,
can you run the test with below patch and see if this makes any difference ?. I know we are not fixing any bugs in the below patch.

ok, i checked out the old version again and applied both patches, the BUG is gone (no surprise)
In the case where it would have hit the BUG i now get the following message:

[  740.400288] Aborting journal on device loop0.

No message before that about *why* it aborted?

Quoted 11 lines
[  740.405032] ext4_abort called.
[  740.405097] EXT4-fs error (device loop0): ext4_journal_start_sb: Detected aborted journal
[  740.405178] Remounting filesystem read-only
[  740.410974] EXT4-fs error (device loop0) in ext4_ordered_write_end: IO failure
[  740.414300] EXT4-fs error (device loop0) in ext4_reserve_inode_write: Journal has aborted
[  740.414422] pa cba56990: logic 16, phys. 1953, len 16
[  740.414447] EXT4-fs error (device loop0): ext4_mb_release_inode_pa: free 4, pa_free 3
[  740.414548] EXT4-fs error (device loop0) in ext4_mb_free_blocks: Journal has aborted

Greetings, Eric

author
#12 lore raw
Quoted 5 lines · * Eric Sandeen ([email protected]) wrote:
Quoted 4 lines · Eric Sesterhenn
Quoted 3 lines

Eric ,
can you run the test with below patch and see if this makes any difference ?. I know we are not fixing any bugs in the below patch.

Quoted 7 lines
Quoted 5 lines

ok, i checked out the old version again and applied both patches, the BUG is gone (no surprise)
In the case where it would have hit the BUG i now get the following message:

[  740.400288] Aborting journal on device loop0.

No message before that about *why* it aborted?

assumed the stuff was from the previous runs

[  113.318700] Aborting journal on device loop0.
[  113.324237] ext4_abort called.
[  113.324312] EXT4-fs error (device loop0): ext4_journal_start_sb:
Detected aborted journal
[  113.324394] Remounting filesystem read-only
[  113.330324] EXT4-fs error (device loop0) in ext4_dirty_inode: IO
failure
[  113.330438] EXT4-fs error (device loop0) in ext4_ordered_write_end:
IO failure
[  114.884485] EXT4-fs error (device loop0): ext4_mb_generate_buddy:
EXT4-fs: group 0: 6590 blocks in bitmap, 6600 in gd
[  116.193424] Aborting journal on device loop0.
[  116.196910] ext4_abort called.
[  116.197064] EXT4-fs error (device loop0): ext4_journal_start_sb:
Detected aborted journal
[  116.197147] Remounting filesystem read-only
[  118.031066] EXT4-fs error (device loop0): ext4_mb_generate_buddy:
EXT4-fs: group 0: 6590 blocks in bitmap, 6600 in gd
[  119.692812] Buffer I/O error on device loop0, logical block 20729
[  121.968397] Buffer I/O error on device loop0, logical block 20729
[  123.124070] Aborting journal on device loop0.
[  123.125550] ext4_abort called.
[  123.125654] EXT4-fs error (device loop0): ext4_journal_start_sb:
Detected aborted journal
[  123.125736] Remounting filesystem read-only
[  123.145792] pa cba56770: logic 32, phys. 3649, len 32
[  123.145861] EXT4-fs error (device loop0): ext4_mb_release_inode_pa:
free 30, pa_free 29
[  123.145943] EXT4-fs error (device loop0) in ext4_mb_free_blocks:
Journal has aborted
[  123.153174] EXT4-fs error (device loop0) in ext4_dirty_inode: IO
failure
[  123.153287] EXT4-fs error (device loop0) in ext4_reserve_inode_write:
Journal has aborted
[  123.153363] pa cba56198: logic 16, phys. 2113, len 16
[  123.153387] EXT4-fs error (device loop0): ext4_mb_release_inode_pa:
free 15, pa_free 14
[  123.153488] EXT4-fs error (device loop0) in ext4_mb_free_blocks:
Journal has aborted
[  125.193083] EXT4-fs error (device loop0): ext4_mb_generate_buddy:
EXT4-fs: group 0: 6590 blocks in bitmap, 6600 in gd
[  127.683441] Aborting journal on device loop0.
[  127.685090] EXT4-fs error (device loop0) in ext4_reserve_inode_write:
Journal has aborted
[  127.687548] pa cba56330: logic 16, phys. 1969, len 16
[  127.687585] EXT4-fs error (device loop0): ext4_mb_release_inode_pa:
free 16, pa_free 15
[  127.687687] BUG: sleeping function called from invalid context at
include/linux/buffer_head.h:325
[  127.688494] BUG: scheduling while atomic: fstest/4447/0x00000002
[  127.712616] EXT4-fs error (device loop0) in ext4_reserve_inode_write:
Journal has aborted
[  127.713055] BUG: scheduling while atomic: fstest/4447/0x00000002
[  127.715557] EXT4-fs error (device loop0) in ext4_orphan_add: Journal
has aborted
[  127.735782] EXT4-fs error (device loop0) in ext4_reserve_inode_write:
Journal has aborted
[  127.735883] BUG: scheduling while atomic: fstest/4447/0x00000002
[  127.736851] EXT4-fs error (device loop0) in ext4_setattr: Journal has
aborted
[  127.758924] ext4_abort called.
[  127.759044] EXT4-fs error (device loop0): ext4_journal_start_sb:
Detected aborted journal
[  127.759125] Remounting filesystem read-only
[  127.762504] EXT4-fs error (device loop0) in ext4_mb_free_blocks:
Journal has aborted
[  130.003586] EXT4-fs error (device loop0): ext4_mb_generate_buddy:
EXT4-fs: group 0: 6590 blocks in bitmap, 6600 in gd
[  133.104600] Aborting journal on device loop0.
[  133.109459] ext4_abort called.
[  133.109528] EXT4-fs error (device loop0): ext4_journal_start_sb:
Detected aborted journal
[  133.109683] Remounting filesystem read-only
[  133.128537] EXT4-fs error (device loop0) in ext4_dirty_inode: IO
failure
[  133.128766] EXT4-fs error (device loop0) in ext4_reserve_inode_write:
Journal has aborted
[  133.128803] EXT4-fs error (device loop0) in ext4_mb_free_blocks:
Journal has aborted
[  135.037160] EXT4-fs error (device loop0): ext4_mb_generate_buddy:
EXT4-fs: group 0: 6590 blocks in bitmap, 6600 in gd
[  135.995986] Aborting journal on device loop0.
[  135.999977] ext4_abort called.
[  136.000049] EXT4-fs error (device loop0): ext4_journal_start_sb:
Detected aborted journal
[  136.000129] Remounting filesystem read-only
[  136.005258] pa cba56440: logic 32, phys. 2081, len 32
[  136.005312] EXT4-fs error (device loop0): ext4_mb_release_inode_pa:
free 30, pa_free 29
[  136.005478] EXT4-fs error (device loop0) in ext4_mb_free_blocks:
Journal has aborted
[  136.011164] EXT4-fs error (device loop0) in ext4_reserve_inode_write:
Journal has aborted
[  136.011280] pa cba56088: logic 16, phys. 1857, len 16
[  136.011304] EXT4-fs error (device loop0): ext4_mb_release_inode_pa:
free 7, pa_free 6
[  136.011403] EXT4-fs error (device loop0) in ext4_mb_free_blocks:
Journal has aborted
[  137.489878] EXT4-fs error (device loop0): ext4_mb_generate_buddy:
EXT4-fs: group 0: 6590 blocks in bitmap, 6600 in gd
[  139.140550] Aborting journal on device loop0.
[  139.144889] ext4_abort called.
[  139.145015] EXT4-fs error (device loop0): ext4_journal_start_sb:
Detected aborted journal
[  139.145098] Remounting filesystem read-only
[  141.115285] EXT4-fs error (device loop0): ext4_mb_generate_buddy:
EXT4-fs: group 0: 6590 blocks in bitmap, 6600 in gd
[  142.790793] Buffer I/O error on device loop0, logical block 13239314
[  673.819560] EXT4-fs error (device loop0): ext4_mb_generate_buddy:
EXT4-fs: group 0: 6590 blocks in bitmap, 6600 in gd
[  675.794735] Buffer I/O error on device loop0, logical block
4060087480
[  676.048909] Aborting journal on device loop0.
[  676.050604] ext4_abort called.
[  676.050670] EXT4-fs error (device loop0): ext4_journal_start_sb:
Detected aborted journal
[  676.050752] Remounting filesystem read-only
[  676.065725] EXT4-fs error (device loop0) in ext4_ordered_write_end:
IO failure
[  697.154481] EXT4-fs error (device loop0): ext4_mb_generate_buddy:
EXT4-fs: group 0: 6590 blocks in bitmap, 6600 in gd
[  701.149256] Aborting journal on device loop0.
[  701.150812] ext4_abort called.
[  701.150856] EXT4-fs error (device loop0): ext4_journal_start_sb:
Detected aborted journal
[  701.151010] Remounting filesystem read-only
[  701.171010] EXT4-fs error (device loop0) in ext4_ordered_write_end:
IO failure
[  728.261874] EXT4-fs error (device loop0): ext4_mb_generate_buddy:
EXT4-fs: group 0: 6590 blocks in bitmap, 6600 in gd
[  729.913716] Aborting journal on device loop0.
[  729.917148] ext4_abort called.
[  729.917216] EXT4-fs error (device loop0): ext4_journal_start_sb:
Detected aborted journal
[  729.917298] Remounting filesystem read-only
[  729.933777] EXT4-fs error (device loop0) in ext4_reserve_inode_write:
Journal has aborted
[  729.933858] EXT4-fs error (device loop0) in ext4_mb_free_blocks:
Journal has aborted
[  729.941235] EXT4-fs error (device loop0) in ext4_mb_free_blocks:
Journal has aborted
[  729.941314] EXT4-fs error (device loop0) in ext4_reserve_inode_write:
Journal has aborted
[  729.941343] EXT4-fs error (device loop0) in ext4_reserve_inode_write:
Journal has aborted
[  729.941398] EXT4-fs error (device loop0) in ext4_ext_remove_space:
Journal has aborted
[  729.941431] EXT4-fs error (device loop0) in ext4_reserve_inode_write:
Journal has aborted
[  729.941481] EXT4-fs error (device loop0) in ext4_orphan_del: Journal
has aborted
[  735.424574] EXT4-fs error (device loop0): ext4_mb_generate_buddy:
EXT4-fs: group 0: 6590 blocks in bitmap, 6600 in gd
[  740.400288] Aborting journal on device loop0.
[  740.405032] ext4_abort called.
[  740.405097] EXT4-fs error (device loop0): ext4_journal_start_sb:
Detected aborted journal
[  740.405178] Remounting filesystem read-only
[  740.410974] EXT4-fs error (device loop0) in ext4_ordered_write_end:
IO failure
[  740.414300] EXT4-fs error (device loop0) in ext4_reserve_inode_write:
Journal has aborted
[  740.414422] pa cba56990: logic 16, phys. 1953, len 16
[  740.414447] EXT4-fs error (device loop0): ext4_mb_release_inode_pa:
free 4, pa_free 3
[  740.414548] EXT4-fs error (device loop0) in ext4_mb_free_blocks:

Journal has aborted

Greetings, Eric

#13 lore raw
Quoted 10 lines · Eric Sesterhenn
Quoted 9 lines · * Eric Sandeen ([email protected]) wrote:
Quoted 8 lines · Eric Sesterhenn
Quoted 3 lines

Eric ,
can you run the test with below patch and see if this makes any difference ?. I know we are not fixing any bugs in the below patch.

ok, i checked out the old version again and applied both patches, the BUG is gone (no surprise)
In the case where it would have hit the BUG i now get the following message:

[  740.400288] Aborting journal on device loop0.
Quoted 8 lines
Quoted 1 line

No message before that about *why* it aborted?

assumed the stuff was from the previous runs

[  735.424574] EXT4-fs error (device loop0): ext4_mb_generate_buddy:
EXT4-fs: group 0: 6590 blocks in bitmap, 6600 in gd
[  740.400288] Aborting journal on device loop0.

There it is, thanks. Just making sure :)

-Eric

#14 lore raw
In reply to Eric Sesterhenn
Quoted 10 lines · Eric Sesterhenn

hi,

while running a modified version of fsfuzzer i triggered the BUG() in ext4_mb_release_inode_pa(). Sadly I am not able to reproduce this using the generated image, but running the fuzzer will usually trigger this in less than 40 attempts. Increasing the JBD2 Debug level didnt give more information. The kernel is current git with ext4-fix-null-pointer-deref-in-journal_wait_on_commit_record.patch applied.

Quoted 2 lines

Greetings, Eric

Thanks for reporting this.

Quoted 1 line
[ 1570.971980] EXT4-fs error (device loop0) in ext4_reserve_inode_write: Journal has aborted

Is there any more info about why jbd has aborted?

Quoted 2 lines
[ 1570.972077] pa c6512330: logic 16, phys. 2337, len 16
[ 1570.972103] free 2, pa_free 1

looks like free!=pa_free.

Aneesh, could you take a look? Thanks!

Mingming

Quoted 161 lines
[ 1570.972191] ------------[ cut here ]------------
[ 1570.972217] kernel BUG at fs/ext4/mballoc.c:3752!
[ 1570.972241] invalid opcode: 0000 [#1] PREEMPT DEBUG_PAGEALLOC
[ 1570.972386] Modules linked in:
[ 1570.972425] 
[ 1570.972509] Pid: 6629, comm: fstest Not tainted (2.6.24-05749-g8af03e7-dirty #19)
[ 1570.972534] EIP: 0060:[<c02266b9>] EFLAGS: 00010202 CPU: 0
[ 1570.972570] EIP is at ext4_mb_release_inode_pa+0x169/0x1a0
[ 1570.972595] EAX: 00000001 EBX: 00000930 ECX: 00000001 EDX: 00000001
[ 1570.972678] ESI: 00000930 EDI: c6512330 EBP: cb638b28 ESP: cb638a84
[ 1570.972703]  DS: 007b ES: 007b FS: 0000 GS: 0033 SS: 0068
[ 1570.972728] Process fstest (pid: 6629, ti=cb638000 task=cb698000 task.ti=cb638000)
[ 1570.972751] Stack: c07c21bb 00000002 00000001 00000921 00000010 cbff34e0 cb638b54 00000002 
[ 1570.972899]        cb5fa430 c64824a0 cb5fb920 00000022 cbff34e0 cb638ad4 00000246 00000400 
[ 1570.972899]        cbfa2000 cb5fb920 cbff34e0 00000000 0000092e 00000000 00000002 cbfa2000 
[ 1570.972899] Call Trace:
[ 1570.972899]  [<c020e3a4>] ? read_block_bitmap+0x54/0x120
[ 1570.972899]  [<c022bd24>] ? ext4_mb_discard_inode_preallocations+0x124/0x300
[ 1570.972899]  [<c022bda5>] ? ext4_mb_discard_inode_preallocations+0x1a5/0x300
[ 1570.972899]  [<c0223577>] ? ext4_ext_get_blocks+0x3a7/0x4b0
[ 1570.972899]  [<c0213928>] ? ext4_get_blocks_wrap+0xe8/0x130
[ 1570.972899]  [<c0213bce>] ? ext4_get_block+0x7e/0xf0
[ 1570.972899]  [<c019d7ba>] ? __block_prepare_write+0x17a/0x3a0
[ 1570.972899]  [<c019da68>] ? block_write_begin+0x48/0xe0
[ 1570.972899]  [<c0213b50>] ? ext4_get_block+0x0/0xf0
[ 1570.972899]  [<c0215127>] ? ext4_write_begin+0xb7/0x190
[ 1570.972899]  [<c0213b50>] ? ext4_get_block+0x0/0xf0
[ 1570.972899]  [<c01557e9>] ? generic_perform_write+0xa9/0x190
[ 1570.972899]  [<c01575bd>] ? generic_file_buffered_write+0x6d/0x130
[ 1570.972899]  [<c01578c1>] ? __generic_file_aio_write_nolock+0x241/0x550
[ 1570.972899]  [<c0144b44>] ? trace_hardirqs_on+0xc4/0x150
[ 1570.972899]  [<c0157c2c>] ? generic_file_aio_write+0x5c/0xd0
[ 1570.972899]  [<c015ab0d>] ? free_one_page+0x1ed/0x220
[ 1570.972899]  [<c0210410>] ? ext4_file_write+0x50/0x160
[ 1570.972899]  [<c017b11d>] ? do_sync_write+0xcd/0x110
[ 1570.972899]  [<c01096f9>] ? native_sched_clock+0x69/0xc0
[ 1570.972899]  [<c01373c0>] ? autoremove_wake_function+0x0/0x50
[ 1570.972899]  [<c01070e5>] ? do_softirq+0x55/0xd0
[ 1570.972899]  [<c01050d3>] ? restore_nocheck+0x12/0x15
[ 1570.972899]  [<c0144b44>] ? trace_hardirqs_on+0xc4/0x150
[ 1570.972899]  [<c017b959>] ? vfs_write+0x99/0x130
[ 1570.972899]  [<c017b050>] ? do_sync_write+0x0/0x110
[ 1570.972899]  [<c017c048>] ? sys_pwrite64+0x68/0x70
[ 1570.972899]  [<c0104fea>] ? sysenter_past_esp+0x5f/0xa5
[ 1570.972899]  =======================
[ 1570.972899] Code: ff 0f b7 47 4e 89 44 24 08 8b 85 78 ff ff ff c7 04 24 bb 21 7c c0 89 44 24 04 e8 c3 e0 ef ff 0f b7 47 4e 39 85 78 ff ff ff 74 07 <0f> 0b eb fe 8d 76 00 8b 85 78 ff ff ff 8b 95 7c ff ff ff 01 82 
[ 1570.972899] EIP: [<c02266b9>] ext4_mb_release_inode_pa+0x169/0x1a0 SS:ESP 0068:cb638a84
[ 1570.972942] ---[ end trace 51819e80cd9431da ]---
[ 1570.972969] note: fstest[6629] exited with preempt_count 1
[ 1570.973013] BUG: sleeping function called from invalid context at kernel/rwsem.c:21
[ 1570.973039] in_atomic():1, irqs_disabled():0
[ 1570.973077] INFO: lockdep is turned off.
[ 1570.973104] Pid: 6629, comm: fstest Tainted: G      D 2.6.24-05749-g8af03e7-dirty #19
[ 1570.973159]  [<c011e1a6>] __might_sleep+0xc6/0xf0
[ 1570.973224]  [<c06b2c99>] down_read+0x19/0x80
[ 1570.973295]  [<c013a7fd>] ? hrtimer_try_to_cancel+0x3d/0x80
[ 1570.973396]  [<c0125a27>] exit_mm+0x27/0xd0
[ 1570.973467]  [<c01272f3>] do_exit+0x133/0x2e0
[ 1570.973529]  [<c010611c>] die+0x13c/0x140
[ 1570.973590]  [<c0135197>] ? search_exception_tables+0x27/0x30
[ 1570.973993]  [<c01061b1>] do_trap+0x91/0xc0
[ 1570.974054]  [<c0106440>] ? do_invalid_op+0x0/0xa0
[ 1570.974133]  [<c01064c9>] do_invalid_op+0x89/0xa0
[ 1570.974195]  [<c02266b9>] ? ext4_mb_release_inode_pa+0x169/0x1a0
[ 1570.974290]  [<c012007b>] ? account_system_time+0x9b/0xd0
[ 1570.974370]  [<c01245de>] ? vprintk+0x1ce/0x360
[ 1570.974465]  [<c06b4492>] error_code+0x6a/0x70
[ 1570.974531]  [<c012007b>] ? account_system_time+0x9b/0xd0
[ 1570.974626]  [<c02266b9>] ? ext4_mb_release_inode_pa+0x169/0x1a0
[ 1570.974707]  [<c020e3a4>] ? read_block_bitmap+0x54/0x120
[ 1570.974803]  [<c022bd24>] ? ext4_mb_discard_inode_preallocations+0x124/0x300
[ 1570.975151]  [<c022bda5>] ext4_mb_discard_inode_preallocations+0x1a5/0x300
[ 1570.975221]  [<c0223577>] ext4_ext_get_blocks+0x3a7/0x4b0
[ 1570.975289]  [<c0213928>] ext4_get_blocks_wrap+0xe8/0x130
[ 1570.975352]  [<c0213bce>] ext4_get_block+0x7e/0xf0
[ 1570.975413]  [<c019d7ba>] __block_prepare_write+0x17a/0x3a0
[ 1570.975479]  [<c019da68>] block_write_begin+0x48/0xe0
[ 1570.975541]  [<c0213b50>] ? ext4_get_block+0x0/0xf0
[ 1570.975635]  [<c0215127>] ext4_write_begin+0xb7/0x190
[ 1570.975697]  [<c0213b50>] ? ext4_get_block+0x0/0xf0
[ 1570.975776]  [<c01557e9>] generic_perform_write+0xa9/0x190
[ 1570.975838]  [<c01575bd>] generic_file_buffered_write+0x6d/0x130
[ 1570.975944]  [<c01578c1>] __generic_file_aio_write_nolock+0x241/0x550
[ 1570.976007]  [<c0144b44>] ? trace_hardirqs_on+0xc4/0x150
[ 1570.976105]  [<c0157c2c>] generic_file_aio_write+0x5c/0xd0
[ 1570.976166]  [<c015ab0d>] ? free_one_page+0x1ed/0x220
[ 1570.976247]  [<c0210410>] ext4_file_write+0x50/0x160
[ 1570.976308]  [<c017b11d>] do_sync_write+0xcd/0x110
[ 1570.976372]  [<c01096f9>] ? native_sched_clock+0x69/0xc0
[ 1570.976470]  [<c01373c0>] ? autoremove_wake_function+0x0/0x50
[ 1570.976567]  [<c01070e5>] ? do_softirq+0x55/0xd0
[ 1570.976662]  [<c01050d3>] ? restore_nocheck+0x12/0x15
[ 1570.976741]  [<c0144b44>] ? trace_hardirqs_on+0xc4/0x150
[ 1570.976837]  [<c017b959>] vfs_write+0x99/0x130
[ 1570.976933]  [<c017b050>] ? do_sync_write+0x0/0x110
[ 1570.977014]  [<c017c048>] sys_pwrite64+0x68/0x70
[ 1570.977075]  [<c0104fea>] sysenter_past_esp+0x5f/0xa5
[ 1570.977137]  =======================
[ 1570.977400] BUG: scheduling while atomic: fstest/6629/0x00000002
[ 1570.977426] INFO: lockdep is turned off.
[ 1570.977468] Pid: 6629, comm: fstest Tainted: G      D 2.6.24-05749-g8af03e7-dirty #19
[ 1570.977494]  [<c0120125>] __schedule_bug+0x75/0x80
[ 1570.977557]  [<c06b1db5>] schedule+0x2d5/0x3a0
[ 1570.977621]  [<c06b3325>] rwsem_down_failed_common+0x75/0x170
[ 1570.977684]  [<c0142fde>] ? __lock_contended+0xbe/0x110
[ 1570.977780]  [<c06b343d>] rwsem_down_write_failed+0x1d/0x30
[ 1570.977842]  [<c06b34ca>] call_rwsem_down_write_failed+0x6/0x8
[ 1570.977933]  [<c06b2d81>] ? down_write+0x81/0x90
[ 1570.978013]  [<c021058c>] ? ext4_release_file+0x6c/0x80
[ 1570.978108]  [<c021058c>] ext4_release_file+0x6c/0x80
[ 1570.978168]  [<c017c484>] __fput+0xb4/0x1b0
[ 1570.978231]  [<c017c788>] fput+0x18/0x20
[ 1570.978291]  [<c0179827>] filp_close+0x47/0x70
[ 1570.978352]  [<c0125dd0>] close_files+0x70/0x80
[ 1570.978415]  [<c0125e0a>] put_files_struct+0x2a/0x60
[ 1570.978477]  [<c0125e80>] __exit_files+0x40/0x50
[ 1570.978538]  [<c0127301>] do_exit+0x141/0x2e0
[ 1570.978600]  [<c010611c>] die+0x13c/0x140
[ 1570.978661]  [<c0135197>] ? search_exception_tables+0x27/0x30
[ 1570.978741]  [<c01061b1>] do_trap+0x91/0xc0
[ 1570.978803]  [<c0106440>] ? do_invalid_op+0x0/0xa0
[ 1570.979039]  [<c01064c9>] do_invalid_op+0x89/0xa0
[ 1570.979104]  [<c02266b9>] ? ext4_mb_release_inode_pa+0x169/0x1a0
[ 1570.979185]  [<c012007b>] ? account_system_time+0x9b/0xd0
[ 1570.979280]  [<c01245de>] ? vprintk+0x1ce/0x360
[ 1570.979360]  [<c06b4492>] error_code+0x6a/0x70
[ 1570.979423]  [<c012007b>] ? account_system_time+0x9b/0xd0
[ 1570.979519]  [<c02266b9>] ? ext4_mb_release_inode_pa+0x169/0x1a0
[ 1570.979600]  [<c020e3a4>] ? read_block_bitmap+0x54/0x120
[ 1570.979700]  [<c022bd24>] ? ext4_mb_discard_inode_preallocations+0x124/0x300
[ 1570.979797]  [<c022bda5>] ext4_mb_discard_inode_preallocations+0x1a5/0x300
[ 1570.979861]  [<c0223577>] ext4_ext_get_blocks+0x3a7/0x4b0
[ 1570.979964]  [<c0213928>] ext4_get_blocks_wrap+0xe8/0x130
[ 1570.980026]  [<c0213bce>] ext4_get_block+0x7e/0xf0
[ 1570.980087]  [<c019d7ba>] __block_prepare_write+0x17a/0x3a0
[ 1570.980153]  [<c019da68>] block_write_begin+0x48/0xe0
[ 1570.980215]  [<c0213b50>] ? ext4_get_block+0x0/0xf0
[ 1570.980309]  [<c0215127>] ext4_write_begin+0xb7/0x190
[ 1570.980371]  [<c0213b50>] ? ext4_get_block+0x0/0xf0
[ 1570.980450]  [<c01557e9>] generic_perform_write+0xa9/0x190
[ 1570.980513]  [<c01575bd>] generic_file_buffered_write+0x6d/0x130
[ 1570.980576]  [<c01578c1>] __generic_file_aio_write_nolock+0x241/0x550
[ 1570.980639]  [<c0144b44>] ? trace_hardirqs_on+0xc4/0x150
[ 1570.980735]  [<c0157c2c>] generic_file_aio_write+0x5c/0xd0
[ 1570.980796]  [<c015ab0d>] ? free_one_page+0x1ed/0x220
[ 1570.980932]  [<c0210410>] ext4_file_write+0x50/0x160
[ 1570.980995]  [<c017b11d>] do_sync_write+0xcd/0x110
[ 1570.981058]  [<c01096f9>] ? native_sched_clock+0x69/0xc0
[ 1570.981142]  [<c01373c0>] ? autoremove_wake_function+0x0/0x50
[ 1570.981238]  [<c01070e5>] ? do_softirq+0x55/0xd0
[ 1570.981317]  [<c01050d3>] ? restore_nocheck+0x12/0x15
[ 1570.981410]  [<c0144b44>] ? trace_hardirqs_on+0xc4/0x150
[ 1570.981491]  [<c017b959>] vfs_write+0x99/0x130
[ 1570.981552]  [<c017b050>] ? do_sync_write+0x0/0x110
[ 1570.981646]  [<c017c048>] sys_pwrite64+0x68/0x70
[ 1570.981708]  [<c0104fea>] sysenter_past_esp+0x5f/0xa5
[ 1570.981769]  =======================

-
To unsubscribe from this list: send the line "unsubscribe linux-ext4" in the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html