Re: GPF in run_workqueue()/list_del_init(cwq->worklist.next) on resume (was: Re: Help needed: Resume problems in 2.6.32-rc, perhaps related to preempt_count leakage in keventd)

Re: GPF in run_workqueue()/list_del_init(cwq->worklist.next) on resume (was: Re: Help needed: Resume problems in 2.6.32-rc, perhaps related to preempt_count leakage in keventd)

[Linus Torvalds]

On Wed, 11 Nov 2009, Rafael J. Wysocki wrote:
> 
> I thought that the problem was somehow related to user space, because it only
> happens after we've thawed tasks.  At least, all of the call traces I was able
> to collect indicated so.
> 
> Moreover, in a few cases I got
> 
> kernel: PM: Finishing wakeup.
> kernel: Restarting tasks ...
> kernel: usb 5-2: USB disconnect, address 2
> kernel: done.
> bluetoothd[3445]: HCI dev 0 unregistered
> bluetoothd[3445]: Unregister path: /org/bluez/3445/hci0
> bluetoothd[3445]: Unregistered interface org.bluez.NetworkPeer on path /org/bluez/3445/hci0
> bluetoothd[3445]: Unregistered interface org.bluez.NetworkHub on path /org/bluez/3445/hci0
> bluetoothd[3445]: Unregistered interface org.bluez.NetworkRouter on path /org/bluez/3445/hci0
> kernel: Slab corruption: size-512 start=ffff88007f1182b0, len=512
> 
> and so on (of course, the bluetoothd PID was different each time), so I thought
> that the problem might be related to Bluetooth.

Hmm. Sounds reasonable. It's still that 'size-512', but if the sound 
subsystem and the bluetooth code both happen to use that size, that would 
explain why there was sound data in the slab.

> So, I've disabled the Bluetooth subsystem in the kernel config and I'm not able
> to reproduce the problem any more (at least not within 50 consecutive
> suspend-resume and hibernate-resume cycles).  Thus Bluetooth seems to be
> at least necessary to reproduce the issue and perhaps it's also the cause of
> it.

Which BT driver are you using? Maybe it's specific to the low-level 
driver?

For example, I could imagine that (say) a USB bluetooth dongle (I think 
they are common for for mice, and are sometimes built-in on the 
motherboard) could get the USB "disconnect" event, and get freed while 
some work from the resume is still pending.

I'm looking at btusb_disconnect(), for example. It's one of the few BT 
drivers that seem to use workqueues, and I'm not seeing a 
cancel_work_sync() in the disconnect routine - but maybe the btusb_close() 
routine is called indirectly some way that I just don't see.

Marcel?

			Linus

Re: GPF in run_workqueue()/list_del_init(cwq->worklist.next) on resume (was: Re: Help needed: Resume problems in 2.6.32-rc, perhaps related to preempt_count leakage in keventd)

[Marcel Holtmann]

Hi Linus,

> > I thought that the problem was somehow related to user space, because it only
> > happens after we've thawed tasks.  At least, all of the call traces I was able
> > to collect indicated so.
> > 
> > Moreover, in a few cases I got
> > 
> > kernel: PM: Finishing wakeup.
> > kernel: Restarting tasks ...
> > kernel: usb 5-2: USB disconnect, address 2
> > kernel: done.
> > bluetoothd[3445]: HCI dev 0 unregistered
> > bluetoothd[3445]: Unregister path: /org/bluez/3445/hci0
> > bluetoothd[3445]: Unregistered interface org.bluez.NetworkPeer on path /org/bluez/3445/hci0
> > bluetoothd[3445]: Unregistered interface org.bluez.NetworkHub on path /org/bluez/3445/hci0
> > bluetoothd[3445]: Unregistered interface org.bluez.NetworkRouter on path /org/bluez/3445/hci0
> > kernel: Slab corruption: size-512 start=ffff88007f1182b0, len=512
> > 
> > and so on (of course, the bluetoothd PID was different each time), so I thought
> > that the problem might be related to Bluetooth.
> 
> Hmm. Sounds reasonable. It's still that 'size-512', but if the sound 
> subsystem and the bluetooth code both happen to use that size, that would 
> explain why there was sound data in the slab.
> 
> > So, I've disabled the Bluetooth subsystem in the kernel config and I'm not able
> > to reproduce the problem any more (at least not within 50 consecutive
> > suspend-resume and hibernate-resume cycles).  Thus Bluetooth seems to be
> > at least necessary to reproduce the issue and perhaps it's also the cause of
> > it.
> 
> Which BT driver are you using? Maybe it's specific to the low-level 
> driver?
> 
> For example, I could imagine that (say) a USB bluetooth dongle (I think 
> they are common for for mice, and are sometimes built-in on the 
> motherboard) could get the USB "disconnect" event, and get freed while 
> some work from the resume is still pending.
> 
> I'm looking at btusb_disconnect(), for example. It's one of the few BT 
> drivers that seem to use workqueues, and I'm not seeing a 
> cancel_work_sync() in the disconnect routine - but maybe the btusb_close() 
> routine is called indirectly some way that I just don't see.

