On Tue, 2004-07-13 at 14:46, Alan Stern wrote:
> 
> A very informative and detailed response, thank you.
> 

It's the least I can do.

> The problem shows up clearly in your "dmesg" file; something is calling 
> usb_unlock_device() without calling usb_lock_device() first.  
> Unfortunately the diagnostic patch didn't include a dump_stack() call in 
> usb_unlock_device(), so I can't tell who the guilty party is.
> 
> Here's a shorter patch for you to try.  It ought to pinpoint the culprit.  
> This is probably some stupid mistake on my part that will end up being
> obvious, but I just can't see where it is...

Here is the end of dmesg (the whole log is attached:

usb_lock_device: udev=f7fd2800 count=fffefffe
 [<c025037a>] usb_lock_device+0x3a/0x60
 [<c025fc80>] usb_device_read+0xb0/0x130
 [<c014f6d8>] vfs_read+0xb8/0x130
 [<c014f972>] sys_read+0x42/0x70
 [<c0104035>] sysenter_past_esp+0x52/0x71

Jesse

-- 
Jesse Stockall <[EMAIL PROTECTED]>
hdc: LITEON DVD-ROM LTD122, ATAPI CD/DVD-ROM drive
ide1 at 0x170-0x177,0x376 on irq 15
PDC20265: IDE controller at PCI slot 0000:00:11.0
ACPI: PCI interrupt 0000:00:11.0[A] -> GSI 10 (level, low) -> IRQ 10
PDC20265: chipset revision 2
PDC20265: 100% native mode on irq 10
PDC20265: (U)DMA Burst Bit ENABLED Primary PCI Mode Secondary PCI Mode.
    ide2: BM-DMA at 0x8000-0x8007, BIOS settings: hde:DMA, hdf:pio
    ide3: BM-DMA at 0x8008-0x800f, BIOS settings: hdg:DMA, hdh:pio
hde: Maxtor 5T040H4, ATA DISK drive
ide2 at 0x9400-0x9407,0x9002 on irq 10
hdg: Maxtor 6Y080P0, ATA DISK drive
ide3 at 0x8800-0x8807,0x8402 on irq 10
hde: max request size: 128KiB
hde: 80043264 sectors (40982 MB) w/2048KiB Cache, CHS=65535/16/63, UDMA(100)
hde: cache flushes supported
 hde: hde1 hde2 hde3
hdg: max request size: 128KiB
hdg: 160086528 sectors (81964 MB) w/7936KiB Cache, CHS=65535/16/63, UDMA(100)
hdg: cache flushes supported
 hdg: hdg1 hdg2
hda: ATAPI 52X CD-ROM CD-R/RW drive, 2048kB Cache, UDMA(33)
Uniform CD-ROM driver Revision: 3.20
hdc: ATAPI 40X DVD-ROM drive, 512kB Cache, UDMA(33)
serio: i8042 AUX port at 0x60,0x64 irq 12
serio: i8042 KBD port at 0x60,0x64 irq 1
mice: PS/2 mouse device common for all mice
input: AT Translated Set 2 keyboard on isa0060/serio0
psmouse.c: Failed to reset mouse on isa0060/serio1
input: PS/2 Generic Mouse on isa0060/serio1
psmouse.c: Failed to enable mouse on isa0060/serio1
NET: Registered protocol family 2
IP: routing cache hash table of 8192 buckets, 64Kbytes
TCP: Hash tables configured (established 262144 bind 65536)
NET: Registered protocol family 1
NET: Registered protocol family 17
ACPI: (supports S0 S1 S4 S5)
ReiserFS: hde2: found reiserfs format "3.6" with standard journal
ReiserFS: hde2: using ordered data mode
ReiserFS: hde2: journal params: device hde2, size 8192, journal first block 18, max 
trans len 1024, max batch 900, max commit age 30, max trans age 30
ReiserFS: hde2: checking transaction log (hde2)
ReiserFS: hde2: Using r5 hash to sort names
VFS: Mounted root (reiserfs filesystem) readonly.
Freeing unused kernel memory: 136k freed
Adding 999896k swap on /dev/hdg1.  Priority:-1 extents:1
ACPI: PCI interrupt 0000:00:0d.0[A] -> GSI 9 (level, low) -> IRQ 9
3c59x: Donald Becker and others. www.scyld.com/network/vortex.html
0000:00:0d.0: 3Com PCI 3c905B Cyclone 100baseTx at 0x9800. Vers LK1.1.19
Linux agpgart interface v0.100 (c) Dave Jones
agpgart: Detected VIA Twister-K/KT133x/KM133 chipset
agpgart: Maximum main memory to use for agp memory: 816M
agpgart: AGP aperture is 32M @ 0xe6000000
[drm] Initialized mga 3.1.0 20021029 on minor 0: Matrox Graphics, Inc. MGA G400 AGP
USB Universal Host Controller Interface driver v2.2
ACPI: PCI interrupt 0000:00:04.2[D] -> GSI 9 (level, low) -> IRQ 9
uhci_hcd 0000:00:04.2: VIA Technologies, Inc. VT82xxxxx UHCI USB 1.1 Controller
uhci_hcd 0000:00:04.2: irq 9, io base 0000d400
uhci_hcd 0000:00:04.2: new USB bus registered, assigned bus number 1
uhci_hcd 0000:00:04.2: detected 2 ports
usb_lock_device: udev=f7fdea00 count=0
 [<c025037a>] usb_lock_device+0x3a/0x60
 [<c02553ed>] usb_register_root_hub+0xdd/0x150
 [<f896d803>] uhci_start+0x563/0x750 [uhci_hcd]
 [<c025521f>] usb_register_bus+0x10f/0x140
 [<c025a986>] usb_hcd_pci_probe+0x2a6/0x5b0
 [<c01dadd2>] pci_device_probe_static+0x52/0x70
 [<c01dae2b>] __pci_device_probe+0x3b/0x50
 [<c01dae6c>] pci_device_probe+0x2c/0x50
 [<c0216e8f>] bus_match+0x3f/0x70
 [<c0216fb9>] driver_attach+0x59/0x90
 [<c0216f61>] driver_attach+0x1/0x90
 [<c0217371>] bus_add_driver+0x91/0xb0
 [<c021791f>] driver_register+0x2f/0x40
 [<c01db0ec>] pci_register_driver+0x5c/0x90
 [<f89330c9>] uhci_hcd_init+0xc9/0x131 [uhci_hcd]
 [<c012ff24>] sys_init_module+0x114/0x230
 [<c0104035>] sysenter_past_esp+0x52/0x71
usb usb1: new device strings: Mfr=3, Product=2, SerialNumber=1
usb usb1: default language 0x0409
usb usb1: Product: VIA Technologies, Inc. VT82xxxxx UHCI USB 1.1 Controller
usb usb1: Manufacturer: Linux 2.6.7-mm6 uhci_hcd
usb usb1: SerialNumber: 0000:00:04.2
usb usb1: hotplug
usb usb1: adding 1-0:1.0 (config #1, interface 0)
usb 1-0:1.0: hotplug
hub 1-0:1.0: usb_probe_interface
hub 1-0:1.0: usb_probe_interface - got id
hub 1-0:1.0: USB hub found
hub 1-0:1.0: 2 ports detected
hub 1-0:1.0: standalone hub
hub 1-0:1.0: no power switching (usb 1.0)
hub 1-0:1.0: individual port over-current protection
hub 1-0:1.0: power on to power good time: 2ms
hub 1-0:1.0: local power source is good
usb_unlock_device: udev=f7fdea00 count=1
 [<c02504da>] usb_unlock_device+0x3a/0x70
 [<c02553ff>] usb_register_root_hub+0xef/0x150
 [<f896d803>] uhci_start+0x563/0x750 [uhci_hcd]
 [<c025521f>] usb_register_bus+0x10f/0x140
 [<c025a986>] usb_hcd_pci_probe+0x2a6/0x5b0
 [<c01dadd2>] pci_device_probe_static+0x52/0x70
 [<c01dae2b>] __pci_device_probe+0x3b/0x50
 [<c01dae6c>] pci_device_probe+0x2c/0x50
 [<c0216e8f>] bus_match+0x3f/0x70
 [<c0216fb9>] driver_attach+0x59/0x90
 [<c0216f61>] driver_attach+0x1/0x90
 [<c0217371>] bus_add_driver+0x91/0xb0
 [<c021791f>] driver_register+0x2f/0x40
 [<c01db0ec>] pci_register_driver+0x5c/0x90
 [<f89330c9>] uhci_hcd_init+0xc9/0x131 [uhci_hcd]
 [<c012ff24>] sys_init_module+0x114/0x230
 [<c0104035>] sysenter_past_esp+0x52/0x71
ACPI: PCI interrupt 0000:00:04.3[D] -> GSI 9 (level, low) -> IRQ 9
uhci_hcd 0000:00:04.3: VIA Technologies, Inc. VT82xxxxx UHCI USB 1.1 Controller (#2)
uhci_hcd 0000:00:04.3: irq 9, io base 0000d000
uhci_hcd 0000:00:04.3: new USB bus registered, assigned bus number 2
uhci_hcd 0000:00:04.3: detected 2 ports
usb_lock_device: udev=f7fd2800 count=0
 [<c025037a>] usb_lock_device+0x3a/0x60
 [<c02553ed>] usb_register_root_hub+0xdd/0x150
 [<f896d803>] uhci_start+0x563/0x750 [uhci_hcd]
 [<c025521f>] usb_register_bus+0x10f/0x140
 [<c025a986>] usb_hcd_pci_probe+0x2a6/0x5b0
 [<c01dadd2>] pci_device_probe_static+0x52/0x70
 [<c01dae2b>] __pci_device_probe+0x3b/0x50
 [<c01dae6c>] pci_device_probe+0x2c/0x50
 [<c0216e8f>] bus_match+0x3f/0x70
 [<c0216fb9>] driver_attach+0x59/0x90
 [<c0216f61>] driver_attach+0x1/0x90
 [<c0217371>] bus_add_driver+0x91/0xb0
 [<c021791f>] driver_register+0x2f/0x40
 [<c01db0ec>] pci_register_driver+0x5c/0x90
 [<f89330c9>] uhci_hcd_init+0xc9/0x131 [uhci_hcd]
 [<c012ff24>] sys_init_module+0x114/0x230
 [<c0104035>] sysenter_past_esp+0x52/0x71
usb usb2: new device strings: Mfr=3, Product=2, SerialNumber=1
usb usb2: default language 0x0409
usb usb2: Product: VIA Technologies, Inc. VT82xxxxx UHCI USB 1.1 Controller (#2)
usb usb2: Manufacturer: Linux 2.6.7-mm6 uhci_hcd
usb usb2: SerialNumber: 0000:00:04.3
usb usb2: hotplug
usb usb2: adding 2-0:1.0 (config #1, interface 0)
usb 2-0:1.0: hotplug
usb_lock_device: udev=f7fdea00 count=1
 [<c025037a>] usb_lock_device+0x3a/0x60
 [<c02539e4>] hub_events+0x64/0x4d0
 [<c0253e85>] hub_thread+0x35/0x130
 [<c0117a00>] autoremove_wake_function+0x0/0x60
 [<c0103f5e>] ret_from_fork+0x6/0x14
 [<c0117a00>] autoremove_wake_function+0x0/0x60
 [<c0253e50>] hub_thread+0x0/0x130
 [<c0102291>] kernel_thread_helper+0x5/0x14
uhci_hcd 0000:00:04.2: port 1 portsc 018a
hub 1-0:1.0: port 1, status 0300, change 0003, 1.5 Mb/s
hub 2-0:1.0: usb_probe_interface
hub 2-0:1.0: usb_probe_interface - got id
hub 2-0:1.0: USB hub found
hub 2-0:1.0: 2 ports detected
hub 2-0:1.0: standalone hub
hub 2-0:1.0: no power switching (usb 1.0)
hub 2-0:1.0: individual port over-current protection
hub 2-0:1.0: power on to power good time: 2ms
hub 2-0:1.0: local power source is good
usb_unlock_device: udev=f7fd2800 count=2
 [<c02504da>] usb_unlock_device+0x3a/0x70
 [<c02553ff>] usb_register_root_hub+0xef/0x150
 [<f896d803>] uhci_start+0x563/0x750 [uhci_hcd]
 [<c025521f>] usb_register_bus+0x10f/0x140
 [<c025a986>] usb_hcd_pci_probe+0x2a6/0x5b0
 [<c01dadd2>] pci_device_probe_static+0x52/0x70
 [<c01dae2b>] __pci_device_probe+0x3b/0x50
 [<c01dae6c>] pci_device_probe+0x2c/0x50
 [<c0216e8f>] bus_match+0x3f/0x70
 [<c0216fb9>] driver_attach+0x59/0x90
 [<c0216f61>] driver_attach+0x1/0x90
 [<c0217371>] bus_add_driver+0x91/0xb0
 [<c021791f>] driver_register+0x2f/0x40
 [<c01db0ec>] pci_register_driver+0x5c/0x90
 [<f89330c9>] uhci_hcd_init+0xc9/0x131 [uhci_hcd]
 [<c012ff24>] sys_init_module+0x114/0x230
 [<c0104035>] sysenter_past_esp+0x52/0x71
Real Time Clock Driver v1.12
parport0: PC-style at 0x278 (0x678) [PCSPP(,...)]
parport_pc: Via 686A parallel port: io=0x278
lp0: using parport0 (polling).
Linux video capture interface: v1.00
hub 1-0:1.0: debounce: port 1: total 100ms stable 100ms status 0x300
uhci_hcd 0000:00:04.2: port 2 portsc 01ab
hub 1-0:1.0: port 2, status 0301, change 0003, 1.5 Mb/s
bttv: driver version 0.9.15 loaded
bttv: using 8 buffers with 2080k (520 pages) each for capture
bttv: Bt8xx card found (0).
ACPI: PCI interrupt 0000:00:09.0[A] -> GSI 9 (level, low) -> IRQ 9
bttv0: Bt878 (rev 2) at 0000:00:09.0, irq: 9, latency: 32, mmio: 0xe3000000
bttv0: detected: Hauppauge WinTV [card=10], PCI subsystem ID is 0070:13eb
bttv0: using: Hauppauge (bt878) [card=10,autodetected]
bttv0: gpio: en=00000000, out=00000000 in=00fffffb [init]
bttv0: Hauppauge/Voodoo msp34xx: reset line init [5]
hub 1-0:1.0: debounce: port 2: total 100ms stable 100ms status 0x301
bttv0: Hauppauge eeprom: model=61201, tuner=Temic 4036FY5 (8), radio=no
bttv0: using tuner=8
bttv0: i2c: checking for MSP34xx @ 0x80... not found
bttv0: i2c: checking for TDA9875 @ 0xb0... not found
bttv0: i2c: checking for TDA7432 @ 0x8a... not found
tvaudio: TV audio decoder + audio/video mux driver
tvaudio: known chips: 
tda9840,tda9873h,tda9874h/a,tda9850,tda9855,tea6300,tea6420,tda8425,pic16c54 
(PV951),ta8874z
tuner: chip found at addr 0xc2 i2c-bus bt878 #0 [sw]
tuner: type set to 8 (Temic NTSC (4036 FY5)) by bt878 #0 [sw]
bttv0: registered device video0
bttv0: registered device vbi0
bttv0: PLL: 28636363 => 35468950 .. ok
usb 1-2: new low speed USB device using address 2
usb 1-2: skipped 1 descriptor after interface
usb 1-2: new device strings: Mfr=1, Product=2, SerialNumber=0
usb 1-2: default language 0x0409
ReiserFS: hdg2: found reiserfs format "3.6" with standard journal
usb 1-2: Product: Microsoft Wheel Mouse Optical®
usb 1-2: Manufacturer: Microsoft
usb 1-2: hotplug
usb 1-2: adding 1-2:1.0 (config #1, interface 0)
usb 1-2:1.0: hotplug
usb_unlock_device: udev=f7fd4a00 count=1
 [<c02504da>] usb_unlock_device+0x3a/0x70
 [<c02536a9>] hub_port_connect_change+0x219/0x4f0
 [<c0253dc2>] hub_events+0x442/0x4d0
 [<c0253e85>] hub_thread+0x35/0x130
 [<c0117a00>] autoremove_wake_function+0x0/0x60
 [<c0103f5e>] ret_from_fork+0x6/0x14
 [<c0117a00>] autoremove_wake_function+0x0/0x60
 [<c0253e50>] hub_thread+0x0/0x130
 [<c0102291>] kernel_thread_helper+0x5/0x14
usb_unlock_device: udev=f7fdea00 count=0
 [<c02504da>] usb_unlock_device+0x3a/0x70
 [<c02539f2>]<6>usb_lock_all_devices: count=0
 [<c025053e>] usb_lock_all_devices+0x2e/0x50
 [<c024f9dd>] usb_register+0x3d/0xb0
 [<f89ae00f>] hid_init+0xf/0x2d [usbhid]
 [<c012ff24>] sys_init_module+0x114/0x230
 [<c0104035>] sysenter_past_esp+0x52/0x71
usbhid 1-2:1.0: usb_probe_interface
usbhid 1-2:1.0: usb_probe_interface - got id
 hub_events+0x72/0x4d0
 [<c0253e85>] hub_thread+0x35/0x130
 [<c0117a00>] autoremove_wake_function+0x0/0x60
 [<c0103f5e>] ret_from_fork+0x6/0x14
 [<c0117a00>] autoremove_wake_function+0x0/0x60
 [<c0253e50>] hub_thread+0x0/0x130
 [<c0102291>] kernel_thread_helper+0x5/0x14
usb_lock_device: udev=f7fd2800 count=ffff0000
 [<c025037a>] usb_lock_device+0x3a/0x60
 [<c02539e4>] hub_events+0x64/0x4d0
 [<c0253e85>] hub_thread+0x35/0x130
 [<c0117a00>] autoremove_wake_function+0x0/0x60
 [<c0103f5e>] ret_from_fork+0x6/0x14
 [<c0117a00>] autoremove_wake_function+0x0/0x60
 [<c0253e50>] hub_thread+0x0/0x130
 [<c0102291>] kernel_thread_helper+0x5/0x14
uhci_hcd 0000:00:04.3: port 1 portsc 008a
hub 2-0:1.0: port 1, status 0100, change 0003, 12 Mb/s
input: USB HID v1.00 Mouse [Microsoft Microsoft Wheel Mouse Optical®] on 
usb-0000:00:04.2-2
usb_unlock_all_devices: count=ffff0001
usbcore: registered new driver usbhid
drivers/usb/input/hid-core.c: v2.0:USB HID core driver
hub 2-0:1.0: debounce: port 1: total 100ms stable 100ms status 0x100
uhci_hcd 0000:00:04.3: port 2 portsc 009b
hub 2-0:1.0: port 2, status 0101, change 0003, 12 Mb/s
hub 2-0:1.0: debounce: port 2: total 100ms stable 100ms status 0x101
usb 2-2: new full speed USB device using address 2
usb 2-2: new device strings: Mfr=1, Product=2, SerialNumber=0
usb 2-2: default language 0x0409
usb 2-2: Product: Generic USB Hub
usb 2-2: Manufacturer: ALCOR
usb 2-2: hotplug
usb 2-2: adding 2-2:1.0 (config #1, interface 0)
usb 2-2:1.0: hotplug
hub 2-2:1.0: usb_probe_interface
hub 2-2:1.0: usb_probe_interface - got id
hub 2-2:1.0: USB hub found
hub 2-2:1.0: 4 ports detected
hub 2-2:1.0: standalone hub
hub 2-2:1.0: ganged power switching
hub 2-2:1.0: global over-current protection
hub 2-2:1.0: power on to power good time: 44ms
hub 2-2:1.0: local power source is good
hub 2-2:1.0: no over-current condition exists
hub 2-2:1.0: enabling power on all ports
usb_unlock_device: udev=f7fd5a00 count=0
 [<c02504da>] usb_unlock_device+0x3a/0x70
 [<c02536a9>] hub_port_connect_change+0x219/0x4f0
 [<c0253dc2>] hub_events+0x442/0x4d0
 [<c0253e85>] hub_thread+0x35/0x130
 [<c0117a00>] autoremove_wake_function+0x0/0x60
 [<c0103f5e>] ret_from_fork+0x6/0x14
 [<c0117a00>] autoremove_wake_function+0x0/0x60
 [<c0253e50>] hub_thread+0x0/0x130
 [<c0102291>] kernel_thread_helper+0x5/0x14
usb_unlock_device: udev=f7fd2800 count=ffffffff
 [<c02504da>] usb_unlock_device+0x3a/0x70
 [<c02539f2>] hub_events+0x72/0x4d0
 [<c0253e85>] hub_thread+0x35/0x130
 [<c0117a00>] autoremove_wake_function+0x0/0x60
 [<c0103f5e>] ret_from_fork+0x6/0x14
 [<c0117a00>] autoremove_wake_function+0x0/0x60
 [<c0253e50>] hub_thread+0x0/0x130
 [<c0102291>] kernel_thread_helper+0x5/0x14
usb_lock_device: udev=f7fd2800 count=fffffffe
 [<c025037a>] usb_lock_device+0x3a/0x60
 [<c02539e4>] hub_events+0x64/0x4d0
 [<c0253e85>] hub_thread+0x35/0x130
 [<c0117a00>] autoremove_wake_function+0x0/0x60
 [<c0103f5e>] ret_from_fork+0x6/0x14
 [<c0117a00>] autoremove_wake_function+0x0/0x60
 [<c0253e50>] hub_thread+0x0/0x130
 [<c0102291>] kernel_thread_helper+0x5/0x14
ReiserFS: hdg2: using ordered data mode
ReiserFS: hdg2: journal params: device hdg2, size 8192, journal first block 18, max 
trans len 1024, max batch 900, max commit age 30, max trans age 30
ReiserFS: hdg2: checking transaction log (hdg2)
ReiserFS: hdg2: Using r5 hash to sort names
ReiserFS: hde1: found reiserfs format "3.6" with standard journal
ReiserFS: hde1: using ordered data mode
ReiserFS: hde1: journal params: device hde1, size 8192, journal first block 18, max 
trans len 1024, max batch 900, max commit age 30, max trans age 30
ReiserFS: hde1: checking transaction log (hde1)
ReiserFS: hde1: Using r5 hash to sort names
ACPI: PCI interrupt 0000:00:0a.0[A] -> GSI 7 (level, low) -> IRQ 7
ACPI: PCI interrupt 0000:00:09.1[A] -> GSI 9 (level, low) -> IRQ 9
vt596 smbus 0000:00:04.4: SMBus region 0xe800 already in use!
i2c_adapter i2c-1: enabling sensors
agpgart: Found an AGP 2.0 compliant device at 0000:00:00.0.
agpgart: Putting AGP V2 device at 0000:00:00.0 into 2x mode
agpgart: Putting AGP V2 device at 0000:01:00.0 into 2x mode
usb_lock_device: udev=f7fd2800 count=fffefffe
 [<c025037a>] usb_lock_device+0x3a/0x60
 [<c025fc80>] usb_device_read+0xb0/0x130
 [<c014f6d8>] vfs_read+0xb8/0x130
 [<c014f972>] sys_read+0x42/0x70
 [<c0104035>] sysenter_past_esp+0x52/0x71

Reply via email to