Re: [PATCH] Input: uinput - Allow uinput_request to be interrupted

Re: [PATCH] Input: uinput - Allow uinput_request to be interrupted

[Dmitry Torokhov]

Hi Marcos,

On Sun, Feb 17, 2019 at 09:42:52PM -0300, Marcos Paulo de Souza wrote:
> Commit 8e009118a45a ("Input: uinput - allow FF requests to time out")
> sets a timeout of 30 seconds to wait for force feedback interaction with
> userspace, but also made it impossible to interrupt the event handling of
> uinput code.

No, the original code was using wait_for_completion() and therefore did
not allow interrupting FF requests either. I'll apply the patch, but
will drop the "Fixes" reference.

Thanks.

> Make it interrutible by changing from
> wait_for_completion_timeout to wait_for_completion_interruptible_timeout.
> 
> Bugzilla: https://bugzilla.kernel.org/show_bug.cgi?id=193741
> 
> Fixes: 8e009118a45a ("Input: uinput - allow FF requests to time out")
> Signed-off-by: Marcos Paulo de Souza <marcos.souza.org@gmail.com>
> ---
>  drivers/input/misc/uinput.c | 3 ++-
>  1 file changed, 2 insertions(+), 1 deletion(-)
> 
> diff --git a/drivers/input/misc/uinput.c b/drivers/input/misc/uinput.c
> index 26ec603fe220..b7bdf332ef4c 100644
> --- a/drivers/input/misc/uinput.c
> +++ b/drivers/input/misc/uinput.c
> @@ -191,7 +191,8 @@ static int uinput_request_submit(struct uinput_device *udev,
>  	if (retval)
>  		goto out;
>  
> -	if (!wait_for_completion_timeout(&request->done, 30 * HZ)) {
> +	if (!wait_for_completion_interruptible_timeout(&request->done,
> +							30 * HZ)) {
>  		retval = -ETIMEDOUT;
>  		goto out;
>  	}
> -- 
> 2.16.4
> 

-- 
Dmitry

Re: [PATCH] Input: uinput - Allow uinput_request to be interrupted

[Rodrigo Rivas Costa]

On Sun, Feb 17, 2019 at 09:42:52PM -0300, Marcos Paulo de Souza wrote:
> -	if (!wait_for_completion_timeout(&request->done, 30 * HZ)) {
> +	if (!wait_for_completion_interruptible_timeout(&request->done,
> +							30 * HZ)) {
>  		retval = -ETIMEDOUT;
>  		goto out;
>  	}

Now this function can succeed or fail because of ETIMEDOUT or an
interrupt. I think you should return -EINTR or maybe -ESYSRESTART if
interrupted.

Re: [PATCH] Input: uinput - Allow uinput_request to be interrupted

[Rodrigo Rivas Costa]

On Sun, Feb 17, 2019 at 09:42:52PM -0300, Marcos Paulo de Souza wrote:
> -	if (!wait_for_completion_timeout(&request->done, 30 * HZ)) {
> +	if (!wait_for_completion_interruptible_timeout(&request->done,
> +							30 * HZ)) {
>  		retval = -ETIMEDOUT;
>  		goto out;
>  	}

Now this function can succeed or fail because of ETIMEDOUT or an
interrupt. I think you should return -EINTR or maybe -ESYSRESTART if
interrupted.

Re: [PATCH] Input: uinput - Allow uinput_request to be interrupted

[Dmitry Torokhov]

On Mon, Feb 18, 2019 at 03:21:10PM +0100, Rodrigo Rivas Costa wrote:
> On Sun, Feb 17, 2019 at 09:42:52PM -0300, Marcos Paulo de Souza wrote:
> > -	if (!wait_for_completion_timeout(&request->done, 30 * HZ)) {
> > +	if (!wait_for_completion_interruptible_timeout(&request->done,
> > +							30 * HZ)) {
> >  		retval = -ETIMEDOUT;
> >  		goto out;
> >  	}
> 
> Now this function can succeed or fail because of ETIMEDOUT or an
> interrupt. I think you should return -EINTR or maybe -ESYSRESTART if
> interrupted.

Rodrigo, you are right. Marcos, could you please send updated patch that
returns different error code for timeout vs interrupt condition?

I dropped the patch for now.

Thanks.

-- 
Dmitry

Re: [PATCH] Input: uinput - Allow uinput_request to be interrupted

[Dmitry Torokhov]

On Mon, Feb 18, 2019 at 03:21:10PM +0100, Rodrigo Rivas Costa wrote:
> On Sun, Feb 17, 2019 at 09:42:52PM -0300, Marcos Paulo de Souza wrote:
> > -	if (!wait_for_completion_timeout(&request->done, 30 * HZ)) {
> > +	if (!wait_for_completion_interruptible_timeout(&request->done,
> > +							30 * HZ)) {
> >  		retval = -ETIMEDOUT;
> >  		goto out;
> >  	}
> 
> Now this function can succeed or fail because of ETIMEDOUT or an
> interrupt. I think you should return -EINTR or maybe -ESYSRESTART if
> interrupted.

Rodrigo, you are right. Marcos, could you please send updated patch that
returns different error code for timeout vs interrupt condition?

I dropped the patch for now.

Thanks.

-- 
Dmitry

Re: [PATCH] Input: uinput - Allow uinput_request to be interrupted

[Marcos Paulo de Souza]

Hi Dmitry,

On 2/18/19 5:15 PM, Dmitry Torokhov wrote:
> On Mon, Feb 18, 2019 at 03:21:10PM +0100, Rodrigo Rivas Costa wrote:
>> On Sun, Feb 17, 2019 at 09:42:52PM -0300, Marcos Paulo de Souza wrote:
>>> -	if (!wait_for_completion_timeout(&request->done, 30 * HZ)) {
>>> +	if (!wait_for_completion_interruptible_timeout(&request->done,
>>> +							30 * HZ)) {
>>>   		retval = -ETIMEDOUT;
>>>   		goto out;
>>>   	}
>> Now this function can succeed or fail because of ETIMEDOUT or an
>> interrupt. I think you should return -EINTR or maybe -ESYSRESTART if
>> interrupted.
> Rodrigo, you are right. Marcos, could you please send updated patch that
> returns different error code for timeout vs interrupt condition?

Sure. But now I found another issue: If we start fftest and press 
Ctrl-C, it works (as Rodrigo and we all tested), but if we press -1 
(Stopping effects), it gets stuck in the same old way. Now I'm running 
lockdep and trying to fix this missing case (lockdep added bellow).

This lockdep warning is shown before the fftest can even allow the user 
to choose between his available options or press -1.

>
> I dropped the patch for now.
>
> Thanks.
[   11.528465] WARNING: possible circular locking dependency detected 
[37/7926]
[   11.530419] 5.0.0-rc7+ #5 Not tainted
[   11.531368] ------------------------------------------------------
[   11.533295] fftest/200 is trying to acquire lock:
[   11.534713] 000000006528ddcb (&newdev->mutex){+.+.}, at: 
uinput_request_submit+0x10a/0x320 [uinput]
[ 11.536939]
[   11.536939] but task is already holding lock:
[   11.538338] 000000004113875e (&ff->mutex){+.+.}, at: 
input_ff_upload+0xa6/0x250
[ 11.540114]
[   11.540114] which lock already depends on the new lock.
[ 11.540114]
[ 11.541966]
[   11.541966] the existing dependency chain (in reverse order) is:
[ 11.543765]
[   11.543765] -> #3 (&ff->mutex){+.+.}:
[   11.544982] input_ff_flush+0x23/0x60
[   11.545933] input_flush_device+0x3b/0x60
[   11.546985]        evdev_flush+0x54/0x60
[   11.547974]        filp_close+0x25/0x70
[   11.548849]        __x64_sys_close+0x19/0x40
[   11.549838]        do_syscall_64+0x4b/0x180
[   11.550853]        entry_SYSCALL_64_after_hwframe+0x49/0xbe
[   11.552584]
[   11.552584] -> #2 (&dev->mutex#2){+.+.}:
[   11.554077]        input_register_handle+0x25/0xc0
[   11.555228]        kbd_connect+0x44/0x90
[   11.556141]        input_attach_handler+0x73/0xb0
[   11.557222]        input_register_device+0x438/0x4b0
[   11.558383]        acpi_button_add+0x179/0x470
[   11.559392]        acpi_device_probe+0x43/0x110
[   11.560432]        really_probe+0x1c4/0x2d0
[   11.561334]        driver_probe_device+0x4a/0xe0
[   11.562286]        __driver_attach+0xb0/0xc0
[   11.563165]        bus_for_each_dev+0x74/0xc0
[   11.564159]        bus_add_driver+0x194/0x210
[   11.565142]        driver_register+0x56/0xe0
[   11.566157]        do_one_initcall+0x58/0x2ae
[   11.567095]        kernel_init_freeable+0x1ca/0x256
[   11.568176]        kernel_init+0x5/0x100
[   11.569032]        ret_from_fork+0x3a/0x50
[   11.569898]
[   11.569898] -> #1 (input_mutex){+.+.}:
[   11.571027]        input_register_device+0x3e6/0x4b0
[   11.572116]        uinput_ioctl_handler.isra.9+0x557/0x980 [uinput]
[   11.573509]        do_vfs_ioctl+0xa0/0x6e0
[   11.574395]        ksys_ioctl+0x6b/0x80
[   11.575234]        __x64_sys_ioctl+0x11/0x20
[   11.576161]        do_syscall_64+0x4b/0x180
[   11.577085]        entry_SYSCALL_64_after_hwframe+0x49/0xbe
[   11.578281]
[   11.578281] -> #0 (&newdev->mutex){+.+.}:
[   11.579436]        __mutex_lock+0x7d/0x9a0
[   11.580381]        uinput_request_submit+0x10a/0x320 [uinput]
[   11.581590]        uinput_dev_upload_effect+0x76/0xb0 [uinput]
[   11.582893]        input_ff_upload+0x1c0/0x250
[   11.583853]        evdev_ioctl_handler+0x388/0xbd0
[   11.584926]        do_vfs_ioctl+0xa0/0x6e0
[   11.586208]        ksys_ioctl+0x6b/0x80
[   11.587292]        __x64_sys_ioctl+0x11/0x20
[   11.588254]        do_syscall_64+0x4b/0x180
[   11.589221]        entry_SYSCALL_64_after_hwframe+0x49/0xbe
[   11.590424]
[   11.590424] other info that might help us debug this:
[   11.590424]
[   11.592162] Chain exists of:
[   11.592162]   &newdev->mutex --> &dev->mutex#2 --> &ff->mutex
[   11.592162]
[   11.594156]  Possible unsafe locking scenario:
[   11.594156]
[   11.595456]        CPU0                    CPU1
[   11.596452]        ----                    ----
[   11.597377]   lock(&ff->mutex);
[   11.598004] lock(&dev->mutex#2);
[   11.599163] lock(&ff->mutex);
[   11.600282]   lock(&newdev->mutex);
[   11.600982]
[   11.600982]  *** DEADLOCK ***
[   11.600982]
[   11.602144] 2 locks held by fftest/200:
[   11.602915]  #0: 000000006ae3e58b (&evdev->mutex){+.+.}, at: 
evdev_ioctl_handler+0x48/0xbd0
[   11.604581]  #1: 000000004113875e (&ff->mutex){+.+.}, at: 
input_ff_upload+0xa6/0x250
[   11.606110]
[   11.606110] stack backtrace:
[   11.606982] CPU: 0 PID: 200 Comm: fftest Not tainted 5.0.0-rc7+ #5
[   11.608140] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), 
BIOS rel-1.11.0-0-g63451fc-prebuilt.qemu-project.org 04/01/2014
[   11.610344] Call Trace:
[   11.610827]  dump_stack+0x67/0x9b
[   11.611470]  print_circular_bug.isra.35+0x1ce/0x1db
[   11.612392]  __lock_acquire+0x15e4/0x1650
[   11.613188]  ? _raw_spin_unlock_irq+0x24/0x30
[   11.614045]  ? lock_acquire+0xa7/0x1b0
[   11.614793]  lock_acquire+0xa7/0x1b0
[   11.615489]  ? uinput_request_submit+0x10a/0x320 [uinput]
[   11.616526]  ? uinput_request_submit+0x10a/0x320 [uinput]
[   11.617562]  __mutex_lock+0x7d/0x9a0
[   11.618243]  ? uinput_request_submit+0x10a/0x320 [uinput]
[   11.619234]  ? vprintk_emit+0xec/0x260
[   11.620271]  ? printk+0x4d/0x69
[   11.621158]  ? uinput_request_submit+0x10a/0x320 [uinput]
[   11.622464]  uinput_request_submit+0x10a/0x320 [uinput]
[   11.623587]  uinput_dev_upload_effect+0x76/0xb0 [uinput]
[   11.624788]  ? find_held_lock+0x2d/0x90
[   11.625633]  input_ff_upload+0x1c0/0x250
[   11.626524]  evdev_ioctl_handler+0x388/0xbd0
[   11.627439]  do_vfs_ioctl+0xa0/0x6e0
[   11.628215]  ksys_ioctl+0x6b/0x80
[   11.628967]  __x64_sys_ioctl+0x11/0x20
[   11.629734]  do_syscall_64+0x4b/0x180
[   11.630483]  entry_SYSCALL_64_after_hwframe+0x49/0xbe
[   11.631508] RIP: 0033:0x7f2d99a76467
[   11.632220] Code: b3 66 90 48 8b 05 31 4a 2c 00 64 c7 00 26 00 00 00 
48 c7 c0 ff ff ff ff c3 66 2e 0f 1f 84 00 00 00 00 00 b8 10 00 00 00 0f 
05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d 01 4a 2c 00 f7 d8 64 89 01 48
[   11.635876] RSP: 002b:00007ffe1ab6fbd8 EFLAGS: 00000246 ORIG_RAX: 
0000000000000010
[   11.637355] RAX: ffffffffffffffda RBX: 00007ffe1ab6fc50 RCX: 
00007f2d99a76467
[   11.638766] RDX: 00007ffe1ab6fd10 RSI: 0000000040304580 RDI: 
0000000000000003
[   11.640177] RBP: 0000000000000003 R08: 00007f2d99d3d880 R09: 
00007f2d99f47500
[   11.641679] R10: 000055c75edf2140 R11: 0000000000000246 R12: 
000055c75edf1a80
[   11.643211] R13: 00007ffe1ab6feb0 R14: 0000000000000000 R15: 
0000000000000000

>

Re: [PATCH] Input: uinput - Allow uinput_request to be interrupted

[Marcos Paulo de Souza]

Hi Dmitry,

On 2/18/19 5:15 PM, Dmitry Torokhov wrote:
> On Mon, Feb 18, 2019 at 03:21:10PM +0100, Rodrigo Rivas Costa wrote:
>> On Sun, Feb 17, 2019 at 09:42:52PM -0300, Marcos Paulo de Souza wrote:
>>> -	if (!wait_for_completion_timeout(&request->done, 30 * HZ)) {
>>> +	if (!wait_for_completion_interruptible_timeout(&request->done,
>>> +							30 * HZ)) {
>>>   		retval = -ETIMEDOUT;
>>>   		goto out;
>>>   	}
>> Now this function can succeed or fail because of ETIMEDOUT or an
>> interrupt. I think you should return -EINTR or maybe -ESYSRESTART if
>> interrupted.
> Rodrigo, you are right. Marcos, could you please send updated patch that
> returns different error code for timeout vs interrupt condition?

Sure. But now I found another issue: If we start fftest and press 
Ctrl-C, it works (as Rodrigo and we all tested), but if we press -1 
(Stopping effects), it gets stuck in the same old way. Now I'm running 
lockdep and trying to fix this missing case (lockdep added bellow).

This lockdep warning is shown before the fftest can even allow the user 
to choose between his available options or press -1.

>
> I dropped the patch for now.
>
> Thanks.
[   11.528465] WARNING: possible circular locking dependency detected 
[37/7926]
[   11.530419] 5.0.0-rc7+ #5 Not tainted
[   11.531368] ------------------------------------------------------
[   11.533295] fftest/200 is trying to acquire lock:
[   11.534713] 000000006528ddcb (&newdev->mutex){+.+.}, at: 
uinput_request_submit+0x10a/0x320 [uinput]
[ 11.536939]
[   11.536939] but task is already holding lock:
[   11.538338] 000000004113875e (&ff->mutex){+.+.}, at: 
input_ff_upload+0xa6/0x250
[ 11.540114]
[   11.540114] which lock already depends on the new lock.
[ 11.540114]
[ 11.541966]
[   11.541966] the existing dependency chain (in reverse order) is:
[ 11.543765]
[   11.543765] -> #3 (&ff->mutex){+.+.}:
[   11.544982] input_ff_flush+0x23/0x60
[   11.545933] input_flush_device+0x3b/0x60
[   11.546985]        evdev_flush+0x54/0x60
[   11.547974]        filp_close+0x25/0x70
[   11.548849]        __x64_sys_close+0x19/0x40
[   11.549838]        do_syscall_64+0x4b/0x180
[   11.550853]        entry_SYSCALL_64_after_hwframe+0x49/0xbe
[   11.552584]
[   11.552584] -> #2 (&dev->mutex#2){+.+.}:
[   11.554077]        input_register_handle+0x25/0xc0
[   11.555228]        kbd_connect+0x44/0x90
[   11.556141]        input_attach_handler+0x73/0xb0
[   11.557222]        input_register_device+0x438/0x4b0
[   11.558383]        acpi_button_add+0x179/0x470
[   11.559392]        acpi_device_probe+0x43/0x110
[   11.560432]        really_probe+0x1c4/0x2d0
[   11.561334]        driver_probe_device+0x4a/0xe0
[   11.562286]        __driver_attach+0xb0/0xc0
[   11.563165]        bus_for_each_dev+0x74/0xc0
[   11.564159]        bus_add_driver+0x194/0x210
[   11.565142]        driver_register+0x56/0xe0
[   11.566157]        do_one_initcall+0x58/0x2ae
[   11.567095]        kernel_init_freeable+0x1ca/0x256
[   11.568176]        kernel_init+0x5/0x100
[   11.569032]        ret_from_fork+0x3a/0x50
[   11.569898]
[   11.569898] -> #1 (input_mutex){+.+.}:
[   11.571027]        input_register_device+0x3e6/0x4b0
[   11.572116]        uinput_ioctl_handler.isra.9+0x557/0x980 [uinput]
[   11.573509]        do_vfs_ioctl+0xa0/0x6e0
[   11.574395]        ksys_ioctl+0x6b/0x80
[   11.575234]        __x64_sys_ioctl+0x11/0x20
[   11.576161]        do_syscall_64+0x4b/0x180
[   11.577085]        entry_SYSCALL_64_after_hwframe+0x49/0xbe
[   11.578281]
[   11.578281] -> #0 (&newdev->mutex){+.+.}:
[   11.579436]        __mutex_lock+0x7d/0x9a0
[   11.580381]        uinput_request_submit+0x10a/0x320 [uinput]
[   11.581590]        uinput_dev_upload_effect+0x76/0xb0 [uinput]
[   11.582893]        input_ff_upload+0x1c0/0x250
[   11.583853]        evdev_ioctl_handler+0x388/0xbd0
[   11.584926]        do_vfs_ioctl+0xa0/0x6e0
[   11.586208]        ksys_ioctl+0x6b/0x80
[   11.587292]        __x64_sys_ioctl+0x11/0x20
[   11.588254]        do_syscall_64+0x4b/0x180
[   11.589221]        entry_SYSCALL_64_after_hwframe+0x49/0xbe
[   11.590424]
[   11.590424] other info that might help us debug this:
[   11.590424]
[   11.592162] Chain exists of:
[   11.592162]   &newdev->mutex --> &dev->mutex#2 --> &ff->mutex
[   11.592162]
[   11.594156]  Possible unsafe locking scenario:
[   11.594156]
[   11.595456]        CPU0                    CPU1
[   11.596452]        ----                    ----
[   11.597377]   lock(&ff->mutex);
[   11.598004] lock(&dev->mutex#2);
[   11.599163] lock(&ff->mutex);
[   11.600282]   lock(&newdev->mutex);
[   11.600982]
[   11.600982]  *** DEADLOCK ***
[   11.600982]
[   11.602144] 2 locks held by fftest/200:
[   11.602915]  #0: 000000006ae3e58b (&evdev->mutex){+.+.}, at: 
evdev_ioctl_handler+0x48/0xbd0
[   11.604581]  #1: 000000004113875e (&ff->mutex){+.+.}, at: 
input_ff_upload+0xa6/0x250
[   11.606110]
[   11.606110] stack backtrace:
[   11.606982] CPU: 0 PID: 200 Comm: fftest Not tainted 5.0.0-rc7+ #5
[   11.608140] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), 
BIOS rel-1.11.0-0-g63451fc-prebuilt.qemu-project.org 04/01/2014
[   11.610344] Call Trace:
[   11.610827]  dump_stack+0x67/0x9b
[   11.611470]  print_circular_bug.isra.35+0x1ce/0x1db
[   11.612392]  __lock_acquire+0x15e4/0x1650
[   11.613188]  ? _raw_spin_unlock_irq+0x24/0x30
[   11.614045]  ? lock_acquire+0xa7/0x1b0
[   11.614793]  lock_acquire+0xa7/0x1b0
[   11.615489]  ? uinput_request_submit+0x10a/0x320 [uinput]
[   11.616526]  ? uinput_request_submit+0x10a/0x320 [uinput]
[   11.617562]  __mutex_lock+0x7d/0x9a0
[   11.618243]  ? uinput_request_submit+0x10a/0x320 [uinput]
[   11.619234]  ? vprintk_emit+0xec/0x260
[   11.620271]  ? printk+0x4d/0x69
[   11.621158]  ? uinput_request_submit+0x10a/0x320 [uinput]
[   11.622464]  uinput_request_submit+0x10a/0x320 [uinput]
[   11.623587]  uinput_dev_upload_effect+0x76/0xb0 [uinput]
[   11.624788]  ? find_held_lock+0x2d/0x90
[   11.625633]  input_ff_upload+0x1c0/0x250
[   11.626524]  evdev_ioctl_handler+0x388/0xbd0
[   11.627439]  do_vfs_ioctl+0xa0/0x6e0
[   11.628215]  ksys_ioctl+0x6b/0x80
[   11.628967]  __x64_sys_ioctl+0x11/0x20
[   11.629734]  do_syscall_64+0x4b/0x180
[   11.630483]  entry_SYSCALL_64_after_hwframe+0x49/0xbe
[   11.631508] RIP: 0033:0x7f2d99a76467
[   11.632220] Code: b3 66 90 48 8b 05 31 4a 2c 00 64 c7 00 26 00 00 00 
48 c7 c0 ff ff ff ff c3 66 2e 0f 1f 84 00 00 00 00 00 b8 10 00 00 00 0f 
05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d 01 4a 2c 00 f7 d8 64 89 01 48
[   11.635876] RSP: 002b:00007ffe1ab6fbd8 EFLAGS: 00000246 ORIG_RAX: 
0000000000000010
[   11.637355] RAX: ffffffffffffffda RBX: 00007ffe1ab6fc50 RCX: 
00007f2d99a76467
[   11.638766] RDX: 00007ffe1ab6fd10 RSI: 0000000040304580 RDI: 
0000000000000003
[   11.640177] RBP: 0000000000000003 R08: 00007f2d99d3d880 R09: 
00007f2d99f47500
[   11.641679] R10: 000055c75edf2140 R11: 0000000000000246 R12: 
000055c75edf1a80
[   11.643211] R13: 00007ffe1ab6feb0 R14: 0000000000000000 R15: 
0000000000000000

>