mpd VPN won't work after upgrade from 4.6-STABLE to 4.8-STABLE

Doug Lee dgl at dlee.org
Wed Jun 25 15:25:44 PDT 2003


On Wed, Jun 25, 2003 at 02:32:42PM -0500, Archie Cobbs wrote:
> Doug Lee wrote:
> > Yes, but it's a good enough idea that I'm doing it again just to be
> > totally sure...and you reminded me that I forgot to rm -r work before
> > doing it last time :P
> > 
> > ...but I am getting the same results after just having done
> 
> The build compile warnings are "normal" and due to old style
> function declarations in OpenSSL.
> 
> If you're getting protocol reject errors -- while trying to use
> Microsoft MPPE encryption? Then probably one side is generating
> the keys incorrectly. What is the other side? Also, let's see
> the log trace.

Here is a trace consisting of link-up, responses to a set of five
pings, and link-terminate, all from the originating side, which is the
side I upgraded from 4.6-STABLE to 4.8-STABLE before this all began.
IDs and ips have been replaced by descriptive <something> strings.

One specific question, other than "Why won't this work?" :-) :  What's
this line doing in here at the end of the successful CHAP negotiation:

17:35:00  MESG: S=181EBCAE417331F125BCDDB3991C14EF7B39750D 


On with the logs...


