Re: general protection fault in put_pid

Dmitry Vyukov
2018-12-25T09:42:08Z

On Sun, Dec 23, 2018 at 1:32 PM Manfred Spraul <manfred@colorfullife.com> wrote:
>
> Hi Dmitry,
>
> let's simplify the mail, otherwise noone can follow:
>
> On 12/23/18 11:42 AM, Dmitry Vyukov wrote:
> >
> >> My naive attempts to re-reproduce this failed so far.
> >> But I noticed that _all_ logs for these 3 crashes:
> >> https://syzkaller.appspot.com/bug?extid=c92d3646e35bc5d1a909
> >> https://syzkaller.appspot.com/bug?extid=1145ec2e23165570c3ac
> >> https://syzkaller.appspot.com/bug?extid=9d8b6fa6ee7636f350c1
> >> involve low memory conditions. My gut feeling says this is not a
> >> coincidence. This is also probably the reason why all reproducers
> >> create large sem sets. There must be some bad interaction between low
> >> memory condition and semaphores/ipc namespaces.
> >
> > Actually was able to reproduce this with a syzkaller program:
> >
> > ./syz-execprog -repeat=0 -procs=10 prog
> > ...
> > kasan: CONFIG_KASAN_INLINE enabled
> > kasan: GPF could be caused by NULL-ptr deref or user memory access
> > general protection fault: 0000 [#1] PREEMPT SMP KASAN
> > CPU: 1 PID: 8788 Comm: syz-executor8 Not tainted 4.20.0-rc7+ #6
> > Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
> > RIP: 0010:__list_del_entry_valid+0x7e/0x150 lib/list_debug.c:51
> > Code: ad de 4c 8b 26 49 39 c4 74 66 48 b8 00 02 00 00 00 00 ad de 48
> > 89 da 48 39 c3 74 65 48 b8 00 00 00 00 00 fc ff df 48 c1 ea 03 <80> 3c
> > 02 00 75 7b 48 8b 13 48 39 f2 75 57 49 8d 7c 24 08 48 b8 00
> > RSP: 0018:ffff88804faef210 EFLAGS: 00010a02
> > RAX: dffffc0000000000 RBX: f817edba555e1f00 RCX: ffffffff831bad5f
> > RDX: 1f02fdb74aabc3e0 RSI: ffff88801b8a0720 RDI: ffff88801b8a0728
> > RBP: ffff88804faef228 R08: fffff52001055401 R09: fffff52001055401
> > R10: 0000000000000001 R11: fffff52001055400 R12: ffff88802d52cc98
> > R13: ffff88801b8a0728 R14: ffff88801b8a0720 R15: dffffc0000000000
> > FS: 0000000000d24940(0000) GS:ffff88802d500000(0000) knlGS:0000000000000000
> > CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> > CR2: 00000000004bb580 CR3: 0000000011177005 CR4: 00000000003606e0
> > DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> > DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
> > Call Trace:
> > __list_del_entry include/linux/list.h:117 [inline]
> > list_del include/linux/list.h:125 [inline]
> > unlink_queue ipc/sem.c:786 [inline]
> > freeary+0xddb/0x1c90 ipc/sem.c:1164
> > free_ipcs+0xf0/0x160 ipc/namespace.c:112
> > sem_exit_ns+0x20/0x40 ipc/sem.c:237
> > free_ipc_ns ipc/namespace.c:120 [inline]
> > put_ipc_ns+0x55/0x160 ipc/namespace.c:152
> > free_nsproxy+0xc0/0x1f0 kernel/nsproxy.c:180
> > switch_task_namespaces+0xa5/0xc0 kernel/nsproxy.c:229
> > exit_task_namespaces+0x17/0x20 kernel/nsproxy.c:234
> > do_exit+0x19e5/0x27d0 kernel/exit.c:866
> > do_group_exit+0x151/0x410 kernel/exit.c:970
> > __do_sys_exit_group kernel/exit.c:981 [inline]
> > __se_sys_exit_group kernel/exit.c:979 [inline]
> > __x64_sys_exit_group+0x3e/0x50 kernel/exit.c:979
> > do_syscall_64+0x192/0x770 arch/x86/entry/common.c:290
> > entry_SYSCALL_64_after_hwframe+0x49/0xbe
> > RIP: 0033:0x4570e9
> > Code: 5d af fb ff c3 66 2e 0f 1f 84 00 00 00 00 00 66 90 48 89 f8 48
> > 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d
> > 01 f0 ff ff 0f 83 2b af fb ff c3 66 2e 0f 1f 84 00 00 00 00
> > RSP: 002b:00007ffe35f12018 EFLAGS: 00000246 ORIG_RAX: 00000000000000e7
> > RAX: ffffffffffffffda RBX: 0000000000000001 RCX: 00000000004570e9
> > RDX: 0000000000410540 RSI: 0000000000a34c00 RDI: 0000000000000045
> > RBP: 00000000004a43a4 R08: 000000000000000c R09: 0000000000000000
> > R10: 0000000000d24940 R11: 0000000000000246 R12: 0000000000000000
> > R13: 0000000000000001 R14: 0000000000000000 R15: 0000000000000008
> > Modules linked in:
> > Dumping ftrace buffer:
> > (ftrace buffer empty)
> > ---[ end trace 17829b0f00569a59 ]---
> > RIP: 0010:__list_del_entry_valid+0x7e/0x150 lib/list_debug.c:51
> > Code: ad de 4c 8b 26 49 39 c4 74 66 48 b8 00 02 00 00 00 00 ad de 48
> > 89 da 48 39 c3 74 65 48 b8 00 00 00 00 00 fc ff df 48 c1 ea 03 <80> 3c
> > 02 00 75 7b 48 8b 13 48 39 f2 75 57 49 8d 7c 24 08 48 b8 00
> > RSP: 0018:ffff88804faef210 EFLAGS: 00010a02
> > RAX: dffffc0000000000 RBX: f817edba555e1f00 RCX: ffffffff831bad5f
> > RDX: 1f02fdb74aabc3e0 RSI: ffff88801b8a0720 RDI: ffff88801b8a0728
> > RBP: ffff88804faef228 R08: fffff52001055401 R09: fffff52001055401
> > R10: 0000000000000001 R11: fffff52001055400 R12: ffff88802d52cc98
> > R13: ffff88801b8a0728 R14: ffff88801b8a0720 R15: dffffc0000000000
> > FS: 0000000000d24940(0000) GS:ffff88802d500000(0000) knlGS:0000000000000000
> > CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> > CR2: 00000000004bb580 CR3: 0000000011177005 CR4: 00000000003606e0
> > DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> > DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
> >
> >
> > The prog is:
> > unshare(0x8020000)
> > semget$private(0x0, 0x4007, 0x0)
> >
> > kernel is on 9105b8aa50c182371533fc97db64fc8f26f051b3
> >
> > and again it involved lots of oom kills, the repro eats all memory, a
> > process getting killed, frees some memory and the process repeats.
>
> Ok, thus the above program triggers two bugs:
>
> - a huge memory leak with semaphore arrays
>
> - under OOM pressure, an oops.
>
>
> 1) I can reproduce the memory leak, it happens all the time :-(
>
> I must look what is wrong.
>
> 2) regarding the crash:
>
> What differs under oom pressure?
>
> - kvmalloc can fall back to vmalloc()
>
> - the 2nd or 3rd of multiple allocations can fail, and that triggers a
> rare codepath/race condition.
>
> - rcu callback can happen earlier that expected
>
> So far, I didn't notice anything unexpected :-(

