hfsplus corruption, failed fsck, journalling and zero'ing extent record on delete

hfsplus corruption, failed fsck, journalling and zero'ing extent record on delete

[Hin-Tak Leung]

Hi Vyacheslav,

I mentioned briefly some days ago that I managed to corrupt an HFS+ paritition while experimenting with the journalling code, to the extent that fsck_hfs/fsck.hfsplus (Apple's diskdev_cmds tool) refuses to fix. And that partition, with the unmodified module used ready-only can get the kernel to BUG() "reliably" by just doing "du" on it (and I was thinking whether BUG()'ing on corrupted disk is a bug to file...).

With a lot of reading-up, and some C, some python, in the end, some dd if=/of= and a hex editor with a calculator, I managed to get fsck to go successfully again. So now I have some idea of how to stress HFS+ for fsck to refuse to fix. The recipe is something like this:

- a disk with a lot of small files and quite full. (I have a 105 GB partition, 75% full, 600,000 leaf records in the catalog btree, or 400,000 inodes depends on how you count... untar'ing a few kernel trees under it should do)

- try to delete the small files one by one very quickly. (I did essentially 
    cat list | perl -ne 'chomp; if (-f $_) {unlink $_;}' 
, after comparing the netgear code with stock kernel's and generating an "uninteresting" file list).

- probably SMP system + reasonably amount of memory for disk cache (dual core + 2GB RAM).

Under that combination of conditions, it may be possible to stress HFS+ in a way such that:

1. the Catalog B-Tree needs to be substantially re-written/re-located, rather than being updated in-place. i.e. a large number of changes of leaf-records in a short time.

2. the re-written/re-located part of the Catalog B-Tree needs to re-use the extents which are recently "vacated" by the deletion. i.e. need a fairly full disk to see this.

It seems that when files are deleted, leaf records are made only *partially* invalid, and a partially up-to-date new Catalog B-Tree is written, and then further updates happen in-place to bring to whole thing consistent (the extent bitmap & volume headers, etc) ... but in my case, for whatever reason, things was interrupted in the middle.

So I had a new Catalog B-Tree sitting on the overlapping extents as partially deleted file records. fsck thinks the files need to be "undeleted", but cannot read the B-Tree without error on those partially invalid leaf records, and cannot fix either of them.

I pieced together the Catalog B-Tree (in 3 fragments - actually it was 4 to begin with, fsck in rebuild-Catalog mode gives me a new one which is "differently" broken - i.e. overlap with another set of ~140 partially deleted records), found all the overlaping leaf records - ~140 of them in 17 leaf nodes , used a hex editor to zero'ed the extents and file sizes by hand, and voila, fsck was a lot happier afterwards.

- the linux hfsplus driver probably *should* zero' the corresponding extent descriptor in the leaf record when a file is deleted?
I seem to remember years ago between ext2 and ext3, one notable/advertised difference of ext3 is that ext3 zero's inodes on delete (and make it difficult for low-level data recovery) - and there was a reason for it... I should read that up... disk formatting & file deleting under Mac OS X seems to take much longer, compared to under linux - do they zero' records *fully* on format/delete?

- whether this possibility of corruption is related to the experimental journalling code - it does work correctly under light use - i.e. fsck is fully happy after unmount.

- HFS+ is probably one of the rare minority of file systems where critical parts of it, the Catalog B-Tree, (and the other 3-4(?) B-Tree), are regular files and subjected to the same fragmentation and competition from normal file usage?! (instead of being in "dedicated" allocated areas, and also having multiple copies).

- oh, one last thing: there was one later version of the journalling code from netgear, which copied a lot of files from ext3 (the jbd part). Maybe they know about HFS+ needing a kernel demon to do more regular sync to disk than others...

More experiments... fixing things which fsck cannot, makes experimenting easier...

Hin-Tak

hfsplus BUG: Bad page state in process du pfn:07759 (Re: hfsplus corruption, failed fsck, journalling and zero'ing extent record on delete)

[Hin-Tak Leung]

Argh, the BUG() seems to be a genuine bug - running du on the recently "fsck.hfsplus -f" clean disk, mounting read-only with unmod'ed distro hfsplus driver: (see, "not Tainted"...)

=================
[103022.493765] hfs: write access to a journaled filesystem is not supported, use the force option at your own risk, mounting read-only.
[103022.536649] SELinux: initialized (dev sdb5, type hfsplus), uses genfs_contexts
[111015.478171] BUG: Bad page state in process du  pfn:07759
[111015.478182] page:ffffea00001dd640 count:0 mapcount:0 mapping:          (null) index:0x1935
[111015.478185] page flags: 0x20000000000004(referenced)
[111015.478189] Modules linked in: usb_storage tcp_lp nls_utf8 hfsplus fuse ip6table_filter ip6_tables ebtable_nat ebtables ipt_MASQUERADE 
iptable_nat nf_nat xt_CHECKSUM iptable_mangle bridge stp llc xt_LOG xt_physdev nf_conntrack_ipv4 nf_defrag_ipv4 xt_state nf_conntrack arc4 
rtl8187 eeprom_93cx6 mac80211 cfg80211 snd_hda_codec_realtek joydev vhost_net tun macvtap macvlan kvm_amd kvm edac_core edac_mce_amd k8temp
 r592 memstick sp5100_tco snd_hda_intel snd_hda_codec snd_hwdep snd_pcm snd_page_alloc snd_timer snd soundcore i2c_piix4 r8169 mii shpchp t
oshiba_acpi sparse_keymap rfkill wmi ecryptfs sha256_generic encrypted_keys nfsd nfs_acl auth_rpcgss lockd sunrpc uinput binfmt_misc truste
d tpm tpm_bios ata_generic pata_acpi firewire_ohci sdhci_pci sdhci firewire_core crc_itu_t mmc_core pata_atiixp video radeon i2c_algo_bit d
rm_kms_helper ttm drm i2c_core [last unloaded: scsi_wait_scan]
[111015.478274] Pid: 23364, comm: du Not tainted 3.5.4-1.fc17.x86_64 #1
[111015.478277] Call Trace:
[111015.478291]  [<ffffffff81604213>] bad_page+0xe6/0xfb
[111015.478299]  [<ffffffff8112dd8e>] get_page_from_freelist+0x77e/0x940
[111015.478305]  [<ffffffff8112e0fd>] __alloc_pages_nodemask+0x1ad/0x970
[111015.478318]  [<ffffffffa05e5719>] ? hfsplus_bnode_read+0x89/0x100 [hfsplus]
[111015.478324]  [<ffffffffa05e5775>] ? hfsplus_bnode_read+0xe5/0x100 [hfsplus]
[111015.478329]  [<ffffffff811699e0>] alloc_pages_current+0xb0/0x120
[111015.478334]  [<ffffffff811721b8>] new_slab+0x268/0x320
[111015.478339]  [<ffffffff8160546e>] __slab_alloc+0x36e/0x4c8
[111015.478344]  [<ffffffffa05df11a>] ? hfsplus_alloc_inode+0x1a/0x40 [hfsplus]
[111015.478349]  [<ffffffffa05df11a>] ? hfsplus_alloc_inode+0x1a/0x40 [hfsplus]
[111015.478354]  [<ffffffff811733f8>] kmem_cache_alloc+0x108/0x160
[111015.478359]  [<ffffffffa05e7d40>] ? __hplusfs_brec_find+0xa0/0x180 [hfsplus]
[111015.478364]  [<ffffffffa05df11a>] hfsplus_alloc_inode+0x1a/0x40 [hfsplus]
[111015.478371]  [<ffffffff811a0606>] alloc_inode+0x26/0xa0
[111015.478375]  [<ffffffff811a1c78>] iget_locked+0xb8/0x190
[111015.478380]  [<ffffffffa05df715>] hfsplus_iget+0x15/0x230 [hfsplus]
[111015.478386]  [<ffffffffa05e7c8f>] ? hfsplus_find_exit+0x2f/0x40 [hfsplus]
[111015.478391]  [<ffffffffa05e467f>] hfsplus_lookup+0x20f/0x2d0 [hfsplus]
[111015.478397]  [<ffffffff8119ed84>] ? __d_alloc+0x34/0x180
[111015.478402]  [<ffffffffa05d701a>] ? char2uni+0x1a/0x50 [nls_utf8]
[111015.478406]  [<ffffffff81173321>] ? kmem_cache_alloc+0x31/0x160
[111015.478410]  [<ffffffff8119ed84>] ? __d_alloc+0x34/0x180
[111015.478413]  [<ffffffff8119ee9c>] ? __d_alloc+0x14c/0x180
[111015.478419]  [<ffffffff811928e1>] __lookup_hash+0x61/0x120
[111015.478423]  [<ffffffff81194b49>] ? lookup_fast+0x219/0x310
[111015.478427]  [<ffffffff81605959>] lookup_slow+0x47/0xab
[111015.478431]  [<ffffffff81196ac6>] path_lookupat+0x716/0x750
[111015.478436]  [<ffffffff81173321>] ? kmem_cache_alloc+0x31/0x160
[111015.478440]  [<ffffffff81196b31>] do_path_lookup+0x31/0xc0
[111015.478444]  [<ffffffff81192b33>] ? getname_flags+0x53/0xf0
[111015.478448]  [<ffffffff8119787d>] user_path_at_empty+0x5d/0xa0
[111015.478454]  [<ffffffff8127973a>] ? inode_has_perm.isra.31.constprop.61+0x2a/0x30
[111015.478459]  [<ffffffff8127d835>] ? selinux_inode_getattr+0x45/0x50
[111015.478464]  [<ffffffff8118c910>] ? cp_new_stat+0x120/0x140
[111015.478468]  [<ffffffff811978d1>] user_path_at+0x11/0x20
[111015.478472]  [<ffffffff8118cba5>] vfs_fstatat+0x35/0x70
[111015.478475]  [<ffffffff8118ceaa>] sys_newfstatat+0x1a/0x40
[111015.478482]  [<ffffffff81614e29>] system_call_fastpath+0x16/0x1b
[111015.478485] Disabling lock debugging due to kernel taint
============================

--- On Mon, 24/9/12, Hin-Tak Leung <htl10@users.sourceforge.net> wrote:

<snipped>
> I mentioned briefly some days ago that I managed to corrupt
> an HFS+ paritition while experimenting with the journalling
> code, to the extent that fsck_hfs/fsck.hfsplus (Apple's
> diskdev_cmds tool) refuses to fix. And that partition, with
> the unmodified module used ready-only can get the kernel to
> BUG() "reliably" by just doing "du" on it (and I was
> thinking whether BUG()'ing on corrupted disk is a bug to
> file...).

Re: hfsplus BUG: Bad page state in process du pfn:07759 (Re: hfsplus corruption, failed fsck, journalling and zero'ing extent record on delete)

[Vyacheslav Dubeyko]

Hi Hin-Tak,

Could you describe the way of issue reproduction in more details?

I need to know:
1. What kernel version do you use?
2. Do you have some special configuration of the system ([103022.536649]
SELinux: initialized (dev sdb5, type hfsplus), uses genfs_contexts)?
3. How did you generate small files? How small is it (I mean size)?

Sorry, but currently I haven't clear understanding how to reproduce this
issue from your description.

With the best regards,
Vyacheslav Dubeyko.

On Mon, 2012-09-24 at 08:30 +0100, Hin-Tak Leung wrote:
> Argh, the BUG() seems to be a genuine bug - running du on the recently "fsck.hfsplus -f" clean disk, mounting read-only with unmod'ed distro hfsplus driver: (see, "not Tainted"...)
> 
> =================
> [103022.493765] hfs: write access to a journaled filesystem is not supported, use the force option at your own risk, mounting read-only.
> [103022.536649] SELinux: initialized (dev sdb5, type hfsplus), uses genfs_contexts
> [111015.478171] BUG: Bad page state in process du  pfn:07759
> [111015.478182] page:ffffea00001dd640 count:0 mapcount:0 mapping:          (null) index:0x1935
> [111015.478185] page flags: 0x20000000000004(referenced)
> [111015.478189] Modules linked in: usb_storage tcp_lp nls_utf8 hfsplus fuse ip6table_filter ip6_tables ebtable_nat ebtables ipt_MASQUERADE 
> iptable_nat nf_nat xt_CHECKSUM iptable_mangle bridge stp llc xt_LOG xt_physdev nf_conntrack_ipv4 nf_defrag_ipv4 xt_state nf_conntrack arc4 
> rtl8187 eeprom_93cx6 mac80211 cfg80211 snd_hda_codec_realtek joydev vhost_net tun macvtap macvlan kvm_amd kvm edac_core edac_mce_amd k8temp
>  r592 memstick sp5100_tco snd_hda_intel snd_hda_codec snd_hwdep snd_pcm snd_page_alloc snd_timer snd soundcore i2c_piix4 r8169 mii shpchp t
> oshiba_acpi sparse_keymap rfkill wmi ecryptfs sha256_generic encrypted_keys nfsd nfs_acl auth_rpcgss lockd sunrpc uinput binfmt_misc truste
> d tpm tpm_bios ata_generic pata_acpi firewire_ohci sdhci_pci sdhci firewire_core crc_itu_t mmc_core pata_atiixp video radeon i2c_algo_bit d
> rm_kms_helper ttm drm i2c_core [last unloaded: scsi_wait_scan]
> [111015.478274] Pid: 23364, comm: du Not tainted 3.5.4-1.fc17.x86_64 #1
> [111015.478277] Call Trace:
> [111015.478291]  [<ffffffff81604213>] bad_page+0xe6/0xfb
> [111015.478299]  [<ffffffff8112dd8e>] get_page_from_freelist+0x77e/0x940
> [111015.478305]  [<ffffffff8112e0fd>] __alloc_pages_nodemask+0x1ad/0x970
> [111015.478318]  [<ffffffffa05e5719>] ? hfsplus_bnode_read+0x89/0x100 [hfsplus]
> [111015.478324]  [<ffffffffa05e5775>] ? hfsplus_bnode_read+0xe5/0x100 [hfsplus]
> [111015.478329]  [<ffffffff811699e0>] alloc_pages_current+0xb0/0x120
> [111015.478334]  [<ffffffff811721b8>] new_slab+0x268/0x320
> [111015.478339]  [<ffffffff8160546e>] __slab_alloc+0x36e/0x4c8
> [111015.478344]  [<ffffffffa05df11a>] ? hfsplus_alloc_inode+0x1a/0x40 [hfsplus]
> [111015.478349]  [<ffffffffa05df11a>] ? hfsplus_alloc_inode+0x1a/0x40 [hfsplus]
> [111015.478354]  [<ffffffff811733f8>] kmem_cache_alloc+0x108/0x160
> [111015.478359]  [<ffffffffa05e7d40>] ? __hplusfs_brec_find+0xa0/0x180 [hfsplus]
> [111015.478364]  [<ffffffffa05df11a>] hfsplus_alloc_inode+0x1a/0x40 [hfsplus]
> [111015.478371]  [<ffffffff811a0606>] alloc_inode+0x26/0xa0
> [111015.478375]  [<ffffffff811a1c78>] iget_locked+0xb8/0x190
> [111015.478380]  [<ffffffffa05df715>] hfsplus_iget+0x15/0x230 [hfsplus]
> [111015.478386]  [<ffffffffa05e7c8f>] ? hfsplus_find_exit+0x2f/0x40 [hfsplus]
> [111015.478391]  [<ffffffffa05e467f>] hfsplus_lookup+0x20f/0x2d0 [hfsplus]
> [111015.478397]  [<ffffffff8119ed84>] ? __d_alloc+0x34/0x180
> [111015.478402]  [<ffffffffa05d701a>] ? char2uni+0x1a/0x50 [nls_utf8]
> [111015.478406]  [<ffffffff81173321>] ? kmem_cache_alloc+0x31/0x160
> [111015.478410]  [<ffffffff8119ed84>] ? __d_alloc+0x34/0x180
> [111015.478413]  [<ffffffff8119ee9c>] ? __d_alloc+0x14c/0x180
> [111015.478419]  [<ffffffff811928e1>] __lookup_hash+0x61/0x120
> [111015.478423]  [<ffffffff81194b49>] ? lookup_fast+0x219/0x310
> [111015.478427]  [<ffffffff81605959>] lookup_slow+0x47/0xab
> [111015.478431]  [<ffffffff81196ac6>] path_lookupat+0x716/0x750
> [111015.478436]  [<ffffffff81173321>] ? kmem_cache_alloc+0x31/0x160
> [111015.478440]  [<ffffffff81196b31>] do_path_lookup+0x31/0xc0
> [111015.478444]  [<ffffffff81192b33>] ? getname_flags+0x53/0xf0
> [111015.478448]  [<ffffffff8119787d>] user_path_at_empty+0x5d/0xa0
> [111015.478454]  [<ffffffff8127973a>] ? inode_has_perm.isra.31.constprop.61+0x2a/0x30
> [111015.478459]  [<ffffffff8127d835>] ? selinux_inode_getattr+0x45/0x50
> [111015.478464]  [<ffffffff8118c910>] ? cp_new_stat+0x120/0x140
> [111015.478468]  [<ffffffff811978d1>] user_path_at+0x11/0x20
> [111015.478472]  [<ffffffff8118cba5>] vfs_fstatat+0x35/0x70
> [111015.478475]  [<ffffffff8118ceaa>] sys_newfstatat+0x1a/0x40
> [111015.478482]  [<ffffffff81614e29>] system_call_fastpath+0x16/0x1b
> [111015.478485] Disabling lock debugging due to kernel taint
> ============================
> 
> --- On Mon, 24/9/12, Hin-Tak Leung <htl10@users.sourceforge.net> wrote:
> 
> <snipped>
> > I mentioned briefly some days ago that I managed to corrupt
> > an HFS+ paritition while experimenting with the journalling
> > code, to the extent that fsck_hfs/fsck.hfsplus (Apple's
> > diskdev_cmds tool) refuses to fix. And that partition, with
> > the unmodified module used ready-only can get the kernel to
> > BUG() "reliably" by just doing "du" on it (and I was
> > thinking whether BUG()'ing on corrupted disk is a bug to
> > file...).
> 
> 
> --
> To unsubscribe from this list: send the line "unsubscribe linux-fsdevel" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: hfsplus BUG: Bad page state in process du pfn:07759 (Re: hfsplus corruption, failed fsck, journalling and zero'ing extent record on delete)

[Hin-Tak Leung]

Hi Vyacheslav,

1. Up-to-date fedora, 3.5.4-1.fc17.x86_64, unmodified.
2. The genfs_contexts message you comes from selinux. It always happens after mounting removable storage media of any fs type (fat, ntfs, ext4 - I have a few USB drives). The hardware is a 160 GB SATA 2.5 hard disc in an external USB enclosure. 
3. The directory I can regularly get this sort of messages is a folder containing all 6 of ftp://downloads.netgear.com/files/GPL/WNDRMAC*tar.bz2.zip - 
(netgear's source code for their HFS+-capable network storage appliances), unzip'ed themselves, as well as the further un-tar.bz2 contents. So it have 6 expanded kernel trees as well as the source codes/git repositories of samba, etc other software that constitutes the product. 

There is possibly one important detail - 103022 to 111015 is 7000 seconds, or almost two hours. Between mounting (read-only, the default for journalled HFS+), I was doing something else. I think it tends to happen when I leave the drive connected but don't do anything on it for some time, and the message seems to be about some of the file system's structure being paged out? It is just running "du" on one terminal while doing dmesg on another.

This is the first time I see this on a completely fsck-clean fs. (fsck.hfsplus -f a few times). It had a somewhat complicated history. Previously it was created as hfs+ case-sensitive journalled, and written to with the experimental journalling code, and it went corrupted after some read/write experiments with quick-deletes some weeks ago. I learned enough about hfs+, found the fragments and the sectors of the catalog b-tree, dd them out, hacked them with a hex-editor and dd them back in, to help fsck a bit... and then fsck a few times and passed, before mounting. I have seen this sort of messages quite a few times, but so far I have dismissed them since any bad messages are expected mounting corrupted fs (read-only), and the fs was corrupted until yesterday. (the drive also have two ntfs partitions, and I use them fairly regularly, so udev/etc automount the hfs+ one read-only often, and I looked around often enough).

I can probably go back and see the earlier BUG messages, to see how long between mounting and du/BUG() - I think every time I see it the drive has been idling for some time. I have collected a few such messages (but as I said, any scary messages are expected for corrupted fs; this latest one is on a clean one though which has have "fsck -f" a few times recently before mounting).

Regards,
Hin-Tak

--- On Mon, 24/9/12, Vyacheslav Dubeyko <slava@dubeyko.com> wrote:

> Hi Hin-Tak,
> 
> Could you describe the way of issue reproduction in more
> details?
> 
> I need to know:
> 1. What kernel version do you use?
> 2. Do you have some special configuration of the system
> ([103022.536649]
> SELinux: initialized (dev sdb5, type hfsplus), uses
> genfs_contexts)?
> 3. How did you generate small files? How small is it (I mean
> size)?
> 
> Sorry, but currently I haven't clear understanding how to
> reproduce this
> issue from your description.
> 
> With the best regards,
> Vyacheslav Dubeyko.
> 
> On Mon, 2012-09-24 at 08:30 +0100, Hin-Tak Leung wrote:
> > Argh, the BUG() seems to be a genuine bug - running du
> on the recently "fsck.hfsplus -f" clean disk, mounting
> read-only with unmod'ed distro hfsplus driver: (see, "not
> Tainted"...)
> > 
> > =================
> > [103022.493765] hfs: write access to a journaled
> filesystem is not supported, use the force option at your
> own risk, mounting read-only.
> > [103022.536649] SELinux: initialized (dev sdb5, type
> hfsplus), uses genfs_contexts
> > [111015.478171] BUG: Bad page state in process du 
> pfn:07759
> > [111015.478182] page:ffffea00001dd640 count:0
> mapcount:0 mapping:          (null)
> index:0x1935
> > [111015.478185] page flags:
> 0x20000000000004(referenced)
> > [111015.478189] Modules linked in: usb_storage tcp_lp
> nls_utf8 hfsplus fuse ip6table_filter ip6_tables ebtable_nat
> ebtables ipt_MASQUERADE 
> > iptable_nat nf_nat xt_CHECKSUM iptable_mangle bridge
> stp llc xt_LOG xt_physdev nf_conntrack_ipv4 nf_defrag_ipv4
> xt_state nf_conntrack arc4 
> > rtl8187 eeprom_93cx6 mac80211 cfg80211
> snd_hda_codec_realtek joydev vhost_net tun macvtap macvlan
> kvm_amd kvm edac_core edac_mce_amd k8temp
> >  r592 memstick sp5100_tco snd_hda_intel
> snd_hda_codec snd_hwdep snd_pcm snd_page_alloc snd_timer snd
> soundcore i2c_piix4 r8169 mii shpchp t
> > oshiba_acpi sparse_keymap rfkill wmi ecryptfs
> sha256_generic encrypted_keys nfsd nfs_acl auth_rpcgss lockd
> sunrpc uinput binfmt_misc truste
> > d tpm tpm_bios ata_generic pata_acpi firewire_ohci
> sdhci_pci sdhci firewire_core crc_itu_t mmc_core pata_atiixp
> video radeon i2c_algo_bit d
> > rm_kms_helper ttm drm i2c_core [last unloaded:
> scsi_wait_scan]
> > [111015.478274] Pid: 23364, comm: du Not tainted
> 3.5.4-1.fc17.x86_64 #1
> > [111015.478277] Call Trace:
> > [111015.478291]  [<ffffffff81604213>]
> bad_page+0xe6/0xfb
> > [111015.478299]  [<ffffffff8112dd8e>]
> get_page_from_freelist+0x77e/0x940
> > [111015.478305]  [<ffffffff8112e0fd>]
> __alloc_pages_nodemask+0x1ad/0x970
> > [111015.478318]  [<ffffffffa05e5719>] ?
> hfsplus_bnode_read+0x89/0x100 [hfsplus]
> > [111015.478324]  [<ffffffffa05e5775>] ?
> hfsplus_bnode_read+0xe5/0x100 [hfsplus]
> > [111015.478329]  [<ffffffff811699e0>]
> alloc_pages_current+0xb0/0x120
> > [111015.478334]  [<ffffffff811721b8>]
> new_slab+0x268/0x320
> > [111015.478339]  [<ffffffff8160546e>]
> __slab_alloc+0x36e/0x4c8
> > [111015.478344]  [<ffffffffa05df11a>] ?
> hfsplus_alloc_inode+0x1a/0x40 [hfsplus]
> > [111015.478349]  [<ffffffffa05df11a>] ?
> hfsplus_alloc_inode+0x1a/0x40 [hfsplus]
> > [111015.478354]  [<ffffffff811733f8>]
> kmem_cache_alloc+0x108/0x160
> > [111015.478359]  [<ffffffffa05e7d40>] ?
> __hplusfs_brec_find+0xa0/0x180 [hfsplus]
> > [111015.478364]  [<ffffffffa05df11a>]
> hfsplus_alloc_inode+0x1a/0x40 [hfsplus]
> > [111015.478371]  [<ffffffff811a0606>]
> alloc_inode+0x26/0xa0
> > [111015.478375]  [<ffffffff811a1c78>]
> iget_locked+0xb8/0x190
> > [111015.478380]  [<ffffffffa05df715>]
> hfsplus_iget+0x15/0x230 [hfsplus]
> > [111015.478386]  [<ffffffffa05e7c8f>] ?
> hfsplus_find_exit+0x2f/0x40 [hfsplus]
> > [111015.478391]  [<ffffffffa05e467f>]
> hfsplus_lookup+0x20f/0x2d0 [hfsplus]
> > [111015.478397]  [<ffffffff8119ed84>] ?
> __d_alloc+0x34/0x180
> > [111015.478402]  [<ffffffffa05d701a>] ?
> char2uni+0x1a/0x50 [nls_utf8]
> > [111015.478406]  [<ffffffff81173321>] ?
> kmem_cache_alloc+0x31/0x160
> > [111015.478410]  [<ffffffff8119ed84>] ?
> __d_alloc+0x34/0x180
> > [111015.478413]  [<ffffffff8119ee9c>] ?
> __d_alloc+0x14c/0x180
> > [111015.478419]  [<ffffffff811928e1>]
> __lookup_hash+0x61/0x120
> > [111015.478423]  [<ffffffff81194b49>] ?
> lookup_fast+0x219/0x310
> > [111015.478427]  [<ffffffff81605959>]
> lookup_slow+0x47/0xab
> > [111015.478431]  [<ffffffff81196ac6>]
> path_lookupat+0x716/0x750
> > [111015.478436]  [<ffffffff81173321>] ?
> kmem_cache_alloc+0x31/0x160
> > [111015.478440]  [<ffffffff81196b31>]
> do_path_lookup+0x31/0xc0
> > [111015.478444]  [<ffffffff81192b33>] ?
> getname_flags+0x53/0xf0
> > [111015.478448]  [<ffffffff8119787d>]
> user_path_at_empty+0x5d/0xa0
> > [111015.478454]  [<ffffffff8127973a>] ?
> inode_has_perm.isra.31.constprop.61+0x2a/0x30
> > [111015.478459]  [<ffffffff8127d835>] ?
> selinux_inode_getattr+0x45/0x50
> > [111015.478464]  [<ffffffff8118c910>] ?
> cp_new_stat+0x120/0x140
> > [111015.478468]  [<ffffffff811978d1>]
> user_path_at+0x11/0x20
> > [111015.478472]  [<ffffffff8118cba5>]
> vfs_fstatat+0x35/0x70
> > [111015.478475]  [<ffffffff8118ceaa>]
> sys_newfstatat+0x1a/0x40
> > [111015.478482]  [<ffffffff81614e29>]
> system_call_fastpath+0x16/0x1b
> > [111015.478485] Disabling lock debugging due to kernel
> taint
> > ============================
> > 
> > --- On Mon, 24/9/12, Hin-Tak Leung <htl10@users.sourceforge.net>
> wrote:
> > 
> > <snipped>
> > > I mentioned briefly some days ago that I managed
> to corrupt
> > > an HFS+ paritition while experimenting with the
> journalling
> > > code, to the extent that fsck_hfs/fsck.hfsplus
> (Apple's
> > > diskdev_cmds tool) refuses to fix. And that
> partition, with
> > > the unmodified module used ready-only can get the
> kernel to
> > > BUG() "reliably" by just doing "du" on it (and I
> was
> > > thinking whether BUG()'ing on corrupted disk is a
> bug to
> > > file...).
> > 
> > 
> > --
> > To unsubscribe from this list: send the line
> "unsubscribe linux-fsdevel" in
> > the body of a message to majordomo@vger.kernel.org
> > More majordomo info at  http://vger.kernel.org/majordomo-info.html
> 
> 
> 
--
To unsubscribe from this list: send the line "unsubscribe linux-fsdevel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: hfsplus BUG: Bad page state in process du pfn:07759 (Re: hfsplus corruption, failed fsck, journalling and zero'ing extent record on delete)

[Vyacheslav Dubeyko]

Hi Hin-Tak,

On Sep 24, 2012, at 9:43 PM, Hin-Tak Leung wrote:

> Hi Vyacheslav,
> 
> 1. Up-to-date fedora, 3.5.4-1.fc17.x86_64, unmodified.
> 2. The genfs_contexts message you comes from selinux. It always happens after mounting removable storage media of any fs type (fat, ntfs, ext4 - I have a few USB drives). The hardware is a 160 GB SATA 2.5 hard disc in an external USB enclosure. 
> 3. The directory I can regularly get this sort of messages is a folder containing all 6 of ftp://downloads.netgear.com/files/GPL/WNDRMAC*tar.bz2.zip - 
> (netgear's source code for their HFS+-capable network storage appliances), unzip'ed themselves, as well as the further un-tar.bz2 contents. So it have 6 expanded kernel trees as well as the source codes/git repositories of samba, etc other software that constitutes the product. 
> 

So, you use journaled HFS+ partition when the issue takes place. Am I correct?

> There is possibly one important detail - 103022 to 111015 is 7000 seconds, or almost two hours. Between mounting (read-only, the default for journalled HFS+), I was doing something else. I think it tends to happen when I leave the drive connected but don't do anything on it for some time, and the message seems to be about some of the file system's structure being paged out? It is just running "du" on one terminal while doing dmesg on another.
> 
> This is the first time I see this on a completely fsck-clean fs. (fsck.hfsplus -f a few times). It had a somewhat complicated history. Previously it was created as hfs+ case-sensitive journalled, and written to with the experimental journalling code, and it went corrupted after some read/write experiments with quick-deletes some weeks ago. I learned enough about hfs+, found the fragments and the sectors of the catalog b-tree, dd them out, hacked them with a hex-editor and dd them back in, to help fsck a bit... and then fsck a few times and passed, before mounting. I have seen this sort of messages quite a few times, but so far I have dismissed them since any bad messages are expected mounting corrupted fs (read-only), and the fs was corrupted until yesterday. (the drive also have two ntf
 s partitions, and I use them fairly regularly, so udev/etc automount the hfs+ one read-only often, and I looked around often enough).
> 

As I can understand:
1. You had corrupted journaled HFS+ partition.
2. You modify metadata by hand.
3. Then you check this partition by fsck.hfsplus. And fsck.hfsplus ends checking without any error message.
4. But it takes place BUG message after trying to mount this partition.

Am I correct in this description?

With the best regards,
Vyacheslav Dubeyko.

> I can probably go back and see the earlier BUG messages, to see how long between mounting and du/BUG() - I think every time I see it the drive has been idling for some time. I have collected a few such messages (but as I said, any scary messages are expected for corrupted fs; this latest one is on a clean one though which has have "fsck -f" a few times recently before mounting).
> 
> Regards,
> Hin-Tak
> 
> --- On Mon, 24/9/12, Vyacheslav Dubeyko <slava@dubeyko.com> wrote:
> 
>> Hi Hin-Tak,
>> 
>> Could you describe the way of issue reproduction in more
>> details?
>> 
>> I need to know:
>> 1. What kernel version do you use?
>> 2. Do you have some special configuration of the system
>> ([103022.536649]
>> SELinux: initialized (dev sdb5, type hfsplus), uses
>> genfs_contexts)?
>> 3. How did you generate small files? How small is it (I mean
>> size)?
>> 
>> Sorry, but currently I haven't clear understanding how to
>> reproduce this
>> issue from your description.
>> 
>> With the best regards,
>> Vyacheslav Dubeyko.
>> 
>> On Mon, 2012-09-24 at 08:30 +0100, Hin-Tak Leung wrote:
>>> Argh, the BUG() seems to be a genuine bug - running du
>> on the recently "fsck.hfsplus -f" clean disk, mounting
>> read-only with unmod'ed distro hfsplus driver: (see, "not
>> Tainted"...)
>>> 
>>> =================
>>> [103022.493765] hfs: write access to a journaled
>> filesystem is not supported, use the force option at your
>> own risk, mounting read-only.
>>> [103022.536649] SELinux: initialized (dev sdb5, type
>> hfsplus), uses genfs_contexts
>>> [111015.478171] BUG: Bad page state in process du 
>> pfn:07759
>>> [111015.478182] page:ffffea00001dd640 count:0
>> mapcount:0 mapping:          (null)
>> index:0x1935
>>> [111015.478185] page flags:
>> 0x20000000000004(referenced)
>>> [111015.478189] Modules linked in: usb_storage tcp_lp
>> nls_utf8 hfsplus fuse ip6table_filter ip6_tables ebtable_nat
>> ebtables ipt_MASQUERADE 
>>> iptable_nat nf_nat xt_CHECKSUM iptable_mangle bridge
>> stp llc xt_LOG xt_physdev nf_conntrack_ipv4 nf_defrag_ipv4
>> xt_state nf_conntrack arc4 
>>> rtl8187 eeprom_93cx6 mac80211 cfg80211
>> snd_hda_codec_realtek joydev vhost_net tun macvtap macvlan
>> kvm_amd kvm edac_core edac_mce_amd k8temp
>>>   r592 memstick sp5100_tco snd_hda_intel
>> snd_hda_codec snd_hwdep snd_pcm snd_page_alloc snd_timer snd
>> soundcore i2c_piix4 r8169 mii shpchp t
>>> oshiba_acpi sparse_keymap rfkill wmi ecryptfs
>> sha256_generic encrypted_keys nfsd nfs_acl auth_rpcgss lockd
>> sunrpc uinput binfmt_misc truste
>>> d tpm tpm_bios ata_generic pata_acpi firewire_ohci
>> sdhci_pci sdhci firewire_core crc_itu_t mmc_core pata_atiixp
>> video radeon i2c_algo_bit d
>>> rm_kms_helper ttm drm i2c_core [last unloaded:
>> scsi_wait_scan]
>>> [111015.478274] Pid: 23364, comm: du Not tainted
>> 3.5.4-1.fc17.x86_64 #1
>>> [111015.478277] Call Trace:
>>> [111015.478291]  [<ffffffff81604213>]
>> bad_page+0xe6/0xfb
>>> [111015.478299]  [<ffffffff8112dd8e>]
>> get_page_from_freelist+0x77e/0x940
>>> [111015.478305]  [<ffffffff8112e0fd>]
>> __alloc_pages_nodemask+0x1ad/0x970
>>> [111015.478318]  [<ffffffffa05e5719>] ?
>> hfsplus_bnode_read+0x89/0x100 [hfsplus]
>>> [111015.478324]  [<ffffffffa05e5775>] ?
>> hfsplus_bnode_read+0xe5/0x100 [hfsplus]
>>> [111015.478329]  [<ffffffff811699e0>]
>> alloc_pages_current+0xb0/0x120
>>> [111015.478334]  [<ffffffff811721b8>]
>> new_slab+0x268/0x320
>>> [111015.478339]  [<ffffffff8160546e>]
>> __slab_alloc+0x36e/0x4c8
>>> [111015.478344]  [<ffffffffa05df11a>] ?
>> hfsplus_alloc_inode+0x1a/0x40 [hfsplus]
>>> [111015.478349]  [<ffffffffa05df11a>] ?
>> hfsplus_alloc_inode+0x1a/0x40 [hfsplus]
>>> [111015.478354]  [<ffffffff811733f8>]
>> kmem_cache_alloc+0x108/0x160
>>> [111015.478359]  [<ffffffffa05e7d40>] ?
>> __hplusfs_brec_find+0xa0/0x180 [hfsplus]
>>> [111015.478364]  [<ffffffffa05df11a>]
>> hfsplus_alloc_inode+0x1a/0x40 [hfsplus]
>>> [111015.478371]  [<ffffffff811a0606>]
>> alloc_inode+0x26/0xa0
>>> [111015.478375]  [<ffffffff811a1c78>]
>> iget_locked+0xb8/0x190
>>> [111015.478380]  [<ffffffffa05df715>]
>> hfsplus_iget+0x15/0x230 [hfsplus]
>>> [111015.478386]  [<ffffffffa05e7c8f>] ?
>> hfsplus_find_exit+0x2f/0x40 [hfsplus]
>>> [111015.478391]  [<ffffffffa05e467f>]
>> hfsplus_lookup+0x20f/0x2d0 [hfsplus]
>>> [111015.478397]  [<ffffffff8119ed84>] ?
>> __d_alloc+0x34/0x180
>>> [111015.478402]  [<ffffffffa05d701a>] ?
>> char2uni+0x1a/0x50 [nls_utf8]
>>> [111015.478406]  [<ffffffff81173321>] ?
>> kmem_cache_alloc+0x31/0x160
>>> [111015.478410]  [<ffffffff8119ed84>] ?
>> __d_alloc+0x34/0x180
>>> [111015.478413]  [<ffffffff8119ee9c>] ?
>> __d_alloc+0x14c/0x180
>>> [111015.478419]  [<ffffffff811928e1>]
>> __lookup_hash+0x61/0x120
>>> [111015.478423]  [<ffffffff81194b49>] ?
>> lookup_fast+0x219/0x310
>>> [111015.478427]  [<ffffffff81605959>]
>> lookup_slow+0x47/0xab
>>> [111015.478431]  [<ffffffff81196ac6>]
>> path_lookupat+0x716/0x750
>>> [111015.478436]  [<ffffffff81173321>] ?
>> kmem_cache_alloc+0x31/0x160
>>> [111015.478440]  [<ffffffff81196b31>]
>> do_path_lookup+0x31/0xc0
>>> [111015.478444]  [<ffffffff81192b33>] ?
>> getname_flags+0x53/0xf0
>>> [111015.478448]  [<ffffffff8119787d>]
>> user_path_at_empty+0x5d/0xa0
>>> [111015.478454]  [<ffffffff8127973a>] ?
>> inode_has_perm.isra.31.constprop.61+0x2a/0x30
>>> [111015.478459]  [<ffffffff8127d835>] ?
>> selinux_inode_getattr+0x45/0x50
>>> [111015.478464]  [<ffffffff8118c910>] ?
>> cp_new_stat+0x120/0x140
>>> [111015.478468]  [<ffffffff811978d1>]
>> user_path_at+0x11/0x20
>>> [111015.478472]  [<ffffffff8118cba5>]
>> vfs_fstatat+0x35/0x70
>>> [111015.478475]  [<ffffffff8118ceaa>]
>> sys_newfstatat+0x1a/0x40
>>> [111015.478482]  [<ffffffff81614e29>]
>> system_call_fastpath+0x16/0x1b
>>> [111015.478485] Disabling lock debugging due to kernel
>> taint
>>> ============================
>>> 
>>> --- On Mon, 24/9/12, Hin-Tak Leung <htl10@users.sourceforge.net>
>> wrote:
>>> 
>>> <snipped>
>>>> I mentioned briefly some days ago that I managed
>> to corrupt
>>>> an HFS+ paritition while experimenting with the
>> journalling
>>>> code, to the extent that fsck_hfs/fsck.hfsplus
>> (Apple's
>>>> diskdev_cmds tool) refuses to fix. And that
>> partition, with
>>>> the unmodified module used ready-only can get the
>> kernel to
>>>> BUG() "reliably" by just doing "du" on it (and I
>> was
>>>> thinking whether BUG()'ing on corrupted disk is a
>> bug to
>>>> file...).
>>> 
>>> 
>>> --
>>> To unsubscribe from this list: send the line
>> "unsubscribe linux-fsdevel" in
>>> the body of a message to majordomo@vger.kernel.org
>>> More majordomo info at  http://vger.kernel.org/majordomo-info.html
>> 
>> 
>> 
> --
> To unsubscribe from this list: send the line "unsubscribe linux-fsdevel" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: hfsplus BUG: Bad page state in process du pfn:07759 (Re: hfsplus corruption, failed fsck, journalling and zero'ing extent record on delete)

[Hin-Tak Leung]

Hi Vyacheslav,

--- On Mon, 24/9/12, Vyacheslav Dubeyko <slava@dubeyko.com> wrote:

<snipped>
> So, you use journaled HFS+ partition when the issue takes
> place. Am I correct?

That's correct - it is also the case-sensitive version.

<snipped>
> As I can understand:
> 1. You had corrupted journaled HFS+ partition.
> 2. You modify metadata by hand.
> 3. Then you check this partition by fsck.hfsplus. And
> fsck.hfsplus ends checking without any error message.
> 4. But it takes place BUG message after trying to mount this
> partition.
>
> Am I correct in this description?

That's also correct. About item 3, I actually ran it three times -
"fsck.hfsplus -d -D 0x0033 -f -n -l /dev/sdb5"  once
"fsck.hfsplus -d -D 0x0033 -f /dev/sdb5" then twice. 

The first was just to verify that there are fewer critical errors (the "Overlapping extents" type) after modifying the the metadata by hand, without further change; the 2nd to actually fix the fixable errors; and the 3rd time to see that it is clean.
(I piped to "tee" and kept the logs if you feel like looking at them - the last one was the least interesting, of course).

Regards,
Hin-Tak

<snipped>
> > --- On Mon, 24/9/12, Vyacheslav Dubeyko <slava@dubeyko.com>
> wrote:
> > 
> >> Hi Hin-Tak,
> >> 
> >> Could you describe the way of issue reproduction in
> more
> >> details?
> >> 
> >> I need to know:
> >> 1. What kernel version do you use?
> >> 2. Do you have some special configuration of the
> system
> >> ([103022.536649]
> >> SELinux: initialized (dev sdb5, type hfsplus),
> uses
> >> genfs_contexts)?
> >> 3. How did you generate small files? How small is
> it (I mean
> >> size)?
> >> 
> >> Sorry, but currently I haven't clear understanding
> how to
> >> reproduce this
> >> issue from your description.
> >> 
> >> With the best regards,
> >> Vyacheslav Dubeyko.
> >> 
> >> On Mon, 2012-09-24 at 08:30 +0100, Hin-Tak Leung
> wrote:
> >>> Argh, the BUG() seems to be a genuine bug -
> running du
> >> on the recently "fsck.hfsplus -f" clean disk,
> mounting
> >> read-only with unmod'ed distro hfsplus driver:
> (see, "not
> >> Tainted"...)
> >>> 
> >>> =================
> >>> [103022.493765] hfs: write access to a
> journaled
> >> filesystem is not supported, use the force option
> at your
> >> own risk, mounting read-only.
> >>> [103022.536649] SELinux: initialized (dev sdb5,
> type
> >> hfsplus), uses genfs_contexts
> >>> [111015.478171] BUG: Bad page state in process
> du 
> >> pfn:07759
> >>> [111015.478182] page:ffffea00001dd640 count:0
> >> mapcount:0 mapping:       
>   (null)
> >> index:0x1935
> >>> [111015.478185] page flags:
> >> 0x20000000000004(referenced)
> >>> [111015.478189] Modules linked in: usb_storage
> tcp_lp
> >> nls_utf8 hfsplus fuse ip6table_filter ip6_tables
> ebtable_nat
> >> ebtables ipt_MASQUERADE 
> >>> iptable_nat nf_nat xt_CHECKSUM iptable_mangle
> bridge
> >> stp llc xt_LOG xt_physdev nf_conntrack_ipv4
> nf_defrag_ipv4
> >> xt_state nf_conntrack arc4 
> >>> rtl8187 eeprom_93cx6 mac80211 cfg80211
> >> snd_hda_codec_realtek joydev vhost_net tun macvtap
> macvlan
> >> kvm_amd kvm edac_core edac_mce_amd k8temp
> >>>   r592 memstick sp5100_tco
> snd_hda_intel
> >> snd_hda_codec snd_hwdep snd_pcm snd_page_alloc
> snd_timer snd
> >> soundcore i2c_piix4 r8169 mii shpchp t
> >>> oshiba_acpi sparse_keymap rfkill wmi ecryptfs
> >> sha256_generic encrypted_keys nfsd nfs_acl
> auth_rpcgss lockd
> >> sunrpc uinput binfmt_misc truste
> >>> d tpm tpm_bios ata_generic pata_acpi
> firewire_ohci
> >> sdhci_pci sdhci firewire_core crc_itu_t mmc_core
> pata_atiixp
> >> video radeon i2c_algo_bit d
> >>> rm_kms_helper ttm drm i2c_core [last unloaded:
> >> scsi_wait_scan]
> >>> [111015.478274] Pid: 23364, comm: du Not
> tainted
> >> 3.5.4-1.fc17.x86_64 #1
> >>> [111015.478277] Call Trace:
> >>> [111015.478291] 
> [<ffffffff81604213>]
> >> bad_page+0xe6/0xfb
> >>> [111015.478299] 
> [<ffffffff8112dd8e>]
> >> get_page_from_freelist+0x77e/0x940
> >>> [111015.478305] 
> [<ffffffff8112e0fd>]
> >> __alloc_pages_nodemask+0x1ad/0x970
> >>> [111015.478318] 
> [<ffffffffa05e5719>] ?
> >> hfsplus_bnode_read+0x89/0x100 [hfsplus]
> >>> [111015.478324] 
> [<ffffffffa05e5775>] ?
> >> hfsplus_bnode_read+0xe5/0x100 [hfsplus]
> >>> [111015.478329] 
> [<ffffffff811699e0>]
> >> alloc_pages_current+0xb0/0x120
> >>> [111015.478334] 
> [<ffffffff811721b8>]
> >> new_slab+0x268/0x320
> >>> [111015.478339] 
> [<ffffffff8160546e>]
> >> __slab_alloc+0x36e/0x4c8
> >>> [111015.478344] 
> [<ffffffffa05df11a>] ?
> >> hfsplus_alloc_inode+0x1a/0x40 [hfsplus]
> >>> [111015.478349] 
> [<ffffffffa05df11a>] ?
> >> hfsplus_alloc_inode+0x1a/0x40 [hfsplus]
> >>> [111015.478354] 
> [<ffffffff811733f8>]
> >> kmem_cache_alloc+0x108/0x160
> >>> [111015.478359] 
> [<ffffffffa05e7d40>] ?
> >> __hplusfs_brec_find+0xa0/0x180 [hfsplus]
> >>> [111015.478364] 
> [<ffffffffa05df11a>]
> >> hfsplus_alloc_inode+0x1a/0x40 [hfsplus]
> >>> [111015.478371] 
> [<ffffffff811a0606>]
> >> alloc_inode+0x26/0xa0
> >>> [111015.478375] 
> [<ffffffff811a1c78>]
> >> iget_locked+0xb8/0x190
> >>> [111015.478380] 
> [<ffffffffa05df715>]
> >> hfsplus_iget+0x15/0x230 [hfsplus]
> >>> [111015.478386] 
> [<ffffffffa05e7c8f>] ?
> >> hfsplus_find_exit+0x2f/0x40 [hfsplus]
> >>> [111015.478391] 
> [<ffffffffa05e467f>]
> >> hfsplus_lookup+0x20f/0x2d0 [hfsplus]
> >>> [111015.478397] 
> [<ffffffff8119ed84>] ?
> >> __d_alloc+0x34/0x180
> >>> [111015.478402] 
> [<ffffffffa05d701a>] ?
> >> char2uni+0x1a/0x50 [nls_utf8]
> >>> [111015.478406] 
> [<ffffffff81173321>] ?
> >> kmem_cache_alloc+0x31/0x160
> >>> [111015.478410] 
> [<ffffffff8119ed84>] ?
> >> __d_alloc+0x34/0x180
> >>> [111015.478413] 
> [<ffffffff8119ee9c>] ?
> >> __d_alloc+0x14c/0x180
> >>> [111015.478419] 
> [<ffffffff811928e1>]
> >> __lookup_hash+0x61/0x120
> >>> [111015.478423] 
> [<ffffffff81194b49>] ?
> >> lookup_fast+0x219/0x310
> >>> [111015.478427] 
> [<ffffffff81605959>]
> >> lookup_slow+0x47/0xab
> >>> [111015.478431] 
> [<ffffffff81196ac6>]
> >> path_lookupat+0x716/0x750
> >>> [111015.478436] 
> [<ffffffff81173321>] ?
> >> kmem_cache_alloc+0x31/0x160
> >>> [111015.478440] 
> [<ffffffff81196b31>]
> >> do_path_lookup+0x31/0xc0
> >>> [111015.478444] 
> [<ffffffff81192b33>] ?
> >> getname_flags+0x53/0xf0
> >>> [111015.478448] 
> [<ffffffff8119787d>]
> >> user_path_at_empty+0x5d/0xa0
> >>> [111015.478454] 
> [<ffffffff8127973a>] ?
> >> inode_has_perm.isra.31.constprop.61+0x2a/0x30
> >>> [111015.478459] 
> [<ffffffff8127d835>] ?
> >> selinux_inode_getattr+0x45/0x50
> >>> [111015.478464] 
> [<ffffffff8118c910>] ?
> >> cp_new_stat+0x120/0x140
> >>> [111015.478468] 
> [<ffffffff811978d1>]
> >> user_path_at+0x11/0x20
> >>> [111015.478472] 
> [<ffffffff8118cba5>]
> >> vfs_fstatat+0x35/0x70
> >>> [111015.478475] 
> [<ffffffff8118ceaa>]
> >> sys_newfstatat+0x1a/0x40
> >>> [111015.478482] 
> [<ffffffff81614e29>]
> >> system_call_fastpath+0x16/0x1b
> >>> [111015.478485] Disabling lock debugging due to
> kernel
> >> taint
> >>> ============================
> >>> 
> >>> --- On Mon, 24/9/12, Hin-Tak Leung <htl10@users.sourceforge.net>
> >> wrote:
> >>> 
> >>> <snipped>
> >>>> I mentioned briefly some days ago that I
> managed
> >> to corrupt
> >>>> an HFS+ paritition while experimenting with
> the
> >> journalling
> >>>> code, to the extent that
> fsck_hfs/fsck.hfsplus
> >> (Apple's
> >>>> diskdev_cmds tool) refuses to fix. And
> that
> >> partition, with
> >>>> the unmodified module used ready-only can
> get the
> >> kernel to
> >>>> BUG() "reliably" by just doing "du" on it
> (and I
> >> was
> >>>> thinking whether BUG()'ing on corrupted
> disk is a
> >> bug to
> >>>> file...).
> >>> 
> >>> 
> >>> --
> >>> To unsubscribe from this list: send the line
> >> "unsubscribe linux-fsdevel" in
> >>> the body of a message to majordomo@vger.kernel.org
> >>> More majordomo info at  http://vger.kernel.org/majordomo-info.html
> >> 
> >> 
> >> 
> > --
> > To unsubscribe from this list: send the line
> "unsubscribe linux-fsdevel" in
> > the body of a message to majordomo@vger.kernel.org
> > More majordomo info at  http://vger.kernel.org/majordomo-info.html
> 
> 
--
To unsubscribe from this list: send the line "unsubscribe linux-fsdevel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: hfsplus BUG: Bad page state in process du pfn:07759 (Re: hfsplus corruption, failed fsck, journalling and zero'ing extent record on delete)

[Vyacheslav Dubeyko]

Hi Hin-Tak,

On Sep 24, 2012, at 11:30 AM, Hin-Tak Leung wrote:

> Argh, the BUG() seems to be a genuine bug - running du on the recently "fsck.hfsplus -f" clean disk, mounting read-only with unmod'ed distro hfsplus driver: (see, "not Tainted"...)
> 
> =================
> [103022.493765] hfs: write access to a journaled filesystem is not supported, use the force option at your own risk, mounting read-only.
> [103022.536649] SELinux: initialized (dev sdb5, type hfsplus), uses genfs_contexts
> [111015.478171] BUG: Bad page state in process du  pfn:07759
> [111015.478182] page:ffffea00001dd640 count:0 mapcount:0 mapping:          (null) index:0x1935
> [111015.478185] page flags: 0x20000000000004(referenced)
> [111015.478189] Modules linked in: usb_storage tcp_lp nls_utf8 hfsplus fuse ip6table_filter ip6_tables ebtable_nat ebtables ipt_MASQUERADE 
> iptable_nat nf_nat xt_CHECKSUM iptable_mangle bridge stp llc xt_LOG xt_physdev nf_conntrack_ipv4 nf_defrag_ipv4 xt_state nf_conntrack arc4 
> rtl8187 eeprom_93cx6 mac80211 cfg80211 snd_hda_codec_realtek joydev vhost_net tun macvtap macvlan kvm_amd kvm edac_core edac_mce_amd k8temp
> r592 memstick sp5100_tco snd_hda_intel snd_hda_codec snd_hwdep snd_pcm snd_page_alloc snd_timer snd soundcore i2c_piix4 r8169 mii shpchp t
> oshiba_acpi sparse_keymap rfkill wmi ecryptfs sha256_generic encrypted_keys nfsd nfs_acl auth_rpcgss lockd sunrpc uinput binfmt_misc truste
> d tpm tpm_bios ata_generic pata_acpi firewire_ohci sdhci_pci sdhci firewire_core crc_itu_t mmc_core pata_atiixp video radeon i2c_algo_bit d
> rm_kms_helper ttm drm i2c_core [last unloaded: scsi_wait_scan]
> [111015.478274] Pid: 23364, comm: du Not tainted 3.5.4-1.fc17.x86_64 #1
> [111015.478277] Call Trace:
> [111015.478291]  [<ffffffff81604213>] bad_page+0xe6/0xfb
> [111015.478299]  [<ffffffff8112dd8e>] get_page_from_freelist+0x77e/0x940
> [111015.478305]  [<ffffffff8112e0fd>] __alloc_pages_nodemask+0x1ad/0x970
> [111015.478318]  [<ffffffffa05e5719>] ? hfsplus_bnode_read+0x89/0x100 [hfsplus]
> [111015.478324]  [<ffffffffa05e5775>] ? hfsplus_bnode_read+0xe5/0x100 [hfsplus]
> [111015.478329]  [<ffffffff811699e0>] alloc_pages_current+0xb0/0x120
> [111015.478334]  [<ffffffff811721b8>] new_slab+0x268/0x320
> [111015.478339]  [<ffffffff8160546e>] __slab_alloc+0x36e/0x4c8
> [111015.478344]  [<ffffffffa05df11a>] ? hfsplus_alloc_inode+0x1a/0x40 [hfsplus]
> [111015.478349]  [<ffffffffa05df11a>] ? hfsplus_alloc_inode+0x1a/0x40 [hfsplus]
> [111015.478354]  [<ffffffff811733f8>] kmem_cache_alloc+0x108/0x160
> [111015.478359]  [<ffffffffa05e7d40>] ? __hplusfs_brec_find+0xa0/0x180 [hfsplus]
> [111015.478364]  [<ffffffffa05df11a>] hfsplus_alloc_inode+0x1a/0x40 [hfsplus]
> [111015.478371]  [<ffffffff811a0606>] alloc_inode+0x26/0xa0
> [111015.478375]  [<ffffffff811a1c78>] iget_locked+0xb8/0x190
> [111015.478380]  [<ffffffffa05df715>] hfsplus_iget+0x15/0x230 [hfsplus]
> [111015.478386]  [<ffffffffa05e7c8f>] ? hfsplus_find_exit+0x2f/0x40 [hfsplus]
> [111015.478391]  [<ffffffffa05e467f>] hfsplus_lookup+0x20f/0x2d0 [hfsplus]
> [111015.478397]  [<ffffffff8119ed84>] ? __d_alloc+0x34/0x180
> [111015.478402]  [<ffffffffa05d701a>] ? char2uni+0x1a/0x50 [nls_utf8]
> [111015.478406]  [<ffffffff81173321>] ? kmem_cache_alloc+0x31/0x160
> [111015.478410]  [<ffffffff8119ed84>] ? __d_alloc+0x34/0x180
> [111015.478413]  [<ffffffff8119ee9c>] ? __d_alloc+0x14c/0x180
> [111015.478419]  [<ffffffff811928e1>] __lookup_hash+0x61/0x120
> [111015.478423]  [<ffffffff81194b49>] ? lookup_fast+0x219/0x310
> [111015.478427]  [<ffffffff81605959>] lookup_slow+0x47/0xab
> [111015.478431]  [<ffffffff81196ac6>] path_lookupat+0x716/0x750
> [111015.478436]  [<ffffffff81173321>] ? kmem_cache_alloc+0x31/0x160
> [111015.478440]  [<ffffffff81196b31>] do_path_lookup+0x31/0xc0
> [111015.478444]  [<ffffffff81192b33>] ? getname_flags+0x53/0xf0
> [111015.478448]  [<ffffffff8119787d>] user_path_at_empty+0x5d/0xa0
> [111015.478454]  [<ffffffff8127973a>] ? inode_has_perm.isra.31.constprop.61+0x2a/0x30
> [111015.478459]  [<ffffffff8127d835>] ? selinux_inode_getattr+0x45/0x50
> [111015.478464]  [<ffffffff8118c910>] ? cp_new_stat+0x120/0x140
> [111015.478468]  [<ffffffff811978d1>] user_path_at+0x11/0x20
> [111015.478472]  [<ffffffff8118cba5>] vfs_fstatat+0x35/0x70
> [111015.478475]  [<ffffffff8118ceaa>] sys_newfstatat+0x1a/0x40
> [111015.478482]  [<ffffffff81614e29>] system_call_fastpath+0x16/0x1b
> [111015.478485] Disabling lock debugging due to kernel taint
> ============================
> 

I am analyzing this call trace. I think that strace output under "du" can be very helpful for investigation the issue. Could you share such strace output?

Also, if I correct, you wrote about dmesg calling also. Could you share strace output for dmesg command also?

Thanks,
Vyacheslav Dubeyko. 


> --- On Mon, 24/9/12, Hin-Tak Leung <htl10@users.sourceforge.net> wrote:
> 
> <snipped>
>> I mentioned briefly some days ago that I managed to corrupt
>> an HFS+ paritition while experimenting with the journalling
>> code, to the extent that fsck_hfs/fsck.hfsplus (Apple's
>> diskdev_cmds tool) refuses to fix. And that partition, with
>> the unmodified module used ready-only can get the kernel to
>> BUG() "reliably" by just doing "du" on it (and I was
>> thinking whether BUG()'ing on corrupted disk is a bug to
>> file...).
> 
> 
> --
> To unsubscribe from this list: send the line "unsubscribe linux-fsdevel" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: hfsplus BUG: Bad page state in process du pfn:07759 (Re: hfsplus corruption, failed fsck, journalling and zero'ing extent record on delete)

[Hin-Tak Leung]

--- On Mon, 1/10/12, Vyacheslav Dubeyko <slava@dubeyko.com> wrote:

> From: Vyacheslav Dubeyko <slava@dubeyko.com>
> Subject: Re: hfsplus BUG: Bad page state in process du  pfn:07759 (Re: hfsplus corruption, failed fsck, journalling and zero'ing extent record on delete)
> To: "Hin-Tak Leung" <hintak_leung@yahoo.co.uk>
> Cc: linux-fsdevel@vger.kernel.org, "Till Kamppeter" <till.kamppeter@gmail.com>, "Naohiro Aota" <naota@elisp.net>, "Matthew Garrett" <mjg@redhat.com>
> Date: Monday, 1 October, 2012, 20:09
> Hi Hin-Tak,
> 
> On Sep 24, 2012, at 11:30 AM, Hin-Tak Leung wrote:
> 
> > Argh, the BUG() seems to be a genuine bug - running du
> on the recently "fsck.hfsplus -f" clean disk, mounting
> read-only with unmod'ed distro hfsplus driver: (see, "not
> Tainted"...)
> > 
> > =================
> > [103022.493765] hfs: write access to a journaled
> filesystem is not supported, use the force option at your
> own risk, mounting read-only.
> > [103022.536649] SELinux: initialized (dev sdb5, type
> hfsplus), uses genfs_contexts
> > [111015.478171] BUG: Bad page state in process du 
> pfn:07759
> > [111015.478182] page:ffffea00001dd640 count:0
> mapcount:0 mapping:          (null)
> index:0x1935
> > [111015.478185] page flags:
> 0x20000000000004(referenced)
> > [111015.478189] Modules linked in: usb_storage tcp_lp
> nls_utf8 hfsplus fuse ip6table_filter ip6_tables ebtable_nat
> ebtables ipt_MASQUERADE 
> > iptable_nat nf_nat xt_CHECKSUM iptable_mangle bridge
> stp llc xt_LOG xt_physdev nf_conntrack_ipv4 nf_defrag_ipv4
> xt_state nf_conntrack arc4 
> > rtl8187 eeprom_93cx6 mac80211 cfg80211
> snd_hda_codec_realtek joydev vhost_net tun macvtap macvlan
> kvm_amd kvm edac_core edac_mce_amd k8temp
> > r592 memstick sp5100_tco snd_hda_intel snd_hda_codec
> snd_hwdep snd_pcm snd_page_alloc snd_timer snd soundcore
> i2c_piix4 r8169 mii shpchp t
> > oshiba_acpi sparse_keymap rfkill wmi ecryptfs
> sha256_generic encrypted_keys nfsd nfs_acl auth_rpcgss lockd
> sunrpc uinput binfmt_misc truste
> > d tpm tpm_bios ata_generic pata_acpi firewire_ohci
> sdhci_pci sdhci firewire_core crc_itu_t mmc_core pata_atiixp
> video radeon i2c_algo_bit d
> > rm_kms_helper ttm drm i2c_core [last unloaded:
> scsi_wait_scan]
> > [111015.478274] Pid: 23364, comm: du Not tainted
> 3.5.4-1.fc17.x86_64 #1
> > [111015.478277] Call Trace:
> > [111015.478291]  [<ffffffff81604213>]
> bad_page+0xe6/0xfb
> > [111015.478299]  [<ffffffff8112dd8e>]
> get_page_from_freelist+0x77e/0x940
> > [111015.478305]  [<ffffffff8112e0fd>]
> __alloc_pages_nodemask+0x1ad/0x970
> > [111015.478318]  [<ffffffffa05e5719>] ?
> hfsplus_bnode_read+0x89/0x100 [hfsplus]
> > [111015.478324]  [<ffffffffa05e5775>] ?
> hfsplus_bnode_read+0xe5/0x100 [hfsplus]
> > [111015.478329]  [<ffffffff811699e0>]
> alloc_pages_current+0xb0/0x120
> > [111015.478334]  [<ffffffff811721b8>]
> new_slab+0x268/0x320
> > [111015.478339]  [<ffffffff8160546e>]
> __slab_alloc+0x36e/0x4c8
> > [111015.478344]  [<ffffffffa05df11a>] ?
> hfsplus_alloc_inode+0x1a/0x40 [hfsplus]
> > [111015.478349]  [<ffffffffa05df11a>] ?
> hfsplus_alloc_inode+0x1a/0x40 [hfsplus]
> > [111015.478354]  [<ffffffff811733f8>]
> kmem_cache_alloc+0x108/0x160
> > [111015.478359]  [<ffffffffa05e7d40>] ?
> __hplusfs_brec_find+0xa0/0x180 [hfsplus]
> > [111015.478364]  [<ffffffffa05df11a>]
> hfsplus_alloc_inode+0x1a/0x40 [hfsplus]
> > [111015.478371]  [<ffffffff811a0606>]
> alloc_inode+0x26/0xa0
> > [111015.478375]  [<ffffffff811a1c78>]
> iget_locked+0xb8/0x190
> > [111015.478380]  [<ffffffffa05df715>]
> hfsplus_iget+0x15/0x230 [hfsplus]
> > [111015.478386]  [<ffffffffa05e7c8f>] ?
> hfsplus_find_exit+0x2f/0x40 [hfsplus]
> > [111015.478391]  [<ffffffffa05e467f>]
> hfsplus_lookup+0x20f/0x2d0 [hfsplus]
> > [111015.478397]  [<ffffffff8119ed84>] ?
> __d_alloc+0x34/0x180
> > [111015.478402]  [<ffffffffa05d701a>] ?
> char2uni+0x1a/0x50 [nls_utf8]
> > [111015.478406]  [<ffffffff81173321>] ?
> kmem_cache_alloc+0x31/0x160
> > [111015.478410]  [<ffffffff8119ed84>] ?
> __d_alloc+0x34/0x180
> > [111015.478413]  [<ffffffff8119ee9c>] ?
> __d_alloc+0x14c/0x180
> > [111015.478419]  [<ffffffff811928e1>]
> __lookup_hash+0x61/0x120
> > [111015.478423]  [<ffffffff81194b49>] ?
> lookup_fast+0x219/0x310
> > [111015.478427]  [<ffffffff81605959>]
> lookup_slow+0x47/0xab
> > [111015.478431]  [<ffffffff81196ac6>]
> path_lookupat+0x716/0x750
> > [111015.478436]  [<ffffffff81173321>] ?
> kmem_cache_alloc+0x31/0x160
> > [111015.478440]  [<ffffffff81196b31>]
> do_path_lookup+0x31/0xc0
> > [111015.478444]  [<ffffffff81192b33>] ?
> getname_flags+0x53/0xf0
> > [111015.478448]  [<ffffffff8119787d>]
> user_path_at_empty+0x5d/0xa0
> > [111015.478454]  [<ffffffff8127973a>] ?
> inode_has_perm.isra.31.constprop.61+0x2a/0x30
> > [111015.478459]  [<ffffffff8127d835>] ?
> selinux_inode_getattr+0x45/0x50
> > [111015.478464]  [<ffffffff8118c910>] ?
> cp_new_stat+0x120/0x140
> > [111015.478468]  [<ffffffff811978d1>]
> user_path_at+0x11/0x20
> > [111015.478472]  [<ffffffff8118cba5>]
> vfs_fstatat+0x35/0x70
> > [111015.478475]  [<ffffffff8118ceaa>]
> sys_newfstatat+0x1a/0x40
> > [111015.478482]  [<ffffffff81614e29>]
> system_call_fastpath+0x16/0x1b
> > [111015.478485] Disabling lock debugging due to kernel
> taint
> > ============================
> > 

Unless I state otherwise (I wouldn't post such things against tainted modules with experimental patches anyway), these are against one of the fedora distro kernels. The above shows "3.5.4-1.fc17.x86_64", which you could look up on fedora's compile farm for exact configs:
http://koji.fedoraproject.org/koji/packageinfo?packageID=8

If you are brave enough, you could even unpack one of those and graft it on a non-fedora system, I suppose...

So I have been able to consistently get BUG() by running du on a particular directory on a USB drive (which is fsck-clean), just using one of the distro kernel packages. I know I probably should file this first with Fedora, but then I reckon it would probably get referred to linux-fsdevel anyway.

> I am analyzing this call trace. I think that strace output
> under "du" can be very helpful for investigation the issue.
> Could you share such strace output?
> 
> Also, if I correct, you wrote about dmesg calling also.
> Could you share strace output for dmesg command also?

I'll get you those soon. the du trace would be quite big (since it is du'ing a 6 kernel trees, etc).

Hin-Tak

> > --- On Mon, 24/9/12, Hin-Tak Leung <htl10@users.sourceforge.net>
> wrote:
> > 
> > <snipped>
> >> I mentioned briefly some days ago that I managed to
> corrupt
> >> an HFS+ paritition while experimenting with the
> journalling
> >> code, to the extent that fsck_hfs/fsck.hfsplus
> (Apple's
> >> diskdev_cmds tool) refuses to fix. And that
> partition, with
> >> the unmodified module used ready-only can get the
> kernel to
> >> BUG() "reliably" by just doing "du" on it (and I
> was
> >> thinking whether BUG()'ing on corrupted disk is a
> bug to
> >> file...).
> > 
> > 
> > --
> > To unsubscribe from this list: send the line
> "unsubscribe linux-fsdevel" in
> > the body of a message to majordomo@vger.kernel.org
> > More majordomo info at  http://vger.kernel.org/majordomo-info.html
> 
> 
--
To unsubscribe from this list: send the line "unsubscribe linux-fsdevel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html