On Mon, 08 Nov 2004 20:35:12 +0000, John Hardin wrote:
> 1) Every five minutes or so (the time varies) the Cisco sends a LCP
> config request, which renegotiates the PPP session. There is no apparent
> reason for it to do this.
I ran an analysis and the duration is pretty reliably 140 seconds from the
end of the initial LCP configuration. I guess that shows how accurate my
cuffs are...
I believe I understand what is going on now, and it looks to me like a bug
in the Cisco PPP implementation.
The Linux pppd was sending LCP ConfReqs as soon as the T1 came up. The
Cisco was ignoring them (neither ACKing nor NAKing), but apparently was
remembering them. After the LCP and IPCP configuration completed and 140
seconds passed, the Cisco would start a renegotiation and AT THAT TIME it
would ACK the ConfReqs from the ORIGINAL negotiation. I assume it
remembered that it had received them, and after some internal timer
expired, would see them and decide the link was in a down state and needed
to be reconfigured.
Workaround: set my ppp options to:
lcp-restart 45
lcp-max-configure 2
....which essentially makes the Linux pppd passive. It doesn't send any LCP
confreqs that the Cisco can see (the first gets lost during T1 setup) and
thus it doesn't remember them and get confused about the link state.
My Multilink PPP T1 configuration using the Sangoma Wanpipe Dual T1 card
to a Cisco router at Sprint is UP and appears reliable with this change.
This hardware is RECOMMENDED. Please note: make sure you get the latest
stable Wanpipe drivers if you want to do this. They had to make some
changes to get this up and running here. A gold star for Nenad Corbic
at Sangoma!
Here are the details:
=================================
Nov 10 08:08:18 t1_up: Starting pppd on wanpipe1...
Nov 10 08:08:19 wanpipe1_pppd: using channel 1
Nov 10 08:08:19 wanpipe1_pppd: Connect: <--> /dev/ttyWP0
Nov 10 08:08:19 wanpipe1_pppd: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x22d00757> <mrru 1500> <endpoint [MAC:00:02:a5:8a:35:64]>]
....T1 in YEL alarm, no PPP responses (not too surprising)
....note our magic: 0x22d00757
....T1 takes 20 sec to come up
Nov 10 08:08:40 wanpipe1_pppd: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x22d00757> <mrru 1500> <endpoint [MAC:00:02:a5:8a:35:64]>]
....OK, T1 now up
Nov 10 08:08:41 wanpipe1_pppd: rcvd [LCP ConfReq id=0x5c <magic 0x17de7f4> <mrru 1500> <endpoint [local:73.6c.2d.67.77.35.2d.74.61.63]>]
....First confreq from Cisco router
Nov 10 08:08:41 wanpipe1_pppd: sent [LCP ConfAck id=0x5c <magic 0x17de7f4> <mrru 1500> <endpoint [local:73.6c.2d.67.77.35.2d.74.61.63]>]
....We ACK it
Nov 10 08:08:43 wanpipe1_pppd: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x22d00757> <mrru 1500> <endpoint [MAC:00:02:a5:8a:35:64]>]
....and send a REQ of our own
Nov 10 08:08:43 wanpipe1_pppd: rcvd [LCP ConfReq id=0x5d <magic 0x17de7f4> <mrru 1500> <endpoint [local:73.6c.2d.67.77.35.2d.74.61.63]>]
Nov 10 08:08:43 wanpipe1_pppd: sent [LCP ConfAck id=0x5d <magic 0x17de7f4> <mrru 1500> <endpoint [local:73.6c.2d.67.77.35.2d.74.61.63]>]
Nov 10 08:08:45 wanpipe1_pppd: rcvd [LCP ConfReq id=0x5e <magic 0x17de7f4> <mrru 1500> <endpoint [local:73.6c.2d.67.77.35.2d.74.61.63]>]
Nov 10 08:08:45 wanpipe1_pppd: sent [LCP ConfAck id=0x5e <magic 0x17de7f4> <mrru 1500> <endpoint [local:73.6c.2d.67.77.35.2d.74.61.63]>]
Nov 10 08:08:46 wanpipe1_pppd: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x22d00757> <mrru 1500> <endpoint [MAC:00:02:a5:8a:35:64]>]
Nov 10 08:08:47 wanpipe1_pppd: rcvd [LCP ConfReq id=0x5f <magic 0x17de7f4> <mrru 1500> <endpoint [local:73.6c.2d.67.77.35.2d.74.61.63]>]
Nov 10 08:08:47 wanpipe1_pppd: sent [LCP ConfAck id=0x5f <magic 0x17de7f4> <mrru 1500> <endpoint [local:73.6c.2d.67.77.35.2d.74.61.63]>]
....chat chat chat
....To this point we have received NO ConfAcks for ANY of the ConfReqs we have sent...
Nov 10 08:08:49 wanpipe1_pppd: sent [LCP ConfReq id=0x1 <asyncmap 0x0> <magic 0x22d00757> <mrru 1500> <endpoint [MAC:00:02:a5:8a:35:64]>]
Nov 10 08:08:49 wanpipe1_pppd: rcvd [LCP ConfAck id=0x1 <asyncmap 0x0> <magic 0x22d00757> <mrru 1500> <endpoint [MAC:00:02:a5:8a:35:64]>]
....Finally, one gets ACKed!
Nov 10 08:08:49 wanpipe1_pppd: Using interface ppp0
Nov 10 08:08:49 wanpipe1_pppd: New bundle ppp0 created
Nov 10 08:08:49 wanpipe1_pppd: sent [IPCP ConfReq id=0x1 <addr x.x.x.x>]
Nov 10 08:08:51 wanpipe1_pppd: rcvd [IPCP ConfReq id=0xd9 <addr x.x.x.x>]
Nov 10 08:08:51 wanpipe1_pppd: sent [IPCP ConfAck id=0xd9 <addr x.x.x.x>]
Nov 10 08:08:52 wanpipe1_pppd: sent [IPCP ConfReq id=0x1 <addr x.x.x.x>]
Nov 10 08:08:52 wanpipe1_pppd: rcvd [IPCP ConfAck id=0x1 <addr x.x.x.x>]
Nov 10 08:08:52 wanpipe1_pppd: local IP address x.x.x.x
Nov 10 08:08:52 wanpipe1_pppd: remote IP address x.x.x.x
....Okay, everything is up and running
Nov 10 08:08:52 wanpipe1_pppd: Script /etc/ppp/ip-up started (pid 4478)
Nov 10 08:08:53 wanpipe1_pppd: Script /etc/ppp/ip-up finished (pid 4478), status = 0x0
....everything is fine for a while, then...
Nov 10 08:11:09 wanpipe1_pppd: rcvd [LCP ConfReq id=0x60 <magic 0x180313d> <mrru 1500> <endpoint [local:73.6c.2d.67.77.35.2d.74.61.63]>]
....Cisco wants to reconfigure! Note the magic has changed...
Nov 10 08:11:09 wanpipe1_pppd: Script /etc/ppp/ip-down started (pid 5628)
....Okay, tearing down our end
Nov 10 08:11:09 wanpipe1_pppd: sent [LCP ConfReq id=0x2 <asyncmap 0x0> <magic 0xcaee1de0> <mrru 1500> <endpoint [MAC:00:02:a5:8a:35:64]>]
....Here we send a ConfReq of our own with a new magic: 0xcaee1de0
Nov 10 08:11:09 wanpipe1_pppd: sent [LCP ConfAck id=0x60 <magic 0x180313d> <mrru 1500> <endpoint [local:73.6c.2d.67.77.35.2d.74.61.63]>]
....We ACK the Cisco's reconfigure REQ
Nov 10 08:11:09 wanpipe1_pppd: rcvd [LCP ConfAck id=0x1 <asyncmap 0x0> <magic 0x22d00757> <mrru 1500> <endpoint [MAC:00:02:a5:8a:35:64]>]
Nov 10 08:11:09 wanpipe1_pppd: rcvd [LCP ConfAck id=0x1 <asyncmap 0x0> <magic 0x22d00757> <mrru 1500> <endpoint [MAC:00:02:a5:8a:35:64]>]
....Huh? We just received two ACKs for requests we sent minutes ago!
....Note the OLD magic number...
Nov 10 08:11:11 wanpipe1_pppd: rcvd [LCP ConfReq id=0x61 <magic 0x180313d> <mrru 1500> <endpoint [local:73.6c.2d.67.77.35.2d.74.61.63]>]
Nov 10 08:11:11 wanpipe1_pppd: sent [LCP ConfAck id=0x61 <magic 0x180313d> <mrru 1500> <endpoint [local:73.6c.2d.67.77.35.2d.74.61.63]>]
Nov 10 08:11:12 wanpipe1_pppd: sent [LCP ConfReq id=0x2 <asyncmap 0x0> <magic 0xcaee1de0> <mrru 1500> <endpoint [MAC:00:02:a5:8a:35:64]>]
Nov 10 08:11:13 wanpipe1_pppd: rcvd [LCP ConfReq id=0x62 <magic 0x180313d> <mrru 1500> <endpoint [local:73.6c.2d.67.77.35.2d.74.61.63]>]
Nov 10 08:11:13 wanpipe1_pppd: sent [LCP ConfAck id=0x62 <magic 0x180313d> <mrru 1500> <endpoint [local:73.6c.2d.67.77.35.2d.74.61.63]>]
Nov 10 08:11:14 wanpipe1_pppd: Script /etc/ppp/ip-down finished (pid 5628), status = 0x0
Nov 10 08:11:15 wanpipe1_pppd: rcvd [LCP ConfReq id=0x63 <magic 0x180313d> <mrru 1500> <endpoint [local:73.6c.2d.67.77.35.2d.74.61.63]>]
Nov 10 08:11:15 wanpipe1_pppd: sent [LCP ConfAck id=0x63 <magic 0x180313d> <mrru 1500> <endpoint [local:73.6c.2d.67.77.35.2d.74.61.63]>]
Nov 10 08:11:15 wanpipe1_pppd: sent [LCP ConfReq id=0x2 <asyncmap 0x0> <magic 0xcaee1de0> <mrru 1500> <endpoint [MAC:00:02:a5:8a:35:64]>]
Nov 10 08:11:15 wanpipe1_pppd: rcvd [LCP ConfAck id=0x2 <asyncmap 0x0> <magic 0xcaee1de0> <mrru 1500> <endpoint [MAC:00:02:a5:8a:35:64]>]
....and so forth.
=================================
--
John Hardin
Internal Systems Administrator (Seattle)
CRS Retail Systems, Inc.
3400 188th Street SW, Suite 185
Lynnwood, WA 98037
voice: (425) 672-1304
fax: (425) 672-0192
email:
(E-Mail Removed)
web:
http://www.crsretail.com
-----------------------------------------------------------------------
If you smash a computer to bits with a mallet, that appears to count
as encryption in the state of Nevada.
- CRYPTO-GRAM 12/2001
-----------------------------------------------------------------------