2.6.9-mm1 usb oopses

2.6.9-mm1 usb oopses

[Fabio Coatti]

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

Noticed in 2.6.9-rc4-mm1, still present in 2.6.9-mm1:
When a usb flash memory key is inserted, I get this report on syslog:

Oct 22 21:40:04 kefk kernel: ehci_hcd 0000:00:1d.7: GetStatus port 3 status 
001803 POWER sig=j  CSC CONNECT
Oct 22 21:40:04 kefk kernel: hub 5-0:1.0: port 3, status 0501, change 0001, 
480 Mb/s
Oct 22 21:40:04 kefk kernel: hub 5-0:1.0: debounce: port 3: total 100ms stable 
100ms status 0x501
Oct 22 21:40:04 kefk kernel: hub 5-0:1.0: port 3 not reset yet, waiting 50ms
Oct 22 21:40:04 kefk kernel: ehci_hcd 0000:00:1d.7: port 3 high speed
Oct 22 21:40:04 kefk kernel: ehci_hcd 0000:00:1d.7: GetStatus port 3 status 
001005 POWER sig=se0  PE CONNECT
Oct 22 21:40:04 kefk kernel: usb 5-3: new high speed USB device using address 
6
Oct 22 21:40:04 kefk kernel: usb 5-3: new device strings: Mfr=1, Product=2, 
SerialNumber=3
Oct 22 21:40:04 kefk kernel: usb 5-3: default language 0x0409
Oct 22 21:40:04 kefk kernel: usb 5-3: Product: Mass storage
Oct 22 21:40:04 kefk kernel: usb 5-3: Manufacturer: USB
Oct 22 21:40:04 kefk kernel: usb 5-3: SerialNumber: 142E19413C2FCA34
Oct 22 21:40:04 kefk kernel: usb 5-3: hotplug
Oct 22 21:40:04 kefk kernel: usb 5-3: adding 5-3:1.0 (config #1, interface 0)
Oct 22 21:40:04 kefk kernel: usb 5-3:1.0: hotplug
Oct 22 21:40:05 kefk kernel: ub: sizeof ub_scsi_cmd 64 ub_dev 964
Oct 22 21:40:05 kefk kernel: ub 5-3:1.0: usb_probe_interface
Oct 22 21:40:05 kefk kernel: ub 5-3:1.0: usb_probe_interface - got id
Oct 22 21:40:05 kefk kernel: uba: device 6 capacity nsec 50 bsize 512
Oct 22 21:40:05 kefk kernel: uba: made changed
Oct 22 21:40:05 kefk kernel: uba: device 6 capacity nsec 1024000 bsize 512
Oct 22 21:40:05 kefk kernel: uba: device 6 capacity nsec 1024000 bsize 512
Oct 22 21:40:05 kefk kernel:  uba: uba1
Oct 22 21:40:05 kefk kernel:  uba: uba1
Oct 22 21:40:05 kefk kernel: kobject_register failed for uba1 (-17)
Oct 22 21:40:05 kefk kernel:  [<c01f1f77>] kobject_register+0x51/0x5f
Oct 22 21:40:05 kefk kernel:  [<c018467c>] add_partition+0xbb/0xf0
Oct 22 21:40:05 kefk kernel:  [<c01847f4>] register_disk+0xee/0x11d
Oct 22 21:40:05 kefk kernel:  [<c024b8e6>] add_disk+0x36/0x41
Oct 22 21:40:05 kefk kernel:  [<c024b89c>] exact_match+0x0/0x7
Oct 22 21:40:05 kefk kernel:  [<c024b8a3>] exact_lock+0x0/0xd
Oct 22 21:40:05 kefk kernel:  [<f8c48e70>] ub_probe+0x291/0x2f4 [ub]
Oct 22 21:40:05 kefk kernel:  [<c0298f0e>] usb_probe_interface+0xb8/0xe1
Oct 22 21:40:05 kefk kernel:  [<c0243274>] bus_match+0x32/0x6a
Oct 22 21:40:05 kefk kernel:  [<c024339c>] driver_attach+0x46/0x85
Oct 22 21:40:05 kefk kernel:  [<c01f1f48>] kobject_register+0x22/0x5f
Oct 22 21:40:05 kefk kernel:  [<c0243800>] bus_add_driver+0x91/0xcb
Oct 22 21:40:05 kefk kernel:  [<c0298fe0>] usb_register+0x49/0x9f
Oct 22 21:40:05 kefk kernel:  [<f8c4d03f>] ub_init+0x3f/0x5f [ub]
Oct 22 21:40:05 kefk kernel:  [<c0131de7>] sys_init_module+0x160/0x246
Oct 22 21:40:05 kefk kernel:  [<c0103d71>] sysenter_past_esp+0x52/0x71
Oct 22 21:40:05 kefk kernel: usbcore: registered new driver ub

After that, uba appears as /dev/uba, but /dev/uba1 is missing. I can create by 
hand /dev/uba1 and access data on flash key, but if I umount and then remove 
the key I get this oops:


Oct 22 21:45:05 kefk kernel: ehci_hcd 0000:00:1d.7: GetStatus port 3 status 
001002 POWER sig=se0  CSC
Oct 22 21:45:05 kefk kernel: hub 5-0:1.0: port 3, status 0100, change 0001, 12 
Mb/s
Oct 22 21:45:05 kefk kernel: usb 5-3: USB disconnect, address 6
Oct 22 21:45:05 kefk kernel: usb 5-3: usb_disable_device nuking all URBs
Oct 22 21:45:05 kefk kernel: usb 5-3: unregistering interface 5-3:1.0
Oct 22 21:45:05 kefk kernel: Unable to handle kernel NULL pointer dereference 
at virtual address 00000050
Oct 22 21:45:05 kefk kernel:  printing eip:
Oct 22 21:45:05 kefk kernel: c01862cf
Oct 22 21:45:05 kefk kernel: *pde = 00000000
Oct 22 21:45:05 kefk kernel: Oops: 0000 [#1]
Oct 22 21:45:05 kefk kernel: PREEMPT SMP
Oct 22 21:45:05 kefk kernel: Modules linked in: nls_cp437 lp parport_pc ub 
hidp hci_usb snd_seq_midi snd_emu10k1_synth snd_emux_synth snd_seq_virmidi 
snd_seq_midi_emul nvidia tun md5 ipv6 rfcomm l2cap bluetooth snd_seq_oss 
snd_seq_midi_event snd_seq snd_pcm_oss snd_mixer_oss snd_emu10k1 snd_rawmidi 
snd_seq_device snd_ac97_codec snd_pcm snd_timer snd_page_alloc snd_util_mem 
snd_hwdep snd soundcore ipt_REJECT iptable_filter ip_tables loop nls_utf8 
ide_cd i2c_dev w83
781d i2c_sensor i2c_isa i2c_i801 isofs zlib_inflate e1000 ppa parport ehci_hcd 
usblp uhci_hcd genrtc
Oct 22 21:45:05 kefk kernel: CPU:    1
Oct 22 21:45:05 kefk kernel: EIP:    0060:[<c01862cf>]    Tainted: P      VLI
Oct 22 21:45:05 kefk kernel: EFLAGS: 00010246   (2.6.9-mm1)
Oct 22 21:45:05 kefk kernel: EIP is at sysfs_remove_dir+0x1d/0xef
Oct 22 21:45:05 kefk kernel: eax: cf85c308   ebx: cf85c308   ecx: c18ff480   
edx: c1000000
Oct 22 21:45:05 kefk kernel: esi: edce7c00   edi: 00000000   ebp: 00000246   
esp: c1bace20
Oct 22 21:45:05 kefk kernel: ds: 007b   es: 007b   ss: 0068
Oct 22 21:45:05 kefk kernel: Process khubd (pid: 125, threadinfo=c1bac000 
task=c1baba40)
Oct 22 21:45:05 kefk kernel: Stack: 00000000 cf85c308 edce7c00 00000001 
00000246 c01f2087 cf85c308 c01f2097
Oct 22 21:45:05 kefk kernel:        cca37180 c01849fc 00000000 edce7c00 
00000000 00000246 f8c48ff1 dc3ac848
Oct 22 21:45:05 kefk kernel:        0000003c 00000003 cca37294 f74ff02c 
cca37180 cca37280 f8c4b220 c86ad000
Oct 22 21:45:05 kefk kernel: Call Trace:
Oct 22 21:45:05 kefk kernel:  [<c01f2087>] kobject_del+0x14/0x1c
Oct 22 21:45:05 kefk kernel:  [<c01f2097>] kobject_unregister+0x8/0x10
Oct 22 21:45:05 kefk kernel:  [<c01849fc>] del_gendisk+0x1d/0xd5
Oct 22 21:45:05 kefk kernel:  [<f8c48ff1>] ub_disconnect+0x11e/0x171 [ub]
Oct 22 21:45:05 kefk kernel:  [<c0298f95>] usb_unbind_interface+0x5e/0x60
Oct 22 21:45:05 kefk kernel:  [<c0243431>] device_release_driver+0x56/0x58
Oct 22 21:45:05 kefk kernel:  [<c0243637>] bus_remove_device+0x53/0x90
Oct 22 21:45:05 kefk kernel:  [<c0242752>] device_del+0x54/0x91
Oct 22 21:45:05 kefk kernel:  [<c02a0ac3>] usb_disable_device+0xda/0x147
Oct 22 21:45:05 kefk kernel:  [<c029b7ab>] usb_disconnect+0xab/0x198
Oct 22 21:45:05 kefk kernel:  [<c029ca61>] hub_port_connect_change+0x2ce/0x47b
Oct 22 21:45:05 kefk kernel:  [<c029cee2>] hub_events+0x2d4/0x4ac
Oct 22 21:45:05 kefk kernel:  [<c029d0ef>] hub_thread+0x35/0x10e
Oct 22 21:45:05 kefk kernel:  [<c0115155>] finish_task_switch+0x3b/0x87
Oct 22 21:45:05 kefk kernel:  [<c012d9ad>] autoremove_wake_function+0x0/0x43
Oct 22 21:45:05 kefk kernel:  [<c0103ca6>] ret_from_fork+0x6/0x14
Oct 22 21:45:05 kefk kernel:  [<c012d9ad>] autoremove_wake_function+0x0/0x43
Oct 22 21:45:05 kefk kernel:  [<c029d0ba>] hub_thread+0x0/0x10e
Oct 22 21:45:05 kefk kernel:  [<c0102025>] kernel_thread_helper+0x5/0xb
Oct 22 21:45:05 kefk kernel: Code: 02 4c 32 c0 e9 4d ff ff ff e9 23 ff ff ff 
55 57 56 53 83 ec 04 8b 78 30 85 ff 74 0d 8b 07 85 c0 0f 84 ca 00 00 00 f0 ff 
07 85 ff <8b> 57 50 0f 84 b4 00 00 00 8b 47 10 8d 48 78 f0 ff 48 78 0f 88


After this, usb stack is unable to detect other usb devices insertions.

system: P IV 2.8 HT, smp/t+preempt, i875p (abit ic7g) 1Gb ram.
flash key: usb 2.0 flash drive, 512 MB

I can provide more details/testing if needed, config.gz attached.



-- 
Fabio Coatti       http://members.ferrara.linux.it/cova     
Ferrara Linux Users Group           http://ferrara.linux.it
GnuPG fp:9765 A5B6 6843 17BC A646  BE8C FA56 373A 5374 C703
Old SysOps never die... they simply forget their password.

[-- Attachment #2: config.gz --]
[-- Type: application/x-gzip, Size: 8300 bytes --]

Re: 2.6.9-mm1 usb oopses

[Pete Zaitcev]

On Fri, 22 Oct 2004 20:45:18 -0700, Andrew Morton <akpm@osdl.org> wrote:

> looks like a ub.c problem.

Yes. At least partially.

> Date: Fri, 22 Oct 2004 21:59:20 +0200
> From: Fabio Coatti <cova@ferrara.linux.it>

> Oct 22 21:40:05 kefk kernel: ub 5-3:1.0: usb_probe_interface - got id
> Oct 22 21:40:05 kefk kernel: uba: device 6 capacity nsec 50 bsize 512
> Oct 22 21:40:05 kefk kernel: uba: made changed
> Oct 22 21:40:05 kefk kernel: uba: device 6 capacity nsec 1024000 bsize 512
> Oct 22 21:40:05 kefk kernel: uba: device 6 capacity nsec 1024000 bsize 512
> Oct 22 21:40:05 kefk kernel:  uba: uba1
> Oct 22 21:40:05 kefk kernel:  uba: uba1
> Oct 22 21:40:05 kefk kernel: kobject_register failed for uba1 (-17)
> Oct 22 21:40:05 kefk kernel:  [<c01f1f77>] kobject_register+0x51/0x5f

This looks like a race, but isn't. What actually happens is that the ub
returns a device changed indication from check_media_changed when the
device is connected. In such case, do_open will make another attempt
to read partitions. I discussed it with Al and he opined that no block
device should ever return a changed indication before the first open
has completed. If it cannot, it should refuse the open.

This only happens to devices which refuse to come online easily. Therefore,
I was going to fold a fix into a patch to add START STOP UNIT command.
It is not written yet.

The other side of this, the oops, is something for Viro/James/Axboe
to check out. It's entirely on their side. But of course, if ub quits
tripping the double registration condition, the problem of buggy
error paths in the block layer becomes moot. I'll work on it as soon
as possible.

-- Pete