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]
Date:   Wed, 7 Jun 2017 10:07:38 +0800
From:   kernel test robot <xiaolong.ye@...el.com>
To:     Mike Galbraith <efault@....de>
Cc:     Vegard Nossum <vegard.nossum@...cle.com>,
        Greg Kroah-Hartman <gregkh@...uxfoundation.org>,
        Dave Jones <davej@...emonkey.org.uk>,
        Linux Kernel <linux-kernel@...r.kernel.org>,
        Jiri Slaby <jslaby@...e.com>, lkp@...org
Subject: [lkp-robot] [tty]  52b03e644f: calltrace:flush_to_ldisc


FYI, we noticed the following commit:

commit: 52b03e644f702dbcb252f6aec92fc0f0d6e29f78 ("tty: fix port buffer locking V2")
url: https://github.com/0day-ci/linux/commits/Mike-Galbraith/tty-fix-port-buffer-locking-V2/20170605-134432
base: https://git.kernel.org/cgit/linux/kernel/git/gregkh/tty.git tty-testing

in testcase: trinity
with following parameters:

	runtime: 300s

test-description: Trinity is a linux system call fuzz tester.
test-url: http://codemonkey.org.uk/projects/trinity/


on test machine: qemu-system-x86_64 -enable-kvm -cpu SandyBridge -m 512M

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


+--------------------------------------------------+------------+------------+
|                                                  | 094094a937 | 52b03e644f |
+--------------------------------------------------+------------+------------+
| boot_successes                                   | 4          | 2          |
| boot_failures                                    | 4          | 4          |
| BUG:kernel_hang_in_test_stage                    | 4          |            |
| calltrace:flush_to_ldisc                         | 0          | 4          |
| INFO:task_blocked_for_more_than#seconds          | 0          | 4          |
| INFO:lockdep_is_turned_off                       | 0          | 4          |
| Kernel_panic-not_syncing:hung_task:blocked_tasks | 0          | 4          |
+--------------------------------------------------+------------+------------+



