Bug 1976
| Summary: | USB speedtch unplugging causes oops (in modem_run?) | ||
|---|---|---|---|
| Product: | Drivers | Reporter: | Sampo Kellom (sampo) |
| Component: | USB | Assignee: | baldrick (baldrick) |
| Status: | REJECTED INSUFFICIENT_DATA | ||
| Severity: | normal | CC: | greg, nacc, tal00r |
| Priority: | P2 | ||
| Hardware: | i386 | ||
| OS: | Linux | ||
| Kernel Version: | 2.6.1 | Subsystem: | |
| Regression: | --- | Bisected commit-id: | |
| Bug Depends on: | |||
| Bug Blocks: | 5089 | ||
|
Description
Sampo Kellom
2004-01-30 14:39:04 UTC
*** Bug 1977 has been marked as a duplicate of this bug. *** *** Bug 1978 has been marked as a duplicate of this bug. *** *** Bug 1979 has been marked as a duplicate of this bug. *** Here's another similar oops on the same machine. This time I had killed pppd and br2684ctl, but forgot to kill modem_run before unplugging. Feb 2 12:36:47 mju pppd[1958]: Terminating on signal 15. Feb 2 12:36:47 mju pppd[1958]: Couldn't increase MTU to 1500 Feb 2 12:36:47 mju pppd[1958]: Couldn't increase MRU to 1500 Feb 2 12:36:47 mju pppd[1958]: Connection terminated. Feb 2 12:36:47 mju pppd[1958]: Connect time 353.7 minutes. Feb 2 12:36:47 mju pppd[1958]: Sent 16240 bytes, received 16620 bytes. Feb 2 12:36:47 mju /etc/hotplug/net.agent: NET remove event not supported Feb 2 12:36:47 mju pppd[1958]: Connect time 353.7 minutes. Feb 2 12:36:47 mju pppd[1958]: Sent 16240 bytes, received 16620 bytes. Feb 2 12:36:47 mju pppd[1958]: Exit. Feb 2 12:37:02 mju /etc/hotplug/net.agent: NET remove event not supported Feb 2 12:37:11 mju kernel: ohci_hcd 0000:00:14.0: urb cadc1ec0 path 1 ep1in 5e160000 cc 5 --> status -110 Feb 2 12:37:11 mju kernel: ohci_hcd 0000:00:14.0: urb cadc1f20 path 1 ep7in 5f160000 cc 5 --> status -110 Feb 2 12:37:11 mju kernel: ohci_hcd 0000:00:14.0: urb cadc1c80 path 1 ep7in 5f160000 cc 5 --> status -110 Feb 2 12:37:11 mju modem_run[1887]: Error reading interrupts Feb 2 12:37:12 mju kernel: ohci_hcd 0000:00:14.0: urb cadc1ec0 path 1 ep0in 5ec20000 cc 5 --> status -110 Feb 2 12:37:12 mju kernel: usbfs: USBDEVFS_CONTROL failed cmd modem_run dev 2 rqt 192 rq 18 len 1 ret -110 Feb 2 12:37:12 mju kernel: ohci_hcd 0000:00:14.0: urb cadc1ec0 path 1 ep1in 5e160000 cc 5 --> status -110 Feb 2 12:37:12 mju modem_run[1887]: Error reading interrupts Feb 2 12:37:12 mju kernel: ohci_hcd 0000:00:14.0: urb cadc1ec0 path 1 ep0in 5ec20000 cc 5 --> status -110 Feb 2 12:37:12 mju kernel: usbfs: USBDEVFS_CONTROL failed cmd modem_run dev 2 rqt 192 rq 18 len 1 ret -110 Feb 2 12:37:12 mju modem_run[1887]: Error reading interrupts Feb 2 12:37:12 mju kernel: ohci_hcd 0000:00:14.0: urb cadc1ec0 path 1 ep1in 5e160000 cc 5 --> status -110 Feb 2 12:37:12 mju kernel: ohci_hcd 0000:00:14.0: urb cadc1ec0 path 1 ep0in 5ec20000 cc 5 --> status -110 Feb 2 12:37:12 mju kernel: ohci_hcd 0000:00:14.0: GetStatus roothub.portstatus [1] = 0x00030100 PESC CSC PPS Feb 2 12:37:12 mju modem_run[1887]: Device disconnected, shutting down Feb 2 12:37:12 mju kernel: hub 2-0:1.0: port 1, status 100, change 3, 12 Mb/s Feb 2 12:37:12 mju /etc/hotplug/usb.agent: Bad USB agent invocation (prod=, act=remove) Feb 2 12:37:12 mju kernel: usb 2-1: USB disconnect, address 2 Feb 2 12:37:12 mju kernel: usb 2-1: usb_disable_device nuking all URBs Feb 2 12:37:12 mju kernel: usb 2-1: unregistering interface 2-1:1.0 Feb 2 12:37:12 mju kernel: drivers/usb/core/usb.c: usb_hotplug Feb 2 12:37:12 mju kernel: usbfs: USBDEVFS_CONTROL failed cmd modem_run dev 2 rqt 192 rq 18 len 1 ret -110 Feb 2 12:37:12 mju kernel: usbfs: usb_submit_urb returned -19 Feb 2 12:37:12 mju kernel: usb 2-1: unregistering interface 2-1:1.1 Feb 2 12:37:12 mju kernel: usb 2-1: hcd_unlink_urb cadc1f20 fail -22 Feb 2 12:37:12 mju kernel: usb 2-1: hcd_unlink_urb cadc1c80 fail -22 Feb 2 12:37:12 mju kernel: usb 2-1: hcd_unlink_urb ca665960 fail -22 Feb 2 12:37:12 mju kernel: usb 2-1: hcd_unlink_urb cadc10e0 fail -22 Feb 2 12:37:12 mju kernel: drivers/usb/core/usb.c: usb_hotplug Feb 2 12:37:12 mju kernel: usb 2-1: unregistering interface 2-1:1.2 Feb 2 12:37:12 mju kernel: drivers/usb/core/usb.c: usb_hotplug Feb 2 12:37:12 mju kernel: usb 2-1: unregistering device Feb 2 12:37:12 mju kernel: drivers/usb/core/usb.c: usb_hotplug Feb 2 12:37:12 mju kernel: Unable to handle kernel NULL pointer dereference at virtual address 0000000c Feb 2 12:37:13 mju kernel: printing eip: Feb 2 12:37:13 mju kernel: cfad34f3 Feb 2 12:37:13 mju kernel: *pde = 00000000 Feb 2 12:37:13 mju kernel: Oops: 0000 [#1] Feb 2 12:37:13 mju kernel: CPU: 0 Feb 2 12:37:13 mju kernel: EIP: 0060:[<cfad34f3>] Not tainted Feb 2 12:37:13 mju kernel: EFLAGS: 00010206 Feb 2 12:37:13 mju kernel: EIP is at releaseintf+0x41/0x66 [usbcore] Feb 2 12:37:13 mju kernel: eax: 0000000c ebx: c13c7400 ecx: c13c7424 edx: 00000000 Feb 2 12:37:13 mju kernel: esi: c13c7424 edi: ffffffea ebp: cadc17a0 esp: ca261f20 Feb 2 12:37:13 mju kernel: ds: 007b es: 007b ss: 0068 Feb 2 12:37:13 mju kernel: Process modem_run (pid: 1887, threadinfo=ca260000 task=ca4f6d40) Feb 2 12:37:13 mju kernel: Stack: cadc17a0 00000000 ceff4ae0 ca2f4b60 cfad37bd cadc17a0 00000000 ca2eede0 Feb 2 12:37:13 mju kernel: ca2f27a0 c0147c14 ca2f27a0 ca2eede0 ca2eede0 00000000 ca477de0 00000001 Feb 2 12:37:13 mju kernel: c0147bd8 c0146965 ca2eede0 ca477de0 ca2eede0 ca477de0 00000001 ca477de0 Feb 2 12:37:13 mju kernel: Call Trace: Feb 2 12:37:13 mju kernel: [<cfad37bd>] usbdev_release+0x37/0x61 [usbcore] Feb 2 12:37:13 mju kernel: [<c0147c14>] __fput+0x3b/0xdc Feb 2 12:37:13 mju kernel: [<c0147bd8>] fput+0x13/0x14 Feb 2 12:37:13 mju kernel: [<c0146965>] filp_close+0x5f/0x68 Feb 2 12:37:13 mju kernel: [<c011d7ba>] put_files_struct+0x4c/0xb2 Feb 2 12:37:13 mju kernel: [<c011e1ad>] do_exit+0x188/0x2d8 Feb 2 12:37:13 mju kernel: [<c011e322>] next_thread+0x0/0x1f Feb 2 12:37:13 mju kernel: [<c0108c8b>] syscall_call+0x7/0xb Feb 2 12:37:13 mju kernel: Feb 2 12:37:13 mju kernel: Code: 8b 04 90 50 68 c0 1c ae cf e8 9d 7d ff ff 31 ff 83 c4 08 89 Feb 2 12:37:13 mju kernel: <7>ohci_hcd 0000:00:14.0: GetStatus roothub.portstatus [1] = 0x00020100 PESC PPS Feb 2 12:37:13 mju kernel: hub 2-0:1.0: port 1 enable change, status 100 --Sampo Still a problem on 2.6.3? I'm not the original reporter, but I'm seeing the same problem on 2.6.5.
I get the crash using uhci_hcd, but not with usb-uhci.
The first few times, the machine locked solid (even SysRq didn't work). When it
happened when I wasn't in X, I saw it was trying to dump a continuous stack
trace to the console. I limited the number of items a stack trace could contain,
and added a call to panic() in do_IRQ after printing the trace (the <1K stack
space check was triggering it). The section on the screen (copied by hand) was:
mm_release +35
do_exit + ba
die + b6
do_page_fault + 327
do_page_fault + 0
scheduler_tick + 6d
update_process_times + 2c
update_wall_time +d
do_timer +4d
rcu_process_callbacks +c3
tasklet_action +41
error_code +2d
mm_release +35
do_exit +ba
die +b6
do_page_fault +327
do_page_fault +0
mod_timer +44
i8042_timer_func +0
i8042_interrupt +22
i8042_timer_func +0
Looking in do_exit (__exit_mm), it seemed it was calling mm_release with mm=NULL.
mm_release(tsk, mm);
if (!mm)
return;
This was causing a futher page fault in atomic_read in mm_release:
if (tsk->clear_child_tid && atomic_read(&mm->mm_users) > 1) {
Returning earlier if mm was NULL stopped the complete lockups.
After that, I got the trace reported above (usbdev_release in the modem_run
process).
I also saw these messages at various times:
vcc_sock_destruct: wmem leakage (1800 bytes) detected.
Apr 9 11:29:56 sue kernel: usb 1-1.5: bulk timeout on ep5in
Apr 9 11:29:56 sue kernel: usbfs: USBDEVFS_BULK failed dev 7 ep 0x85 len 512
ret -110
I only have access to this machine for a couple more days (I'm visiting my
parents), so if you want me to try anything ask soon!
(the reason for wanting to unplug the modem is that it frequently fails to
connect, despite working fine from Windows, but these hard-lockups are annoying
while trying to track that down)
> After that, I got the trace reported above (usbdev_release in the modem_run process). usbfs has a number of issues that I'm working on right now. Try killing modem_run before unplugging the modem. Does it make any difference? > vcc_sock_destruct: wmem leakage (1800 bytes) detected. Yes, there is a memory leak when you try to send packets when the modem is disconnected. This is fixed in the CVS version of the kernel module at http:// linux-usb.sf.net/SpeedTouch I doubt this is the reason for the panic though. > I only have access to this machine for a couple more days (I'm visiting my > parents), so if you want me to try anything ask soon! Does it work with earlier versions of the 2.6 kernel? Does it work with 2.4. > (the reason for wanting to unplug the modem is that it frequently fails to > connect, despite working fine from Windows, but these hard-lockups are > annoying while trying to track that down) What kind of error messages do you get when it fails to connect? You need to launch the connection after the firmware has been uploaded. This may require sleeping for 20 seconds after launching modem_run. Ciao, Duncan. OK, the crash in releaseintf is caused by dev->actconfig being NULL. I added an
assertion which triggers when you unplug the modem:
if (test_and_clear_bit(intf, &ps->ifclaimed)) {
BUG_ON(dev->actconfig == NULL);
Not sure if I should just ignore this case, or what.
As for not connecting, it looks like this:
Apr 10 11:35:52 sue modem_run[3466]: [monitoring report] ADSL link went up
Apr 10 11:36:03 sue modem_run[3266]: ADSL synchronization has been obtained
Apr 10 11:36:03 sue modem_run[3266]: ADSL line is up (576 kbit/s down | 288
kbit/s up)
Apr 10 11:36:26 sue modem_run[3466]: [monitoring report] ADSL link went down
Apr 10 11:36:46 sue modem_run[3466]: [monitoring report] ADSL link went up
Apr 10 11:36:56 sue modem_run[3466]: [monitoring report] ADSL link went down
Apr 10 11:38:09 sue modem_run[3466]: [monitoring report] ADSL link went up
Apr 10 11:38:59 sue modem_run[3466]: [monitoring report] ADSL link went down
Apr 10 11:40:03 sue modem_run[3466]: [monitoring report] ADSL link went up
Apr 10 11:40:28 sue modem_run[3466]: [monitoring report] ADSL link went down
Apr 10 11:40:44 sue modem_run[3466]: [monitoring report] ADSL link went up
Apr 10 11:41:05 sue modem_run[3466]: [monitoring report] ADSL link went down
Apr 10 11:42:30 sue modem_run[3466]: [monitoring report] ADSL link went up
Apr 10 11:42:47 sue modem_run[3466]: [monitoring report] ADSL link went down
Apr 10 11:43:04 sue modem_run[3466]: [monitoring report] ADSL link went up
(Not sure about the different PIDs... maybe an old instance of modem_run was
monitoring the new line? However, it still goes up and down like this after a
clean boot.)
pppd keeps trying to connect, and is often successful if it tries while the line
is up:
Apr 10 11:36:08 sue pppd[3685]: Plugin /usr/lib/pppd/2.4.2b3/pppoatm.so loaded.
Apr 10 11:36:08 sue pppd[3685]: PPPoATM plugin_init
Apr 10 11:36:08 sue pppd[3685]: PPPoATM setdevname - remove unwanted options
Apr 10 11:36:08 sue pppd[3685]: PPPoATM setdevname_pppoatm - SUCCESS:0.38
Apr 10 11:36:08 sue pppd[3686]: pppd 2.4.2b3 started by root, uid 0
Apr 10 11:36:08 sue pppd[3686]: Using interface ppp0
Apr 10 11:36:08 sue pppd[3686]: Connect: ppp0 <--> 0.38
Apr 10 11:36:38 sue pppd[3686]: LCP: timeout sending Config-Requests
Apr 10 11:36:38 sue pppd[3686]: Connection terminated.
Apr 10 11:36:42 sue pppd[3686]: Using interface ppp0
Apr 10 11:36:42 sue pppd[3686]: Connect: ppp0 <--> 0.38
Apr 10 11:36:49 sue pppd[3686]: CHAP authentication succeeded
Apr 10 11:36:49 sue pppd[3686]: local IP address 80.177....
Apr 10 11:36:49 sue pppd[3686]: remote IP address 217.47....
Apr 10 11:37:04 sue pppd[3686]: No response to 7 echo-requests
Apr 10 11:37:04 sue pppd[3686]: Serial link appears to be disconnected.
Apr 10 11:37:10 sue pppd[3686]: Connection terminated.
Apr 10 11:37:10 sue pppd[3686]: Connect time 0.4 minutes.
Apr 10 11:37:10 sue pppd[3686]: Sent 177 bytes, received 164 bytes.
Apr 10 11:37:14 sue pppd[3686]: Using interface ppp0
Apr 10 11:37:14 sue pppd[3686]: Connect: ppp0 <--> 0.38
Apr 10 11:37:44 sue pppd[3686]: LCP: timeout sending Config-Requests
Apr 10 11:37:44 sue pppd[3686]: Connection terminated.
Apr 10 11:37:44 sue pppd[3686]: Connect time 0.4 minutes.
Apr 10 11:37:44 sue pppd[3686]: Sent 177 bytes, received 164 bytes.
Apr 10 11:37:49 sue pppd[3686]: Using interface ppp0
Apr 10 11:37:49 sue pppd[3686]: Connect: ppp0 <--> 0.38
Apr 10 11:38:30 sue pppd[3686]: No response to 7 echo-requests
Apr 10 11:38:30 sue pppd[3686]: Serial link appears to be disconnected.
Apr 10 11:38:36 sue pppd[3686]: Connection terminated.
Apr 10 11:38:36 sue pppd[3686]: Connect time 0.4 minutes.
Apr 10 11:38:36 sue pppd[3686]: Sent 177 bytes, received 164 bytes.
Apr 10 11:38:40 sue pppd[3686]: Using interface ppp0
Apr 10 11:38:40 sue pppd[3686]: Connect: ppp0 <--> 0.38
Apr 10 11:39:06 sue pppd[3686]: No response to 7 echo-requests
Apr 10 11:39:06 sue pppd[3686]: Serial link appears to be disconnected.
Apr 10 11:39:12 sue pppd[3686]: Connection terminated.
Apr 10 11:39:12 sue pppd[3686]: Connect time 0.4 minutes.
Apr 10 11:39:12 sue pppd[3686]: Sent 177 bytes, received 164 bytes.
Apr 10 11:39:16 sue pppd[3686]: Using interface ppp0
Apr 10 11:39:16 sue pppd[3686]: Connect: ppp0 <--> 0.38
Apr 10 11:39:46 sue pppd[3686]: LCP: timeout sending Config-Requests
Apr 10 11:39:46 sue pppd[3686]: Connection terminated.
Apr 10 11:39:46 sue pppd[3686]: Connect time 0.4 minutes.
Apr 10 11:39:46 sue pppd[3686]: Sent 177 bytes, received 164 bytes.
Apr 10 11:39:50 sue pppd[3686]: Using interface ppp0
Apr 10 11:39:50 sue pppd[3686]: Connect: ppp0 <--> 0.38
Apr 10 11:40:08 sue pppd[3686]: CHAP authentication succeeded
Apr 10 11:40:08 sue pppd[3686]: local IP address 80.177...
Apr 10 11:40:08 sue pppd[3686]: remote IP address 217.47...
Apr 10 11:40:26 sue pppd[3686]: No response to 7 echo-requests
Apr 10 11:40:26 sue pppd[3686]: Serial link appears to be disconnected.
Apr 10 11:40:32 sue pppd[3686]: Connection terminated.
Apr 10 11:40:32 sue pppd[3686]: Connect time 0.6 minutes.
Apr 10 11:40:32 sue pppd[3686]: Sent 311 bytes, received 164 bytes.
Apr 10 11:40:36 sue pppd[3686]: Using interface ppp0
Apr 10 11:40:36 sue pppd[3686]: Connect: ppp0 <--> 0.38
Apr 10 11:41:06 sue pppd[3686]: LCP: timeout sending Config-Requests
Apr 10 11:41:06 sue pppd[3686]: Connection terminated.
Apr 10 11:41:06 sue pppd[3686]: Connect time 0.6 minutes.
Apr 10 11:41:06 sue pppd[3686]: Sent 311 bytes, received 164 bytes.
Apr 10 11:41:10 sue pppd[3686]: Using interface ppp0
Apr 10 11:41:10 sue pppd[3686]: Connect: ppp0 <--> 0.38
Apr 10 11:41:40 sue pppd[3686]: LCP: timeout sending Config-Requests
Apr 10 11:41:40 sue pppd[3686]: Connection terminated.
Apr 10 11:41:40 sue pppd[3686]: Connect time 0.6 minutes.
Apr 10 11:41:40 sue pppd[3686]: Sent 311 bytes, received 164 bytes.
Apr 10 11:41:44 sue pppd[3686]: Using interface ppp0
Apr 10 11:41:44 sue pppd[3686]: Connect: ppp0 <--> 0.38
Apr 10 11:42:14 sue pppd[3686]: LCP: timeout sending Config-Requests
Apr 10 11:42:14 sue pppd[3686]: Connection terminated.
Apr 10 11:42:14 sue pppd[3686]: Connect time 0.6 minutes.
Apr 10 11:42:14 sue pppd[3686]: Sent 311 bytes, received 164 bytes.
Apr 10 11:42:18 sue pppd[3686]: Using interface ppp0
Apr 10 11:42:18 sue pppd[3686]: Connect: ppp0 <--> 0.38
Apr 10 11:42:48 sue pppd[3686]: LCP: timeout sending Config-Requests
Apr 10 11:42:48 sue pppd[3686]: Connection terminated.
Apr 10 11:42:48 sue pppd[3686]: Connect time 0.6 minutes.
Apr 10 11:42:48 sue pppd[3686]: Sent 311 bytes, received 164 bytes.
Apr 10 11:42:52 sue pppd[3686]: Using interface ppp0
Apr 10 11:42:52 sue pppd[3686]: Connect: ppp0 <--> 0.38
Apr 10 11:43:07 sue pppd[3686]: CHAP authentication succeeded
Apr 10 11:43:07 sue pppd[3686]: local IP address 80.177...
Apr 10 11:43:07 sue pppd[3686]: remote IP address 217.47...
(that last connection stayed up and I'm using it to write this)
Is there any update on the status of this issue with later kernels? 2.6.9/10-rc*? this has been fixed for a log time now, right? If the submitter doesn't update the bug by the end of April 2005 I'll suggest closing this bug out. Thanks David, I'll keep my eye on it and close it when appropriate. Closing due to age. |