More info (Re: ppp dialin problems: mgetty and ppp.conf)
Timothy Luoma
lists at tntluoma.com
Mon Jan 17 07:50:00 PST 2005
[more information on the problems originally outlined at
http://lists.freebsd.org/pipermail/freebsd-questions/2005-January/
072284.html ]
updated summary: dialing into FreeBSD box sometimes fails to provide a
connection to the Internet, however, it appears that if I maintain the
connection long enough, the problem will solve itself after awhile (~10
minutes). I hope that the netstat and ppp log information below will
help someone smarter than me figure out what is going on.
More information:
I am using my Powerbook to dial in via Airport Extreme to a FreeBSD 5.3
machine running mgetty and ppp.
I am having occasional problems connecting. Sometimes when I connect,
I can only ping/ssh to the IP address of the FreeBSD machine. (ssh
often fails to connect, although it will say it is connected, it will
time out.)
I am trying to diagnose whether the problem is on the dial in end
(Airport Extreme/Powerbook) or the FreeBSD end.
I believe that something is not being correctly configured for my
routing, but I could be wrong.
In an attempt to diagnose this, I ran 'netstat -rn -f inet' from my
Powerbook when the Airport Extreme was connected and when the
connection was working perfectly:
[NOTE: when 192.168.2.1 is the Airport Extreme IP address, and shows up
on 'en1']
Routing tables [when working]
Internet:
Destination Gateway Flags Refs Use Netif
Expire
default 192.168.2.1 UGSc 5 10 en1
127 127.0.0.1 UCS 0 0 lo0
127.0.0.1 127.0.0.1 UH 23 8498 lo0
169.254 link#5 UCS 0 0 en1
192.168.2 link#5 UCS 1 0 en1
192.168.2.1 0:3:93:df:e7:6a UHLW 5 1292 en1
1178
192.168.2.2 127.0.0.1 UHS 0 3 lo0
And then, later, I ran it again when it was connected but NOT working
Routing tables [when NOT working]
Internet:
Destination Gateway Flags Refs Use Netif
Expire
default 192.168.2.1 UGSc 11 10 en1
127 127.0.0.1 UCS 0 0 lo0
127.0.0.1 127.0.0.1 UH 46 64040 lo0
169.254 link#5 UCS 0 0 en1
192.168.2 link#5 UCS 2 0 en1
192.168.2.1 0:3:93:df:e7:6a UHLW 11 281 en1
1059
192.168.2.2 127.0.0.1 UHS 1 47 lo0
192.168.2.255 link#5 UHLWb 1 3 en1
Now while I was writing this, the connection seems to have "healed
itself" automagically, and I ran netstat again (not long after the
previous NOT working example) and saw this:
Routing tables [when suddenly working again]
Internet:
Destination Gateway Flags Refs Use Netif
Expire
default 192.168.2.1 UGSc 17 13 en1
127 127.0.0.1 UCS 0 0 lo0
127.0.0.1 127.0.0.1 UH 77 66575 lo0
169.254 link#5 UCS 0 0 en1
192.168.2 link#5 UCS 2 0 en1
192.168.2.1 0:3:93:df:e7:6a UHLW 16 1464 en1
1059
192.168.2.2 127.0.0.1 UHS 1 93 lo0
192.168.2.255 link#5 UHLWb 1 6 en1
Here is the relevant ppp log data from when that connection was first
made:
Jan 17 10:18:56 freebsd ppp[2027]: Phase: Using interface: tun0
Jan 17 10:18:56 freebsd ppp[2027]: Phase: deflink: Created in closed
state
Jan 17 10:18:56 freebsd ppp[2027]: tun0: Command: default: enable
passwdauth
Jan 17 10:18:56 freebsd ppp[2027]: tun0: Command: default: set speed
115200
Jan 17 10:18:56 freebsd ppp[2027]: tun0: Command: default: set dial
ABORT BUSY ABORT NO\sCARRIER TIMEOUT 5 "" AT OK-AT-OK ATE1Q0 OK
\dATDT\TTIMEOUT 40 CONNECT
Jan 17 10:18:56 freebsd ppp[2027]: tun0: Command: default: set timeout
120
Jan 17 10:18:56 freebsd ppp[2027]: tun0: Command: default: set ifaddr
192.168.1.1/0 192.168.1.2/0 255.255.255.0 0.0.0.0
Jan 17 10:18:56 freebsd ppp[2027]: tun0: Command: default: add default
HISADDR
Jan 17 10:18:56 freebsd ppp[2027]: tun0: Warning: Add route failed:
0.0.0.0/0 already exists
Jan 17 10:18:56 freebsd ppp[2027]: tun0: Command: pap: enable pap
Jan 17 10:18:56 freebsd ppp[2027]: tun0: Command: pap: set ifaddr
192.168.1.3 192.168.1.4-192.168.1.9
Jan 17 10:18:56 freebsd ppp[2027]: tun0: IPCP: Selected IP address
192.168.1.8
Jan 17 10:18:56 freebsd ppp[2027]: tun0: Command: pap: enable proxy
Jan 17 10:18:56 freebsd ppp[2027]: tun0: Command: pap: enable passwdauth
Jan 17 10:18:56 freebsd ppp[2027]: tun0: Phase: PPP Started (direct
mode).
Jan 17 10:18:56 freebsd ppp[2027]: tun0: Phase: bundle: Establish
Jan 17 10:18:56 freebsd ppp[2027]: tun0: Phase: deflink: closed ->
opening
Jan 17 10:18:56 freebsd ppp[2027]: tun0: Phase: deflink: Connected!
Jan 17 10:18:56 freebsd ppp[2027]: tun0: Phase: deflink: opening ->
carrier
Jan 17 10:18:57 freebsd ppp[2027]: tun0: Phase: deflink: /dev/ttyd0: CD
detected
Jan 17 10:18:57 freebsd ppp[2027]: tun0: Phase: deflink: carrier -> lcp
Jan 17 10:18:57 freebsd ppp[2027]: tun0: LCP: FSM: Using "deflink" as a
transport
Jan 17 10:18:57 freebsd ppp[2027]: tun0: LCP: deflink: State change
Initial --> Closed
Jan 17 10:18:57 freebsd ppp[2027]: tun0: LCP: deflink: State change
Closed --> Stopped
Jan 17 10:18:57 freebsd ppp[2027]: tun0: LCP: deflink:
RecvConfigReq(235) state = Stopped
Jan 17 10:18:57 freebsd ppp[2027]: tun0: LCP: ACCMAP[6] 0x00000000
Jan 17 10:18:57 freebsd ppp[2027]: tun0: LCP: MAGICNUM[6] 0x00000001
Jan 17 10:18:57 freebsd ppp[2027]: tun0: LCP: deflink: SendConfigReq(1)
state = Stopped
Jan 17 10:18:57 freebsd ppp[2027]: tun0: LCP: ACFCOMP[2]
Jan 17 10:18:57 freebsd ppp[2027]: tun0: LCP: PROTOCOMP[2]
Jan 17 10:18:57 freebsd ppp[2027]: tun0: LCP: ACCMAP[6] 0x00000000
Jan 17 10:18:57 freebsd ppp[2027]: tun0: LCP: MRU[4] 1500
Jan 17 10:18:57 freebsd ppp[2027]: tun0: LCP: MAGICNUM[6] 0xcb118bb6
Jan 17 10:18:57 freebsd ppp[2027]: tun0: LCP: AUTHPROTO[4] 0xc023 (PAP)
Jan 17 10:18:57 freebsd ppp[2027]: tun0: LCP: deflink:
SendConfigAck(235) state = Stopped
Jan 17 10:18:57 freebsd ppp[2027]: tun0: LCP: ACCMAP[6] 0x00000000
Jan 17 10:18:57 freebsd ppp[2027]: tun0: LCP: MAGICNUM[6] 0x00000001
Jan 17 10:18:57 freebsd ppp[2027]: tun0: LCP: deflink: LayerStart
Jan 17 10:18:57 freebsd ppp[2027]: tun0: LCP: deflink: State change
Stopped --> Ack-Sent
Jan 17 10:18:57 freebsd ppp[2027]: tun0: LCP: deflink: RecvConfigAck(1)
state = Ack-Sent
Jan 17 10:18:57 freebsd ppp[2027]: tun0: LCP: ACFCOMP[2]
Jan 17 10:18:57 freebsd ppp[2027]: tun0: LCP: PROTOCOMP[2]
Jan 17 10:18:57 freebsd ppp[2027]: tun0: LCP: ACCMAP[6] 0x00000000
Jan 17 10:18:57 freebsd ppp[2027]: tun0: LCP: MRU[4] 1500
Jan 17 10:18:57 freebsd ppp[2027]: tun0: LCP: MAGICNUM[6] 0xcb118bb6
Jan 17 10:18:57 freebsd ppp[2027]: tun0: LCP: AUTHPROTO[4] 0xc023 (PAP)
Jan 17 10:18:57 freebsd ppp[2027]: tun0: LCP: deflink: State change
Ack-Sent --> Opened
Jan 17 10:18:57 freebsd ppp[2027]: tun0: LCP: deflink: LayerUp
Jan 17 10:18:57 freebsd ppp[2027]: tun0: Phase: bundle: Authenticate
Jan 17 10:18:57 freebsd ppp[2027]: tun0: Phase: deflink: his = none,
mine = PAP
Jan 17 10:18:57 freebsd ppp[2027]: tun0: Phase: Pap Input: REQUEST (ppp)
Jan 17 10:18:57 freebsd ppp[2027]: tun0: Warning: OpenSecret: Can't
open /etc/ppp/ppp.secret.
Jan 17 10:18:57 freebsd ppp[2027]: tun0: Phase: Pap Output: SUCCESS
Jan 17 10:18:57 freebsd ppp[2027]: tun0: Warning: OpenSecret: Can't
open /etc/ppp/ppp.secret.
[now it is my understanding that it should NOT be looking for
/etc/ppp/ppp.secret if I am using passwdauth, so something seems to be
going wrong there]
Jan 17 10:18:57 freebsd ppp[2027]: tun0: CCP: FSM: Using "deflink" as a
transport
Jan 17 10:18:57 freebsd ppp[2027]: tun0: CCP: deflink: State change
Initial --> Closed
Jan 17 10:18:57 freebsd ppp[2027]: tun0: CCP: deflink: LayerStart.
Jan 17 10:18:57 freebsd ppp[2027]: tun0: CCP: MPPE: Not usable without
CHAP81
Jan 17 10:18:57 freebsd ppp[2027]: tun0: CCP: deflink: SendConfigReq(1)
state = Closed
Jan 17 10:18:57 freebsd ppp[2027]: tun0: CCP: DEFLATE[4] win 15
Jan 17 10:18:57 freebsd ppp[2027]: tun0: CCP: PRED1[2]
Jan 17 10:18:57 freebsd ppp[2027]: tun0: CCP: deflink: State change
Closed --> Req-Sent
Jan 17 10:18:57 freebsd ppp[2027]: tun0: Phase: deflink: lcp -> open
Jan 17 10:18:57 freebsd ppp[2027]: tun0: Phase: bundle: Network
Jan 17 10:18:57 freebsd ppp[2027]: tun0: IPCP: FSM: Using "deflink" as
a transport
Jan 17 10:18:57 freebsd ppp[2027]: tun0: IPCP: deflink: State change
Initial --> Closed
Jan 17 10:18:57 freebsd ppp[2027]: tun0: IPCP: deflink: LayerStart.
Jan 17 10:18:57 freebsd ppp[2027]: tun0: IPCP: deflink:
SendConfigReq(1) state = Closed
Jan 17 10:18:57 freebsd ppp[2027]: tun0: IPCP: IPADDR[6] 192.168.1.3
Jan 17 10:18:57 freebsd ppp[2027]: tun0: IPCP: COMPPROTO[6] 16 VJ
slots with slot compression
Jan 17 10:18:57 freebsd ppp[2027]: tun0: IPCP: deflink: State change
Closed --> Req-Sent
Jan 17 10:18:58 freebsd ppp[2027]: tun0: IPCP: deflink:
RecvConfigReq(1) state = Req-Sent
Jan 17 10:18:58 freebsd ppp[2027]: tun0: IPCP: COMPPROTO[6] 16 VJ
slots with slot compression
Jan 17 10:18:58 freebsd ppp[2027]: tun0: IPCP: IPADDR[6] 0.0.0.0
Jan 17 10:18:58 freebsd ppp[2027]: tun0: IPCP: 0.0.0.0: Address invalid
or already in use
Jan 17 10:18:58 freebsd ppp[2027]: tun0: IPCP: PRIDNS[6] 0.0.0.0
Jan 17 10:18:58 freebsd ppp[2027]: tun0: IPCP: SECDNS[6] 0.0.0.0
Jan 17 10:18:58 freebsd ppp[2027]: tun0: IPCP: deflink:
SendConfigRej(1) state = Req-Sent
Jan 17 10:18:58 freebsd ppp[2027]: tun0: IPCP: PRIDNS[6] 0.0.0.0
Jan 17 10:18:58 freebsd ppp[2027]: tun0: IPCP: SECDNS[6] 0.0.0.0
Jan 17 10:18:58 freebsd ppp[2027]: tun0: LCP: deflink:
RecvProtocolRej(236) state = Opened
Jan 17 10:18:58 freebsd ppp[2027]: tun0: LCP: deflink: -- Protocol
0x80fd (Compression Control Protocol) was rejected!
Jan 17 10:18:58 freebsd ppp[2027]: tun0: CCP: deflink: State change
Req-Sent --> Stopped
Jan 17 10:18:58 freebsd ppp[2027]: tun0: IPCP: deflink:
RecvConfigAck(1) state = Req-Sent
Jan 17 10:18:58 freebsd ppp[2027]: tun0: IPCP: IPADDR[6] 192.168.1.3
Jan 17 10:18:58 freebsd ppp[2027]: tun0: IPCP: COMPPROTO[6] 16 VJ
slots with slot compression
Jan 17 10:18:58 freebsd ppp[2027]: tun0: IPCP: deflink: State change
Req-Sent --> Ack-Rcvd
Jan 17 10:18:58 freebsd ppp[2027]: tun0: LCP: deflink:
RecvProtocolRej(237) state = Opened
Jan 17 10:18:58 freebsd ppp[2027]: tun0: LCP: deflink: -- Protocol
0x8057 (Internet Protocol V6 Control Protocol) was rejected!
Jan 17 10:18:58 freebsd ppp[2027]: tun0: Phase: deflink: IPV6CP
protocol reject closes IPV6CP !
Jan 17 10:18:58 freebsd ppp[2027]: tun0: IPCP: deflink:
RecvConfigReq(2) state = Ack-Rcvd
Jan 17 10:18:58 freebsd ppp[2027]: tun0: IPCP: COMPPROTO[6] 16 VJ
slots with slot compression
Jan 17 10:18:58 freebsd ppp[2027]: tun0: IPCP: IPADDR[6] 0.0.0.0
Jan 17 10:18:58 freebsd ppp[2027]: tun0: IPCP: 0.0.0.0: Address invalid
or already in use
Jan 17 10:18:58 freebsd ppp[2027]: tun0: IPCP: deflink:
SendConfigNak(2) state = Ack-Rcvd
Jan 17 10:18:58 freebsd ppp[2027]: tun0: IPCP: IPADDR[6] 192.168.1.8
Jan 17 10:18:58 freebsd ppp[2027]: tun0: LCP: deflink:
RecvProtocolRej(238) state = Opened
Jan 17 10:18:58 freebsd ppp[2027]: tun0: LCP: deflink: -- Protocol
0x8057 (Internet Protocol V6 Control Protocol) was rejected!
Jan 17 10:18:58 freebsd ppp[2027]: tun0: Phase: deflink: IPV6CP
protocol reject closes IPV6CP !
Jan 17 10:18:58 freebsd ppp[2027]: tun0: IPCP: deflink:
RecvConfigReq(3) state = Ack-Rcvd
Jan 17 10:18:58 freebsd ppp[2027]: tun0: IPCP: COMPPROTO[6] 16 VJ
slots with slot compression
Jan 17 10:18:58 freebsd ppp[2027]: tun0: IPCP: IPADDR[6] 192.168.1.8
Jan 17 10:18:58 freebsd ppp[2027]: tun0: IPCP: deflink:
SendConfigAck(3) state = Ack-Rcvd
Jan 17 10:18:58 freebsd ppp[2027]: tun0: IPCP: COMPPROTO[6] 16 VJ
slots with slot compression
Jan 17 10:18:58 freebsd ppp[2027]: tun0: IPCP: IPADDR[6] 192.168.1.8
Jan 17 10:18:58 freebsd ppp[2027]: tun0: IPCP: deflink: State change
Ack-Rcvd --> Opened
Jan 17 10:18:58 freebsd ppp[2027]: tun0: IPCP: deflink: LayerUp.
Jan 17 10:18:58 freebsd ppp[2027]: tun0: IPCP: myaddr 192.168.1.3
hisaddr = 192.168.1.8
Jan 17 10:18:58 freebsd ppp[2027]: tun0: Warning: ff02:5::/32: Change
route failed: errno: Network is unreachable
Jan 17 10:19:01 freebsd ppp[2027]: tun0: LCP: deflink:
RecvProtocolRej(239) state = Opened
Jan 17 10:19:01 freebsd ppp[2027]: tun0: LCP: deflink: -- Protocol
0x8057 (Internet Protocol V6 Control Protocol) was rejected!
Jan 17 10:19:01 freebsd ppp[2027]: tun0: Phase: deflink: IPV6CP
protocol reject closes IPV6CP !
Jan 17 10:19:04 freebsd ppp[2027]: tun0: LCP: deflink:
RecvProtocolRej(240) state = Opened
Jan 17 10:19:04 freebsd ppp[2027]: tun0: LCP: deflink: -- Protocol
0x8057 (Internet Protocol V6 Control Protocol) was rejected!
Jan 17 10:19:04 freebsd ppp[2027]: tun0: Phase: deflink: IPV6CP
protocol reject closes IPV6CP !
Jan 17 10:19:07 freebsd ppp[2027]: tun0: LCP: deflink:
RecvProtocolRej(241) state = Opened
Jan 17 10:19:07 freebsd ppp[2027]: tun0: LCP: deflink: -- Protocol
0x8057 (Internet Protocol V6 Control Protocol) was rejected!
Jan 17 10:19:07 freebsd ppp[2027]: tun0: Phase: deflink: IPV6CP
protocol reject closes IPV6CP !
Jan 17 10:19:10 freebsd ppp[2027]: tun0: LCP: deflink:
RecvProtocolRej(242) state = Opened
Jan 17 10:19:10 freebsd ppp[2027]: tun0: LCP: deflink: -- Protocol
0x8057 (Internet Protocol V6 Control Protocol) was rejected!
Jan 17 10:19:10 freebsd ppp[2027]: tun0: Phase: deflink: IPV6CP
protocol reject closes IPV6CP !
[that is the end of the log]
it was approximately 10:30 when the connection "healed itself" but
there was no log data to explain what happened.
More information about the freebsd-questions
mailing list