so the btusb_close() should be called before btusb_destruct() and the
destruct() callback is only when the last reference count gets dropped
and we do have to free the memory. So it seems we are doing something
wrong in btusb_close(). The close() callback is triggered via
hci_unregister_dev() from btusb_disconnect().

As it seems the btusb_close() only cancels the work workqueue and not
the waker workqueue. Could that be the problem.

Oliver, what do you think?

Regards

Marcel

Re: GPF in run_workqueue()/list_del_init(cwq->worklist.next) on resume (was: Re: Help needed: Resume problems in 2.6.32-rc, perhaps related to preempt_count leakage in keventd)

[Linus Torvalds]

On Wed, 11 Nov 2009, Marcel Holtmann wrote:
> 
> As it seems the btusb_close() only cancels the work workqueue and not
> the waker workqueue. Could that be the problem.

It's the waker workqueue that Rafael apparently sees with the debug patch 
from Oleg, so yeah, that sounds possible.

Rafael, since apparently htusb_close() _is_ called, does the following 
simpler patch fix it for you? I bet your patch does it too.

		Linus

---
 drivers/bluetooth/btusb.c |    1 +
 1 files changed, 1 insertions(+), 0 deletions(-)

diff --git a/drivers/bluetooth/btusb.c b/drivers/bluetooth/btusb.c
index 7ba91aa..2fb3802 100644
--- a/drivers/bluetooth/btusb.c
+++ b/drivers/bluetooth/btusb.c
@@ -591,6 +591,7 @@ static int btusb_close(struct hci_dev *hdev)
 		return 0;
 
 	cancel_work_sync(&data->work);
+	cancel_work_sync(&data->waker);
 
 	clear_bit(BTUSB_ISOC_RUNNING, &data->flags);
 	clear_bit(BTUSB_BULK_RUNNING, &data->flags);

Re: GPF in run_workqueue()/list_del_init(cwq->worklist.next) on resume (was: Re: Help needed: Resume problems in 2.6.32-rc, perhaps related to preempt_count leakage in keventd)

[Rafael J. Wysocki]

On Wednesday 11 November 2009, Linus Torvalds wrote:
> 
> On Wed, 11 Nov 2009, Marcel Holtmann wrote:
> > 
> > As it seems the btusb_close() only cancels the work workqueue and not
> > the waker workqueue. Could that be the problem.
> 
> It's the waker workqueue that Rafael apparently sees with the debug patch 
> from Oleg, so yeah, that sounds possible.
> 
> Rafael, since apparently htusb_close() _is_ called, does the following 
> simpler patch fix it for you? I bet your patch does it too.

Yes and yes.

And in fact this is a post-2.6.31 regression introduced by commit
7bee549e197c9c0e92b89857a409675c1d5e9dff (Bluetooth: Add USB autosuspend
support to btusb driver).

Thanks,
Rafael

Re: GPF in run_workqueue()/list_del_init(cwq->worklist.next) on resume (was: Re: Help needed: Resume problems in 2.6.32-rc, perhaps related to preempt_count leakage in keventd)

[Oliver Neukum]

Am Mittwoch, 11. November 2009 21:18:39 schrieb Marcel Holtmann:
> > I'm looking at btusb_disconnect(), for example. It's one of the few BT 
> > drivers that seem to use workqueues, and I'm not seeing a 
> > cancel_work_sync() in the disconnect routine - but maybe the
> > btusb_close()  routine is called indirectly some way that I just don't
> > see.
> 
> so the btusb_close() should be called before btusb_destruct() and the
> destruct() callback is only when the last reference count gets dropped
> and we do have to free the memory. So it seems we are doing something
> wrong in btusb_close(). The close() callback is triggered via
> hci_unregister_dev() from btusb_disconnect().
> 
> As it seems the btusb_close() only cancels the work workqueue and not
> the waker workqueue. Could that be the problem.

Yes, btusb_close() needs to cancel the waker workqueue, too.
In addition, in order to avoid a memory leak it must call
usb_scuttle_anchored_urbs(&data->deferred)
to make sure any deferred data is destroyed.

	Regards
		Oliver

Re: GPF in run_workqueue()/list_del_init(cwq->worklist.next) on resume (was: Re: Help needed: Resume problems in 2.6.32-rc, perhaps related to preempt_count leakage in keventd)

[Linus Torvalds]

