Date: Wed, 25 Jun 2003 18:25:34 -0400 From: Doug Lee <dgl@dlee.org> To: Archie Cobbs <archie@dellroad.org> Cc: Kris Kennaway <kris@obsecurity.org> Subject: Re: mpd VPN won't work after upgrade from 4.6-STABLE to 4.8-STABLE Message-ID: <20030625222534.GD478@kirk.dlee.org> In-Reply-To: <200306251932.h5PJWgUf004385@arch20m.dellroad.org> References: <20030624065138.GB478@kirk.dlee.org> <200306251932.h5PJWgUf004385@arch20m.dellroad.org>
next in thread | previous in thread | raw e-mail | index | archive | help
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@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@dlee.org http://www.dlee.org Bartimaeus Group doug@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
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?20030625222534.GD478>