diff mbox

net/bluetooth: workqueue destruction WARNING in hci_unregister_dev

Message ID 56F0FDCE.1040701@suse.cz
State RFC, archived
Delegated to: David Miller
Headers show

Commit Message

Jiri Slaby March 22, 2016, 8:09 a.m. UTC 
On 03/21/2016, 04:58 PM, Jiri Slaby wrote:
> Hello,
> 
> On 03/18/2016, 09:52 PM, Tejun Heo wrote:
>> On Thu, Mar 17, 2016 at 01:00:13PM +0100, Jiri Slaby wrote:
>>>>> I have not done that yet, but today, I see:
>>>>> destroy_workqueue: name='req_hci0' pwq=ffff88002f590300
>>>>> wq->dfl_pwq=ffff88002f591e00 pwq->refcnt=2 pwq->nr_active=0 delayed_works:
>>>>>    pwq 12: cpus=0-1 node=0 flags=0x4 nice=-20 active=0/1
>>>>>      in-flight: 18568:wq_barrier_func
>>>>
>>>> So, this means that there's flush_work() racing against workqueue
>>>> destruction, which can't be safe. :(
>>>
>>> But I cannot trigger the WARN_ONs in the attached patch, so I am
>>> confused how this can happen :(. (While I am still seeing the destroy
>>> WARNINGs.)
>>
>> So, no operations should be in progress when destroy_workqueue() is
>> called.  If somebody was flushing a work item, the flush call must
>> have returned before destroy_workqueue() was invoked, which doesn't
>> seem to be the case here.  Can you trigger BUG_ON() or sysrq-t when
>> the above triggers?  There must be a task which is flushing a work
>> item there and it shouldn't be difficult to pinpoint what's going on
>> from it.
> 
> The output of sysrq-t is here (> 200k), but I cannot see anything
> suspicious in it:
> http://www.fi.muni.cz/~xslaby/sklad/panics/jctl.txt

Hmm, so I seem I cannot reproduce with this hunk:



I cannot explain why though. I do not see how it matters in this
particular case...

Dmitry, could you apply it too? But I don't know how often you see the
warning.

PS. next on the table is the gsm tty warning.

thanks,

Comments

Dmitry Vyukov March 22, 2016, 12:32 p.m. UTC | #1 
On Tue, Mar 22, 2016 at 9:09 AM, Jiri Slaby <jslaby@suse.cz> wrote:
> On 03/21/2016, 04:58 PM, Jiri Slaby wrote:
>> Hello,
>>
>> On 03/18/2016, 09:52 PM, Tejun Heo wrote:
>>> On Thu, Mar 17, 2016 at 01:00:13PM +0100, Jiri Slaby wrote:
>>>>>> I have not done that yet, but today, I see:
>>>>>> destroy_workqueue: name='req_hci0' pwq=ffff88002f590300
>>>>>> wq->dfl_pwq=ffff88002f591e00 pwq->refcnt=2 pwq->nr_active=0 delayed_works:
>>>>>>    pwq 12: cpus=0-1 node=0 flags=0x4 nice=-20 active=0/1
>>>>>>      in-flight: 18568:wq_barrier_func
>>>>>
>>>>> So, this means that there's flush_work() racing against workqueue
>>>>> destruction, which can't be safe. :(
>>>>
>>>> But I cannot trigger the WARN_ONs in the attached patch, so I am
>>>> confused how this can happen :(. (While I am still seeing the destroy
>>>> WARNINGs.)
>>>
>>> So, no operations should be in progress when destroy_workqueue() is
>>> called.  If somebody was flushing a work item, the flush call must
>>> have returned before destroy_workqueue() was invoked, which doesn't
>>> seem to be the case here.  Can you trigger BUG_ON() or sysrq-t when
>>> the above triggers?  There must be a task which is flushing a work
>>> item there and it shouldn't be difficult to pinpoint what's going on
>>> from it.
>>
>> The output of sysrq-t is here (> 200k), but I cannot see anything
>> suspicious in it:
>> http://www.fi.muni.cz/~xslaby/sklad/panics/jctl.txt
>
> Hmm, so I seem I cannot reproduce with this hunk:
> --- a/net/bluetooth/hci_core.c
> +++ b/net/bluetooth/hci_core.c
> @@ -3139,10 +3139,10 @@ void hci_unregister_dev(struct hci_dev *hdev)
>         list_del(&hdev->list);
>         write_unlock(&hci_dev_list_lock);
>
> -       hci_dev_do_close(hdev);
> -
>         cancel_work_sync(&hdev->power_on);
>
> +       hci_dev_do_close(hdev);
> +
>         if (!test_bit(HCI_INIT, &hdev->flags) &&
>             !hci_dev_test_flag(hdev, HCI_SETUP) &&
>             !hci_dev_test_flag(hdev, HCI_CONFIG)) {
>
>
>
> I cannot explain why though. I do not see how it matters in this
> particular case...
>
> Dmitry, could you apply it too? But I don't know how often you see the
> warning.

I've seen it only several times in several months, so I don't it will
be helpful.
Dmitry Vyukov Sept. 3, 2016, 10:58 a.m. UTC | #2 
On Tue, Mar 22, 2016 at 1:32 PM, Dmitry Vyukov <dvyukov@google.com> wrote:
> On Tue, Mar 22, 2016 at 9:09 AM, Jiri Slaby <jslaby@suse.cz> wrote:
>> On 03/21/2016, 04:58 PM, Jiri Slaby wrote:
>>> Hello,
>>>
>>> On 03/18/2016, 09:52 PM, Tejun Heo wrote:
>>>> On Thu, Mar 17, 2016 at 01:00:13PM +0100, Jiri Slaby wrote:
>>>>>>> I have not done that yet, but today, I see:
>>>>>>> destroy_workqueue: name='req_hci0' pwq=ffff88002f590300
>>>>>>> wq->dfl_pwq=ffff88002f591e00 pwq->refcnt=2 pwq->nr_active=0 delayed_works:
>>>>>>>    pwq 12: cpus=0-1 node=0 flags=0x4 nice=-20 active=0/1
>>>>>>>      in-flight: 18568:wq_barrier_func
>>>>>>
>>>>>> So, this means that there's flush_work() racing against workqueue
>>>>>> destruction, which can't be safe. :(
>>>>>
>>>>> But I cannot trigger the WARN_ONs in the attached patch, so I am
>>>>> confused how this can happen :(. (While I am still seeing the destroy
>>>>> WARNINGs.)
>>>>
>>>> So, no operations should be in progress when destroy_workqueue() is
>>>> called.  If somebody was flushing a work item, the flush call must
>>>> have returned before destroy_workqueue() was invoked, which doesn't
>>>> seem to be the case here.  Can you trigger BUG_ON() or sysrq-t when
>>>> the above triggers?  There must be a task which is flushing a work
>>>> item there and it shouldn't be difficult to pinpoint what's going on
>>>> from it.
>>>
>>> The output of sysrq-t is here (> 200k), but I cannot see anything
>>> suspicious in it:
>>> http://www.fi.muni.cz/~xslaby/sklad/panics/jctl.txt
>>
>> Hmm, so I seem I cannot reproduce with this hunk:
>> --- a/net/bluetooth/hci_core.c
>> +++ b/net/bluetooth/hci_core.c
>> @@ -3139,10 +3139,10 @@ void hci_unregister_dev(struct hci_dev *hdev)
>>         list_del(&hdev->list);
>>         write_unlock(&hci_dev_list_lock);
>>
>> -       hci_dev_do_close(hdev);
>> -
>>         cancel_work_sync(&hdev->power_on);
>>
>> +       hci_dev_do_close(hdev);
>> +
>>         if (!test_bit(HCI_INIT, &hdev->flags) &&
>>             !hci_dev_test_flag(hdev, HCI_SETUP) &&
>>             !hci_dev_test_flag(hdev, HCI_CONFIG)) {
>>
>>
>>
>> I cannot explain why though. I do not see how it matters in this
>> particular case...
>>
>> Dmitry, could you apply it too? But I don't know how often you see the
>> warning.
>
> I've seen it only several times in several months, so I don't it will
> be helpful.


Bad news: I hit it again.
On 0f98f121e1670eaa2a2fbb675e07d6ba7f0e146f of linux-next, so I have
bf389cabb3b8079c23f9762e62b05f291e2d5e99.

WARNING: CPU: 3 PID: 23168 at kernel/workqueue.c:4029
destroy_workqueue+0x172/0x620
CPU: 3 PID: 23168 Comm: syz-executor Not tainted 4.8.0-rc3-next-20160825+ #8
Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS Bochs 01/01/2011
 ffffffff886b6fe0 ffff880037be77a8 ffffffff82db38d9 ffffffff00000016
 fffffbfff10d6dfc ffffffff8708f000 ffff880037be7880 ffffffff8709be00
 dffffc0000000000 0000000000000009 ffff880037be7870 ffffffff816cf888
Call Trace:
 [<     inline     >] __dump_stack lib/dump_stack.c:15
 [<ffffffff82db38d9>] dump_stack+0x12e/0x185 lib/dump_stack.c:51
 [<ffffffff816cf888>] panic+0x1e4/0x3fb kernel/panic.c:179
 [<ffffffff813863b4>] __warn+0x1c4/0x1e0 kernel/panic.c:542
 [<ffffffff8138659c>] warn_slowpath_null+0x2c/0x40 kernel/panic.c:585
 [<ffffffff813dc6d2>] destroy_workqueue+0x172/0x620 kernel/workqueue.c:4029
 [<ffffffff8645973f>] hci_unregister_dev+0x3df/0x8a0
net/bluetooth/hci_core.c:3170
 [<ffffffff84cb6926>] vhci_release+0x76/0xf0 drivers/bluetooth/hci_vhci.c:354
 [<ffffffff81868bbc>] __fput+0x28c/0x780 fs/file_table.c:208
 [<ffffffff81869135>] ____fput+0x15/0x20 fs/file_table.c:244
 [<ffffffff813ebf63>] task_work_run+0xf3/0x170
 [<     inline     >] exit_task_work include/linux/task_work.h:21
 [<ffffffff81394218>] do_exit+0x868/0x2e70 kernel/exit.c:828
 [<ffffffff81396998>] do_group_exit+0x108/0x330 kernel/exit.c:958
 [<ffffffff813ba4aa>] get_signal+0x62a/0x15d0 kernel/signal.c:2307
 [<ffffffff81202333>] do_signal+0x83/0x1f60 arch/x86/kernel/signal.c:805
 [<ffffffff81006345>] exit_to_usermode_loop+0x1a5/0x210
arch/x86/entry/common.c:163
 [<     inline     >] prepare_exit_to_usermode arch/x86/entry/common.c:198
 [<ffffffff8100869f>] syscall_return_slowpath+0x2bf/0x340
arch/x86/entry/common.c:267
 [<ffffffff86e1079c>] entry_SYSCALL_64_fastpath+0xbf/0xc1
diff mbox

Patch

--- a/net/bluetooth/hci_core.c
+++ b/net/bluetooth/hci_core.c
@@ -3139,10 +3139,10 @@  void hci_unregister_dev(struct hci_dev *hdev)
        list_del(&hdev->list);
        write_unlock(&hci_dev_list_lock);

-       hci_dev_do_close(hdev);
-
        cancel_work_sync(&hdev->power_on);

+       hci_dev_do_close(hdev);
+
        if (!test_bit(HCI_INIT, &hdev->flags) &&
            !hci_dev_test_flag(hdev, HCI_SETUP) &&
            !hci_dev_test_flag(hdev, HCI_CONFIG)) {