Message-ID: <CABymUCNq9yqhAS0zxg+-gsCjj0GgTd=wmT7TjOcRz2TTew8zDA@mail.gmail.com>
Date:   Mon, 14 Nov 2022 09:47:09 +0800
From:   Jun Nie <jun.nie@...aro.org>
To:     chao@...nel.org, jaegeuk@...nel.org,
        linux-f2fs-devel@...ts.sourceforge.net,
        Linux Kernel Mailing List <linux-kernel@...r.kernel.org>
Cc:     Lee Jones <joneslee@...gle.com>, davem@...emloft.net,
        edumazet@...gle.com, kuba@...nel.org, pabeni@...hat.com,
        netdev@...r.kernel.org
Subject: [BUG REPORT] f2fs: use-after-free during garbage collection

Hi  Chao & Jaegeuk,

There is a KASAN report[0] that shows invalid memory
access(use-after-free) in f2fs garbage collection process, and this
issue is fixed by a recent f2fs patch set[1]. The KASAN report is caused
by an abnormal sum->ofs_in_node value 0xc3f1 in the first check. And
the investigation indicates that the f2fs_summary_block address range
is not from f2fs_kzalloc() in build_curseg(). The memory
allocation/free happens in non-f2fs thread, such as network. So I
guess the f2fs subsystem is accessing memory that's not belong to f2fs
in some cases. With the below commit merged into mainline recently,
this  use-after-free issue disappears. But there is another thread
blocked issue as below. The patch c6ad7fd16657 check the valid
ofs_in_node and stop further gc. I am not sure whether it is expected
that the f2fs_summary_block address in gc thread is not from
allocation in build_curseg(). Because I am not familiar with f2fs.

Could you help comment on my question and new issue? Is there any work
in progress to fix the new blocked issue? Thanks!

[0] https://syzkaller.appspot.com/bug?id=4cbcff00422ea402c2e5be2bc041a8f4196d608c
[1] c6ad7fd16657 f2fs: fix to do sanity check on summary info

Log of new issue:
[  250.167041][   T58] INFO: task kworker/u16:1:11 blocked for more
than 122 seconds.
[  250.169071][   T58]       Not tainted 6.1.0-rc4+gc0daf896 #3
[  250.170443][   T58] "echo 0 >
/proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  250.172487][   T58] task:kworker/u16:1   state:D stack:0     pid:11
   ppid:2      flags:0x00004000
