Date: Thu, 24 Dec 1998 11:20:18 +0000 From: David Goddard <goddard@acm.org> To: freebsd-questions@FreeBSD.ORG Subject: ppp hanging problem Message-ID: <3.0.3.32.19981224112018.00932e60@mailgate.ftech.net>
next in thread | raw e-mail | index | archive | help
Hi, I've been having a problem with ppp since my 2.2.5 installation and now it seems worse with my fresh 3.0 install. Basically, during a session (typically downloading news), my connection fails, but ppp keeps the line open until timeout. When this happens, I can't ping any other host and my active download (or whatever) fails. Using pppctl, I can close the connection manually but it's very sluggish - the prompt changes to: PPp ON dmg> and stays like this for some time before changing to the closed prompt. Once this has happened once, it seems much more likely to happen again. I'm using ppp -auto. I don't get anything analogous when dialling using NT so it doesn't seem to be any major problem with my line or the ISP, as far as I can tell... Can anyone shed any light on the cause of the problem? Thanks (and merry christmas :), Dave Some config/log info: === start ppp.log === [...] Dec 23 21:50:43 dmg ppp[59]: tun0: Phase: Connected to client from 127.0.0.1:5892 Dec 23 21:50:43 dmg ppp[59]: tun0: Command: 127.0.0.1:5892: passwd ******** Dec 23 21:50:43 dmg ppp[59]: tun0: Command: 127.0.0.1:5892: set timeout 300 Dec 23 21:50:43 dmg ppp[59]: tun0: Command: 127.0.0.1:5892: close Dec 23 21:50:43 dmg ppp[59]: tun0: IPCP: deflink: LayerDown: 195.200.12.2 Dec 23 21:50:43 dmg ppp[59]: tun0: IPCP: deflink: SendTerminateReq(4) state = Opened Dec 23 21:50:43 dmg ppp[59]: tun0: IPCP: deflink: State change Opened --> Closing Dec 23 21:50:43 dmg ppp[59]: tun0: Phase: 127.0.0.1:5892: Client connection closed. Dec 23 21:50:46 dmg ppp[59]: tun0: IPCP: deflink: SendTerminateReq(4) state = Closing Dec 23 21:50:55 dmg last message repeated 3 times Dec 23 21:50:58 dmg ppp[59]: tun0: IPCP: deflink: LayerFinish. Dec 23 21:50:58 dmg ppp[59]: tun0: IPCP: Connect time: 652 secs: 248186 octets in, 27767 octets out Dec 23 21:50:58 dmg ppp[59]: tun0: IPCP: total 423 bytes/sec, peak 5176 bytes/sec on Wed Dec 23 21:50:58 1998 Dec 23 21:50:58 dmg ppp[59]: tun0: IPCP: deflink: State change Closing --> Closed Dec 23 21:50:58 dmg ppp[59]: tun0: Phase: bundle: Terminate Dec 23 21:50:58 dmg ppp[59]: tun0: CCP: deflink: State change Closed --> Initial Dec 23 21:50:58 dmg ppp[59]: tun0: LCP: deflink: LayerDown Dec 23 21:50:58 dmg ppp[59]: tun0: LCP: deflink: SendTerminateReq(4) state = Opened Dec 23 21:50:58 dmg ppp[59]: tun0: LCP: deflink: State change Opened --> Closing Dec 23 21:50:58 dmg ppp[59]: tun0: Phase: deflink: open -> lcp Dec 23 21:50:58 dmg ppp[59]: tun0: IPCP: deflink: State change Closed --> Initial Dec 23 21:50:59 dmg ppp[59]: tun0: Phase: Connected to client from 127.0.0.1:6148 Dec 23 21:51:01 dmg ppp[59]: tun0: LCP: deflink: SendTerminateReq(4) state = Closing Dec 23 21:51:01 dmg ppp[59]: tun0: Command: 127.0.0.1:6148: passwd ******** Dec 23 21:51:04 dmg ppp[59]: tun0: LCP: deflink: SendTerminateReq(4) state = Closing Dec 23 21:51:07 dmg ppp[59]: tun0: LCP: deflink: SendTerminateReq(4) state = Closing Dec 23 21:51:08 dmg ppp[59]: tun0: Command: 127.0.0.1:6148: dial Dec 23 21:51:10 dmg ppp[59]: tun0: LCP: deflink: SendTerminateReq(4) state = Closing Dec 23 21:51:12 dmg ppp[59]: tun0: Command: 127.0.0.1:6148: close Dec 23 21:51:13 dmg ppp[59]: tun0: LCP: deflink: LayerFinish Dec 23 21:51:13 dmg ppp[59]: tun0: LCP: deflink: State change Closing --> Closed Dec 23 21:51:13 dmg ppp[59]: tun0: LCP: deflink: State change Closed --> Initial Dec 23 21:51:13 dmg ppp[59]: tun0: Phase: deflink: Disconnected! Dec 23 21:51:13 dmg ppp[59]: tun0: Phase: deflink: lcp -> hangup Dec 23 21:51:13 dmg ppp[59]: tun0: Phase: deflink: Connect time: 695 secs: 236371 octets in, 30749 octets out Dec 23 21:51:13 dmg ppp[59]: tun0: Phase: total 384 bytes/sec, peak 4923 bytes/sec on Wed Dec 23 21:51:13 1998 Dec 23 21:51:13 dmg ppp[59]: tun0: Phase: deflink: hangup -> closed Dec 23 21:51:13 dmg ppp[59]: tun0: Phase: bundle: Dead Dec 23 21:51:17 dmg ppp[59]: tun0: Command: 127.0.0.1:6148: qquit Dec 23 21:51:19 dmg ppp[59]: tun0: Command: 127.0.0.1:6148: quit Dec 23 21:51:19 dmg ppp[59]: tun0: Phase: 127.0.0.1:6148: Client connection dropped. Dec 23 21:51:22 dmg ppp[59]: tun0: Phase: bundle: Establish Dec 23 21:51:22 dmg ppp[59]: tun0: Phase: deflink: closed -> opening Dec 23 21:51:43 dmg ppp[59]: tun0: Phase: deflink: Redial timer expired. Dec 23 21:51:43 dmg ppp[59]: tun0: Phase: deflink: Connected! Dec 23 21:51:43 dmg ppp[59]: tun0: Phase: deflink: opening -> dial Dec 23 21:51:43 dmg ppp[59]: tun0: Phase: Phone: 01715790117 Dec 23 21:51:43 dmg ppp[59]: tun0: Chat: deflink: Dial attempt 1 of 1 Dec 23 21:51:43 dmg ppp[59]: tun0: Chat: Send: AT^M Dec 23 21:51:43 dmg ppp[59]: tun0: Chat: Expect(5): OK Dec 23 21:51:43 dmg ppp[59]: tun0: Chat: Received: AT^M^M Dec 23 21:51:43 dmg ppp[59]: tun0: Chat: Received: OK^M Dec 23 21:51:43 dmg ppp[59]: tun0: Chat: Send: ATE1Q0^M Dec 23 21:51:43 dmg ppp[59]: tun0: Chat: Expect(5): OK Dec 23 21:51:43 dmg ppp[59]: tun0: Chat: Received: ATE1Q0^M^M Dec 23 21:51:43 dmg ppp[59]: tun0: Chat: Received: OK^M Dec 23 21:51:43 dmg ppp[59]: tun0: Chat: Send: ATDT01715790117^M Dec 23 21:51:45 dmg ppp[59]: tun0: Chat: Expect(40): CONNECT Dec 23 21:52:05 dmg ppp[59]: tun0: Chat: Received: ATDT01715790117^M^M Dec 23 21:52:05 dmg ppp[59]: tun0: Chat: Received: CONNECT 33600/ARQ/V34/LAPM/V42BIS^M Dec 23 21:52:05 dmg ppp[59]: tun0: Phase: deflink: dial -> login Dec 23 21:52:05 dmg ppp[59]: tun0: Chat: Expect(5): ogin: Dec 23 21:52:10 dmg ppp[59]: tun0: Chat: Expect timeout Dec 23 21:52:10 dmg ppp[59]: tun0: Chat: Send: ^M Dec 23 21:52:10 dmg ppp[59]: tun0: Chat: Expect(5): ogin: Dec 23 21:52:10 dmg ppp[59]: tun0: Chat: Received: Frontier Internet Services^M Dec 23 21:52:10 dmg ppp[59]: tun0: Chat: Received: ^M Dec 23 21:52:10 dmg ppp[59]: tun0: Chat: Received: ^M Dec 23 21:52:10 dmg ppp[59]: tun0: Chat: Received: login: Dec 23 21:52:10 dmg ppp[59]: tun0: Chat: Send: mylusername^M Dec 23 21:52:10 dmg ppp[59]: tun0: Chat: Expect(5): word: Dec 23 21:52:11 dmg ppp[59]: tun0: Chat: Received: mylusername^M Dec 23 21:52:11 dmg ppp[59]: tun0: Chat: Received: password: Dec 23 21:52:11 dmg ppp[59]: tun0: Chat: Send: mypassword^M Dec 23 21:52:11 dmg ppp[59]: tun0: Chat: Expect(5): ocol: Dec 23 21:52:11 dmg ppp[59]: tun0: Chat: Received: ^M Dec 23 21:52:11 dmg ppp[59]: tun0: Chat: Received: Protocol: Dec 23 21:52:11 dmg ppp[59]: tun0: Chat: Send: ppp^M Dec 23 21:52:11 dmg ppp[59]: tun0: Phase: deflink: login -> lcp Dec 23 21:52:11 dmg ppp[59]: tun0: LCP: FSM: Using "deflink" as a transport Dec 23 21:52:11 dmg ppp[59]: tun0: LCP: deflink: State change Initial --> Closed Dec 23 21:52:11 dmg ppp[59]: tun0: LCP: deflink: State change Closed --> Stopped Dec 23 21:52:12 dmg ppp[59]: tun0: LCP: deflink: RecvConfigReq(1) state = Stopped Dec 23 21:52:12 dmg ppp[59]: tun0: LCP: MRU[4] 1524 Dec 23 21:52:12 dmg ppp[59]: tun0: LCP: ACCMAP[6] 0x000a0000 Dec 23 21:52:12 dmg ppp[59]: tun0: LCP: PROTOCOMP[2] Dec 23 21:52:12 dmg ppp[59]: tun0: LCP: ACFCOMP[2] Dec 23 21:52:12 dmg ppp[59]: tun0: LCP: ENDDISC[8] Local Addr: ftech Dec 23 21:52:12 dmg ppp[59]: tun0: LCP: LDBACP[4] da00 Dec 23 21:52:12 dmg ppp[59]: tun0: LCP: deflink: SendConfigReq(4) state = Stopped Dec 23 21:52:12 dmg ppp[59]: tun0: LCP: ACFCOMP[2] Dec 23 21:52:12 dmg ppp[59]: tun0: LCP: PROTOCOMP[2] Dec 23 21:52:12 dmg ppp[59]: tun0: LCP: ACCMAP[6] 0x00000000 Dec 23 21:52:12 dmg ppp[59]: tun0: LCP: MRU[4] 1500 Dec 23 21:52:12 dmg ppp[59]: tun0: LCP: MAGICNUM[6] 0x103fbbde Dec 23 21:52:12 dmg ppp[59]: tun0: LCP: deflink: SendConfigRej(1) state = Stopped Dec 23 21:52:12 dmg ppp[59]: tun0: LCP: LDBACP[4] da00 Dec 23 21:52:12 dmg ppp[59]: tun0: LCP: deflink: State change Stopped --> Req-Sent Dec 23 21:52:12 dmg ppp[59]: tun0: LCP: deflink: RecvConfigAck(4) state = Req-Sent Dec 23 21:52:12 dmg ppp[59]: tun0: LCP: deflink: State change Req-Sent --> Ack-Rcvd Dec 23 21:52:12 dmg ppp[59]: tun0: LCP: deflink: RecvConfigReq(2) state = Ack-Rcvd Dec 23 21:52:12 dmg ppp[59]: tun0: LCP: MRU[4] 1524 Dec 23 21:52:12 dmg ppp[59]: tun0: LCP: ACCMAP[6] 0x000a0000 Dec 23 21:52:12 dmg ppp[59]: tun0: LCP: PROTOCOMP[2] Dec 23 21:52:12 dmg ppp[59]: tun0: LCP: ACFCOMP[2] Dec 23 21:52:12 dmg ppp[59]: tun0: LCP: ENDDISC[8] Local Addr: ftech Dec 23 21:52:12 dmg ppp[59]: tun0: LCP: deflink: SendConfigAck(2) state = Ack-Rcvd Dec 23 21:52:12 dmg ppp[59]: tun0: LCP: MRU[4] 1524 Dec 23 21:52:12 dmg ppp[59]: tun0: LCP: ACCMAP[6] 0x000a0000 Dec 23 21:52:12 dmg ppp[59]: tun0: LCP: PROTOCOMP[2] Dec 23 21:52:12 dmg ppp[59]: tun0: LCP: ACFCOMP[2] Dec 23 21:52:12 dmg ppp[59]: tun0: LCP: ENDDISC[8] Local Addr: ftech Dec 23 21:52:12 dmg ppp[59]: tun0: LCP: deflink: State change Ack-Rcvd --> Opened Dec 23 21:52:12 dmg ppp[59]: tun0: LCP: deflink: LayerUp Dec 23 21:52:12 dmg ppp[59]: tun0: CCP: FSM: Using "deflink" as a transport Dec 23 21:52:12 dmg ppp[59]: tun0: CCP: deflink: State change Initial --> Closed Dec 23 21:52:12 dmg ppp[59]: tun0: CCP: deflink: LayerStart. Dec 23 21:52:12 dmg ppp[59]: tun0: CCP: deflink: SendConfigReq(17) state = Closed Dec 23 21:52:12 dmg ppp[59]: tun0: CCP: DEFLATE[4] win 15 Dec 23 21:52:12 dmg ppp[59]: tun0: CCP: PRED1[2] Dec 23 21:52:12 dmg ppp[59]: tun0: CCP: deflink: State change Closed --> Req-Sent Dec 23 21:52:12 dmg ppp[59]: tun0: Phase: deflink: lcp -> open Dec 23 21:52:12 dmg ppp[59]: tun0: Phase: bundle: Network Dec 23 21:52:12 dmg ppp[59]: tun0: IPCP: FSM: Using "deflink" as a transport Dec 23 21:52:12 dmg ppp[59]: tun0: IPCP: deflink: State change Initial --> Closed Dec 23 21:52:12 dmg ppp[59]: tun0: IPCP: deflink: LayerStart. Dec 23 21:52:12 dmg ppp[59]: tun0: IPCP: deflink: SendConfigReq(4) state = Closed Dec 23 21:52:12 dmg ppp[59]: tun0: IPCP: IPADDR[6] 195.200.9.208 Dec 23 21:52:12 dmg ppp[59]: tun0: IPCP: COMPPROTO[6] 14 VJ slots without slot compression Dec 23 21:52:12 dmg ppp[59]: tun0: IPCP: PRIDNS[6] 195.200.0.78 Dec 23 21:52:12 dmg ppp[59]: tun0: IPCP: SECDNS[6] 195.200.0.76 Dec 23 21:52:12 dmg ppp[59]: tun0: IPCP: deflink: State change Closed --> Req-Sent Dec 23 21:52:12 dmg ppp[59]: tun0: IPCP: deflink: RecvConfigReq(1) state = Req-Sent Dec 23 21:52:12 dmg ppp[59]: tun0: IPCP: COMPPROTO[6] 14 VJ slots without slot compression Dec 23 21:52:12 dmg ppp[59]: tun0: IPCP: IPADDR[6] 195.200.12.15 Dec 23 21:52:12 dmg ppp[59]: tun0: IPCP: deflink: SendConfigAck(1) state = Req-Sent Dec 23 21:52:12 dmg ppp[59]: tun0: IPCP: COMPPROTO[6] 14 VJ slots without slot compression Dec 23 21:52:12 dmg ppp[59]: tun0: IPCP: IPADDR[6] 195.200.12.15 Dec 23 21:52:12 dmg ppp[59]: tun0: IPCP: deflink: State change Req-Sent --> Ack-Sent Dec 23 21:52:12 dmg ppp[59]: tun0: LCP: deflink: RecvProtocolRej(3) state = Opened Dec 23 21:52:12 dmg ppp[59]: tun0: LCP: deflink: -- Protocol 0x80fd (Compression Control Protocol) was rejected! Dec 23 21:52:12 dmg ppp[59]: tun0: CCP: deflink: LayerFinish. Dec 23 21:52:12 dmg ppp[59]: tun0: CCP: deflink: State change Req-Sent --> Stopped Dec 23 21:52:12 dmg ppp[59]: tun0: IPCP: deflink: RecvConfigAck(4) state = Ack-Sent Dec 23 21:52:12 dmg ppp[59]: tun0: IPCP: deflink: State change Ack-Sent --> Opened Dec 23 21:52:12 dmg ppp[59]: tun0: IPCP: deflink: LayerUp. Dec 23 21:52:12 dmg ppp[59]: tun0: IPCP: myaddr = 195.200.9.208 hisaddr = 195.200.12.15 Dec 23 21:52:12 dmg ppp[59]: tun0: Command: 195.200.9.208: delete ALL Dec 23 21:52:12 dmg ppp[59]: tun0: Command: 195.200.12.15: add 0 0 HISADDR Dec 23 21:58:52 dmg ppp[59]: tun0: Phase: Connected to client from 127.0.0.1:7428 Dec 23 21:58:54 dmg ppp[59]: tun0: Command: 127.0.0.1:7428: passwd ******** Dec 23 21:58:58 dmg ppp[59]: tun0: Command: 127.0.0.1:7428: quit Dec 23 21:58:58 dmg ppp[59]: tun0: Phase: 127.0.0.1:7428: Client connection dropped. Dec 23 22:03:15 dmg ppp[59]: tun0: Phase: Connected to client from 127.0.0.1:7940 Dec 23 22:03:18 dmg ppp[59]: tun0: Command: 127.0.0.1:7940: passwd ******** Dec 23 22:03:23 dmg ppp[59]: tun0: Command: 127.0.0.1:7940: quit Dec 23 22:03:23 dmg ppp[59]: tun0: Phase: 127.0.0.1:7940: Client connection dropped. Dec 23 22:08:49 dmg ppp[59]: tun0: Phase: Idle timer expired. Dec 23 22:08:49 dmg ppp[59]: tun0: IPCP: deflink: LayerDown: 195.200.12.15 Dec 23 22:08:49 dmg ppp[59]: tun0: IPCP: deflink: SendTerminateReq(5) state = Opened Dec 23 22:08:49 dmg ppp[59]: tun0: IPCP: deflink: State change Opened --> Closing Dec 23 22:08:52 dmg ppp[59]: tun0: IPCP: deflink: SendTerminateReq(5) state = Closing Dec 23 22:09:01 dmg last message repeated 3 times Dec 23 22:09:04 dmg ppp[59]: tun0: IPCP: deflink: LayerFinish. Dec 23 22:09:04 dmg ppp[59]: tun0: IPCP: Connect time: 1012 secs: 147445 octets in, 18455 octets out Dec 23 22:09:04 dmg ppp[59]: tun0: IPCP: total 163 bytes/sec, peak 7984 bytes/sec on Wed Dec 23 22:09:04 1998 Dec 23 22:09:04 dmg ppp[59]: tun0: IPCP: deflink: State change Closing --> Closed Dec 23 22:09:04 dmg ppp[59]: tun0: Phase: bundle: Terminate Dec 23 22:09:04 dmg ppp[59]: tun0: CCP: deflink: State change Stopped --> Closed Dec 23 22:09:04 dmg ppp[59]: tun0: CCP: deflink: State change Closed --> Initial Dec 23 22:09:04 dmg ppp[59]: tun0: LCP: deflink: LayerDown Dec 23 22:09:04 dmg ppp[59]: tun0: LCP: deflink: SendTerminateReq(5) state = Opened Dec 23 22:09:04 dmg ppp[59]: tun0: LCP: deflink: State change Opened --> Closing Dec 23 22:09:04 dmg ppp[59]: tun0: Phase: deflink: open -> lcp Dec 23 22:09:04 dmg ppp[59]: tun0: IPCP: deflink: State change Closed --> Initial Dec 23 22:09:07 dmg ppp[59]: tun0: LCP: deflink: SendTerminateReq(5) state = Closing Dec 23 22:09:16 dmg last message repeated 3 times Dec 23 22:09:19 dmg ppp[59]: tun0: LCP: deflink: LayerFinish Dec 23 22:09:19 dmg ppp[59]: tun0: LCP: deflink: State change Closing --> Closed Dec 23 22:09:19 dmg ppp[59]: tun0: LCP: deflink: State change Closed --> Initial Dec 23 22:09:19 dmg ppp[59]: tun0: Phase: deflink: Disconnected! Dec 23 22:09:19 dmg ppp[59]: tun0: Phase: deflink: lcp -> hangup Dec 23 22:09:19 dmg ppp[59]: tun0: Phase: deflink: Connect time: 1056 secs: 139514 octets in, 20772 octets out Dec 23 22:09:19 dmg ppp[59]: tun0: Phase: total 151 bytes/sec, peak 7500 bytes/sec on Wed Dec 23 22:09:19 1998 Dec 23 22:09:19 dmg ppp[59]: tun0: Phase: deflink: hangup -> closed Dec 23 22:09:19 dmg ppp[59]: tun0: Phase: bundle: Dead Dec 23 22:14:17 dmg ppp[59]: tun0: Phase: Connected to client from 127.0.0.1:8196 Dec 23 22:14:20 dmg ppp[59]: tun0: Command: 127.0.0.1:8196: passwd ******** Dec 23 22:14:27 dmg ppp[59]: tun0: Command: 127.0.0.1:8196: quit all Dec 23 22:14:27 dmg ppp[59]: tun0: Phase: 127.0.0.1:8196: Client connection dropped. Dec 23 22:14:27 dmg ppp[59]: tun0: Phase: PPP Terminated (normal). === end ppp.log === This is what pppctl showed me when the link was dead but not yet timed out (note that it's from a different session but same circumstance): === start typescript === dmg% pppctl 3000 Password: PPP ON dmg> show ipcp IPCP [Opened] His side: 195.200.12.15, 14 VJ slots without slot compression My side: 195.200.9.208, 16 VJ slots with slot compression Sticky routes: add default HISADDR Defaults: My Address: 195.200.9.208/32 VJ compression: enabled & accepted (16 slots with slot compression) His Address: 10.0.0.10/0 DNS: 0.0.0.0, 0.0.0.0, enabled & denied NetBIOS NS: 0.0.0.0, 0.0.0.0 Connect time: 561 secs 167555 octets in, 15740 octets out overall 326 bytes/sec currently 0 bytes/sec peak 7092 bytes/sec on Wed Dec 23 01:08:26 1998 PPP ON dmg> show lcp deflink: LCP [Opened] his side: MRU 1524, ACCMAP 000a0000, PROTOCOMP on, ACFCOMP on, MAGIC 00000000, MRRU 0, SHORTSEQ off, REJECT 0000 my side: MRU 1500, ACCMAP 00000000, PROTOCOMP on, ACFCOMP on, MAGIC 4c041ebc, MRRU 0, SHORTSEQ on, REJECT 800000 Defaults: MRU = 1500, ACCMAP = 00000000 LQR period = 30s, Open Mode = active (delay 1s) FSM retry = 3s Negotiation: ACFCOMP = enabled & accepted CHAP = disabled & accepted LQR = disabled & accepted PAP = disabled & accepted PROTOCOMP = enabled & accepted PPP ON dmg> === end typescript === Here are some bits from ppp.conf: default: set log Phase Chat LCP IPCP CCP tun command # set log Phase tun set server 3000 myserverpasswd set device /dev/cuaa1 set speed 115200 set dial "ABORT BUSY ABORT NO\\sCARRIER TIMEOUT 5 \"\" AT OK-AT-OK ATE1Q0 OK \\dATDT\\T TIMEOUT 40 CONNECT" [...] frontier: set phone 01715790117 set login "ABORT NO\\sCARRIER TIMEOUT 5 ogin:--ogin: mylusername word: mypasswd ocol: ppp" set timeout 120 set ifaddr 195.200.9.208 10.0.0.10/0 add default HISADDR enable dns And from ppp.linkup: 195.200.9.208: delete ALL add 0 0 HISADDR -- David Goddard ~ goddard@acm.org ~ http://freeweb.ftech.net/dmg Some mornings it's just not worth chewing through the leather straps To Unsubscribe: send mail to majordomo@FreeBSD.org with "unsubscribe freebsd-questions" in the body of the message
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?3.0.3.32.19981224112018.00932e60>