Received-SPF: pass (google.com: domain of linux-ext4-owner@vger.kernel.org designates 2620:137:e000::1:20 as permitted sender) client-ip=2620:137:e000::1:20;
Date:   Mon, 17 Jul 2023 12:42:35 +0530
From:   Ojaswin Mujoo <ojaswin@linux.ibm.com>
To:     Ritesh Harjani <ritesh.list@gmail.com>
Cc:     Naresh Kamboju <naresh.kamboju@linaro.org>,
        open list <linux-kernel@vger.kernel.org>,
        linux-mm <linux-mm@kvack.org>, lkft-triage@lists.linaro.org,
        linux-ext4 <linux-ext4@vger.kernel.org>,
        LTP List <ltp@lists.linux.it>,
        Andrew Morton <akpm@linux-foundation.org>,
        Arnd Bergmann <arnd@arndb.de>,
        Dan Carpenter <dan.carpenter@linaro.org>,
        "Theodore Ts'o" <tytso@mit.edu>,
        Andreas Dilger <adilger.kernel@dilger.ca>
Subject: Re: next: kernel BUG at fs/ext4/mballoc.c:4369!
Message-ID: <ZLTp4xyWPkBrPBgF@li-bb2b2a4c-3307-11b2-a85c-8fa5c3a69313.ibm.com>
References: <CA+G9fYv2FRpLqBZf34ZinR8bU2_ZRAUOjKAD3+tKRFaEQHtt8Q@mail.gmail.com>
 <87o7kbnle9.fsf@doe.com>
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
In-Reply-To: <87o7kbnle9.fsf@doe.com>
MIME-Version: 1.0
Precedence: bulk

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().

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

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

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