[  250.174678][   T58] Workqueue: writeback wb_workfn (flush-7:0)
[  250.176128][   T58] Call Trace:
[  250.176908][   T58]  <TASK>
[  250.177638][   T58]  __schedule+0x8b7/0x1940
[  250.178736][   T58]  ? io_schedule_timeout+0x150/0x150
[  250.180013][   T58]  ? __sanitizer_cov_trace_const_cmp4+0x16/0x20
[  250.181541][   T58]  ? kthread_data+0x5d/0xd0
[  250.182615][   T58]  schedule+0xec/0x1b0
[  250.183582][   T58]  io_schedule+0xcd/0x150
[  250.184619][   T58]  folio_wait_bit_common+0x35d/0x910
[  250.185919][   T58]  ? filemap_map_pages+0x1230/0x1230
[  250.187214][   T58]  ? add_gc_inode+0xc9/0x2e0
[  250.188323][   T58]  ? do_garbage_collect+0x2b47/0x3730
[  250.189597][   T58]  ? f2fs_gc+0x816/0x1df0
[  250.190629][   T58]  ? f2fs_balance_fs+0x391/0x420
[  250.191803][   T58]  ? f2fs_write_inode+0x598/0xe20
[  250.193009][   T58]  ? __writeback_single_inode+0x7b8/0xac0
[  250.194369][   T58]  ? writeback_sb_inodes+0x585/0xea0
[  250.195623][   T58]  ? wb_writeback+0x25c/0x8a0
[  250.196737][   T58]  ? wb_workfn+0x277/0xed0
[  250.197831][   T58]  ? folio_unlock+0x60/0x60
[  250.198943][   T58]  ? __sanitizer_cov_trace_const_cmp1+0x1a/0x20
[  250.200438][   T58]  ? xas_load+0x64/0x2e0
[  250.201459][   T58]  __filemap_get_folio+0x84c/0x900
[  250.202685][   T58]  ? filemap_add_folio+0x1c0/0x1c0
[  250.203937][   T58]  ? __sanitizer_cov_trace_const_cmp8+0x18/0x20
[  250.205454][   T58]  pagecache_get_page+0x36/0x130
[  250.206634][   T58]  __get_node_page.part.0+0xa7/0x960
[  250.207918][   T58]  f2fs_get_node_page+0x10f/0x190
[  250.209119][   T58]  do_garbage_collect+0x1bbc/0x3730
[  250.210377][   T58]  ? ra_data_block+0x860/0x860
[  250.211522][   T58]  f2fs_gc+0x816/0x1df0
[  250.212510][   T58]  ? f2fs_start_bidx_of_node+0x50/0x50
[  250.213816][   T58]  ? map_id_up+0x1a3/0x320
[  250.214872][   T58]  ? down_write+0xf7/0x170
[  250.215931][   T58]  ? down_write_killable+0x180/0x180
[  250.217213][   T58]  ? has_not_enough_free_secs.constprop.0+0x6d8/0x840
[  250.218824][   T58]  f2fs_balance_fs+0x391/0x420
[  250.219963][   T58]  ? f2fs_balance_fs_bg+0xf70/0xf70
[  250.221205][   T58]  ? __sanitizer_cov_trace_const_cmp4+0x16/0x20
[  250.222688][   T58]  ? __sanitizer_cov_trace_const_cmp1+0x1a/0x20
[  250.224174][   T58]  ? folio_unlock+0x3c/0x60
[  250.225274][   T58]  ? __sanitizer_cov_trace_const_cmp1+0x1a/0x20
[  250.226990][   T58]  ? f2fs_update_inode_page+0x1d4/0x4c0
[  250.228357][   T58]  f2fs_write_inode+0x598/0xe20
[  250.229522][   T58]  ? _raw_spin_lock_bh+0x110/0x110
[  250.230760][   T58]  ? __kasan_check_write+0x14/0x20
[  250.232017][   T58]  ? _raw_spin_lock+0x8b/0x110
[  250.233177][   T58]  __writeback_single_inode+0x7b8/0xac0
[  250.234503][   T58]  writeback_sb_inodes+0x585/0xea0
[  250.235727][   T58]  ? sync_inode_metadata+0xf0/0xf0
[  250.236951][   T58]  ? __sanitizer_cov_trace_const_cmp1+0x1a/0x20
[  250.238464][   T58]  ? queue_io+0x23d/0x450
[  250.239484][   T58]  wb_writeback+0x25c/0x8a0
[  250.240566][   T58]  ? __writeback_inodes_wb+0x270/0x270
[  250.241865][   T58]  ? _raw_spin_lock+0x110/0x110
[  250.243027][   T58]  ? __sanitizer_cov_trace_const_cmp4+0x16/0x20
[  250.244510][   T58]  ? kthread_data+0x5d/0xd0
[  250.245581][   T58]  wb_workfn+0x277/0xed0
[  250.246594][   T58]  ? __kasan_check_read+0x11/0x20
[  250.247841][   T58]  ? psi_group_change+0x716/0xc20
[  250.249055][   T58]  ? inode_wait_for_writeback+0x40/0x40
[  250.250378][   T58]  ? _raw_spin_unlock+0x45/0x70
[  250.251540][   T58]  ? finish_task_switch.isra.0+0x174/0x7e0
[  250.252923][   T58]  ? __switch_to+0x5da/0xef0
[  250.254019][   T58]  ? __kasan_check_read+0x11/0x20
[  250.255222][   T58]  ? read_word_at_a_time+0x12/0x20
[  250.256466][   T58]  ? strscpy+0x9a/0x2a0
[  250.257513][   T58]  process_one_work+0x735/0x1000
[  250.258695][   T58]  ? __sanitizer_cov_trace_const_cmp4+0x16/0x20
[  250.260184][   T58]  worker_thread+0x635/0x1050
[  250.261321][   T58]  kthread+0x2cf/0x380
[  250.262322][   T58]  ? process_one_work+0x1000/0x1000
[  250.263566][   T58]  ? kthread_complete_and_exit+0x40/0x40
[  250.264913][   T58]  ret_from_fork+0x1f/0x30
[  250.265970][   T58]  </TASK>
[  250.266711][   T58] INFO: task repro:392 blocked for more than 122 seconds.
[  250.268415][   T58]       Not tainted 6.1.0-rc4+gc0daf896 #3
[  250.269785][   T58] "echo 0 >
/proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  250.271823][   T58] task:repro           state:D stack:0
pid:392   ppid:390    flags:0x00004000
[  250.273999][   T58] Call Trace:
[  250.274771][   T58]  <TASK>
[  250.275461][   T58]  __schedule+0x8b7/0x1940
[  250.276520][   T58]  ? io_schedule_timeout+0x150/0x150
[  250.277799][   T58]  ? _raw_spin_unlock_irq+0x46/0x70
[  250.279045][   T58]  ? _raw_spin_unlock_irqrestore+0x51/0x90
[  250.280440][   T58]  schedule+0xec/0x1b0
[  250.281410][   T58]  wb_wait_for_completion+0x18c/0x260
[  250.282696][   T58]  ? wb_writeback+0x8a0/0x8a0
[  250.283814][   T58]  ? __kasan_check_read+0x11/0x20
[  250.285019][   T58]  ? prepare_to_wait_exclusive+0x250/0x250
[  250.286396][   T58]  ? __d_free_external+0x70/0x70
[  250.287659][   T58]  ? __call_rcu_nocb_wake.part.0+0x8b0/0x8b0
[  250.289105][   T58]  __writeback_inodes_sb_nr+0x215/0x2c0
[  250.290428][   T58]  ? bdi_split_work_to_wbs+0xaf0/0xaf0
[  250.291732][   T58]  ? _find_next_bit+0x11c/0x150
[  250.292929][   T58]  ? __sanitizer_cov_trace_cmp4+0x16/0x20
[  250.294391][   T58]  ? get_nr_dirty_inodes+0x12e/0x1c0
[  250.295663][   T58]  writeback_inodes_sb+0x6e/0x90
[  250.296855][   T58]  sync_filesystem.part.0+0x29/0x1e0
[  250.298162][   T58]  sync_filesystem+0x99/0xd0
[  250.299277][   T58]  generic_shutdown_super+0x7a/0x420
[  250.300545][   T58]  kill_block_super+0xa5/0x100
[  250.301687][   T58]  kill_f2fs_super+0x2e0/0x400
[  250.302826][   T58]  ? f2fs_dquot_mark_dquot_dirty+0x210/0x210
[  250.304254][   T58]  ? up_write+0x71/0xb0
[  250.305253][   T58]  ? unregister_shrinker+0x68/0x340
[  250.306496][   T58]  deactivate_locked_super+0xa2/0x180
[  250.307799][   T58]  deactivate_super+0xb8/0xd0
[  250.308920][   T58]  cleanup_mnt+0x2c7/0x3f0
[  250.309976][   T58]  __cleanup_mnt+0x1b/0x30
[  250.311065][   T58]  task_work_run+0x19e/0x2b0
[  250.312171][   T58]  ? task_work_cancel+0x30/0x30
[  250.313334][   T58]  ? __x64_sys_umount+0x12a/0x1a0
[  250.314528][   T58]  exit_to_user_mode_prepare+0x123/0x130
[  250.315863][   T58]  syscall_exit_to_user_mode+0x21/0x40
[  250.317185][   T58]  do_syscall_64+0x42/0x80
[  250.318272][   T58]  entry_SYSCALL_64_after_hwframe+0x63/0xcd
[  250.319728][   T58] RIP: 0033:0x7f189f0e8d77
[  250.320789][   T58] RSP: 002b:00007ffe4c4e7ab8 EFLAGS: 00000206
ORIG_RAX: 00000000000000a6
[  250.322794][   T58] RAX: 0000000000000000 RBX: 0000000000000000
RCX: 00007f189f0e8d77
[  250.324729][   T58] RDX: 00007ffe4c4e7b99 RSI: 000000000000000a
RDI: 00007ffe4c4e7b90
[  250.326612][   T58] RBP: 00007ffe4c4e8ba0 R08: 00005649086330a3
R09: 0000000000000009
[  250.328526][   T58] R10: 0000000000000073 R11: 0000000000000206
R12: 0000564906b91540
[  250.330408][   T58] R13: 00007ffe4c4e8cf0 R14: 0000000000000000
R15: 0000000000000000
[  250.332288][   T58]  </TASK>
[  250.333013][   T58] NMI backtrace for cpu 5
[  250.334033][   T58] CPU: 5 PID: 58 Comm: khungtaskd Not tainted
6.1.0-rc4+gc0daf896 #3
[  250.335937][   T58] Hardware name: QEMU Standard PC (i440FX + PIIX,
1996), BIOS 1.15.0-1 04/01/2014
[  250.338106][   T58] Call Trace:
[  250.338874][   T58]  <TASK>
[  250.339559][   T58]  dump_stack_lvl+0x75/0x9b
[  250.340638][   T58]  dump_stack+0x15/0x17
[  250.341625][   T58]  nmi_cpu_backtrace.cold+0xee/0xf3
[  250.342867][   T58]  ? lapic_can_unplug_cpu+0x80/0x80
[  250.344109][   T58]  nmi_trigger_cpumask_backtrace+0x251/0x2e0
[  250.345536][   T58]  arch_trigger_cpumask_backtrace+0x19/0x20
[  250.346938][   T58]  watchdog+0x9d1/0xb40
[  250.347920][   T58]  kthread+0x2cf/0x380
[  250.348915][   T58]  ? proc_dohung_task_timeout_secs+0x90/0x90
[  250.350375][   T58]  ? kthread_complete_and_exit+0x40/0x40
[  250.351713][   T58]  ret_from_fork+0x1f/0x30
[  250.352771][   T58]  </TASK>
[  250.353509][   T58] Sending NMI from CPU 5 to CPUs 0-4,6-7:
[  250.354943][    C1] NMI backtrace for cpu 1
[  250.354953][    C1] CPU: 1 PID: 195 Comm: systemd-journal Not
tainted 6.1.0-rc4+gc0daf896 #3
[  250.354974][    C1] Hardware name: QEMU Standard PC (i440FX + PIIX,
1996), BIOS 1.15.0-1 04/01/2014
[  250.354984][    C1] RIP: 0010:__stack_depot_save+0xcc/0x540
[  250.355016][    C1] Code: ee 03 48 83 c1 0c 8b 79 f4 03 41 f8 29 df
01 fa 89 df 01 c3 c1 c7 04 31 fa 89 d7 29 d0 01 da c1 c7 06 31 f8 89
c7 29 c3 01 d0 <c1> c7 08 31 fb 89 df 29 da 01 c3 c1 c7 10 31 fa 89 d7
29 d0 01 da
[  250.355035][    C1] RSP: 0018:ffffc900018a7a40 EFLAGS: 00000216
[  250.355050][    C1] RAX: 000000005f2a3d14 RBX: 0000000086514fa8
RCX: ffffc900018a7b14
[  250.355064][    C1] RDX: 000000000242647a RSI: 0000000000000005
RDI: 000000005ce7d89a
[  250.355076][    C1] RBP: ffffc900018a7ab0 R08: 000000000000000d
R09: 0000000000000000
[  250.355089][    C1] R10: 0000000000000000 R11: 000000000000000d
R12: 0000000000000000
[  250.355100][    C1] R13: 0000000000000000 R14: ffffc900018a7ac0
R15: 0000000000000001
[  250.355113][    C1] FS:  00007fdb4d99e8c0(0000)
GS:ffff8883eee80000(0000) knlGS:0000000000000000
[  250.355132][    C1] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  250.355146][    C1] CR2: 00007fdb490fe020 CR3: 000000011bc32000
CR4: 0000000000350ea0
[  250.355159][    C1] DR0: 0000000000000000 DR1: 0000000000000000
DR2: 0000000000000000
[  250.355170][    C1] DR3: 0000000000000000 DR6: 00000000fffe0ff0
DR7: 0000000000000400
[  250.355183][    C1] Call Trace:
[  250.355187][    C1]  <TASK>
[  250.355193][    C1]  ? lockref_get_not_dead+0x181/0x2a0
[  250.355225][    C1]  ? kmem_cache_free+0x1f4/0x3a0
[  250.355246][    C1]  kasan_save_stack+0x3d/0x50
[  250.355267][    C1]  ? kasan_save_stack+0x26/0x50
[  250.355287][    C1]  ? kasan_set_track+0x25/0x30
[  250.355307][    C1]  ? kasan_save_free_info+0x2e/0x50
[  250.355333][    C1]  ? ____kasan_slab_free+0x13a/0x1a0
[  250.355354][    C1]  ? __kasan_slab_free+0x12/0x20
[  250.355376][    C1]  ? slab_free_freelist_hook+0xd2/0x1a0
[  250.355409][    C1]  ? kmem_cache_free+0x1f4/0x3a0
[  250.355428][    C1]  ? putname+0x115/0x150
[  250.355449][    C1]  ? user_path_at_empty+0x56/0x70
[  250.355473][    C1]  ? do_faccessat+0x147/0x840
[  250.355498][    C1]  ? __x64_sys_access+0x60/0x80
[  250.355525][    C1]  ? do_syscall_64+0x35/0x80
[  250.355547][    C1]  ? entry_SYSCALL_64_after_hwframe+0x63/0xcd
[  250.355581][    C1]  ? __sanitizer_cov_trace_cmp4+0x16/0x20
[  250.355603][    C1]  ? dput+0x11c/0xb40
[  250.355620][    C1]  ? try_to_unlazy+0x278/0x4f0
[  250.355640][    C1]  ? mntput+0x79/0xa0
[  250.355656][    C1]  ? __sanitizer_cov_trace_const_cmp4+0x16/0x20
[  250.355679][    C1]  ? terminate_walk+0x334/0x5f0
[  250.355699][    C1]  ? __sanitizer_cov_trace_const_cmp4+0x16/0x20
[  250.355722][    C1]  ? walk_component+0x10e/0x5d0
[  250.355745][    C1]  ? path_lookupat+0x25f/0x840
[  250.355769][    C1]  ? __sanitizer_cov_trace_const_cmp4+0x16/0x20
[  250.355791][    C1]  ? filename_lookup+0x3d2/0x590
[  250.355816][    C1]  ? may_linkat+0x520/0x520
[  250.355840][    C1]  kasan_set_track+0x25/0x30
[  250.355861][    C1]  kasan_save_free_info+0x2e/0x50
[  250.355888][    C1]  ____kasan_slab_free+0x13a/0x1a0
[  250.355910][    C1]  __kasan_slab_free+0x12/0x20
[  250.355932][    C1]  slab_free_freelist_hook+0xd2/0x1a0
[  250.355966][    C1]  ? putname+0x115/0x150
[  250.355987][    C1]  kmem_cache_free+0x1f4/0x3a0
[  250.356044][    C1]  putname+0x115/0x150
[  250.356066][    C1]  user_path_at_empty+0x56/0x70
[  250.356091][    C1]  do_faccessat+0x147/0x840
[  250.356116][    C1]  ? ksys_read+0x1cc/0x290
[  250.356149][    C1]  ? stream_open+0x60/0x60
[  250.356174][    C1]  ? __secure_computing+0x181/0x2f0
[  250.356199][    C1]  __x64_sys_access+0x60/0x80
[  250.356226][    C1]  do_syscall_64+0x35/0x80
[  250.356248][    C1]  entry_SYSCALL_64_after_hwframe+0x63/0xcd
[  250.356299][    C1] Code: 83 c4 08 48 3d 01 f0 ff ff 73 01 c3 48 8b
0d c8 d4 2b 00 f7 d8 64 89 01 48 83 c8 ff c3 66 0f 1f 44 00 00 b8 15
00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d a1 d4 2b 00 f7 d8
64 89 01 48
[  250.356327][    C1] RSP: 002b:00007fff03576e68 EFLAGS: 00000246
ORIG_RAX: 0000000000000015
[  250.356345][    C1] RAX: ffffffffffffffda RBX: 00007fff03579d80
RCX: 00007fdb4c2db9c7
[  250.356358][    C1] RDX: 00007fdb4d360a00 RSI: 0000000000000000
RDI: 000055f4a1c229a3
[  250.356370][    C1] RBP: 00007fff03576ea0 R08: 0000000000000000
R09: 0000000000000000
[  250.356383][    C1] R10: 0000000000000069 R11: 0000000000000246
R12: 0000000000000000
[  250.356394][    C1] R13: 0000000000000000 R14: 00007fff03579d80
R15: 00007fff03577390
[  250.356420][    C3] NMI backtrace for cpu 3 skipped: idling at
default_idle+0x14/0x20


Regards,
Jun

Powered by blists - more mailing lists