2.5.8-pre3: kernel BUG at usb.c:849! (preempt_count 1)

2.5.8-pre3: kernel BUG at usb.c:849! (preempt_count 1)

[Duncan Sands]

UP x86 K6 system running 2.5.8-pre3 with preemption.
Using usb-uhci.  I got the following bug when powering off:

usb.c: USB disconnect on device 3
kernel BUG at usb.c:849!
invalid operand: 0000
CPU:    0
EIP:    0010:[<cc8babe2>]    Not tainted
EFLAGS: 00010246
eax: 00000000   ebx: cb8e2800   ecx: cb8e2550   edx: 00000002
esi: cbc75d88   edi: cc8c7a20   ebp: ffffffff   esp: cab5ff24
ds: 0018   es: 0018   ss: 0018
Process rmmod (pid: 1787, threadinfo=cab5e000 task=c952a6a0)
Stack: cb8e29f8 cc8bbafe cb8e2800 cb8e25bc cb796180 cc8c79a0 0000000e 0000024c
       cb8e2800 cc8bbaad cb8e25bc cb796080 cc8ce600 c71a5000 cc8c9000 000000c4
       cb8e2400 cc8ccc7a cab5ff74 c12dc800 00000000 c01cf07f c12dc800 cc8c9000
Call Trace: [<cc8bbafe>] [<cc8c79a0>] [<cc8bbaad>] [<cc8ce600>] [<cc8ccc7a>]
   [pci_unregister_driver+51/76] [<cc8cd176>] [<cc8ce600>] [free_module+23/192] [sys_delete_module+292/628] [syscall_call+7/11]
Code: 0f 0b 51 03 94 42 8c cc 8b 83 cc 00 00 00 8b 40 18 53 8b 40
 <3>error: rmmod[1787] exited with preempt_count 1

Re: 2.5.8-pre3: kernel BUG at usb.c:849! (preempt_count 1)

[Johannes Erdfelt]

On Wed, Apr 10, 2002, Duncan Sands <duncan.sands@math.u-psud.fr> wrote:
> UP x86 K6 system running 2.5.8-pre3 with preemption.
> Using usb-uhci.  I got the following bug when powering off:
> 
> usb.c: USB disconnect on device 3
> kernel BUG at usb.c:849!
> invalid operand: 0000
> CPU:    0
> EIP:    0010:[<cc8babe2>]    Not tainted
> EFLAGS: 00010246
> eax: 00000000   ebx: cb8e2800   ecx: cb8e2550   edx: 00000002
> esi: cbc75d88   edi: cc8c7a20   ebp: ffffffff   esp: cab5ff24
> ds: 0018   es: 0018   ss: 0018
> Process rmmod (pid: 1787, threadinfo=cab5e000 task=c952a6a0)
> Stack: cb8e29f8 cc8bbafe cb8e2800 cb8e25bc cb796180 cc8c79a0 0000000e 0000024c
>        cb8e2800 cc8bbaad cb8e25bc cb796080 cc8ce600 c71a5000 cc8c9000 000000c4
>        cb8e2400 cc8ccc7a cab5ff74 c12dc800 00000000 c01cf07f c12dc800 cc8c9000
> Call Trace: [<cc8bbafe>] [<cc8c79a0>] [<cc8bbaad>] [<cc8ce600>] [<cc8ccc7a>]
>    [pci_unregister_driver+51/76] [<cc8cd176>] [<cc8ce600>] [free_module+23/192] [sys_delete_module+292/628] [syscall_call+7/11]
> Code: 0f 0b 51 03 94 42 8c cc 8b 83 cc 00 00 00 8b 40 18 53 8b 40

Could you run this through ksymoops?

>  <3>error: rmmod[1787] exited with preempt_count 1

I don't like the looks of that.

JE

Re: [linux-usb-devel] Re: 2.5.8-pre3: kernel BUG at usb.c:849! (preempt_count 1)

[David Brownell]

> > UP x86 K6 system running 2.5.8-pre3 with preemption.
> > Using usb-uhci.  I got the following bug when powering off:
> >
> > usb.c: USB disconnect on device 3
> > ...

Does the same BUG happen with "uhci"?

And what usb device driver(s) were supposed to have stopped
using "device 3"?  I've only noticed such device refcounting bugs
being caused by the USB device drivers with bad disconnect()
routines, not usbcore or any of the host controller drivers, but of
course that can change.

- Dave

Re: [linux-usb-devel] Re: 2.5.8-pre3: kernel BUG at usb.c:849! (preempt_count 1)

[Duncan Sands]

