[sched/core] f1a0a376ca: BUG:KASAN:stack-out-of-bounds_in_vsnprintf

* [sched/core]  f1a0a376ca: BUG:KASAN:stack-out-of-bounds_in_vsnprintf
@ 2021-07-06 15:10 ` kernel test robot
  0 siblings, 0 replies; 4+ messages in thread
From: kernel test robot @ 2021-07-06 15:10 UTC (permalink / raw)
  To: Valentin Schneider
  Cc: Ingo Molnar, Peter Zijlstra, LKML, lkp, lkp, aubrey.li, yu.c.chen

[-- Attachment #1: Type: text/plain, Size: 5262 bytes --]

Greeting,

FYI, we noticed the following commit (built with gcc-9):

commit: f1a0a376ca0c4ef1fc3d24e3e502acbb5b795674 ("sched/core: Initialize the idle task with preemption disabled")
https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git master

in testcase: locktorture
version: 
with following parameters:

	runtime: 300s
	test: cpuhotplug

test-description: This torture test consists of creating a number of kernel threads which acquire the lock and hold it for specific amount of time, thus simulating different critical region behaviors.
test-url: https://www.kernel.org/doc/Documentation/locking/locktorture.txt

on test machine: qemu-system-x86_64 -enable-kvm -cpu SandyBridge -smp 2 -m 16G

caused below changes (please refer to attached dmesg/kmsg for entire log/backtrace):

If you fix the issue, kindly add following tag
Reported-by: kernel test robot <oliver.sang@intel.com>

[  227.905035] BUG: KASAN: stack-out-of-bounds in vsnprintf+0x1823/0x1a80
[  227.905062] Read of size 8 at addr ffffc9000010ff00 by task swapper/1/0
[  227.905084] 
[  227.905102] CPU: 1 PID: 0 Comm: swapper/1 Not tainted 5.13.0-rc1-00108-gf1a0a376ca0c #1
[  227.905133] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.12.0-1 04/01/2014
[  227.905157] Call Trace:
[  227.905171]  dump_stack+0x198/0x247
[  227.905190]  print_address_description.cold+0x5/0x32d
[  227.905212]  ? vsnprintf+0x1823/0x1a80
[  227.905229]  kasan_report.cold+0x7c/0xd8
[  227.905246]  ? vsnprintf+0x1823/0x1a80
[  227.905263]  vsnprintf+0x1823/0x1a80
[  227.905279]  ? pointer+0x780/0x780
[  227.905295]  ? sched_clock_cpu+0x38/0x220
[  227.905312]  vprintk_store+0x14d/0xa80
[  227.905330]  ? __ia32_sys_syslog+0xc0/0xc0
[  227.905348]  ? ftrace_likely_update+0xa4/0x180
[  227.905367]  ? pvclock_clocksource_read+0x2dd/0x5a0
[  227.905386]  ? write_comp_data+0x2a/0x80
[  227.905404]  ? __sanitizer_cov_trace_pc+0x1d/0x60
[  227.905423]  vprintk_emit+0x144/0x600
[  227.905439]  vprintk+0xac/0x1e0
[  227.905453]  printk+0xa3/0xc1
[  227.905470]  ? stress_reorder_work.cold+0x2a/0x2a
[  227.905489]  ? slow_virt_to_phys+0x15b/0x340
[  227.905507]  ? ftrace_likely_update+0xa4/0x180
[  227.905526]  start_secondary+0x4a/0x280
[  227.905544]  secondary_startup_64_no_verify+0xb0/0xbb
[  227.905561] 
[  227.905572] 
[  227.905592] addr ffffc9000010ff00 is located in stack of task swapper/1/0 at offset 120 in frame:
[  227.905619]  printk+0x0/0xc1
[  227.905633] 
[  227.905646] this frame has 1 object:
[  227.905664]  [32, 56) 'args'
[  227.905678] 
[  227.905694] Memory state around the buggy address:
[  227.905718]  ffffc9000010fe00: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[  227.905746]  ffffc9000010fe80: 00 f1 f1 f1 f1 00 00 00 f3 f3 f3 f3 f3 00 00 00
[  227.905775] >ffffc9000010ff00: f3 f3 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[  227.905799]                    ^
[  227.905820]  ffffc9000010ff80: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[  227.905848]  ffffc90000110000: f8 f8 f8 f8 f8 f8 f8 f8 f8 f8 f8 f8 f8 f8 f8 f8
[  227.905876] ==================================================================
[  227.905902] Disabling lock debugging due to kernel taint
[  227.974158] smpboot: CPU 1 is now offline
[  231.067528] x86: Booting SMP configuration:
[  231.068838] smpboot: Booting Node 0 Processor 1 APIC 0x1
[  231.090360] kvm-clock: cpu 1, msr 8a01041, secondary cpu clock
[  231.090509] masked ExtINT on CPU#1
[  231.117328] kvm-guest: stealtime: cpu 1, msr 3aebf8080
[  237.501337] smpboot: CPU 1 is now offline
[  240.667721] x86: Booting SMP configuration:
[  240.669915] smpboot: Booting Node 0 Processor 1 APIC 0x1
[  240.672831] kvm-clock: cpu 1, msr 8a01041, secondary cpu clock
[  240.672991] masked ExtINT on CPU#1
[  240.713721] kvm-guest: stealtime: cpu 1, msr 3aebf8080

Kboot worker: lkp-worker51
Elapsed time: 240

kvm=(
	qemu-system-x86_64
	-enable-kvm
	-cpu SandyBridge
	-kernel $kernel
	-initrd initrd-vm-snb-228.cgz
	-m 16384
	-smp 2
	-device e1000,netdev=net0
	-netdev user,id=net0,hostfwd=tcp::32032-:22
	-boot order=nc
	-no-reboot
	-watchdog i6300esb
	-watchdog-action debug
	-rtc base=localtime
	-serial stdio
	-display none
	-monitor null
)

append=(
	ip=::::vm-snb-228::dhcp
	root=/dev/ram0
	user=lkp
	job=/job-script
	ARCH=x86_64
	kconfig=x86_64-randconfig-a014-20210513
	branch=tip/sched/core
	commit=f1a0a376ca0c4ef1fc3d24e3e502acbb5b795674
	BOOT_IMAGE=/pkg/linux/x86_64-randconfig-a014-20210513/gcc-9/f1a0a376ca0c4ef1fc3d24e3e502acbb5b795674/vmlinuz-5.13.0-rc1-00108-gf1a0a376ca0c
	vmalloc=512M
	max_uptime=2100
	RESULT_ROOT=/result/locktorture/300s-cpuhotplug/vm-snb/debian-10.4-x86_64-20200603.cgz/x86_64-randconfig-a014-20210513/gcc-9/f1a0a376ca0c4ef1fc3d24e3e502acbb5b795674/21
	result_service=tmpfs
	selinux=0
	debug
	apic=debug
	sysrq_always_enabled
	rcupdate.rcu_cpu_stall_timeout=100
	net.ifnames=0

To reproduce:

        git clone https://github.com/intel/lkp-tests.git
        cd lkp-tests
        bin/lkp qemu -k <bzImage> -m modules.cgz job-script # job-script is attached in this email

---
0DAY/LKP+ Test Infrastructure                   Open Source Technology Center
https://lists.01.org/hyperkitty/list/lkp@lists.01.org       Intel Corporation

Thanks,
Oliver Sang

[-- Attachment #2: job-script --]
[-- Type: text/plain, Size: 4567 bytes --]

#!/bin/sh

export_top_env()
{
	export suite='locktorture'
	export testcase='locktorture'
	export category='functional'
	export need_modules=true
	export need_memory='300MB'
	export runtime=300
	export job_origin='locktorture.yaml'
	export queue_cmdline_keys=
	export queue='int'
	export testbox='vm-snb-228'
	export tbox_group='vm-snb'
	export branch='tip/sched/core'
	export commit='f1a0a376ca0c4ef1fc3d24e3e502acbb5b795674'
	export kconfig='x86_64-randconfig-a014-20210513'
	export nr_vm=160
	export submit_id='60a47a900b9a9364a1ec58ed'
	export job_file='/lkp/jobs/scheduled/vm-snb-228/locktorture-300s-cpuhotplug-debian-10.4-x86_64-20200603.cgz-f1a0a376ca0c4ef1fc3d24e3e502acbb5b795674-20210519-25761-woq8s9-38.yaml'
	export id='b977acb2f978482e90666402e67ebe95878195ca'
	export queuer_version='/lkp/xsang/.src-20210519-100815'
	export model='qemu-system-x86_64 -enable-kvm -cpu SandyBridge'
	export nr_cpu=2
	export memory='16G'
	export need_kconfig='CONFIG_LOCK_TORTURE_TEST=m
CONFIG_SECURITY_LOADPIN_ENABLED=n ~ "<= v4.19"
CONFIG_SECURITY_LOADPIN_ENFORCE=n ~ ">= v4.20"
CONFIG_KVM_GUEST=y'
	export ssh_base_port=23032
	export kernel_cmdline='vmalloc=512M'
	export rootfs='debian-10.4-x86_64-20200603.cgz'
	export compiler='gcc-9'
	export enqueue_time='2021-05-19 10:40:16 +0800'
	export _id='60a47a920b9a9364a1ec5913'
	export _rt='/result/locktorture/300s-cpuhotplug/vm-snb/debian-10.4-x86_64-20200603.cgz/x86_64-randconfig-a014-20210513/gcc-9/f1a0a376ca0c4ef1fc3d24e3e502acbb5b795674'
	export user='lkp'
	export LKP_SERVER='internal-lkp-server'
	export result_root='/result/locktorture/300s-cpuhotplug/vm-snb/debian-10.4-x86_64-20200603.cgz/x86_64-randconfig-a014-20210513/gcc-9/f1a0a376ca0c4ef1fc3d24e3e502acbb5b795674/21'
	export scheduler_version='/lkp/lkp/src'
	export arch='x86_64'
	export max_uptime=2100
	export initrd='/osimage/debian/debian-10.4-x86_64-20200603.cgz'
	export bootloader_append='root=/dev/ram0
user=lkp
job=/lkp/jobs/scheduled/vm-snb-228/locktorture-300s-cpuhotplug-debian-10.4-x86_64-20200603.cgz-f1a0a376ca0c4ef1fc3d24e3e502acbb5b795674-20210519-25761-woq8s9-38.yaml
ARCH=x86_64
kconfig=x86_64-randconfig-a014-20210513
branch=tip/sched/core
commit=f1a0a376ca0c4ef1fc3d24e3e502acbb5b795674
BOOT_IMAGE=/pkg/linux/x86_64-randconfig-a014-20210513/gcc-9/f1a0a376ca0c4ef1fc3d24e3e502acbb5b795674/vmlinuz-5.13.0-rc1-00108-gf1a0a376ca0c
vmalloc=512M
max_uptime=2100
RESULT_ROOT=/result/locktorture/300s-cpuhotplug/vm-snb/debian-10.4-x86_64-20200603.cgz/x86_64-randconfig-a014-20210513/gcc-9/f1a0a376ca0c4ef1fc3d24e3e502acbb5b795674/21
LKP_SERVER=internal-lkp-server
selinux=0
debug
apic=debug
sysrq_always_enabled
rcupdate.rcu_cpu_stall_timeout=100
net.ifnames=0
printk.devkmsg=on
panic=-1
softlockup_panic=1
nmi_watchdog=panic
oops=panic
load_ramdisk=2
prompt_ramdisk=0
drbd.minor_count=8
systemd.log_level=err
ignore_loglevel
console=tty0
earlyprintk=ttyS0,115200
console=ttyS0,115200
vga=normal
rw'
	export modules_initrd='/pkg/linux/x86_64-randconfig-a014-20210513/gcc-9/f1a0a376ca0c4ef1fc3d24e3e502acbb5b795674/modules.cgz'
	export bm_initrd='/osimage/deps/debian-10.4-x86_64-20200603.cgz/run-ipconfig_20200608.cgz,/osimage/deps/debian-10.4-x86_64-20200603.cgz/lkp_20201211.cgz,/osimage/deps/debian-10.4-x86_64-20200603.cgz/rsync-rootfs_20200608.cgz'
	export lkp_initrd='/osimage/user/lkp/lkp-x86_64.cgz'
	export site='46a1f7098976'
	export queue_at_least_once=1
	export kernel='/pkg/linux/x86_64-randconfig-a014-20210513/gcc-9/f1a0a376ca0c4ef1fc3d24e3e502acbb5b795674/vmlinuz-5.13.0-rc1-00108-gf1a0a376ca0c'
	export dequeue_time='2021-05-19 10:53:29 +0800'
	export job_initrd='/lkp/jobs/scheduled/vm-snb-228/locktorture-300s-cpuhotplug-debian-10.4-x86_64-20200603.cgz-f1a0a376ca0c4ef1fc3d24e3e502acbb5b795674-20210519-25761-woq8s9-38.cgz'

	[ -n "$LKP_SRC" ] ||
	export LKP_SRC=/lkp/${user:-lkp}/src
}

run_job()
{
	echo $$ > $TMP/run-job.pid

	. $LKP_SRC/lib/http.sh
	. $LKP_SRC/lib/job.sh
	. $LKP_SRC/lib/env.sh

	export_top_env

	run_monitor $LKP_SRC/monitors/wrapper kmsg
	run_monitor $LKP_SRC/monitors/wrapper heartbeat
	run_monitor $LKP_SRC/monitors/wrapper meminfo

	run_test test='cpuhotplug' $LKP_SRC/tests/wrapper locktorture
}

extract_stats()
{
	export stats_part_begin=
	export stats_part_end=

	env test='cpuhotplug' $LKP_SRC/stats/wrapper locktorture
	$LKP_SRC/stats/wrapper kmsg
	$LKP_SRC/stats/wrapper meminfo

	$LKP_SRC/stats/wrapper time locktorture.time
	$LKP_SRC/stats/wrapper dmesg
	$LKP_SRC/stats/wrapper kmsg
	$LKP_SRC/stats/wrapper last_state
	$LKP_SRC/stats/wrapper stderr
	$LKP_SRC/stats/wrapper time
}

"$@"

[-- Attachment #3: dmesg.xz --]
[-- Type: application/x-xz, Size: 14912 bytes --]

^ permalink raw reply	[flat|nested] 4+ messages in thread