The imon_ir_change_protocol function gets called two different ways, one
way is from rc_register_device, for initial protocol selection/setup,
and the other is via a userspace-initiated protocol change request,
either by direct sysfs prodding or by something like ir-keytable.
In the rc_register_device case, the imon context lock is already held,
but when initiated from userspace, it is not, so we must acquire it,
prior to calling send_packet, which requires that the lock is held.
Without this change, there's an easily reproduceable deadlock when
another function calls send_packet (such as either of the display write
fops) after a userspace-initiated change_protocol.
With a lock-debugging-enabled kernel, I was getting this:
[ 15.014153] =====================================
[ 15.015048] [ BUG: bad unlock balance detected! ]
[ 15.015048] -------------------------------------
[ 15.015048] ir-keytable/773 is trying to release lock (&ictx->lock) at:
[ 15.015048] [<ffffffff814c6297>] mutex_unlock+0xe/0x10
[ 15.015048] but there are no more locks to release!
[ 15.015048]
[ 15.015048] other info that might help us debug this:
[ 15.015048] 2 locks held by ir-keytable/773:
[ 15.015048] #0: (&buffer->mutex){+.+.+.}, at: [<ffffffff8119d400>] sysfs_write_file+0x3c/0x144
[ 15.015048] #1: (s_active#87){.+.+.+}, at: [<ffffffff8119d4ab>] sysfs_write_file+0xe7/0x144
[ 15.015048]
[ 15.015048] stack backtrace:
[ 15.015048] Pid: 773, comm: ir-keytable Not tainted 2.6.38.4-20.fc15.x86_64.debug #1
[ 15.015048] Call Trace:
[ 15.015048] [<ffffffff81089715>] ? print_unlock_inbalance_bug+0xca/0xd5
[ 15.015048] [<ffffffff8108b35c>] ? lock_release_non_nested+0xc1/0x263
[ 15.015048] [<ffffffff814c6297>] ? mutex_unlock+0xe/0x10
[ 15.015048] [<ffffffff814c6297>] ? mutex_unlock+0xe/0x10
[ 15.015048] [<ffffffff8108b67b>] ? lock_release+0x17d/0x1a4
[ 15.015048] [<ffffffff814c6229>] ? __mutex_unlock_slowpath+0xc5/0x125
[ 15.015048] [<ffffffff814c6297>] ? mutex_unlock+0xe/0x10
[ 15.015048] [<ffffffffa02964b6>] ? send_packet+0x1c9/0x264 [imon]
[ 15.015048] [<ffffffff8108b376>] ? lock_release_non_nested+0xdb/0x263
[ 15.015048] [<ffffffffa0296731>] ? imon_ir_change_protocol+0x126/0x15e [imon]
[ 15.015048] [<ffffffffa024a334>] ? store_protocols+0x1c3/0x286 [rc_core]
[ 15.015048] [<ffffffff81326e4e>] ? dev_attr_store+0x20/0x22
[ 15.015048] [<ffffffff8119d4cc>] ? sysfs_write_file+0x108/0x144
...
The original report that led to the investigation was the following:
[ 1679.457305] INFO: task LCDd:8460 blocked for more than 120 seconds.
[ 1679.457307] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1679.457309] LCDd D ffff88010fcd89c8 0 8460 1 0x00000000
[ 1679.457312] ffff8800d5a03b48 0000000000000082 0000000000000000 ffff8800d5a03fd8
[ 1679.457314] 00000000012dcd30 fffffffffffffffd ffff8800d5a03fd8 ffff88010fcd86f0
[ 1679.457316] ffff8800d5a03fd8 ffff8800d5a03fd8 ffff88010fcd89d0 ffff8800d5a03fd8
[ 1679.457319] Call Trace:
[ 1679.457324] [<ffffffff810ff1a5>] ? zone_statistics+0x75/0x90
[ 1679.457327] [<ffffffff810ea907>] ? get_page_from_freelist+0x3c7/0x820
[ 1679.457330] [<ffffffff813b0a49>] __mutex_lock_slowpath+0x139/0x320
[ 1679.457335] [<ffffffff813b0c41>] mutex_lock+0x11/0x30
[ 1679.457338] [<ffffffffa0d54216>] display_open+0x66/0x130 [imon]
[ 1679.457345] [<ffffffffa01d06c0>] usb_open+0x180/0x310 [usbcore]
[ 1679.457349] [<ffffffff81143b3b>] chrdev_open+0x1bb/0x2d0
[ 1679.457350] [<ffffffff8113d93d>] __dentry_open+0x10d/0x370
[ 1679.457352] [<ffffffff81143980>] ? chrdev_open+0x0/0x2d0
...
Bump the driver version here so its easier to tell if people have this
locking fix or not, and also make locking during probe easier to follow.
CC: stable@kernel.org
Reported-by: Benjamin Hodgetts <ben@xnode.org>
Signed-off-by: Jarod Wilson <jarod@redhat.com>
Signed-off-by: Mauro Carvalho Chehab <mchehab@redhat.com>
23ef710e1a