[    9.320461] WARNING: possible recursive locking detected
[    9.321874] 4.12.0-rc3-00033-g52b03e6 #39 Not tainted
[    9.323249] --------------------------------------------
[    9.324663] kworker/u2:5/140 is trying to acquire lock:
[    9.326056]  (&tty->atomic_write_lock){+.+.+.}, at: [<ffffffffa4678e69>] tty_port_default_receive_buf+0x4e/0x81
[    9.328716] 
[    9.328716] but task is already holding lock:
[    9.330742]  (&tty->atomic_write_lock){+.+.+.}, at: [<ffffffffa46788ed>] flush_to_ldisc+0x48/0xf6
[    9.346254] 
[    9.346254] other info that might help us debug this:
[    9.348393]  Possible unsafe locking scenario:
[    9.348393] 
[    9.350438]        CPU0
[    9.351425]        ----
[    9.352419]   lock(&tty->atomic_write_lock);
[    9.353679]   lock(&tty->atomic_write_lock);
[    9.354934] 
[    9.354934]  *** DEADLOCK ***
[    9.354934] 
[    9.357511]  May be due to missing lock nesting notation
[    9.357511] 
[    9.372673] 6 locks held by kworker/u2:5/140:
[    9.373945]  #0:  ("events_unbound"){.+.+.+}, at: [<ffffffffa40b8d8b>] process_one_work+0x165/0x56d
[    9.376458]  #1:  ((&buf->work)){+.+...}, at: [<ffffffffa40b8d8b>] process_one_work+0x165/0x56d
[    9.378918]  #2:  (&tty->ldisc_sem){++++.+}, at: [<ffffffffa4677c39>] tty_ldisc_ref+0x1f/0x41
[    9.381356]  #3:  (&tty->atomic_write_lock){+.+.+.}, at: [<ffffffffa46788ed>] flush_to_ldisc+0x48/0xf6
[    9.383917]  #4:  (&buf->lock){+.+...}, at: [<ffffffffa46788fb>] flush_to_ldisc+0x56/0xf6
[    9.399315]  #5:  (&tty->ldisc_sem){++++.+}, at: [<ffffffffa4677c39>] tty_ldisc_ref+0x1f/0x41
[    9.401739] 
[    9.401739] stack backtrace:
[    9.403544] CPU: 0 PID: 140 Comm: kworker/u2:5 Not tainted 4.12.0-rc3-00033-g52b03e6 #39
[    9.405898] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.9.3-20161025_171302-gandalf 04/01/2014
[    9.408556] Workqueue: events_unbound flush_to_ldisc
[    9.409914] Call Trace:
[    9.410910]  dump_stack+0x86/0xc0
[    9.412030]  __lock_acquire+0x86b/0xe43
[    9.413230]  lock_acquire+0x142/0x1dd
[    9.414401]  ? tty_port_default_receive_buf+0x4e/0x81
[    9.415769]  __mutex_lock+0x8a/0x815
[    9.416932]  ? tty_port_default_receive_buf+0x4e/0x81
[    9.418317]  ? find_held_lock+0x31/0x73
[    9.419517]  ? tty_port_default_receive_buf+0x4e/0x81
[    9.420888]  ? tty_ldisc_ref+0x1f/0x41
[    9.422076]  mutex_lock_nested+0x1b/0x1d
[    9.423290]  ? mutex_lock_nested+0x1b/0x1d
[    9.424525]  tty_port_default_receive_buf+0x4e/0x81
[    9.425880]  flush_to_ldisc+0xba/0xf6
[    9.427051]  process_one_work+0x283/0x56d
[    9.428277]  worker_thread+0x1f3/0x2c5
[    9.429460]  ? rescuer_thread+0x2ca/0x2ca
[    9.430682]  kthread+0x134/0x13c
[    9.431787]  ? kthread_create_on_node+0x3f/0x3f
[    9.433083]  ret_from_fork+0x2a/0x40
[    9.762099] random: dd: uninitialized urandom read (512 bytes read)
Poky (Yocto Project Reference Distro) 2.1 qemux86-64 /dev/ttyS0
[   62.664612] rcu-torture: Reader Pipe:  2 0 0 0 0 0 0 0 0 0 0
[   62.666546] rcu-torture: Reader Batch:  1 1 0 0 0 0 0 0 0 0 0
[   62.668279] rcu-torture: Free-Block Circulation:  0 0 0 0 0 0 0 0 0 0 0
[  124.100000] rcu-torture: rtc: ffffffffa67031e0 ver: 1 tfle: 0 rta: 1 rtaf: 0 rtf: 0 rtmbe: 0 rtbe: 0 rtbke: 0 rtbre: 0 rtbf: 0 rtb: 0 nt: 1 onoff: 0/0:0/0 -1,0:-1,0 0:0 (HZ=1000) barrier: 0/0:0 cbflood: 1
[  124.104845] rcu-torture: Reader Pipe:  2 0 0 0 0 0 0 0 0 0 0
[  124.106669] rcu-torture: Reader Batch:  1 1 0 0 0 0 0 0 0 0 0
[  124.108507] rcu-torture: Free-Block Circulation:  0 0 0 0 0 0 0 0 0 0 0
[  124.110337] ??? Writer stall state RTWS_STUTTER(8) g3977 c3976 f0x0 ->state 0x1
[  124.112729] rcu_sched: wait state: 1 ->state: 0x1
[  124.121003] rcu_bh: wait state: 1 ->state: 0x1
[  124.122436] Dumping ftrace buffer:
[  124.123613]    (ftrace buffer empty)
[  185.540010] rcu-torture: rtc: ffffffffa67031e0 ver: 1 tfle: 0 rta: 1 rtaf: 0 rtf: 0 rtmbe: 0 rtbe: 0 rtbke: 0 rtbre: 0 rtbf: 0 rtb: 0 nt: 1 onoff: 0/0:0/0 -1,0:-1,0 0:0 (HZ=1000) barrier: 0/0:0 cbflood: 1
[  185.546024] rcu-torture: Reader Pipe:  2 0 0 0 0 0 0 0 0 0 0
[  185.548198] rcu-torture: Reader Batch:  1 1 0 0 0 0 0 0 0 0 0
[  185.550097] rcu-torture: Free-Block Circulation:  0 0 0 0 0 0 0 0 0 0 0
[  185.552229] ??? Writer stall state RTWS_STUTTER(8) g3979 c3978 f0x0 ->state 0x1
[  185.554941] rcu_sched: wait state: 1 ->state: 0x1
[  185.556603] rcu_bh: wait state: 1 ->state: 0x1
[  246.980009] rcu-torture: rtc: ffffffffa67031e0 ver: 1 tfle: 0 rta: 1 rtaf: 0 rtf: 0 rtmbe: 0 rtbe: 0 rtbke: 0 rtbre: 0 rtbf: 0 rtb: 0 nt: 1 onoff: 0/0:0/0 -1,0:-1,0 0:0 (HZ=1000) barrier: 0/0:0 cbflood: 1
[  246.985336] INFO: task kworker/u2:5:140 blocked for more than 120 seconds.
[  246.985338]       Not tainted 4.12.0-rc3-00033-g52b03e6 #39
[  246.985339] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  246.985341] kworker/u2:5    D13128   140      2 0x00000000
[  246.985361] Workqueue: events_unbound flush_to_ldisc
[  246.985363] Call Trace:
[  246.985370]  __schedule+0x8cd/0xa60
[  246.985373]  ? kvm_sched_clock_read+0x9/0x12
[  246.985377]  schedule+0x89/0x9a
[  246.985379]  schedule_preempt_disabled+0x15/0x1e
[  246.985381]  __mutex_lock+0x595/0x815
[  246.985480]  ? tty_port_default_receive_buf+0x4e/0x81
[  246.985484]  ? tty_ldisc_ref+0x1f/0x41
[  246.985488]  mutex_lock_nested+0x1b/0x1d
[  246.985489]  ? mutex_lock_nested+0x1b/0x1d
[  246.985492]  tty_port_default_receive_buf+0x4e/0x81
[  246.985495]  flush_to_ldisc+0xba/0xf6
[  246.985499]  process_one_work+0x283/0x56d
[  246.985503]  worker_thread+0x1f3/0x2c5
[  246.985507]  ? rescuer_thread+0x2ca/0x2ca
[  246.985509]  kthread+0x134/0x13c
[  246.985511]  ? kthread_create_on_node+0x3f/0x3f
[  246.985514]  ret_from_fork+0x2a/0x40
[  246.985519] INFO: lockdep is turned off.
[  246.985520] NMI backtrace for cpu 0
[  246.985523] CPU: 0 PID: 672 Comm: khungtaskd Not tainted 4.12.0-rc3-00033-g52b03e6 #39
[  246.985524] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.9.3-20161025_171302-gandalf 04/01/2014
[  246.985525] Call Trace:
[  246.985528]  dump_stack+0x86/0xc0
[  246.985530]  nmi_cpu_backtrace+0x7f/0x9c
[  246.985533]  ? irq_force_complete_move+0xeb/0xeb
[  246.985535]  nmi_trigger_cpumask_backtrace+0x62/0xc6
[  246.985538]  arch_trigger_cpumask_backtrace+0x19/0x1b
[  246.985540]  watchdog+0x486/0x55d
[  246.985543]  ? reset_hung_task_detector+0x15/0x15
[  246.985545]  kthread+0x134/0x13c
[  246.985547]  ? kthread_create_on_node+0x3f/0x3f
[  246.985549]  ret_from_fork+0x2a/0x40
[  246.985555] Kernel panic - not syncing: hung_task: blocked tasks
[  246.985557] CPU: 0 PID: 672 Comm: khungtaskd Not tainted 4.12.0-rc3-00033-g52b03e6 #39
[  246.985558] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.9.3-20161025_171302-gandalf 04/01/2014
[  246.985559] Call Trace:
[  246.985560]  dump_stack+0x86/0xc0
[  246.985563]  panic+0xdd/0x221
[  246.985568]  watchdog+0x492/0x55d
[  246.985570]  ? reset_hung_task_detector+0x15/0x15
[  246.985572]  kthread+0x134/0x13c
[  246.985574]  ? kthread_create_on_node+0x3f/0x3f
[  246.985577]  ret_from_fork+0x2a/0x40
[  246.985632] Kernel Offset: 0x23000000 from 0xffffffff81000000 (relocation range: 0xffffffff80000000-0xffffffffbfffffff)

