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