17:34:58 mpd: pid 33535, version 3.13 (root at kirk.dlee.org 01:21 24-Jun-2003) 
17:34:58 [vpn] ppp node is "mpd33535-vpn" 
17:34:58 mpd: local IP address for PPTP is 0.0.0.0 
17:34:58 [vpn] using interface ng1 
17:34:58 [vpn] IFACE: Open event 
17:34:58 [vpn] IPCP: Open event 
17:34:58 [vpn] IPCP: state change Initial --> Starting 
17:34:58 [vpn] IPCP: LayerStart 
17:34:58 [vpn] bundle: OPEN event in state CLOSED 
17:34:58 [vpn] opening link "vpn"... 
17:34:58 [vpn] link: OPEN event 
17:34:58 [vpn] LCP: Open event 
17:34:58 [vpn] LCP: state change Initial --> Starting 
17:34:58 [vpn] LCP: LayerStart 
17:34:58 [vpn] device: OPEN event in state DOWN 
17:34:58 pptp0: connecting to <dest_ip>:1723 
17:34:58 [vpn] device is now in state OPENING 
17:34:58 pptp0: connected to <dest_ip>:1723 
17:34:58 pptp0: attached to connection with <dest_ip>:1723 
17:34:58 pptp0-0: outgoing call connected at 64000 bps 
17:34:58 [vpn] PPTP call successful 
17:34:58 [vpn] device: UP event in state OPENING 
17:34:58 [vpn] device is now in state UP 
17:34:58 [vpn] link: UP event 
17:34:58 [vpn] link: origination is local 
17:34:58 [vpn] LCP: Up event 
17:34:58 [vpn] LCP: state change Starting --> Req-Sent 
17:34:58 [vpn] LCP: phase shift DEAD --> ESTABLISH 
17:34:58 [vpn] LCP: SendConfigReq #1 
17:34:58  ACFCOMP 
17:34:58  PROTOCOMP 
17:34:58  MRU 1500 
17:34:58  MAGICNUM 77220d8e 
17:34:58  AUTHPROTO CHAP MSOFTv2 
17:34:58 [vpn] LCP: rec'd Configure Ack #1 link 0 (Req-Sent) 
17:34:58  ACFCOMP 
17:34:58  PROTOCOMP 
17:34:58  MRU 1500 
17:34:58  MAGICNUM 77220d8e 
17:34:58  AUTHPROTO CHAP MSOFTv2 
17:34:58 [vpn] LCP: state change Req-Sent --> Ack-Rcvd 
17:35:00 [vpn] LCP: rec'd Configure Request #5 link 0 (Ack-Rcvd) 
17:35:00  ACFCOMP 
17:35:00  PROTOCOMP 
17:35:00  MRU 1500 
17:35:00  MAGICNUM 3254ee69 
17:35:00  AUTHPROTO CHAP MSOFTv2 
17:35:00 [vpn] LCP: SendConfigAck #5 
17:35:00  ACFCOMP 
17:35:00  PROTOCOMP 
17:35:00  MRU 1500 
17:35:00  MAGICNUM 3254ee69 
17:35:00  AUTHPROTO CHAP MSOFTv2 
17:35:00 [vpn] LCP: state change Ack-Rcvd --> Opened 
17:35:00 [vpn] LCP: phase shift ESTABLISH --> AUTHENTICATE 
17:35:00 [vpn] LCP: auth: peer wants CHAP, I want CHAP 
17:35:00 [vpn] CHAP: sending CHALLENGE 
17:35:00 [vpn] LCP: LayerUp 
17:35:00 [vpn] CHAP: rec'd CHALLENGE #1 
17:35:00  Name: "<remoteName>" 
17:35:00  Using authname "<localName>" 
17:35:00 [vpn] CHAP: sending RESPONSE 
17:35:00 [vpn] CHAP: rec'd RESPONSE #1 
17:35:00  Name: "<remoteName>" 
17:35:00  Peer name: "<remoteName>" 
17:35:00  Response is valid 
17:35:00 [vpn] CHAP: sending SUCCESS 
17:35:00 [vpn] CHAP: rec'd SUCCESS #1 
17:35:00  MESG: S=181EBCAE417331F125BCDDB3991C14EF7B39750D 
17:35:00 [vpn] LCP: authorization successful 
17:35:00 [vpn] LCP: phase shift AUTHENTICATE --> NETWORK 
17:35:00 [vpn] setting interface ng1 MTU to 1500 bytes 
17:35:00 [vpn] up: 1 link, total bandwidth 64000 bps 
17:35:00 [vpn] IPCP: Up event 
17:35:00 [vpn] IPCP: state change Starting --> Req-Sent 
17:35:00 [vpn] IPCP: SendConfigReq #1 
17:35:00  IPADDR <local_PPTP_ip> 
17:35:00  COMPPROTO VJCOMP, 16 comp. channels, no comp-cid 
17:35:00 [vpn] CCP: Open event 
17:35:00 [vpn] CCP: state change Initial --> Starting 
17:35:00 [vpn] CCP: LayerStart 
17:35:00 [vpn] CCP: Up event 
17:35:00 [vpn] CCP: state change Starting --> Req-Sent 
17:35:00 [vpn] CCP: SendConfigReq #1 
17:35:00  MPPC 
17:35:00    0x01000040: MPPE, 128 bit, stateless 
17:35:00 [vpn] IPCP: rec'd Configure Request #2 link 0 (Req-Sent) 
17:35:00  IPADDR <remote_PPTP_ip> 
17:35:00    <remote_PPTP_ip> is OK 
17:35:00  COMPPROTO VJCOMP, 16 comp. channels, no comp-cid 
17:35:00 [vpn] IPCP: SendConfigAck #2 
17:35:00  IPADDR <remote_PPTP_ip> 
17:35:00  COMPPROTO VJCOMP, 16 comp. channels, no comp-cid 
17:35:01 [vpn] IPCP: state change Req-Sent --> Ack-Sent 
17:35:01 [vpn] CCP: rec'd Configure Request #3 link 0 (Req-Sent) 
17:35:01  MPPC 
17:35:01    0x01000040: MPPE, 128 bit, stateless 
17:35:01 [vpn] CCP: SendConfigAck #3 
17:35:01  MPPC 
17:35:01    0x01000040: MPPE, 128 bit, stateless 
17:35:01 [vpn] CCP: state change Req-Sent --> Ack-Sent 
17:35:01 [vpn] IPCP: rec'd Configure Ack #1 link 0 (Ack-Sent) 
17:35:01  IPADDR <local_PPTP_ip> 
17:35:01  COMPPROTO VJCOMP, 16 comp. channels, no comp-cid 
17:35:01 [vpn] IPCP: state change Ack-Sent --> Opened 
17:35:01 [vpn] IPCP: LayerUp 
17:35:01   <local_PPTP_ip> -> <remote_PPTP_ip> 
17:35:01 [vpn] IFACE: Up event 
17:35:01 [vpn] setting interface ng1 MTU to 1496 bytes 
17:35:01 [vpn] exec: /sbin/ifconfig ng1 <local_PPTP_ip> <remote_PPTP_ip> netmask 0xffffffff -link0 
17:35:01 [vpn] exec: /sbin/route add <local_PPTP_ip> -iface lo0 
17:35:01 [vpn] exec: /sbin/route add <remoteNet> <remote_PPTP_ip> -netmask 0xffffff00 
17:35:01 [vpn] IFACE: Up event 
17:35:01 [vpn] CCP: rec'd Configure Ack #1 link 0 (Ack-Sent) 
17:35:01  MPPC 
17:35:01    0x01000040: MPPE, 128 bit, stateless 
17:35:01 [vpn] CCP: state change Ack-Sent --> Opened 
17:35:01 [vpn] CCP: LayerUp 
17:35:01   Compress using: MPPE, 128 bit, stateless 
17:35:01 Decompress using: MPPE, 128 bit, stateless 
17:35:01 [vpn] setting interface ng1 MTU to 1496 bytes 
17:35:03 [vpn] CCP: rec'd Configure Request #4 link 0 (Opened) 
17:35:03  MPPC 
17:35:03    0x01000040: MPPE, 128 bit, stateless 
17:35:03 [vpn] CCP: LayerDown 
17:35:03 [vpn] CCP: SendConfigReq #2 
17:35:03  MPPC 
17:35:03    0x01000040: MPPE, 128 bit, stateless 
17:35:03 [vpn] CCP: SendConfigAck #4 
17:35:03  MPPC 
17:35:03    0x01000040: MPPE, 128 bit, stateless 
17:35:03 [vpn] CCP: state change Opened --> Ack-Sent 
17:35:03 [vpn] CCP: rec'd Configure Ack #2 link 0 (Ack-Sent) 
17:35:03  MPPC 
17:35:03    0x01000040: MPPE, 128 bit, stateless 
17:35:03 [vpn] CCP: state change Ack-Sent --> Opened 
17:35:03 [vpn] CCP: LayerUp 
17:35:03   Compress using: MPPE, 128 bit, stateless 
17:35:03 Decompress using: MPPE, 128 bit, stateless 
17:35:03 [vpn] setting interface ng1 MTU to 1496 bytes 

