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

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

Could you run this through ksymoops?

I don't like the looks of that.

JE

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

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

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

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

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 

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

... 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

@@ -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 = {

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.