Elapsed time: 250

initrds=(
	/osimage/yocto/yocto-minimal-x86_64-2016-04-22.cgz
	/lkp/scheduled/vm-kbuild-yocto-x86_64-4/trinity-300s-yocto-minimal-x86_64-2016-04-22.cgz-52b03e644f702dbcb252f6aec92fc0f0d6e29f78-20170606-60571-12g8yql-0.cgz
	/lkp/lkp/lkp-x86_64.cgz
	/osimage/pkg/static/trinity-x86_64.cgz
	/pkg/linux/x86_64-nfsroot/gcc-6/52b03e644f702dbcb252f6aec92fc0f0d6e29f78/modules.cgz
)

cat "${initrds[@]}" > /fs/sdh1/initrd-vm-kbuild-yocto-x86_64-4

kvm=(
	qemu-system-x86_64
	-enable-kvm
	-cpu SandyBridge
	-kernel /pkg/linux/x86_64-nfsroot/gcc-6/52b03e644f702dbcb252f6aec92fc0f0d6e29f78/vmlinuz-4.12.0-rc3-00033-g52b03e6
	-initrd /fs/sdh1/initrd-vm-kbuild-yocto-x86_64-4
	-m 512
	-smp 1
	-device e1000,netdev=net0
	-netdev user,id=net0
	-boot order=nc
	-no-reboot
	-watchdog i6300esb
	-watchdog-action debug
	-rtc base=localtime
	-drive file=/fs/sdh1/disk0-vm-kbuild-yocto-x86_64-4,media=disk,if=virtio
	-pidfile /dev/shm/kboot/pid-vm-kbuild-yocto-x86_64-4
	-serial file:/dev/shm/kboot/vm-kbuild-yocto-x86_64-4/serial
	-serial file:/dev/shm/kboot/vm-kbuild-yocto-x86_64-4/kmsg
	-daemonize
	-display none
	-monitor null
)

