BUG: KASAN: stack-out-of-bounds in sched_show_task

From: Sasha Levin
Date: Tue Jan 26 2016 - 08:49:52 EST


Hi all,

I've added a little "heartbeat" code to my testing which simply sysrq-t every two
minutes to get a snapshot of what's going on, which I added in hopes of tracking
down an odd lockup.

However, this sysrq call seems to produce the following quite often:

[4628498.116069] BUG: KASAN: stack-out-of-bounds in sched_show_task+0x28a/0x3b0 at addr ffff8802c9a47e08
[4628498.116933] Read of size 8 by task runtrin.sh/8510
[4628498.117431] page:ffffea000b2691c0 count:0 mapcount:0 mapping: (null) index:0x0
[4628498.118232] flags: 0x26fffff80000000()
[4628498.118637] page dumped because: kasan: bad access detected
[4628498.119229] CPU: 3 PID: 8510 Comm: runtrin.sh Not tainted 4.4.0-next-20160125-sasha-12175-gc123483-dirty #2836
[4628498.120288] 1ffff100510e0f3c 0000000056bd98e4 ffff880288707a60 ffffffffa34489f1
[4628498.121119] 0000000041b58ab3 ffffffffaf6f3d88 ffffffffa3448926 0000000000000000
[4628498.121885] ffff880200000000 0000000000000000 0000000000000000 ffffea000b2691c0
[4628498.122655] Call Trace:
[4628498.122930] dump_stack (lib/dump_stack.c:52)
[4628498.123459] ? _atomic_dec_and_lock (lib/dump_stack.c:27)
[4628498.124081] kasan_report_error (mm/kasan/report.c:150 mm/kasan/report.c:236)
[4628498.124671] ? vprintk_default (kernel/printk/printk.c:1879)
[4628498.125246] ? rt_mutex_top_waiter.part.7 (kernel/printk/printk.c:1904)
[4628498.125881] ? sched_show_task (kernel/sched/core.c:5021)
[4628498.126452] __asan_report_load8_noabort (mm/kasan/report.c:259 mm/kasan/report.c:280)
[4628498.127068] ? sched_show_task (kernel/sched/core.c:5021)
[4628498.127641] sched_show_task (kernel/sched/core.c:5021)
[4628498.128202] show_state_filter (kernel/sched/core.c:5058)
[4628498.128805] sysrq_handle_showstate (drivers/tty/sysrq.c:281)
[4628498.129396] __handle_sysrq (include/linux/rcupdate.h:929 drivers/tty/sysrq.c:573)
[4628498.129959] ? __might_sleep (kernel/sched/core.c:7666 (discriminator 14))
[4628498.130607] write_sysrq_trigger (drivers/tty/sysrq.c:1097)
[4628498.131198] proc_reg_write (fs/proc/inode.c:217)
[4628498.131764] ? sysrq_filter (drivers/tty/sysrq.c:1091)
[4628498.132318] __vfs_write (fs/read_write.c:529)
[4628498.132855] ? proc_reg_poll (fs/proc/inode.c:210)
[4628498.133420] ? vfs_iter_write (fs/read_write.c:527)
[4628498.133993] ? __fd_install (fs/file.c:606 (discriminator 3))
[4628498.134548] ? check_preemption_disabled (lib/smp_processor_id.c:52)
[4628498.135194] ? __this_cpu_preempt_check (lib/smp_processor_id.c:63)
[4628498.135824] ? update_fast_ctr (./arch/x86/include/asm/preempt.h:92 kernel/locking/percpu-rwsem.c:57)
[4628498.136385] vfs_write (fs/read_write.c:579)
[4628498.136895] SyS_write (fs/read_write.c:626 fs/read_write.c:617)
[4628498.137398] ? SyS_read (fs/read_write.c:617)
[4628498.137915] entry_SYSCALL_64_fastpath (arch/x86/entry/entry_64.S:186)
[4628498.138528] Memory state around the buggy address:
[4628498.139010] ffff8802c9a47d00: f4 f2 f2 f2 f2 00 f4 f4 f4 f3 f3 f3 f3 00 00 00
[4628498.139710] ffff8802c9a47d80: 00 00 00 00 00 00 00 00 00 00 00 f1 f1 f1 f1 00
[4628498.140554] >ffff8802c9a47e00: f4 f4 f4 f3 f3 f3 f3 00 00 00 00 00 00 00 00 00
[4628498.141301] ^
[4628498.141652] ffff8802c9a47e80: f1 f1 f1 f1 00 00 00 00 00 00 00 00 00 00 00 f4
[4628498.142372] ffff8802c9a47f00: f3 f3 f3 f3 00 00 00 00 00 00 00 00 00 00 00 00

This is pointing to:

void sched_show_task(struct task_struct *p)
{
unsigned long free = 0;
int ppid;
unsigned long state = p->state;

if (state)
state = __ffs(state) + 1;
printk(KERN_INFO "%-15.15s %c", p->comm,
state < sizeof(stat_nam) - 1 ? stat_nam[state] : '?');
#if BITS_PER_LONG == 32
if (state == TASK_RUNNING)
printk(KERN_CONT " running ");
else
printk(KERN_CONT " %08lx ", thread_saved_pc(p));
#else
if (state == TASK_RUNNING)
printk(KERN_CONT " running task ");
else
printk(KERN_CONT " %016lx ", thread_saved_pc(p)); <=== HERE



Thanks,
Sasha