Problems with 8.1, PPPoE server, and Cisco client
Paul Thornton
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@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@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@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
_______________________________________________
freeb...@freebsd.org mailing list
http://lists.freebsd.org/mailman/listinfo/freebsd-net
To unsubscribe, send any mail to "freebsd-net...@freebsd.org"
Julian Elischer
>
> 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.
Immediate things to look at:
Wireshark understands all the protocols in question so get packet
captures of good and
bad sessions (as similar as you can) and see what is different.
(wireshark reads
tcpdump files so it's easy to capture).
also for fun you might look at the documentation for running mpd.. I
dont' remember if it
can do a pppoe SERVER but I vaguely remember that it can.
Bjoern A. Zeeb
> default:
> set log Chat Command Phase #turn on some logging. See man ppp.conf
increase the log level for your test. According to the Cisco debug
log the O(ther), which would be the FreeBSD to my understanding, sends
a TERMREQ and closes the connection.
>> Oct 19 20:05:36 vdsl02a ppp[2234]: Warning: iface add: ioctl(SIOCAIFADDR, 217.65.168.254 -> 217.65.167.1): File exists
Not sure why that happens.
>> 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
And here it goes but the missing, probably lcp, information is
missing in the log due to our log level.
>> *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
And here it goes away. And thanks to Cisco you cannot say why either
here. The line above could be a hint if you can find it but ...
/bz
--
Bjoern A. Zeeb Welcome a new stage of life.
Alireza Torabi
Ian Smith
> 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.
Just to add to what Julian and Bjoern said .. something about addressing
/ routing looks maybe odd to me, without knowing your network setup or
much at all about vlans.
Adding both lcp and ipcp to ppp logging should confirm success (or
indicate problems) at those levels.
> set ifaddr 217.65.168.254/32
> > Oct 19 20:05:33 vdsl02a ppp[2234]: Command: default: set ifaddr 217.65.168.254/32
> > 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
Does that all look right?
> > Oct 19 20:05:36 vdsl02a ppp[2234]: Warning: iface add: ioctl(SIOCAIFADDR, 217.65.168.254 -> 217.65.167.1): File exists
>From memory, 'File exists' means more like 'route exists'
> > Oct 19 20:05:36 vdsl02a ppp[2234]: Phase: deflink: open -> lcp
> > Oct 19 20:05:36 vdsl02a ppp[2234]: Phase: bundle: Terminate
Bang.
> And every time the router attempts to reconnect, the same thing is seen.
>
> Here is the log from the router's perspective:
Maybe add IPCP logging on the Cisco too? No addressing info shown here.
> > *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
Definitely looks like LCP, but that could come from IPCP layer .. I've
been using mpd for so long I hardly remember ppp logging.
Just another stab in the dark,
Ian
Julian Elischer
> On Tue, 19 Oct 2010, Paul Thornton wrote:
>
>
>
> > > Oct 19 20:05:36 vdsl02a ppp[2234]: Warning: iface add: ioctl(SIOCAIFADDR, 217.65.168.254 -> 217.65.167.1): File exists
>
> > From memory, 'File exists' means more like 'route exists'
yes
in 8.x the routing code changed somewhat.
it is possible it is trying to put in a route that we now already put
in automatically.
> > > Oct 19 20:05:36 vdsl02a ppp[2234]: Phase: deflink: open -> lcp
> > > Oct 19 20:05:36 vdsl02a ppp[2234]: Phase: bundle
Julian Elischer
> Hi,
>
> On 19/10/2010 22:06, Julian Elischer wrote:
>> Wireshark understands all the protocols in question so get packet
>> captures of good and
>> bad sessions (as similar as you can) and see what is different.
>> (wireshark reads
>> tcpdump files so it's easy to capture).
> what is happening... still not sure about the why, but progress is being
> made. Thanks for that nudge.
>
> With a Windows XP client (I know, it was nearby though) the following
> things happen:
>
> Server -> Client PPP CHAP Success (Welcome!! message).
> Server -> Client PPP CCP config request
> Server -> Client IPCP Config request (setting IP address of server end)
> Client -> Server PPP CCP config request
> - and they carry on here working fine -
>
> With the Cisco client, things break at this point:
> Server -> Client PPP CHAP Success (Welcome!! message).
> Server -> Client PPP CCP Config request
> Server -> Client IPCP Config Request (setting IP address of server end)
> Client -> Server Termination request
> Server -> Client Termination ack
>
> So either that CCP request or the IPCP request is upsetting the Cisco.
> However, even with its debugging fully on for PPP, it isn't clear why.
> Initially, my server was requesting deflate compression and VJ
> compression - so I disabled all compression options in ppp.conf but it
> made no difference. The tcpdumps were taken after compression was disabled.
>
> The cisco config being used on the WAN interface and Dialer interface
> for testing is as follows. This is an 891 and so is an Ethernet WAN
> port (no VDSL or other cable interface to add problems):
>
> interface GigabitEthernet0
> no ip address
> ip accounting output-packets
> duplex auto
> speed auto
> pppoe enable group global
> pppoe-client dial-pool-number 1
> !
> interface Dialer0
> description PPPoE dialer
> mtu 1492
> ip address negotiated
> no ip redirects
> no ip proxy-arp
> ip accounting output-packets
> encapsulation ppp
> ip tcp adjust-mss 1452
> dialer pool 1
> dialer-group 1
> ppp mtu adaptive
> ppp authentication chap callin optional
> ppp chap hostname VT123456789@vdsl01
> ppp chap password 0 LetMeIn123
> !
> !
> ip route 0.0.0.0 0.0.0.0 Dialer0
> !
> dialer-list 1 protocol ip permit
> !
>
>
>
>
>
> Here is part of the tcpdump with the XP client, starting at the CHAP
> success message. I've included quite a lot as there seems to be
> something going on with IPCP and setting DNS addresses - is this normal?
> (address ending 5e:ed is the server):
>
[...]
> And here is the similar section from the Cisco router, it all goes
> downhill quickly (address ending 5e:ed is the server):
>
have you tried to connect this cisco router to anything else pppoe?
(take it home and make it connect to your ISP for example?)
The command from the server to set an address seems ok
so I wonder if there is some setting on the cisco that doesn't like it.
Unfortunately, despite having worked for cisco, my IOS
foo is pretty weak.
>> 14:59:44.053482 d8:d3:85:c1:5e:ed> 54:75:d0:38:ca:7a, ethertype PPPoE S (0x8864), length 35: PPPoE [ses 0x21] CHAP (0xc223), length 15: CHAP, Success (0x03), id 1, Msg Welcome!!
>> 14:59:44.053491 d8:d3:85:c1:5e:ed> 54:75:d0:38:ca:7a, ethertype PPPoE S (0x8864), length 26: PPPoE [ses 0x21] unknown (0x80fd), length 6: unknown ctrl-proto (0x80fd), Conf-Request (0x01), id 1, length 6
>> 14:59:44.053498 d8:d3:85:c1:5e:ed> 54:75:d0:38:ca:7a, ethertype PPPoE S (0x8864), length 32: PPPoE [ses 0x21] IPCP (0x8021), length 12: IPCP, Conf-Request (0x01), id 1, length 12
>> encoded length 10 (=Option(s) length 6)
>> 0x0000: 8021 0101 000a
>> IP-Addr Option (0x03), length 6: 217.65.168.254
>> 0x0000: d941 a8fe
>> 14:59:44.059344 54:75:d0:38:ca:7a> d8:d3:85:c1:5e:ed, ethertype PPPoE S (0x8864), length 60: PPPoE [ses 0x21] LCP (0xc021), length 6: LCP, Term-Request (0x05), id 2, length 6
>> 14:59:44.059739 d8:d3:85:c1:5e:ed> 54:75:d0:38:ca:7a, ethertype PPPoE S (0x8864), length 26: PPPoE [ses 0x21] LCP (0xc021), length 6: LCP, Term-Ack (0x06), id 2, length 6
>> 14:59:44.060925 54:75:d0:38:ca:7a> d8:d3:85:c1:5e:ed, ethertype PPPoE D (0x8863), length 60: PPPoE PADT [ses 0x21]
>> 14:59:44.060939 d8:d3:85:c1:5e:ed> 54:75:d0:38:ca:7a, ethertype PPPoE D (0x8863), length 38: PPPoE PADT [ses 0x21] [Generic-Error "session closed"]
Ian Smith
[..]
> With a Windows XP client (I know, it was nearby though) the following
> things happen:
>
> Server -> Client PPP CHAP Success (Welcome!! message).
> Server -> Client PPP CCP config request
> Server -> Client IPCP Config request (setting IP address of server end)
> Client -> Server PPP CCP config request
> - and they carry on here working fine -
>
> With the Cisco client, things break at this point:
> Server -> Client PPP CHAP Success (Welcome!! message).
> Server -> Client PPP CCP Config request
> Server -> Client IPCP Config Request (setting IP address of server end)
> Client -> Server Termination request
> Server -> Client Termination ack
>
> So either that CCP request or the IPCP request is upsetting the Cisco.
My money's on IPCP or maybe LCP so far ..
> However, even with its debugging fully on for PPP, it isn't clear why.
> Initially, my server was requesting deflate compression and VJ
> compression - so I disabled all compression options in ppp.conf but it
> made no difference. The tcpdumps were taken after compression was disabled.
Good idea, keeps the logging reasonable meanwhile ..
Left to those who speak cisco ..
> Here is part of the tcpdump with the XP client, starting at the CHAP
> success message. I've included quite a lot as there seems to be
> something going on with IPCP and setting DNS addresses - is this normal?
Looks pretty normal. Omitting 'unknown ctrl-proto (0x80fd)' MPPC stuff:
> (address ending 5e:ed is the server):
>
> > 14:40:27.733755 d8:d3:85:c1:5e:ed > 18:a9:05:db:8e:5c, ethertype PPPoE S (0x8864), length 35: PPPoE [ses 0x20] CHAP (0xc223), length 15: CHAP, Success (0x03), id 1, Msg Welcome!!
> > 14:40:27.733764 d8:d3:85:c1:5e:ed > 18:a9:05:db:8e:5c, ethertype PPPoE S (0x8864), length 26: PPPoE [ses 0x20] unknown (0x80fd), length 6: unknown ctrl-proto (0x80fd), Conf-Request (0x01), id 1, length 6
> > 14:40:27.733770 d8:d3:85:c1:5e:ed > 18:a9:05:db:8e:5c, ethertype PPPoE S (0x8864), length 32: PPPoE [ses 0x20] IPCP (0x8021), length 12: IPCP, Conf-Request (0x01), id 1, length 12
> > encoded length 10 (=Option(s) length 6)
> > 0x0000: 8021 0101 000a
> > IP-Addr Option (0x03), length 6: 217.65.168.254
> > 0x0000: d941 a8fe
we want this address.
> > 14:40:27.741992 18:a9:05:db:8e:5c > d8:d3:85:c1:5e:ed, ethertype PPPoE S (0x8864), length 60: PPPoE [ses 0x20] IPCP (0x8021), length 36: IPCP, Conf-Request (0x01), id 7, length 36
> > encoded length 34 (=Option(s) length 30)
> > 0x0000: 8021 0107 0022
> > IP-Addr Option (0x03), length 6: 0.0.0.0
> > 0x0000: 0000 0000
> > Pri-DNS Option (0x81), length 6: 0.0.0.0
> > 0x0000: 0000 0000
> > Pri-NBNS Option (0x82), length 6: 0.0.0.0
> > 0x0000: 0000 0000
> > Sec-DNS Option (0x83), length 6: 0.0.0.0
> > 0x0000: 0000 0000
> > Sec-NBNS Option (0x84), length 6: 0.0.0.0
> > 0x0000: 0000 0000
it's open to persuasion for all these.
> > 14:40:27.742107 d8:d3:85:c1:5e:ed > 18:a9:05:db:8e:5c, ethertype PPPoE S (0x8864), length 38: PPPoE [ses 0x20] IPCP (0x8021), length 18: IPCP, Conf-Reject (0x04), id 7, length 18
> > encoded length 16 (=Option(s) length 12)
> > 0x0000: 8021 0407 0010
> > Pri-NBNS Option (0x82), length 6: 0.0.0.0
> > 0x0000: 0000 0000
> > Sec-NBNS Option (0x84), length 6: 0.0.0.0
> > 0x0000: 0000 0000
we don't do NBNS.
> > 14:40:27.742559 18:a9:05:db:8e:5c > d8:d3:85:c1:5e:ed, ethertype PPPoE S (0x8864), length 60: PPPoE [ses 0x20] IPCP (0x8021), length 12: IPCP, Conf-Ack (0x02), id 1, length 12
> > encoded length 10 (=Option(s) length 6)
> > 0x0000: 8021 0201 000a
> > IP-Addr Option (0x03), length 6: 217.65.168.254
> > 0x0000: d941 a8fe
it's happy with our IP addr.
> > 14:40:27.756230 18:a9:05:db:8e:5c > d8:d3:85:c1:5e:ed, ethertype PPPoE S (0x8864), length 60: PPPoE [ses 0x20] IPCP (0x8021), length 24: IPCP, Conf-Request (0x01), id 9, length 24
> > encoded length 22 (=Option(s) length 18)
> > 0x0000: 8021 0109 0016
> > IP-Addr Option (0x03), length 6: 0.0.0.0
> > 0x0000: 0000 0000
> > Pri-DNS Option (0x81), length 6: 0.0.0.0
> > 0x0000: 0000 0000
> > Sec-DNS Option (0x83), length 6: 0.0.0.0
> > 0x0000: 0000 0000
it still needs these.
> > 14:40:27.756316 d8:d3:85:c1:5e:ed > 18:a9:05:db:8e:5c, ethertype PPPoE S (0x8864), length 44: PPPoE [ses 0x20] IPCP (0x8021), length 24: IPCP, Conf-Nack (0x03), id 9, length 24
> > encoded length 22 (=Option(s) length 18)
> > 0x0000: 8021 0309 0016
> > IP-Addr Option (0x03), length 6: 217.65.167.128
> > 0x0000: d941 a780
> > Pri-DNS Option (0x81), length 6: 217.65.160.42
> > 0x0000: d941 a02a
> > Sec-DNS Option (0x83), length 6: 255.255.255.255
> > 0x0000: ffff ffff
so we offer it these.
> > 14:40:27.771794 18:a9:05:db:8e:5c > d8:d3:85:c1:5e:ed, ethertype PPPoE S (0x8864), length 60: PPPoE [ses 0x20] IPCP (0x8021), length 24: IPCP, Conf-Request (0x01), id 10, length 24
> > encoded length 22 (=Option(s) length 18)
> > 0x0000: 8021 010a 0016
> > IP-Addr Option (0x03), length 6: 217.65.167.128
> > 0x0000: d941 a780
> > Pri-DNS Option (0x81), length 6: 217.65.160.42
> > 0x0000: d941 a02a
> > Sec-DNS Option (0x83), length 6: 255.255.255.255
> > 0x0000: ffff ffff
it asks for just what we've offered, ok ..
> > 14:40:27.779058 d8:d3:85:c1:5e:ed > 18:a9:05:db:8e:5c, ethertype PPPoE S (0x8864), length 44: PPPoE [ses 0x20] IPCP (0x8021), length 24: IPCP, Conf-Ack (0x02), id 10, length 24
> > encoded length 22 (=Option(s) length 18)
> > 0x0000: 8021 020a 0016
> > IP-Addr Option (0x03), length 6: 217.65.167.128
> > 0x0000: d941 a780
> > Pri-DNS Option (0x81), length 6: 217.65.160.42
> > 0x0000: d941 a02a
> > Sec-DNS Option (0x83), length 6: 255.255.255.255
> > 0x0000: ffff ffff
so we ack those. Ready to roll at IPCP level.
> And here is the similar section from the Cisco router, it all goes
> downhill quickly (address ending 5e:ed is the server):
>
> > 14:59:44.053482 d8:d3:85:c1:5e:ed > 54:75:d0:38:ca:7a, ethertype PPPoE S (0x8864), length 35: PPPoE [ses 0x21] CHAP (0xc223), length 15: CHAP, Success (0x03), id 1, Msg Welcome!!
> > 14:59:44.053491 d8:d3:85:c1:5e:ed > 54:75:d0:38:ca:7a, ethertype PPPoE S (0x8864), length 26: PPPoE [ses 0x21] unknown (0x80fd), length 6: unknown ctrl-proto (0x80fd), Conf-Request (0x01), id 1, length 6
> > 14:59:44.053498 d8:d3:85:c1:5e:ed > 54:75:d0:38:ca:7a, ethertype PPPoE S (0x8864), length 32: PPPoE [ses 0x21] IPCP (0x8021), length 12: IPCP, Conf-Request (0x01), id 1, length 12
> > encoded length 10 (=Option(s) length 6)
> > 0x0000: 8021 0101 000a
> > IP-Addr Option (0x03), length 6: 217.65.168.254
> > 0x0000: d941 a8fe
we want this IP address.
> > 14:59:44.059344 54:75:d0:38:ca:7a > d8:d3:85:c1:5e:ed, ethertype PPPoE S (0x8864), length 60: PPPoE [ses 0x21] LCP (0xc021), length 6: LCP, Term-Request (0x05), id 2, length 6
and it requests termination, that's it. Any reason the Cisco might
reject that address? It's not even being too polite about it, not even
a friendly Conf-Reject ..
> > 14:59:44.059739 d8:d3:85:c1:5e:ed > 54:75:d0:38:ca:7a, ethertype PPPoE S (0x8864), length 26: PPPoE [ses 0x21] LCP (0xc021), length 6: LCP, Term-Ack (0x06), id 2, length 6
we ack its termination request.
> > 14:59:44.060925 54:75:d0:38:ca:7a > d8:d3:85:c1:5e:ed, ethertype PPPoE D (0x8863), length 60: PPPoE PADT [ses 0x21]
> > 14:59:44.060939 d8:d3:85:c1:5e:ed > 54:75:d0:38:ca:7a, ethertype PPPoE D (0x8863), length 38: PPPoE PADT [ses 0x21] [Generic-Error "session closed"]
dunno.
> Many thanks for ideas, suggestions, etc. so far. I'm not well clued up
> on the inner workings of PPP so any pointers to understand the IPCP or
> CCP requests that seem to be causing the problem would be welcome.
I suspect that the ppp log from Greeting past LCP close including LCP,
IPCP and (why not?) CCP logging with the cisco might show what's not
acceptable, and to whom ..
cheers, Ian
Alireza Torabi
Paul Thornton
things for a few days, and hopefully have some more information that
might help point in the right direction for a fix / where to debug next.
On 20/10/2010 17:16, Julian Elischer wrote:
> have you tried to connect this cisco router to anything else pppoe?
> (take it home and make it connect to your ISP for example?)
The Cisco client does work to a Cisco router acting as a PPPoE server -
I used a 891 (client) to a 3945 (server) and using an established setup
that is known to work, I collected a happy tcpdump. Of course that
doesn't tell us why there was such an issue with the FreeBSD ppp server
and it looks very similar to me.
I'm also going to give mpd a go and see if that works - but if it tries
the same config options as pppoed then I may be straight back to where I
am now.
Thanks to everyone for their help with this.
So here is the dump from a known good setup, IOS at both ends - starting
from the CHAP success point again. This time, both ends play the game
and agree amongst themselves what they will and won't do as expected
(many thanks to Ian here for the commentary as to what was going on in
the exchanges I have):
> 20:29:10.200860 PPPoE [ses 0x13] CHAP, Response (0x02), id 1, Value 8f917e3cd84fd4b3a5e8b705655bf16772d0cd1462392eed8bb4ab0ccb7f75bb2d01695ac26cdc07127b4fb3435a279a01, Name VT123456789@vdsl01.v
> 20:29:14.501312 PPPoE [ses 0x13] CHAP, Success (0x03), id 1, Msg
> 20:29:14.501702 PPPoE [ses 0x13] IPCP, Conf-Request (0x01), id 1, length 12
> encoded length 10 (=Option(s) length 6)
> 0x0000: 8021 0101 000a
> IP-Addr Option (0x03), length 6: 109.71.168.123
> 0x0000: 6d47 a87b
> 20:29:14.504344 PPPoE [ses 0x13] IPCP, Conf-Request (0x01), id 1, length 12
> encoded length 10 (=Option(s) length 6)
> 0x0000: 8021 0101 000a
> IP-Addr Option (0x03), length 6: 0.0.0.0
> 0x0000: 0000 0000
> 20:29:14.504497 PPPoE [ses 0x13] unknown PPP protocol (0x8207)
> 0x0000: 0101 0004
> 20:29:14.504669 PPPoE [ses 0x13] IPCP, Conf-Ack (0x02), id 1, length 12
> encoded length 10 (=Option(s) length 6)
> 0x0000: 8021 0201 000a
> IP-Addr Option (0x03), length 6: 109.71.168.123
> 0x0000: 6d47 a87b
> 20:29:14.505200 PPPoE [ses 0x13] IPCP, Conf-Nack (0x03), id 1, length 12
> encoded length 10 (=Option(s) length 6)
> 0x0000: 8021 0301 000a
> IP-Addr Option (0x03), length 6: 109.71.174.50
> 0x0000: 6d47 ae32
> 20:29:14.505290 PPPoE [ses 0x13] LCP, Prot-Reject (0x08), id 2, length 12
> encoded length 10 (=Option(s) length 6)
> 0x0000: c021 0802 000a
> Rejected unknown Protocol (0x8207)
> Rejected Packet
> 0x0000: 0101 0006 0000 0000
> 20:29:14.505800 PPPoE [ses 0x13] IPCP, Conf-Request (0x01), id 2, length 12
> encoded length 10 (=Option(s) length 6)
> 0x0000: 8021 0102 000a
> IP-Addr Option (0x03), length 6: 109.71.174.50
> 0x0000: 6d47 ae32
> 20:29:14.506753 PPPoE [ses 0x13] IPCP, Conf-Ack (0x02), id 2, length 12
> encoded length 10 (=Option(s) length 6)
> 0x0000: 8021 0202 000a
> IP-Addr Option (0x03), length 6: 109.71.174.50
> 0x0000: 6d47 ae32
> 20:29:23.247975 PPPoE [ses 0x13] IP (tos 0x0, ttl 255, id 35, offset 0, flags [none], proto ICMP (1), length 100)
> 109.71.174.50 > 217.65.161.4: ICMP echo request, id 10, seq 0, length 80
> 20:29:23.257872 PPPoE [ses 0x13] IP (tos 0x0, ttl 61, id 51771, offset 0, flags [none], proto ICMP (1), length 100)
> 217.65.161.4 > 109.71.174.50: ICMP echo reply, id 10, seq 0, length 80
The ping here is the start of real data flowing - I used this setup for
about 30 minutes of web browsing with no problems.
Paul.