I started suspecting a stack overflow. But I was afraid if may be a
KASAN artifact, as it both increases stack usage and disables vmap
stacks.
But I was able to reproduce this without KASAN and root cause at the same time.

I am on v4.20, config is (basically just defconfig+kvmconfig):
https://gist.githubusercontent.com/dvyukov/f8401c8da367088c789bfb953d42d3b3/raw/eac0e85d3db577ba68ec59acf916899b61741ee1/gistfile1.txt

Running the syzkaller program gave me:

Out of memory: Kill process 13971 (syz-executor) score 998 or sacrifice child
Killed process 13971 (syz-executor) total-vm:37512kB, anon-rss:92kB,
file-rss:0kB, shmem-rss:0kB
oom_reaper: reaped process 13971 (syz-executor), now anon-rss:0kB,
file-rss:0kB, shmem-rss:0kB
Kernel panic - not syncing: corrupted stack end detected inside scheduler
CPU: 3 PID: 2555 Comm: kworker/u12:3 Not tainted 4.20.0-rc7+ #6
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
Workqueue: writeback wb_workfn (flush-8:0)
Call Trace:
dump_stack+0x1d4/0x2b5 lib/earlycpio.c:120
panic+0x25e/0x49c kernel/cpu.c:617
__schedule+0x1be8/0x21d0
preempt_schedule_common+0x35/0xe0
preempt_schedule+0x23/0x30
___preempt_schedule+0x16/0x18
_raw_spin_unlock_irq+0x75/0x80
mark_work_canceling kernel/workqueue.c:747 [inline]
__flush_work+0x4f5/0x970 kernel/workqueue.c:2996
flush_work+0x17/0x20 kernel/workqueue.c:3059
drain_all_pages+0x418/0x680 mm/page_alloc.c:4570
__alloc_pages_slowpath+0xb76/0x2c10 mm/page_alloc.c:4072
__alloc_pages_nodemask+0xa6c/0xe10 mm/page_alloc.c:5029
cache_grow_begin+0x9d/0x8a0
fallback_alloc+0x204/0x2e0
____cache_alloc_node+0x1cc/0x1f0
slab_alloc_node mm/slub.c:2710 [inline]
slab_alloc mm/slub.c:2752 [inline]
kmem_cache_alloc+0x296/0x720 mm/slub.c:2769
mempool_alloc_slab+0x44/0x60 mm/mempool.c:130
mempool_alloc+0x174/0x4e0 mm/mempool.c:433
bvec_alloc+0x150/0x2d0 block/bio.c:485
bio_alloc_bioset+0x44e/0x650 block/bio.c:1455
ext4_bio_write_page+0xc11/0x1780 fs/ext4/resize.c:76
mpage_add_bh_to_extent fs/ext4/inode.c:2300 [inline]
mpage_submit_page+0x138/0x230 fs/ext4/inode.c:2335
ext4_da_page_release_reservation fs/ext4/inode.c:1651 [inline]
mpage_process_page_bufs+0x429/0x500 fs/ext4/inode.c:3226
mpage_prepare_extent_to_map+0xb2a/0x1640 fs/ext4/inode.c:154
ext4_inode_journal_mode fs/ext4/ext4_jbd2.h:411 [inline]
ext4_should_journal_data fs/ext4/ext4_jbd2.h:427 [inline]
ext4_writepages+0x112c/0x3a20 fs/ext4/inode.c:2190
test_and_set_bit arch/x86/include/asm/bitops.h:220 [inline]
TestSetPageDirty include/linux/page-flags.h:287 [inline]
do_writepages+0xfc/0x170 mm/page-writeback.c:2383
mark_inode_dirty_sync include/linux/fs.h:2124 [inline]
__writeback_single_inode+0x1cd/0x12e0 fs/fs-writeback.c:1372
writeback_sb_inodes+0x6c7/0x1040 fs/fs-writeback.c:1795
__writeback_inodes_wb+0x1a3/0x310 fs/fs-writeback.c:1704
wb_writeback+0x92c/0xe10 include/trace/events/writeback.h:572
syz-executor invoked oom-killer:
gfp_mask=0x7080c0(GFP_KERNEL_ACCOUNT|__GFP_ZERO), nodemask=(null),
order=3, oom_score_adj=0
syz-executor cpuset=/ mems_allowed=0-1
wb_workfn+0xdf3/0x1600 fs/pnode.c:430
get_unbound_pool kernel/workqueue.c:3437 [inline]
process_one_work+0xcf3/0x1be0 kernel/workqueue.c:3612
worker_thread+0x17d/0x12f0 kernel/workqueue.c:2289
__write_once_size include/linux/compiler.h:218 [inline]
__list_del include/linux/list.h:106 [inline]
__list_del_entry include/linux/list.h:120 [inline]
list_del_init include/linux/list.h:159 [inline]
kthread+0x354/0x430 kernel/kthread.c:1010
ret_from_fork+0x3a/0x50 arch/x86/entry/entry_64.S:358
CPU: 0 PID: 6768 Comm: syz-executor Not tainted 4.20.0-rc7+ #6
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-1 04/01/2014
Call Trace:
dump_stack+0x1d4/0x2b5 lib/earlycpio.c:120
dump_header+0x294/0xfaf
oom_killer_enable mm/oom_kill.c:715 [inline]
oom_kill_process+0xa3f/0xd20 mm/oom_kill.c:750
out_of_memory+0x88c/0x12a0 mm/fadvise.c:184
compound_order include/linux/mm.h:707 [inline]
page_hstate include/linux/hugetlb.h:469 [inline]
__alloc_pages_slowpath+0x1cfa/0x2c10 mm/page_alloc.c:7820
__alloc_pages_nodemask+0xa6c/0xe10 mm/page_alloc.c:5029
copy_process+0x94c/0x7b00
variable_test_bit arch/x86/include/asm/bitops.h:332 [inline]
cpumask_test_cpu include/linux/cpumask.h:344 [inline]
trace_sched_process_fork include/trace/events/sched.h:288 [inline]
_do_fork+0x191/0xf20 kernel/fork.c:2232
__x64_sys_clone+0xbf/0x150 kernel/fork.c:2340
prepare_exit_to_usermode arch/x86/entry/common.c:196 [inline]
syscall_return_slowpath arch/x86/entry/common.c:268 [inline]
do_syscall_32_irqs_on arch/x86/entry/common.c:341 [inline]
do_syscall_64+0x192/0x770 arch/x86/entry/common.c:349
entry_SYSCALL_64_after_hwframe+0x49/0xbe
RIP: 0033:0x45578b
Code: db 45 85 f6 0f 85 95 01 00 00 64 4c 8b 04 25 10 00 00 00 31 d2
4d 8d 90 d0 02 00 00 31 f6 bf 11 00 20 01 b8 38 00 00 00 0f 05 <48> 3d
00 f0 ff ff 0f 87 d6 00 00 00 85 c0 41 89 c5 0f 85 dd 00 00
RSP: 002b:00007fff9dc6ca20 EFLAGS: 00000246 ORIG_RAX: 0000000000000038
RAX: ffffffffffffffda RBX: 00007fff9dc6ca20 RCX: 000000000045578b
RDX: 0000000000000000 RSI: 0000000000000000 RDI: 0000000001200011
RBP: 00007fff9dc6ca70 R08: 0000000001d0d940 R09: 0000000000000000
R10: 0000000001d0dc10 R11: 0000000000000246 R12: 0000000000000000
R13: 0000000000000020 R14: 0000000000000000 R15: 0000000000000000

