On Mon, Jul 17, 2023, 12:42 PM Ojaswin Mujoo <ojaswin@linux.ibm.com> wrote:

> On Mon, Jul 17, 2023 at 11:13:10AM +0530, Ritesh Harjani wrote:
> > Naresh Kamboju <naresh.kamboju@linaro.org> writes:
> >
> > > Following kernel BUG noticed while testing LTP fs testing on x86_64
> > > arch x86_64 on the Linux next-20230716 built with clang toolchain.
> > >
> > > I see a similar crash log on arm64 Juno-r2. The logs are shared below.
> > >
> > > Reported-by: Linux Kernel Functional Testing <lkft@linaro.org>
> > >
> > > x86 log:
> > > -------
> > > tst_test.c:1634: TINFO: === Testing on ext2 ===
> > > tst_test.c:1093: TINFO: Formatting /dev/loop0 with ext2 opts='' extra
> opts=''
> > > mke2fs 1.46.5 (30-Dec-2021)
> > > [ 1393.346989] EXT4-fs (loop0): mounting ext2 file system using the
> > > ext4 subsystem
> >
> > ext4 driver is used for ext2 filesystem here. It will be using indirect
> > block mapping path.
> >
> > > [ 1393.396754] EXT4-fs (loop0): mounted filesystem
> > > 7ca8e239-bc8f-488c-af12-5e0ef12d17a5 r/w without journal. Quota mode:
> > > none.
> > > fs_fill.c:115: TINFO: Running 6 writer threads
> > > tst_fill_fs.c:109: TINFO: writev(\"mntpoint/subdir/thread6/AOF\", iov,
> > > 512): ENOSPC
> > > tst_fill_fs.c:109: TINFO: writev(\"mntpoint/subdir/thread5/AOF\", iov,
> > > 512): ENOSPC
> > > ...
> > > tst_fill_fs.c:109: TINFO: writev(\"mntpoint/subdir/thread6/AOF\", iov,
> > > 512): ENOSPC
> > > tst_fill_fs.c:109: TINFO: writev(\"mntpoint/subdir/thread3/AOF\", iov,
> > > 512): ENOSPC
> > > tst_fill_fs.c:109: TINF[ 1393.817197] ------------[ cut here
> ]------------
> > > [ 1393.823305] kernel BUG at fs/ext4/mballoc.c:4369!
> >
> > It's hard to trigger the race I guess. But here are some debugging
> > information.
> >
> > [  955.508751] EXT4-fs (loop1): mounting ext2 file system using the ext4
> subsystem
> > [  955.515527] EXT4-fs (loop1): mounted filesystem
> 57096378-d173-4bc5-ac06-9cd53c1dfa1c r/w without journal. Quota mode: none.
> > [  959.289672] EXT4-fs (loop1): unmounting filesystem
> 57096378-d173-4bc5-ac06-9cd53c1dfa1c.
> > [  959.490548] EXT4-fs (loop1): mounting ext3 file system using the ext4
> subsystem
> > [  959.503719] EXT4-fs (loop1): mounted filesystem
> 841c90bd-4d83-4bc5-be10-39452034e84b r/w with ordered data mode. Quota
> mode: none.
> > [  960.553669] ext4_mb_pa_adjust_overlap: ==== This should not happend
> ==== left_pa=ffff8881471c7f50 deleted=0 lstart=6144 len=656
> right_pa=0000000000000000
> > [  960.557437] ext4_mb_pa_adjust_overlap: pa = ffff8881471c7540,
> deleted=1 lstart=5872 len=272 pstart=34560
> > [  960.560659] ext4_mb_pa_adjust_overlap: pa = ffff8881471c7f50,
> deleted=0 lstart=6144 len=656 pstart=26848
> > [  960.563855] ext4_mb_pa_adjust_overlap: pa = ffff8881471c7ee0,
> deleted=1 lstart=6623 len=2 pstart=45503
> >
> > (This is the rbtree printed ^^^ )
> >
> > (gdb) p ac->ac_o_ex
> > $8 = {
> >   fe_logical = 6625,
> >   fe_start = 27328,
> >   fe_group = 0,
> >   fe_len = 1
> > }
> > (gdb) p new_start
> > $9 = 6144
> > (gdb) p new_end
> > $10 = 8192
> > (gdb) p left_pa_end
> > $11 = 6800
> >
> >
> > The bug one happens here -
> >
> >       if (left_pa) {
> >               left_pa_end =
> >                       left_pa->pa_lstart + EXT4_C2B(sbi,
> left_pa->pa_len);
> >               BUG_ON(left_pa_end > ac->ac_o_ex.fe_logical);
> >       }
> >
> > i.e. left_pa_end(6144 + 656 = 6800) > ac->ac_o_ex.fe_logical(6625)
> >
> > Thought of sharing this info which can save time for others.
>
> Hi Ritesh,
>
> Thanks for sharing the information. So it seems there's an overlapping
> preallocation already present in which case the request should ideally
> be satisfied by it and we shouldn't enter ext4_mb_normalize_request().
>