On Wednesday 10 April 2002 6:40 pm, you wrote:
> > > UP x86 K6 system running 2.5.8-pre3 with preemption.
> > > Using usb-uhci.  I got the following bug when powering off:
> > >
> > > usb.c: USB disconnect on device 3
> > > ...
>
> Does the same BUG happen with "uhci"?

I haven't been able to reproduce it yet with usb-uhci...  I will try uhci
also.

> And what usb device driver(s) were supposed to have stopped
> using "device 3"?  I've only noticed such device refcounting bugs
> being caused by the USB device drivers with bad disconnect()
> routines, not usbcore or any of the host controller drivers, but of
> course that can change.

Ha!

$ cat /proc/bus/usb/drivers
         usbfs
         hub

There are no other drivers!  I have a USB webcam and a modem
attached.  I didn't compile the driver for the webcam, and the modem
has a user space driver that works via usbfs.

Duncan.

T:  Bus=01 Lev=00 Prnt=00 Port=00 Cnt=00 Dev#=  1 Spd=12  MxCh= 2
B:  Alloc=  0/900 us ( 0%), #Int=  0, #Iso=  0
D:  Ver= 1.00 Cls=09(hub  ) Sub=00 Prot=00 MxPS= 8 #Cfgs=  1
P:  Vendor=0000 ProdID=0000 Rev= 0.00
S:  Product=USB UHCI Root Hub
S:  SerialNumber=b800
C:* #Ifs= 1 Cfg#= 1 Atr=40 MxPwr=  0mA
I:  If#= 0 Alt= 0 #EPs= 1 Cls=09(hub  ) Sub=00 Prot=00 Driver=hub
E:  Ad=81(I) Atr=03(Int.) MxPS=   8 Ivl=255ms
T:  Bus=01 Lev=01 Prnt=01 Port=00 Cnt=01 Dev#=  2 Spd=12  MxCh= 0
D:  Ver= 1.00 Cls=ff(vend.) Sub=ff Prot=ff MxPS= 8 #Cfgs=  1
P:  Vendor=046d ProdID=0840 Rev= 1.00
S:  Product=Camera
C:* #Ifs= 1 Cfg#= 1 Atr=80 MxPwr=500mA
I:  If#= 0 Alt= 0 #EPs= 2 Cls=ff(vend.) Sub=ff Prot=ff Driver=(none)
E:  Ad=81(I) Atr=01(Isoc) MxPS=   0 Ivl=1ms
E:  Ad=82(I) Atr=03(Int.) MxPS=   1 Ivl=16ms
I:  If#= 0 Alt= 1 #EPs= 2 Cls=ff(vend.) Sub=ff Prot=ff Driver=(none)
E:  Ad=81(I) Atr=01(Isoc) MxPS=1023 Ivl=1ms
E:  Ad=82(I) Atr=03(Int.) MxPS=   1 Ivl=16ms
T:  Bus=01 Lev=01 Prnt=01 Port=01 Cnt=02 Dev#=  3 Spd=12  MxCh= 0
D:  Ver= 1.10 Cls=ff(vend.) Sub=00 Prot=00 MxPS= 8 #Cfgs=  1
P:  Vendor=06b9 ProdID=4061 Rev= 0.00
S:  Manufacturer=ALCATEL
S:  Product=Speed Touch USB 
S:  SerialNumber=0090D02C2C5A
C:* #Ifs= 3 Cfg#= 1 Atr=80 MxPwr=500mA
I:  If#= 0 Alt= 0 #EPs= 1 Cls=ff(vend.) Sub=00 Prot=00 Driver=usbfs
E:  Ad=81(I) Atr=03(Int.) MxPS=  16 Ivl=50ms
I:  If#= 1 Alt= 0 #EPs= 0 Cls=ff(vend.) Sub=00 Prot=00 Driver=usbfs
I:  If#= 1 Alt= 1 #EPs= 3 Cls=ff(vend.) Sub=00 Prot=00 Driver=usbfs
E:  Ad=06(O) Atr=02(Bulk) MxPS=  64 Ivl=0ms
E:  Ad=07(O) Atr=02(Bulk) MxPS=  64 Ivl=0ms
E:  Ad=87(I) Atr=02(Bulk) MxPS=  64 Ivl=0ms
I:  If#= 1 Alt= 2 #EPs= 3 Cls=ff(vend.) Sub=00 Prot=00 Driver=usbfs
E:  Ad=06(O) Atr=02(Bulk) MxPS=  32 Ivl=0ms
E:  Ad=07(O) Atr=02(Bulk) MxPS=  32 Ivl=0ms
E:  Ad=87(I) Atr=02(Bulk) MxPS=  64 Ivl=0ms
I:  If#= 1 Alt= 3 #EPs= 3 Cls=ff(vend.) Sub=00 Prot=00 Driver=usbfs
E:  Ad=06(O) Atr=02(Bulk) MxPS=  16 Ivl=0ms
E:  Ad=07(O) Atr=02(Bulk) MxPS=  16 Ivl=0ms
E:  Ad=87(I) Atr=02(Bulk) MxPS=  64 Ivl=0ms
I:  If#= 2 Alt= 0 #EPs= 2 Cls=ff(vend.) Sub=00 Prot=00 Driver=(none)
E:  Ad=05(O) Atr=02(Bulk) MxPS=   8 Ivl=0ms
E:  Ad=85(I) Atr=02(Bulk) MxPS=   8 Ivl=0ms

