Problems with 8.1, PPPoE server, and Cisco client
Paul Thornton
prt at prt.org
Tue Oct 19 20:57:11 UTC 2010
Hi all,
I'm hoping that someone can point me in the right direction to get
enough debug to troubleshoot a very annoying connection problem with
PPPoE to a Cisco.
I have a freshly installed 8.1-RELEASE amd64 box with a very simple
PPPoE daemon setup on it. This works fine for a test WinXP and Mac OS X
client so I know that fundamentally that side of things should be OK. I
have also used a similar setup (under 7.0) with all sorts of consumer
routers doing PPPoE and it "just works". The server I'm testing with
has VLANs on top of igb interfaces, and I haven't seen any other network
issues.
Using a Cisco 800 series as the client, however, things start off
working fine - connects up OK, authenticates, etc. but then it
immediately disconnects.
There is no clear error as to why the disconnect happens at either end -
hence my confusion. I've tried several routers (some direct Ethernet
link, some via VDSL) and have upgraded to the latest IOS in an attempt
to make this work, nothing changes.
Have also tried with 7.2-RELEASE in case it was an 8.X issue - again,
same problem seen.
Any hints to help debug this (from either end) would be much appreciated.
Thanks,
Paul.
Info follows:
FreeBSD vdsl02a 8.1-RELEASE FreeBSD 8.1-RELEASE #0: Tue Oct 19 14:48:21
UTC 2010 root at vdsl01a:/usr/src/sys/amd64/compile/PPPOE-ROUTER-2 amd64
ppp.conf:
default:
set log Chat Command Phase #turn on some logging. See man ppp.conf
enable pap #turn on chap and pap accounting
enable chap
allow mode direct #turn on ppp bridging
disable proxy #turn on ppp proxyarping
disable ipv6cp #don't currently support v6
set mru 1492 #set mru below 1500 (PPPoE MTU issue)
set mtu 1492 #set mtu below 1500 (PPPoE MTU issue)
set timeout 0
enable lqr echo
set echoperiod 5
accept dns
set dns 217.65.160.42
set radius /etc/ppp/radius.conf
set ifaddr 217.65.168.254/32
# access VLAN PPPoE definitions
cv1004e:
set device PPPoE:vlan1004:test
cv1005e:
set device PPPoE:vlan1005:test
The daemon is running with the following command:
> /usr/libexec/pppoed -P /var/run/pppoed-1005.pid -a test -l cv1005e vlan1005
The RADIUS plumbing works as expected, and the router gets past
authentication and gets the correct IP address.
ppp.log shows:
> Oct 19 20:05:33 vdsl02a ppp[2234]: Phase: Using interface: tun0
> Oct 19 20:05:33 vdsl02a ppp[2234]: Phase: deflink: Created in closed state
> Oct 19 20:05:33 vdsl02a ppp[2234]: Command: default: enable pap
> Oct 19 20:05:33 vdsl02a ppp[2234]: Command: default: enable chap
> Oct 19 20:05:33 vdsl02a ppp[2234]: Command: default: disable proxy
> Oct 19 20:05:33 vdsl02a ppp[2234]: Command: default: disable ipv6cp
> Oct 19 20:05:33 vdsl02a ppp[2234]: Command: default: set mru 1492
> Oct 19 20:05:33 vdsl02a ppp[2234]: Command: default: set mtu 1492
> Oct 19 20:05:33 vdsl02a ppp[2234]: Command: default: set timeout 0
> Oct 19 20:05:33 vdsl02a ppp[2234]: Command: default: enable lqr echo
> Oct 19 20:05:33 vdsl02a ppp[2234]: Command: default: set echoperiod 5
> Oct 19 20:05:33 vdsl02a ppp[2234]: Command: default: accept dns
> Oct 19 20:05:33 vdsl02a ppp[2234]: Command: default: set dns 217.65.160.42
> Oct 19 20:05:33 vdsl02a ppp[2234]: Command: default: set radius /etc/ppp/radius.conf
> Oct 19 20:05:33 vdsl02a ppp[2234]: Command: default: set ifaddr 217.65.168.254/32
> Oct 19 20:05:33 vdsl02a ppp[2234]: Command: cv1005e: set device PPPoE:vlan1005:test
> Oct 19 20:05:33 vdsl02a ppp[2234]: Phase: PPP Started (direct mode).
> Oct 19 20:05:33 vdsl02a ppp[2234]: Phase: bundle: Establish
> Oct 19 20:05:33 vdsl02a ppp[2234]: Phase: deflink: closed -> opening
> Oct 19 20:05:33 vdsl02a ppp[2234]: Phase: deflink: Link is a netgraph node
> Oct 19 20:05:33 vdsl02a ppp[2234]: Phase: deflink: Connected!
> Oct 19 20:05:33 vdsl02a ppp[2234]: Phase: deflink: opening -> carrier
> Oct 19 20:05:33 vdsl02a ppp[2234]: Phase: deflink: carrier -> lcp
> Oct 19 20:05:33 vdsl02a ppp[2234]: Phase: bundle: Authenticate
> Oct 19 20:05:33 vdsl02a ppp[2234]: Phase: deflink: his = none, mine = CHAP 0x05
> Oct 19 20:05:33 vdsl02a ppp[2234]: Phase: Chap Output: CHALLENGE
> Oct 19 20:05:36 vdsl02a ppp[2234]: Phase: Chap Output: CHALLENGE
> Oct 19 20:05:36 vdsl02a ppp[2234]: Phase: Chap Input: RESPONSE dropped (got id 1, not 2)
> Oct 19 20:05:36 vdsl02a ppp[2234]: Phase: Chap Input: RESPONSE (16 bytes from VT123456789 at vdsl01)
> Oct 19 20:05:36 vdsl02a ppp[2234]: Phase: Radius: Request sent
> Oct 19 20:05:36 vdsl02a ppp[2234]: Phase: Radius(auth): ACCEPT received
> Oct 19 20:05:36 vdsl02a ppp[2234]: Phase: IP 217.65.167.1
> Oct 19 20:05:36 vdsl02a ppp[2234]: Phase: Route: 217.65.167.64/29 217.65.167.1 1
> Oct 19 20:05:36 vdsl02a ppp[2234]: Phase: MTU 1492
> Oct 19 20:05:36 vdsl02a ppp[2234]: Phase: Netmask 255.255.255.255
> Oct 19 20:05:36 vdsl02a ppp[2234]: Phase: Chap Output: SUCCESS
> Oct 19 20:05:36 vdsl02a ppp[2234]: Warning: iface add: ioctl(SIOCAIFADDR, 217.65.168.254 -> 217.65.167.1): File exists
> Oct 19 20:05:36 vdsl02a ppp[2234]: Phase: deflink: lcp -> open
> Oct 19 20:05:36 vdsl02a ppp[2234]: Phase: bundle: Network
> Oct 19 20:05:36 vdsl02a ppp[2234]: Phase: deflink: open -> lcp
> Oct 19 20:05:36 vdsl02a ppp[2234]: Phase: bundle: Terminate
> Oct 19 20:05:36 vdsl02a ppp[2234]: Phase: deflink: read (0): Got zero bytes
> Oct 19 20:05:36 vdsl02a ppp[2234]: Phase: deflink: Disconnected!
> Oct 19 20:05:36 vdsl02a ppp[2234]: Phase: deflink: Connect time: 3 secs: 221 octets in, 241 octets out
> Oct 19 20:05:36 vdsl02a ppp[2234]: Phase: deflink: 7 packets in, 10 packets out
> Oct 19 20:05:36 vdsl02a ppp[2234]: Phase: total 154 bytes/sec, peak 142 bytes/sec on Tue Oct 19 20:05:34 2010
> Oct 19 20:05:36 vdsl02a ppp[2234]: Phase: deflink: lcp -> closed
> Oct 19 20:05:36 vdsl02a ppp[2234]: Phase: bundle: Dead
> Oct 19 20:05:36 vdsl02a ppp[2234]: Phase: PPP Terminated (normal).
And every time the router attempts to reconnect, the same thing is seen.
Here is the log from the router's perspective:
> *Oct 19 20:19:49.955: Sending PADI: Interface = GigabitEthernet0
> *Oct 19 20:19:49.955: PPPoE 0: I PADO R:d8d3.85c1.5eed L:5475.d038.ca7a Gi0
> *Oct 19 20:19:52.003: PPPOE: we've got our pado and the pado timer went off
> *Oct 19 20:19:52.003: OUT PADR from PPPoE Session
> *Oct 19 20:19:52.003: PPPoE 48: I PADS R:d8d3.85c1.5eed L:5475.d038.ca7a Gi0
> *Oct 19 20:19:52.003: IN PADS from PPPoE Session
> *Oct 19 20:19:52.003: %DIALER-6-BIND: Interface Vi2 bound to profile Di0
> *Oct 19 20:19:52.003: PPPoE: Virtual Access interface obtained.
> *Oct 19 20:19:52.003: PPPoE : encap string prepared
> *Oct 19 20:19:52.003: [0]PPPoE 48: data path set to PPPoE Client
> *Oct 19 20:19:52.007: %LINK-3-UPDOWN: Interface Virtual-Access2, changed state to up
> *Oct 19 20:19:52.007: Vi2 PPP: Sending cstate UP notification
> *Oct 19 20:19:52.007: Vi2 PPP: Processing CstateUp message
> *Oct 19 20:19:52.011: PPP: Alloc Context [857AB7A4]
> *Oct 19 20:19:52.011: ppp67 PPP: Phase is ESTABLISHING
> *Oct 19 20:19:52.011: Vi2 PPP: Using dialer call direction
> *Oct 19 20:19:52.011: Vi2 PPP: Treating connection as a callout
> *Oct 19 20:19:52.011: Vi2 PPP: Session handle[91000003] Session id[67]
> *Oct 19 20:19:52.011: Vi2 LCP: Event[OPEN] State[Initial to Starting]
> *Oct 19 20:19:52.011: Vi2 PPP: No remote authentication for call-out
> *Oct 19 20:19:52.011: Vi2 LCP: O CONFREQ [Starting] id 1 len 14
> *Oct 19 20:19:52.011: Vi2 LCP: MRU 1492 (0x010405D4)
> *Oct 19 20:19:52.011: Vi2 LCP: MagicNumber 0x950F314C (0x0506950F314C)
> *Oct 19 20:19:52.011: Vi2 LCP: Event[UP] State[Starting to REQsent]
> *Oct 19 20:19:52.115: Vi2 LCP: I CONFREQ [REQsent] id 1 len 37
> *Oct 19 20:19:52.115: Vi2 LCP: ACFC (0x0802)
> *Oct 19 20:19:52.115: Vi2 LCP: PFC (0x0702)
> *Oct 19 20:19:52.115: Vi2 LCP: ACCM 0x00000000 (0x020600000000)
> *Oct 19 20:19:52.115: Vi2 LCP: MRU 1492 (0x010405D4)
> *Oct 19 20:19:52.115: Vi2 LCP: MagicNumber 0xFC1067FE (0x0506FC1067FE)
> *Oct 19 20:19:52.115: Vi2 LCP: QualityType 0xC025 period 500 (0x0408C025000001F4)
> *Oct 19 20:19:52.115: Vi2 LCP: AuthProto CHAP (0x0305C22305)
> *Oct 19 20:19:52.115: Vi2 LCP: O CONFNAK [REQsent] id 1 len 12
> *Oct 19 20:19:52.115: Vi2 LCP: QualityType 0xC025 period 1000 (0x0408C025000003E8)
> *Oct 19 20:19:52.115: Vi2 LCP: Event[Receive ConfReq-] State[REQsent to REQsent]
> *Oct 19 20:19:52.115: Vi2 LCP: I CONFACK [REQsent] id 1 len 14
> *Oct 19 20:19:52.115: Vi2 LCP: MRU 1492 (0x010405D4)
> *Oct 19 20:19:52.115: Vi2 LCP: MagicNumber 0x950F314C (0x0506950F314C)
> *Oct 19 20:19:52.115: Vi2 LCP: Event[Receive ConfAck] State[REQsent to ACKrcvd]
> *Oct 19 20:19:52.115: Vi2 LCP: I CONFREQ [ACKrcvd] id 2 len 37
> *Oct 19 20:19:52.115: Vi2 LCP: ACFC (0x0802)
> *Oct 19 20:19:52.115: Vi2 LCP: PFC (0x0702)
> *Oct 19 20:19:52.115: Vi2 LCP: ACCM 0x00000000 (0x020600000000)
> *Oct 19 20:19:52.115: Vi2 LCP: MRU 1492 (0x010405D4)
> *Oct 19 20:19:52.115: Vi2 LCP: MagicNumber 0xFC1067FE (0x0506FC1067FE)
> *Oct 19 20:19:52.115: Vi2 LCP: QualityType 0xC025 period 1000 (0x0408C025000003E8)
> *Oct 19 20:19:52.115: Vi2 LCP: AuthProto CHAP (0x0305C22305)
> *Oct 19 20:19:52.115: Vi2 LCP: O CONFACK [ACKrcvd] id 2 len 37
> *Oct 19 20:19:52.115: Vi2 LCP: ACFC (0x0802)
> *Oct 19 20:19:52.115: Vi2 LCP: PFC (0x0702)
> *Oct 19 20:19:52.115: Vi2 LCP: ACCM 0x00000000 (0x020600000000)
> *Oct 19 20:19:52.115: Vi2 LCP: MRU 1492 (0x010405D4)
> *Oct 19 20:19:52.115: Vi2 LCP: MagicNumber 0xFC1067FE (0x0506FC1067FE)
> *Oct 19 20:19:52.115: Vi2 LCP: QualityType 0xC025 period 1000 (0x0408C025000003E8)
> *Oct 19 20:19:52.115: Vi2 LCP: AuthProto CHAP (0x0305C22305)
> *Oct 19 20:19:52.115: Vi2 LCP: Event[Receive ConfReq+] State[ACKrcvd to Open]
> *Oct 19 20:19:52.115: Vi2 LQM: I state Open magic 0xFC1067FE len 48
> *Oct 19 20:19:52.115: Vi2 LQM: LastOutLQRs 0 LastOutPackets/Octets 0/0
> *Oct 19 20:19:52.115: Vi2 LQM: PeerInLQRs 0 PeerInPackets/Discards/Errors/Octets 0/0/0/0
> *Oct 19 20:19:52.115: Vi2 LQM: PeerOutLQRs 1 PeerOutPackets/Octets 4/148
> *Oct 19 20:19:52.115: Vi2 PPP: Queue CHAP code[1] id[1]
> *Oct 19 20:19:52.139: Vi2 PPP: Phase is AUTHENTICATING, by the peer
> *Oct 19 20:19:52.139: Vi2 CHAP: Redirect packet to Vi2
> *Oct 19 20:19:52.139: Vi2 CHAP: I CHALLENGE id 1 len 21
> *Oct 19 20:19:52.139: Vi2 CHAP: No name received from peer
> *Oct 19 20:19:52.139: Vi2 CHAP: Using hostname from interface CHAP
> *Oct 19 20:19:52.139: Vi2 CHAP: Using password from interface CHAP
> *Oct 19 20:19:52.139: Vi2 CHAP: O RESPONSE id 1 len 46 from "VT123456789 at vdsl01"
> *Oct 19 20:19:52.139: Vi2 LCP: State is Open
> *Oct 19 20:19:52.147: Vi2 CHAP: I SUCCESS id 1 len 13 msg is "Welcome!!"
> *Oct 19 20:19:52.147: Vi2 PPP: Phase is FORWARDING, Attempting Forward
> *Oct 19 20:19:52.147: Vi2 PPP: Queue CCP code[1] id[1]
> *Oct 19 20:19:52.147: Vi2 PPP: Queue IPCP code[1] id[1]
> *Oct 19 20:19:52.151: Vi2 PPP DISC: Lower Layer disconnected
> *Oct 19 20:19:52.151: Vi2 LCP: O TERMREQ [Open] id 2 len 4
> *Oct 19 20:19:52.151: Vi2 LCP: Event[CLOSE] State[Open to Closing]
> *Oct 19 20:19:52.151: Vi2 PPP: Phase is TERMINATING
> *Oct 19 20:19:52.151: PPPoE : Shutting down client session
> *Oct 19 20:19:52.155: [0]PPPoE 48: O PADT R:d8d3.85c1.5eed L:5475.d038.ca7a Gi0
> *Oct 19 20:19:52.155: PPPoE: Failed to add PPPoE switching subblock
> *Oct 19 20:19:52.155: %DIALER-6-UNBIND: Interface Vi2 unbound from profile Di0
> *Oct 19 20:19:52.155: Vi2 PPP: Block vaccess from being freed [0x10]
> *Oct 19 20:19:52.155: Vi2 LCP: Event[DOWN] State[Closing to Initial]
> *Oct 19 20:19:52.155: Vi2 PPP: Unlocked by [0x10] Still Locked by [0x0]
> *Oct 19 20:19:52.155: Vi2 PPP: Free previously blocked vaccess
> *Oct 19 20:19:52.155: Vi2 PPP: Phase is DOWN
> *Oct 19 20:19:52.155: PPPoE 48: I PADT R:d8d3.85c1.5eed L:5475.d038.ca7a Gi0
> *Oct 19 20:19:52.159: %LINK-3-UPDOWN: Interface Virtual-Access2, changed state to down
> *Oct 19 20:19:52.159: PPPoE: Unexpected Event!. PPPoE switching Subblockdestroy called
Kernel config has the following additional options:
> +options HZ=1000
> +options NETGRAPH
> +options NETGRAPH_PPPOE
> +options NETGRAPH_SOCKET
> +
> +options NETGRAPH_CISCO
> +options NETGRAPH_ECHO
> +options NETGRAPH_FRAME_RELAY
> +options NETGRAPH_HOLE
> +options NETGRAPH_LMI
> +options NETGRAPH_RFC1490
> +options NETGRAPH_TTY
> +
> +options NETGRAPH_ASYNC
> +options NETGRAPH_BPF
> +options NETGRAPH_ETHER
> +options NETGRAPH_IFACE
> +options NETGRAPH_KSOCKET
> +options NETGRAPH_L2TP
> +options NETGRAPH_MPPC_ENCRYPTION
> +options NETGRAPH_PPP
> +options NETGRAPH_PPTPGRE
> +options NETGRAPH_TEE
> +options NETGRAPH_UI
> +options NETGRAPH_VJC
> +
> +options DEVICE_POLLING
More information about the freebsd-net
mailing list