2011-06-03 16:09:31

by Duane Griffin

[permalink] [raw]
Subject: rfkill deadlock

Hi there,

I'm getting a deadlock with 3.0.0-rc1:

Jun 3 12:06:20 kereru kernel: =======================================================
Jun 3 12:06:20 kereru kernel: [ INFO: possible circular locking dependency detected ]
Jun 3 12:06:20 kereru kernel: 3.0.0-rc1-00049-g1fa7b6a #57
Jun 3 12:06:20 kereru kernel: -------------------------------------------------------
Jun 3 12:06:20 kereru kernel: kworker/0:1/4525 is trying to acquire lock:
Jun 3 12:06:20 kereru kernel: (&rdev->mtx){+.+.+.}, at: [<ffffffff8164c831>] cfg80211_netdev_notifier_call+0x131/0x5b0
Jun 3 12:06:20 kereru kernel:
Jun 3 12:06:20 kereru kernel: but task is already holding lock:
Jun 3 12:06:20 kereru kernel: (&rdev->devlist_mtx){+.+.+.}, at: [<ffffffff8164dcef>] cfg80211_rfkill_set_block+0x4f/0xa0
Jun 3 12:06:20 kereru kernel:
Jun 3 12:06:20 kereru kernel: which lock already depends on the new lock.
Jun 3 12:06:20 kereru kernel:
Jun 3 12:06:20 kereru kernel:
Jun 3 12:06:20 kereru kernel: the existing dependency chain (in reverse order) is:
Jun 3 12:06:20 kereru kernel:
Jun 3 12:06:20 kereru kernel: -> #1 (&rdev->devlist_mtx){+.+.+.}:
Jun 3 12:06:20 kereru kernel: [<ffffffff81096473>] lock_acquire+0x103/0x140
Jun 3 12:06:20 kereru kernel: [<ffffffff816b0872>] mutex_lock_nested+0x72/0x3f0
Jun 3 12:06:20 kereru kernel: [<ffffffff8164cbcd>] cfg80211_netdev_notifier_call+0x4cd/0x5b0
Jun 3 12:06:20 kereru kernel: [<ffffffff816b615d>] notifier_call_chain+0x6d/0xb0
Jun 3 12:06:20 kereru kernel: [<ffffffff810814a6>] raw_notifier_call_chain+0x16/0x20
Jun 3 12:06:20 kereru kernel: [<ffffffff81597047>] call_netdevice_notifiers+0x37/0x70
Jun 3 12:06:20 kereru kernel: [<ffffffff81597c09>] __dev_notify_flags+0x39/0x90
Jun 3 12:06:20 kereru kernel: [<ffffffff81597ca5>] dev_change_flags+0x45/0x70
Jun 3 12:06:20 kereru kernel: [<ffffffff815a5745>] do_setlink+0x225/0x9e0
Jun 3 12:06:20 kereru kernel: [<ffffffff815a6c6c>] rtnl_newlink+0x3dc/0x5d0
Jun 3 12:06:20 kereru kernel: [<ffffffff815a683f>] rtnetlink_rcv_msg+0x21f/0x270
Jun 3 12:06:20 kereru kernel: [<ffffffff815b4979>] netlink_rcv_skb+0x89/0xb0
Jun 3 12:06:20 kereru kernel: [<ffffffff815a660e>] rtnetlink_rcv+0x2e/0x40
Jun 3 12:06:20 kereru kernel: [<ffffffff815b462f>] netlink_unicast+0x2af/0x2c0
Jun 3 12:06:20 kereru kernel: [<ffffffff815b5026>] netlink_sendmsg+0x316/0x350
Jun 3 12:06:20 kereru kernel: [<ffffffff81580938>] sock_sendmsg+0xe8/0x120
Jun 3 12:06:20 kereru kernel: [<ffffffff815817a1>] __sys_sendmsg+0x191/0x340
Jun 3 12:06:20 kereru kernel: [<ffffffff81581b29>] sys_sendmsg+0x49/0x80
Jun 3 12:06:20 kereru kernel: [<ffffffff816b9beb>] system_call_fastpath+0x16/0x1b
Jun 3 12:06:20 kereru kernel:
Jun 3 12:06:20 kereru kernel: -> #0 (&rdev->mtx){+.+.+.}:
Jun 3 12:06:20 kereru kernel: [<ffffffff81095d13>] __lock_acquire+0x1e13/0x1ef0
Jun 3 12:06:20 kereru kernel: [<ffffffff81096473>] lock_acquire+0x103/0x140
Jun 3 12:06:20 kereru kernel: [<ffffffff816b0872>] mutex_lock_nested+0x72/0x3f0
Jun 3 12:06:20 kereru kernel: [<ffffffff8164c831>] cfg80211_netdev_notifier_call+0x131/0x5b0
Jun 3 12:06:20 kereru kernel: [<ffffffff816b615d>] notifier_call_chain+0x6d/0xb0
Jun 3 12:06:20 kereru kernel: [<ffffffff810814a6>] raw_notifier_call_chain+0x16/0x20
Jun 3 12:06:20 kereru kernel: [<ffffffff81597047>] call_netdevice_notifiers+0x37/0x70
Jun 3 12:06:20 kereru kernel: [<ffffffff815970cd>] __dev_close_many+0x4d/0xf0
Jun 3 12:06:20 kereru kernel: [<ffffffff81597265>] dev_close_many+0xa5/0x120
Jun 3 12:06:20 kereru kernel: [<ffffffff8159731f>] dev_close+0x3f/0x60
Jun 3 12:06:20 kereru kernel: [<ffffffff8164dd19>] cfg80211_rfkill_set_block+0x79/0xa0
Jun 3 12:06:20 kereru kernel: [<ffffffff81693022>] rfkill_set_block+0x82/0x110
Jun 3 12:06:20 kereru kernel: [<ffffffff81693377>] rfkill_switch_all+0xa7/0xd0
Jun 3 12:06:20 kereru kernel: [<ffffffff8169453d>] rfkill_op_handler+0xdd/0x1a0
Jun 3 12:06:20 kereru kernel: [<ffffffff8107348f>] process_one_work+0x20f/0x590
Jun 3 12:06:20 kereru kernel: [<ffffffff81073bbb>] worker_thread+0x19b/0x420
Jun 3 12:06:20 kereru kernel: [<ffffffff8107aed6>] kthread+0xa6/0xb0
Jun 3 12:06:20 kereru kernel: [<ffffffff816baa14>] kernel_thread_helper+0x4/0x10
Jun 3 12:06:20 kereru kernel:
Jun 3 12:06:20 kereru kernel: other info that might help us debug this:
Jun 3 12:06:20 kereru kernel:
Jun 3 12:06:20 kereru kernel: Possible unsafe locking scenario:
Jun 3 12:06:20 kereru kernel:
Jun 3 12:06:20 kereru kernel: CPU0 CPU1
Jun 3 12:06:20 kereru kernel: ---- ----
Jun 3 12:06:20 kereru kernel: lock(&rdev->devlist_mtx);
Jun 3 12:06:20 kereru kernel: lock(&rdev->mtx);
Jun 3 12:06:20 kereru kernel: lock(&rdev->devlist_mtx);
Jun 3 12:06:20 kereru kernel: lock(&rdev->mtx);
Jun 3 12:06:20 kereru kernel:
Jun 3 12:06:20 kereru kernel: *** DEADLOCK ***
Jun 3 12:06:20 kereru kernel:
Jun 3 12:06:20 kereru kernel: 5 locks held by kworker/0:1/4525:
Jun 3 12:06:20 kereru kernel: #0: (events){.+.+.+}, at: [<ffffffff810733d1>] process_one_work+0x151/0x590
Jun 3 12:06:20 kereru kernel: #1: ((rfkill_op_work).work){+.+.+.}, at: [<ffffffff810733d1>] process_one_work+0x151/0x590
Jun 3 12:06:20 kereru kernel: #2: (rfkill_global_mutex){+.+.+.}, at: [<ffffffff8169331e>] rfkill_switch_all+0x4e/0xd0
Jun 3 12:06:20 kereru kernel: #3: (rtnl_mutex){+.+.+.}, at: [<ffffffff815a65d7>] rtnl_lock+0x17/0x20
Jun 3 12:06:20 kereru kernel: #4: (&rdev->devlist_mtx){+.+.+.}, at: [<ffffffff8164dcef>] cfg80211_rfkill_set_block+0x4f/0xa0
Jun 3 12:06:20 kereru kernel:
Jun 3 12:06:20 kereru kernel: stack backtrace:
Jun 3 12:06:20 kereru kernel: Pid: 4525, comm: kworker/0:1 Not tainted 3.0.0-rc1-00049-g1fa7b6a #57
Jun 3 12:06:20 kereru kernel: Call Trace:
Jun 3 12:06:20 kereru kernel: [<ffffffff81093df8>] print_circular_bug+0x218/0x320
Jun 3 12:06:20 kereru kernel: [<ffffffff81095d13>] __lock_acquire+0x1e13/0x1ef0
Jun 3 12:06:20 kereru kernel: [<ffffffff81093533>] ? check_usage+0x93/0x640
Jun 3 12:06:20 kereru kernel: [<ffffffff81096473>] lock_acquire+0x103/0x140
Jun 3 12:06:20 kereru kernel: [<ffffffff8164c831>] ? cfg80211_netdev_notifier_call+0x131/0x5b0
Jun 3 12:06:20 kereru kernel: [<ffffffff816b0872>] mutex_lock_nested+0x72/0x3f0
Jun 3 12:06:20 kereru kernel: [<ffffffff8164c831>] ? cfg80211_netdev_notifier_call+0x131/0x5b0
Jun 3 12:06:20 kereru kernel: [<ffffffff8164c831>] ? cfg80211_netdev_notifier_call+0x131/0x5b0
Jun 3 12:06:20 kereru kernel: [<ffffffff816b2f44>] ? retint_restore_args+0xe/0xe
Jun 3 12:06:20 kereru kernel: [<ffffffff8164c831>] cfg80211_netdev_notifier_call+0x131/0x5b0
Jun 3 12:06:20 kereru logger: ACPI event unhandled: button/wlan WLAN 00000080 00000000
Jun 3 12:06:20 kereru kernel: [<ffffffff816b615d>] notifier_call_chain+0x6d/0xb0
Jun 3 12:06:20 kereru kernel: [<ffffffff810814a6>] raw_notifier_call_chain+0x16/0x20
Jun 3 12:06:20 kereru kernel: [<ffffffff81597047>] call_netdevice_notifiers+0x37/0x70
Jun 3 12:06:20 kereru kernel: [<ffffffff815970cd>] __dev_close_many+0x4d/0xf0
Jun 3 12:06:20 kereru kernel: [<ffffffff81597265>] dev_close_many+0xa5/0x120
Jun 3 12:06:20 kereru kernel: [<ffffffff8159731f>] dev_close+0x3f/0x60
Jun 3 12:06:20 kereru kernel: [<ffffffff8164dd19>] cfg80211_rfkill_set_block+0x79/0xa0
Jun 3 12:06:20 kereru kernel: [<ffffffff81693022>] rfkill_set_block+0x82/0x110
Jun 3 12:06:20 kereru kernel: [<ffffffff81693377>] rfkill_switch_all+0xa7/0xd0
Jun 3 12:06:20 kereru kernel: [<ffffffff8169453d>] rfkill_op_handler+0xdd/0x1a0
Jun 3 12:06:20 kereru kernel: [<ffffffff8107348f>] process_one_work+0x20f/0x590
Jun 3 12:06:20 kereru kernel: [<ffffffff810733d1>] ? process_one_work+0x151/0x590
Jun 3 12:06:20 kereru kernel: [<ffffffff8109035e>] ? put_lock_stats+0xe/0x40
Jun 3 12:06:20 kereru kernel: [<ffffffff81694460>] ? rfkill_alloc+0x150/0x150
Jun 3 12:06:20 kereru kernel: [<ffffffff81073bbb>] worker_thread+0x19b/0x420
Jun 3 12:06:20 kereru kernel: [<ffffffff81073a20>] ? manage_workers+0x210/0x210
Jun 3 12:06:20 kereru kernel: [<ffffffff8107aed6>] kthread+0xa6/0xb0
Jun 3 12:06:20 kereru kernel: [<ffffffff816baa14>] kernel_thread_helper+0x4/0x10
Jun 3 12:06:20 kereru kernel: [<ffffffff8104ad08>] ? finish_task_switch+0x88/0x110
Jun 3 12:06:20 kereru kernel: [<ffffffff816b2f44>] ? retint_restore_args+0xe/0xe
Jun 3 12:06:20 kereru kernel: [<ffffffff8107ae30>] ? __init_kthread_worker+0x70/0x70
Jun 3 12:06:20 kereru kernel: [<ffffffff816baa10>] ? gs_change+0xb/0xb
Jun 3 12:06:20 kereru kernel: wlan%d: deauthenticating from 54:e6:fc:ae:e8:3d by local choice (reason=3)
Jun 3 12:06:20 kereru kernel: cfg80211: Calling CRDA to update world regulatory domain
Jun 3 12:06:20 kereru dhcpcd[3290]: wlan0: carrier lost

