Bug 1978

Distribution: Self made

Hardware Environment:
Sony Vaio Piturebook PCG-C1MSX
Thomson SpeedTouch 330 USB ADSL modem

Software Environment: 
speedbundle-1.0 (includes modem_run version 1.2-beta2)
firmware.bin (the Macintosh firmware from somewhere in the 'Net)
pppd version 2.4.2 (i.e. NOT the one distributed with speedbundle)
brctl-010226.c (quite dated, is there a better version available anywhere?)
libc-2.2.5
module-init-tools-0.9.10
ochi

Problem Description:

1. Oopses as follows when I unplugh the ADSL modem "on the fly", i.e. without
   shutting down pppd or br2684ctl or modem_run. After the Oops the
   machine stays semi usable and it is possible to cleanly shut down most
   apps before more Oopses happen and block the machine, after which
   only Alt-SysRq works.

2. sleep between ifconfig and pppd (see reproduction) apparently is needed to
prevent kernel
   from hanging (or becoming "unresponsive"). Alt-SysRq still works. I have
   not investigated this problem further since the workaround was easy.

Jan 30 15:07:31 mju kernel: ohci_hcd 0000:00:14.0: urb c9d55420 path 1 ep1in
5e160000 cc 5 --> status -110
Jan 30 15:07:31 mju kernel: ohci_hcd 0000:00:14.0: urb c9d55f60 path 1 ep7in
5f160000 cc 5 --> status -110
Jan 30 15:07:31 mju kernel: ohci_hcd 0000:00:14.0: urb c9d55540 path 1 ep7in
5f160000 cc 5 --> status -110
Jan 30 15:07:31 mju modem_run[546]: Error reading interrupts 
Jan 30 15:07:31 mju kernel: ohci_hcd 0000:00:14.0: urb c9d55420 path 1 ep0in
5ec20000 cc 5 --> status -110
Jan 30 15:07:31 mju kernel: usbfs: USBDEVFS_CONTROL failed cmd modem_run dev 2
rqt 192 rq 18 len 1 ret -110
Jan 30 15:07:31 mju kernel: ohci_hcd 0000:00:14.0: urb c9d55420 path 1 ep1in
5e160000 cc 5 --> status -110
Jan 30 15:07:31 mju modem_run[546]: Error reading interrupts 
Jan 30 15:07:31 mju kernel: ohci_hcd 0000:00:14.0: urb c9d55420 path 1 ep0in
5ec20000 cc 5 --> status -110
Jan 30 15:07:31 mju kernel: usbfs: USBDEVFS_CONTROL failed cmd modem_run dev 2
rqt 192 rq 18 len 1 ret -110
Jan 30 15:07:31 mju kernel: ohci_hcd 0000:00:14.0: urb c9d55420 path 1 ep1in
5e160000 cc 5 --> status -110
Jan 30 15:07:31 mju modem_run[546]: Error reading interrupts 
Jan 30 15:07:32 mju modem_run[546]: Device disconnected, shutting down
Jan 30 15:07:32 mju kernel: ohci_hcd 0000:00:14.0: GetStatus roothub.portstatus
[1] = 0x00030100 PESC CSC PPS
Jan 30 15:07:32 mju kernel: hub 2-0:1.0: port 1, status 100, change 3, 12 Mb/s
Jan 30 15:07:32 mju kernel: usb 2-1: USB disconnect, address 2
Jan 30 15:07:32 mju /etc/hotplug/usb.agent: Bad USB agent invocation (prod=,
act=remove)
Jan 30 15:07:32 mju kernel: usb 2-1: usb_disable_device nuking all URBs
Jan 30 15:07:32 mju kernel: usb 2-1: unregistering interface 2-1:1.0
Jan 30 15:07:32 mju kernel: drivers/usb/core/usb.c: usb_hotplug
Jan 30 15:07:32 mju kernel: usbfs: USBDEVFS_CONTROL failed cmd modem_run dev 2
rqt 192 rq 18 len 1 ret -19
Jan 30 15:07:32 mju kernel: usbfs: usb_submit_urb returned -19
Jan 30 15:07:32 mju kernel: usb 2-1: unregistering interface 2-1:1.1
Jan 30 15:07:32 mju kernel: usb 2-1: hcd_unlink_urb c9d55f60 fail -22
Jan 30 15:07:32 mju kernel: usb 2-1: hcd_unlink_urb c9d55540 fail -22
Jan 30 15:07:32 mju kernel: usb 2-1: hcd_unlink_urb c9d55ba0 fail -22
Jan 30 15:07:32 mju kernel: usb 2-1: hcd_unlink_urb c9d55c00 fail -22
Jan 30 15:07:32 mju kernel: drivers/usb/core/usb.c: usb_hotplug
Jan 30 15:07:32 mju kernel: usb 2-1: unregistering interface 2-1:1.2
Jan 30 15:07:32 mju kernel: drivers/usb/core/usb.c: usb_hotplug
Jan 30 15:07:32 mju kernel: usb 2-1: unregistering device
Jan 30 15:07:32 mju kernel: drivers/usb/core/usb.c: usb_hotplug
Jan 30 15:07:32 mju kernel: Unable to handle kernel NULL pointer dereference at
virtual address 0000000c
Jan 30 15:07:32 mju kernel:  printing eip:
Jan 30 15:07:32 mju kernel: cfad34f3
Jan 30 15:07:32 mju kernel: *pde = 00000000
Jan 30 15:07:32 mju kernel: Oops: 0000 [#1]
Jan 30 15:07:32 mju kernel: CPU:    0
Jan 30 15:07:32 mju kernel: EIP:    0060:[<cfad34f3>]    Not tainted
Jan 30 15:07:32 mju kernel: EFLAGS: 00010206
Jan 30 15:07:32 mju kernel: EIP is at releaseintf+0x41/0x66 [usbcore]
Jan 30 15:07:32 mju kernel: eax: 0000000c   ebx: cce08000   ecx: cce08024   edx:
00000000
Jan 30 15:07:32 mju kernel: esi: cce08024   edi: ffffffea   ebp: cb1f63e0   esp:
c9e0bf20
Jan 30 15:07:32 mju kernel: ds: 007b   es: 007b   ss: 0068
Jan 30 15:07:32 mju kernel: Process modem_run (pid: 546, threadinfo=c9e0a000
task=c9adb920)
Jan 30 15:07:32 mju kernel: Stack: cb1f63e0 00000000 ceff4b60 c9b5aa40 cfad37bd
cb1f63e0 00000000 c9e950a0 
Jan 30 15:07:32 mju kernel:        c9b78080 c0147c14 c9b78080 c9e950a0 c9e950a0
00000000 c9b5daa0 00000001 
Jan 30 15:07:32 mju kernel:        c0147bd8 c0146965 c9e950a0 c9b5daa0 c9e950a0
c9b5daa0 00000001 c9b5daa0 
Jan 30 15:07:32 mju kernel: Call Trace:
Jan 30 15:07:32 mju kernel:  [<cfad37bd>] usbdev_release+0x37/0x61 [usbcore]
Jan 30 15:07:33 mju kernel:  [<c0147c14>] __fput+0x3b/0xdc
Jan 30 15:07:33 mju kernel:  [<c0147bd8>] fput+0x13/0x14
Jan 30 15:07:33 mju kernel:  [<c0146965>] filp_close+0x5f/0x68
Jan 30 15:07:33 mju kernel:  [<c011d7ba>] put_files_struct+0x4c/0xb2
Jan 30 15:07:33 mju kernel:  [<c011e1ad>] do_exit+0x188/0x2d8
Jan 30 15:07:33 mju kernel:  [<c011e322>] next_thread+0x0/0x1f
Jan 30 15:07:33 mju kernel:  [<c0108c8b>] syscall_call+0x7/0xb
Jan 30 15:07:33 mju kernel: 
Jan 30 15:07:33 mju kernel: Code: 8b 04 90 50 68 c0 1c ae cf e8 9d 7d ff ff 31
ff 83 c4 08 89 
Jan 30 15:07:33 mju kernel:  <7>ohci_hcd 0000:00:14.0: GetStatus
roothub.portstatus [1] = 0x00020100 PESC PPS
Jan 30 15:07:33 mju kernel: hub 2-0:1.0: port 1 enable change, status 100

sampo@mju:~ 0$ Jan 30 15:08:02 mju pppd[614]: No response to 3 echo-requests
Jan 30 15:08:02 mju pppd[614]: Serial link appears to be disconnected.
Jan 30 15:08:02 mju pppd[614]: Couldn't increase MTU to 1500
Jan 30 15:08:02 mju pppd[614]: Couldn't increase MRU to 1500
Jan 30 15:08:08 mju pppd[614]: Connection terminated.
Jan 30 15:08:08 mju pppd[614]: Connect time 1100.0 minutes.
Jan 30 15:08:08 mju pppd[614]: Sent 3480286 bytes, received 30695248 bytes.
Jan 30 15:08:09 mju /etc/hotplug/net.agent: NET remove event not supported
Jan 30 15:08:48 mju pppd[614]: Timeout waiting for PADO packets
Jan 30 15:08:48 mju pppd[614]: Unable to complete PPPoE Discovery

Steps to reproduce:

I get the modem up and running with commands

modprobe usbcore
modprobe ohci-hcd
mount -t usbfs usbfs /proc/bus/usb
modprobe speedtch  # ADSL related
modprobe pppoe
modprobe br2684
modem_run -k -m -f firmware.bin
br2684ctl -b -c 0 -a 0.35    # VPI.VCI for Telepac, Portugal
ifconfig nas0 up
sleep 1                      # without this sleep pppd causes kernel hang
pppd call speedtch
cat /etc/ppp/peers/speedtch
# To connect to using this configuration file, do
#       pppd call speedtch
lcp-echo-interval 10
lcp-echo-failure 3
noipdefault
defaultroute
user "salainen@telepac"
noauth
noaccomp
nopcomp
noccp
novj
holdoff 4
persist
maxfail 25
updetach
usepeerdns
plugin rp-pppoe.so
nas0

At this point connection gets established and everything works
fine. The connection is stable and drops less than once a day and I
appear to be getting the advertised speed: 512 down, 128 up.

If I now unplug the modem, the oops happens with about 50%
probability, i.e. not every thime, but quite often.

--Sampo