Return-Path: <cyrus@holtmann.org>
Date: Sun, 26 Jan 2014 11:47:21 +0100
From: Sander Eikelenboom <linux@eikelenboom.it>
Message-ID: <378824645.20140126114721@eikelenboom.it>
To: Greg Kroah-Hartman <gregkh@linuxfoundation.org>,
	Marcel Holtmann <marcel@holtmann.org>
CC: linux-wireless@vger.kernel.org, linux-bluetooth@vger.kernel.org,
	<linux-serial@vger.kernel.org>
Subject: 3.14-mw regression:  circular locking dependency (&tty->legacy_mutex){+.+.+.}, at: [<ffffffff81ad6344>] tty_lock_nested+0x44/0xa0
MIME-Version: 1.0
Content-Type: text/plain; charset=us-ascii
List-ID: <linux-bluetooth.vger.kernel.org>

Hi,

I have got a regression with a 3.14-mw kernel (last commit is 4ba9920e5e9c0e16b5ed24292d45322907bb9035)
when a script is started that reads from serial over bluetooth, that wasn't in the 3.13 release kernel:


Jan 26 11:36:10 serveerstertje kernel: [   72.892926]
Jan 26 11:36:10 serveerstertje kernel: [   72.900249] ======================================================
Jan 26 11:36:10 serveerstertje kernel: [   72.907697] [ INFO: possible circular locking dependency detected ]
Jan 26 11:36:10 serveerstertje kernel: [   72.915214] 3.13.0-20140125-mw-pcireset+ #1 Not tainted
Jan 26 11:36:10 serveerstertje kernel: [   72.922307] -------------------------------------------------------
Jan 26 11:36:10 serveerstertje kernel: [   72.928315] zabbix_slimmeme/5909 is trying to acquire lock:
Jan 26 11:36:10 serveerstertje kernel: [   72.934323]  (&tty->legacy_mutex){+.+.+.}, at: [<ffffffff81ad6344>] tty_lock_nested+0x44/0xa0
Jan 26 11:36:10 serveerstertje kernel: [   72.940434] 
Jan 26 11:36:10 serveerstertje kernel: [   72.940434] but task is already holding lock:
Jan 26 11:36:10 serveerstertje kernel: [   72.952263]  (&port->mutex){+.+.+.}, at: [<ffffffff81518aa7>] tty_port_open+0x67/0xe0
Jan 26 11:36:10 serveerstertje kernel: [   72.958292] 
Jan 26 11:36:10 serveerstertje kernel: [   72.958292] which lock already depends on the new lock.
Jan 26 11:36:10 serveerstertje kernel: [   72.958292] 
Jan 26 11:36:10 serveerstertje kernel: [   72.976267] 
Jan 26 11:36:10 serveerstertje kernel: [   72.976267] the existing dependency chain (in reverse order) is:
Jan 26 11:36:10 serveerstertje kernel: [   72.988276] 
Jan 26 11:36:10 serveerstertje kernel: [   72.988276] -> #1 (&port->mutex){+.+.+.}:
Jan 26 11:36:10 serveerstertje kernel: [   73.000386]        [<ffffffff81102dfd>] lock_acquire+0xcd/0x110
Jan 26 11:36:10 serveerstertje kernel: [   73.006526]        [<ffffffff81ad3f97>] mutex_lock_nested+0x47/0x560
Jan 26 11:36:10 serveerstertje kernel: [   73.012612]        [<ffffffff81518aa7>] tty_port_open+0x67/0xe0
Jan 26 11:36:10 serveerstertje kernel: [   73.018637]        [<ffffffff81aa4356>] rfcomm_tty_open+0x26/0xe0
Jan 26 11:36:10 serveerstertje kernel: [   73.024674]        [<ffffffff8150fcea>] tty_open+0x16a/0x5c0
Jan 26 11:36:10 serveerstertje kernel: [   73.030748]        [<ffffffff811b4013>] chrdev_open+0xa3/0x1c0
Jan 26 11:36:10 serveerstertje kernel: [   73.036833]        [<ffffffff811ad686>] do_dentry_open.isra.16+0x246/0x2f0
Jan 26 11:36:10 serveerstertje kernel: [   73.043001]        [<ffffffff811ad81d>] finish_open+0x1d/0x30
Jan 26 11:36:10 serveerstertje kernel: [   73.049106]        [<ffffffff811befae>] do_last+0x7ce/0xdf0
Jan 26 11:36:10 serveerstertje kernel: [   73.055191]        [<ffffffff811bf68d>] path_openat+0xbd/0x6b0
Jan 26 11:36:10 serveerstertje kernel: [   73.061211]        [<ffffffff811c004e>] do_filp_open+0x3e/0xa0
Jan 26 11:36:10 serveerstertje kernel: [   73.067177]        [<ffffffff811aeaec>] do_sys_open+0x13c/0x230
Jan 26 11:36:10 serveerstertje kernel: [   73.073141]        [<ffffffff811aebfd>] SyS_open+0x1d/0x20
Jan 26 11:36:10 serveerstertje kernel: [   73.079047]        [<ffffffff81ad6f39>] system_call_fastpath+0x16/0x1b
Jan 26 11:36:10 serveerstertje kernel: [   73.084962] 
Jan 26 11:36:10 serveerstertje kernel: [   73.084962] -> #0 (&tty->legacy_mutex){+.+.+.}:
Jan 26 11:36:10 serveerstertje kernel: [   73.096600]        [<ffffffff8110230b>] __lock_acquire+0x1d4b/0x2220
Jan 26 11:36:10 serveerstertje kernel: [   73.102559]        [<ffffffff81102dfd>] lock_acquire+0xcd/0x110
Jan 26 11:36:10 serveerstertje kernel: [   73.108475]        [<ffffffff81ad3f97>] mutex_lock_nested+0x47/0x560
Jan 26 11:36:10 serveerstertje kernel: [   73.114419]        [<ffffffff81ad6344>] tty_lock_nested+0x44/0xa0
Jan 26 11:36:10 serveerstertje kernel: [   73.120354]        [<ffffffff81ad63ab>] tty_lock+0xb/0x10
Jan 26 11:36:10 serveerstertje kernel: [   73.126258]        [<ffffffff81aa4677>] rfcomm_dev_activate+0xb7/0x250
Jan 26 11:36:10 serveerstertje kernel: [   73.132222]        [<ffffffff81518ad7>] tty_port_open+0x97/0xe0
Jan 26 11:36:10 serveerstertje kernel: [   73.138195]        [<ffffffff81aa4356>] rfcomm_tty_open+0x26/0xe0
Jan 26 11:36:10 serveerstertje kernel: [   73.144207]        [<ffffffff8150fcea>] tty_open+0x16a/0x5c0
Jan 26 11:36:10 serveerstertje kernel: [   73.150164]        [<ffffffff811b4013>] chrdev_open+0xa3/0x1c0
Jan 26 11:36:10 serveerstertje kernel: [   73.156127]        [<ffffffff811ad686>] do_dentry_open.isra.16+0x246/0x2f0
Jan 26 11:36:10 serveerstertje kernel: [   73.162070]        [<ffffffff811ad81d>] finish_open+0x1d/0x30
Jan 26 11:36:10 serveerstertje kernel: [   73.167933]        [<ffffffff811befae>] do_last+0x7ce/0xdf0
Jan 26 11:36:10 serveerstertje kernel: [   73.173787]        [<ffffffff811bf68d>] path_openat+0xbd/0x6b0
Jan 26 11:36:10 serveerstertje kernel: [   73.179600]        [<ffffffff811c004e>] do_filp_open+0x3e/0xa0
Jan 26 11:36:10 serveerstertje kernel: [   73.185302]        [<ffffffff811aeaec>] do_sys_open+0x13c/0x230
Jan 26 11:36:10 serveerstertje kernel: [   73.190880]        [<ffffffff811aebfd>] SyS_open+0x1d/0x20
Jan 26 11:36:10 serveerstertje kernel: [   73.196247]        [<ffffffff81ad6f39>] system_call_fastpath+0x16/0x1b
Jan 26 11:36:10 serveerstertje kernel: [   73.201486] 
Jan 26 11:36:10 serveerstertje kernel: [   73.201486] other info that might help us debug this:
Jan 26 11:36:10 serveerstertje kernel: [   73.201486] 
Jan 26 11:36:10 serveerstertje kernel: [   73.216718]  Possible unsafe locking scenario:
Jan 26 11:36:10 serveerstertje kernel: [   73.216718] 
Jan 26 11:36:10 serveerstertje kernel: [   73.226933]        CPU0                    CPU1
Jan 26 11:36:10 serveerstertje kernel: [   73.231978]        ----                    ----
Jan 26 11:36:10 serveerstertje kernel: [   73.237001]   lock(&port->mutex);
Jan 26 11:36:10 serveerstertje kernel: [   73.241994]                                lock(&tty->legacy_mutex);
Jan 26 11:36:10 serveerstertje kernel: [   73.247043]                                lock(&port->mutex);
Jan 26 11:36:10 serveerstertje kernel: [   73.251999]   lock(&tty->legacy_mutex);
Jan 26 11:36:10 serveerstertje kernel: [   73.256902] 
Jan 26 11:36:10 serveerstertje kernel: [   73.256902]  *** DEADLOCK ***
Jan 26 11:36:10 serveerstertje kernel: [   73.256902] 
Jan 26 11:36:10 serveerstertje kernel: [   73.270890] 1 lock held by zabbix_slimmeme/5909:
Jan 26 11:36:10 serveerstertje kernel: [   73.275398]  #0:  (&port->mutex){+.+.+.}, at: [<ffffffff81518aa7>] tty_port_open+0x67/0xe0
Jan 26 11:36:10 serveerstertje kernel: [   73.280124] 
Jan 26 11:36:10 serveerstertje kernel: [   73.280124] stack backtrace:
Jan 26 11:36:10 serveerstertje kernel: [   73.289130] CPU: 5 PID: 5909 Comm: zabbix_slimmeme Not tainted 3.13.0-20140125-mw-pcireset+ #1
Jan 26 11:36:10 serveerstertje kernel: [   73.293860] Hardware name: MSI MS-7640/890FXA-GD70 (MS-7640)  , BIOS V1.8B1 09/13/2010
Jan 26 11:36:10 serveerstertje kernel: [   73.298625]  ffffffff826e2b70 ffff88005858f818 ffffffff81acbcfa ffff880057c72300
Jan 26 11:36:10 serveerstertje kernel: [   73.303571]  ffffffff826e2b70 ffff88005858f868 ffffffff81ac7011 ffff880057c72300
Jan 26 11:36:10 serveerstertje kernel: [   73.308511]  ffff880057c72300 ffff88005858f868 ffff880057c72ac0 0000000000000000
Jan 26 11:36:10 serveerstertje kernel: [   73.313325] Call Trace:
Jan 26 11:36:10 serveerstertje kernel: [   73.318092]  [<ffffffff81acbcfa>] dump_stack+0x46/0x58
Jan 26 11:36:10 serveerstertje kernel: [   73.322900]  [<ffffffff81ac7011>] print_circular_bug+0x2f6/0x32a
Jan 26 11:36:10 serveerstertje kernel: [   73.327723]  [<ffffffff8110230b>] __lock_acquire+0x1d4b/0x2220
Jan 26 11:36:10 serveerstertje kernel: [   73.332545]  [<ffffffff810fedbd>] ? trace_hardirqs_on+0xd/0x10
Jan 26 11:36:10 serveerstertje kernel: [   73.337414]  [<ffffffff810e6141>] ? finish_task_switch+0x41/0xf0
Jan 26 11:36:10 serveerstertje kernel: [   73.342279]  [<ffffffff81ad0244>] ? sleep_on_timeout+0x4/0x20
Jan 26 11:36:10 serveerstertje kernel: [   73.347128]  [<ffffffff81102dfd>] lock_acquire+0xcd/0x110
Jan 26 11:36:10 serveerstertje kernel: [   73.351950]  [<ffffffff81ad6344>] ? tty_lock_nested+0x44/0xa0
Jan 26 11:36:10 serveerstertje kernel: [   73.356792]  [<ffffffff81ad3f97>] mutex_lock_nested+0x47/0x560
Jan 26 11:36:10 serveerstertje kernel: [   73.361599]  [<ffffffff81ad6344>] ? tty_lock_nested+0x44/0xa0
Jan 26 11:36:10 serveerstertje kernel: [   73.366363]  [<ffffffff810fec6b>] ? trace_hardirqs_on_caller+0xfb/0x240
Jan 26 11:36:10 serveerstertje kernel: [   73.371200]  [<ffffffff810fedbd>] ? trace_hardirqs_on+0xd/0x10
Jan 26 11:36:10 serveerstertje kernel: [   73.376030]  [<ffffffff81ad6344>] tty_lock_nested+0x44/0xa0
Jan 26 11:36:10 serveerstertje kernel: [   73.380842]  [<ffffffff81ad63ab>] tty_lock+0xb/0x10
Jan 26 11:36:10 serveerstertje kernel: [   73.385616]  [<ffffffff81aa4677>] rfcomm_dev_activate+0xb7/0x250
Jan 26 11:36:10 serveerstertje kernel: [   73.390398]  [<ffffffff81ad4287>] ? mutex_lock_nested+0x337/0x560
Jan 26 11:36:10 serveerstertje kernel: [   73.395154]  [<ffffffff810f90f0>] ? __init_waitqueue_head+0x60/0x60
Jan 26 11:36:10 serveerstertje kernel: [   73.399861]  [<ffffffff81518ad7>] tty_port_open+0x97/0xe0
Jan 26 11:36:10 serveerstertje kernel: [   73.404552]  [<ffffffff81aa4356>] rfcomm_tty_open+0x26/0xe0
Jan 26 11:36:10 serveerstertje kernel: [   73.409263]  [<ffffffff8150fcea>] tty_open+0x16a/0x5c0
Jan 26 11:36:10 serveerstertje kernel: [   73.413954]  [<ffffffff811b4013>] chrdev_open+0xa3/0x1c0
Jan 26 11:36:10 serveerstertje kernel: [   73.418657]  [<ffffffff81457bfd>] ? lockref_get+0x1d/0x30
Jan 26 11:36:10 serveerstertje kernel: [   73.423379]  [<ffffffff811b3f70>] ? cdev_put+0x30/0x30
Jan 26 11:36:10 serveerstertje kernel: [   73.428056]  [<ffffffff811ad686>] do_dentry_open.isra.16+0x246/0x2f0
Jan 26 11:36:10 serveerstertje kernel: [   73.432768]  [<ffffffff811ad81d>] finish_open+0x1d/0x30
Jan 26 11:36:10 serveerstertje kernel: [   73.437464]  [<ffffffff811befae>] do_last+0x7ce/0xdf0
Jan 26 11:36:10 serveerstertje kernel: [   73.442166]  [<ffffffff811baff3>] ? inode_permission+0x13/0x50
Jan 26 11:36:10 serveerstertje kernel: [   73.446861]  [<ffffffff811bb5ce>] ? link_path_walk+0x21e/0x880
Jan 26 11:36:10 serveerstertje kernel: [   73.451533]  [<ffffffff810fec6b>] ? trace_hardirqs_on_caller+0xfb/0x240
Jan 26 11:36:10 serveerstertje kernel: [   73.456280]  [<ffffffff811bf68d>] path_openat+0xbd/0x6b0
Jan 26 11:36:10 serveerstertje kernel: [   73.461029]  [<ffffffff8104cb03>] ? __do_page_fault+0x103/0x4e0
Jan 26 11:36:10 serveerstertje kernel: [   73.465782]  [<ffffffff81102e1d>] ? lock_acquire+0xed/0x110
Jan 26 11:36:10 serveerstertje kernel: [   73.470553]  [<ffffffff811c004e>] do_filp_open+0x3e/0xa0
Jan 26 11:36:10 serveerstertje kernel: [   73.475321]  [<ffffffff811cda31>] ? __alloc_fd+0xd1/0x120
Jan 26 11:36:10 serveerstertje kernel: [   73.480064]  [<ffffffff811aeaec>] do_sys_open+0x13c/0x230
Jan 26 11:36:10 serveerstertje kernel: [   73.484743]  [<ffffffff810fec6b>] ? trace_hardirqs_on_caller+0xfb/0x240
Jan 26 11:36:10 serveerstertje kernel: [   73.489470]  [<ffffffff811aebfd>] SyS_open+0x1d/0x20
Jan 26 11:36:10 serveerstertje kernel: [   73.494191]  [<ffffffff81ad6f39>] system_call_fastpath+0x16/0x1b