lists.openwall.net   lists  /  announce  owl-users  owl-dev  john-users  john-dev  passwdqc-users  yescrypt  popa3d-users  /  oss-security  kernel-hardening  musl  sabotage  tlsify  passwords  /  crypt-dev  xvendor  /  Bugtraq  Full-Disclosure  linux-kernel  linux-netdev  linux-ext4  linux-hardening  linux-cve-announce  PHC 
Open Source and information security mailing list archives
 
Hash Suite: Windows password security audit tool. GUI, reports in PDF.
[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]
Message-ID: <Y7Yr3kEkDEd51xns@xsang-OptiPlex-9020>
Date:   Thu, 5 Jan 2023 09:46:06 +0800
From:   Oliver Sang <oliver.sang@...el.com>
To:     Hyeonggon Yoo <42.hyeyoo@...il.com>
CC:     Vlastimil Babka <vbabka@...e.cz>, <oe-lkp@...ts.linux.dev>,
        <lkp@...el.com>, Mike Rapoport <rppt@...ux.ibm.com>,
        Christoph Lameter <cl@...ux.com>,
        <linux-kernel@...r.kernel.org>, <linux-mm@...ck.org>,
        Matthew Wilcox <willy@...radead.org>
Subject: Re: [linus:master] [mm, slub] 0af8489b02:
 kernel_BUG_at_include/linux/mm.h

hi, Hyeonggon, hi, Vlastimil,

On Wed, Jan 04, 2023 at 06:04:20PM +0900, Hyeonggon Yoo wrote:
> On Tue, Jan 03, 2023 at 09:46:33PM +0800, Oliver Sang wrote:
> > On Tue, Jan 03, 2023 at 11:42:11AM +0100, Vlastimil Babka wrote:
> > > So the events leading up to this could be something like:
> > > 
> > > - 0x2daee is order-1 slab folio of the inode cache, sitting on the partial list
> > > - despite being on partial list, it's freed ???
> > > - somebody else allocates order-2 page 0x2daec and uses it for whatever,
> > > then frees it
> > > - 0x2daec is reallocated as order-1 slab from names_cache, then freed
> > > - we try to allocate from the slab page 0x2daee and trip on the PageTail
> > > 
> > > Except, the freeing of order-2 page would have reset the PageTail and
> > > compound_head in 0x2daec, so this is even more complicated or involves some
> > > extra race?
> > 
> > FYI, we ran tests more up to 500 times, then saw different issues but rate is
> > actually low
> > 
> > 56d5a2b9ba85a390 0af8489b0216fa1dd83e264bef8
> > ---------------- ---------------------------
> >        fail:runs  %reproduction    fail:runs
> >            |             |             |
> >            :500         12%          61:500   dmesg.invalid_opcode:#[##]
> >            :500          3%          14:500   dmesg.kernel_BUG_at_include/linux/mm.h
> >            :500          3%          17:500   dmesg.kernel_BUG_at_include/linux/page-flags.h
> >            :500          5%          26:500   dmesg.kernel_BUG_at_lib/list_debug.c
> >            :500          0%           2:500   dmesg.kernel_BUG_at_mm/page_alloc.c
> >            :500          0%           2:500   dmesg.kernel_BUG_at_mm/usercopy.c
> > 

hi Vlastimil,

as you mentioned
> Hm even if rate is low, the different kinds of reports could be useful to
> see, if all of that is caused by the commit.

we tried to run tests even more times, but with the config which enable
    CONFIG_DEBUG_PAGEALLOC
    CONFIG_DEBUG_PAGEALLOC_ENABLE_DEFAULT
(config is attached as
    config-6.1.0-rc2-00014-g0af8489b0216+CONFIG_DEBUG_PAGEALLOC+CONFIG_DEBUG_PAGEALLOC_ENABLE_DEFAULT
the only diff with previous config is
@@ -5601,7 +5601,8 @@ CONFIG_HAVE_KCSAN_COMPILER=y
 # Memory Debugging
 #
 CONFIG_PAGE_EXTENSION=y
-# CONFIG_DEBUG_PAGEALLOC is not set
+CONFIG_DEBUG_PAGEALLOC=y
+CONFIG_DEBUG_PAGEALLOC_ENABLE_DEFAULT=y
 CONFIG_PAGE_OWNER=y
 # CONFIG_PAGE_POISONING is not set
 CONFIG_DEBUG_PAGE_REF=y
)

