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

From: Doug Lee (dgl_at_dlee.org)
Date: 06/26/03

  • Next message: Julian C. Dunn - Lists: "Re: ICRC error?" 
    Date: Wed, 25 Jun 2003 18:25:34 -0400
To: Archie Cobbs <archie@dellroad.org>

    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
_______________________________________________
freebsd-stable@freebsd.org mailing list
http://lists.freebsd.org/mailman/listinfo/freebsd-stable
To unsubscribe, send any mail to "freebsd-stable-unsubscribe@freebsd.org"
  • Next message: Julian C. Dunn - Lists: "Re: ICRC error?"

    Relevant Pages