Re: [linux-usb-devel] Re: 2.5.8-pre3: kernel BUG at usb.c:849! (preempt_count 1)

[David Brownell]

[-- Attachment #1: Type: text/plain, Size: 1238 bytes --]

> > And what usb device driver(s) were supposed to have stopped
> > using "device 3"?  I've only noticed such device refcounting bugs
> > being caused by the USB device drivers with bad disconnect()
> > routines, not usbcore or any of the host controller drivers, but of
> > course that can change.
> 
> Ha!
> 
> $ cat /proc/bus/usb/drivers
>          usbfs
>          hub
> 
> There are no other drivers!  I have a USB webcam and a modem
> ... has a user space driver that works via usbfs.

... OK, this is sounding familiar.  "usbfs" has some recently noted
bugs in its disconnect() routine.  That SpeedTouch driver seems to
be triggering them with regularity, though more often with usb-ohci.

The ksymoops info you sent is compatible with the bug being in
the usbfs code:  exactly what I'd expect such a BUG() to show.

I hate to send around untested patches, but I think the one I've
attached is at least in the right direction.  (Attachment, to avoid
mangling by mailers...)  It's an update of what I sent around late
last month to address someone's SpeedTouch oopsing with
usb-ohci (!) on 2.4.19-pre2, redone against 2.5.8-pre3, which
compiles.  I hope it doesn't create new oopses.

If it works for you, let us know ...

- Dave



[-- Attachment #2: devio-0410.patch --]
[-- Type: application/octet-stream, Size: 893 bytes --]

--- drivers/usb-dist/core/devio.c	Sat Apr  6 15:12:31 2002
+++ drivers/usb/core/devio.c	Wed Apr 10 10:11:38 2002
@@ -297,7 +297,9 @@
 }
 
 /*
- * interface claiming
+ * interface claims are made only at the request of user level code,
+ * which can also release them (explicitly or by closing files).
+ * they're also undone when devices disconnect.
  */
 
 static void *driver_probe(struct usb_device *dev, unsigned int intf,
@@ -310,8 +312,20 @@
 {
 	struct dev_state *ps = (struct dev_state *)context;
 
-	if (ps)
-		ps->ifclaimed = 0;
+	if (!ps)
+		return;
+
+	/* this waits till synchronous requests complete */
+	down_write (&ps->devsem);
+
+	/* prevent new I/O requests */
+	ps->dev = 0;
+	ps->ifclaimed = 0;
+
+	/* force async requests to complete */
+	destroy_all_async (ps);
+
+	up_write (&ps->devsem);
 }
 
 struct usb_driver usbdevfs_driver = {

Re: [linux-usb-devel] Re: 2.5.8-pre3: kernel BUG at usb.c:849! (preempt_count 1)

[Duncan Sands]

On Wednesday 10 April 2002 7:23 pm, David Brownell wrote:
> > > And what usb device driver(s) were supposed to have stopped
> > > using "device 3"?  I've only noticed such device refcounting bugs
> > > being caused by the USB device drivers with bad disconnect()
> > > routines, not usbcore or any of the host controller drivers, but of
> > > course that can change.
> >
> > Ha!
> >
> > $ cat /proc/bus/usb/drivers
> >          usbfs
> >          hub
> >
> > There are no other drivers!  I have a USB webcam and a modem
> > ... has a user space driver that works via usbfs.
>
> ... OK, this is sounding familiar.  "usbfs" has some recently noted
> bugs in its disconnect() routine.  That SpeedTouch driver seems to
> be triggering them with regularity, though more often with usb-ohci.
>
> The ksymoops info you sent is compatible with the bug being in
> the usbfs code:  exactly what I'd expect such a BUG() to show.
>
> I hate to send around untested patches, but I think the one I've
> attached is at least in the right direction.  (Attachment, to avoid
> mangling by mailers...)  It's an update of what I sent around late
> last month to address someone's SpeedTouch oopsing with
> usb-ohci (!) on 2.4.19-pre2, redone against 2.5.8-pre3, which
> compiles.  I hope it doesn't create new oopses.
>
> If it works for you, let us know ...
>
> - Dave

It seems to work - thanks!  I will test more, but so far so good.
System shutdown still completes with "preempt_count = 1"
though.

All the best,

Duncan.

Re: 2.5.8-pre3: kernel BUG at usb.c:849! (preempt_count 1)

[Robert Love]

On Wed, 2002-04-10 at 11:41, Johannes Erdfelt wrote:

> >  <3>error: rmmod[1787] exited with preempt_count 1
> 
> I don't like the looks of that.

That error means a task exited with a nonzero preempt_count, in this
case 1.  This means a lock was held after exit (or, a lock was never
unlocked - e.g. it was dynamic and just deleted, but the lock counting
code can't know that).

In this case it may just be because the task oopsed while holding the
lock and then exited.  This may point to the lock being the BKL since it
would be trivial to have it reschedule and then die while holding it.

While the main point of that error is to point out code that does rude
things with preemption, in this case we probably just have another
problem and this is another sign of it.

	Robert Love

Re: 2.5.8-pre3: kernel BUG at usb.c:849! (preempt_count 1)

[Duncan Sands]

Ok, I got a new oops, which I could decode:

ksymoops 2.4.5 on i586 2.5.8-pre3.  Options used
     -V (default)
     -k /var/log/ksymoops/20020410185940.ksyms (specified)
     -l /var/log/ksymoops/20020410185940.modules (specified)
     -o /lib/modules/2.5.8-pre3/ (specified)
     -m /boot/System.map-2.5.8-pre3 (specified)

kernel BUG at usb.c:849!
invalid operand: 0000
CPU:    0
EIP:    0010:[<cc8babe2>]    Not tainted
Using defaults from ksymoops -t elf32-i386 -a i386
EFLAGS: 00010246
eax: 00000000   ebx: cb987800   ecx: cb987550   edx: 00000002
esi: c962c588   edi: cc8c7a20   ebp: ffffffff   esp: c93bff24
ds: 0018   es: 0018   ss: 0018
Stack: cb9879f8 cc8bbafe cb987800 cb9875bc cb763180 cc8c79a0 0000000e 0000024c 
       cb987800 cc8bbaad cb9875bc cb763080 cc8ce600 c991e000 cc8c9000 000000c4 
       cb987400 cc8ccc7a c93bff74 c12dc800 00000000 c01cf07f c12dc800 cc8c9000 
Call Trace: [<cc8bbafe>] [<cc8c79a0>] [<cc8bbaad>] [<cc8ce600>] [<cc8ccc7a>] 
Code: 0f 0b 51 03 94 42 8c cc 8b 83 cc 00 00 00 8b 40 18 53 8b 40 


>>EIP; cc8babe2 <[usbcore]usb_free_dev+26/5c>   <=====

>>ebx; cb987800 <_end+b6a64e0/c589ce0>
>>ecx; cb987550 <_end+b6a6230/c589ce0>
>>esi; c962c588 <_end+934b268/c589ce0>
>>edi; cc8c7a20 <[usbcore]usbdevfs_driver+20/40>
>>ebp; ffffffff <END_OF_CODE+337319bc/????>
>>esp; c93bff24 <_end+90dec04/c589ce0>

Trace; cc8bbafe <[usbcore]usb_disconnect+156/160>
Trace; cc8c79a0 <[usbcore]hub_driver+20/40>
Trace; cc8bbaad <[usbcore]usb_disconnect+105/160>
Trace; cc8ce600 <[usb-uhci]uhci_pci_driver+0/3f>
Trace; cc8ccc7a <[usb-uhci]uhci_pci_remove+2a/c0>

Code;  cc8babe2 <[usbcore]usb_free_dev+26/5c>
00000000 <_EIP>:
Code;  cc8babe2 <[usbcore]usb_free_dev+26/5c>   <=====
   0:   0f 0b                     ud2a      <=====
Code;  cc8babe4 <[usbcore]usb_free_dev+28/5c>
   2:   51                        push   %ecx
Code;  cc8babe5 <[usbcore]usb_free_dev+29/5c>
   3:   03 94 42 8c cc 8b 83      add    0x838bcc8c(%edx,%eax,2),%edx
Code;  cc8babec <[usbcore]usb_free_dev+30/5c>
   a:   cc                        int3   
Code;  cc8babed <[usbcore]usb_free_dev+31/5c>
   b:   00 00                     add    %al,(%eax)
Code;  cc8babef <[usbcore]usb_free_dev+33/5c>
   d:   00 8b 40 18 53 8b         add    %cl,0x8b531840(%ebx)
Code;  cc8babf5 <[usbcore]usb_free_dev+39/5c>
  13:   40                        inc    %eax