what we found now is some issues are also reproduced on parent now (still by
rcutorture tests here), though seems lower rate on parent.

=========================================================================================
compiler/kconfig/rootfs/runtime/tbox_group/test/testcase/torture_type:
  gcc-11/i386-randconfig-a012-20221226+CONFIG_DEBUG_PAGEALLOC+CONFIG_DEBUG_PAGEALLOC_ENABLE_DEFAULT/debian-11.1-i386-20220923.cgz/300s/vm-snb/default/rcutorture/tasks-tracing

56d5a2b9ba85a390 0af8489b0216fa1dd83e264bef8
---------------- ---------------------------
       fail:runs  %reproduction    fail:runs
           |             |             |
          8:985         19%         199:990   dmesg.invalid_opcode:#[##]
           :985          5%          51:990   dmesg.kernel_BUG_at_include/linux/mm.h
          3:985          4%          41:990   dmesg.kernel_BUG_at_include/linux/page-flags.h
          4:985         10%         102:990   dmesg.kernel_BUG_at_lib/list_debug.c
           :985          0%           2:990   dmesg.kernel_BUG_at_mm/page_alloc.c
          1:985          0%           3:990   dmesg.kernel_BUG_at_mm/usercopy.c

however, we noticed dmesg.kernel_BUG_at_include/linux/mm.h still have
relatively high rate on this commit but keeps clean on parent.