Yes. The undeleted PA in above tree should satisfy the request in
ext4_mb_use_preallocated() so it should have never gone into normalization
path.

And I don't think the PA rbtree can get entries inserted since we must be
holding the locks in write path.


> Further, the presence of deleted PAs can suggest a group discard is
> ongoing which happens low storage scenarios.
>

Yes it seems the test is doing ENOSPC testing and it's not easy to trigger
it. For me, I had kept it for overnight testing with some debug logs added.
Although I don't know if it got triggered in few hours or maybe more.

I'll try to replicate it in my setup and update here.


Sure, I haven't yet looked closely into the code yet. But I feel maybe with
the above debug information pasted it will be easy to find out why
ext4_mb_use_preallocated() was not successful.

-ritesh


> Regards,
> ojaswin
> >
> > > O: writev(\"mntpo[ 1393.828041] invalid opcode: 0000 [#1] PREEMPT SMP
> PTI
> > > [ 1393.834448] CPU: 3 PID: 8606 Comm: fs_fill Not tainted
> > > 6.5.0-rc1-next-20230714 #1
> > > [ 1393.841925] Hardware name: Supermicro SYS-5019S-ML/X11SSH-F, BIOS
> > > 2.0b 07/27/2017
> > > [ 1393.849396] RIP: 0010:ext4_mb_normalize_request+0x58f/0x5a0
> > > int[/ s1u3b9d3i.r8ode: d7 b4 fc ff 80 4b 59 02 e9 b4 fa ff ff 48 8b 7b
> > > 08 48 c7 c6 ba 35 7b 9a 48 c7 c2 75 26 83 9a e8 17 a9 02 00 0f 0b 0f
> > > 0b 0f 0b <0f> 0b 66 66 66 66 66 66 2e 0f 1f 84 00 00 00 00 00 90 90 90
> > > 90 90
> > > [ 1393.873879] RSP: 0018:ffffad2c03327708 EFLAGS: 00010212
> > > [ 1393.879098] RAX: 0000000080000000 RBX: 0000000000000000 RCX:
> 0000000000000000
> > > [ 1393.886228] RDX: 0000000000000800 RSI: 000000000000c000 RDI:
> 000000000000c000
> > > [ 1393.893353] RBP: ffffad2c03327770 R08: 00000000ffffffff R09:
> 000000000000bdac
> > > [ 1393.900487] R10: ffffa28309e47098 R11: ffffffff991a03a0 R12:
> ffffa283232a3620
> > > [ 1393.907611] R13: 0000000000000000 R14: ffffa283232a3658 R15:
> ffffa28309e47098
> > > [ 1393.914733] FS:  00007f6963e80640(0000) GS:ffffa2865fd80000(0000)
> > > knlGS:0000000000000000
> > > [ 1393.922811] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> > > [ 1393.928550] CR2: 00007f694c008ba8 CR3: 000000012cb72001 CR4:
> 00000000003706e0
> > > [ 1393.935681] DR0: 0000000000000000 DR1: 0000000000000000 DR2:
> 0000000000000000
> > > [ 1393.942804] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7:
> 0000000000000400
> > > [ 1393.949930] Call Trace:
> > > [ 1393.952374]  <TASK>
> > > [ 1393.954472]  ? __die_body+0x6c/0xc0
> > > [ 1393.957964]  ? die+0xae/0xe0
> > > [ 1393.960841]  ? do_trap+0x8d/0x160
> > > [ 1393.964159]  ? ext4_mb_normalize_request+0x58f/0x5a0
> > > [ 1393.969119]  ? handle_invalid_op+0x7f/0xd0
> > > [ 1393.973218]  ? ext4_mb_normalize_request+0x58f/0x5a0
> > > [ 1393.978183]  ? exc_invalid_op+0x36/0x50
> > > [ 1393.982023]  ? asm_exc_invalid_op+0x1f/0x30
> > > [ 1393.986210]  ? __pfx_ext4_dirty_inode+0x10/0x10
> > > [ 1393.990740]  ? ext4_mb_normalize_request+0x58f/0x5a0
> > > [ 1393.995698]  ? ext4_mb_normalize_request+0x311/0x5a0
> > > [ 1394.000664]  ? _raw_read_unlock+0x20/0x40
> > > [ 1394.004676]  ext4_mb_new_blocks+0x3c8/0xdf0
> > > [ 1394.008864]  ? mark_buffer_dirty_inode+0x26/0xb0
> > > [ 1394.013483]  ? __ext4_handle_dirty_metadata+0x7d/0x230
> > > [ 1394.018620]  ext4_ind_map_blocks+0x74e/0xc30
> > > [ 1394.022897]  ext4_map_blocks+0x2d6/0x640
> > > [ 1394.026821]  _ext4_get_block+0x92/0x150
> > > [ 1394.030659]  ext4_get_block+0x1b/0x30
> > > [ 1394.034316]  __block_write_begin_int+0x193/0x670
> > > [ 1394.038928]  ? __pfx_ext4_get_block+0x10/0x10
> > > [ 1394.043277]  ? __ext4_journal_start_sb+0x9f/0x210
> > > [ 1394.047974]  __block_write_begin+0x1f/0x50
> > > [ 1394.052065]  ext4_write_begin+0x1fa/0x520
> > > [ 1394.056072]  generic_perform_write+0xb7/0x260
> > > [ 1394.060431]  ext4_buffered_write_iter+0xcd/0x150
> > > [ 1394.065049]  ext4_file_write_iter+0x341/0x960
> > > [ 1394.069407]  ? iovec_from_user+0x53/0x110
> > > [ 1394.073420]  do_iter_write+0x202/0x320
> > > [ 1394.077173]  vfs_writev+0x19c/0x280
> > > [ 1394.080666]  do_writev+0x77/0x110
> > > [ 1394.083978]  __x64_sys_writev+0x23/0x30
> > > [ 1394.087816]  do_syscall_64+0x48/0xa0
> > > [ 1394.091386]  entry_SYSCALL_64_after_hwframe+0x6e/0xd8
> > > [ 1394.096440] RIP: 0033:0x7f696678aa7d
> > > [ 1394.100011] Code: 28 89 54 24 1c 48 89 74 24 10 89 7c 24 08 e8 0a
> > > 55 f8 ff 8b 54 24 1c 48 8b 74 24 10 41 89 c0 8b 7c 24 08 b8 14 00 00
> > > 00 0f 05 <48> 3d 00 f0 ff ff 77 33 44 89 c7 48 89 44 24 08 e8 5e 55 f8
> > > ff 48
> > > [ 1394.118756] RSP: 002b:00007f6963e7cdd0 EFLAGS: 00000293 ORIG_RAX:
> > > 0000000000000014
> > > [ 1394.126315] RAX: ffffffffffffffda RBX: 0000000000000001 RCX:
> 00007f696678aa7d
> > > [ 1394.133436] RDX: 0000000000000200 RSI: 00007f6963e7ce00 RDI:
> 0000000000000007
> > > [ 1394.140562] RBP: 0000000000d4bbe8 R08: 0000000000000000 R09:
> 0000000000000180
> > > [ 1394.147684] R10: 0000000000000180 R11: 0000000000000293 R12:
> 0000000000000007
> > > [ 1394.154809] R13: 0000000000000003 R14: 00007f6963e805c0 R15:
> 0000000000200000
> > > [ 1394.161933]  </TASK>
> > > [ 1394.164118] Modules linked in: tun x86_pkg_temp_thermal
> > > [ 1394.169352] ---[ end trace 0000000000000000 ]---
> > >
> > >
> > > Links:
> > >  -
> https://qa-reports.linaro.org/lkft/linux-next-master/build/next-20230714/testrun/18306459/suite/log-parser-test/tests/
> > >  -
> https://qa-reports.linaro.org/lkft/linux-next-master/build/next-20230714/testrun/18306459/suite/log-parser-test/test/check-kernel-bug/log
> > >  - https://lkft.validation.linaro.org/scheduler/job/6584529#L2195
> > >  -
> https://storage.tuxsuite.com/public/linaro/lkft/builds/2SY3QjxEGsLoae4uGpfjPnZqwKC/
> > >
> > >
> > > Juno-r2 log:
> > > ------------
> > >
> > > tst_test.c:1634: TINFO: === Testing on ext3 ===
> > > tst_test.c:1093: TINFO: Formatting /dev/loop0 with ext3 opts='' extra
> opts=''
> > > mke2fs 1.46.5 (30-Dec-2021)
> > > [ 2086.751198] EXT4-fs (loop0): mounting ext3 file system using the
> > > ext4 subsystem
> > > [ 2086.802353] EXT4-fs (loop0): mounted filesystem
> > > 0b1ac79e-51b8-47a0-b8c8-13ff4c4c2459 r/w with ordered data mode. Quota
> > > mode: none.
> > > [ 2092.630907]
> ==================================================================
> > > [ 2092.638172] BUG: KASAN: slab-use-after-free in
> > > copy_page_from_iter_atomic+0x778/0x8c8
> >
> > This seems to be a different issue than above.
> >
> >
> > > [ 2092.646046] Read of size 1024 at addr ffff000834540000 by task
> > > kworker/u12:1/15943
> > > [ 2092.653643]
> > > [ 2092.655141] CPU: 2 PID: 15943 Comm: kworker/u12:1 Not tainted
> > > 6.5.0-rc1-next-20230714 #1
> > > [ 2092.663264] Hardware name: ARM Juno development board (r2) (DT)
> > > [ 2092.669204] Workqueue: loop0 loop_rootcg_workfn
> > > [ 2092.673773] Call trace:
> > > [ 2092.676226]  dump_backtrace+0x9c/0x128
> > > [ 2092.679997]  show_stack+0x20/0x38
> > > [ 2092.683328]  dump_stack_lvl+0x60/0xb0
> > > [ 2092.687009]  print_report+0xf4/0x5b0
> > > [ 2092.690607]  kasan_report+0xa8/0x100
> > > [ 2092.694204]  kasan_check_range+0xe8/0x190
> > > [ 2092.698231]  memcpy+0x3c/0xa0
> > > [ 2092.701213]  copy_page_from_iter_atomic+0x778/0x8c8
> > > [ 2092.706113]  generic_perform_write+0x1b4/0x318
> > > [ 2092.710576]  ext4_buffered_write_iter+0x98/0x1a8
> > > [ 2092.715217]  ext4_file_write_iter+0xf0/0xb20
> > > [ 2092.719507]  do_iter_readv_writev+0x134/0x200
> > > [ 2092.723889]  do_iter_write+0xd8/0x390
> > > [ 2092.727572]  vfs_iter_write+0x60/0x88
> > > [ 2092.731256]  loop_process_work+0x8f0/0x1000
> > > [ 2092.735463]  loop_rootcg_workfn+0x28/0x40
> > > [ 2092.739495]  process_one_work+0x42c/0x888
> > > [ 2092.743524]  worker_thread+0xa4/0x6a8
> > > [ 2092.747203]  kthread+0x19c/0x1b0
> > > [ 2092.750450]  ret_from_fork+0x10/0x20
> > > [ 2092.754045]
> > > [ 2092.755539] Allocated by task 15409:
> > > [ 2092.759126]  kasan_save_stack+0x2c/0x58
> > > [ 2092.762986]  kasan_set_track+0x2c/0x40
> > > [ 2092.766756]  kasan_save_alloc_info+0x24/0x38
> > > [ 2092.771044]  __kasan_slab_alloc+0xa8/0xb0
> > > [ 2092.775075]  kmem_cache_alloc+0x130/0x330
> > > [ 2092.779105]  jbd2_alloc+0x78/0x90
> > > [ 2092.782437]  do_get_write_access+0x2b8/0x758
> > > [ 2092.786728]  jbd2_journal_get_write_access+0xb0/0xf8
> > > [ 2092.791715]  __ext4_journal_get_write_access+0xc4/0x250
> > > [ 2092.796968]  ext4_reserve_inode_write+0xe0/0x138
> > > [ 2092.801610]  __ext4_mark_inode_dirty+0xe4/0x3e8
> > > [ 2092.806164]  ext4_dirty_inode+0x8c/0xb8
> > > [ 2092.810021]  __mark_inode_dirty+0x84/0x618
> > > [ 2092.814138]  generic_write_end+0x170/0x180
> > > [ 2092.818253]  ext4_da_write_end+0x120/0x3d0
> > > [ 2092.822372]  generic_perform_write+0x1ec/0x318
> > > [ 2092.826835]  ext4_buffered_write_iter+0x98/0x1a8
> > > [ 2092.831472]  ext4_file_write_iter+0xf0/0xb20
> > > [ 2092.835760]  vfs_write+0x450/0x550
> > > [ 2092.839176]  ksys_write+0xcc/0x178
> > > [ 2092.842592]  __arm64_sys_write+0x4c/0x68
> > > [ 2092.846530]  invoke_syscall+0x68/0x198
> > > [ 2092.850303]  el0_svc_common.constprop.0+0x12c/0x168
> > > [ 2092.855206]  do_el0_svc+0x4c/0xd8
> > > [ 2092.858541]  el0_svc+0x30/0x70
> > > [ 2092.861612]  el0t_64_sync_handler+0x13c/0x158
> > > [ 2092.865990]  el0t_64_sync+0x190/0x198
> > > [ 2092.869668]
> > > [ 2092.871163] The buggy address belongs to the object at
> ffff000834540000
> > > [ 2092.871163]  which belongs to the cache jbd2_1k of size 1024
> > > [ 2092.883459] The buggy address is located 0 bytes inside of
> > > [ 2092.883459]  freed 1024-byte region [ffff000834540000,
> ffff000834540400)
> > > [ 2092.895670]
> > > [ 2092.897164] The buggy address belongs to the physical page:
> > > [ 2092.902751] page:0000000021bf671c refcount:1 mapcount:0
> > > mapping:0000000000000000 index:0xffff000834540000 pfn:0x8b4540
> > > [ 2092.913485] head:0000000021bf671c order:3 entire_mapcount:0
> > > nr_pages_mapped:0 pincount:0
> > > [ 2092.921602] flags:
> > > 0xbfffc0000010200(slab|head|node=0|zone=2|lastcpupid=0xffff)
> > > [ 2092.928944] page_type: 0xffffffff()
> > > [ 2092.932452] raw: 0bfffc0000010200 ffff00082b6c4000 dead000000000122
> > > 0000000000000000
> > > [ 2092.940224] raw: ffff000834540000 000000008010000f 00000001ffffffff
> > > 0000000000000000
> > > [ 2092.947989] page dumped because: kasan: bad access detected
> > > [ 2092.953576]
> > > [ 2092.955070] Memory state around the buggy address:
> > > [ 2092.959877]  ffff00083453ff00: ff ff ff ff ff ff ff ff ff ff ff ff
> > > ff ff ff ff
> > > [ 2092.967123]  ffff00083453ff80: ff ff ff ff ff ff ff ff ff ff ff ff
> > > ff ff ff ff
> > > [ 2092.974368] >ffff000834540000: fb fb fb fb fb fb fb fb fb fb fb fb
> > > fb fb fb fb
> > > [ 2092.981610]                    ^
> > > [ 2092.984849]  ffff000834540080: fb fb fb fb fb fb fb fb fb fb fb fb
> > > fb fb fb fb
> > > [ 2092.992094]  ffff000834540100: fb fb fb fb fb fb fb fb fb fb fb fb
> > > fb fb fb fb
> > > [ 2092.999336]
> ==================================================================
> > > [ 2093.006683] Disabling lock debugging due to kernel taint
> > > [ 2099.278554] preadv203 (103227): drop_caches: 3
> > > [ 2099.514899] preadv203 (103228): drop_caches: 3
> > > [ 2099.552185] preadv203 (103228): drop_caches: 3
> > > [ 2099.586917] preadv203 (103228): drop_caches: 3
> > >
> > > Links:
> > >  -
> https://qa-reports.linaro.org/lkft/linux-next-master/build/next-20230714/testrun/18303379/suite/log-parser-test/tests/
> > >  - https://lkft.validation.linaro.org/scheduler/job/6584681#L2640
> > >  -
> https://storage.tuxsuite.com/public/linaro/lkft/builds/2SY3ZSm0bzBoyQkWFQAYYZru1UJ/
> > >
> > >
> > > --
> > > Linaro LKFT
> > > https://lkft.linaro.org
> >
> > -ritesh
>