and second time:

[ 281.244340] Kernel panic - not syncing: corrupted stack end
detected inside scheduler
[ 281.245754] CPU: 2 PID: 6265 Comm: kworker/u12:4 Not tainted 4.20.0-rc7+ #6
[ 281.246887] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996),
BIOS 1.10.2-1 04/01/2014
[ 281.248240] Workqueue: writeback wb_workfn (flush-8:0)
[ 281.248992] Call Trace:
[ 281.249364] dump_stack+0x1d4/0x2b5
[ 281.252261] panic+0x25e/0x49c
[ 281.255403] __schedule+0x1be8/0x21d0
[ 281.263754] preempt_schedule_common+0x35/0xe0
[ 281.264425] preempt_schedule+0x23/0x30
[ 281.265010] ___preempt_schedule+0x16/0x18
[ 281.265635] _raw_spin_unlock_irqrestore+0xbf/0xe0
[ 281.266357] __remove_mapping+0x77b/0x17e0
[ 281.291388] shrink_page_list+0x5232/0xa6b0
[ 281.414732] shrink_inactive_list+0x997/0x1ab0
[ 281.419009] shrink_node_memcg+0x9de/0x16a0
[ 281.424799] shrink_node+0x3af/0x1530
[ 281.433316] do_try_to_free_pages+0x3bc/0x1170
[ 281.435723] try_to_free_pages+0x43c/0x9e0
[ 281.442644] __alloc_pages_slowpath+0xa4c/0x2c10
[ 281.459197] __alloc_pages_nodemask+0xa6c/0xe10
[ 281.466504] alloc_pages_current+0xb6/0x1e0
[ 281.467326] __page_cache_alloc+0x332/0x560
[ 281.471049] pagecache_get_page+0x2af/0xdd0
[ 281.487360] __getblk_gfp+0x36e/0xd50
[ 281.497989] ext4_read_block_bitmap_nowait+0x2ed/0x1e10
[ 281.509111] ext4_read_block_bitmap+0x23/0x80
[ 281.509934] ext4_mb_mark_diskspace_used+0x180/0x10a0
[ 281.512755] ext4_mb_new_blocks+0xeb7/0x4260
[ 281.540189] ext4_ext_map_blocks+0x2776/0x5b00
[ 281.556040] ext4_map_blocks+0xcaa/0x1860
[ 281.559967] ext4_writepages+0x1e4c/0x3a20
[ 281.575738] do_writepages+0xfc/0x170
[ 281.578546] __writeback_single_inode+0x1cd/0x12e0
[ 281.592498] writeback_sb_inodes+0x6c7/0x1040
[ 281.598601] __writeback_inodes_wb+0x1a3/0x310
[ 281.600816] wb_writeback+0x92c/0xe10
[ 281.618064] wb_workfn+0xdf3/0x1600
[ 281.635970] process_one_work+0xcf3/0x1be0
[ 281.662614] worker_thread+0x17d/0x12f0
[ 281.680989] kthread+0x354/0x430
[ 281.682529] ret_from_fork+0x3a/0x50

One time it took about 10 seconds and another time it took 5 minutes.

Whom should we route this to? It looks both mm and ext4 related.