Date: Mon, 30 Jun 2003 23:36:26 +0200 From: Alessandro de Manzano <ale@unixmania.net> To: Doug White <dwhite@gumbysoft.com> Cc: net@freebsd.org Subject: Re: strange PPP negotiation problem with GPRS mobile phone Message-ID: <20030630233626.A73415@libero.sunshine.ale> In-Reply-To: <20030630124257.M31036@carver.gumbysoft.com>; from dwhite@gumbysoft.com on Mon, Jun 30, 2003 at 12:44:51PM -0700 References: <20030630212122.A72414@libero.sunshine.ale> <20030630124257.M31036@carver.gumbysoft.com>
next in thread | previous in thread | raw e-mail | index | archive | help
On Mon, Jun 30, 2003 at 12:44:51PM -0700, Doug White wrote: > Quick analysis: It doesn't like something in the negotiation, since it > rejects config attempts. Usually its supposed to tell you what it didn't > like, but I'm not seeing that in the printout. Ok, now after the kind help of Mr. Speyerer I've reached the following phase: Now PPP seems to negotiate some IP address, but after about a second it still close the session... Could someone, please, help me understanding what's wrong now according to this log ? ;) Many thanks forever :)) Jun 30 23:27:13 asusmobile ppp[274]: Phase: Using interface: tun0 Jun 30 23:27:13 asusmobile ppp[274]: Phase: deflink: Created in closed state Jun 30 23:27:15 asusmobile ppp[274]: tun0: Command: default: ident user-ppp VERSION (built COMPILATIONDATE) Jun 30 23:27:15 asusmobile ppp[274]: tun0: Command: default: set device /dev/cuaa0 Jun 30 23:27:15 asusmobile ppp[274]: tun0: Command: default: set speed 115200 Jun 30 23:27:15 asusmobile ppp[274]: tun0: Command: default: set dial ABORT BUSY ABORT NO\sCARRIER TIMEOUT 5 "" AT OK-AT-OK ATE1Q0 OK \dATDT\T TIMEOUT 40 CONNECT Jun 30 23:27:15 asusmobile ppp[274]: tun0: Command: default: set timeout 180 Jun 30 23:27:15 asusmobile ppp[274]: tun0: Command: default: enable dns Jun 30 23:27:15 asusmobile ppp[274]: tun0: Command: default: disable ipv6cp Jun 30 23:27:15 asusmobile ppp[274]: tun0: Command: default: disable mppe Jun 30 23:27:15 asusmobile ppp[274]: tun0: Command: vodagprs: set speed 57600 Jun 30 23:27:15 asusmobile ppp[274]: tun0: Command: vodagprs: set dial ABORT BUSY ABORT NO\sCARRIER TIMEOUT 5 "" ATZ OK-AT-OK ATE1Q0 OK AT+CGDCONT=1,\"IP\",\"web.omnitel.it\",,0,0 OK AT+CGQREQ=1,0,0,0,0,0 OK ATD*99***1# TIMEOUT 85 CONNECT Jun 30 23:27:15 asusmobile ppp[274]: tun0: Command: vodagprs: set phone Jun 30 23:27:15 asusmobile ppp[274]: tun0: Command: vodagprs: set login Jun 30 23:27:15 asusmobile ppp[274]: tun0: Command: vodagprs: set authname Jun 30 23:27:15 asusmobile ppp[274]: tun0: Command: vodagprs: set authkey Jun 30 23:27:15 asusmobile ppp[274]: tun0: Command: vodagprs: set timeout 0 Jun 30 23:27:15 asusmobile ppp[274]: tun0: Command: vodagprs: add default HISADDR Jun 30 23:27:15 asusmobile ppp[274]: tun0: Command: vodagprs: disable dns Jun 30 23:27:15 asusmobile ppp[274]: tun0: Command: vodagprs: disable vjcomp Jun 30 23:27:15 asusmobile ppp[274]: tun0: Command: vodagprs: disable deflate Jun 30 23:27:15 asusmobile ppp[274]: tun0: Command: vodagprs: disable protocomp Jun 30 23:27:15 asusmobile ppp[275]: tun0: Phase: PPP Started (background mode). Jun 30 23:27:15 asusmobile ppp[275]: tun0: Phase: bundle: Establish Jun 30 23:27:15 asusmobile ppp[275]: tun0: Phase: deflink: closed -> opening Jun 30 23:27:15 asusmobile ppp[275]: tun0: Phase: deflink: Connected! Jun 30 23:27:15 asusmobile ppp[275]: tun0: Phase: deflink: opening -> dial Jun 30 23:27:15 asusmobile ppp[275]: tun0: Chat: deflink: Dial attempt 1 of 1 Jun 30 23:27:15 asusmobile ppp[275]: tun0: Chat: Send: ATZ^M Jun 30 23:27:15 asusmobile ppp[275]: tun0: Chat: Expect(5): OK Jun 30 23:27:15 asusmobile ppp[275]: tun0: Chat: Received: ATZ^M^M Jun 30 23:27:15 asusmobile ppp[275]: tun0: Chat: Received: OK^M Jun 30 23:27:15 asusmobile ppp[275]: tun0: Chat: Send: ATE1Q0^M Jun 30 23:27:15 asusmobile ppp[275]: tun0: Chat: Expect(5): OK Jun 30 23:27:15 asusmobile ppp[275]: tun0: Chat: Received: ATE1Q0^M^M Jun 30 23:27:15 asusmobile ppp[275]: tun0: Chat: Received: OK^M Jun 30 23:27:15 asusmobile ppp[275]: tun0: Chat: Send: AT+CGDCONT=1,"IP","web.omnitel.it",,0,0^M Jun 30 23:27:15 asusmobile ppp[275]: tun0: Chat: Expect(5): OK Jun 30 23:27:15 asusmobile ppp[275]: tun0: Chat: Received: AT+CGDCONT=1,"IP","web.omnitel.it",,0,0^M^M Jun 30 23:27:15 asusmobile ppp[275]: tun0: Chat: Received: OK^M Jun 30 23:27:15 asusmobile ppp[275]: tun0: Chat: Send: AT+CGQREQ=1,0,0,0,0,0^M Jun 30 23:27:15 asusmobile ppp[275]: tun0: Chat: Expect(5): OK Jun 30 23:27:15 asusmobile ppp[275]: tun0: Chat: Received: AT+CGQREQ=1,0,0,0,0,0^M^M Jun 30 23:27:15 asusmobile ppp[275]: tun0: Chat: Received: OK^M Jun 30 23:27:15 asusmobile ppp[275]: tun0: Chat: Send: ATD*99***1#^M Jun 30 23:27:15 asusmobile ppp[275]: tun0: Chat: Expect(85): CONNECT Jun 30 23:27:15 asusmobile ppp[275]: tun0: Chat: Received: ATD*99***1#^M^M Jun 30 23:27:15 asusmobile ppp[275]: tun0: Chat: Received: CONNECT^M Jun 30 23:27:15 asusmobile ppp[275]: tun0: Phase: deflink: dial -> carrier Jun 30 23:27:16 asusmobile ppp[275]: tun0: Phase: deflink: /dev/cuaa0: CD detected Jun 30 23:27:16 asusmobile ppp[275]: tun0: Phase: deflink: carrier -> login Jun 30 23:27:16 asusmobile ppp[275]: tun0: Phase: deflink: login -> lcp Jun 30 23:27:16 asusmobile ppp[275]: tun0: LCP: FSM: Using "deflink" as a transport Jun 30 23:27:16 asusmobile ppp[275]: tun0: LCP: deflink: State change Initial --> Closed Jun 30 23:27:16 asusmobile ppp[275]: tun0: LCP: deflink: State change Closed --> Stopped Jun 30 23:27:17 asusmobile ppp[275]: tun0: LCP: deflink: LayerStart Jun 30 23:27:17 asusmobile ppp[275]: tun0: LCP: deflink: SendConfigReq(1) state = Stopped Jun 30 23:27:17 asusmobile ppp[275]: tun0: LCP: ACFCOMP[2] Jun 30 23:27:17 asusmobile ppp[275]: tun0: LCP: ACCMAP[6] 0x00000000 Jun 30 23:27:17 asusmobile ppp[275]: tun0: LCP: MRU[4] 1500 Jun 30 23:27:17 asusmobile ppp[275]: tun0: LCP: MAGICNUM[6] 0x570341ed Jun 30 23:27:17 asusmobile ppp[275]: tun0: LCP: deflink: State change Stopped --> Req-Sent Jun 30 23:27:17 asusmobile ppp[275]: tun0: LCP: deflink: RecvConfigRej(1) state = Req-Sent Jun 30 23:27:17 asusmobile ppp[275]: tun0: LCP: deflink: SendIdent(0) state = Req-Sent Jun 30 23:27:17 asusmobile ppp[275]: tun0: LCP: MAGICNUM 570341ed Jun 30 23:27:17 asusmobile ppp[275]: tun0: LCP: TEXT user-ppp 3.1 (built Jun 15 2003) Jun 30 23:27:17 asusmobile ppp[275]: tun0: LCP: ACFCOMP[2] Jun 30 23:27:17 asusmobile ppp[275]: tun0: LCP: deflink: SendConfigReq(2) state = Req-Sent Jun 30 23:27:17 asusmobile ppp[275]: tun0: LCP: ACCMAP[6] 0x00000000 Jun 30 23:27:17 asusmobile ppp[275]: tun0: LCP: MRU[4] 1500 Jun 30 23:27:17 asusmobile ppp[275]: tun0: LCP: MAGICNUM[6] 0x570341ed Jun 30 23:27:17 asusmobile ppp[275]: tun0: LCP: deflink: RecvConfigReq(32) state = Req-Sent Jun 30 23:27:17 asusmobile ppp[275]: tun0: LCP: ACCMAP[6] 0x00000000 Jun 30 23:27:17 asusmobile ppp[275]: tun0: LCP: AUTHPROTO[4] 0xc023 (PAP) Jun 30 23:27:17 asusmobile ppp[275]: tun0: LCP: MAGICNUM[6] 0x003aaa33 Jun 30 23:27:17 asusmobile ppp[275]: tun0: LCP: deflink: SendConfigAck(32) state = Req-Sent Jun 30 23:27:17 asusmobile ppp[275]: tun0: LCP: ACCMAP[6] 0x00000000 Jun 30 23:27:17 asusmobile ppp[275]: tun0: LCP: AUTHPROTO[4] 0xc023 (PAP) Jun 30 23:27:17 asusmobile ppp[275]: tun0: LCP: MAGICNUM[6] 0x003aaa33 Jun 30 23:27:17 asusmobile ppp[275]: tun0: LCP: deflink: State change Req-Sent --> Ack-Sent Jun 30 23:27:17 asusmobile ppp[275]: tun0: LCP: deflink: RecvConfigAck(2) state = Ack-Sent Jun 30 23:27:17 asusmobile ppp[275]: tun0: LCP: ACCMAP[6] 0x00000000 Jun 30 23:27:17 asusmobile ppp[275]: tun0: LCP: MRU[4] 1500 Jun 30 23:27:17 asusmobile ppp[275]: tun0: LCP: MAGICNUM[6] 0x570341ed Jun 30 23:27:17 asusmobile ppp[275]: tun0: LCP: deflink: State change Ack-Sent --> Opened Jun 30 23:27:17 asusmobile ppp[275]: tun0: LCP: deflink: LayerUp Jun 30 23:27:17 asusmobile ppp[275]: tun0: LCP: deflink: SendIdent(1) state = Opened Jun 30 23:27:17 asusmobile ppp[275]: tun0: LCP: MAGICNUM 570341ed Jun 30 23:27:17 asusmobile ppp[275]: tun0: LCP: TEXT user-ppp 3.1 (built Jun 15 2003) Jun 30 23:27:17 asusmobile ppp[275]: tun0: Phase: bundle: Authenticate Jun 30 23:27:17 asusmobile ppp[275]: tun0: Phase: deflink: his = PAP, mine = none Jun 30 23:27:17 asusmobile ppp[275]: tun0: Phase: Pap Output: ******** Jun 30 23:27:17 asusmobile ppp[275]: tun0: Warning: Sending empty PAP authname! Jun 30 23:27:17 asusmobile ppp[275]: tun0: Phase: Pap Input: SUCCESS () Jun 30 23:27:17 asusmobile ppp[275]: tun0: CCP: FSM: Using "deflink" as a transport Jun 30 23:27:17 asusmobile ppp[275]: tun0: CCP: deflink: State change Initial --> Closed Jun 30 23:27:17 asusmobile ppp[275]: tun0: CCP: deflink: LayerStart. Jun 30 23:27:17 asusmobile ppp[275]: tun0: CCP: deflink: SendConfigReq(1) state = Closed Jun 30 23:27:17 asusmobile ppp[275]: tun0: CCP: PRED1[2] Jun 30 23:27:17 asusmobile ppp[275]: tun0: CCP: deflink: State change Closed --> Req-Sent Jun 30 23:27:17 asusmobile ppp[275]: tun0: Phase: deflink: lcp -> open Jun 30 23:27:17 asusmobile ppp[275]: tun0: Phase: bundle: Network Jun 30 23:27:17 asusmobile ppp[275]: tun0: IPCP: FSM: Using "deflink" as a transport Jun 30 23:27:17 asusmobile ppp[275]: tun0: IPCP: deflink: State change Initial --> Closed Jun 30 23:27:17 asusmobile ppp[275]: tun0: IPCP: deflink: LayerStart. Jun 30 23:27:17 asusmobile ppp[275]: tun0: IPCP: deflink: SendConfigReq(1) state = Closed Jun 30 23:27:17 asusmobile ppp[275]: tun0: IPCP: IPADDR[6] 127.0.0.1 Jun 30 23:27:17 asusmobile ppp[275]: tun0: IPCP: deflink: State change Closed --> Req-Sent Jun 30 23:27:17 asusmobile ppp[275]: tun0: IPCP: deflink: RecvConfigReq(33) state = Req-Sent Jun 30 23:27:17 asusmobile ppp[275]: tun0: IPCP: IPADDR[6] 192.168.100.101 Jun 30 23:27:17 asusmobile ppp[275]: tun0: IPCP: COMPPROTO[6] 16 VJ slots with slot compression Jun 30 23:27:17 asusmobile ppp[275]: tun0: IPCP: deflink: SendConfigAck(33) state = Req-Sent Jun 30 23:27:17 asusmobile ppp[275]: tun0: IPCP: IPADDR[6] 192.168.100.101 Jun 30 23:27:17 asusmobile ppp[275]: tun0: IPCP: COMPPROTO[6] 16 VJ slots with slot compression Jun 30 23:27:17 asusmobile ppp[275]: tun0: IPCP: deflink: State change Req-Sent --> Ack-Sent Jun 30 23:27:17 asusmobile ppp[275]: tun0: IPCP: deflink: RecvConfigReq(33) state = Ack-Sent Jun 30 23:27:17 asusmobile ppp[275]: tun0: IPCP: IPADDR[6] 192.168.100.101 Jun 30 23:27:17 asusmobile ppp[275]: tun0: IPCP: COMPPROTO[6] 16 VJ slots with slot compression Jun 30 23:27:17 asusmobile ppp[275]: tun0: IPCP: deflink: SendConfigAck(33) state = Ack-Sent Jun 30 23:27:17 asusmobile ppp[275]: tun0: IPCP: IPADDR[6] 192.168.100.101 Jun 30 23:27:17 asusmobile ppp[275]: tun0: IPCP: COMPPROTO[6] 16 VJ slots with slot compression Jun 30 23:27:19 asusmobile ppp[275]: tun0: LCP: deflink: RecvTerminateReq(34) state = Opened Jun 30 23:27:19 asusmobile ppp[275]: tun0: LCP: deflink: LayerDown Jun 30 23:27:19 asusmobile ppp[275]: tun0: LCP: deflink: SendTerminateAck(34) state = Opened Jun 30 23:27:19 asusmobile ppp[275]: tun0: LCP: deflink: State change Opened --> Stopping Jun 30 23:27:19 asusmobile ppp[275]: tun0: CCP: deflink: State change Req-Sent --> Starting Jun 30 23:27:19 asusmobile ppp[275]: tun0: CCP: deflink: LayerFinish. Jun 30 23:27:19 asusmobile ppp[275]: tun0: CCP: deflink: State change Starting --> Initial Jun 30 23:27:19 asusmobile ppp[275]: tun0: Phase: deflink: open -> lcp Jun 30 23:27:19 asusmobile ppp[275]: tun0: IPCP: deflink: State change Ack-Sent --> Starting Jun 30 23:27:19 asusmobile ppp[275]: tun0: IPCP: deflink: LayerFinish. Jun 30 23:27:19 asusmobile ppp[275]: tun0: IPCP: Connect time: 2 secs: 0 octets in, 0 octets out Jun 30 23:27:19 asusmobile ppp[275]: tun0: IPCP: 0 packets in, 0 packets out Jun 30 23:27:19 asusmobile ppp[275]: tun0: IPCP: total 0 bytes/sec, peak 0 bytes/sec on Mon Jun 30 23:27:17 2003 Jun 30 23:27:19 asusmobile ppp[275]: tun0: IPCP: deflink: State change Starting --> Initial Jun 30 23:27:19 asusmobile ppp[275]: tun0: Phase: bundle: Terminate Jun 30 23:27:20 asusmobile ppp[275]: tun0: Phase: deflink: Carrier lost Jun 30 23:27:20 asusmobile ppp[275]: tun0: LCP: deflink: State change Stopping --> Starting Jun 30 23:27:20 asusmobile ppp[275]: tun0: LCP: deflink: LayerFinish Jun 30 23:27:20 asusmobile ppp[275]: tun0: LCP: deflink: State change Starting --> Initial Jun 30 23:27:20 asusmobile ppp[275]: tun0: Phase: deflink: Disconnected! Jun 30 23:27:20 asusmobile ppp[275]: tun0: Phase: deflink: lcp -> logout Jun 30 23:27:20 asusmobile ppp[275]: tun0: Phase: deflink: Disconnected! Jun 30 23:27:20 asusmobile ppp[275]: tun0: Phase: deflink: logout -> hangup Jun 30 23:27:20 asusmobile ppp[275]: tun0: Phase: deflink: Connect time: 5 secs: 240 octets in, 354 octets out Jun 30 23:27:20 asusmobile ppp[275]: tun0: Phase: deflink: 10 packets in, 11 packets out Jun 30 23:27:20 asusmobile ppp[275]: tun0: Phase: total 118 bytes/sec, peak 133 bytes/sec on Mon Jun 30 23:27:18 2003 Jun 30 23:27:21 asusmobile ppp[275]: tun0: Phase: deflink: hangup -> closed Jun 30 23:27:21 asusmobile ppp[275]: tun0: Phase: bundle: Dead Jun 30 23:27:21 asusmobile ppp[275]: tun0: Phase: PPP Terminated (normal). Jun 30 23:27:21 asusmobile ppp[274]: tun0: Phase: Parent: Child failed (errdead) Jun 30 23:27:21 asusmobile ppp[275]: tun0: Chat: Parent notified of failure -- bye! Ale
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?20030630233626.A73415>