On 2020/6/11 10:28, Dave Chinner wrote
Actually, it's a lot simpler:
thread1 thread2
__xfs_trans_commit
xfs_log_commit_cil
xlog_wait
schedule
xlog_cil_push_work
wake_up_all
<shutdown aborts commit>
xlog_cil_committed
kmem_free
remove_wait_queue
spin_lock_irqsave --> UAF
It's ture in this case, however, I got another result when I
tried to reporduce it, which seems 'ctx' can be freed in a
different path:
[ 64.975996] run fstests generic/019 at 2020-06-10 16:13:44
[ 69.126208] xfs filesystem being mounted at /tmp/scratch supports
timestamps until 2038 (0x7fffffff)
[ 99.166846] XFS (sdb): log I/O error -5
[ 99.170111] XFS (sdb): Log I/O Error Detected. Shutting down filesystem
[ 99.171071] XFS (sdb): Please unmount the filesystem and rectify the
problem(s)
[ 99.179569] ------------[ cut here ]------------
[ 99.180432] WARNING: CPU: 7 PID: 2705 at fs/iomap/buffered-io.c:1030
iomap_page_mkwrite_actor+0x17d/0x1b0
[ 99.181273]
==================================================================
[ 99.181758] Modules linked in:
[ 99.182806] BUG: KASAN: use-after-free in do_raw_spin_trylock+0x67/0x180
[ 99.183255] CPU: 7 PID: 2705 Comm: fio Not tainted
5.7.0-next-20200602+ #29
[ 99.184166] Read of size 4 at addr ffff888115f28868 by task fio/2704
[ 99.184171]
[ 99.185142] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996),
BIOS ?-20190727_073836-buildvm-ppc64le-16.ppc.fedoraproject.org-3.fc31
04/01/2014
[ 99.185995] CPU: 6 PID: 2704 Comm: fio Not tainted
5.7.0-next-20200602+ #29
[ 99.186227] RIP: 0010:iomap_page_mkwrite_actor+0x17d/0x1b0
[ 99.188199] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996),
BIOS ?-20190727_073836-buildvm-ppc64le-16.ppc.fedoraproject.org-3.fc31
04/01/2014
[ 99.189178] Code: 89 ef e8 a6 d4 c7 ff e9 3f ff ff ff e8 fc 64 ad ff
89 da 31 f6 48 89 ef e8 b0 1e f2 ff 49 89 dc e9 26 ff ff ff e8 e3 64 ad
ff <0f> 0b eb be e8 da 64 ad ff 4d 8d 67 ffe
[ 99.189899] Call Trace:
[ 99.191748] RSP: 0000:ffff88810599fa18 EFLAGS: 00010293
[ 99.194218] dump_stack+0xf6/0x16e
[ 99.194574] RAX: ffff888106df3680 RBX: 0000000000001000 RCX:
ffffffff94338cad
[ 99.195301] ? do_raw_spin_trylock+0x67/0x180
[ 99.195777] RDX: 0000000000000000 RSI: 0000000000000000 RDI:
0000000000000001
[ 99.195786] RBP: ffffea0002544800 R08: ffff888106df3680 R09:
fffff940004a8901
[ 99.196764] ? do_raw_spin_trylock+0x67/0x180
[ 99.196778] print_address_description.constprop.0.cold+0xd3/0x415
[ 99.197393] R10: ffffea0002544807 R11: fffff940004a8900 R12:
0000000000000000
[ 99.198380] ? do_raw_spin_trylock+0x67/0x180
[ 99.199349] R13: 0000000000000000 R14: ffff8880b6ee7280 R15:
ffffea00025447c8
[ 99.199939] kasan_report.cold+0x1f/0x37
[ 99.199949] ? __switch_to+0x510/0xef0
[ 99.200812] FS: 00007ff7d8562740(0000) GS:ffff88811a400000(0000)
knlGS:0000000000000000
[ 99.201755] ? do_raw_spin_trylock+0x67/0x180
[ 99.201765] check_memory_region+0x14e/0x1b0
[ 99.202378] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 99.203319] do_raw_spin_trylock+0x67/0x180
[ 99.203858] CR2: 00007ff7ae3e4ff0 CR3: 00000001028be000 CR4:
00000000000006e0
[ 99.204374] ? do_raw_spin_lock+0x290/0x290
[ 99.205470] DR0: 0000000000000000 DR1: 0000000000000000 DR2:
0000000000000000
[ 99.206069] _raw_spin_lock_irqsave+0x44/0x80
[ 99.206641] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7:
0000000000000400
[ 99.206647] Call Trace:
[ 99.207420] ? remove_wait_queue+0x22/0x190
[ 99.208014] iomap_apply+0x2d7/0xc00
[ 99.208949] remove_wait_queue+0x22/0x190
[ 99.209539] ? iomap_page_create+0x350/0x350
[ 99.210510] xfs_log_commit_cil+0x1c7e/0x2940
[ 99.211115] ? trace_event_raw_event_iomap_apply+0x430/0x430
[ 99.212073] ? xlog_cil_empty+0x90/0x90
[ 99.212421] ? down_write_trylock+0x2f0/0x2f0
[ 99.212979] ? check_flags.part.0+0x430/0x430
[ 99.213486] ? update_time+0xc0/0xc0
[ 99.214025] ? wake_up_q+0x140/0x140
[ 99.214610] iomap_page_mkwrite+0x26a/0x3b0
[ 99.215201] ? xlog_ticket_alloc+0x3e0/0x3e0
[ 99.215966] ? iomap_page_create+0x350/0x350
[ 99.216487] ? __kasan_kmalloc.constprop.0+0xc2/0xd0
[ 99.217097] __xfs_filemap_fault.constprop.0+0x32f/0x4e0
[ 99.217675] __xfs_trans_commit+0x2b3/0xf20
[ 99.218206] do_page_mkwrite+0x1b1/0x470
[ 99.218681] ? xfs_trans_unreserve_and_mod_sb+0xab0/0xab0
[ 99.219259] do_wp_page+0x9e7/0x1b10
[ 99.219838] ? xfs_isilocked+0x8c/0x2f0
[ 99.220439] ? finish_mkwrite_fault+0x4b0/0x4b0
[ 99.221102] ? xfs_trans_log_inode+0x1b2/0x480
[ 99.221817] ? do_user_addr_fault+0x2fd/0xd42
[ 99.222382] xfs_vn_update_time+0x40a/0x730
[ 99.222922] handle_mm_fault+0x1c9f/0x3600
[ 99.223634] ? xfs_setattr_mode.isra.0+0xb0/0xb0
[ 99.224140] ? __pmd_alloc+0x390/0x390
[ 99.224653] ? current_time+0xad/0x110
[ 99.225278] ? vmacache_find+0x5a/0x2a0
[ 99.225861] ? timestamp_truncate+0x2f0/0x2f0
[ 99.226461] do_user_addr_fault+0x635/0xd42
[ 99.227019] ? xfs_setattr_mode.isra.0+0xb0/0xb0
[ 99.227029] update_time+0x75/0xc0
[ 99.227760] exc_page_fault+0x12a/0x6f0
[ 99.228377] file_update_time+0x2bc/0x490
[ 99.228889] ? asm_exc_page_fault+0x8/0x30
[ 99.229414] ? update_time+0xc0/0xc0
[ 99.229933] asm_exc_page_fault+0x1e/0x30
[ 99.230515] ? __sb_start_write+0x225/0x3f0
[ 99.231099] RIP: 0033:0x7ff7d709636a
[ 99.231743] ? __sb_start_write+0x1a3/0x3f0
[ 99.231755] __xfs_filemap_fault.constprop.0+0x313/0x4e0
[ 99.232230] Code: Bad RIP value.
[ 99.232747] do_page_mkwrite+0x1b1/0x470
[ 99.233296] RSP: 002b:00007ffd89c6e2a8 EFLAGS: 00010206
[ 99.233841] do_wp_page+0x9e7/0x1b10
[ 99.234333] RAX: 00007ff7ae3e4000 RBX: 000000000159c280 RCX:
000000000159d3d0
[ 99.234863] ? finish_mkwrite_fault+0x4b0/0x4b0
[ 99.235432] RDX: 0000000000000fc0 RSI: 000000000159c420 RDI:
00007ff7ae3e4000
[ 99.235906] ? _raw_spin_unlock_irq+0x24/0x30
[ 99.236485] RBP: 00007ff7af493190 R08: 0000000000000000 R09:
00007ff7ae3e4ff0
[ 99.237198] handle_mm_fault+0x1c9f/0x3600
[ 99.237638] R10: 00007ffd89d04000 R11: 00007ff7ae3e4ff0 R12:
0000000000000001
[ 99.238163] ? __pmd_alloc+0x390/0x390
[ 99.238861] R13: 0000000000001000 R14: 000000000159c2a8 R15:
00007ff7af493198
[ 99.238874] irq event stamp: 0
[ 99.239368] ? vmacache_find+0x5a/0x2a0
[ 99.240324] hardirqs last enabled at (0): [<0000000000000000>] 0x0
[ 99.240946] do_user_addr_fault+0x635/0xd42
[ 99.241903] hardirqs last disabled at (0): [<ffffffff93b3715c>]
copy_process+0x182c/0x64b0
[ 99.242488] exc_page_fault+0x12a/0x6f0
[ 99.243447] softirqs last enabled at (0): [<ffffffff93b371fd>]
copy_process+0x18cd/0x64b0
[ 99.244001] ? asm_exc_page_fault+0x8/0x30
[ 99.244959] softirqs last disabled at (0): [<0000000000000000>] 0x0
[ 99.244965] ---[ end trace a1aa182be3fbd861 ]---
[ 99.245482] asm_exc_page_fault+0x1e/0x30
[ 99.254277] RIP: 0033:0x7ff7d709636a
[ 99.254749] Code: Bad RIP value.
[ 99.255182] RSP: 002b:00007ffd89c6e2a8 EFLAGS: 00010206
[ 99.255879] RAX: 00007ff7ae7f5000 RBX: 000000000159c280 RCX:
000000000159d3d0
[ 99.256815] RDX: 0000000000000fc0 RSI: 000000000159c420 RDI:
00007ff7ae7f5000
[ 99.257760] RBP: 00007ff7af47a3a0 R08: 0000000000000000 R09:
00007ff7ae7f5ff0
[ 99.258720] R10: 00007ffd89d04000 R11: 00007ff7ae7f5ff0 R12:
0000000000000001
[ 99.259727] R13: 0000000000001000 R14: 000000000159c2a8 R15:
00007ff7af47a3a8
[ 99.260722]
[ 99.260934] Allocated by task 986:
[ 99.261403] save_stack+0x1b/0x40
[ 99.261843] __kasan_kmalloc.constprop.0+0xc2/0xd0
[ 99.262483] __kmalloc+0x179/0x3e0
[ 99.262937] kmem_alloc+0x175/0x4a0
[ 99.263416] xlog_cil_push_work+0x104/0x1250
[ 99.264038] process_one_work+0xa62/0x1840
[ 99.264583] worker_thread+0xa3/0x1050
[ 99.265087] kthread+0x35a/0x470
[ 99.265520] ret_from_fork+0x22/0x30
[ 99.266021]
[ 99.266238] Freed by task 1123:
[ 99.266658] save_stack+0x1b/0x40
[ 99.267095] __kasan_slab_free+0x117/0x160
[ 99.267652] kfree+0xdf/0x320
[ 99.268070] kvfree+0x47/0x50
[ 99.268500] xlog_cil_committed+0xaf0/0xf80
[ 99.269104] xlog_cil_process_committed+0xfe/0x1e0
[ 99.269743] xlog_state_do_callback+0x513/0x9b0
[ 99.270335] xfs_log_force_umount+0x2d6/0x4a0
[ 99.270925] xfs_do_force_shutdown+0xa2/0x220
[ 99.271514] xlog_ioend_work+0x13a/0x240
[ 99.272042] process_one_work+0xa62/0x1840
[ 99.272582] worker_thread+0xa3/0x1050
[ 99.273104] kthread+0x35a/0x470
[ 99.273527] ret_from_fork+0x22/0x30
[ 99.274008]
[ 99.274221] The buggy address belongs to the object at ffff888115f28800
[ 99.274221] which belongs to the cache kmalloc-512 of size 512
[ 99.275821] The buggy address is located 104 bytes inside of
[ 99.275821] 512-byte region [ffff888115f28800, ffff888115f28a00)
[ 99.277477] The buggy address belongs to the page:
[ 99.278121] page:ffffea000457ca00 refcount:1 mapcount:0
mapping:0000000000000000 index:0x0 head:ffffea000457ca00 order:3
compound_mapcount:0 compound_pincount:0
[ 99.279988] flags: 0x200000000010200(slab|head)
[ 99.280582] raw: 0200000000010200 ffffea0004156c00 0000000400000004
ffff888117c0e580
[ 99.281615] raw: 0000000000000000 0000000080200020 00000001ffffffff
0000000000000000
[ 99.282615] page dumped because: kasan: bad access detected
[ 99.283364]
[ 99.283585] Memory state around the buggy address:
[ 99.284227] ffff888115f28700: fc fc fc fc fc fc fc fc fc fc fc fc fc
fc fc fc
[ 99.285206] ffff888115f28780: fc fc fc fc fc fc fc fc fc fc fc fc fc
fc fc fc
[ 99.286164] >ffff888115f28800: fb fb fb fb fb fb fb fb fb fb fb fb fb
fb fb fb
[ 99.287116] ^
[ 99.287962] ffff888115f28880: fb fb fb fb fb fb fb fb fb fb fb fb fb
fb fb fb
[ 99.288915] ffff888115f28900: fb fb fb fb fb fb fb fb fb fb fb fb fb
fb fb fb
[ 99.289874]
==================================================================
Thanks!
Yu Kuai