This is a new machine, so I've not tried earlier kernels on it. Let me
know if you'd like further information or other testing.

BTW, I assume that the "wlan%d" is also a (minor) bug :)

Cheers,
Duane Griffin.


2011-06-03 20:58:49

by Johannes Berg

[permalink] [raw]
Subject: Re: rfkill deadlock

On Fri, 2011-06-03 at 17:00 +0100, [email protected] wrote:
> Hi there,
>
> I'm getting a deadlock with 3.0.0-rc1:
>
> Jun 3 12:06:20 kereru kernel: =======================================================
> Jun 3 12:06:20 kereru kernel: [ INFO: possible circular locking dependency detected ]
> Jun 3 12:06:20 kereru kernel: 3.0.0-rc1-00049-g1fa7b6a #57
> Jun 3 12:06:20 kereru kernel: -------------------------------------------------------
> Jun 3 12:06:20 kereru kernel: kworker/0:1/4525 is trying to acquire lock:
> Jun 3 12:06:20 kereru kernel: (&rdev->mtx){+.+.+.}, at: [<ffffffff8164c831>] cfg80211_netdev_notifier_call+0x131/0x5b0
> Jun 3 12:06:20 kereru kernel:
> Jun 3 12:06:20 kereru kernel: but task is already holding lock:
> Jun 3 12:06:20 kereru kernel: (&rdev->devlist_mtx){+.+.+.}, at: [<ffffffff8164dcef>] cfg80211_rfkill_set_block+0x4f/0xa0
> Jun 3 12:06:20 kereru kernel:
> Jun 3 12:06:20 kereru kernel: which lock already depends on the new lock.