append=(
	ip=::::vm-kbuild-yocto-x86_64-4::dhcp
	root=/dev/ram0
	user=lkp
	job=/lkp/scheduled/vm-kbuild-yocto-x86_64-4/trinity-300s-yocto-minimal-x86_64-2016-04-22.cgz-52b03e644f702dbcb252f6aec92fc0f0d6e29f78-20170606-60571-12g8yql-0.yaml
	ARCH=x86_64
	kconfig=x86_64-nfsroot
	branch=linux-devel/devel-catchup-201706051509
	commit=52b03e644f702dbcb252f6aec92fc0f0d6e29f78
	BOOT_IMAGE=/pkg/linux/x86_64-nfsroot/gcc-6/52b03e644f702dbcb252f6aec92fc0f0d6e29f78/vmlinuz-4.12.0-rc3-00033-g52b03e6
	max_uptime=1500
	RESULT_ROOT=/result/trinity/300s/vm-kbuild-yocto-x86_64/yocto-minimal-x86_64-2016-04-22.cgz/x86_64-nfsroot/gcc-6/52b03e644f702dbcb252f6aec92fc0f0d6e29f78/0
	LKP_SERVER=inn
	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
	earlyprintk=ttyS0,115200
	console=ttyS0,115200
	console=tty0
	vga=normal
	rw
	drbd.minor_count=8
)

"${kvm[@]}" -append "${append[*]}"


To reproduce:

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



Thanks,
Xiaolong

View attachment "config-4.12.0-rc3-00033-g52b03e6" of type "text/plain" (117109 bytes)

View attachment "job-script" of type "text/plain" (3827 bytes)

Download attachment "dmesg.xz" of type "application/octet-stream" (15028 bytes)

Powered by blists - more mailing lists

Powered by Openwall GNU/*/Linux Powered by OpenVZ