Re: [PATCH v4 1/2] x86/unwind: add ORC unwinder
From: Levin, Alexander (Sasha Levin)
Date: Fri Jul 28 2017 - 14:31:10 EST
On Fri, Jul 28, 2017 at 12:52:34PM -0500, Josh Poimboeuf wrote:
>On Fri, Jul 28, 2017 at 04:48:47PM +0000, Levin, Alexander (Sasha Levin) wrote:
>> Hey Josh,
>>
>> Syzkaller seems to trigger the following:
>>
>> ==================================================================
>> BUG: KASAN: stack-out-of-bounds in __read_once_size include/linux/compiler.h:253 [inline]
>> BUG: KASAN: stack-out-of-bounds in deref_stack_reg+0x123/0x140 arch/x86/kernel/unwind_orc.c:282
>> Read of size 8 at addr ffff8800374a7b28 by task syz-executor4/6474
>>
>> CPU: 2 PID: 6474 Comm: syz-executor4 Not tainted 4.13.0-rc2-next-20170727 #232
>> Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.1-1ubuntu1 04/01/2014
>> Call Trace:
>> <IRQ>
>> __dump_stack lib/dump_stack.c:16 [inline]
>> dump_stack+0xab/0x105 lib/dump_stack.c:52
>> print_address_description+0xc2/0x250 mm/kasan/report.c:252
>> kasan_report_error mm/kasan/report.c:351 [inline]
>> kasan_report+0x24f/0x360 mm/kasan/report.c:408
>> __read_once_size include/linux/compiler.h:253 [inline]
>> deref_stack_reg+0x123/0x140 arch/x86/kernel/unwind_orc.c:282
>> unwind_next_frame+0xd9b/0x1b80 arch/x86/kernel/unwind_orc.c:426
>> __save_stack_trace+0x7d/0xf0 arch/x86/kernel/stacktrace.c:44
>> save_stack+0x33/0xa0 mm/kasan/kasan.c:447
>> set_track mm/kasan/kasan.c:459 [inline]
>> kasan_slab_free+0x72/0xc0 mm/kasan/kasan.c:524
>> slab_free_hook mm/slub.c:1357 [inline]
>> slab_free_freelist_hook mm/slub.c:1379 [inline]
>> slab_free mm/slub.c:2955 [inline]
>> kmem_cache_free+0xae/0x310 mm/slub.c:2977
>> put_pid+0xe2/0x120 kernel/pid.c:246
>> __rcu_reclaim kernel/rcu/rcu.h:195 [inline]
>> rcu_do_batch kernel/rcu/tree.c:2666 [inline]
>> invoke_rcu_callbacks kernel/rcu/tree.c:2920 [inline]
>> __rcu_process_callbacks kernel/rcu/tree.c:2887 [inline]
>> rcu_process_callbacks+0x599/0x12b0 kernel/rcu/tree.c:2904
>> __do_softirq+0x234/0x934 kernel/softirq.c:284
>> invoke_softirq kernel/softirq.c:364 [inline]
>> irq_exit+0x164/0x190 kernel/softirq.c:405
>> exiting_irq arch/x86/include/asm/apic.h:638 [inline]
>> smp_apic_timer_interrupt+0x71/0x90 arch/x86/kernel/apic/apic.c:1044
>> apic_timer_interrupt+0xb9/0xc0 arch/x86/entry/entry_64.S:793
>> </IRQ>
>> RIP: 0010:arch_local_irq_enable arch/x86/include/asm/paravirt.h:824 [inline]
>> RIP: 0010:preempt_schedule_irq+0x71/0xd0 kernel/sched/core.c:3579
>> RSP: 0018:ffff8800374a7958 EFLAGS: 00000246 ORIG_RAX: ffffffffffffff10
>> RAX: 0000000000000007 RBX: ffffed0006d95808 RCX: 1ffffffff534d022
>> RDX: 0000000000000000 RSI: ffffffffa7065fe0 RDI: ffff880036cac9a4
>> RBP: 0000000000000000 R08: ffff88007ffd709c R09: 0000000000000000
>> R10: 0000000000000000 R11: 0000000000000000 R12: ffff880036cac040
>> R13: 00000000000002eb R14: ffff880036cac040 R15: ffff88005fdc2728
>> retint_kernel+0x1b/0x2d
>> RIP: 0010:arch_local_save_flags arch/x86/include/asm/paravirt.h:809 [inline]
>> RIP: 0010:___might_sleep+0x159/0x480 kernel/sched/core.c:5968
>> RSP: 0018:ffff8800374a7a28 EFLAGS: 00000246 ORIG_RAX: ffffffffffffff02
>> RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000001
>> RDX: 1ffff10006d95882 RSI: 00000000ffffffff RDI: ffff880036cac410
>> RBP: 0000000000000000 R08: ffffffffa3b1546e R09: dffffc0000000000
>> R10: ffff8800374a7c08 R11: 0000000000000001 R12: ffffffffa7065320
>> R13: 00000000000002eb R14: ffff880036cac040 R15: ffff88005fdc2728
>> ext4_orphan_add+0x34e/0xd70 fs/ext4/namei.c:2801
>
>Thanks for reporting this. I'm confused by the stack trace. It seems
>to end at ext4_orphan_add, which would normally make sense because the
>unwinder would have stopped when it read the bad address on the stack.
>
>But there aren't any of the '?' entries, which should still be there.
>Any chance your post-processing script removes those? Can you share the
>raw dmesg before it was post-processed?
Hey Josh,
Sure, here it is:
[ 391.851860] ==================================================================
[ 391.856663] BUG: KASAN: stack-out-of-bounds in deref_stack_reg+0x123/0x140
[ 391.861469] Read of size 8 at addr ffff8800374a7b28 by task syz-executor4/6474
[ 391.864387]
[ 391.864651] CPU: 2 PID: 6474 Comm: syz-executor4 Not tainted 4.13.0-rc2-next-20170727 #232
[ 391.865919] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.1-1ubuntu1 04/01/2014
[ 391.867424] Call Trace:
[ 391.867875] <IRQ>
[ 391.868269] dump_stack+0xab/0x105
[ 391.868923] print_address_description+0xc2/0x250
[ 391.869843] kasan_report+0x24f/0x360
[ 391.870534] ? deref_stack_reg+0x123/0x140
[ 391.871490] deref_stack_reg+0x123/0x140
[ 391.872239] ? __read_once_size_nocheck.constprop.7+0x10/0x10
[ 391.873289] ? get_stack_info+0x32/0x150
[ 391.874016] ? stack_access_ok+0xd6/0x150
[ 391.874701] ? sched_clock+0x5/0x10
[ 391.875516] ? sched_clock_cpu+0x18/0x1d0
[ 391.877449] unwind_next_frame+0xd9b/0x1b80
[ 391.878149] ? ext4_orphan_add+0x34e/0xd70
[ 391.878798] ? deref_stack_reg+0x140/0x140
[ 391.882077] ? check_preemption_disabled+0x34/0x1f0
[ 391.884084] __save_stack_trace+0x7d/0xf0
[ 391.885471] ? ext4_orphan_add+0x34e/0xd70
[ 391.886123] ? put_pid+0xe2/0x120
[ 391.889839] save_stack+0x33/0xa0
[ 391.890367] ? save_stack+0x33/0xa0
[ 391.890902] ? kasan_slab_free+0x72/0xc0
[ 391.891508] ? kmem_cache_free+0xae/0x310
[ 391.892134] ? put_pid+0xe2/0x120
[ 391.892659] ? rcu_process_callbacks+0x599/0x12b0
[ 391.893791] ? __do_softirq+0x234/0x934
[ 391.894418] ? irq_exit+0x164/0x190
[ 391.894973] ? smp_apic_timer_interrupt+0x71/0x90
[ 391.895705] ? apic_timer_interrupt+0xb9/0xc0
[ 391.896379] ? preempt_schedule_irq+0x71/0xd0
[ 391.897062] ? retint_kernel+0x1b/0x2d
[ 391.901512] ? ___might_sleep+0x159/0x480
[ 391.902143] ? ext4_orphan_add+0x34e/0xd70
[ 391.902794] ? mark_held_locks+0xc7/0x110
[ 391.903422] ? check_preemption_disabled+0x34/0x1f0
[ 391.911223] ? trace_hardirqs_on_caller+0x284/0x590
[ 391.911987] ? _raw_spin_unlock_irqrestore+0x41/0x70
[ 391.912771] ? free_object+0xce/0x160
[ 391.913376] ? __debug_check_no_obj_freed+0x400/0x900
[ 391.919901] ? check_preemption_disabled+0x34/0x1f0
[ 391.920664] ? debug_object_free+0x10/0x10
[ 391.921324] ? mark_held_locks+0xc7/0x110
[ 391.921952] ? check_preemption_disabled+0x34/0x1f0
[ 391.922718] kasan_slab_free+0x72/0xc0
[ 391.923314] kmem_cache_free+0xae/0x310
[ 391.923927] put_pid+0xe2/0x120
[ 391.924633] rcu_process_callbacks+0x599/0x12b0
[ 391.928396] ? rcu_exp_wait_wake+0x1100/0x1100
[ 391.929078] ? check_preemption_disabled+0x34/0x1f0
[ 391.929967] __do_softirq+0x234/0x934
[ 391.930867] irq_exit+0x164/0x190
[ 391.931482] smp_apic_timer_interrupt+0x71/0x90
[ 391.934785] apic_timer_interrupt+0xb9/0xc0
[ 391.935393] </IRQ>
[ 391.935720] RIP: 0010:preempt_schedule_irq+0x71/0xd0
[ 391.936799] RSP: 0018:ffff8800374a7958 EFLAGS: 00000246 ORIG_RAX: ffffffffffffff10
[ 391.940748] RAX: 0000000000000007 RBX: ffffed0006d95808 RCX: 1ffffffff534d022
[ 391.942554] RDX: 0000000000000000 RSI: ffffffffa7065fe0 RDI: ffff880036cac9a4
[ 391.943536] RBP: 0000000000000000 R08: ffff88007ffd709c R09: 0000000000000000
[ 391.950270] R10: 0000000000000000 R11: 0000000000000000 R12: ffff880036cac040
[ 391.952836] R13: 00000000000002eb R14: ffff880036cac040 R15: ffff88005fdc2728
[ 391.957222] ? preempt_schedule_irq+0x6d/0xd0
[ 391.957915] retint_kernel+0x1b/0x2d
[ 391.958483] RIP: 0010:___might_sleep+0x159/0x480
[ 391.959904] RSP: 0018:ffff8800374a7a28 EFLAGS: 00000246 ORIG_RAX: ffffffffffffff02
[ 391.969771] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000001
[ 391.971302] RDX: 1ffff10006d95882 RSI: 00000000ffffffff RDI: ffff880036cac410
[ 391.972390] RBP: 0000000000000000 R08: ffffffffa3b1546e R09: dffffc0000000000
[ 391.973523] R10: ffff8800374a7c08 R11: 0000000000000001 R12: ffffffffa7065320
[ 391.974947] R13: 00000000000002eb R14: ffff880036cac040 R15: ffff88005fdc2728
[ 391.976216] ? ext4_orphan_add+0x34e/0xd70
[ 391.977434] ext4_orphan_add+0x34e/0xd70
[ 391.979303] ? __mutex_lock+0xc7/0x14b0
[ 391.980692] ? ext4_orphan_add+0x34e/0xd70
[ 391.981547] ? mutex_lock_io_nested+0x1350/0x1350
[ 391.982276] ? lock_acquire+0x3a0/0x3a0
[ 391.982884] ? check_preemption_disabled+0x34/0x1f0
[ 391.983655] ? jbd2_write_access_granted.part.7+0x1b9/0x2b0
[ 391.984534] ? jbd2_journal_get_write_access+0x77/0x90
[ 391.990212] ? __ext4_journal_get_write_access+0x117/0x1d0
[ 391.994173] ? ext4_orphan_add+0x34e/0xd70
[ 391.994820] ? ext4_orphan_add+0x34e/0xd70
[ 391.995467] ? ext4_delete_entry+0x25c/0x420
[ 391.996137] ? jbd2__journal_start+0xef/0x8c0
[ 391.996799] ? ext4_empty_dir+0x750/0x750
[ 391.998128] ? __ext4_journal_start_sb+0x100/0x440
[ 391.998873] ? ext4_rmdir+0x432/0xc30
[ 391.999484] ? ext4_rmdir+0x703/0xc30
[ 392.000071] ? ext4_rename2+0x130/0x130
[ 392.000692] ? vfs_rmdir+0x1cd/0x3a0
[ 392.001273] ? do_rmdir+0x39f/0x400
[ 392.001833] ? user_path_create+0x40/0x40
[ 392.002458] ? syscall_trace_enter+0x324/0xe30
[ 392.008656] ? lock_acquire+0x3a0/0x3a0
[ 392.009278] ? exit_to_usermode_loop+0x160/0x160
[ 392.009997] ? check_preemption_disabled+0x34/0x1f0
[ 392.010765] ? check_preemption_disabled+0x34/0x1f0
[ 392.011527] ? SyS_mkdir+0x230/0x230
[ 392.012094] ? do_syscall_64+0x1b0/0x600
[ 392.012718] ? entry_SYSCALL64_slow_path+0x25/0x25
[ 392.013484]
[ 392.013734] The buggy address belongs to the page:
[ 392.014750] page:ffffea0000dd29c0 count:0 mapcount:0 mapping: (null) index:0x0
[ 392.016276] flags: 0xfffe0000000000()
[ 392.016939] raw: 00fffe0000000000 0000000000000000 0000000000000000 00000000ffffffff
[ 392.018679] raw: 0000000000000000 dead000000000200 0000000000000000 0000000000000000
[ 392.019881] page dumped because: kasan: bad access detected
[ 392.020729]
[ 392.020979] Memory state around the buggy address:
[ 392.021738] ffff8800374a7a00: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[ 392.022836] ffff8800374a7a80: 00 00 00 00 00 00 00 00 f1 f1 f1 f1 00 f4 f4 f4
[ 392.023950] >ffff8800374a7b00: f2 f2 f2 f2 00 f4 f4 f4 f2 f2 f2 f2 00 00 00 00
[ 392.025193] ^
[ 392.025890] ffff8800374a7b80: 00 f4 f4 f4 00 00 00 00 00 00 00 00 00 00 00 00
[ 392.026961] ffff8800374a7c00: 00 00 00 00 00 00 00 00 00 f1 f1 f1 f1 00 00 00
[ 392.028049] ==================================================================
[ 392.029713] Disabling lock debugging due to kernel taint
[ 392.030551] Kernel panic - not syncing: panic_on_warn set ...
[ 392.030551]
[ 392.031651] CPU: 2 PID: 6474 Comm: syz-executor4 Tainted: G B 4.13.0-rc2-next-20170727 #232
[ 392.033060] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.1-1ubuntu1 04/01/2014
[ 392.034399] Call Trace:
[ 392.034785] <IRQ>
[ 392.035115] dump_stack+0xab/0x105
[ 392.035649] panic+0x1bc/0x3ba
[ 392.036306] ? __warn+0x1d6/0x1d6
[ 392.036836] kasan_end_report+0x4a/0x50
[ 392.037438] kasan_report+0x168/0x360
[ 392.038004] ? deref_stack_reg+0x123/0x140
[ 392.038581] deref_stack_reg+0x123/0x140
[ 392.039161] ? __read_once_size_nocheck.constprop.7+0x10/0x10
[ 392.040072] ? get_stack_info+0x32/0x150
[ 392.040895] ? stack_access_ok+0xd6/0x150
[ 392.041764] ? sched_clock+0x5/0x10
[ 392.042346] ? sched_clock_cpu+0x18/0x1d0
[ 392.043076] unwind_next_frame+0xd9b/0x1b80
[ 392.043776] ? ext4_orphan_add+0x34e/0xd70
[ 392.044425] ? deref_stack_reg+0x140/0x140
[ 392.045073] ? check_preemption_disabled+0x34/0x1f0
[ 392.045833] __save_stack_trace+0x7d/0xf0
[ 392.047297] ? ext4_orphan_add+0x34e/0xd70
[ 392.047932] ? put_pid+0xe2/0x120
[ 392.048447] save_stack+0x33/0xa0
[ 392.048986] ? save_stack+0x33/0xa0
[ 392.049564] ? kasan_slab_free+0x72/0xc0
[ 392.050171] ? kmem_cache_free+0xae/0x310
[ 392.050792] ? put_pid+0xe2/0x120
[ 392.051650] ? rcu_process_callbacks+0x599/0x12b0
[ 392.052357] ? __do_softirq+0x234/0x934
[ 392.052948] ? irq_exit+0x164/0x190
[ 392.053523] ? smp_apic_timer_interrupt+0x71/0x90
[ 392.054273] ? apic_timer_interrupt+0xb9/0xc0
[ 392.054951] ? preempt_schedule_irq+0x71/0xd0
[ 392.055594] ? retint_kernel+0x1b/0x2d
[ 392.056168] ? ___might_sleep+0x159/0x480
[ 392.056784] ? ext4_orphan_add+0x34e/0xd70
[ 392.057442] ? mark_held_locks+0xc7/0x110
[ 392.058235] ? check_preemption_disabled+0x34/0x1f0
[ 392.058979] ? trace_hardirqs_on_caller+0x284/0x590
[ 392.059730] ? _raw_spin_unlock_irqrestore+0x41/0x70
[ 392.060486] ? free_object+0xce/0x160
[ 392.060997] ? __debug_check_no_obj_freed+0x400/0x900
[ 392.061905] ? check_preemption_disabled+0x34/0x1f0
[ 392.062763] ? debug_object_free+0x10/0x10
[ 392.063334] ? mark_held_locks+0xc7/0x110
[ 392.063914] ? check_preemption_disabled+0x34/0x1f0
[ 392.064764] kasan_slab_free+0x72/0xc0
[ 392.065451] kmem_cache_free+0xae/0x310
[ 392.066139] put_pid+0xe2/0x120
[ 392.066723] rcu_process_callbacks+0x599/0x12b0
[ 392.067532] ? rcu_exp_wait_wake+0x1100/0x1100
[ 392.068293] ? check_preemption_disabled+0x34/0x1f0
[ 392.069231] __do_softirq+0x234/0x934
[ 392.069760] irq_exit+0x164/0x190
[ 392.070270] smp_apic_timer_interrupt+0x71/0x90
[ 392.070978] apic_timer_interrupt+0xb9/0xc0
[ 392.071614] </IRQ>
[ 392.072152] RIP: 0010:preempt_schedule_irq+0x71/0xd0
[ 392.072903] RSP: 0018:ffff8800374a7958 EFLAGS: 00000246 ORIG_RAX: ffffffffffffff10
[ 392.074336] RAX: 0000000000000007 RBX: ffffed0006d95808 RCX: 1ffffffff534d022
[ 392.075285] RDX: 0000000000000000 RSI: ffffffffa7065fe0 RDI: ffff880036cac9a4
[ 392.076235] RBP: 0000000000000000 R08: ffff88007ffd709c R09: 0000000000000000
[ 392.077204] R10: 0000000000000000 R11: 0000000000000000 R12: ffff880036cac040
[ 392.078271] R13: 00000000000002eb R14: ffff880036cac040 R15: ffff88005fdc2728
[ 392.080105] ? preempt_schedule_irq+0x6d/0xd0
[ 392.080882] retint_kernel+0x1b/0x2d
[ 392.081563] RIP: 0010:___might_sleep+0x159/0x480
[ 392.082364] RSP: 0018:ffff8800374a7a28 EFLAGS: 00000246 ORIG_RAX: ffffffffffffff02
[ 392.083604] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000001
[ 392.084879] RDX: 1ffff10006d95882 RSI: 00000000ffffffff RDI: ffff880036cac410
[ 392.085967] RBP: 0000000000000000 R08: ffffffffa3b1546e R09: dffffc0000000000
[ 392.087029] R10: ffff8800374a7c08 R11: 0000000000000001 R12: ffffffffa7065320
[ 392.088090] R13: 00000000000002eb R14: ffff880036cac040 R15: ffff88005fdc2728
[ 392.089199] ? ext4_orphan_add+0x34e/0xd70
[ 392.089833] ext4_orphan_add+0x34e/0xd70
[ 392.090441] ? __mutex_lock+0xc7/0x14b0
[ 392.091197] ? ext4_orphan_add+0x34e/0xd70
[ 392.091833] ? mutex_lock_io_nested+0x1350/0x1350
[ 392.092550] ? lock_acquire+0x3a0/0x3a0
[ 392.093153] ? check_preemption_disabled+0x34/0x1f0
[ 392.093917] ? jbd2_write_access_granted.part.7+0x1b9/0x2b0
[ 392.094774] ? jbd2_journal_get_write_access+0x77/0x90
[ 392.095946] ? __ext4_journal_get_write_access+0x117/0x1d0
[ 392.096785] ? ext4_orphan_add+0x34e/0xd70
[ 392.097431] ? ext4_orphan_add+0x34e/0xd70
[ 392.098063] ? ext4_delete_entry+0x25c/0x420
[ 392.098934] ? jbd2__journal_start+0xef/0x8c0
[ 392.099602] ? ext4_empty_dir+0x750/0x750
[ 392.100233] ? __ext4_journal_start_sb+0x100/0x440
[ 392.100964] ? ext4_rmdir+0x432/0xc30
[ 392.101561] ? ext4_rmdir+0x703/0xc30
[ 392.102303] ? ext4_rename2+0x130/0x130
[ 392.102906] ? vfs_rmdir+0x1cd/0x3a0
[ 392.103460] ? do_rmdir+0x39f/0x400
[ 392.104097] ? user_path_create+0x40/0x40
[ 392.104806] ? syscall_trace_enter+0x324/0xe30
[ 392.105812] ? lock_acquire+0x3a0/0x3a0
[ 392.106684] ? exit_to_usermode_loop+0x160/0x160
[ 392.107501] ? check_preemption_disabled+0x34/0x1f0
[ 392.108299] ? check_preemption_disabled+0x34/0x1f0
[ 392.110963] ? SyS_mkdir+0x230/0x230
[ 392.111521] ? do_syscall_64+0x1b0/0x600
[ 392.112154] ? entry_SYSCALL64_slow_path+0x25/0x25
[ 392.113310] Dumping ftrace buffer:
[ 392.113849] (ftrace buffer empty)
[ 392.114400] Kernel Offset: 0x22200000 from 0xffffffff81000000 (relocation range: 0xffffffff80000000-0xffffffffbfffffff)
[ 392.116033] Rebooting in 86400 seconds..
--
Thanks,
Sasha