Re: [PATCH] hfsplus: release bnode pages after use, not before

[Hin-Tak Leung <hintak.leung@gmail.com>]

On 10 June 2015 at 00:40, Sergei Antonov <saproj@gmail.com> wrote:
...
> I did not try to change the logic of the driver. Just fixed one
> glaring defect. Which, by the way, in addition to the aforementioned
> bug by Sasha Levin caused:
> 1. A "du"-related bug reported by Hin-Tak Leung earlier in the list.
> 2. https://bugzilla.kernel.org/show_bug.cgi?id=63841
> 3. https://bugzilla.kernel.org/show_bug.cgi?id=78761
> 4. https://bugzilla.kernel.org/show_bug.cgi?id=42342

For some unknown reason majordomo won't let my regular sourceforge
account/alias post
to its lists (not just fsdevel, but also git), anyway, I just managed
to reproduced the issue -
my older hardware has been retired so it is harder on more-generous
memory systems.
The steps are:
1. mount mac os x system disk image (I do read-only, and also from
qemu-nbd read-only, but those
details don't seem to be important)
2. run "du /mnt" on the mac os x disk mount repeatedly; I wasn't able
to cause the kernel
to fault on my current system - 8GB, kernel 4.0.5-300.fc22.x86_64 ,
until I also run 'du /' (i.e. the whole linux system) in a separate window.

Then I get this:
--------------
[17257.917645] hfsplus: recoff 22364 too large
[17257.993329] hfsplus: recoff 22364 too large
[17274.686714] hfsplus: recoff 27136 too large
[17274.686747] hfsplus: recoff 27136 too large
[17276.643246] hfsplus: recoff 28528 too large
[17276.643283] hfsplus: recoff 28528 too large
[17276.643334] hfsplus: recoff 31034 too large
[17276.643432] hfsplus: recoff 31034 too large
[17276.644568] hfsplus: recoff 31034 too large
[17276.645408] hfsplus: recoff 31034 too large
[17276.648083] hfsplus: recoff 31034 too large
[17283.456405] hfsplus: recoff 18688 too large
[17283.484236] hfsplus: recoff 18688 too large
[17283.489637] hfsplus: recoff 18688 too large
[17283.567689] hfsplus: recoff 18688 too large
[17283.580719] hfsplus: recoff 18688 too large
[17283.586192] hfsplus: recoff 18688 too large
[17283.590115] hfsplus: recoff 18688 too large
[17283.594808] hfsplus: recoff 18688 too large
[17283.598225] hfsplus: recoff 18688 too large
[17283.608131] hfsplus: recoff 18688 too large
[17283.613090] hfsplus: recoff 18688 too large
[17283.621220] hfsplus: recoff 18688 too large
[17283.777970] hfsplus: recoff 18688 too large
[17283.816374] hfsplus: recoff 18688 too large
[17283.902398] hfsplus: recoff 18688 too large
[17284.552987] hfsplus: recoff 16933 too large
[17284.738526] hfsplus: recoff 25661 too large
[17284.738557] hfsplus: recoff 25661 too large
[17284.871063] hfsplus: recoff 14131 too large
[17284.871992] hfsplus: recoff 14131 too large
[17287.330129] hfsplus: recoff 14131 too large
[17287.685383] hfsplus: recoff 14131 too large
[17287.860485] hfsplus: recoff 14131 too large
[17287.881720] hfsplus: recoff 14131 too large
[17287.923793] hfsplus: recoff 14131 too large
[17288.133657] hfsplus: recoff 14131 too large
[17288.310771] hfsplus: recoff 14131 too large
[17288.789545] BUG: Bad page state in process firefox  pfn:22cb45
[17288.789559] page:ffffea0008b2d140 count:0 mapcount:0 mapping:
   (null) index:0x2
[17288.789563] flags: 0x5ffff800000004(referenced)
[17288.789570] page dumped because: PAGE_FLAGS_CHECK_AT_PREP flag set
[17288.789573] bad because of flags:
[17288.789576] flags: 0x4(referenced)
[17288.789580] Modules linked in: nls_utf8 hfsplus nbd uas usb_storage
fuse ccm ip6t_rpfilter ip6t_REJECT nf_reject_ipv6 xt_conntrack
ebtable_nat ebtable_broute bridge stp llc ebtable_filter ebtables
ip6table_nat nf_conntrack_ipv6 nf_defrag_ipv6 nf_nat_ipv6
ip6table_mangle ip6table_security ip6table_raw ip6table_filter
ip6_tables iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4
nf_nat nf_conntrack iptable_mangle iptable_security iptable_raw vfat
fat uvcvideo videobuf2_vmalloc videobuf2_core videobuf2_memops
v4l2_common videodev ath3k btusb bluetooth media kvm_amd kvm
snd_hda_codec_realtek snd_hda_codec_hdmi snd_hda_codec_generic arc4
ath9k ath9k_common snd_hda_intel crct10dif_pclmul snd_hda_controller
ath9k_hw crc32_pclmul ath snd_hda_codec crc32c_intel mac80211
snd_hwdep snd_seq snd_seq_device
[17288.789660]  snd_pcm ghash_clmulni_intel toshiba_acpi fam15h_power
edac_core edac_mce_amd cfg80211 snd_timer joydev rtsx_pci_ms memstick
serio_raw i2c_piix4 sparse_keymap k10temp wmi tpm_tis tpm video ccp
acpi_cpufreq rfkill snd soundcore shpchp toshiba_haps
toshiba_bluetooth nfsd auth_rpcgss nfs_acl lockd grace sunrpc
vboxnetadp(O) vboxnetflt(O) binfmt_misc vboxdrv(O) radeon
rtsx_pci_sdmmc mmc_core i2c_algo_bit drm_kms_helper ttm drm r8169
rtsx_pci mii mfd_core
[17288.789722] CPU: 3 PID: 2844 Comm: firefox Tainted: G           O
 4.0.5-300.fc22.x86_64 #1
[17288.789726] Hardware name: TOSHIBA SATELLITE C50D-B/ZBWAE, BIOS
1.30 06/06/2014
[17288.789730]  0000000000000000 0000000064b601fc ffff8801fff9baf8
ffffffff817834f4
[17288.789736]  0000000000000000 ffffea0008b2d140 ffff8801fff9bb28
ffffffff811a48ec
[17288.789742]  ffffffff811c0330 ffff8801fff9bce8 ffff88023ed98e38
ffff88023ed98e58
[17288.789748] Call Trace:
[17288.789762]  [<ffffffff817834f4>] dump_stack+0x45/0x57
[17288.789771]  [<ffffffff811a48ec>] bad_page.part.62+0xbc/0x110
[17288.789780]  [<ffffffff811c0330>] ? zone_statistics+0x80/0xa0
[17288.789787]  [<ffffffff811a9135>] get_page_from_freelist+0x4f5/0xab0
[17288.789794]  [<ffffffff8101265b>] ? __switch_to+0x19b/0x5e0
[17288.789802]  [<ffffffff811a998a>] __alloc_pages_nodemask+0x19a/0xa10
[17288.789808]  [<ffffffff811a7db6>] ? free_hot_cold_page_list+0x56/0xb0
[17288.789817]  [<ffffffff811f4778>] alloc_pages_vma+0xb8/0x230
[17288.789825]  [<ffffffff811d2c3c>] handle_mm_fault+0x10ec/0x1840
[17288.789832]  [<ffffffff810cea88>] ? __enqueue_entity+0x78/0x80
[17288.789839]  [<ffffffff810d8b29>] ? pick_next_task_fair+0x919/0x970
[17288.789846]  [<ffffffff81063d33>] __do_page_fault+0x193/0x440
[17288.789851]  [<ffffffff81064011>] do_page_fault+0x31/0x70
[17288.789858]  [<ffffffff8178bb08>] page_fault+0x28/0x30
[17288.789862] Disabling lock debugging due to kernel taint
[17288.790999] BUG: Bad page state in process firefox  pfn:22ce72
[17288.791042] page:ffffea0008b39c80 count:0 mapcount:0 mapping:
   (null) index:0x2
[17288.791046] flags: 0x5ffff800000004(referenced)
[17288.791053] page dumped because: PAGE_FLAGS_CHECK_AT_PREP flag set
[17288.791055] bad because of flags:
[17288.791057] flags: 0x4(referenced)
[17288.791062] Modules linked in: nls_utf8 hfsplus nbd uas usb_storage
fuse ccm ip6t_rpfilter ip6t_REJECT nf_reject_ipv6 xt_conntrack
ebtable_nat ebtable_broute bridge stp llc ebtable_filter ebtables
ip6table_nat nf_conntrack_ipv6 nf_defrag_ipv6 nf_nat_ipv6
ip6table_mangle ip6table_security ip6table_raw ip6table_filter
ip6_tables iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4
nf_nat nf_conntrack iptable_mangle iptable_security iptable_raw vfat
fat uvcvideo videobuf2_vmalloc videobuf2_core videobuf2_memops
v4l2_common videodev ath3k btusb bluetooth media kvm_amd kvm
snd_hda_codec_realtek snd_hda_codec_hdmi snd_hda_codec_generic arc4
ath9k ath9k_common snd_hda_intel crct10dif_pclmul snd_hda_controller
ath9k_hw crc32_pclmul ath snd_hda_codec crc32c_intel mac80211
snd_hwdep snd_seq snd_seq_device
[17288.791141]  snd_pcm ghash_clmulni_intel toshiba_acpi fam15h_power
edac_core edac_mce_amd cfg80211 snd_timer joydev rtsx_pci_ms memstick
serio_raw i2c_piix4 sparse_keymap k10temp wmi tpm_tis tpm video ccp
acpi_cpufreq rfkill snd soundcore shpchp toshiba_haps
toshiba_bluetooth nfsd auth_rpcgss nfs_acl lockd grace sunrpc
vboxnetadp(O) vboxnetflt(O) binfmt_misc vboxdrv(O) radeon
rtsx_pci_sdmmc mmc_core i2c_algo_bit drm_kms_helper ttm drm r8169
rtsx_pci mii mfd_core
[17288.791202] CPU: 3 PID: 2844 Comm: firefox Tainted: G    B      O
 4.0.5-300.fc22.x86_64 #1
[17288.791206] Hardware name: TOSHIBA SATELLITE C50D-B/ZBWAE, BIOS
1.30 06/06/2014
[17288.791209]  0000000000000000 0000000064b601fc ffff8801fff9baf8
ffffffff817834f4
[17288.791215]  0000000000000000 ffffea0008b39c80 ffff8801fff9bb28
ffffffff811a48ec
[17288.791221]  ffffffff811c0330 ffff8801fff9bce8 ffff88023ed98e38
ffff88023ed98e58
[17288.791226] Call Trace:
[17288.791241]  [<ffffffff817834f4>] dump_stack+0x45/0x57
[17288.791249]  [<ffffffff811a48ec>] bad_page.part.62+0xbc/0x110
[17288.791256]  [<ffffffff811c0330>] ? zone_statistics+0x80/0xa0
[17288.791263]  [<ffffffff811a9135>] get_page_from_freelist+0x4f5/0xab0
[17288.791271]  [<ffffffff8101265b>] ? __switch_to+0x19b/0x5e0
[17288.791278]  [<ffffffff811a998a>] __alloc_pages_nodemask+0x19a/0xa10
[17288.791283]  [<ffffffff811a7db6>] ? free_hot_cold_page_list+0x56/0xb0
[17288.791292]  [<ffffffff811f4778>] alloc_pages_vma+0xb8/0x230
[17288.791300]  [<ffffffff811d2c3c>] handle_mm_fault+0x10ec/0x1840
[17288.791307]  [<ffffffff810cea88>] ? __enqueue_entity+0x78/0x80
[17288.791314]  [<ffffffff810d8b29>] ? pick_next_task_fair+0x919/0x970
[17288.791320]  [<ffffffff81063d33>] __do_page_fault+0x193/0x440
[17288.791325]  [<ffffffff81064011>] do_page_fault+0x31/0x70
[17288.791332]  [<ffffffff8178bb08>] page_fault+0x28/0x30
[17288.791338] BUG: Bad page state in process firefox  pfn:22ce73
[17288.791342] page:ffffea0008b39cc0 count:0 mapcount:0 mapping:
   (null) index:0x2
[17288.791344] flags: 0x5ffff800000004(referenced)
[17288.791349] page dumped because: PAGE_FLAGS_CHECK_AT_PREP flag set
[17288.791351] bad because of flags:
[17288.791354] flags: 0x4(referenced)
[17288.791357] Modules linked in: nls_utf8 hfsplus nbd uas usb_storage
fuse ccm ip6t_rpfilter ip6t_REJECT nf_reject_ipv6 xt_conntrack
ebtable_nat ebtable_broute bridge stp llc ebtable_filter ebtables
ip6table_nat nf_conntrack_ipv6 nf_defrag_ipv6 nf_nat_ipv6
ip6table_mangle ip6table_security ip6table_raw ip6table_filter
ip6_tables iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4
nf_nat nf_conntrack iptable_mangle iptable_security iptable_raw vfat
fat uvcvideo videobuf2_vmalloc videobuf2_core videobuf2_memops
v4l2_common videodev ath3k btusb bluetooth media kvm_amd kvm
snd_hda_codec_realtek snd_hda_codec_hdmi snd_hda_codec_generic arc4
ath9k ath9k_common snd_hda_intel crct10dif_pclmul snd_hda_controller
ath9k_hw crc32_pclmul ath snd_hda_codec crc32c_intel mac80211
snd_hwdep snd_seq snd_seq_device
[17288.791419]  snd_pcm ghash_clmulni_intel toshiba_acpi fam15h_power
edac_core edac_mce_amd cfg80211 snd_timer joydev rtsx_pci_ms memstick
serio_raw i2c_piix4 sparse_keymap k10temp wmi tpm_tis tpm video ccp
acpi_cpufreq rfkill snd soundcore shpchp toshiba_haps
toshiba_bluetooth nfsd auth_rpcgss nfs_acl lockd grace sunrpc
vboxnetadp(O) vboxnetflt(O) binfmt_misc vboxdrv(O) radeon
rtsx_pci_sdmmc mmc_core i2c_algo_bit drm_kms_helper ttm drm r8169
rtsx_pci mii mfd_core
[17288.791464] CPU: 3 PID: 2844 Comm: firefox Tainted: G    B      O
 4.0.5-300.fc22.x86_64 #1
[17288.791467] Hardware name: TOSHIBA SATELLITE C50D-B/ZBWAE, BIOS
1.30 06/06/2014
[17288.791470]  0000000000000000 0000000064b601fc ffff8801fff9baf8
ffffffff817834f4
[17288.791475]  0000000000000000 ffffea0008b39cc0 ffff8801fff9bb28
ffffffff811a48ec
[17288.791480]  ffffffff811c0330 ffff8801fff9bce8 ffff88023ed98e38
ffff88023ed98e58
[17288.791486] Call Trace:
[17288.791492]  [<ffffffff817834f4>] dump_stack+0x45/0x57
[17288.791497]  [<ffffffff811a48ec>] bad_page.part.62+0xbc/0x110
[17288.791503]  [<ffffffff811c0330>] ? zone_statistics+0x80/0xa0
[17288.791509]  [<ffffffff811a9135>] get_page_from_freelist+0x4f5/0xab0
[17288.791514]  [<ffffffff8101265b>] ? __switch_to+0x19b/0x5e0
[17288.791521]  [<ffffffff811a998a>] __alloc_pages_nodemask+0x19a/0xa10
[17288.791527]  [<ffffffff811a7db6>] ? free_hot_cold_page_list+0x56/0xb0
[17288.791534]  [<ffffffff811f4778>] alloc_pages_vma+0xb8/0x230
[17288.791540]  [<ffffffff811d2c3c>] handle_mm_fault+0x10ec/0x1840
[17288.791546]  [<ffffffff810cea88>] ? __enqueue_entity+0x78/0x80
[17288.791552]  [<ffffffff810d8b29>] ? pick_next_task_fair+0x919/0x970
[17288.791558]  [<ffffffff81063d33>] __do_page_fault+0x193/0x440
[17288.791563]  [<ffffffff81064011>] do_page_fault+0x31/0x70
[17288.791568]  [<ffffffff8178bb08>] page_fault+0x28/0x30
[17289.351078] hfsplus: recoff 14131 too large
[17289.900811] hfsplus: recoff 14131 too large
[17290.059094] hfsplus: recoff 16933 too large
[17323.760264] hfsplus: recoff 27392 too large
[17323.761847] hfsplus: recoff 27392 too large
[17323.762163] hfsplus: recoff 27392 too large
[17323.762435] hfsplus: recoff 27392 too large
[17323.762545] hfsplus: recoff 27392 too large
[17323.762811] hfsplus: recoff 27392 too large
[17323.763119] hfsplus: recoff 27392 too large
[17323.763236] hfsplus: recoff 27392 too large
[17323.763345] hfsplus: recoff 27392 too large
[17323.763453] hfsplus: recoff 27392 too large
[17323.763725] hfsplus: recoff 27392 too large
[17348.390526] hfsplus: recoff 30565 too large
[17348.390629] hfsplus: recoff 30565 too large
[17371.062906] hfsplus: bad catalog entry type
[17371.062944] hfsplus: bad catalog entry type
[17387.389622] hfsplus: recoff 22364 too large
[17387.501186] hfsplus: recoff 22364 too large
[17394.430052] hfsplus: walked past end of dir
[17394.430099] hfsplus: walked past end of dir
[17395.077257] hfsplus: recoff 18688 too large
[17395.081749] hfsplus: recoff 18688 too large
[17395.086034] hfsplus: recoff 18688 too large
[17395.090322] hfsplus: recoff 18688 too large
[17395.094605] hfsplus: recoff 18688 too large
[17395.099004] hfsplus: recoff 18688 too large
[17395.103987] hfsplus: recoff 18688 too large
[17395.108969] hfsplus: recoff 18688 too large
[17395.113921] hfsplus: recoff 18688 too large
[17395.123899] hfsplus: recoff 18688 too large
[17395.128711] hfsplus: recoff 18688 too large
[17395.133313] hfsplus: recoff 18688 too large
[17395.142577] hfsplus: recoff 18688 too large
[17395.147776] hfsplus: recoff 18688 too large
[17395.157595] hfsplus: recoff 18688 too large
[17399.292963] BUG: Bad page state in process qemu-nbd  pfn:2307de
[17399.292975] page:ffffea0008c1f780 count:0 mapcount:0 mapping:
   (null) index:0x2
[17399.292979] flags: 0x5ffff800000004(referenced)
[17399.292986] page dumped because: PAGE_FLAGS_CHECK_AT_PREP flag set
[17399.292988] bad because of flags:
[17399.292991] flags: 0x4(referenced)
[17399.292995] Modules linked in: nls_utf8 hfsplus nbd uas usb_storage
fuse ccm ip6t_rpfilter ip6t_REJECT nf_reject_ipv6 xt_conntrack
ebtable_nat ebtable_broute bridge stp llc ebtable_filter ebtables
ip6table_nat nf_conntrack_ipv6 nf_defrag_ipv6 nf_nat_ipv6
ip6table_mangle ip6table_security ip6table_raw ip6table_filter
ip6_tables iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4
nf_nat nf_conntrack iptable_mangle iptable_security iptable_raw vfat
fat uvcvideo videobuf2_vmalloc videobuf2_core videobuf2_memops
v4l2_common videodev ath3k btusb bluetooth media kvm_amd kvm
snd_hda_codec_realtek snd_hda_codec_hdmi snd_hda_codec_generic arc4
ath9k ath9k_common snd_hda_intel crct10dif_pclmul snd_hda_controller
ath9k_hw crc32_pclmul ath snd_hda_codec crc32c_intel mac80211
snd_hwdep snd_seq snd_seq_device
[17399.293117]  snd_pcm ghash_clmulni_intel toshiba_acpi fam15h_power
edac_core edac_mce_amd cfg80211 snd_timer joydev rtsx_pci_ms memstick
serio_raw i2c_piix4 sparse_keymap k10temp wmi tpm_tis tpm video ccp
acpi_cpufreq rfkill snd soundcore shpchp toshiba_haps
toshiba_bluetooth nfsd auth_rpcgss nfs_acl lockd grace sunrpc
vboxnetadp(O) vboxnetflt(O) binfmt_misc vboxdrv(O) radeon
rtsx_pci_sdmmc mmc_core i2c_algo_bit drm_kms_helper ttm drm r8169
rtsx_pci mii mfd_core
[17399.293181] CPU: 3 PID: 14819 Comm: qemu-nbd Tainted: G    B      O
   4.0.5-300.fc22.x86_64 #1
[17399.293185] Hardware name: TOSHIBA SATELLITE C50D-B/ZBWAE, BIOS
1.30 06/06/2014
[17399.293189]  0000000000000000 00000000ffffffff ffff88010a30b948
ffffffff817834f4
[17399.293194]  0000000000000000 ffffea0008c1f780 ffff88010a30b978
ffffffff811a48ec
[17399.293199]  ffffffff811c0330 ffff88010a30bb38 ffff88023ed98e38
ffff88023ed98e58
[17399.293205] Call Trace:
[17399.293219]  [<ffffffff817834f4>] dump_stack+0x45/0x57
[17399.293227]  [<ffffffff811a48ec>] bad_page.part.62+0xbc/0x110
[17399.293234]  [<ffffffff811c0330>] ? zone_statistics+0x80/0xa0
[17399.293241]  [<ffffffff811a9135>] get_page_from_freelist+0x4f5/0xab0
[17399.293249]  [<ffffffff813965a1>] ? cfq_dispatch_requests+0xaf1/0xca0
[17399.293256]  [<ffffffff811a998a>] __alloc_pages_nodemask+0x19a/0xa10
[17399.293263]  [<ffffffff810d3cfc>] ? update_curr+0x5c/0x160
[17399.293272]  [<ffffffff811f2e21>] alloc_pages_current+0x91/0x110
[17399.293277]  [<ffffffff8119fbdf>] __page_cache_alloc+0xaf/0xd0
[17399.293284]  [<ffffffff811ad601>] __do_page_cache_readahead+0x101/0x250
[17399.293291]  [<ffffffff81117a14>] ? futex_wait+0x204/0x290
[17399.293298]  [<ffffffff811ad9c4>] ondemand_readahead+0x274/0x280
[17399.293304]  [<ffffffff811adb1e>] page_cache_sync_readahead+0x2e/0x50
[17399.293309]  [<ffffffff811a1574>] generic_file_read_iter+0x504/0x620
[17399.293315]  [<ffffffff8121c92e>] new_sync_read+0x8e/0xd0
[17399.293321]  [<ffffffff8121dc38>] __vfs_read+0x18/0x50
[17399.293326]  [<ffffffff8121dcf7>] vfs_read+0x87/0x140
[17399.293331]  [<ffffffff8121dfea>] SyS_pread64+0x9a/0xc0
[17399.293339]  [<ffffffff81789b09>] system_call_fastpath+0x12/0x17
------------------

My previous experience with is problem has a sightly different oops,
but closer to what's in
http://www.spinics.net/lists/linux-fsdevel/msg63807.html
involving hfsplus_brec_find and hfsplus_bnode_read .

I remember there were other simular reports concerning updatedb,but I
could only find
https://bugs.launchpad.net/ubuntu/+source/linux/+bug/740814
https://bugs.launchpad.net/ubuntu/+source/linux/+bug/1027887
No doubt there are more.

I agree that Sergei needs to explain the problem clearer though.