Bug 24872

Summary: usbip: several error messages when trying to detach on client side
Product: Drivers Reporter: Márton Németh (nm127)
Component: StagingAssignee: drivers_staging (drivers_staging)
Status: RESOLVED CODE_FIX    
Severity: normal CC: florian
Priority: P1    
Hardware: All   
OS: Linux   
Kernel Version: 2.6.37-rc5 Subsystem:
Regression: No Bisected commit-id:
Attachments: full dmesg captured via "netconsole"
2.6.36-rc5 kernel config used
2.6.37-rc5 kernel config used

Description Márton Németh 2010-12-13 18:02:23 UTC 
Created attachment 40042 [details]
full dmesg captured via "netconsole"

The following types of error messages appeared in dmesg when I tried to detach an USB device with "usbip -d 0" on client side (see http://usbip.sourceforge.net/#documentation for the interpretation of server/client side):

 - Slab corruption
 - scheduling while atomic
 - sleeping function called from invalid context

I executed this test on an EeePC 901 laptop. The steps to reproduce are the following:

First disable the internally built camera by executing the command "echo 0 >/sys/devices/platform/eeepc/camera".
Connect a hama AC-150 webcam to the USB port 3-2.
Open two xterms: one for the usbip server and one for the usbip client.

On server xterm:
----------------
# modprobe usbip
# usbip_bind_driver --list
List USB devices
 - busid 1-5 (058f:6335)
         1-5:1.0 -> usb-storage

 - busid 3-2 (0c45:6142)
         3-2:1.0 -> sonixj

 - busid 2-2 (1241:1503)
         2-2:1.0 -> usbhid
         2-2:1.1 -> usbhid

# usbip_bind_driver --usbip 3-2
** (process:1762): DEBUG:  3-2:1.0      -> sonixj 
** (process:1762): DEBUG: unbinding interface
** (process:1762): DEBUG: write "add 3-2" to /sys/bus/usb/drivers/usbip/match_busid
** Message: bind 3-2 to usbip, complete!
# usbipd
listen at [0.0.0.0]:3240
usbipd start (usbip 0.1.7 ($Id: stub_server.c 42 2007-09-07 12:07:51Z hirofuchi $))
connected from 127.0.0.1:56627
connected from 127.0.0.1:56628
connect 3-2

On the client xterm:
--------------------
# modprobe vhci-hcd
root@asus-eeepc:/home/nmarci# usbip --list localhost
- localhost
     3-2: Microdia : unknown product (0c45:6142)
        : /sys/devices/pci0000:00/0000:00:1d.1/usb3/3-2
        : (Defined at Interface level) (00/00/00)
        :  0 - Vendor Specific Class / Vendor Specific Subclass / Vendor Specific Protocol (ff/ff/ff)
 
# usbip -a localhost 3-2
8 ports available

port 0 attached
root@asus-eeepc:/home/nmarci# usbip -p
8 ports available

Port 00: <Port in Use> at Full Speed(12Mbps)
       Microdia : unknown product (0c45:6142)
       6-1 -> usbip://localhost:3240/3-2  (remote devid 00030002 (bus/dev 003/002))
       6-1:1.0 used by sonixj           
           /sys/devices/platform/vhci_hcd/usb6/6-1/6-1:1.0/video4linux/video0/device
Port 01: <Port Available>
Port 02: <Port Available>
Port 03: <Port Available>
Port 04: <Port Available>
Port 05: <Port Available>
Port 06: <Port Available>
Port 07: <Port Available>
# usbip -d 0

When executing the detach command then the followings appear in dmesg (for the full log captured via "netconsole" see the attached dmesg.txt): 

[  250.032863] usbip 3-2:1.0: recv a header, 0
[  250.032982] vhci_rx   : ***ERROR*** (drivers/staging/usbip/vhci_rx.c,210) vhci_rx_pdu: receiving pdu failed! size is 0, should be 48
[  250.033089] usbip: vhci_tx signal catched
[  250.033160] usbip: stop threads
[  250.033206] usbip: release socket
[  250.033233] usbip: changed 1
[  250.033276] usbip: disconnect device
[  250.033362] usb 6-1: USB disconnect, address 2
[  250.033781] usbip: vhci_hcd: dequeue a urb f5855090
[  250.033801] vhci_hcd vhci_hcd: Unlink after no-IRQ?  Controller is probably using the wrong IRQ.
[  250.033818] usbip: vhci_hcd: device f58821a8 seems to be disconnected
[  250.033835] usbip: vhci_hcd: vhci_urb_dequeue() gives back urb f5855090
[  250.033852] usbip: vhci_hcd: vhci_urb_dequeue() gives back urb f5855090
[  250.033873] gspca: video0 disconnect
[  250.033913] BUG: unable to handle kernel 
[  250.033931] Slab corruption: size-128 start=f5855090, len=128
[  250.033937] Redzone: 0x9f911029d74e35b/0x9f911029d74e35b.
[  250.033941] Last user: [<c121baf5>](urb_destroy+0x1b/0x1e)
[  250.033955] 000: 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6b 6c 6b 6b 6b
[  250.033979] Next obj: start=f5855128, len=128
[  250.033984] Redzone: 0xd84156c5635688c0/0xd84156c5635688c0.
[  250.033988] Last user: [<c12606e8>](sock_alloc_inode+0x36/0xf3)
[  250.033998] 000: 4e 4e 00 00 ad 4e ad de ff ff ff ff ff ff ff ff
[  250.034020] 010: 80 21 cd c1 00 00 00 00 00 00 00 00 88 dd 40 c1
[  250.035252] paging request at 6b6b6bf3
[  250.035361] IP: [<c1157c98>] kref_get+0x6/0x22
[  250.035489] *pde = 00000000 
[  250.035580] Oops: 0000 [#1] PREEMPT SMP 
[  250.035724] last sysfs file: /sys/devices/platform/vhci_hcd/detach
[  250.035867] Modules linked in: option usb_wwan usbserial vhci_hcd(C) gspca_sonixj gspca_main usbip(C) usbip_common_mod(C) i915 drm_kms_helper drm sco i2c_algo_bit bridge stp llc bnep rfcomm l2cap crc16 bluetooth ipv6 fuse cpufreq_ondemand acpi_cpufreq freq_table mperf loop snd_hda_codec_realtek snd_hda_intel snd_hda_codec snd_pcm snd_seq snd_timer snd_seq_device uvcvideo snd videodev rtc_cmos tpm_tis intel_agp v4l1_compat psmouse rtc_core intel_gtt soundcore i2c_core tpm tpm_bios serio_raw evdev rng_core uhci_hcd agpgart thermal snd_page_alloc processor rtc_lib video eeepc_laptop battery output ac button thermal_sys
[  250.036014] 
[  250.036014] Pid: 246, comm: khubd Tainted: G         C  2.6.37-rc5 #1 901/901
[  250.036014] EIP: 0060:[<c1157c98>] EFLAGS: 00010006 CPU: 0
[  250.036014] EIP is at kref_get+0x6/0x22
[  250.036014] EAX: 6b6b6bf3 EBX: 6b6b6bf3 ECX: c12ebd48 EDX: 6b6b6bcf
[  250.036014] ESI: 00000000 EDI: fffffffe EBP: f6a1bde4 ESP: f6a1bde0
[  250.036014]  DS: 007b ES: 007b FS: 00d8 GS: 0000 SS: 0068
[  250.036014] Process khubd (pid: 246, ti=f6a1a000 task=f6976a30 task.ti=f6a1a000)
[  250.036014] Stack:
[  250.036014]  6b6b6bd7 f6a1bdf0 c1156ec8 6b6b6b6b f6a1bdf8 c11d63de f6a1be04 c1215f36
[  250.036014]  f5855090 f6a1be1c c121b3ec 00000296 f5855090 f4033000 f62e097c f6a1be44
[  250.036014]  c121b5ff f40337fc f82686e1 f6976a30 f4033810 00000246 f5855090 f4033000
[  250.036014] Call Trace:
[  250.036014]  [<c1156ec8>] ? kobject_get+0x12/0x17
[  250.036014]  [<c11d63de>] ? get_device+0x13/0x18
[  250.036014]  [<c1215f36>] ? usb_get_dev+0x12/0x17
[  250.036014]  [<c121b3ec>] ? usb_hcd_unlink_urb+0x32/0x6e
[  250.036014]  [<c121b5ff>] ? usb_kill_urb+0x3c/0xa5
[  250.036014]  [<f82686e1>] ? gspca_disconnect+0x41/0xb9 [gspca_main]
[  250.036014]  [<f8267e9a>] ? gspca_input_destroy_urb+0x22/0x45 [gspca_main]
[  250.036014]  [<f8268717>] ? gspca_disconnect+0x77/0xb9 [gspca_main]
[  250.036014]  [<c121de31>] ? usb_unbind_interface+0x3e/0xb5
[  250.036014]  [<c11d8fd0>] ? __device_release_driver+0x50/0x8e
[  250.036014]  [<c11d90b7>] ? device_release_driver+0x1a/0x25
[  250.036014]  [<c11d8798>] ? bus_remove_device+0x81/0x91
[  250.036014]  [<c11d718a>] ? device_del+0xf8/0x153
[  250.036014]  [<c121bf2d>] ? usb_disable_device+0x3d/0xcd
[  250.036014]  [<c12180d4>] ? usb_disconnect+0x6e/0xe3
[  250.036014]  [<c1218d91>] ? hub_thread+0x33d/0xb5c
[  250.036014]  [<c104dc5b>] ? autoremove_wake_function+0x0/0x2f
[  250.036014]  [<c1218a54>] ? hub_thread+0x0/0xb5c
[  250.036014]  [<c104d8c6>] ? kthread+0x62/0x67
[  250.036014]  [<c104d864>] ? kthread+0x0/0x67
[  250.036014]  [<c10036ba>] ? kernel_thread_helper+0x6/0x1a
[  250.036014] Code: 00 00 b8 f1 6e 3f c1 e8 83 e1 ed ff f0 ff 0b 0f 94 c2 31 c0 84 d2 74 09 89 d8 ff d6 b8 01 00 00 00 5b 5e 5d c3 55 89 e5 53 89 c3 <8b> 00 85 c0 75 0f ba 22 00 00 00 b8 f1 6e 3f c1 e8 4f e1 ed ff 
[  250.036014] EIP: [<c1157c98>] kref_get+0x6/0x22 SS:ESP 0068:f6a1bde0
[  250.036014] CR2: 000000006b6b6bf3
[  250.036014] BUG: scheduling while atomic: khubd/246/0x00000002
[  250.036014] INFO: lockdep is turned off.
[  250.036014] Modules linked in: option usb_wwan usbserial vhci_hcd(C) gspca_sonixj gspca_main usbip(C) usbip_common_mod(C) i915 drm_kms_helper drm sco i2c_algo_bit bridge stp llc bnep rfcomm l2cap crc16 bluetooth ipv6 fuse cpufreq_ondemand acpi_cpufreq freq_table mperf loop snd_hda_codec_realtek snd_hda_intel snd_hda_codec snd_pcm snd_seq snd_timer snd_seq_device uvcvideo snd videodev rtc_cmos tpm_tis intel_agp v4l1_compat psmouse rtc_core intel_gtt soundcore i2c_core tpm tpm_bios serio_raw evdev rng_core uhci_hcd agpgart thermal snd_page_alloc processor rtc_lib video eeepc_laptop battery output ac button thermal_sys
[  250.036014] irq event stamp: 16072
[  250.036014] hardirqs last  enabled at (16071): [<c1084e22>] rcu_note_context_switch+0x152/0x162
[  250.036014] hardirqs last disabled at (16072): [<c12ebc92>] _raw_spin_lock_irq+0x12/0x63
[  250.036014] softirqs last  enabled at (15478): [<c127bfdb>] sk_filter+0x9a/0xa7
[  250.036014] softirqs last disabled at (15476): [<c127bf5f>] sk_filter+0x1e/0xa7
[  250.036014] Pid: 246, comm: khubd Tainted: G         C  2.6.37-rc5 #1
[  250.036014] Call Trace:
[  250.036014]  [<c102cb04>] __schedule_bug+0x62/0x69
[  250.036014]  [<c12e9377>] schedule+0xb2/0x99e
[  250.036014]  [<c105e24c>] ? print_lock_contention_bug+0x11/0xb2
[  250.036014]  [<c104129b>] ? lock_timer_base+0x21/0x40
[  250.036014]  [<c12ea02f>] schedule_timeout+0x1e5/0x202
[  250.036014]  [<c104141d>] ? process_timeout+0x0/0xa
[  250.036014]  [<c12ea061>] schedule_timeout_uninterruptible+0x15/0x17
[  250.036014]  [<c104189a>] msleep+0x10/0x16
[  250.036014]  [<f88e08b7>] intel_wait_for_vblank+0x8d/0xd4 [i915]
[  250.036014]  [<f88e8330>] intel_crtc_mode_set+0x18d1/0x1997 [i915]
[  250.036014]  [<f88de0e8>] ? intel_update_watermarks+0x10e/0x119 [i915]
[  250.036014]  [<f872064c>] drm_crtc_helper_set_mode+0x230/0x361 [drm_kms_helper]
[  250.036014]  [<f8720e9a>] drm_crtc_helper_set_config+0x548/0x72d [drm_kms_helper]
[  250.036014]  [<f871f2b4>] drm_fb_helper_pan_display+0x61/0x9a [drm_kms_helper]
[  250.036014]  [<c117b1d8>] fb_pan_display+0xc7/0x10b
[  250.036014]  [<c1186cd2>] bit_update_start+0x15/0x37
[  250.036014]  [<c1184230>] fbcon_switch+0x4a5/0x4aa
[  250.036014]  [<c11c6dff>] redraw_screen+0xe4/0x1b5
[  250.036014]  [<c1183cf9>] fbcon_blank+0x1f2/0x284
[  250.036014]  [<c1051eb8>] ? up+0xc/0x2f
[  250.036014]  [<c104129b>] ? lock_timer_base+0x21/0x40
[  250.036014]  [<c105e24c>] ? print_lock_contention_bug+0x11/0xb2
[  250.036014]  [<c1041bec>] ? mod_timer+0x1a2/0x1e1
[  250.036014]  [<c105e24c>] ? print_lock_contention_bug+0x11/0xb2
[  250.036014]  [<c1041bec>] ? mod_timer+0x1a2/0x1e1
[  250.036014]  [<c12ec557>] ? _raw_spin_unlock_irqrestore+0x61/0x65
[  250.036014]  [<c1041c20>] ? mod_timer+0x1d6/0x1e1
[  250.036014]  [<c11c6fb6>] do_unblank_screen+0xe6/0x14c
[  250.036014]  [<c11c7026>] unblank_screen+0xa/0xc
[  250.036014]  [<c115e618>] bust_spinlocks+0x14/0x30
[  250.036014]  [<c1005dd7>] oops_end+0x2d/0xa0
[  250.036014]  [<c101f95f>] no_context+0x110/0x11a
[  250.036014]  [<c101fa5f>] __bad_area_nosemaphore+0xf6/0xfe
[  250.036014]  [<c101fb9b>] ? do_page_fault+0x0/0x366
[  250.036014]  [<c101fa74>] bad_area_nosemaphore+0xd/0x10
[  250.036014]  [<c101fd15>] do_page_fault+0x17a/0x366
[  250.036014]  [<c127ebcc>] ? netpoll_send_udp+0x1be/0x1c6
[  250.036014]  [<c12ec544>] ? _raw_spin_unlock_irqrestore+0x4e/0x65
[  250.036014]  [<c1051eb8>] ? up+0xc/0x2f
[  250.036014]  [<c101fb9b>] ? do_page_fault+0x0/0x366
[  250.036014]  [<c12ecf9b>] error_code+0x5f/0x64
[  250.036014]  [<c12ebd48>] ? _raw_spin_lock_irqsave+0x65/0x6f
[  250.036014]  [<c101fb9b>] ? do_page_fault+0x0/0x366
[  250.036014]  [<c1157c98>] ? kref_get+0x6/0x22
[  250.036014]  [<c1156ec8>] kobject_get+0x12/0x17
[  250.036014]  [<c11d63de>] get_device+0x13/0x18
[  250.036014]  [<c1215f36>] usb_get_dev+0x12/0x17
[  250.036014]  [<c121b3ec>] usb_hcd_unlink_urb+0x32/0x6e
[  250.036014]  [<c121b5ff>] usb_kill_urb+0x3c/0xa5
[  250.036014]  [<f82686e1>] ? gspca_disconnect+0x41/0xb9 [gspca_main]
[  250.036014]  [<f8267e9a>] gspca_input_destroy_urb+0x22/0x45 [gspca_main]
[  250.036014]  [<f8268717>] gspca_disconnect+0x77/0xb9 [gspca_main]
[  250.036014]  [<c121de31>] usb_unbind_interface+0x3e/0xb5
[  250.036014]  [<c11d8fd0>] __device_release_driver+0x50/0x8e
[  250.036014]  [<c11d90b7>] device_release_driver+0x1a/0x25
[  250.036014]  [<c11d8798>] bus_remove_device+0x81/0x91
[  250.036014]  [<c11d718a>] device_del+0xf8/0x153
[  250.036014]  [<c121bf2d>] usb_disable_device+0x3d/0xcd
[  250.036014]  [<c12180d4>] usb_disconnect+0x6e/0xe3
[  250.036014]  [<c1218d91>] hub_thread+0x33d/0xb5c
[  250.036014]  [<c104dc5b>] ? autoremove_wake_function+0x0/0x2f
[  250.036014]  [<c1218a54>] ? hub_thread+0x0/0xb5c
[  250.036014]  [<c104d8c6>] kthread+0x62/0x67
[  250.036014]  [<c104d864>] ? kthread+0x0/0x67
[  250.036014]  [<c10036ba>] kernel_thread_helper+0x6/0x1a
[  250.358234] usbip: stopped by a call of usb_kill_urb() because ofcleaning up a virtual connection
[  250.383821] ---[ end trace 1133173d5c05f650 ]---
[  250.383834] note: khubd[246] exited with preempt_count 1
[  250.383858] BUG: sleeping function called from invalid context at kernel/mutex.c:278
[  250.383868] in_atomic(): 1, irqs_disabled(): 0, pid: 246, name: khubd
[  250.383874] INFO: lockdep is turned off.
[  250.383884] Pid: 246, comm: khubd Tainted: G      D  C  2.6.37-rc5 #1
[  250.383891] Call Trace:
[  250.383911]  [<c102b504>] __might_sleep+0x101/0x109
[  250.383926]  [<c12eac34>] mutex_lock_nested+0x1e/0x2e9
[  250.383940]  [<c1071ec8>] ? cgroup_exit+0x87/0xb3
[  250.383954]  [<c109e3bd>] perf_event_exit_task+0x1b/0x1ae
[  250.383967]  [<c1039212>] do_exit+0x263/0x617
[  250.383978]  [<c1036a3c>] ? kmsg_dump+0x115/0x12a
[  250.383993]  [<c1005e42>] oops_end+0x98/0xa0
[  250.384011]  [<c101f95f>] no_context+0x110/0x11a
[  250.384012]  [<c101fa5f>] __bad_area_nosemaphore+0xf6/0xfe
[  250.384012]  [<c101fb9b>] ? do_page_fault+0x0/0x366
[  250.384012]  [<c101fa74>] bad_area_nosemaphore+0xd/0x10
[  250.384012]  [<c101fd15>] do_page_fault+0x17a/0x366
[  250.384012]  [<c127ebcc>] ? netpoll_send_udp+0x1be/0x1c6
[  250.384012]  [<c12ec544>] ? _raw_spin_unlock_irqrestore+0x4e/0x65
[  250.384012]  [<c1051eb8>] ? up+0xc/0x2f
[  250.384012]  [<c101fb9b>] ? do_page_fault+0x0/0x366
[  250.384012]  [<c12ecf9b>] error_code+0x5f/0x64
[  250.384012]  [<c12ebd48>] ? _raw_spin_lock_irqsave+0x65/0x6f
[  250.384012]  [<c101fb9b>] ? do_page_fault+0x0/0x366
[  250.384012]  [<c1157c98>] ? kref_get+0x6/0x22
[  250.384012]  [<c1156ec8>] kobject_get+0x12/0x17
[  250.384012]  [<c11d63de>] get_device+0x13/0x18
[  250.384227]  [<c1215f36>] usb_get_dev+0x12/0x17
[  250.384240]  [<c121b3ec>] usb_hcd_unlink_urb+0x32/0x6e
[  250.384251]  [<c121b5ff>] usb_kill_urb+0x3c/0xa5
[  250.384271]  [<f82686e1>] ? gspca_disconnect+0x41/0xb9 [gspca_main]
[  250.384288]  [<f8267e9a>] gspca_input_destroy_urb+0x22/0x45 [gspca_main]
[  250.384303]  [<f8268717>] gspca_disconnect+0x77/0xb9 [gspca_main]
[  250.384316]  [<c121de31>] usb_unbind_interface+0x3e/0xb5
[  250.384330]  [<c11d8fd0>] __device_release_driver+0x50/0x8e
[  250.384343]  [<c11d90b7>] device_release_driver+0x1a/0x25
[  250.384379]  [<c11d8798>] bus_remove_device+0x81/0x91
[  250.384391]  [<c11d718a>] device_del+0xf8/0x153
[  250.384403]  [<c121bf2d>] usb_disable_device+0x3d/0xcd
[  250.384415]  [<c12180d4>] usb_disconnect+0x6e/0xe3
[  250.384426]  [<c1218d91>] hub_thread+0x33d/0xb5c
[  250.384444]  [<c104dc5b>] ? autoremove_wake_function+0x0/0x2f
[  250.384456]  [<c1218a54>] ? hub_thread+0x0/0xb5c
[  250.384467]  [<c104d8c6>] kthread+0x62/0x67
[  250.384481]  [<c104d864>] ? kthread+0x0/0x67
[  250.384493]  [<c10036ba>] kernel_thread_helper+0x6/0x1a
[  250.472091] usb 3-2: reset full speed USB device using uhci_hcd and address 2
[  250.618881] usbip 3-2:1.0: USB/IP Stub: register a new interface (bus 3 dev 2 ifn 0)
[  250.618931] usb 3-2: device reset
Comment 1 Márton Németh 2010-12-13 18:04:57 UTC 
Created attachment 40052 [details]
2.6.36-rc5 kernel config used
Comment 2 Márton Németh 2010-12-13 18:13:00 UTC 
Created attachment 40062 [details]
2.6.37-rc5 kernel config used

(Sorry, the previous attachement had a typo in version number.)
Comment 3 Greg Kroah-Hartman 2010-12-13 18:13:42 UTC 
On Mon, Dec 13, 2010 at 06:02:25PM +0000, bugzilla-daemon@bugzilla.kernel.org wrote:
> https://bugzilla.kernel.org/show_bug.cgi?id=24872
> 
>            Summary: usbip: several error messages when trying to detach on
>                     client side

There are several issues like this in the usbip drivers, which is why
they are still in the staging directory.

Any help in resolving them is most appreciated, otherwise they are
probably going to remain in this state as there are no active developers
for the code :(
Comment 4 Florian Mickler 2011-01-22 12:28:51 UTC 
fix for this issue was commited in .38-rc1:

commit 7571f089d7522a95c103558faf313c7af8856ceb
Author: Márton Németh <nm127@freemail.hu>
Date:   Mon Dec 13 21:59:09 2010 +0100

    staging: usbip: remove double giveback of URB