strange PPP negotiation problem with GPRS mobile phone
Alessandro de Manzano
ale at unixmania.net
Mon Jun 30 14:37:00 PDT 2003
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
More information about the freebsd-mobile
mailing list