Dave,

Thanks for the quick response and patch!!! I'm testing your new patch now -- so far so good :-)

In the process of debugging this problem last week I ran into two other issues that I would love your help on now that the corrupted root node issue is fixed... They were:

1) When I create/delete a file repeatedly the di_size grows without bound. Is that expected/safe? Does di_size include the journal? Are we leaking disk space? 

Here's a little Bash script that demonstrates what I'm talking about:

mount_dir="/mnt"
device="/dev/sdb"

jfs_mkfs -f $device
mount $device $mount_dir

# This example does not work without at least one file at the root
touch "$mount_dir/foo"

echo -e "\ndi_size=$(ls -la $mount_dir | grep -E " \.$" | awk '{print $5}')"
for (( file_count=0; file_count<10; file_count+=1 )); do
    for (( i=0; i<1000; i+=1 )); do
        touch $mount_dir/bar
        rm $mount_dir/bar
    done

    echo -e "di_size=$(ls -la $mount_dir | grep -E " \.$" | awk '{print $5}')"
done

Here's the output from the above on my VMware host... Note that creating and deleting the tmp file 'bar' 1,000 times causes di_size to increase by 8k.

jfs_mkfs version 1.1.14.patched.2011.02.07, 06-Apr-2009

Format completed successfully.

20971520 kilobytes total disk space.

di_size=8
di_size=8192
di_size=16384
di_size=24576
di_size=32768
di_size=40960
di_size=49152
di_size=57344
di_size=65536
di_size=73728
di_size=81920

From the jfs_debugfs output it looks like the B+ tree is correct with a single leaf node stored in the inode:

> i 16 a
Inode 16 at block 13, offset 0x0:

[1] di_inostamp: 0x4d51c3d5 [19] di_mtime.tv_nsec: 0x00000000
[2] di_fileset: 1 [20] di_otime.tv_sec: 0x4d51c3d5
[3] di_number: 16 [21] di_otime.tv_nsec: 0x00000000
[4] di_gen: 1 [22] di_acl.flag: 0x00
[5] di_ixpxd.len: 4 [23] di_acl.rsrvd: Not Displayed
[6] di_ixpxd.addr1: 0x00 [24] di_acl.size: 0x00000000
[7] di_ixpxd.addr2: 0x0000000b [25] di_acl.len: 0
     di_ixpxd.address: 11 [26] di_acl.addr1: 0x00
[8] di_size: 0x0000000000002000 [27] di_acl.addr2: 0x00000000
[9] di_nblocks: 0x0000000000000002     di_acl.address: 0
[10] di_nlink: 1 [28] di_ea.flag: 0x00
[11] di_uid: 0 [29] di_ea.rsrvd: Not Displayed
[12] di_gid: 0 [30] di_ea.size: 0x00000000
[13] di_mode: 0x00018000 [31] di_ea.len: 0
0100000      ---- [32] di_ea.addr1: 0x00
[14] di_atime.tv_sec: 0x4d51c3d5 [33] di_ea.addr2: 0x00000000
[15] di_atime.tv_nsec: 0x00000000     di_ea.address: 0
[16] di_ctime.tv_sec: 0x4d51c3d5 [34] di_next_index: 2
[17] di_ctime.tv_nsec: 0x00000000 [35] di_acltype: 0x00000000
[18] di_mtime.tv_sec: 0x4d51c3d5

> i 2
Inode 2 at block 665, offset 0x400:

[1] di_inostamp: 0x4d51c3d5 [19] di_mtime.tv_nsec: 0x23e0fdd3
[2] di_fileset: 16 [20] di_otime.tv_sec: 0x4d51c3d5
[3] di_number: 2 [21] di_otime.tv_nsec: 0x00000000
[4] di_gen: 1 [22] di_acl.flag: 0x00
[5] di_ixpxd.len: 4 [23] di_acl.rsrvd: Not Displayed
[6] di_ixpxd.addr1: 0x00 [24] di_acl.size: 0x00000000
[7] di_ixpxd.addr2: 0x00000299 [25] di_acl.len: 0
     di_ixpxd.address: 665 [26] di_acl.addr1: 0x00
[8] di_size: 0x0000000000014000 [27] di_acl.addr2: 0x00000000
[9] di_nblocks: 0x0000000000000015     di_acl.address: 0
[10] di_nlink: 2 [28] di_ea.flag: 0x00
[11] di_uid: 0 [29] di_ea.rsrvd: Not Displayed
[12] di_gid: 0 [30] di_ea.size: 0x00000000
[13] di_mode: 0x000141ed [31] di_ea.len: 0
0040755      drwx [32] di_ea.addr1: 0x00
[14] di_atime.tv_sec: 0x4d51c402 [33] di_ea.addr2: 0x00000000
[15] di_atime.tv_nsec: 0x241bd157     di_ea.address: 0
[16] di_ctime.tv_sec: 0x4d51c402 [34] di_next_index: 10003
[17] di_ctime.tv_nsec: 0x23e0fdd3 [35] di_acltype: 0x00000000
[18] di_mtime.tv_sec: 0x4d51c402

