From owner-freebsd-net Sat Mar 31 7:47:37 2001 Delivered-To: freebsd-net@freebsd.org Received: from polaris.we.lc.ehu.es (polaris.we.lc.ehu.es [158.227.6.43]) by hub.freebsd.org (Postfix) with ESMTP id 5AE1E37B718 for ; Sat, 31 Mar 2001 07:47:29 -0800 (PST) (envelope-from jose@we.lc.ehu.es) Received: from v-ger.we.lc.ehu.es (lxpx515.lx.ehu.es [158.227.27.161]) by polaris.we.lc.ehu.es (8.11.1/8.11.1) with ESMTP id f2VFkx924271 for ; Sat, 31 Mar 2001 17:46:59 +0200 (MET DST) Received: from we.lc.ehu.es (localhost [127.0.0.1]) by v-ger.we.lc.ehu.es (8.11.3/8.11.3) with ESMTP id f2VFkpA01615 for ; Sat, 31 Mar 2001 17:46:52 +0200 (CEST) (envelope-from jose@we.lc.ehu.es) Message-ID: <3AC5FBEB.E2F09D80@we.lc.ehu.es> Date: Sat, 31 Mar 2001 17:46:51 +0200 From: "Jose M. Alcaide" Organization: Universidad del Pais Vasco - Dpto. de Electricidad y Electronica X-Mailer: Mozilla 4.76 [en] (X11; U; Linux 2.2.12 i386) X-Accept-Language: es-ES, es, en-US, en MIME-Version: 1.0 To: net@FreeBSD.org Subject: user-ppp problems Content-Type: multipart/mixed; boundary="------------ADAE6E5FCDE81FC2EB892A9C" Sender: owner-freebsd-net@FreeBSD.ORG Precedence: bulk X-Loop: FreeBSD.org This is a multi-part message in MIME format. --------------ADAE6E5FCDE81FC2EB892A9C Content-Type: text/plain; charset=us-ascii Content-Transfer-Encoding: 7bit Hello, Some days ago I began to suffer strange problems with user-ppp while trying to connect with one specific ISP. For example, sometimes the connection fails to establish and the following messages are logged: ... tun0: Phase: bundle: Authenticate tun0: Phase: deflink: his = CHAP 0x05, mine = none tun0: Phase: Chap Input: CHALLENGE (16 bytes from AccEuskaltel) tun0: Phase: Chap Output: RESPONSE (**************) tun0: LCP: deflink: RecvEchoRequest(1) state = Opened tun0: LCP: deflink: SendEchoReply(1) state = Opened tun0: IPCP: deflink: Error: Unexpected IPCP in phase Authenticate (ignored) last message repeated 3 times tun0: LCP: deflink: RecvEchoRequest(2) state = Opened tun0: LCP: deflink: SendEchoReply(2) state = Opened tun0: IPCP: deflink: Error: Unexpected IPCP in phase Authenticate (ignored) last message repeated 3 times tun0: LCP: deflink: RecvEchoRequest(3) state = Opened tun0: LCP: deflink: SendEchoReply(3) state = Opened tun0: LCP: deflink: RecvEchoRequest(4) state = Opened tun0: LCP: deflink: SendEchoReply(4) state = Opened ... Also, I am wondering about the LCP "RecvEchoRequest" and "SendEchoReply" messages. Even when the connection is succesfully established, they keep appearing all the time, _only_ with this specific ISP. I thought that they could be related to LQR, but I disabled and denied LQR in ppp.conf to no avail. I updated the machine to 4.3-RC a few days ago, so that I borrowed /usr/sbin/ppp from other machine still running 4.2-RELEASE (the compat4x libraries are installed) and something different happenned, indeed: while using 4.2R's ppp, I got these messages after the connection was established: ... tun0: Error: ip_Input: deflink: wrote 52, got Address family not supported by protocol family tun0: Error: ip_Input: deflink: wrote 532, got Address family not supported by protocol family last message repeated 3 times tun0: Error: ip_Input: deflink: wrote 412, got Address family not supported by protocol family tun0: Error: ip_Input: deflink: wrote 532, got Address family not supported by protocol family tun0: Error: ip_Input: deflink: wrote 532, got Address family not supported by protocol family ... The IPCP negotiation succeeds. However, a ping to the other end of the P-P link does not work. OTOH, the "RecvEchoRequest" and "SendEchoReply" messages are still being logged. I suspect that something was broken in the ISP, so I would like to be able to diagnose this problem before calling to their "support" people (they don't know that there are other OS apart from Win**ws). Any ideas? [I am sending attached the full log of a failed connection] -- JMA ****** Jose M. Alcaide // jose@we.lc.ehu.es // jmas@FreeBSD.org ****** ** "Beware of Programmers who carry screwdrivers" -- Leonard Brandwein ** --------------ADAE6E5FCDE81FC2EB892A9C Content-Type: text/plain; charset=us-ascii; name="ppplog" Content-Transfer-Encoding: 7bit Content-Disposition: inline; filename="ppplog" Phase: Using interface: tun0 Phase: deflink: Created in closed state tun0: Command: default: set speed 115200 tun0: Command: default: set dial ABORT BUSY ABORT NO\sCARRIER TIMEOUT 5 "" AT OK-AT-OK ATE1Q0M3 OK \dATDT\T TIMEOUT 60 CONNECT tun0: Command: default: set ifaddr 10.0.0.1/0 10.0.0.2/0 255.255.255.0 0.0.0.0 tun0: Command: default: set timeout 300 tun0: Command: default: set filter alive 0 deny icmp tun0: Command: default: set filter alive 1 deny udp src eq domain tun0: Command: default: set filter alive 2 deny udp dst eq domain tun0: Command: default: set filter alive 3 permit 0 0 tun0: Command: default: deny lqr tun0: Command: upv: set phone ********* tun0: Command: upv: set authname ************** tun0: Command: upv: set authkey ******** tun0: Command: upv: set server /tmp/ppp-upv ******** 0177 tun0: Phase: Listening at local socket /tmp/ppp-upv. tun0: Command: upv: set papretry 10 tun0: Command: upv: set chapretry 10 tun0: Command: upv: add 158.227.0.0/16 HISADDR tun0: Phase: PPP Started (background mode). tun0: Phase: bundle: Establish tun0: Phase: deflink: closed -> opening tun0: Phase: deflink: Connected! tun0: Phase: deflink: opening -> dial tun0: Chat: Phone: ********* tun0: Chat: deflink: Dial attempt 1 of 1 tun0: Chat: Send: AT^M tun0: Chat: Expect(5): OK tun0: Chat: Received: AT^M^M tun0: Chat: Received: OK^M tun0: Chat: Send: ATE1Q0M3^M tun0: Chat: Expect(5): OK tun0: Chat: Received: ATE1Q0M3^M^M tun0: Chat: Received: OK^M tun0: Chat: Send: ATDT*********^M tun0: Chat: Expect(60): CONNECT tun0: Phase: Connected to local client. tun0: Chat: Received: ATDT*********^M^M tun0: Chat: Received: CONNECT 31200^M tun0: Phase: deflink: dial -> carrier tun0: Phase: deflink: /dev/cuaa1: CD detected tun0: Phase: deflink: carrier -> login tun0: Phase: deflink: login -> lcp tun0: LCP: FSM: Using "deflink" as a transport tun0: LCP: deflink: State change Initial --> Closed tun0: LCP: deflink: State change Closed --> Stopped tun0: LCP: deflink: LayerStart tun0: LCP: deflink: SendConfigReq(1) state = Stopped tun0: LCP: ACFCOMP[2] tun0: LCP: PROTOCOMP[2] tun0: LCP: ACCMAP[6] 0x00000000 tun0: LCP: MRU[4] 1500 tun0: LCP: MAGICNUM[6] 0x38074321 tun0: LCP: deflink: State change Stopped --> Req-Sent tun0: LCP: deflink: RecvConfigReq(240) state = Req-Sent tun0: LCP: ACCMAP[6] 0x000a0000 tun0: LCP: AUTHPROTO[5] 0xc223 (CHAP 0x05) tun0: LCP: MAGICNUM[6] 0x2c3b94d0 tun0: LCP: PROTOCOMP[2] tun0: LCP: ACFCOMP[2] tun0: LCP: deflink: SendConfigAck(240) state = Req-Sent tun0: LCP: ACCMAP[6] 0x000a0000 tun0: LCP: AUTHPROTO[5] 0xc223 (CHAP 0x05) tun0: LCP: MAGICNUM[6] 0x2c3b94d0 tun0: LCP: PROTOCOMP[2] tun0: LCP: ACFCOMP[2] tun0: LCP: deflink: State change Req-Sent --> Ack-Sent tun0: LCP: deflink: RecvConfigAck(1) state = Ack-Sent tun0: LCP: deflink: State change Ack-Sent --> Opened tun0: LCP: deflink: LayerUp tun0: LCP: Sending ident magic 38074321 text user-ppp 2.3 (built Mar 28 2001) tun0: LCP: deflink: SendIdent(0) state = Opened tun0: Phase: bundle: Authenticate tun0: Phase: deflink: his = CHAP 0x05, mine = none tun0: Phase: Chap Input: CHALLENGE (16 bytes from AccEuskaltel) tun0: Phase: Chap Output: RESPONSE (**************) tun0: LCP: deflink: RecvEchoRequest(1) state = Opened tun0: LCP: deflink: SendEchoReply(1) state = Opened tun0: IPCP: deflink: Error: Unexpected IPCP in phase Authenticate (ignored) Mar 31 13:47:02 v-ger last message repeated 3 times tun0: LCP: deflink: RecvEchoRequest(2) state = Opened tun0: LCP: deflink: SendEchoReply(2) state = Opened tun0: IPCP: deflink: Error: Unexpected IPCP in phase Authenticate (ignored) Mar 31 13:47:12 v-ger last message repeated 3 times tun0: LCP: deflink: RecvEchoRequest(3) state = Opened tun0: LCP: deflink: SendEchoReply(3) state = Opened tun0: LCP: deflink: RecvEchoRequest(4) state = Opened tun0: LCP: deflink: SendEchoReply(4) state = Opened tun0: Command: /tmp/ppp-upv: close tun0: LCP: deflink: LayerDown tun0: LCP: deflink: SendTerminateReq(2) state = Opened tun0: LCP: deflink: State change Opened --> Closing tun0: LCP: deflink: SendTerminateReq(2) state = Closing tun0: LCP: deflink: SendTerminateReq(2) state = Closing tun0: Phase: deflink: Carrier lost tun0: LCP: deflink: LayerFinish tun0: LCP: deflink: State change Closing --> Initial tun0: Phase: deflink: Disconnected! tun0: Phase: deflink: lcp -> logout tun0: Phase: deflink: Disconnected! tun0: Phase: deflink: logout -> hangup tun0: Phase: deflink: Connect time: 86 secs: 390 octets in, 363 octets out tun0: Phase: deflink: : 22 packets in, 11 packets out tun0: Phase: total 8 bytes/sec, peak 79 bytes/sec on Sat Mar 31 13:47:30 2001 tun0: Phase: deflink: hangup -> closed tun0: Phase: bundle: Dead tun0: Phase: /tmp/ppp-upv: Client connection dropped. tun0: Phase: PPP Terminated (normal). --------------ADAE6E5FCDE81FC2EB892A9C-- To Unsubscribe: send mail to majordomo@FreeBSD.org with "unsubscribe freebsd-net" in the body of the message