so I attached dmesg-rcutorture-bug-at-mm-h.xz
since it has
[   33.586931][  T183] ------------[ cut here ]------------
[   33.590089][  T183] kernel BUG at include/linux/mm.h:825!
[   33.591219][  T183] invalid opcode: 0000 [#1] SMP DEBUG_PAGEALLOC
not sure if this is helpful.

> > > 
> > > In any case, this is something a debug_pagealloc kernel could have a chance
> > > of catching earlier. Would it be possible to enable CONFIG_DEBUG_PAGEALLOC
> > > and DEBUG_PAGEALLOC_ENABLE_DEFAULT additionally to the rest of the
> > > configuration, and repeat the test?
> > 
> > ok, we are starting to test by these 2 additional configs now.
> 
> BTW it seems to be totally unrelated to rcutorture tests.
> Are there similar reports in boot tests with the same config?

hi Hyeonggon,

per your suggestion (Thanks a lot!) we used same config as above which
enabled CONFIG_DEBUG_PAGEALLOC and CONFIG_DEBUG_PAGEALLOC_ENABLE_DEFAULT
to do boot tests. the results have some differences:

=========================================================================================
compiler/kconfig/rootfs/sleep/tbox_group/testcase:
  gcc-11/i386-randconfig-a012-20221226+CONFIG_DEBUG_PAGEALLOC+CONFIG_DEBUG_PAGEALLOC_ENABLE_DEFAULT/debian-11.1-i386-20220923.cgz/1/vm-snb/boot

56d5a2b9ba85a390 0af8489b0216fa1dd83e264bef8
---------------- ---------------------------
       fail:runs  %reproduction    fail:runs
           |             |             |
         11:999         20%         208:999   dmesg.invalid_opcode:#[##]
          2:999          5%          51:999   dmesg.kernel_BUG_at_include/linux/mm.h
          4:999          4%          40:999   dmesg.kernel_BUG_at_include/linux/page-flags.h
          4:999         11%         111:999   dmesg.kernel_BUG_at_lib/list_debug.c
           :999          0%           2:999   dmesg.kernel_BUG_at_mm/page_alloc.c
          1:999          0%           3:999   dmesg.kernel_BUG_at_mm/usercopy.c

here the dmesg.kernel_BUG_at_include/linux/mm.h is also reproduced on parent,
only issue shows on this commit but not on parent is (but rate is very low)
    dmesg.kernel_BUG_at_mm/page_alloc.c

I also attached dmesg-boot-bug-at-page_alloc-c.xz
which has
[   17.251777][    C0] ------------[ cut here ]------------
[   17.252218][    C0] kernel BUG at mm/page_alloc.c:1406!
[   17.252647][    C0] invalid opcode: 0000 [#1] SMP DEBUG_PAGEALLOC

If you need more information, please let us know. Thanks

> 
> > > 
> > > Separately we should also make the __dump_page() more resilient.
> > > 
> > > Thanks,
> > > Vlastimil
> > > 
> > > > [   25.804432][  T214] ------------[ cut here ]------------
> > > > [   25.804917][  T214] kernel BUG at include/linux/mm.h:825!
> > > > [   25.805402][  T214] invalid opcode: 0000 [#1] SMP
> > > > [   25.805820][  T214] CPU: 0 PID: 214 Comm: udevadm Tainted: G S                 6.1.0-rc2-00014-g0af8489b0216 #2 1c4d7707ec0ce574ed62a77e82a8580202758048
> > > > [   25.806944][  T214] EIP: __dump_page.cold+0x282/0x369
> > > > [   25.807376][  T214] Code: ff ff 83 05 e8 5d bb c5 01 ba 4c c4 2f c4 89 f8 83 15 ec 5d bb c5 00 e8 f2 92 ed fd 83 05 f8 5d bb c5 01 83 15 fc 5d bb c5 00 <0f> 0b 83 05 00 5e bb c5 01 b8 ac 85 a3 c4 83 15 04 5e bb c5 00 e8
> > > > [   25.808960][  T214] EAX: 00000000 EBX: e764d530 ECX: 00000003 EDX: 4108888f
> > > > [   25.809578][  T214] ESI: e764d4e0 EDI: e764d4e0 EBP: ed89db3c ESP: ed89db00
> > > > [   25.810168][  T214] DS: 007b ES: 007b FS: 00d8 GS: 0033 SS: 0068 EFLAGS: 00210046
> > > > [   25.810803][  T214] CR0: 80050033 CR2: 00616abc CR3: 2d878000 CR4: 000406d0
> > > > [   25.811407][  T214] DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
> > > > [   25.811999][  T214] DR6: fffe0ff0 DR7: 00000400
> > > > [   25.812390][  T214] Call Trace:
> > > > [   25.812675][  T214]  dump_page+0x2a/0xc0
> > > > [   25.813025][  T214]  ? _raw_spin_lock_irqsave+0x16/0x30
> > > > [   25.813492][  T214]  folio_flags+0x23/0x70
> > > > [   25.813945][  T214]  get_partial_node+0x89/0x290
> > > > [   25.814357][  T214]  __slab_alloc_node+0xbb/0x270
> > > > [   25.814860][  T214]  kmem_cache_alloc_lru+0x8d/0x4e0
> > > > [   25.815289][  T214]  ? __lock_release+0x3ec/0x410
> > > > [   25.815697][  T214]  ? iget_locked+0x78/0x310
> > > > [   25.816096][  T214]  alloc_inode+0x93/0x150
> > > > [   25.816469][  T214]  iget_locked+0xdd/0x310
> > > > [   25.816829][  T214]  ? lock_is_held_type+0x80/0xf0
> > > > [   25.817264][  T214]  kernfs_get_inode+0x24/0xb0
> > > > [   25.817670][  T214]  kernfs_iop_lookup+0xb5/0x1a0
> > > > [   25.818087][  T214]  __lookup_slow+0xd9/0x2a0
> > > > [   25.818479][  T214]  lookup_slow+0x50/0x90
> > > > [   25.818847][  T214]  walk_component+0x19c/0x2c0
> > > > [   25.819244][  T214]  path_lookupat+0xa3/0x270
> > > > [   25.819627][  T214]  path_openat+0x307/0x3e0
> > > > [   25.820007][  T214]  do_filp_open+0x7c/0x130
> > > > [   25.820409][  T214]  do_sys_openat2+0x113/0x1f0
> > > > [   25.820807][  T214]  do_sys_open+0x8e/0xe0
> > > > [   25.821211][  T214]  __ia32_sys_openat+0x2b/0x40
> > > > [   25.821622][  T214]  __do_fast_syscall_32+0x72/0xd0
> > > > [   25.822057][  T214]  ? trace_hardirqs_on+0xa2/0x110
> > > > [   25.822480][  T214]  ? __fput+0x19f/0x390
> > > > [   25.822842][  T214]  ? lockdep_hardirqs_on_prepare+0x242/0x400
> > > > [   25.823346][  T214]  ? syscall_exit_to_user_mode+0x5f/0x90
> > > > [   25.823823][  T214]  ? __do_fast_syscall_32+0x7c/0xd0
> > > > [   25.824259][  T214]  ? lockdep_hardirqs_on_prepare+0x242/0x400
> > > > [   25.824767][  T214]  ? syscall_exit_to_user_mode+0x5f/0x90
> > > > [   25.825254][  T214]  ? __do_fast_syscall_32+0x7c/0xd0
> > > > [   25.825696][  T214]  ? __do_fast_syscall_32+0x7c/0xd0
> > > > [   25.826155][  T214]  ? syscall_exit_to_user_mode+0x5f/0x90
> > > > [   25.826627][  T214]  ? __do_fast_syscall_32+0x7c/0xd0
> > > > [   25.827056][  T214]  ? __do_fast_syscall_32+0x7c/0xd0
> > > > [   25.827486][  T214]  ? __do_fast_syscall_32+0x7c/0xd0
> > > > [   25.827929][  T214]  ? irqentry_exit_to_user_mode+0x23/0x30
> > > > [   25.828423][  T214]  ? irqentry_exit+0x7f/0xc0
> > > > [   25.828812][  T214]  do_fast_syscall_32+0x32/0x70
> > > > [   25.829223][  T214]  do_SYSENTER_32+0x15/0x20
> > > > [   25.829589][  T214]  entry_SYSENTER_32+0xa2/0xfb
> > > > [   25.830003][  T214] EIP: 0xb7f8c549
> > > > [   25.830330][  T214] Code: 03 74 c0 01 10 05 03 74 b8 01 10 06 03 74 b4 01 10 07 03 74 b0 01 10 08 03 74 d8 01 00 00 00 00 00 51 52 55 89 e5 0f 34 cd 80 <5d> 5a 59 c3 90 90 90 90 8d 76 00 58 b8 77 00 00 00 cd 80 90 8d 76
> > > > [   25.831929][  T214] EAX: ffffffda EBX: 00000006 ECX: 006142a1 EDX: 002a8000
> > > > [   25.832522][  T214] ESI: 00000000 EDI: 00000001 EBP: 00614024 ESP: bff3c4a0
> > > > [   25.833123][  T214] DS: 007b ES: 007b FS: 0000 GS: 0033 SS: 007b EFLAGS: 00200246
> > > > [   25.833738][  T214] Modules linked in:
> > > > [   25.834062][  T214] ---[ end trace 0000000000000000 ]---
> > > > [   25.834522][  T214] EIP: __dump_page.cold+0x282/0x369
> > > > [   25.834960][  T214] Code: ff ff 83 05 e8 5d bb c5 01 ba 4c c4 2f c4 89 f8 83 15 ec 5d bb c5 00 e8 f2 92 ed fd 83 05 f8 5d bb c5 01 83 15 fc 5d bb c5 00 <0f> 0b 83 05 00 5e bb c5 01 b8 ac 85 a3 c4 83 15 04 5e bb c5 00 e8
> > > > [   25.836574][  T214] EAX: 00000000 EBX: e764d530 ECX: 00000003 EDX: 4108888f
> > > > [   25.837183][  T214] ESI: e764d4e0 EDI: e764d4e0 EBP: ed89db3c ESP: ed89db00
> > > > [   25.837772][  T214] DS: 007b ES: 007b FS: 00d8 GS: 0033 SS: 0068 EFLAGS: 00210046
> > > > [   25.838414][  T214] CR0: 80050033 CR2: 00616abc CR3: 2d878000 CR4: 000406d0
> > > > [   25.839011][  T214] DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
> > > > [   25.839597][  T214] DR6: fffe0ff0 DR7: 00000400
> > > > [   25.839995][  T214] Kernel panic - not syncing: Fatal exception
> > > > [   25.840554][  T214] Kernel Offset: disabled
> > > 
> > > 
> 
> -- 
> Thanks,
> Hyeonggon

Content of type "text/plain" skipped

Download attachment "dmesg-rcutorture-bug-at-mm-h.xz" of type "application/x-xz" (56844 bytes)

Download attachment "dmesg-boot-bug-at-page_alloc-c.xz" of type "application/x-xz" (56596 bytes)

Powered by blists - more mailing lists

Powered by Openwall GNU/*/Linux Powered by OpenVZ