On Wed, 11 Nov 2009, Oliver Neukum wrote:
> 
> Yes, btusb_close() needs to cancel the waker workqueue, too.
> In addition, in order to avoid a memory leak it must call
> usb_scuttle_anchored_urbs(&data->deferred)
> to make sure any deferred data is destroyed.

Ok. I committed the one-liner patch to fix the oops (confirmed by Rafael), 
but I'm leaving the memory leak for you as I'm not going to commit some 
untested patch at this stage.

Thanks to everybody involved, I was personally very nervous that this was 
something much more fundamental (we've had some scary bugs during the 
32-rc series), and am relieved that it was "just" a silly driver bug.

			Linus

Re: GPF in run_workqueue()/list_del_init(cwq->worklist.next) on resume (was: Re: Help needed: Resume problems in 2.6.32-rc, perhaps related to preempt_count leakage in keventd)

[Oliver Neukum]

Am Mittwoch, 11. November 2009 22:38:08 schrieb Linus Torvalds:
> On Wed, 11 Nov 2009, Oliver Neukum wrote:
> > Yes, btusb_close() needs to cancel the waker workqueue, too.
> > In addition, in order to avoid a memory leak it must call
> > usb_scuttle_anchored_urbs(&data->deferred)
> > to make sure any deferred data is destroyed.
> 
> Ok. I committed the one-liner patch to fix the oops (confirmed by Rafael),
> but I'm leaving the memory leak for you as I'm not going to commit some
> untested patch at this stage.
> 
> Thanks to everybody involved, I was personally very nervous that this was
> something much more fundamental (we've had some scary bugs during the
> 32-rc series), and am relieved that it was "just" a silly driver bug.

Thanks. A patch is in the works.

	Regards
		Oliver

Re: GPF in run_workqueue()/list_del_init(cwq->worklist.next) on resume (was: Re: Help needed: Resume problems in 2.6.32-rc, perhaps related to preempt_count leakage in keventd)

[Rafael J. Wysocki]

On Wednesday 11 November 2009, Oleg Nesterov wrote:
> On 11/10, Linus Torvalds wrote:
> >
> > > In the meantime I got another trace, this time with a slab corruption involved.
> > > Note that it crashed in exactly the same place as previously.
> >
> > I'm leaving your crash log appended for the new cc's, and I would not be
> > at all surprised to hear that the slab corruption is related. The whole
> > 6b6b6b6b pattern does imply a use-after-free on the workqueue,
> 
> Yes, RCX = 6b6b6b6b6b6b6b6b, and according to decodecode the faulting
> instruction is "mov %rdx,0x8(%rcx)". Looks like the pending work was
> freed.
> 
> Rafael, could you reproduce the problem with the debugging patch below?
> It tries to detect the case when the pending work was corrupted and
> prints its work->func (saved in the previous item). It should work
> if the work_struct was freed and poisoned, or if it was re-initialized.
> See ck_work().

I applied the patch and this is the result of 'dmesg | grep ERR' after 10-or-so
consecutive suspend-resume and hibernate-resume cycles:

[  129.008689] ERR!! btusb_waker+0x0/0x27 [btusb]
[  166.477373] ERR!! btusb_waker+0x0/0x27 [btusb]
[  203.983665] ERR!! btusb_waker+0x0/0x27 [btusb]
[  241.636547] ERR!! btusb_waker+0x0/0x27 [btusb]

which kind of confirms my previous observation that the problem was not
reproducible without Bluetooth.

So, it looks like the bug is in btusb_destruct(), which should call
cancel_work_sync() on data->waker before freeing 'data'.  I guess it should
do the same for data->work.

I'm going to test the appended patch, then.

Thanks,
Rafael

---
 drivers/bluetooth/btusb.c |    3 +++
 1 file changed, 3 insertions(+)

Index: linux-2.6/drivers/bluetooth/btusb.c
===================================================================
--- linux-2.6.orig/drivers/bluetooth/btusb.c
+++ linux-2.6/drivers/bluetooth/btusb.c
@@ -738,6 +738,9 @@ static void btusb_destruct(struct hci_de
 
 	BT_DBG("%s", hdev->name);
 
+	cancel_work_sync(&data->work);
+	cancel_work_sync(&data->waker);
+
 	kfree(data);
 }
 

Re: GPF in run_workqueue()/list_del_init(cwq->worklist.next) on resume (was: Re: Help needed: Resume problems in 2.6.32-rc, perhaps related to preempt_count leakage in keventd)

[Linus Torvalds]

On Wed, 11 Nov 2009, Rafael J. Wysocki wrote:
> 
> I applied the patch and this is the result of 'dmesg | grep ERR' after 10-or-so
> consecutive suspend-resume and hibernate-resume cycles:
> 
> [  129.008689] ERR!! btusb_waker+0x0/0x27 [btusb]
> [  166.477373] ERR!! btusb_waker+0x0/0x27 [btusb]
> [  203.983665] ERR!! btusb_waker+0x0/0x27 [btusb]
> [  241.636547] ERR!! btusb_waker+0x0/0x27 [btusb]
> 
> which kind of confirms my previous observation that the problem was not
> reproducible without Bluetooth.

