Bug 1976 - USB speedtch unplugging causes oops (in modem_run?)
Summary: USB speedtch unplugging causes oops (in modem_run?)
Status: REJECTED INSUFFICIENT_DATA
Alias: None
Product: Drivers
Classification: Unclassified
Component: USB (show other bugs)
Hardware: i386 Linux
: P2 normal
Assignee: baldrick
URL:
Keywords:
: 1977 1978 1979 (view as bug list)
Depends on:
Blocks: USB
  Show dependency tree
 
Reported: 2004-01-30 14:39 UTC by Sampo Kellom
Modified: 2005-08-18 16:23 UTC (History)
3 users (show)

See Also:
Kernel Version: 2.6.1
Subsystem:
Regression: ---
Bisected commit-id:


Attachments

Description Sampo Kellom 2004-01-30 14:39:04 UTC
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
Comment 1 Sampo Kellom 2004-01-30 15:01:28 UTC
*** Bug 1977 has been marked as a duplicate of this bug. ***
Comment 2 Sampo Kellom 2004-01-30 15:04:50 UTC
*** Bug 1978 has been marked as a duplicate of this bug. ***
Comment 3 Sampo Kellom 2004-01-30 15:07:44 UTC
*** Bug 1979 has been marked as a duplicate of this bug. ***
Comment 4 Sampo Kellom 2004-02-03 04:35:45 UTC
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
Comment 5 Greg Kroah-Hartman 2004-02-18 09:24:04 UTC
Still a problem on 2.6.3?
Comment 6 Thomas Leonard 2004-04-09 04:01:28 UTC
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)
Comment 7 baldrick 2004-04-09 05:26:10 UTC
> 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. 
Comment 8 Thomas Leonard 2004-04-10 03:58:20 UTC
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)
Comment 9 Nishanth Aravamudan 2004-12-12 18:16:06 UTC
Is there any update on the status of this issue with later kernels? 2.6.9/10-rc*?
Comment 10 David Brownell 2005-04-04 14:01:33 UTC
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. 
Comment 11 Nishanth Aravamudan 2005-04-04 14:14:22 UTC
Thanks David, I'll keep my eye on it and close it when appropriate.
Comment 12 Greg Kroah-Hartman 2005-08-18 16:23:19 UTC
Closing due to age.

Note You need to log in before you can comment on or make changes to this bug.