> dir 2
idotdot = 2

4 foo

> dt 2
Root D-Tree Node of inode 2

[1] DASDlimit 0
[2] DASDused 0
[3] thresh (%) 0
[4] delta (%) 0

[5] flag 0x83 BT_ROOT  BT_LEAF  
[6] nextindex 1
[7] freecnt 7
[8] freelist 2
[9] idotdot 2
[10] stbl {1,1,0,0,0,0,0,0}
dtree: Hit enter to see entries, [m]odify, or e[x]it: 
stbl[0] = 1
[1] inumber 4
[2] next -1
[3] namlen 3
[4] name foo
[5] index 2
dtree: Press enter for next, [m]odify, [u]p, or e[x]it > x

> su p
[1] s_magic: 'JFS1' [15] s_ait2.addr1: 0x00
[2] s_version: 1 [16] s_ait2.addr2: 0x00000295
[3] s_size: 0x00000000027d7968     s_ait2.address: 661
[4] s_bsize: 4096 [17] s_logdev: 0x00000810
[5] s_l2bsize: 12 [18] s_logserial: 0x00000001
[6] s_l2bfactor: 3 [19] s_logpxd.len: 20480
[7] s_pbsize: 512 [20] s_logpxd.addr1: 0x00
[8] s_l2pbsize: 9 [21] s_logpxd.addr2: 0x004fb000
[9] pad: Not Displayed     s_logpxd.address: 5222400
[10] s_agsize: 0x00010000 [22] s_fsckpxd.len: 211
[11] s_flag: 0x10200900 [23] s_fsckpxd.addr1: 0x00
               JFS_LINUX [24] s_fsckpxd.addr2: 0x004faf2d
JFS_COMMIT JFS_GROUPCOMMIT     s_fsckpxd.address: 5222189
              JFS_INLINELOG [25] s_time.tv_sec: 0x4d51c3d5
                [26] s_time.tv_nsec: 0x00000000
                [27] s_fpack: ''
[12] s_state: 0x00000001
    FM_MOUNT
[13] s_compress: 0
[14] s_ait2.len: 4


2) During my testing I hit "bad page state" kernel warnings when calling unmount. I suspect a timing issue here so the Bash script below that triggers this problem on my VMware host my not cause a problem on faster hardware. I hit this initially because I tried creating/deleting the tmp file just once in the loop I used to reproduce the corrupted root node. 
I've seen similar problems in my production environment so I believe the bug can be triggered in a real world scenario. 

The following Bash script is the simplest example I could come up with... Removing any of the elements seems to avoid the problem.

loop_count=0
mount_dir="/mnt"
device="/dev/sdb"

jfs_mkfs -f $device

while jfs_fsck -n $device > /dev/null 2>&1; do
    if ! expr $loop_count % 50 > /dev/null; then echo "loop_count=$loop_count"; fi
    let loop_count+=1

    mount $device $mount_dir

    touch $mount_dir/tmp
    rm $mount_dir/tmp

    umount $device
done

Here's the output from the above loop...

loop_count=0
loop_count=50
loop_count=100

Message from syslogd@debian at Feb  8 16:45:50 ...
 kernel:[ 6758.610923] Bad page state in process 'umount'

Message from syslogd@debian at Feb  8 16:45:50 ...
 kernel:[ 6758.610929] page:ffffe20000453880 flags:0x0100000000000804 mapping:0000000000000000 mapcount:0 count:0

Message from syslogd@debian at Feb  8 16:45:50 ...
 kernel:[ 6758.611486] Trying to fix it up, but a reboot is needed

Message from syslogd@debian at Feb  8 16:45:50 ...
 kernel:[ 6758.611487] Backtrace:

Here are the details log messages from kern.log