.. and that btusb thing matches my observation that only a few BT drivers 
seem to use workqueues, and btusb_disconnect() isn't doing any work 
cancel.

> I'm going to test the appended patch, then.

Hmm. the USB disconnect doesn't call hci_dev_put(), it calls 
hci_free_dev() and doesn't seem to call the ->destruct thing. 

Although again, maybe that gets called indirectly.

So I'd put the cancel work in the actual disconnect routine. But maybe 
thar's just me.

		Linus

Re: GPF in run_workqueue()/list_del_init(cwq->worklist.next) on resume (was: Re: Help needed: Resume problems in 2.6.32-rc, perhaps related to preempt_count leakage in keventd)

[Marcel Holtmann]

Hi Linus,

> > I applied the patch and this is the result of 'dmesg | grep ERR' after 10-or-so
> > consecutive suspend-resume and hibernate-resume cycles:
> > 
> > [  129.008689] ERR!! btusb_waker+0x0/0x27 [btusb]
> > [  166.477373] ERR!! btusb_waker+0x0/0x27 [btusb]
> > [  203.983665] ERR!! btusb_waker+0x0/0x27 [btusb]
> > [  241.636547] ERR!! btusb_waker+0x0/0x27 [btusb]
> > 
> > which kind of confirms my previous observation that the problem was not
> > reproducible without Bluetooth.
> 
> .. and that btusb thing matches my observation that only a few BT drivers 
> seem to use workqueues, and btusb_disconnect() isn't doing any work 
> cancel.
> 
> > I'm going to test the appended patch, then.
> 
> Hmm. the USB disconnect doesn't call hci_dev_put(), it calls 
> hci_free_dev() and doesn't seem to call the ->destruct thing. 
> 
> Although again, maybe that gets called indirectly.
> 
> So I'd put the cancel work in the actual disconnect routine. But maybe 
> thar's just me.

see my other email, I think we have to cancel the waker in btusb_close()
to fix this. However the suspend/resume and auto-suspend has been done
mostly by Oliver and I like to see what he thinks about this.

Regards

Marcel

Re: GPF in run_workqueue()/list_del_init(cwq->worklist.next) on resume (was: Re: Help needed: Resume problems in 2.6.32-rc, perhaps related to preempt_count leakage in keventd)

[Oleg Nesterov]

On 11/11, Rafael J. Wysocki wrote:
>
> On Wednesday 11 November 2009, Oleg Nesterov wrote:
> >
> > Rafael, could you reproduce the problem with the debugging patch below?
> > It tries to detect the case when the pending work was corrupted and
> > prints its work->func (saved in the previous item). It should work
> > if the work_struct was freed and poisoned, or if it was re-initialized.
> > See ck_work().
>
> I applied the patch and this is the result of 'dmesg | grep ERR' after 10-or-so
> consecutive suspend-resume and hibernate-resume cycles:
>
> [  129.008689] ERR!! btusb_waker+0x0/0x27 [btusb]
> [  166.477373] ERR!! btusb_waker+0x0/0x27 [btusb]
> [  203.983665] ERR!! btusb_waker+0x0/0x27 [btusb]
> [  241.636547] ERR!! btusb_waker+0x0/0x27 [btusb]
>
> which kind of confirms my previous observation that the problem was not
> reproducible without Bluetooth.

Great, thanks.

> So, it looks like the bug is in btusb_destruct(), which should call
> cancel_work_sync() on data->waker before freeing 'data'.  I guess it should
> do the same for data->work.

Or. btusb_suspend() and btusb_close() do cancel_work_sync(data->work),
perhaps they should cancel data->waker as well, I dunno.

I added Oliver to cc.

Oleg.

Re: GPF in run_workqueue()/list_del_init(cwq->worklist.next) on resume (was: Re: Help needed: Resume problems in 2.6.32-rc, perhaps related to preempt_count leakage in keventd)

[Oliver Neukum]

Am Mittwoch, 11. November 2009 21:24:33 schrieb Oleg Nesterov:
> > So, it looks like the bug is in btusb_destruct(), which should call
> > cancel_work_sync() on data->waker before freeing 'data'.  I guess it
> > should do the same for data->work.
> 
> Or. btusb_suspend() and btusb_close() do cancel_work_sync(data->work),
> perhaps they should cancel data->waker as well, I dunno.
> 
> I added Oliver to cc.

btusb_close() must do it. btusb_suspend() must not do it.

	Regards
		Oliver