The following mpd log entries were generated by a set of five pings
I attempted to send up the link:

17:35:15 [vpn] LCP: rec'd Protocol Reject #22 link 0 (Opened) 
17:35:15 [vpn] LCP: protocol 0x0023 was rejected 
17:35:16 [vpn] LCP: rec'd Protocol Reject #23 link 0 (Opened) 
17:35:16 [vpn] LCP: protocol 0x00e7 was rejected 
17:35:17 [vpn] LCP: rec'd Protocol Reject #24 link 0 (Opened) 
17:35:17 [vpn] LCP: protocol 0x0087 was rejected 
17:35:18 [vpn] LCP: rec'd Protocol Reject #25 link 0 (Opened) 
17:35:18 [vpn] LCP: protocol 0x006d was rejected 
17:35:19 [vpn] LCP: rec'd Protocol Reject #26 link 0 (Opened) 
17:35:19 [vpn] LCP: protocol 0x16a1 was rejected 

There were a few more protocol rejections (probably caused by NetBIOS
communication attempts) before I sent mpd a SIGTERM; I'm omitting
those here.

This is the trace of the termination, in case it helps at all:

17:36:43 mpd: caught fatal signal term 
17:36:43 [vpn] IPCP: Down event 
17:36:43 [vpn] IPCP: state change Opened --> Starting 
17:36:43 [vpn] IPCP: LayerDown 
17:36:43 [vpn] IFACE: Down event 
17:36:43 [vpn] exec: /sbin/route delete <remoteNet> <remote_PPTP_ip> -netmask 0xffffff00 
17:36:43 [vpn] exec: /sbin/route delete <local_PPTP_ip> -iface lo0 
17:36:43 [vpn] exec: /sbin/ifconfig ng1 down delete -link0 
17:36:43 [vpn] IFACE: Close event 
17:36:43 [vpn] IPCP: Close event 
17:36:43 [vpn] IPCP: state change Starting --> Initial 
17:36:43 [vpn] IPCP: LayerFinish 
17:36:43 [vpn] bundle: CLOSE event in state OPENED 
17:36:43 [vpn] closing link "vpn"... 
17:36:43 [vpn] link: CLOSE event 
17:36:43 [vpn] LCP: Close event 
17:36:43 [vpn] LCP: state change Opened --> Closing 
17:36:43 [vpn] LCP: phase shift NETWORK --> TERMINATE 
17:36:43 [vpn] setting interface ng1 MTU to 1500 bytes 
17:36:43 [vpn] up: 0 links, total bandwidth 9600 bps 
17:36:43 [vpn] IPCP: Down event 
17:36:43 [vpn] CCP: Down event 
17:36:43 [vpn] CCP: state change Opened --> Starting 
17:36:43 [vpn] CCP: LayerDown 
17:36:43 [vpn] CCP: Close event 
17:36:43 [vpn] CCP: state change Starting --> Initial 
17:36:43 [vpn] CCP: LayerFinish 
17:36:43 [vpn] closing link "vpn"... 
17:36:43 [vpn] LCP: SendTerminateReq #2 
17:36:43 [vpn] LCP: LayerDown 
17:36:43 [vpn] link: CLOSE event 
17:36:43 [vpn] LCP: Close event 
17:36:43 [vpn] LCP: rec'd Terminate Ack #6 link 0 (Closing) 
17:36:43 [vpn] LCP: state change Closing --> Closed 
17:36:43 [vpn] LCP: phase shift TERMINATE --> ESTABLISH 
17:36:43 [vpn] LCP: LayerFinish 
17:36:43 [vpn] device: CLOSE event in state UP 
17:36:43 pptp0-0: clearing call 
17:36:43 [vpn] device is now in state CLOSING 
17:36:43 [vpn] device: DOWN event in state CLOSING 
17:36:43 [vpn] device is now in state DOWN 
17:36:43 [vpn] link: DOWN event 
17:36:43 [vpn] LCP: Down event 
17:36:43 [vpn] LCP: state change Closed --> Initial 
17:36:43 [vpn] LCP: phase shift ESTABLISH --> DEAD 
17:36:43 pptp0: got StopCtrlConnRequest: reason=local shutdown 
17:36:43 pptp0: killing connection with <dest_ip>:1723 
17:36:43 pptp0-0: killing channel 
17:36:45 mpd: process 33535 terminated 


Thanks for any help...


-- 
Doug Lee           dgl at dlee.org        http://www.dlee.org
Bartimaeus Group   doug at bartsite.com   http://www.bartsite.com
"Believe, when you are most unhappy, that there is something for you
to do in the world. So long as you can sweeten another's pain, life is
not in vain."
--Helen Keller


More information about the freebsd-stable mailing list