This is caused by Luca's scheduled scan changes. The reason is that
cfg80211_rfkill_set_block holds devlist_mtx, but then he added
cfg80211_lock_rdev(rdev); to NETDEV_GOING_DOWN, which is of course
invoked by dev_close() in cfg80211_rfkill_set_block(). Thus, the
problem. Not sure what to do to solve it, I'll let him sort it out :)

johannes


2011-06-06 06:23:59

by Luciano Coelho

[permalink] [raw]
Subject: Re: rfkill deadlock

On Fri, 2011-06-03 at 22:58 +0200, Johannes Berg wrote:
> On Fri, 2011-06-03 at 17:00 +0100, [email protected] wrote:
> > Hi there,
> >
> > I'm getting a deadlock with 3.0.0-rc1:
> >
> > Jun 3 12:06:20 kereru kernel: =======================================================
> > Jun 3 12:06:20 kereru kernel: [ INFO: possible circular locking dependency detected ]
> > Jun 3 12:06:20 kereru kernel: 3.0.0-rc1-00049-g1fa7b6a #57
> > Jun 3 12:06:20 kereru kernel: -------------------------------------------------------
> > Jun 3 12:06:20 kereru kernel: kworker/0:1/4525 is trying to acquire lock:
> > Jun 3 12:06:20 kereru kernel: (&rdev->mtx){+.+.+.}, at: [<ffffffff8164c831>] cfg80211_netdev_notifier_call+0x131/0x5b0
> > Jun 3 12:06:20 kereru kernel:
> > Jun 3 12:06:20 kereru kernel: but task is already holding lock:
> > Jun 3 12:06:20 kereru kernel: (&rdev->devlist_mtx){+.+.+.}, at: [<ffffffff8164dcef>] cfg80211_rfkill_set_block+0x4f/0xa0
> > Jun 3 12:06:20 kereru kernel:
> > Jun 3 12:06:20 kereru kernel: which lock already depends on the new lock.
>
> This is caused by Luca's scheduled scan changes. The reason is that
> cfg80211_rfkill_set_block holds devlist_mtx, but then he added
> cfg80211_lock_rdev(rdev); to NETDEV_GOING_DOWN, which is of course
> invoked by dev_close() in cfg80211_rfkill_set_block(). Thus, the
> problem. Not sure what to do to solve it, I'll let him sort it out :)

Argh! Well, I guess I have to look into how to solve this. :\


--
Cheers,
Luca.