Feb  8 16:45:50 debian kernel: [ 6758.610923] Bad page state in process 'umount'
Feb  8 16:45:50 debian kernel: [ 6758.610929] page:ffffe20000453880 flags:0x0100000000000804 mapping:0000000000000000 mapcount:0 count:0
Feb  8 16:45:50 debian kernel: [ 6758.611486] Trying to fix it up, but a reboot is needed
Feb  8 16:45:50 debian kernel: [ 6758.611487] Backtrace:
Feb  8 16:45:50 debian kernel: [ 6758.611819] Pid: 8836, comm: umount Not tainted 2.6.26-2-amd64 #1
Feb  8 16:45:50 debian kernel: [ 6758.611820] 
Feb  8 16:45:50 debian kernel: [ 6758.611821] Call Trace:
Feb  8 16:45:50 debian kernel: [ 6758.611846]  [<ffffffff8031dc43>] radix_tree_delete+0x1a0/0x1b5
Feb  8 16:45:50 debian kernel: [ 6758.611967]  [<ffffffff80275095>] bad_page+0x6b/0x95
Feb  8 16:45:50 debian kernel: [ 6758.611970]  [<ffffffff802756a5>] free_hot_cold_page+0x86/0x168
Feb  8 16:45:50 debian kernel: [ 6758.611973]  [<ffffffff802757a8>] __pagevec_free+0x21/0x2e
Feb  8 16:45:50 debian kernel: [ 6758.611975]  [<ffffffff80279017>] release_pages+0x170/0x182
Feb  8 16:45:50 debian kernel: [ 6758.611981]  [<ffffffff802713a9>] wait_on_page_bit+0x6b/0x71
Feb  8 16:45:50 debian kernel: [ 6758.611985]  [<ffffffff8027290e>] __remove_from_page_cache+0x33/0xa1
Feb  8 16:45:50 debian kernel: [ 6758.611988]  [<ffffffff80279610>] __pagevec_release+0x19/0x22
Feb  8 16:45:50 debian kernel: [ 6758.611990]  [<ffffffff80279d20>] truncate_inode_pages_range+0xed/0x2f9
Feb  8 16:45:50 debian kernel: [ 6758.611994]  [<ffffffff8031d136>] __prop_inc_single+0x1d/0x37
Feb  8 16:45:50 debian kernel: [ 6758.612014]  [<ffffffffa02f7c4e>] :jfs:release_metapage+0x122/0x12d
Feb  8 16:45:50 debian kernel: [ 6758.612022]  [<ffffffffa02ecbe1>] :jfs:diUnmount+0x39/0x48
Feb  8 16:45:50 debian kernel: [ 6758.612029]  [<ffffffffa02e70f9>] :jfs:jfs_umount+0x3a/0xe5
Feb  8 16:45:50 debian kernel: [ 6758.612036]  [<ffffffffa02e37e0>] :jfs:jfs_put_super+0xd/0x5e
Feb  8 16:45:50 debian kernel: [ 6758.612045]  [<ffffffff8029cd91>] generic_shutdown_super+0x60/0xee
Feb  8 16:45:50 debian kernel: [ 6758.612048]  [<ffffffff8029ce2c>] kill_block_super+0xd/0x1e
Feb  8 16:45:50 debian kernel: [ 6758.612050]  [<ffffffff8029cee8>] deactivate_super+0x5f/0x78
Feb  8 16:45:50 debian kernel: [ 6758.612055]  [<ffffffff802b02fc>] sys_umount+0x2f9/0x353
Feb  8 16:45:50 debian kernel: [ 6758.612064]  [<ffffffff80221fbc>] do_page_fault+0x5d8/0x9c8
Feb  8 16:45:50 debian kernel: [ 6758.612067]  [<ffffffff8029e4c8>] sys_newstat+0x19/0x31
Feb  8 16:45:50 debian kernel: [ 6758.612070]  [<ffffffff8031e473>] __up_write+0x21/0x10e
Feb  8 16:45:50 debian kernel: [ 6758.612076]  [<ffffffff8020beda>] system_call_after_swapgs+0x8a/0x8f
Feb  8 16:45:50 debian kernel: [ 6758.612081] 
Feb  8 16:46:41 debian kernel: [ 6809.853678] ------------[ cut here ]------------
Feb  8 16:46:41 debian kernel: [ 6809.853683] WARNING: at fs/jfs/jfs_logmgr.c:1641 jfs_flush_journal+0x21f/0x232 [jfs]()
Feb  8 16:46:41 debian kernel: [ 6809.853685] Modules linked in: jfs nls_base ipv6 vmblock vsock vmmemctl vmhgfs pvscsi acpiphp loop parport_pc parport snd_ens1371 psmouse snd_pcsp gameport serio_raw snd_rawmidi snd_seq_device snd_ac97_codec ac97_bus snd_pcm snd_timer snd soundcore snd_page_alloc vmci i2c_piix4 i2c_core container ac shpchp pci_hotplug button intel_agp evdev ext3 jbd mbcache ide_cd_mod cdrom sd_mod ide_pci_generic floppy ehci_hcd e1000 uhci_hcd mptspi mptscsih mptbase scsi_transport_spi piix ide_core ata_generic libata scsi_mod dock thermal processor fan thermal_sys vmxnet [last unloaded: scsi_wait_scan]
Feb  8 16:46:41 debian kernel: [ 6809.853731] Pid: 8836, comm: umount Tainted: G    B     2.6.26-2-amd64 #1
Feb  8 16:46:41 debian kernel: [ 6809.853732] 
Feb  8 16:46:41 debian kernel: [ 6809.853732] Call Trace:
Feb  8 16:46:41 debian kernel: [ 6809.853744]  [<ffffffff80234958>] warn_on_slowpath+0x51/0x7a
Feb  8 16:46:41 debian kernel: [ 6809.853753]  [<ffffffff8023cfb7>] try_to_del_timer_sync+0x51/0x5a
Feb  8 16:46:41 debian kernel: [ 6809.853756]  [<ffffffff802771b1>] __writepage+0x0/0x23
Feb  8 16:46:41 debian kernel: [ 6809.853847]  [<ffffffff8023cfcc>] del_timer_sync+0xc/0x16
Feb  8 16:46:41 debian kernel: [ 6809.853857]  [<ffffffff8042974a>] schedule_timeout+0x92/0xad
Feb  8 16:46:41 debian kernel: [ 6809.853860]  [<ffffffff8023cc34>] process_timeout+0x0/0x5
Feb  8 16:46:41 debian kernel: [ 6809.853862]  [<ffffffff8042973d>] schedule_timeout+0x85/0xad
Feb  8 16:46:41 debian kernel: [ 6809.853871]  [<ffffffffa02f9809>] :jfs:jfs_flush_journal+0x21f/0x232
Feb  8 16:46:41 debian kernel: [ 6809.853874]  [<ffffffff802777eb>] do_writepages+0x20/0x2d
Feb  8 16:46:41 debian kernel: [ 6809.853881]  [<ffffffffa02f9831>] :jfs:lmLogShutdown+0x15/0xed
Feb  8 16:46:41 debian kernel: [ 6809.853884]  [<ffffffff80271b96>] filemap_write_and_wait+0x26/0x31
Feb  8 16:46:41 debian kernel: [ 6809.853891]  [<ffffffffa02fa196>] :jfs:lmLogClose+0x81/0x111
Feb  8 16:46:41 debian kernel: [ 6809.853897]  [<ffffffffa02e37e0>] :jfs:jfs_put_super+0xd/0x5e
Feb  8 16:46:41 debian kernel: [ 6809.853900]  [<ffffffff8029cd91>] generic_shutdown_super+0x60/0xee
Feb  8 16:46:41 debian kernel: [ 6809.853902]  [<ffffffff8029ce2c>] kill_block_super+0xd/0x1e
Feb  8 16:46:41 debian kernel: [ 6809.853904]  [<ffffffff8029cee8>] deactivate_super+0x5f/0x78
Feb  8 16:46:41 debian kernel: [ 6809.853907]  [<ffffffff802b02fc>] sys_umount+0x2f9/0x353
Feb  8 16:46:41 debian kernel: [ 6809.853911]  [<ffffffff80221fbc>] do_page_fault+0x5d8/0x9c8
Feb  8 16:46:41 debian kernel: [ 6809.853913]  [<ffffffff8029e4c8>] sys_newstat+0x19/0x31
Feb  8 16:46:41 debian kernel: [ 6809.853917]  [<ffffffff8031e473>] __up_write+0x21/0x10e
Feb  8 16:46:41 debian kernel: [ 6809.853921]  [<ffffffff8020beda>] system_call_after_swapgs+0x8a/0x8f
Feb  8 16:46:41 debian kernel: [ 6809.853924] 
Feb  8 16:46:41 debian kernel: [ 6809.853926] ---[ end trace 61e4a222d7f55144 ]---

As always, let me know if there is anything else I could provide to help debug these issues.

Thanks,
Tim

On Feb 7, 2011, at 8:07 PM, Dave Kleikamp wrote:

On Sun, 2011-02-06 at 23:28 -0800, Tim Nufire wrote:
Hello,


Corrupt JFS root nodes continue to plague my Debian 5 based servers
running 2.6.26 and 2.6.32 kernels... This is a big problem for us so I
spent last week learning enough about JFS to create a test script
which reproduces the problems -- I'm hoping this is enough for the
folks on this list to fix the bug :-) I've emailed this list about
this problem before.. For the old thread, see: 


Thanks for taking the time to create the test case.  It made it easy for
me to track down this problem.  There is really nothing wrong with the
directory.  The problem is in jfs_fsck.

The attached patch fixes jfs_fsck.  It should no longer complain about
this directory or attempt to "repair" the filesystem by deleting the
directory.  cvs is currently down on Sourceforge, but I'll try to get an
official fix out soon.

Thanks for your patience and help tracking down the bug!

Shaggy

-- 
Dave Kleikamp
IBM Linux Technology Center
<directory_size.patch>